btrfs: tracepoints: add trace event for btrfs_sync_log()

btrfs_sync_log() is one of the main functions called during a fsync.
Add trace events for when entering and exiting that function.

Reviewed-by: Johannes Thumshirn <johannes.thumshirn@wdc.com>
Signed-off-by: Filipe Manana <fdmanana@suse.com>
Signed-off-by: David Sterba <dsterba@suse.com>

diff --git a/fs/btrfs/tree-log.c b/fs/btrfs/tree-log.c
index 49ab92bc3aa268f73145316e280762c81703db86..875e4ddc68eaea4c0723f7481b470d7923058513 100644 (file)
--- a/fs/btrfs/tree-log.c
+++ b/fs/btrfs/tree-log.c
@@ -3322,8 +3322,10 @@ int btrfs_sync_log(struct btrfs_trans_handle *trans,
        u64 log_root_level;
 
        mutex_lock(&root->log_mutex);
+       trace_btrfs_sync_log_enter(trans, root, ctx);
        log_transid = ctx->log_transid;
        if (root->log_transid_committed >= log_transid) {
+               trace_btrfs_sync_log_exit(trans, root, ctx, ctx->log_ret);
                mutex_unlock(&root->log_mutex);
                return ctx->log_ret;
        }
@@ -3331,6 +3333,7 @@ int btrfs_sync_log(struct btrfs_trans_handle *trans,
        index1 = log_transid % 2;
        if (atomic_read(&root->log_commit[index1])) {
                wait_log_commit(root, log_transid);
+               trace_btrfs_sync_log_exit(trans, root, ctx, ctx->log_ret);
                mutex_unlock(&root->log_mutex);
                return ctx->log_ret;
        }
@@ -3359,6 +3362,7 @@ int btrfs_sync_log(struct btrfs_trans_handle *trans,
        /* bail out if we need to do a full commit */
        if (btrfs_need_log_full_commit(trans)) {
                ret = BTRFS_LOG_FORCE_COMMIT;
+               trace_btrfs_sync_log_exit(trans, root, ctx, ret);
                mutex_unlock(&root->log_mutex);
                goto out;
        }
@@ -3385,6 +3389,7 @@ int btrfs_sync_log(struct btrfs_trans_handle *trans,
        if (ret == -EAGAIN && btrfs_is_zoned(fs_info))
                ret = 0;
        if (ret) {
+               trace_btrfs_sync_log_exit(trans, root, ctx, ret);
                blk_finish_plug(&plug);
                btrfs_set_log_full_commit(trans);
                mutex_unlock(&root->log_mutex);
@@ -3422,6 +3427,7 @@ int btrfs_sync_log(struct btrfs_trans_handle *trans,
                if (!log_root_tree->node) {
                        ret = btrfs_alloc_log_tree_node(trans, log_root_tree);
                        if (ret) {
+                               trace_btrfs_sync_log_exit(trans, root, ctx, ret);
                                mutex_unlock(&fs_info->tree_root->log_mutex);
                                blk_finish_plug(&plug);
                                goto out;
@@ -3445,6 +3451,7 @@ int btrfs_sync_log(struct btrfs_trans_handle *trans,
         */
        ret = update_log_root(trans, log, &new_root_item);
        if (ret) {
+               trace_btrfs_sync_log_exit(trans, root, ctx, ret);
                list_del_init(&root_log_ctx.list);
                blk_finish_plug(&plug);
                btrfs_set_log_full_commit(trans);
@@ -3462,6 +3469,7 @@ int btrfs_sync_log(struct btrfs_trans_handle *trans,
                list_del_init(&root_log_ctx.list);
                mutex_unlock(&log_root_tree->log_mutex);
                ret = root_log_ctx.log_ret;
+               trace_btrfs_sync_log_exit(trans, root, ctx, ret);
                goto out;
        }
 
@@ -3473,6 +3481,7 @@ int btrfs_sync_log(struct btrfs_trans_handle *trans,
                mutex_unlock(&log_root_tree->log_mutex);
                if (!ret)
                        ret = root_log_ctx.log_ret;
+               trace_btrfs_sync_log_exit(trans, root, ctx, ret);
                goto out;
        }
        ASSERT(root_log_ctx.log_transid == log_root_tree->log_transid,
@@ -3494,6 +3503,7 @@ int btrfs_sync_log(struct btrfs_trans_handle *trans,
                btrfs_wait_tree_log_extents(log, mark);
                mutex_unlock(&log_root_tree->log_mutex);
                ret = BTRFS_LOG_FORCE_COMMIT;
+               trace_btrfs_sync_log_exit(trans, root, ctx, ret);
                goto out_wake_log_root;
        }
 
@@ -3507,11 +3517,13 @@ int btrfs_sync_log(struct btrfs_trans_handle *trans,
         * deadlock. Bail out to the full commit instead.
         */
        if (ret == -EAGAIN && btrfs_is_zoned(fs_info)) {
+               trace_btrfs_sync_log_exit(trans, root, ctx, ret);
                btrfs_set_log_full_commit(trans);
                btrfs_wait_tree_log_extents(log, mark);
                mutex_unlock(&log_root_tree->log_mutex);
                goto out_wake_log_root;
        } else if (ret) {
+               trace_btrfs_sync_log_exit(trans, root, ctx, ret);
                btrfs_set_log_full_commit(trans);
                mutex_unlock(&log_root_tree->log_mutex);
                goto out_wake_log_root;
@@ -3521,6 +3533,7 @@ int btrfs_sync_log(struct btrfs_trans_handle *trans,
                ret = btrfs_wait_tree_log_extents(log_root_tree,
                                                  EXTENT_DIRTY_LOG1 | EXTENT_DIRTY_LOG2);
        if (ret) {
+               trace_btrfs_sync_log_exit(trans, root, ctx, ret);
                btrfs_set_log_full_commit(trans);
                mutex_unlock(&log_root_tree->log_mutex);
                goto out_wake_log_root;
@@ -3557,6 +3570,7 @@ int btrfs_sync_log(struct btrfs_trans_handle *trans,
         */
        if (unlikely(BTRFS_FS_ERROR(fs_info))) {
                ret = -EIO;
+               trace_btrfs_sync_log_exit(trans, root, ctx, ret);
                btrfs_set_log_full_commit(trans);
                btrfs_abort_transaction(trans, ret);
                mutex_unlock(&fs_info->tree_log_mutex);
@@ -3568,6 +3582,7 @@ int btrfs_sync_log(struct btrfs_trans_handle *trans,
        ret = write_all_supers(trans);
        mutex_unlock(&fs_info->tree_log_mutex);
        if (unlikely(ret)) {
+               trace_btrfs_sync_log_exit(trans, root, ctx, ret);
                btrfs_set_log_full_commit(trans);
                btrfs_abort_transaction(trans, ret);
                goto out_wake_log_root;

diff --git a/include/trace/events/btrfs.h b/include/trace/events/btrfs.h
index ad9ae2489782ae06a05dc875b2e4bcb40739bd4f..0e96633b8b4b5fb2a4ed107db27818f608f794c7 100644 (file)
--- a/include/trace/events/btrfs.h
+++ b/include/trace/events/btrfs.h
@@ -1547,6 +1547,91 @@ TRACE_EVENT(btrfs_log_new_name_exit,
                        __entry->ino, __entry->old_dir_ino, __entry->ret)
 );
 
+/* Ideally call this while under root->log_mutex (but not always possible). */
+TRACE_EVENT(btrfs_sync_log_enter,
+
+       TP_PROTO(const struct btrfs_trans_handle *trans,
+                const struct btrfs_root *root,
+                const struct btrfs_log_ctx *ctx),
+
+       TP_ARGS(trans, root, ctx),
+
+       TP_STRUCT__entry_btrfs(
+               __field(        u64,            root_objectid           )
+               __field(        u64,            transid                 )
+               __field(        int,            ctx_log_transid         )
+               __field(        int,            root_log_transid        )
+               __field(        int,            log_transid_committed   )
+               __field(        bool,           log_committing          )
+               __field(        bool,           log_committing_prev     )
+               __field(        int,            log_writers             )
+       ),
+
+       TP_fast_assign(
+               TP_fast_assign_fsid(trans->fs_info);
+               __entry->root_objectid          = btrfs_root_id(root);
+               __entry->transid                = trans->transid;
+               __entry->ctx_log_transid        = ctx->log_transid;
+               __entry->root_log_transid       = btrfs_get_root_log_transid(root);
+               __entry->log_transid_committed  =
+                       data_race(root->log_transid_committed);
+               __entry->log_committing         =
+                       atomic_read(&root->log_commit[ctx->log_transid % 2]);
+               __entry->log_committing_prev    =
+                       atomic_read(&root->log_commit[(ctx->log_transid + 1) % 2]);
+               __entry->log_writers            = atomic_read(&root->log_writers);
+       ),
+
+       TP_printk_btrfs("root=%llu(%s) transid=%llu ctx_log_transid=%d"
+                       " root_log_transid=%d log_transid_committed=%d"
+                       " log_committing=%d log_committing_prev=%d log_writers=%d",
+                       show_root_type(__entry->root_objectid), __entry->transid,
+                       __entry->ctx_log_transid, __entry->root_log_transid,
+                       __entry->log_transid_committed, __entry->log_committing,
+                       __entry->log_committing_prev, __entry->log_writers)
+);
+
+/*
+ * Ideally call this while under root->log_mutex and in the same critical
+ * section that calls the btrfs_sync_log_enter() trace event (though it's not
+ * always possible).
+ */
+TRACE_EVENT(btrfs_sync_log_exit,
+
+       TP_PROTO(const struct btrfs_trans_handle *trans,
+                const struct btrfs_root *root,
+                const struct btrfs_log_ctx *ctx,
+                int ret),
+
+       TP_ARGS(trans, root, ctx, ret),
+
+       TP_STRUCT__entry_btrfs(
+               __field(        u64,            root_objectid           )
+               __field(        u64,            transid                 )
+               __field(        int,            ctx_log_transid         )
+               __field(        int,            root_log_transid        )
+               __field(        int,            log_transid_committed   )
+               __field(        int,            ret                     )
+       ),
+
+       TP_fast_assign(
+               TP_fast_assign_fsid(trans->fs_info);
+               __entry->root_objectid          = btrfs_root_id(root);
+               __entry->transid                = trans->transid;
+               __entry->ctx_log_transid        = ctx->log_transid;
+               __entry->root_log_transid       = btrfs_get_root_log_transid(root);
+               __entry->log_transid_committed  =
+                       data_race(root->log_transid_committed);
+               __entry->ret                    = ret;
+       ),
+
+       TP_printk_btrfs("root=%llu(%s) transid=%llu ctx_log_transid=%d"
+                       " root_log_transid=%d log_transid_committed=%d ret=%d",
+                       show_root_type(__entry->root_objectid), __entry->transid,
+                       __entry->ctx_log_transid, __entry->root_log_transid,
+                       __entry->log_transid_committed, __entry->ret)
+);
+
 TRACE_EVENT(btrfs_sync_fs,
 
        TP_PROTO(const struct btrfs_fs_info *fs_info, int wait),