xfs: add tracing to high level transaction operations

Because currently we have no idea what the transaction context we
are operating in is, and I need to know that information to track
down bugs in multiple log item joins to transactions.

Signed-Off-By: Dave Chinner <dchinner@redhat.com>
Reviewed-by: Christoph Hellwig <hch@lst.de>
Reviewed-by: Brian Foster <bfoster@redhat.com>
Reviewed-by: Darrick J. Wong <darrick.wong@oracle.com>
Signed-off-by: Darrick J. Wong <darrick.wong@oracle.com>

diff --git a/fs/xfs/xfs_log_cil.c b/fs/xfs/xfs_log_cil.c
index 4668403b174154fd8e8db92934870fbbf070cfd7..a8675c631438f479c4f484471cddaaadbfec3ba4 100644 (file)
--- a/fs/xfs/xfs_log_cil.c
+++ b/fs/xfs/xfs_log_cil.c
@@ -1013,6 +1013,7 @@ xfs_log_commit_cil(
                *commit_lsn = xc_commit_lsn;
 
        xfs_log_done(mp, tp->t_ticket, NULL, regrant);
+       tp->t_ticket = NULL;
        xfs_trans_unreserve_and_mod_sb(tp);
 
        /*

diff --git a/fs/xfs/xfs_trace.h b/fs/xfs/xfs_trace.h
index 989708d06e106ece30a79422aeda4cef0a3c646f..1f95c20e34424890b4d4352ea255bc62471d3454 100644 (file)
--- a/fs/xfs/xfs_trace.h
+++ b/fs/xfs/xfs_trace.h
@@ -3351,6 +3351,43 @@ TRACE_EVENT(xfs_trans_resv_calc,
                  __entry->logflags)
 );
 
+DECLARE_EVENT_CLASS(xfs_trans_class,
+       TP_PROTO(struct xfs_trans *tp, unsigned long caller_ip),
+       TP_ARGS(tp, caller_ip),
+       TP_STRUCT__entry(
+               __field(dev_t, dev)
+               __field(uint32_t, tid)
+               __field(uint32_t, flags)
+               __field(unsigned long, caller_ip)
+       ),
+       TP_fast_assign(
+               __entry->dev = tp->t_mountp->m_super->s_dev;
+               __entry->tid = 0;
+               if (tp->t_ticket)
+                       __entry->tid = tp->t_ticket->t_tid;
+               __entry->flags = tp->t_flags;
+               __entry->caller_ip = caller_ip;
+       ),
+       TP_printk("dev %d:%d trans %x flags 0x%x caller %pS",
+                 MAJOR(__entry->dev), MINOR(__entry->dev),
+                 __entry->tid,
+                 __entry->flags,
+                 (char *)__entry->caller_ip)
+)
+
+#define DEFINE_TRANS_EVENT(name) \
+DEFINE_EVENT(xfs_trans_class, name, \
+       TP_PROTO(struct xfs_trans *tp, unsigned long caller_ip), \
+       TP_ARGS(tp, caller_ip))
+DEFINE_TRANS_EVENT(xfs_trans_alloc);
+DEFINE_TRANS_EVENT(xfs_trans_cancel);
+DEFINE_TRANS_EVENT(xfs_trans_commit);
+DEFINE_TRANS_EVENT(xfs_trans_dup);
+DEFINE_TRANS_EVENT(xfs_trans_free);
+DEFINE_TRANS_EVENT(xfs_trans_roll);
+DEFINE_TRANS_EVENT(xfs_trans_add_item);
+DEFINE_TRANS_EVENT(xfs_trans_free_items);
+
 #endif /* _TRACE_XFS_H */
 
 #undef TRACE_INCLUDE_PATH

diff --git a/fs/xfs/xfs_trans.c b/fs/xfs/xfs_trans.c
index 83f2032641cff56e91f84fdb764aafeaca1eab58..4bbdb6faec308edb21d9c894d234aa21aa104a44 100644 (file)
--- a/fs/xfs/xfs_trans.c
+++ b/fs/xfs/xfs_trans.c
@@ -80,6 +80,7 @@ xfs_trans_free(
        xfs_extent_busy_sort(&tp->t_busy);
        xfs_extent_busy_clear(tp->t_mountp, &tp->t_busy, false);
 
+       trace_xfs_trans_free(tp, _RET_IP_);
        atomic_dec(&tp->t_mountp->m_active_trans);
        if (!(tp->t_flags & XFS_TRANS_NO_WRITECOUNT))
                sb_end_intwrite(tp->t_mountp->m_super);
@@ -101,6 +102,8 @@ xfs_trans_dup(
 {
        struct xfs_trans        *ntp;
 
+       trace_xfs_trans_dup(tp, _RET_IP_);
+
        ntp = kmem_zone_zalloc(xfs_trans_zone, KM_SLEEP);
 
        /*
@@ -285,6 +288,8 @@ xfs_trans_alloc(
                return error;
        }
 
+       trace_xfs_trans_alloc(tp, _RET_IP_);
+
        *tpp = tp;
        return 0;
 }
@@ -751,6 +756,8 @@ xfs_trans_add_item(
        list_add_tail(&lidp->lid_trans, &tp->t_items);
 
        lip->li_desc = lidp;
+
+       trace_xfs_trans_add_item(tp, _RET_IP_);
 }
 
 STATIC void
@@ -784,6 +791,8 @@ xfs_trans_free_items(
 {
        struct xfs_log_item_desc *lidp, *next;
 
+       trace_xfs_trans_free_items(tp, _RET_IP_);
+
        list_for_each_entry_safe(lidp, next, &tp->t_items, lid_trans) {
                struct xfs_log_item     *lip = lidp->lid_item;
 
@@ -941,6 +950,8 @@ __xfs_trans_commit(
        ASSERT(!tp->t_agfl_dfops ||
               !xfs_defer_has_unfinished_work(tp->t_agfl_dfops) || regrant);
 
+       trace_xfs_trans_commit(tp, _RET_IP_);
+
        /*
         * If there is nothing to be logged by the transaction,
         * then unlock all of the items associated with the
@@ -996,6 +1007,7 @@ out_unreserve:
                commit_lsn = xfs_log_done(mp, tp->t_ticket, NULL, regrant);
                if (commit_lsn == -1 && !error)
                        error = -EIO;
+               tp->t_ticket = NULL;
        }
        current_restore_flags_nested(&tp->t_pflags, PF_MEMALLOC_NOFS);
        xfs_trans_free_items(tp, NULLCOMMITLSN, !!error);
@@ -1027,6 +1039,8 @@ xfs_trans_cancel(
        struct xfs_mount        *mp = tp->t_mountp;
        bool                    dirty = (tp->t_flags & XFS_TRANS_DIRTY);
 
+       trace_xfs_trans_cancel(tp, _RET_IP_);
+
        /*
         * See if the caller is relying on us to shut down the
         * filesystem.  This happens in paths where we detect
@@ -1047,8 +1061,10 @@ xfs_trans_cancel(
        xfs_trans_unreserve_and_mod_sb(tp);
        xfs_trans_unreserve_and_mod_dquots(tp);
 
-       if (tp->t_ticket)
+       if (tp->t_ticket) {
                xfs_log_done(mp, tp->t_ticket, NULL, false);
+               tp->t_ticket = NULL;
+       }
 
        /* mark this thread as no longer being in a transaction */
        current_restore_flags_nested(&tp->t_pflags, PF_MEMALLOC_NOFS);
@@ -1072,6 +1088,8 @@ xfs_trans_roll(
        struct xfs_trans_res    tres;
        int                     error;
 
+       trace_xfs_trans_roll(trans, _RET_IP_);
+
        /*
         * Copy the critical parameters from one trans to the next.
         */