From ba18781b91569af2d721c46740d4ce139720c298 Mon Sep 17 00:00:00 2001 From: Dave Chinner Date: Wed, 9 May 2018 07:47:57 -0700 Subject: [PATCH] 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 Reviewed-by: Christoph Hellwig Reviewed-by: Brian Foster Reviewed-by: Darrick J. Wong Signed-off-by: Darrick J. Wong --- fs/xfs/xfs_log_cil.c | 1 + fs/xfs/xfs_trace.h | 37 +++++++++++++++++++++++++++++++++++++ fs/xfs/xfs_trans.c | 20 +++++++++++++++++++- 3 files changed, 57 insertions(+), 1 deletion(-) diff --git a/fs/xfs/xfs_log_cil.c b/fs/xfs/xfs_log_cil.c index 4668403b1741..a8675c631438 100644 --- 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 989708d06e10..1f95c20e3442 100644 --- 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 83f2032641cf..4bbdb6faec30 100644 --- 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. */