From: Michael Vrable <mvrable@cs.ucsd.edu>
Date: Tue, 23 Nov 2010 17:53:18 +0000 (-0800)
Subject: Start to add request time profiling.
X-Git-Url: http://git.vrable.net/?p=bluesky.git;a=commitdiff_plain;h=5dccfe81a6b4521383acf0b675374493950d09db

Start to add request time profiling.

Allow a "profile" object to be created when a request is received, and
track the time at which various events occur when handling the request.
---

diff --git a/bluesky/bluesky-private.h b/bluesky/bluesky-private.h
index 547fb59..f945a93 100644
--- a/bluesky/bluesky-private.h
+++ b/bluesky/bluesky-private.h
@@ -138,6 +138,10 @@ struct BlueSkyStoreAsync {
     bluesky_time_hires exec_time;   /* Time processing started on operation. */
 
     gpointer store_private;     /* For use by the storage implementation */
+
+    /* If storage operations should be charged to any particular profile, which
+     * one? */
+    BlueSkyProfile *profile;
 };
 
 /* Support for notification lists.  These are lists of one-shot functions which
diff --git a/bluesky/bluesky.h b/bluesky/bluesky.h
index fd0b610..e83c609 100644
--- a/bluesky/bluesky.h
+++ b/bluesky/bluesky.h
@@ -363,6 +363,19 @@ void bluesky_flushd_thread_launch(BlueSkyFS *fs);
 
 void bluesky_debug_dump(BlueSkyFS *fs);
 
+/* Request response time tracking. */
+typedef struct BlueSkyProfile {
+    char *description;
+    GList *events;
+} BlueSkyProfile;
+
+BlueSkyProfile *bluesky_profile_new();
+void bluesky_profile_free(BlueSkyProfile *profile);
+void bluesky_profile_add_event(BlueSkyProfile *profile, char *message);
+void bluesky_profile_print(BlueSkyProfile *profile);
+BlueSkyProfile *bluesky_profile_get();
+void bluesky_profile_set(BlueSkyProfile *profile);
+
 #ifdef __cplusplus
 }
 #endif
diff --git a/bluesky/cloudlog.c b/bluesky/cloudlog.c
index 0668da7..b6ee07f 100644
--- a/bluesky/cloudlog.c
+++ b/bluesky/cloudlog.c
@@ -353,6 +353,10 @@ void bluesky_cloudlog_fetch(BlueSkyCloudLog *log)
         bluesky_string_unref(raw);
     }
 
+    BlueSkyProfile *profile = bluesky_profile_get();
+    if (profile != NULL)
+        bluesky_profile_add_event(profile, g_strdup_printf("Fetch log entry"));
+
     /* At this point all metadata should be available and we need only remap
      * the object data. */
     log->data = bluesky_log_map_object(log, TRUE);
@@ -361,6 +365,8 @@ void bluesky_cloudlog_fetch(BlueSkyCloudLog *log)
         g_error("Unable to fetch cloudlog entry!");
     }
 
+    if (profile != NULL)
+        bluesky_profile_add_event(profile, g_strdup_printf("Fetch complete"));
     g_cond_broadcast(log->cond);
 }
 
diff --git a/bluesky/store.c b/bluesky/store.c
index 5d9dc43..1ee3916 100644
--- a/bluesky/store.c
+++ b/bluesky/store.c
@@ -112,6 +112,7 @@ BlueSkyStoreAsync *bluesky_store_async_new(BlueSkyStore *store)
     async->notifier_count = 0;
     async->barrier = NULL;
     async->store_private = NULL;
+    async->profile = bluesky_profile_get();
 
     return async;
 }
@@ -255,6 +256,18 @@ void bluesky_store_async_mark_complete(BlueSkyStoreAsync *async)
         g_thread_pool_push(notifier_thread_pool, nl, NULL);
     }
 
