From d7d143ef0ccf0f49a8fd23a3c76bc68c0b04e07e Mon Sep 17 00:00:00 2001 From: Michael Vrable Date: Mon, 22 Mar 2010 15:07:21 -0700 Subject: [PATCH] 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. --- bluesky/bluesky-private.h | 1 + bluesky/store-s3.c | 1 + bluesky/store.c | 9 +++++++-- 3 files changed, 9 insertions(+), 2 deletions(-) diff --git a/bluesky/bluesky-private.h b/bluesky/bluesky-private.h index 852b04e..7eaba1e 100644 --- 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 --- 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 --- 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" -- 2.20.1