diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..9ce684e --- /dev/null +++ b/.gitignore @@ -0,0 +1,3 @@ +*.o +build/ +*.out diff --git a/ikcp.o b/ikcp.o deleted file mode 100644 index 43654d2..0000000 Binary files a/ikcp.o and /dev/null differ diff --git a/include/logger.h b/include/logger.h index a8ea804..36fdb1b 100644 --- a/include/logger.h +++ b/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); diff --git a/kcp_impl.o b/kcp_impl.o deleted file mode 100644 index c0883c5..0000000 Binary files a/kcp_impl.o and /dev/null differ diff --git a/logger.o b/logger.o deleted file mode 100644 index 8177274..0000000 Binary files a/logger.o and /dev/null differ diff --git a/network.o b/network.o deleted file mode 100644 index 782c1c7..0000000 Binary files a/network.o and /dev/null differ diff --git a/src/apps/test_main.c b/src/apps/test_main.c new file mode 100644 index 0000000..0aa63af --- /dev/null +++ b/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 +#include +#include +#include + +static void usage(const char *prog) +{ + fprintf(stderr, + "Usage:\n" + " %s -r server -p tcp|udp|kcp -P \n" + " %s -r client -p tcp|udp|kcp -P -H \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; +} + diff --git a/src/core/logger.c b/src/core/logger.c index 676d478..d283afb 100644 --- a/src/core/logger.c +++ b/src/core/logger.c @@ -9,19 +9,36 @@ #include #include #include +#include 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", - component ? component : "general"); + fprintf(fp, "level=%s component=%s ", lvl, comp); + 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) diff --git a/src/core/network.c b/src/core/network.c index e7493a0..b71618a 100644 --- a/src/core/network.c +++ b/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", - (int)ctx->proto, n); + logger_log("DEBUG", "network", "omni_send proto=%d bytes=%zd call_ms=%llu", + (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", - (int)ctx->proto, n); + logger_log("DEBUG", "network", "omni_recv proto=%d bytes=%zd call_ms=%llu", + (int)ctx->proto, n, (unsigned long long)(t1 - t0)); return n; } diff --git a/src/protocols/kcp_impl.c b/src/protocols/kcp_impl.c index 6b254eb..0e838d5 100644 --- a/src/protocols/kcp_impl.c +++ b/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; } diff --git a/src/protocols/tcp_impl.c b/src/protocols/tcp_impl.c index 3c7f60f..b0278aa 100644 --- a/src/protocols/tcp_impl.c +++ b/src/protocols/tcp_impl.c @@ -10,6 +10,7 @@ #include #include #include +#include #include #include #include @@ -17,10 +18,52 @@ #include #include +/* Linux 下 TCP_INFO 定义通常已在 提供，避免引入 重定义 */ + 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; } diff --git a/tcp_impl.o b/tcp_impl.o deleted file mode 100644 index 79355db..0000000 Binary files a/tcp_impl.o and /dev/null differ diff --git a/udp_impl.o b/udp_impl.o deleted file mode 100644 index ad95f38..0000000 Binary files a/udp_impl.o and /dev/null differ