Better track latency of operations issued to S3.

Track the time from when the operation is sent to S3 as well, not just from
when it was submitted locally, as there may be some local queueing
happening.

diff --git a/bluesky/bluesky-private.h b/bluesky/bluesky-private.h
index 852b04e..7eaba1e 100644 (file)
--- a/bluesky/bluesky-private.h
+++ b/bluesky/bluesky-private.h
@@ -72,6 +72,7 @@ struct _BlueSkyStoreAsync {
     BlueSkyStoreAsync *barrier;
 
     bluesky_time_hires start_time;  /* Time operation was submitted. */
+    bluesky_time_hires exec_time;   /* Time processing started on operation. */
 
     gpointer store_private;     /* For use by the storage implementation */
 };

diff --git a/bluesky/store-s3.c b/bluesky/store-s3.c
index 7d70642..8ffc296 100644 (file)
--- a/bluesky/store-s3.c
+++ b/bluesky/store-s3.c
@@ -83,6 +83,7 @@ static void s3store_task(gpointer a, gpointer s)
     S3Store *store = (S3Store *)s;
 
     async->status = ASYNC_RUNNING;
+    async->exec_time = bluesky_now_hires();
 
     if (async->op == STORE_OP_GET) {
         struct get_info info;

diff --git a/bluesky/store.c b/bluesky/store.c
index eea44f2..50d7a21 100644 (file)
--- a/bluesky/store.c
+++ b/bluesky/store.c
@@ -197,6 +197,7 @@ void bluesky_store_async_mark_complete(BlueSkyStoreAsync *async)
     g_return_if_fail(async->status != ASYNC_COMPLETE);
 
     bluesky_time_hires elapsed = bluesky_now_hires() - async->start_time;
+    bluesky_time_hires latency = bluesky_now_hires() - async->exec_time;
 
     g_mutex_lock(async->store->lock);
     async->store->pending--;
@@ -217,8 +218,8 @@ void bluesky_store_async_mark_complete(BlueSkyStoreAsync *async)
     }
 
     g_log("bluesky/store", G_LOG_LEVEL_DEBUG,
-          "[%p] complete: elapsed = %"PRIi64" ns",
-          async, elapsed);
+          "[%p] complete: elapsed = %"PRIi64" ns, latency = %"PRIi64" ns",
+          async, elapsed, latency);
 }
 
 void bluesky_store_async_submit(BlueSkyStoreAsync *async)
@@ -227,6 +228,10 @@ void bluesky_store_async_submit(BlueSkyStoreAsync *async)
 
     async->start_time = bluesky_now_hires();
 
+    // Backends should fill this in with a better estimate of the actual time
+    // processing was started, if there could be a delay from submission time.
+    async->exec_time = bluesky_now_hires();
+
     g_log("bluesky/store", G_LOG_LEVEL_DEBUG, "[%p] submit: %s %s",
           async,
           async->op == STORE_OP_GET ? "GET"