Track time to process each NFS RPC received.

diff --git a/nfs3/nfs3_prot.h b/nfs3/nfs3_prot.h
index 42b46ba..6a3e316 100644 (file)
--- a/nfs3/nfs3_prot.h
+++ b/nfs3/nfs3_prot.h
@@ -661,6 +661,9 @@ typedef struct {
     /* The corresponding connection on which the request was made. */
     RPCConnection *connection;
 
+    /* Timining information for generating statistics about response times. */
+    int64_t time_start;
+
     /* Transaction ID of the request, in host byte order. */
     uint32_t xid;
 

diff --git a/nfs3/rpc.c b/nfs3/rpc.c
index 468c58c..ae39154 100644 (file)
--- a/nfs3/rpc.c
+++ b/nfs3/rpc.c
@@ -218,6 +218,8 @@ async_rpc_send_failure(RPCRequest *req, enum accept_stat stat)
 void
 async_rpc_send_reply(RPCRequest *req, void *result)
 {
+    bluesky_time_hires time_end;
+
     GString *str = g_string_new("");
     XDR xdr_out;
     xdr_string_create(&xdr_out, str, XDR_ENCODE);
@@ -242,6 +244,11 @@ async_rpc_send_reply(RPCRequest *req, void *result)
     async_rpc_write(req->connection, str->str, str->len);
     g_io_channel_flush(req->connection->channel, NULL);
 
+    time_end = bluesky_now_hires();
+
+    printf("RPC[%"PRIx32"]: time = %"PRId64" ns\n",
+           req->xid, time_end - req->time_start);
+
     /* Clean up. */
     g_string_free(str, TRUE);
 
@@ -487,6 +494,7 @@ struct rpc_auth {
  * and the transport should be closed. */
 static gboolean async_rpc_dispatch(RPCConnection *rpc)
 {
+    bluesky_time_hires time_start = bluesky_now_hires();
     int i;
     GString *msg = rpc->msgbuf;
     const char *buf = msg->str;
@@ -510,6 +518,7 @@ static gboolean async_rpc_dispatch(RPCConnection *rpc)
 
     RPCRequest *req = g_new0(RPCRequest, 1);
     req->connection = rpc;
+    req->time_start = time_start;
     req->xid = xid;
 
     if (ntohl(header->prog) != NFS_PROGRAM) {