On Tue, Jun 15, 2021 at 04:46:57PM +1000, Dave Chinner wrote:
> From: Dave Chinner <dchinner@xxxxxxxxxx>
>
> For the DEBUGS!
>
> Signed-off-by: Dave Chinner <dchinner@xxxxxxxxxx>
> ---
> fs/xfs/xfs_log.c | 18 ++++++++++++++++
> fs/xfs/xfs_trace.h | 52 ++++++++++++++++++++++++++++++++++++++++++++++
> 2 files changed, 70 insertions(+)
>
> diff --git a/fs/xfs/xfs_log.c b/fs/xfs/xfs_log.c
> index e921b554b683..54fd6a695bb5 100644
> --- a/fs/xfs/xfs_log.c
> +++ b/fs/xfs/xfs_log.c
> @@ -524,6 +524,7 @@ __xlog_state_release_iclog(
> iclog->ic_header.h_tail_lsn = cpu_to_be64(tail_lsn);
> xlog_verify_tail_lsn(log, iclog, tail_lsn);
> /* cycle incremented when incrementing curr_block */
> + trace_xlog_iclog_syncing(iclog, _RET_IP_);
> return true;
> }
>
> @@ -543,6 +544,7 @@ xlog_state_release_iclog(
> {
> lockdep_assert_held(&log->l_icloglock);
>
> + trace_xlog_iclog_release(iclog, _RET_IP_);
> if (iclog->ic_state == XLOG_STATE_IOERROR)
> return -EIO;
>
> @@ -804,6 +806,7 @@ xlog_wait_on_iclog(
> {
> struct xlog *log = iclog->ic_log;
>
> + trace_xlog_iclog_wait_on(iclog, _RET_IP_);
Seems like this might be more informative if we actually wait.
> if (!XLOG_FORCED_SHUTDOWN(log) &&
> iclog->ic_state != XLOG_STATE_ACTIVE &&
> iclog->ic_state != XLOG_STATE_DIRTY) {
> @@ -1804,6 +1807,7 @@ xlog_write_iclog(
> unsigned int count)
> {
> ASSERT(bno < log->l_logBBsize);
> + trace_xlog_iclog_write(iclog, _RET_IP_);
>
> /*
> * We lock the iclogbufs here so that we can serialise against I/O
> @@ -1950,6 +1954,7 @@ xlog_sync(
> unsigned int size;
>
> ASSERT(atomic_read(&iclog->ic_refcnt) == 0);
> + trace_xlog_iclog_sync(iclog, _RET_IP_);
>
> count = xlog_calc_iclog_size(log, iclog, &roundoff);
>
> @@ -2488,6 +2493,7 @@ xlog_state_activate_iclog(
> int *iclogs_changed)
> {
> ASSERT(list_empty_careful(&iclog->ic_callbacks));
> + trace_xlog_iclog_activate(iclog, _RET_IP_);
>
I wonder a bit whether these state change oriented tracepoints could be
served by a single trace_ixlog_iclog_state() or some such, since the
tracepoint already prints the state. That wouldn't show the before ->
state in each tracepoint, but that should reflect in the full log.
> /*
> * If the number of ops in this iclog indicate it just contains the
> @@ -2577,6 +2583,8 @@ xlog_state_clean_iclog(
> {
> int iclogs_changed = 0;
>
> + trace_xlog_iclog_clean(dirty_iclog, _RET_IP_);
> +
> dirty_iclog->ic_state = XLOG_STATE_DIRTY;
>
> xlog_state_activate_iclogs(log, &iclogs_changed);
> @@ -2636,6 +2644,7 @@ xlog_state_set_callback(
> struct xlog_in_core *iclog,
> xfs_lsn_t header_lsn)
> {
> + trace_xlog_iclog_callback(iclog, _RET_IP_);
> iclog->ic_state = XLOG_STATE_CALLBACK;
>
> ASSERT(XFS_LSN_CMP(atomic64_read(&log->l_last_sync_lsn),
> @@ -2717,6 +2726,7 @@ xlog_state_do_iclog_callbacks(
> __releases(&log->l_icloglock)
> __acquires(&log->l_icloglock)
> {
> + trace_xlog_iclog_callbacks_start(iclog, _RET_IP_);
> spin_unlock(&log->l_icloglock);
> spin_lock(&iclog->ic_callback_lock);
> while (!list_empty(&iclog->ic_callbacks)) {
> @@ -2736,6 +2746,7 @@ xlog_state_do_iclog_callbacks(
> */
> spin_lock(&log->l_icloglock);
> spin_unlock(&iclog->ic_callback_lock);
> + trace_xlog_iclog_callbacks_done(iclog, _RET_IP_);
> }
>
> STATIC void
> @@ -2827,6 +2838,7 @@ xlog_state_done_syncing(
>
> spin_lock(&log->l_icloglock);
> ASSERT(atomic_read(&iclog->ic_refcnt) == 0);
> + trace_xlog_iclog_sync_done(iclog, _RET_IP_);
>
> /*
> * If we got an error, either on the first buffer, or in the case of
> @@ -2899,6 +2911,8 @@ xlog_state_get_iclog_space(
> atomic_inc(&iclog->ic_refcnt); /* prevents sync */
> log_offset = iclog->ic_offset;
>
> + trace_xlog_iclog_get_space(iclog, _RET_IP_);
> +
> /* On the 1st write to an iclog, figure out lsn. This works
> * if iclogs marked XLOG_STATE_WANT_SYNC always write out what they are
> * committing to. If the offset is set, that's how many blocks
> @@ -3056,6 +3070,7 @@ xlog_state_switch_iclogs(
> {
> ASSERT(iclog->ic_state == XLOG_STATE_ACTIVE);
> assert_spin_locked(&log->l_icloglock);
> + trace_xlog_iclog_switch(iclog, _RET_IP_);
>
> if (!eventual_size)
> eventual_size = iclog->ic_offset;
> @@ -3138,6 +3153,8 @@ xfs_log_force(
> if (iclog->ic_state == XLOG_STATE_IOERROR)
> goto out_error;
>
> + trace_xlog_iclog_force(iclog, _RET_IP_);
> +
We have a log force tracepoint a few lines up. Do we need both?
> if (iclog->ic_state == XLOG_STATE_DIRTY ||
> (iclog->ic_state == XLOG_STATE_ACTIVE &&
> atomic_read(&iclog->ic_refcnt) == 0 && iclog->ic_offset == 0)) {
> @@ -3225,6 +3242,7 @@ xlog_force_lsn(
> goto out_error;
>
> while (be64_to_cpu(iclog->ic_header.h_lsn) != lsn) {
> + trace_xlog_iclog_force_lsn(iclog, _RET_IP_);
> iclog = iclog->ic_next;
> if (iclog == log->l_iclog)
> goto out_unlock;
> diff --git a/fs/xfs/xfs_trace.h b/fs/xfs/xfs_trace.h
> index 71dca776c110..79ee973ba1ed 100644
> --- a/fs/xfs/xfs_trace.h
> +++ b/fs/xfs/xfs_trace.h
> @@ -24,6 +24,7 @@ struct xlog_ticket;
> struct xlog_recover;
> struct xlog_recover_item;
> struct xlog_rec_header;
> +struct xlog_in_core;
> struct xfs_buf_log_format;
> struct xfs_inode_log_format;
> struct xfs_bmbt_irec;
> @@ -3927,6 +3928,57 @@ DEFINE_EVENT(xfs_icwalk_class, name, \
> DEFINE_ICWALK_EVENT(xfs_ioc_free_eofblocks);
> DEFINE_ICWALK_EVENT(xfs_blockgc_free_space);
>
> +DECLARE_EVENT_CLASS(xlog_iclog_class,
> + TP_PROTO(struct xlog_in_core *iclog, unsigned long caller_ip),
> + TP_ARGS(iclog, caller_ip),
> + TP_STRUCT__entry(
> + __field(dev_t, dev)
> + __field(uint32_t, state)
> + __field(int32_t, refcount)
> + __field(uint32_t, offset)
> + __field(unsigned long long, lsn)
> + __field(unsigned long, caller_ip)
> + ),
> + TP_fast_assign(
> + __entry->dev = iclog->ic_log->l_mp->m_super->s_dev;
> + __entry->state = iclog->ic_state;
> + __entry->refcount = atomic_read(&iclog->ic_refcnt);
> + __entry->offset = iclog->ic_offset;
> + __entry->lsn = be64_to_cpu(iclog->ic_header.h_lsn);
> + __entry->caller_ip = caller_ip;
> + ),
> + TP_printk("dev %d:%d state 0x%x refcnt %d offset %u lsn 0x%llx caller %pS",
> + MAJOR(__entry->dev), MINOR(__entry->dev),
> + __entry->state,
It might be nice to see a string representation of the state like we do
for other things like log item type, etc.
Brian
> + __entry->refcount,
> + __entry->offset,
> + __entry->lsn,
> + (char *)__entry->caller_ip)
> +
> +);
> +
> +#define DEFINE_ICLOG_EVENT(name) \
> +DEFINE_EVENT(xlog_iclog_class, name, \
> + TP_PROTO(struct xlog_in_core *iclog, unsigned long caller_ip), \
> + TP_ARGS(iclog, caller_ip))
> +
> +DEFINE_ICLOG_EVENT(xlog_iclog_activate);
> +DEFINE_ICLOG_EVENT(xlog_iclog_clean);
> +DEFINE_ICLOG_EVENT(xlog_iclog_callback);
> +DEFINE_ICLOG_EVENT(xlog_iclog_callbacks_start);
> +DEFINE_ICLOG_EVENT(xlog_iclog_callbacks_done);
> +DEFINE_ICLOG_EVENT(xlog_iclog_force);
> +DEFINE_ICLOG_EVENT(xlog_iclog_force_lsn);
> +DEFINE_ICLOG_EVENT(xlog_iclog_get_space);
> +DEFINE_ICLOG_EVENT(xlog_iclog_release);
> +DEFINE_ICLOG_EVENT(xlog_iclog_switch);
> +DEFINE_ICLOG_EVENT(xlog_iclog_sync);
> +DEFINE_ICLOG_EVENT(xlog_iclog_syncing);
> +DEFINE_ICLOG_EVENT(xlog_iclog_sync_done);
> +DEFINE_ICLOG_EVENT(xlog_iclog_want_sync);
> +DEFINE_ICLOG_EVENT(xlog_iclog_wait_on);
> +DEFINE_ICLOG_EVENT(xlog_iclog_write);
> +
> #endif /* _TRACE_XFS_H */
>
> #undef TRACE_INCLUDE_PATH
> --
> 2.31.1
>
