log2json

.gitignore

@@ -0,0 +1,3 @@
+*.o
+build/
+*.out

include/logger.h

@@ -26,6 +26,20 @@ typedef struct OmniStats {
     uint64_t tcp_retrans;        /* 预留：TCP 重传统计（如可从内核获取） */
     uint64_t udp_retrans;        /* UDP 上层重传次数 */
     uint64_t kcp_retrans;        /* KCP 内部重传次数（可从 ikcp 统计） */
+
+    /* 延迟/耗时统计（单位：毫秒） */
+    double send_call_avg_ms;     /* omni_send 平均耗时（EWMA） */
+    double recv_call_avg_ms;     /* omni_recv 平均耗时（EWMA） */
+    double proto_send_avg_ms;    /* 协议 send() 平均耗时（EWMA） */
+    double proto_recv_avg_ms;    /* 协议 recv() 平均耗时（EWMA） */
+
+    uint64_t send_call_min_ms;
+    uint64_t send_call_max_ms;
+    uint64_t recv_call_min_ms;
+    uint64_t recv_call_max_ms;
+
+    uint64_t last_send_call_ms;
+    uint64_t last_recv_call_ms;
 } OmniStats;
 
 /* 初始化统计模块，在程序启动时调用一次 */
@@ -41,6 +55,12 @@ void logger_on_rtt(uint64_t rtt_ms);
 /* 记录 KCP 重传次数变化（可在 KCP 更新循环中调用） */
 void logger_on_kcp_retrans(uint64_t delta);
 
+/* 记录一次耗时（ms） */
+void logger_on_send_call_latency(uint64_t ms);
+void logger_on_recv_call_latency(uint64_t ms);
+void logger_on_proto_send_latency(uint64_t ms);
+void logger_on_proto_recv_latency(uint64_t ms);
+
 /* 计算当前吞吐量（返回：字节/秒） */
 double logger_calculate_throughput(void);
 

src/apps/test_main.c

