Disable most debugging print messages; should help with performance.

diff --git a/bluesky/bluesky-private.h b/bluesky/bluesky-private.h
index ba9df02..5080e00 100644 (file)
--- a/bluesky/bluesky-private.h
+++ b/bluesky/bluesky-private.h
@@ -19,6 +19,8 @@
 extern "C" {
 #endif
 
+extern int bluesky_verbose;
+
 /* Target cache size levels. */
 extern int bluesky_watermark_low_dirty;
 extern int bluesky_watermark_medium_dirty;

diff --git a/bluesky/cache.c b/bluesky/cache.c
index f11168c..72c181a 100644 (file)
--- a/bluesky/cache.c
+++ b/bluesky/cache.c
@@ -21,8 +21,10 @@ static void writeback_complete(gpointer a, gpointer i)
 {
     BlueSkyInode *inode = (BlueSkyInode *)i;
 
-    g_log("bluesky/flushd", G_LOG_LEVEL_DEBUG,
-          "Writeback for inode %"PRIu64" complete", inode->inum);
+    if (bluesky_verbose) {
+        g_log("bluesky/flushd", G_LOG_LEVEL_DEBUG,
+              "Writeback for inode %"PRIu64" complete", inode->inum);
+    }
 
     g_mutex_lock(inode->lock);
 
@@ -145,8 +147,10 @@ static void flushd_dirty_inode(BlueSkyInode *inode)
         return;
     }
 
-    g_log("bluesky/flushd", G_LOG_LEVEL_DEBUG,
-          "Starting flush of inode %"PRIu64, inode->inum);
+    if (bluesky_verbose) {
+        g_log("bluesky/flushd", G_LOG_LEVEL_DEBUG,
+            "Starting flush of inode %"PRIu64, inode->inum);
+    }
     inode->change_pending = inode->change_count;
 
     /* Create a store barrier.  All operations part of the writeback will be
@@ -175,7 +179,10 @@ static void flushd_dirty(BlueSkyFS *fs)
             break;
         inode = fs->dirty_list.prev->data;
 
-        g_print("Considering flushing inode %"PRIu64"\n", inode->inum);
+        if (bluesky_verbose) {
+            g_log("bluesky/flushd", G_LOG_LEVEL_DEBUG,
+                  "Considering flushing inode %"PRIu64, inode->inum);
+        }
 
         /* Stop processing dirty inodes if we both have enough memory available
          * and the oldest inode is sufficiently new that it need not be flushed
@@ -227,8 +234,11 @@ static void flushd_clean(BlueSkyFS *fs)
             break;
         inode = fs->accessed_list.prev->data;
 
-        g_print("Considering dropping cached data for inode %"PRIu64"\n",
-                inode->inum);
+        if (bluesky_verbose) {
+            g_log("bluesky/flushd", G_LOG_LEVEL_DEBUG,
+                  "Considering dropping cached data for inode %"PRIu64,
+                  inode->inum);
+        }
 
         bluesky_inode_ref(inode);
 
@@ -276,10 +286,12 @@ void bluesky_flushd_invoke_conditional(BlueSkyFS *fs)
         && g_atomic_int_get(&fs->cache_total) < bluesky_watermark_high_total)
         return;
 
-    g_log("bluesky/flushd", G_LOG_LEVEL_DEBUG,
-          "Too much data; invoking flushd: dirty=%d total=%d",
-          g_atomic_int_get(&fs->cache_dirty),
-          g_atomic_int_get(&fs->cache_total));
+    if (bluesky_verbose) {
+        g_log("bluesky/flushd", G_LOG_LEVEL_DEBUG,
+              "Too much data; invoking flushd: dirty=%d total=%d",
+              g_atomic_int_get(&fs->cache_dirty),
+              g_atomic_int_get(&fs->cache_total));
+    }
 
     bluesky_flushd_invoke(fs);
 }

diff --git a/bluesky/file.c b/bluesky/file.c
index 8be3ea1..35ed1dc 100644 (file)
--- a/bluesky/file.c
+++ b/bluesky/file.c
@@ -31,7 +31,6 @@ void bluesky_block_touch(BlueSkyInode *inode, uint64_t i)
 
     switch (block->type) {
     case BLUESKY_BLOCK_ZERO:
-        g_print("Allocating zero block of size %zd\n", block_len);
         block->data = bluesky_string_new(g_malloc0(block_len), block_len);
         break;
     case BLUESKY_BLOCK_REF:
@@ -62,7 +61,10 @@ void bluesky_file_truncate(BlueSkyInode *inode, uint64_t size)
     if (size == inode->size)
         return;
 
-    g_print("Truncating file to %"PRIi64" bytes\n", size);
+    if (bluesky_verbose) {
+        g_log("bluesky/file", G_LOG_LEVEL_DEBUG,
+              "Truncating file to %"PRIi64" bytes", size);
+    }
 
     uint64_t blocks = (size + BLUESKY_BLOCK_SIZE - 1) / BLUESKY_BLOCK_SIZE;
 
@@ -129,8 +131,6 @@ void bluesky_file_truncate(BlueSkyInode *inode, uint64_t size)
 void bluesky_file_write(BlueSkyInode *inode, uint64_t offset,
                         const char *data, gint len)
 {
-    g_print("Write %d bytes at offset %"PRIi64"\n", len, offset);
-
     g_return_if_fail(inode->type == BLUESKY_REGULAR);
     g_return_if_fail(offset < inode->size);
     g_return_if_fail(len <= inode->size - offset);
@@ -159,8 +159,6 @@ void bluesky_file_write(BlueSkyInode *inode, uint64_t offset,
 void bluesky_file_read(BlueSkyInode *inode, uint64_t offset,
                        char *buf, gint len)
 {
-    g_print("Read %d bytes at offset %"PRIi64"\n", len, offset);
-
     if (len == 0 && offset <= inode->size)
         return;
 
@@ -174,8 +172,11 @@ void bluesky_file_read(BlueSkyInode *inode, uint64_t offset,
     uint64_t start_block, end_block;
     start_block = offset / BLUESKY_BLOCK_SIZE;
     end_block = (offset + len - 1) / BLUESKY_BLOCK_SIZE;
-    g_print("Start prefetch on blocks %"PRIi64" .. %"PRIi64"\n",
-            start_block, end_block);
+    if (bluesky_verbose) {
+        g_log("bluesky/file", G_LOG_LEVEL_DEBUG,
+              "Start prefetch on blocks %"PRIi64" .. %"PRIi64,
+              start_block, end_block);
+    }
     for (uint64_t i = start_block; i <= end_block; i++) {
         BlueSkyBlock *b = &g_array_index(inode->blocks, BlueSkyBlock,
                                          i);
@@ -185,7 +186,9 @@ void bluesky_file_read(BlueSkyInode *inode, uint64_t offset,
     bluesky_store_async_submit(barrier);
     bluesky_store_async_wait(barrier);
     bluesky_store_async_unref(barrier);
-    g_print("Prefetch complete.\n");
+    if (bluesky_verbose) {
+        g_log("bluesky/file", G_LOG_LEVEL_DEBUG, "Prefetch complete.");
+    }
 
     while (len > 0) {
         uint64_t block_num = offset / BLUESKY_BLOCK_SIZE;
@@ -299,12 +302,14 @@ void bluesky_file_drop_cached(BlueSkyInode *inode)
     for (int i = 0; i < inode->blocks->len; i++) {
         BlueSkyBlock *b = &g_array_index(inode->blocks, BlueSkyBlock, i);
         if (b->type == BLUESKY_BLOCK_CACHED) {
-            g_log("bluesky/cache", G_LOG_LEVEL_DEBUG,
-                  "Dropping block %d of inode %"PRIu64" from cache",
-                  i, inode->inum);
+            if (bluesky_verbose) {
+                g_log("bluesky/cache", G_LOG_LEVEL_DEBUG,
+                      "Dropping block %d of inode %"PRIu64" from cache",
+                      i, inode->inum);
+                g_log("bluesky/cache", G_LOG_LEVEL_DEBUG,
+                      "  (reference count was %d)", b->data->refcount);
+            }
 
-            g_log("bluesky/cache", G_LOG_LEVEL_DEBUG,
-                  "  (reference count was %d)", b->data->refcount);
             bluesky_string_unref(b->data);
             b->data = NULL;
             b->type = BLUESKY_BLOCK_REF;

diff --git a/bluesky/init.c b/bluesky/init.c
index 520ed57..fee9aad 100644 (file)
--- a/bluesky/init.c
+++ b/bluesky/init.c
@@ -13,6 +13,8 @@
 
 #include "bluesky-private.h"
 
+int bluesky_verbose = 0;
+
 BlueSkyOptions bluesky_options;
 
 /* Maximum number of threads to use in any particular thread pool, or -1 for no

diff --git a/bluesky/inode.c b/bluesky/inode.c
index ee63820..e15d5b7 100644 (file)
--- a/bluesky/inode.c
+++ b/bluesky/inode.c
@@ -129,8 +129,11 @@ void bluesky_inode_ref(BlueSkyInode *inode)
 void bluesky_inode_unref(BlueSkyInode *inode)
 {
     if (g_atomic_int_dec_and_test(&inode->refcount)) {
-        g_print("Reference count for inode %"PRIu64" dropped to zero.\n",
-                inode->inum);
+        if (bluesky_verbose) {
+            g_log("bluesky/inode", G_LOG_LEVEL_DEBUG,
+                  "Reference count for inode %"PRIu64" dropped to zero.",
+                  inode->inum);
+        }
 
         /* Sanity check: Is the inode clean? */
         if (inode->change_commit < inode->change_count
@@ -322,24 +325,34 @@ void bluesky_inode_do_sync(BlueSkyInode *inode)
     BlueSkyStoreAsync *barrier = bluesky_store_async_new(inode->fs->store);
     barrier->op = STORE_OP_BARRIER;
 
-    g_log("bluesky/inode", G_LOG_LEVEL_DEBUG,
-          "Synchronous writeback for inode %"PRIu64"...", inode->inum);
+    if (bluesky_verbose) {
+        g_log("bluesky/inode", G_LOG_LEVEL_DEBUG,
+            "Synchronous writeback for inode %"PRIu64"...", inode->inum);
+    }
     bluesky_inode_start_sync(inode, barrier);
     bluesky_store_async_submit(barrier);
     bluesky_store_async_wait(barrier);
     bluesky_store_async_unref(barrier);
-    g_log("bluesky/inode", G_LOG_LEVEL_DEBUG,
-          "Writeback for inode %"PRIu64" complete", inode->inum);
+    if (bluesky_verbose) {
+        g_log("bluesky/inode", G_LOG_LEVEL_DEBUG,
+              "Writeback for inode %"PRIu64" complete", inode->inum);
+    }
 }
 
 static void complete_inode_fetch(BlueSkyStoreAsync *async, BlueSkyInode *inode)
 {
-    g_print("Completing fetch of inode %"PRIu64"...\n", inode->inum);
+    if (bluesky_verbose) {
+        g_log("bluesky/inode", G_LOG_LEVEL_DEBUG,
+              "Completing fetch of inode %"PRIu64"...", inode->inum);
+    }
 
     if (async->result != 0
         || !bluesky_deserialize_inode(inode, async->data->data))
     {
-        g_print("    failed to load inode, cleaning up\n");
+        if (bluesky_verbose) {
+            g_log("bluesky/inode", G_LOG_LEVEL_DEBUG,
+                  "    failed to load inode, cleaning up");
+        }
         g_mutex_lock(inode->fs->lock);
         g_hash_table_remove(inode->fs->inodes, &inode->inum);
         bluesky_list_unlink(&inode->fs->accessed_list, inode->accessed_list);

diff --git a/bluesky/serialize.c b/bluesky/serialize.c
index 2b741b0..e453f49 100644 (file)
--- a/bluesky/serialize.c
+++ b/bluesky/serialize.c
@@ -142,7 +142,10 @@ void bluesky_serialize_inode(GString *out, BlueSkyInode *inode)
  * indicating whether the deserialization was successful. */
 gboolean bluesky_deserialize_inode(BlueSkyInode *inode, const gchar *buf)
 {
-    g_print("Deserializing inode %lld...\n", (long long)inode->inum);
+    if (bluesky_verbose) {
+        g_log("bluesky/serialize", G_LOG_LEVEL_DEBUG,
+              "Deserializing inode %lld...", (long long)inode->inum);
+    }
 
     struct serialized_inode *raw = (struct serialized_inode *)buf;
 
@@ -205,9 +208,6 @@ gboolean bluesky_deserialize_inode(BlueSkyInode *inode, const gchar *buf)
             g_hash_table_insert(inode->dirhash_folded, dirent->name_folded,
                                 dirent);
 
-            g_print("  dirent[%08x]: %s -> %"PRIu64"\n",
-                    dirent->cookie, dirent->name, dirent->inum);
-
             buf = strchr(d->name, '\0') + 1;
             d = (struct serialized_dirent *)buf;
         }

diff --git a/bluesky/store.c b/bluesky/store.c
index 48a69b4..ae6bdb6 100644 (file)
--- a/bluesky/store.c
+++ b/bluesky/store.c
@@ -219,9 +219,11 @@ void bluesky_store_async_mark_complete(BlueSkyStoreAsync *async)
         g_thread_pool_push(notifier_thread_pool, nl, NULL);
     }
 
-    g_log("bluesky/store", G_LOG_LEVEL_DEBUG,
-          "[%p] complete: elapsed = %"PRIi64" ns, latency = %"PRIi64" ns",
-          async, elapsed, latency);
+    if (bluesky_verbose) {
+        g_log("bluesky/store", G_LOG_LEVEL_DEBUG,
+              "[%p] complete: elapsed = %"PRIi64" ns, latency = %"PRIi64" ns",
+              async, elapsed, latency);
+    }
 }
 
 void bluesky_store_async_submit(BlueSkyStoreAsync *async)
@@ -234,13 +236,15 @@ 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();
 
-    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);
+    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. */
@@ -302,12 +306,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. */

