From 1f1a8707d75f7906036e663e26d7b6910ef9d9d3 Mon Sep 17 00:00:00 2001 From: Michael Vrable Date: Wed, 20 Jan 2010 16:11:34 -0800 Subject: [PATCH] Track time to process each NFS RPC received. --- nfs3/nfs3_prot.h | 3 +++ nfs3/rpc.c | 9 +++++++++ 2 files changed, 12 insertions(+) diff --git a/nfs3/nfs3_prot.h b/nfs3/nfs3_prot.h index 42b46ba..6a3e316 100644 --- 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 --- 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) { -- 2.20.1