@@ -0,0 +1,161 @@
+/*
+ * test_main.c
+ * 简单测试程序：客户端/服务端双向传输 + 日志观测
+ *
+ * 使用方式示例（同一机器上，两个终端）：
+ *   终端1：./omni_test -r server -p tcp -P 9000
+ *   终端2：./omni_test -r client -p tcp -P 9000 -H 127.0.0.1
+ *
+ * 协议可选：tcp / udp / kcp
+ */
+
+#include "common.h"
+#include "network.h"
+#include "logger.h"
+
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <unistd.h>
+
+static void usage(const char *prog)
+{
+    fprintf(stderr,
+            "Usage:\n"
+            "  %s -r server -p tcp|udp|kcp -P <port>\n"
+            "  %s -r client -p tcp|udp|kcp -P <port> -H <host>\n",
+            prog, prog);
+}
+
+static OmniProtocol parse_proto(const char *s)
+{
+    if (strcmp(s, "tcp") == 0) return OMNI_PROTO_TCP;
+    if (strcmp(s, "udp") == 0) return OMNI_PROTO_UDP;
+    if (strcmp(s, "kcp") == 0) return OMNI_PROTO_KCP;
+    return OMNI_PROTO_TCP;
+}
+
+static void run_server(OmniProtocol proto, uint16_t port)
+{
+    OmniContext *ctx = omni_init(OMNI_ROLE_SERVER, proto,
+                                 NULL, port,
+                                 NULL, 0);
+    if (!ctx) {
+        fprintf(stderr, "server: omni_init failed\n");
+        return;
+    }
+
+    logger_log("INFO", "test", "server_started proto=%d port=%u",
+               (int)proto, (unsigned)port);
+
+    char buf[4096];
+    for (;;) {
+        ssize_t n = omni_recv(ctx, buf, sizeof(buf));
+        if (n <= 0) {
+            logger_log("INFO", "test", "server_recv_end n=%zd", n);
+            break;
+        }
+        logger_log("INFO", "test", "server_recv bytes=%zd", n);
+
+        /* 简单 echo 回客户端，验证双向通信 */
+        ssize_t m = omni_send(ctx, buf, (size_t)n);
+        logger_log("INFO", "test", "server_echo bytes=%zd", m);
+    }
+
+    omni_close(ctx);
+}
+
+static void run_client(OmniProtocol proto, const char *host, uint16_t port)
+{
+    if (!host) {
+        fprintf(stderr, "client: host is required\n");
+        return;
+    }
+
+    OmniContext *ctx = omni_init(OMNI_ROLE_CLIENT, proto,
+                                 NULL, 0,
+                                 host, port);
+    if (!ctx) {
+        fprintf(stderr, "client: omni_init failed\n");
+        return;
+    }
+
+    logger_log("INFO", "test", "client_started proto=%d host=%s port=%u",
+               (int)proto, host, (unsigned)port);
+
+    char send_buf[2048];
+    char recv_buf[4096];
+
+    for (int i = 0; i < 100; ++i) {
+        int len = snprintf(send_buf, sizeof(send_buf),
+                           "msg=%d time_ms=%llu payload_size=%zu",
+                           i,
+                           (unsigned long long)omni_now_ms(),
+                           sizeof(send_buf));
+
+        ssize_t n = omni_send(ctx, send_buf, (size_t)len);
+        logger_log("INFO", "test", "client_send i=%d bytes=%zd", i, n);
+        if (n <= 0) break;
+
+        ssize_t m = omni_recv(ctx, recv_buf, sizeof(recv_buf));
+        if (m <= 0) {
+            logger_log("INFO", "test", "client_recv_end i=%d bytes=%zd", i, m);
+            break;
+        }
+        logger_log("INFO", "test",
+                   "client_recv_echo i=%d bytes=%zd first_bytes=\"%.32s\"",
+                   i, m, recv_buf);
+
+        usleep(10 * 1000); /* 10ms 间隔，模拟稳定流量 */
+    }
+
+    omni_close(ctx);
+}
+
+int main(int argc, char **argv)
+{
+    const char *role_str = NULL;
+    const char *proto_str = "tcp";
+    const char *host = NULL;
+    int port = 0;
+
+    int opt;
+    while ((opt = getopt(argc, argv, "r:p:P:H:")) != -1) {
+        switch (opt) {
+        case 'r':
+            role_str = optarg;
+            break;
+        case 'p':
+            proto_str = optarg;
+            break;
+        case 'P':
+            port = atoi(optarg);
+            break;
+        case 'H':
+            host = optarg;
+            break;
+        default:
+            usage(argv[0]);
+            return 1;
+        }
+    }
+
+    if (!role_str || port <= 0) {
+        usage(argv[0]);
+        return 1;
+    }
+
+    OmniProtocol proto = parse_proto(proto_str);
+
+    if (strcmp(role_str, "server") == 0) {
+        run_server(proto, (uint16_t)port);
+    } else if (strcmp(role_str, "client") == 0) {
+        run_client(proto, host, (uint16_t)port);
+    } else {
+        usage(argv[0]);
+        return 1;
+    }
+
+    return 0;
+}
+

src/core/logger.c

@@ -9,19 +9,36 @@
 #include <stdio.h>
 #include <stdarg.h>
 #include <string.h>
+#include <inttypes.h>
 
 static OmniStats g_stats;
+static FILE *g_json_fp = NULL;
 
 static uint64_t now_ms(void)
 {
     return omni_now_ms();
 }
 
+static void ewma_update(double *avg, double sample, double alpha)
+{
+    if (*avg <= 0.0) {
+        *avg = sample;
+        return;
+    }
+    *avg = (*avg) * (1.0 - alpha) + sample * alpha;
+}
+
 void logger_init(void)
 {
     memset(&g_stats, 0, sizeof(g_stats));
     g_stats.start_ms = now_ms();
     g_stats.last_report_ms = g_stats.start_ms;
+    g_stats.send_call_min_ms = UINT64_MAX;
+    g_stats.recv_call_min_ms = UINT64_MAX;
+
+    if (!g_json_fp) {
+        g_json_fp = fopen("omni_logs.jsonl", "a");
+    }
 }
 
 void logger_on_send(size_t bytes)