+    if (async->profile) {
+        bluesky_profile_add_event(
+            async->profile,
+            g_strdup_printf("%s for %s complete",
+                            async->op == STORE_OP_GET ? "GET"
+                            : async->op == STORE_OP_PUT ? "PUT"
+                            : async->op == STORE_OP_DELETE ? "DELETE"
+                            : async->op == STORE_OP_BARRIER ? "BARRIER" : "???",
+                            async->key)
+        );
+    }
+
     if (bluesky_verbose) {
         g_log("bluesky/store", G_LOG_LEVEL_DEBUG,
               "[%p] complete: elapsed = %"PRIi64" ns, latency = %"PRIi64" ns",
@@ -280,6 +293,18 @@ void bluesky_store_async_submit(BlueSkyStoreAsync *async)
     // processing was started, if there could be a delay from submission time.
     async->exec_time = bluesky_now_hires();
 
+    if (async->profile) {
+        bluesky_profile_add_event(
+            async->profile,
+            g_strdup_printf("Start %s for %s",
+                            async->op == STORE_OP_GET ? "GET"
+                            : async->op == STORE_OP_PUT ? "PUT"
+                            : async->op == STORE_OP_DELETE ? "DELETE"
+                            : async->op == STORE_OP_BARRIER ? "BARRIER" : "???",
+                            async->key)
+        );
+    }
+
     if (bluesky_verbose) {
         g_log("bluesky/store", G_LOG_LEVEL_DEBUG, "[%p] submit: %s %s",
               async,
diff --git a/bluesky/util.c b/bluesky/util.c
index c5618b9..90eda70 100644
--- a/bluesky/util.c
+++ b/bluesky/util.c
@@ -336,3 +336,65 @@ void bluesky_rangeset_get_extents(BlueSkyRangeset *rangeset,
     item = (BlueSkyRangesetItem *)g_sequence_get(i);
     *length = (item->start + item->length) - *start;
 }
+
+/**** Request response-time tracking. ****/
+/* TODO: Locking */
+typedef struct {
+    bluesky_time_hires timestamp;
+    char *message;
+} RTEvent;
+
+BlueSkyProfile *bluesky_profile_new()
+{
+    return g_new0(BlueSkyProfile, 1);
+}
+
+void bluesky_profile_free(BlueSkyProfile *profile)
+{
+    while (profile->events != NULL) {
+        RTEvent *event = (RTEvent *)profile->events->data;
+        g_free(event->message);
+        g_free(event);
+        profile->events = g_list_delete_link(profile->events, profile->events);
+    }
+    g_free(profile->description);
+    g_free(profile);
+}
+
+void bluesky_profile_add_event(BlueSkyProfile *profile, char *message)
+{
+    g_return_if_fail(profile != NULL);
+
+    RTEvent *event = g_new(RTEvent, 1);
+    event->timestamp = bluesky_now_hires();
+    event->message = message;
+    profile->events = g_list_prepend(profile->events, event);
+}
+
+void bluesky_profile_print(BlueSkyProfile *profile)
+{
+    g_return_if_fail(profile != NULL);
+
+    g_print("Event Timeline: %s\n", profile->description);
+    GList *link = g_list_last(profile->events);
+    bluesky_time_hires last_time = 0;
+    while (link != NULL) {
+        RTEvent *event = (RTEvent *)link->data;
+        g_print("  [%"PRIi64" ns]: %s\n",
+                event->timestamp - last_time, event->message);
+        last_time = event->timestamp;
+        link = link->prev;
+    }
+}
+
+static GStaticPrivate per_thread_profile = G_STATIC_PRIVATE_INIT;
+
+BlueSkyProfile *bluesky_profile_get()
+{
+    return (BlueSkyProfile *)g_static_private_get(&per_thread_profile);
+}
+
+void bluesky_profile_set(BlueSkyProfile *profile)
+{
+    g_static_private_set(&per_thread_profile, profile, NULL);
+}
diff --git a/nfs3/nfs3_prot.h b/nfs3/nfs3_prot.h
index ab1125d..2f8a373 100644
--- a/nfs3/nfs3_prot.h
+++ b/nfs3/nfs3_prot.h
@@ -678,14 +678,16 @@ struct cleanup_list {
     struct cleanup_list *next;
 };
 
+struct BlueSkyProfile;
+
 /* Used to track a single outstanding RPC request.  Not all of the fields are
  * initially filled in, but more are filled in as the request is processed. */
 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;
+    /* To track the time to complete this request and a timing breakdown. */
+    struct BlueSkyProfile *profile;
 
     /* Transaction ID of the request, in host byte order. */
     uint32_t xid;
diff --git a/nfs3/rpc.c b/nfs3/rpc.c
index f753bd1..05d9722 100644
--- a/nfs3/rpc.c
+++ b/nfs3/rpc.c
@@ -149,6 +149,8 @@ async_rpc_send_failure(RPCRequest *req, enum accept_stat stat)
     async_rpc_flush(req->connection);
     g_mutex_unlock(req->connection->send_lock);
 
+    bluesky_profile_free(req->profile);
+
     if (req->args != NULL) {
         char buf[4];
         XDR xdr;
@@ -186,6 +188,9 @@ async_rpc_send_reply(RPCRequest *req, void *result)
 {
     bluesky_time_hires time_end;
 
+    bluesky_profile_add_event(req->profile,
+                              g_strdup("Start encoding NFS response"));
+
     GString *str = g_string_new("");
     XDR xdr_out;
     xdr_string_create(&xdr_out, str, XDR_ENCODE);
@@ -224,7 +229,12 @@ async_rpc_send_reply(RPCRequest *req, void *result)
            req->xid, time_end - req->time_start);
 #endif
 
+    bluesky_profile_add_event(req->profile,
+                              g_strdup("NFS reply sent"));
+    bluesky_profile_print(req->profile);
+
     /* Clean up. */
+    bluesky_profile_free(req->profile);
     g_string_free(str, TRUE);
 
     if (req->args != NULL) {
@@ -319,14 +329,15 @@ nfs_program_3(RPCRequest *req)
     xdrproc_t _xdr_argument, _xdr_result;
     char *(*local)(char *, RPCRequest *);
 
-#if 0
+    bluesky_profile_set(req->profile);
+
     if (req->req_proc < sizeof(nfs_proc_names) / sizeof(const char *)) {
-        printf("Dispatched NFS RPC message type %s\n",
-               nfs_proc_names[req->req_proc]);
-    } else {
-        printf("Dispatched unknown NFS RPC message type %d\n", req->req_proc);
+        bluesky_profile_add_event(
+            req->profile,
+            g_strdup_printf("Dispatching NFS %s request",
+                            nfs_proc_names[req->req_proc])
+        );
     }
-#endif
 
     switch (req->req_proc) {
     case NFSPROC3_NULL:
@@ -596,7 +607,8 @@ static gboolean async_rpc_dispatch(RPCConnection *rpc)
 
     RPCRequest *req = g_new0(RPCRequest, 1);
     req->connection = rpc;
-    req->time_start = time_start;
+    req->profile = bluesky_profile_new();
+    bluesky_profile_add_event(req->profile, g_strdup("Receive NFS request"));
     req->xid = xid;
 
     if (ntohl(header->prog) != NFS_PROGRAM) {