latency优化 + readme修改

src/spdk_engine/io_engine.c

@@ -8,8 +8,11 @@
 #include <stdint.h>
 #include <stdlib.h>
 #include <string.h>
+#include <stdio.h>
 #include <sys/socket.h>
+#include <sys/uio.h>
 #include <sys/un.h>
+#include <time.h>
 #include <unistd.h>
 
 
@@ -28,6 +31,154 @@ static __thread struct ipc_client_ctx g_ipc_tls = {
     .rx_len = 0,
 };
 
+static uint64_t now_mono_ns(void) {
+    struct timespec ts;
+
+    clock_gettime(CLOCK_MONOTONIC, &ts);
+    return (uint64_t)ts.tv_sec * 1000000000ULL + (uint64_t)ts.tv_nsec;
+}
+
+static int latency_trace_enabled(void) {
+    static int inited = 0;
+    static int enabled = 0;
+    const char *v;
+
+    if (!inited) {
+        v = getenv("ZVFS_TRACE_LATENCY");
+        enabled = (v && v[0] != '\0' && strcmp(v, "0") != 0);
+        inited = 1;
+    }
+
+    return enabled;
+}
+
+static uint64_t ns_to_us(uint64_t ns) {
+    return ns / 1000ULL;
+}
+
+static uint64_t ns_diff(uint64_t end, uint64_t start) {
+    return (end >= start) ? (end - start) : 0;
+}
+
+static void maybe_log_latency_trace(const struct zvfs_req *req, const struct zvfs_resp *resp,
+                                    uint64_t client_start_ns, uint64_t client_send_done_ns,
+                                    uint64_t client_recv_ns,
+                                    uint64_t client_parse_done_ns) {
+    uint64_t total_ns;
+    uint64_t server_ns;
+    uint64_t residual_ns;
+    uint64_t client_to_server_ns;
+    uint64_t client_send_ns;
+    uint64_t server_rx_wait_ns;
+    uint64_t server_to_client_ns;
+    uint64_t resp_wait_ns;
+    uint64_t client_parse_ns;
+    uint64_t rx_to_dispatch_ns;
+    uint64_t dispatch_to_spdk_ns;
+    uint64_t spdk_ns;
+    uint64_t spdk_post_ns;
+    uint64_t wake_write_ns;
+    uint64_t wake_sched_ns;
+    uint64_t wake_to_tx_ns;
+    uint64_t reply_q_ns;
+    uint64_t cq_wait_ns;
+
+    if (!latency_trace_enabled() || !req || !resp) {
+        return;
+    }
+    if (resp->status != 0 || (resp->trace.flags & ZVFS_RESP_TRACE_F_VALID) == 0) {
+        return;
+    }
+    if (req->opcode != ZVFS_OP_WRITE && req->opcode != ZVFS_OP_SYNC_MD) {
+        return;
+    }
+
+    total_ns = ns_diff(client_parse_done_ns, client_start_ns);
+    server_ns = ns_diff(resp->trace.resp_tx_ns, resp->trace.req_rx_ns);
+    residual_ns = (total_ns >= server_ns) ? (total_ns - server_ns) : 0;
+    client_to_server_ns = ns_diff(resp->trace.req_rx_ns, client_start_ns);
+    client_send_ns = ns_diff(client_send_done_ns, client_start_ns);
+    server_rx_wait_ns = ns_diff(resp->trace.req_rx_ns, client_send_done_ns);
+    server_to_client_ns = ns_diff(client_parse_done_ns, resp->trace.resp_tx_ns);
+    resp_wait_ns = ns_diff(client_recv_ns, resp->trace.resp_tx_ns);
+    client_parse_ns = ns_diff(client_parse_done_ns, client_recv_ns);
+    rx_to_dispatch_ns = ns_diff(resp->trace.dispatch_ns, resp->trace.req_rx_ns);
+    dispatch_to_spdk_ns = ns_diff(resp->trace.spdk_start_ns, resp->trace.dispatch_ns);
+    spdk_ns = ns_diff(resp->trace.spdk_done_ns, resp->trace.spdk_start_ns);
+    spdk_post_ns = ns_diff(resp->trace.cq_push_ns, resp->trace.spdk_done_ns);
+    wake_write_ns = ns_diff(resp->trace.wake_write_ns, resp->trace.cq_push_ns);
+    wake_sched_ns = ns_diff(resp->trace.reactor_wake_ns, resp->trace.wake_write_ns);
+    wake_to_tx_ns = ns_diff(resp->trace.resp_tx_ns, resp->trace.reactor_wake_ns);
+    reply_q_ns = ns_diff(resp->trace.resp_tx_ns, resp->trace.spdk_done_ns);
+    cq_wait_ns = ns_diff(resp->trace.resp_tx_ns, resp->trace.cq_push_ns);
+
+    if (req->opcode == ZVFS_OP_WRITE) {
+        uint64_t phase1_ns = 0;
+        uint64_t phase2_ns = spdk_ns;
+
+        if ((resp->trace.flags & ZVFS_RESP_TRACE_F_PHASE1_VALID) != 0) {
+            phase1_ns = ns_diff(resp->trace.phase1_done_ns, resp->trace.spdk_start_ns);
+            phase2_ns = ns_diff(resp->trace.spdk_done_ns, resp->trace.phase1_done_ns);
+        }
+
+        fprintf(stderr,
+                "[zvfs][trace][WRITE] total=%luus server=%luus residual=%luus "
+                "c2s=%luus send=%luus server_rx_wait=%luus "
+                "s2c=%luus resp_wait=%luus parse=%luus "
+                "rx_dispatch=%luus dispatch_spdk=%luus spdk=%luus "
+                "phase1=%luus phase2=%luus spdk_post=%luus "
+                "kick=%luus wake_sched=%luus wake_to_tx=%luus "
+                "reply_q=%luus cq_wait=%luus\n",
+                (unsigned long)ns_to_us(total_ns),
+                (unsigned long)ns_to_us(server_ns),
+                (unsigned long)ns_to_us(residual_ns),
+                (unsigned long)ns_to_us(client_to_server_ns),
+                (unsigned long)ns_to_us(client_send_ns),
+                (unsigned long)ns_to_us(server_rx_wait_ns),
+                (unsigned long)ns_to_us(server_to_client_ns),
+                (unsigned long)ns_to_us(resp_wait_ns),
+                (unsigned long)ns_to_us(client_parse_ns),
+                (unsigned long)ns_to_us(rx_to_dispatch_ns),
+                (unsigned long)ns_to_us(dispatch_to_spdk_ns),
+                (unsigned long)ns_to_us(spdk_ns),
+                (unsigned long)ns_to_us(phase1_ns),
+                (unsigned long)ns_to_us(phase2_ns),
+                (unsigned long)ns_to_us(spdk_post_ns),
+                (unsigned long)ns_to_us(wake_write_ns),
+                (unsigned long)ns_to_us(wake_sched_ns),
+                (unsigned long)ns_to_us(wake_to_tx_ns),
+                (unsigned long)ns_to_us(reply_q_ns),
+                (unsigned long)ns_to_us(cq_wait_ns));
+        return;
+    }
+
+    fprintf(stderr,
+            "[zvfs][trace][SYNC_MD] total=%luus server=%luus residual=%luus "
+            "c2s=%luus send=%luus server_rx_wait=%luus "
+            "s2c=%luus resp_wait=%luus parse=%luus "
+            "rx_dispatch=%luus dispatch_spdk=%luus spdk=%luus "
+            "spdk_post=%luus kick=%luus wake_sched=%luus wake_to_tx=%luus "
+            "reply_q=%luus cq_wait=%luus\n",
+            (unsigned long)ns_to_us(total_ns),
+            (unsigned long)ns_to_us(server_ns),
+            (unsigned long)ns_to_us(residual_ns),
+            (unsigned long)ns_to_us(client_to_server_ns),
+            (unsigned long)ns_to_us(client_send_ns),
+            (unsigned long)ns_to_us(server_rx_wait_ns),
+            (unsigned long)ns_to_us(server_to_client_ns),
+            (unsigned long)ns_to_us(resp_wait_ns),
+            (unsigned long)ns_to_us(client_parse_ns),
+            (unsigned long)ns_to_us(rx_to_dispatch_ns),
+            (unsigned long)ns_to_us(dispatch_to_spdk_ns),
+            (unsigned long)ns_to_us(spdk_ns),
+            (unsigned long)ns_to_us(spdk_post_ns),
+            (unsigned long)ns_to_us(wake_write_ns),
+            (unsigned long)ns_to_us(wake_sched_ns),
+            (unsigned long)ns_to_us(wake_to_tx_ns),
+            (unsigned long)ns_to_us(reply_q_ns),
+            (unsigned long)ns_to_us(cq_wait_ns));
+}
+
 static const char *zvfs_ipc_socket_path(void) {
     const char *path = getenv("ZVFS_SOCKET_PATH");
     if (path && path[0] != '\0') {
@@ -119,6 +270,40 @@ static int write_all(int fd, const uint8_t *buf, size_t len) {
     return 0;
 }
 
+static int writev_all(int fd, struct iovec *iov, int iovcnt) {
+    int idx = 0;
+
+    while (idx < iovcnt) {
+        ssize_t n = writev(fd, &iov[idx], iovcnt - idx);
+
+        if (n > 0) {
+            size_t remaining = (size_t)n;
+
+            while (idx < iovcnt && remaining >= iov[idx].iov_len) {
+                remaining -= iov[idx].iov_len;
+                idx++;
+            }
+
+            if (idx < iovcnt && remaining > 0) {
+                iov[idx].iov_base = (uint8_t *)iov[idx].iov_base + remaining;
+                iov[idx].iov_len -= remaining;
+            }
+            continue;
+        }
+
+        if (n < 0 && errno == EINTR) {
+            continue;
+        }
+
+        if (n == 0) {
+            errno = EPIPE;
+        }
+        return -1;
+    }
+
+    return 0;
+}
+
 static int try_pop_resp(struct ipc_client_ctx *ctx, struct zvfs_resp *resp) {
     size_t consumed = zvfs_deserialize_resp(ctx->rx_buf, ctx->rx_len, resp);
     if (consumed == 0) {
@@ -206,6 +391,10 @@ static int set_errno_by_status(int status) {
 
 static int ipc_do_req(struct zvfs_req *req, struct zvfs_resp *resp_out) {
     struct ipc_client_ctx *ctx = &g_ipc_tls;
+    uint64_t client_start_ns;
+    uint64_t client_send_done_ns;
+    uint64_t client_recv_ns;
+    uint64_t client_done_ns;
 
     if (ipc_ensure_buffers(ctx) != 0) {
         return -1;
@@ -215,22 +404,70 @@ static int ipc_do_req(struct zvfs_req *req, struct zvfs_resp *resp_out) {
         return -1;
     }
 
-    size_t tx_len = zvfs_serialize_req(req, ctx->tx_buf, ZVFS_IPC_BUF_SIZE);
-    if (tx_len == 0) {
-        errno = EMSGSIZE;
-        return -1;
+    client_start_ns = now_mono_ns();
+
+    if (req->opcode == ZVFS_OP_WRITE) {
+        struct zvfs_req_header header = {
+            .opcode = req->opcode,
+            .payload_len = (uint32_t)(ZVFS_REQ_WRITE_FIXED_WIRE_SIZE + req->length),
+        };
+        struct zvfs_req_write_body body = {
+            .handle_id = req->handle_id,
+            .offset = req->offset,
+            .length = req->length,
+            .flags = req->write_flags,
+            .data = req->data,
+        };
+        uint8_t hdr_buf[ZVFS_REQ_HEADER_WIRE_SIZE];
+        uint8_t meta_buf[ZVFS_REQ_WRITE_FIXED_WIRE_SIZE];
+        struct iovec iov[3];
+
+        if (req->length > UINT32_MAX) {
+            errno = EMSGSIZE;
+            return -1;
+        }
+        if (zvfs_serialize_req_header(&header, hdr_buf, sizeof(hdr_buf)) != sizeof(hdr_buf) ||
+            zvfs_serialize_req_write_fixed(&body, meta_buf, sizeof(meta_buf)) != sizeof(meta_buf)) {
+            errno = EMSGSIZE;
+            return -1;
+        }
+
+        iov[0].iov_base = hdr_buf;
+        iov[0].iov_len = sizeof(hdr_buf);
+        iov[1].iov_base = meta_buf;
+        iov[1].iov_len = sizeof(meta_buf);
+        iov[2].iov_base = req->data;
+        iov[2].iov_len = (size_t)req->length;
+
+        if (writev_all(ctx->fd, iov, 3) != 0) {
+            ipc_close_conn(ctx);
+            return -1;
+        }
+    } else {
+        size_t tx_len = zvfs_serialize_req(req, ctx->tx_buf, ZVFS_IPC_BUF_SIZE);
+        if (tx_len == 0) {
+            errno = EMSGSIZE;
+            return -1;
+        }
+
+        if (write_all(ctx->fd, ctx->tx_buf, tx_len) != 0) {
+            ipc_close_conn(ctx);
+            return -1;
+        }
     }
 
-    if (write_all(ctx->fd, ctx->tx_buf, tx_len) != 0) {
-        ipc_close_conn(ctx);
-        return -1;
-    }
+    client_send_done_ns = now_mono_ns();
 
     if (recv_one_resp(ctx, resp_out) != 0) {
         ipc_close_conn(ctx);
         return -1;
     }
 
+    client_recv_ns = now_mono_ns();
+    client_done_ns = now_mono_ns();
+    maybe_log_latency_trace(req, resp_out, client_start_ns, client_send_done_ns,
+                            client_recv_ns, client_done_ns);
+
     return set_errno_by_status(resp_out->status);
 }