Improve statistics gathered.
[bluesky.git] / bluesky / store.c
index 200cd3e..427112b 100644 (file)
@@ -24,6 +24,8 @@ struct _BlueSkyStore {
     GMutex *lock;
     GCond *cond_idle;
     int pending;                /* Count of operations not yet complete. */
+
+    struct bluesky_stats *stats_get, *stats_put;
 };
 
 GHashTable *store_implementations;
@@ -71,6 +73,10 @@ BlueSkyStore *bluesky_store_new(const gchar *type)
     store->lock = g_mutex_new();
     store->cond_idle = g_cond_new();
     store->pending = 0;
+    store->stats_get = bluesky_stats_new(g_strdup_printf("Store[%s]: GETS",
+                                                         type));
+    store->stats_put = bluesky_stats_new(g_strdup_printf("Store[%s]: PUTS",
+                                                         type));
     g_free(scheme);
     return store;
 }
@@ -97,6 +103,7 @@ BlueSkyStoreAsync *bluesky_store_async_new(BlueSkyStore *store)
     async->result = -1;
     async->notifiers = NULL;
     async->notifier_count = 0;
+    async->barrier = NULL;
     async->store_private = NULL;
 
     return async;
@@ -171,6 +178,22 @@ void bluesky_store_async_add_notifier(BlueSkyStoreAsync *async,
     g_mutex_unlock(async->lock);
 }
 
+static void op_complete(gpointer a, gpointer b)
+{
+    BlueSkyStoreAsync *barrier = (BlueSkyStoreAsync *)b;
+
+    bluesky_store_async_ref(barrier);
+    g_mutex_lock(barrier->lock);
+    barrier->store_private
+        = GINT_TO_POINTER(GPOINTER_TO_INT(barrier->store_private) - 1);
+    if (GPOINTER_TO_INT(barrier->store_private) == 0
+            && barrier->status != ASYNC_NEW) {
+        bluesky_store_async_mark_complete(barrier);
+    }
+    g_mutex_unlock(barrier->lock);
+    bluesky_store_async_unref(barrier);
+}
+
 /* Mark an asynchronous operation as complete.  This should only be called by
  * the store implementations.  The lock should be held when calling this
  * function.  Any notifier functions will be called, but in a separate thread
@@ -180,25 +203,41 @@ 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;
-
-    g_mutex_lock(async->store->lock);
-    async->store->pending--;
-    if (async->store->pending == 0)
-        g_cond_broadcast(async->store->cond_idle);
-    g_mutex_unlock(async->store->lock);
+    bluesky_time_hires latency = bluesky_now_hires() - async->exec_time;
+
+    if (async->op != STORE_OP_BARRIER) {
+        g_mutex_lock(async->store->lock);
+        async->store->pending--;
+        if (async->store->pending == 0)
+            g_cond_broadcast(async->store->cond_idle);
+        g_mutex_unlock(async->store->lock);
+    }
 
     async->status = ASYNC_COMPLETE;
     g_cond_broadcast(async->completion_cond);
 
+    if (async->barrier != NULL && async->notifiers == NULL)
+        op_complete(async, async->barrier);
+
     while (async->notifiers != NULL) {
         struct BlueSkyNotifierList *nl = async->notifiers;
         async->notifiers = nl->next;
         g_thread_pool_push(notifier_thread_pool, nl, NULL);
     }
 
-    g_log("bluesky/store", G_LOG_LEVEL_DEBUG,
-          "[%p] complete: elapsed = %"PRIi64" ns",
-          async, elapsed);
+    if (bluesky_verbose) {
+        g_log("bluesky/store", G_LOG_LEVEL_DEBUG,
+              "[%p] complete: elapsed = %"PRIi64" ns, latency = %"PRIi64" ns",
+              async, elapsed, latency);
+    }
+
+    if (async->data) {
+        if (async->op == STORE_OP_GET) {
+            bluesky_stats_add(async->store->stats_get, async->data->len);
+        } else if (async->op == STORE_OP_PUT) {
+            bluesky_stats_add(async->store->stats_put, async->data->len);
+        }
+    }
 }
 
 void bluesky_store_async_submit(BlueSkyStoreAsync *async)
@@ -207,13 +246,19 @@ void bluesky_store_async_submit(BlueSkyStoreAsync *async)
 
     async->start_time = bluesky_now_hires();
 
-    g_log("bluesky/store", G_LOG_LEVEL_DEBUG, "[%p] submit: %s %s",
-          async,
-          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);
+    // 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();
+
+    if (bluesky_verbose) {
+        g_log("bluesky/store", G_LOG_LEVEL_DEBUG, "[%p] submit: %s %s",
+              async,
+              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);
+    }
 
     /* Barriers are handled specially, and not handed down the storage
      * implementation layer. */
