From: Michael Vrable Date: Wed, 31 Mar 2010 21:53:54 +0000 (-0700) Subject: Disable most debugging print messages; should help with performance. X-Git-Url: http://git.vrable.net/?p=bluesky.git;a=commitdiff_plain;h=966a43ffed492d387e0d75e56c3984d9001c15b1 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 --- 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 --- 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 --- 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 --- 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 --- 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 --- 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 --- 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 --- 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 --- 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);