diff --git a/nfs3/nfs3.c b/nfs3/nfs3.c
index f7e7b4e..061f835 100644 (file)
--- a/nfs3/nfs3.c
+++ b/nfs3/nfs3.c
@@ -475,7 +475,6 @@ void nfsproc3_create_3_svc(create3args *argp, RPCRequest *req)
     file->nlink = 1;
     file->mode = 0755;
     int64_t time = bluesky_get_current_time();
-    printf("time: %"PRIi64"\n", time);
     file->mtime = time;
     file->ctime = time;
     file->atime = time;

diff --git a/nfs3/rpc.c b/nfs3/rpc.c
index 4dcd21e..2342b79 100644 (file)
--- a/nfs3/rpc.c
+++ b/nfs3/rpc.c
@@ -216,8 +216,10 @@ async_rpc_send_reply(RPCRequest *req, void *result)
 
     time_end = bluesky_now_hires();
 
+#if 0
     printf("RPC[%"PRIx32"]: time = %"PRId64" ns\n",
            req->xid, time_end - req->time_start);
+#endif
 
     /* Clean up. */
     g_string_free(str, TRUE);
@@ -313,12 +315,14 @@ nfs_program_3(RPCRequest *req)
     xdrproc_t _xdr_argument, _xdr_result;
     char *(*local)(char *, RPCRequest *);
 
+#if 0
     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);
     }
+#endif
 
     switch (req->req_proc) {
     case NFSPROC3_NULL:
@@ -495,10 +499,12 @@ static void sig_handler(int sig)
 
 static gboolean async_flushd(gpointer data)
 {
+#if 0
     int rpc_count = g_atomic_int_get(&outstanding_rpcs);
     if (rpc_count != 0) {
         g_print("Currently outstanding RPC requests: %d\n", rpc_count);
     }
+#endif
 
     if (fs_dump_requested) {
         bluesky_debug_dump(fs);