Received-SPF: softfail (google.com: domain of transitioning linux-ext4-owner@vger.kernel.org does not designate 23.128.96.19 as permitted sender) client-ip=23.128.96.19;
Date:   Wed, 23 Feb 2022 15:41:59 +0530
From:   Ritesh Harjani <riteshh@linux.ibm.com>
To:     Jan Kara <jack@suse.cz>
Cc:     linux-ext4@vger.kernel.org,
        Harshad Shirwadkar <harshadshirwadkar@gmail.com>,
        "Theodore Ts'o" <tytso@mit.edu>, linux-fsdevel@vger.kernel.org,
        linux-kernel@vger.kernel.org
Subject: Re: [RFC 3/9] ext4: Add couple of more fast_commit tracepoints
Message-ID: <20220223101159.ekwbylvbmec5v35q@riteshh-domain>
References: <cover.1645558375.git.riteshh@linux.ibm.com>
 <90608d31b7ad8500c33d875d3a7fa50e3456dc1a.1645558375.git.riteshh@linux.ibm.com>
 <20220223094057.53zcovnazrqwbngw@quack3.lan>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20220223094057.53zcovnazrqwbngw@quack3.lan>
Precedence: bulk

On 22/02/23 10:40AM, Jan Kara wrote:
> On Wed 23-02-22 02:04:11, Ritesh Harjani wrote:
> > This adds two more tracepoints for ext4_fc_track_template() &
> > ext4_fc_cleanup() which are helpful in debugging some fast_commit issues.
> >
> > Signed-off-by: Ritesh Harjani <riteshh@linux.ibm.com>
>
> So why is this more useful than trace_ext4_fc_track_range() and other
> tracepoints? I don't think it provides any more information? What am I
> missing?

Thanks Jan for all the reviews.

So ext4_fc_track_template() adds almost all required information
(including the caller info) in this one trace point along with transaction tid
which is useful for tracking issue similar to what is mentioned in Patch-9.

(race with if inode is part of two transactions tid where jbd2 full commit
may begin for txn n-1 while inode is still in sbi->s_fc_q[MAIN])

And similarly ext4_fc_cleanup() helps with that information about which tid
completed and whether it was called from jbd2 full commit or from fast_commit.

-ritesh

>
> 								Honza
>
> > ---
> >  fs/ext4/fast_commit.c       |  3 ++
> >  include/trace/events/ext4.h | 67 +++++++++++++++++++++++++++++++++++++
> >  2 files changed, 70 insertions(+)
> >
> > diff --git a/fs/ext4/fast_commit.c b/fs/ext4/fast_commit.c
> > index 5ac594e03402..bf70879bb4fe 100644
> > --- a/fs/ext4/fast_commit.c
> > +++ b/fs/ext4/fast_commit.c
> > @@ -386,6 +386,8 @@ static int ext4_fc_track_template(
> >  	if (ext4_test_mount_flag(inode->i_sb, EXT4_MF_FC_INELIGIBLE))
> >  		return -EINVAL;
> >
> > +	trace_ext4_fc_track_template(handle, inode, __fc_track_fn, enqueue);
> > +
> >  	tid = handle->h_transaction->t_tid;
> >  	mutex_lock(&ei->i_fc_lock);
> >  	if (tid == ei->i_sync_tid) {
> > @@ -1241,6 +1243,7 @@ static void ext4_fc_cleanup(journal_t *journal, int full, tid_t tid)
> >  	if (full && sbi->s_fc_bh)
> >  		sbi->s_fc_bh = NULL;
> >
> > +	trace_ext4_fc_cleanup(journal, full, tid);
> >  	jbd2_fc_release_bufs(journal);
> >
> >  	spin_lock(&sbi->s_fc_lock);
> > diff --git a/include/trace/events/ext4.h b/include/trace/events/ext4.h
> > index 17fb9c506e8a..cd09dccea502 100644
> > --- a/include/trace/events/ext4.h
> > +++ b/include/trace/events/ext4.h
> > @@ -2855,6 +2855,73 @@ TRACE_EVENT(ext4_fc_track_range,
> >  		      __entry->end)
> >  	);
> >
> > +TRACE_EVENT(ext4_fc_track_template,
> > +	TP_PROTO(handle_t *handle, struct inode *inode,
> > +		 void *__fc_track_fn, int enqueue),
> > +
> > +	TP_ARGS(handle, inode, __fc_track_fn, enqueue),
> > +
> > +	TP_STRUCT__entry(
> > +		__field(dev_t, dev)
> > +		__field(tid_t, t_tid)
> > +		__field(ino_t, i_ino)
> > +		__field(tid_t, i_sync_tid)
> > +		__field(void *, __fc_track_fn)
> > +		__field(int, enqueue)
> > +		__field(bool, jbd2_ongoing)
> > +		__field(bool, fc_ongoing)
> > +	),
> > +
> > +	TP_fast_assign(
> > +		struct ext4_sb_info *sbi = EXT4_SB(inode->i_sb);
> > +		struct ext4_inode_info *ei = EXT4_I(inode);
> > +
> > +		__entry->dev = inode->i_sb->s_dev;
> > +		__entry->t_tid = handle->h_transaction->t_tid;
> > +		__entry->i_ino = inode->i_ino;
> > +		__entry->i_sync_tid = ei->i_sync_tid;
> > +		__entry->__fc_track_fn = __fc_track_fn;
> > +		__entry->enqueue = enqueue;
> > +		__entry->jbd2_ongoing =
> > +		    sbi->s_journal->j_flags & JBD2_FULL_COMMIT_ONGOING;
> > +		__entry->fc_ongoing =
> > +		    sbi->s_journal->j_flags & JBD2_FAST_COMMIT_ONGOING;
> > +	),
> > +
> > +	TP_printk("dev %d,%d, t_tid %u, ino %lu, i_sync_tid %u, "
> > +		  "track_fn %pS, enqueue %d, jbd2_ongoing %d, fc_ongoing %d",
> > +		  MAJOR(__entry->dev), MINOR(__entry->dev),
> > +		  __entry->t_tid, __entry->i_ino, __entry->i_sync_tid,
> > +		  (void *)__entry->__fc_track_fn, __entry->enqueue,
> > +		  __entry->jbd2_ongoing, __entry->fc_ongoing)
> > +	);
> > +
> > +TRACE_EVENT(ext4_fc_cleanup,
> > +	TP_PROTO(journal_t *journal, int full, tid_t tid),
> > +
> > +	TP_ARGS(journal, full, tid),
> > +
> > +	TP_STRUCT__entry(
> > +		__field(dev_t, dev)
> > +		__field(int, j_fc_off)
> > +		__field(int, full)
> > +		__field(tid_t, tid)
> > +	),
> > +
> > +	TP_fast_assign(
> > +		struct super_block *sb = journal->j_private;
> > +
> > +		__entry->dev = sb->s_dev;
> > +		__entry->j_fc_off = journal->j_fc_off;
> > +		__entry->full = full;
> > +		__entry->tid = tid;
> > +	),
> > +
> > +	TP_printk("dev %d,%d, j_fc_off %d, full %d, tid %u",
> > +		  MAJOR(__entry->dev), MINOR(__entry->dev),
> > +		  __entry->j_fc_off, __entry->full, __entry->tid)
> > +	);
> > +
> >  TRACE_EVENT(ext4_update_sb,
> >  	TP_PROTO(struct super_block *sb, ext4_fsblk_t fsblk,
> >  		 unsigned int flags),
> > --
> > 2.31.1
> >
> --
> Jan Kara <jack@suse.com>
> SUSE Labs, CR