@@ -49,6 +66,32 @@ void logger_on_kcp_retrans(uint64_t delta)
     g_stats.kcp_retrans += delta;
 }
 
+void logger_on_send_call_latency(uint64_t ms)
+{
+    g_stats.last_send_call_ms = ms;
+    if (ms < g_stats.send_call_min_ms) g_stats.send_call_min_ms = ms;
+    if (ms > g_stats.send_call_max_ms) g_stats.send_call_max_ms = ms;
+    ewma_update(&g_stats.send_call_avg_ms, (double)ms, 0.2);
+}
+
+void logger_on_recv_call_latency(uint64_t ms)
+{
+    g_stats.last_recv_call_ms = ms;
+    if (ms < g_stats.recv_call_min_ms) g_stats.recv_call_min_ms = ms;
+    if (ms > g_stats.recv_call_max_ms) g_stats.recv_call_max_ms = ms;
+    ewma_update(&g_stats.recv_call_avg_ms, (double)ms, 0.2);
+}
+
+void logger_on_proto_send_latency(uint64_t ms)
+{
+    ewma_update(&g_stats.proto_send_avg_ms, (double)ms, 0.2);
+}
+
+void logger_on_proto_recv_latency(uint64_t ms)
+{
+    ewma_update(&g_stats.proto_recv_avg_ms, (double)ms, 0.2);
+}
+
 double logger_calculate_throughput(void)
 {
     uint64_t now = now_ms();
@@ -66,6 +109,30 @@ static void print_timestamp(FILE *fp)
     fprintf(fp, "ts=%llu ", (unsigned long long)ms);
 }
 
+static void json_escape(const char *src, char *dst, size_t dst_sz)
+{
+    size_t j = 0;
+    for (size_t i = 0; src[i] && j + 2 < dst_sz; ++i) {
+        unsigned char c = (unsigned char)src[i];
+        if (c == '\\' || c == '\"') {
+            dst[j++] = '\\';
+            dst[j++] = (char)c;
+        } else if (c == '\n') {
+            dst[j++] = '\\';
+            dst[j++] = 'n';
+        } else if (c == '\r') {
+            dst[j++] = '\\';
+            dst[j++] = 'r';
+        } else if (c == '\t') {
+            dst[j++] = '\\';
+            dst[j++] = 't';
+        } else {
+            dst[j++] = (char)c;
+        }
+    }
+    dst[j] = '\0';
+}
+
 void logger_print_performance_log(const char *tag)
 {
     uint64_t now = now_ms();
@@ -79,6 +146,9 @@ void logger_print_performance_log(const char *tag)
             "elapsed_ms=%llu bytes_sent=%llu bytes_recv=%llu "
             "send_count=%llu recv_count=%llu "
             "throughput_bytes_per_sec=%.2f "
+            "send_call_last_ms=%llu send_call_min_ms=%llu send_call_max_ms=%llu send_call_avg_ms=%.3f "
+            "recv_call_last_ms=%llu recv_call_min_ms=%llu recv_call_max_ms=%llu recv_call_avg_ms=%.3f "
+            "proto_send_avg_ms=%.3f proto_recv_avg_ms=%.3f "
             "last_rtt_ms=%llu max_rtt_ms=%llu "
             "kcp_retrans=%llu\n",
             tag ? tag : "periodic",
@@ -88,27 +158,106 @@ void logger_print_performance_log(const char *tag)
             (unsigned long long)g_stats.send_count,
             (unsigned long long)g_stats.recv_count,
             thr,
+            (unsigned long long)g_stats.last_send_call_ms,
+            (unsigned long long)((g_stats.send_call_min_ms == UINT64_MAX) ? 0 : g_stats.send_call_min_ms),
+            (unsigned long long)g_stats.send_call_max_ms,
+            g_stats.send_call_avg_ms,
+            (unsigned long long)g_stats.last_recv_call_ms,
+            (unsigned long long)((g_stats.recv_call_min_ms == UINT64_MAX) ? 0 : g_stats.recv_call_min_ms),
+            (unsigned long long)g_stats.recv_call_max_ms,
+            g_stats.recv_call_avg_ms,
+            g_stats.proto_send_avg_ms,
+            g_stats.proto_recv_avg_ms,
             (unsigned long long)g_stats.last_rtt_ms,
             (unsigned long long)g_stats.max_rtt_ms,
             (unsigned long long)g_stats.kcp_retrans);
 
     g_stats.last_report_ms = now;