@@ -234,31 +279,26 @@ void bluesky_store_async_submit(BlueSkyStoreAsync *async)
         bluesky_store_async_wait(async);
 }
 
-static void op_complete(gpointer a, gpointer b)
-{
-    BlueSkyStoreAsync *barrier = (BlueSkyStoreAsync *)b;
-
-    bluesky_store_async_ref(barrier);
-    g_mutex_lock(barrier->lock);
-    barrier->store_private
-        = GINT_TO_POINTER(GPOINTER_TO_INT(barrier->store_private) - 1);
-    if (GPOINTER_TO_INT(barrier->store_private) == 0
-            && barrier->status != ASYNC_NEW) {
-        bluesky_store_async_mark_complete(barrier);
-    }
-    g_mutex_unlock(barrier->lock);
-    bluesky_store_async_unref(barrier);
-}
-
 /* Add the given operation to the barrier.  The barrier will not complete until
  * all operations added to it have completed. */
 void bluesky_store_add_barrier(BlueSkyStoreAsync *barrier,
                                BlueSkyStoreAsync *async)
 {
     g_return_if_fail(barrier->op == STORE_OP_BARRIER);
+
+    g_mutex_lock(barrier->lock);
     barrier->store_private
         = GINT_TO_POINTER(GPOINTER_TO_INT(barrier->store_private) + 1);
-    bluesky_store_async_add_notifier(async, op_complete, barrier);
+    g_mutex_unlock(barrier->lock);
+
+    g_mutex_lock(async->lock);
+    if (async->barrier == NULL) {
+        async->barrier = barrier;
+    } else {
+        g_warning("Adding async to more than one barrier!\n");
+        bluesky_store_async_add_notifier(async, op_complete, barrier);
+    }
+    g_mutex_unlock(async->lock);
 }
 
 static void notifier_task(gpointer n, gpointer s)
@@ -267,7 +307,11 @@ static void notifier_task(gpointer n, gpointer s)
 
     notifier->func(notifier->async, notifier->user_data);
     if (g_atomic_int_dec_and_test(&notifier->async->notifier_count)) {
+        g_mutex_lock(notifier->async->lock);
+        if (notifier->async->barrier != NULL)
+            op_complete(notifier->async, notifier->async->barrier);
         g_cond_broadcast(notifier->async->completion_cond);
+        g_mutex_unlock(notifier->async->lock);
     }
     bluesky_store_async_unref(notifier->async);
     g_free(notifier);
@@ -276,12 +320,17 @@ static void notifier_task(gpointer n, gpointer s)
 void bluesky_store_sync(BlueSkyStore *store)
 {
     g_mutex_lock(store->lock);
-    g_print("Waiting for pending store operations to complete...\n");
+    if (bluesky_verbose) {
+        g_log("bluesky/store", G_LOG_LEVEL_DEBUG,
+              "Waiting for pending store operations to complete...");
+    }
     while (store->pending > 0) {
         g_cond_wait(store->cond_idle, store->lock);
     }
     g_mutex_unlock(store->lock);
-    g_print("Operations are complete.\n");
+    if (bluesky_verbose) {
+        g_log("bluesky/store", G_LOG_LEVEL_DEBUG, "Operations are complete.");
+    }
 }
 
 /* Convenience wrappers that perform a single operation synchronously. */
@@ -453,8 +502,8 @@ static BlueSkyStoreImplementation filestore_impl = {
 void bluesky_store_init()
 {
     store_implementations = g_hash_table_new(g_str_hash, g_str_equal);
-    notifier_thread_pool = g_thread_pool_new(notifier_task, NULL, -1, FALSE,
-                                             NULL);
+    notifier_thread_pool = g_thread_pool_new(notifier_task, NULL,
+                                             bluesky_max_threads, FALSE, NULL);
     bluesky_store_register(&memstore_impl, "mem");
     bluesky_store_register(&filestore_impl, "file");
 }