X-Git-Url: http://git.vrable.net/?a=blobdiff_plain;f=nfs3%2Frpc.c;h=ae39154f3897a2dfe0fa6d2677fbb436f934989a;hb=5f2b6416e93119d1896f5fcf703af81a292cd2ad;hp=67175123fc9c1c90cdd9e2ad78d27fe1b812381d;hpb=3035b12250bf7b9eb0b67d41d5001ccd18683e52;p=bluesky.git

diff --git a/nfs3/rpc.c b/nfs3/rpc.c
index 6717512..ae39154 100644
--- a/nfs3/rpc.c
+++ b/nfs3/rpc.c
@@ -188,8 +188,6 @@ async_rpc_send_failure(RPCRequest *req, enum accept_stat stat)
 {
     struct rpc_fail_reply header;
 
-    fprintf(stderr, "Sending RPC failure status %d\n", stat);
-
     header.xid = htonl(req->xid);
     header.type = htonl(1);     /* REPLY */
     header.stat = htonl(MSG_ACCEPTED);
@@ -220,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);
@@ -238,13 +238,17 @@ async_rpc_send_reply(RPCRequest *req, void *result)
     header.accept_stat = 0;
 
     gsize msg_size = str->len;
-    printf("Have an RPC reply of size %zd bytes\n", msg_size);
     uint32_t fragment = htonl((msg_size + sizeof(header)) | 0x80000000);
     async_rpc_write(req->connection, (const char *)&fragment, sizeof(fragment));
     async_rpc_write(req->connection, (const char *)&header, sizeof(header));
     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);
 
@@ -298,6 +302,8 @@ nfs_program_3(RPCRequest *req)
     xdrproc_t _xdr_argument, _xdr_result;
     char *(*local)(char *, RPCRequest *);
 
+    printf("Dispatched NFS RPC message type %d\n", req->req_proc);
+
     switch (req->req_proc) {
     case NFSPROC3_NULL:
         _xdr_argument = (xdrproc_t) xdr_void;
@@ -452,6 +458,7 @@ nfs_program_3(RPCRequest *req)
     result = (*local)((char *)req->args, req);
 
     bluesky_flushd_invoke(fs);
+    bluesky_debug_dump(fs);
 
     return;
 }
@@ -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) {
@@ -540,8 +549,6 @@ static gboolean async_rpc_dispatch(RPCConnection *rpc)
     if (buf - msg->str > msg->len)
         return FALSE;
 
-    printf("Dispatching RPC procedure %d...\n", proc);
-
     req->raw_args = msg;
     req->raw_args_header_bytes = buf - msg->str;
     req->req_proc = ntohl(header->proc);
@@ -637,7 +644,6 @@ static gboolean async_rpc_do_read(GIOChannel *channel,
             rpc->frag_len = ntohl(rpc->frag_len);
             g_string_set_size(rpc->msgbuf, rpc->msgbuf->len - 4);
             rpc->frag_hdr_bytes = 0;
-            g_print("RPC fragment header: %08x\n", rpc->frag_len);
         }
     } else {
         /* We were reading in the fragment body. */
@@ -646,7 +652,6 @@ static gboolean async_rpc_do_read(GIOChannel *channel,
         if (rpc->frag_len = 0x80000000) {
             /* We have a complete message since this was the last fragment and
              * there are no more bytes in it.  Dispatch the message. */
-            g_print("Complete RPC message: %zd bytes\n", rpc->msgbuf->len);
             if (!async_rpc_dispatch(rpc)) {
                 fprintf(stderr, "Invalid RPC message, closing channel\n");
                 g_io_channel_shutdown(rpc->channel, TRUE, NULL);