+
+    if (g_json_fp) {
+        fprintf(g_json_fp,
+                "{\"ts_ms\":%llu,"
+                "\"level\":\"INFO\","
+                "\"component\":\"perf\","
+                "\"tag\":\"%s\","
+                "\"elapsed_ms\":%llu,"
+                "\"bytes_sent\":%llu,"
+                "\"bytes_recv\":%llu,"
+                "\"send_count\":%llu,"
+                "\"recv_count\":%llu,"
+                "\"throughput_bytes_per_sec\":%.6f,"
+                "\"send_call_last_ms\":%llu,"
+                "\"send_call_min_ms\":%llu,"
+                "\"send_call_max_ms\":%llu,"
+                "\"send_call_avg_ms\":%.6f,"
+                "\"recv_call_last_ms\":%llu,"
+                "\"recv_call_min_ms\":%llu,"
+                "\"recv_call_max_ms\":%llu,"
+                "\"recv_call_avg_ms\":%.6f,"
+                "\"proto_send_avg_ms\":%.6f,"
+                "\"proto_recv_avg_ms\":%.6f,"
+                "\"last_rtt_ms\":%llu,"
+                "\"max_rtt_ms\":%llu,"
+                "\"kcp_retrans\":%llu}\n",
+                (unsigned long long)now,
+                tag ? tag : "periodic",
+                (unsigned long long)elapsed_ms,
+                (unsigned long long)g_stats.bytes_sent,
+                (unsigned long long)g_stats.bytes_recv,
+                (unsigned long long)g_stats.send_count,
+                (unsigned long long)g_stats.recv_count,
+                thr,
+                (unsigned long long)g_stats.last_send_call_ms,
+                (unsigned long long)((g_stats.send_call_min_ms == UINT64_MAX) ? 0 : g_stats.send_call_min_ms),
+                (unsigned long long)g_stats.send_call_max_ms,
+                g_stats.send_call_avg_ms,
+                (unsigned long long)g_stats.last_recv_call_ms,
+                (unsigned long long)((g_stats.recv_call_min_ms == UINT64_MAX) ? 0 : g_stats.recv_call_min_ms),
+                (unsigned long long)g_stats.recv_call_max_ms,
+                g_stats.recv_call_avg_ms,
+                g_stats.proto_send_avg_ms,
+                g_stats.proto_recv_avg_ms,
+                (unsigned long long)g_stats.last_rtt_ms,
+                (unsigned long long)g_stats.max_rtt_ms,
+                (unsigned long long)g_stats.kcp_retrans);
+        fflush(g_json_fp);
+    }
 }
 
 void logger_log(const char *level, const char *component,
                 const char *fmt, ...)
 {
+    const char *lvl = level ? level : "INFO";
+    const char *comp = component ? component : "general";
+
     FILE *fp = stderr;
     print_timestamp(fp);
-    fprintf(fp, "level=%s component=%s ", level ? level : "INFO",
+    fprintf(fp, "level=%s component=%s ", lvl, comp);
-            component ? component : "general");
 
+    char msg_buf[1024];
     va_list ap;
     va_start(ap, fmt);
-    vfprintf(fp, fmt, ap);
+    vsnprintf(msg_buf, sizeof(msg_buf), fmt, ap);
     va_end(ap);
 
+    fputs(msg_buf, fp);
     fputc('\n', fp);
+
+    if (g_json_fp) {
+        char esc_buf[2048];
+        json_escape(msg_buf, esc_buf, sizeof(esc_buf));
+        uint64_t ts = now_ms();
+        fprintf(g_json_fp,
+                "{\"ts_ms\":%llu,"
+                "\"level\":\"%s\","
+                "\"component\":\"%s\","
+                "\"message\":\"%s\"}\n",
+                (unsigned long long)ts,
+                lvl,
+                comp,
+                esc_buf);
+        fflush(g_json_fp);
+    }
 }
 
 OmniStats logger_get_snapshot(void)

