Invoke the stats_cb callback for CALLs when we have written the PDU t…

…o network instead of when it is enqueued. Also change the pdu stats timestamps to us instead of ms. Signed-off-by: Ronnie Sahlberg <ronniesahlberg@gmail.com>
sahlberg · Aug 16, 2024 · 768f88f · 768f88f
1 parent 93aead0
commit 768f88f
Show file tree

Hide file tree

Showing 7 changed files with 25 additions and 9 deletions.
diff --git a/examples/nfs-nfsstat.c b/examples/nfs-nfsstat.c
@@ -149,7 +149,7 @@ void print_final_stats(void)
 	int i;
 	uint64_t avg;
 
-	printf("%-12s %5s %6s %21s %25s\n", "PROCEDURE", "COUNT", "ERRORS", "MAX RESPONSE TIME(ms)", "AVERAGE RESPONSE TIME(ms)");
+	printf("%-12s %5s %6s %21s %25s\n", "PROCEDURE", "COUNT", "ERRORS", "MAX RESPONSE TIME(us)", "AVERAGE RESPONSE TIME(us)");
 	for (i = 0; i < 22; i++) {
 		avg = 0;
 		if (nfs3stats[i].count) {

diff --git a/examples/nfs-stats-cb.c b/examples/nfs-stats-cb.c
@@ -86,7 +86,7 @@ free_file_context(struct file_context *file_context)
 void stats_cb(struct rpc_context *rpc,
 	      struct rpc_pdu_stats *data, void *private_data)
 {
-    printf("%s XID:%08x %d/%d/%d Size:%d Status:%d %dms\n",
+    printf("%s XID:%08x %d/%d/%d Size:%d Status:%d %dus\n",
 	   data->direction == CALL ? "CALL" : "REPLY",
 	   data->xid,
 	   data->prog, data->vers, data->proc,

diff --git a/include/libnfs-private.h b/include/libnfs-private.h
@@ -633,6 +633,7 @@ int rpc_add_fragment(struct rpc_context *rpc, char *data, uint32_t size);
 void rpc_free_all_fragments(struct rpc_context *rpc);
 int rpc_is_udp_socket(struct rpc_context *rpc);
 uint64_t rpc_current_time(void);
+uint64_t rpc_current_time_us(void);
 
 void *zdr_malloc(ZDR *zdrs, uint32_t size);
 

diff --git a/include/nfsc/libnfs-raw.h b/include/nfsc/libnfs-raw.h
@@ -130,8 +130,9 @@ struct rpc_pdu_stats {
         uint32_t prog;
         uint32_t vers;
         uint32_t proc;
-        uint64_t enqueue_time;   /* ms */
-        uint64_t response_time;  /* ms, only valid in replies */
+        uint64_t enqueue_time;   /* us, when the pdu was enqueued */
+        uint64_t send_time;      /* us, when the pdu was sent */
+        uint64_t response_time;  /* us, only valid in replies */
 };
 typedef void (*rpc_stats_cb)(struct rpc_context *rpc,
                              struct rpc_pdu_stats *data,

diff --git a/lib/init.c b/lib/init.c
@@ -82,6 +82,18 @@ uint64_t rpc_current_time(void)
 #endif
 }
 
+uint64_t rpc_current_time_us(void)
+{
+#ifdef HAVE_CLOCK_GETTIME
+	struct timespec tp;
+
+	clock_gettime(CLOCK_MONOTONIC_COARSE, &tp);
+	return (uint64_t)tp.tv_sec * 1000000 + tp.tv_nsec / 1000;
+#else
+	return (uint64_t)time(NULL) * 1000000;
+#endif
+}
+
 int rpc_set_hash_size(struct rpc_context *rpc, int hashes)
 {
 	uint32_t i;

diff --git a/lib/pdu.c b/lib/pdu.c
@@ -566,7 +566,7 @@ int rpc_queue_pdu(struct rpc_context *rpc, struct rpc_pdu *pdu)
         recordmarker = htonl(size | 0x80000000);
 	memcpy(pdu->out.iov[0].buf, &recordmarker, 4);
 
-        pdu->pdu_stats.enqueue_time = rpc_current_time();
+        pdu->pdu_stats.enqueue_time = rpc_current_time_us();
         pdu->pdu_stats.size = size;
         pdu->pdu_stats.xid = pdu->msg.xid;
         pdu->pdu_stats.direction = CALL;
@@ -575,9 +575,6 @@ int rpc_queue_pdu(struct rpc_context *rpc, struct rpc_pdu *pdu)
         pdu->pdu_stats.vers = pdu->msg.body.cbody.vers;
         pdu->pdu_stats.proc = pdu->msg.body.cbody.proc;
         pdu->pdu_stats.response_time = 0;
-        if (rpc->stats_cb) {
-                rpc->stats_cb(rpc, &pdu->pdu_stats, rpc->stats_private_data);
-        }
 
 	/*
 	 * For udp we dont queue, we just send it straight away.
@@ -885,7 +882,7 @@ static int rpc_process_reply(struct rpc_context *rpc, ZDR *zdr)
         pdu->pdu_stats.size = rpc->rm_xid[0];
         pdu->pdu_stats.direction = REPLY;
         pdu->pdu_stats.status = msg.body.rbody.stat;
-        pdu->pdu_stats.response_time = rpc_current_time() - pdu->pdu_stats.enqueue_time;
+        pdu->pdu_stats.response_time = rpc_current_time_us() - pdu->pdu_stats.send_time;
         if (rpc->stats_cb) {
                 rpc->stats_cb(rpc, &pdu->pdu_stats, rpc->stats_private_data);
         }

diff --git a/lib/socket.c b/lib/socket.c
@@ -420,6 +420,11 @@ rpc_write_to_socket(struct rpc_context *rpc)
                                 hash = rpc_hash_xid(rpc, pdu->xid);
                                 rpc_enqueue(&rpc->waitpdu[hash], pdu);
                                 rpc->waitpdu_len++;
+
+                                pdu->pdu_stats.send_time = rpc_current_time_us();
+                                if (rpc->stats_cb) {
+                                        rpc->stats_cb(rpc, &pdu->pdu_stats, rpc->stats_private_data);
+                                }
                         } else {
                                 pdu->out.num_done += count;
                                 break;