src/core/network.c

@@ -87,12 +87,15 @@ ssize_t omni_send(OmniContext *ctx, const void *buf, size_t len)
         return OMNI_ERR_PARAM;
     }
 
+    uint64_t t0 = omni_now_ms();
     ssize_t n = ctx->vt->send((OmniContext *)ctx->impl, buf, len);
+    uint64_t t1 = omni_now_ms();
+    logger_on_send_call_latency(t1 - t0);
     if (n > 0) {
         logger_on_send((size_t)n);
     }
-    logger_log("DEBUG", "network", "omni_send proto=%d bytes=%zd",
+    logger_log("DEBUG", "network", "omni_send proto=%d bytes=%zd call_ms=%llu",
-               (int)ctx->proto, n);
+               (int)ctx->proto, n, (unsigned long long)(t1 - t0));
     return n;
 }
 
@@ -102,12 +105,15 @@ ssize_t omni_recv(OmniContext *ctx, void *buf, size_t len)
         return OMNI_ERR_PARAM;
     }
 
+    uint64_t t0 = omni_now_ms();
     ssize_t n = ctx->vt->recv((OmniContext *)ctx->impl, buf, len);
+    uint64_t t1 = omni_now_ms();
+    logger_on_recv_call_latency(t1 - t0);
     if (n > 0) {
         logger_on_recv((size_t)n);
     }
-    logger_log("DEBUG", "network", "omni_recv proto=%d bytes=%zd",
+    logger_log("DEBUG", "network", "omni_recv proto=%d bytes=%zd call_ms=%llu",
-               (int)ctx->proto, n);
+               (int)ctx->proto, n, (unsigned long long)(t1 - t0));
     return n;
 }
 

src/protocols/kcp_impl.c

@@ -22,6 +22,7 @@ struct KcpContext {
     struct sockaddr_in peer_addr;
     socklen_t peer_len;
     ikcpcb *kcp;
+    uint32_t last_xmit; /* 用于推算重传/发送次数变化 */
 };
 
 static int kcp_output(const char *buf, int len, ikcpcb *kcp, void *user)
@@ -104,6 +105,7 @@ static OmniContext *kcp_init(OmniRole role,
 
 static void kcp_update_loop(struct KcpContext *ctx)
 {
+    uint64_t t0 = omni_now_ms();
     IUINT32 current = (IUINT32)omni_now_ms();
     ikcp_update(ctx->kcp, current);
 
@@ -117,6 +119,32 @@ static void kcp_update_loop(struct KcpContext *ctx)
         ctx->peer_len = fromlen;
         ikcp_input(ctx->kcp, buf, (long)n);
     }
+
+    /* KCP 内部状态监控 */
+    uint32_t xmit = ctx->kcp->xmit;
+    if (xmit >= ctx->last_xmit) {
+        logger_on_kcp_retrans((uint64_t)(xmit - ctx->last_xmit));
+    }
+    ctx->last_xmit = xmit;
+
+    uint64_t t1 = omni_now_ms();
+    logger_log("DEBUG", "kcp",
+               "update ms=%llu cwnd=%u ssthresh=%u rmt_wnd=%u snd_wnd=%u rcv_wnd=%u "
+               "rx_srtt=%u rx_rto=%u nsnd_buf=%u nsnd_que=%u nrcv_buf=%u nrcv_que=%u xmit=%u state=%u",
+               (unsigned long long)(t1 - t0),
+               (unsigned)ctx->kcp->cwnd,
+               (unsigned)ctx->kcp->ssthresh,
+               (unsigned)ctx->kcp->rmt_wnd,
+               (unsigned)ctx->kcp->snd_wnd,
+               (unsigned)ctx->kcp->rcv_wnd,
+               (unsigned)ctx->kcp->rx_srtt,
+               (unsigned)ctx->kcp->rx_rto,
+               (unsigned)ctx->kcp->nsnd_buf,
+               (unsigned)ctx->kcp->nsnd_que,
+               (unsigned)ctx->kcp->nrcv_buf,
+               (unsigned)ctx->kcp->nrcv_que,
+               (unsigned)ctx->kcp->xmit,
+               (unsigned)ctx->kcp->state);
 }
 
 static ssize_t kcp_send(OmniContext *c, const void *buf, size_t len)
@@ -124,6 +152,7 @@ static ssize_t kcp_send(OmniContext *c, const void *buf, size_t len)
     struct KcpContext *ctx = (struct KcpContext *)c;
     if (!ctx || !ctx->kcp) return OMNI_ERR_PARAM;
 
+    uint64_t t0 = omni_now_ms();
     int rc = ikcp_send(ctx->kcp, (const char *)buf, (int)len);
     if (rc < 0) {
         logger_log("ERROR", "kcp", "ikcp_send_failed rc=%d", rc);
@@ -132,6 +161,10 @@ static ssize_t kcp_send(OmniContext *c, const void *buf, size_t len)
 
     /* 驱动一次 flush */
     kcp_update_loop(ctx);
+    uint64_t t1 = omni_now_ms();
+    logger_on_proto_send_latency(t1 - t0);
+    logger_log("DEBUG", "kcp", "send payload_bytes=%zu proto_ms=%llu waitsnd=%d",
+               len, (unsigned long long)(t1 - t0), ikcp_waitsnd(ctx->kcp));
     return (ssize_t)len;
 }
 
@@ -140,12 +173,17 @@ static ssize_t kcp_recv(OmniContext *c, void *buf, size_t len)
     struct KcpContext *ctx = (struct KcpContext *)c;
     if (!ctx || !ctx->kcp) return OMNI_ERR_PARAM;
 
+    uint64_t t0 = omni_now_ms();
     kcp_update_loop(ctx);
 
     int n = ikcp_recv(ctx->kcp, (char *)buf, (int)len);
     if (n < 0) {
         return 0; /* 暂无数据 */
     }
+    uint64_t t1 = omni_now_ms();
+    logger_on_proto_recv_latency(t1 - t0);
+    logger_log("DEBUG", "kcp", "recv payload_bytes=%d proto_ms=%llu",
+               n, (unsigned long long)(t1 - t0));
     return (ssize_t)n;
 }
 

src/protocols/tcp_impl.c

@@ -10,6 +10,7 @@
 #include <arpa/inet.h>
 #include <errno.h>
 #include <netinet/tcp.h>
+#include <netinet/in.h>
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
@@ -17,10 +18,52 @@
 #include <sys/types.h>
 #include <unistd.h>
 
+/* Linux 下 TCP_INFO 定义通常已在 <netinet/tcp.h> 提供，避免引入 <linux/tcp.h> 重定义 */
+
 struct TcpContext {
     int fd;
 };
 
+#ifdef __linux__
+static void tcp_log_info(int fd, const char *tag)
+{
+    struct tcp_info ti;
+    socklen_t len = sizeof(ti);
+    if (getsockopt(fd, IPPROTO_TCP, TCP_INFO, &ti, &len) != 0) {
+        return;
+    }
+
+    /* 注意：tcpi_rtt 单位通常为微秒（Linux），这里转 ms 仅用于日志观察 */
+    unsigned long long rtt_ms = (unsigned long long)(ti.tcpi_rtt / 1000u);
+    unsigned long long rttvar_ms = (unsigned long long)(ti.tcpi_rttvar / 1000u);
+
+    logger_log("INFO", "tcpinfo",
+               "tag=%s state=%u retransmits=%u probes=%u backoff=%u "
+               "rto=%u ato=%u rtt_ms=%llu rttvar_ms=%llu "
+               "snd_cwnd=%u snd_ssthresh=%u snd_mss=%u rcv_mss=%u "
+               "lost=%u retrans=%u fackets=%u "
+               "last_data_sent_ms=%u last_data_recv_ms=%u",
+               tag ? tag : "sample",
+               (unsigned)ti.tcpi_state,
+               (unsigned)ti.tcpi_retransmits,
+               (unsigned)ti.tcpi_probes,
+               (unsigned)ti.tcpi_backoff,
+               (unsigned)ti.tcpi_rto,
+               (unsigned)ti.tcpi_ato,
+               rtt_ms,
+               rttvar_ms,
+               (unsigned)ti.tcpi_snd_cwnd,
+               (unsigned)ti.tcpi_snd_ssthresh,
+               (unsigned)ti.tcpi_snd_mss,
+               (unsigned)ti.tcpi_rcv_mss,
+               (unsigned)ti.tcpi_lost,
+               (unsigned)ti.tcpi_retrans,
+               (unsigned)ti.tcpi_fackets,
+               (unsigned)ti.tcpi_last_data_sent,
+               (unsigned)ti.tcpi_last_data_recv);
+}
+#endif
+
 static int tcp_set_nodelay(int fd)
 {
     int flag = 1;
@@ -178,6 +221,7 @@ static ssize_t tcp_send(OmniContext *c, const void *buf, size_t len)
     struct TcpContext *ctx = (struct TcpContext *)c;
     if (!ctx || ctx->fd < 0) return OMNI_ERR_PARAM;
 
+    uint64_t t0 = omni_now_ms();
     MsgHeader hdr;
     hdr.magic = htonl(MSG_MAGIC);
     hdr.length = htonl((uint32_t)len);
@@ -196,6 +240,13 @@ static ssize_t tcp_send(OmniContext *c, const void *buf, size_t len)
         return OMNI_ERR_IO;
     }
 
+    uint64_t t1 = omni_now_ms();
+    logger_on_proto_send_latency(t1 - t0);
+    logger_log("DEBUG", "tcp", "send payload_bytes=%zu header_bytes=%zu proto_ms=%llu",
+               len, (size_t)MSG_HEADER_SIZE, (unsigned long long)(t1 - t0));
+#ifdef __linux__
+    tcp_log_info(ctx->fd, "after_send");
+#endif
     return (ssize_t)len;
 }
 
@@ -204,6 +255,7 @@ static ssize_t tcp_recv(OmniContext *c, void *buf, size_t len)
     struct TcpContext *ctx = (struct TcpContext *)c;
     if (!ctx || ctx->fd < 0) return OMNI_ERR_PARAM;
 
+    uint64_t t0 = omni_now_ms();
     uint8_t header_buf[MSG_HEADER_SIZE];
     ssize_t n1 = tcp_read_n(ctx->fd, header_buf, MSG_HEADER_SIZE);
     if (n1 <= 0) {
@@ -233,6 +285,13 @@ static ssize_t tcp_recv(OmniContext *c, void *buf, size_t len)
         return OMNI_ERR_IO;
     }
 
+    uint64_t t1 = omni_now_ms();
+    logger_on_proto_recv_latency(t1 - t0);
+    logger_log("DEBUG", "tcp", "recv payload_bytes=%u header_bytes=%zu proto_ms=%llu",
+               payload_len, (size_t)MSG_HEADER_SIZE, (unsigned long long)(t1 - t0));
+#ifdef __linux__
+    tcp_log_info(ctx->fd, "after_recv");
+#endif
     return (ssize_t)payload_len;
 }