| Message ID | 90608d31b7ad8500c33d875d3a7fa50e3456dc1a.1645558375.git.riteshh@linux.ibm.com |
|---|---|
| State | Not Applicable |
| Headers | show |
| Series | ext4: Improve FC trace events and discuss one FC failure | expand |
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? 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 >
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
On Wed 23-02-22 15:41:59, Ritesh Harjani wrote: > 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]) I understand commit tid is interesting but cannot we just add it to tracepoints like trace_ext4_fc_track_range() directly? It would seem useful to have it there and when it is there, the need for ext4_fc_track_template() is not really big. I don't care too much but this tracepoint looked a bit superfluous to me. > 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. Yeah, that one is clear. Honza
On 22/02/23 12:53PM, Jan Kara wrote: > On Wed 23-02-22 15:41:59, Ritesh Harjani wrote: > > 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]) > > I understand commit tid is interesting but cannot we just add it to > tracepoints like trace_ext4_fc_track_range() directly? It would seem useful > to have it there and when it is there, the need for > ext4_fc_track_template() is not really big. I don't care too much but Yes make sense. Sure, I will look into adding this info to existing trace points then. With that I think trace_ext4_fc_track_template() won't be required. Will add those changes in V2. > this tracepoint looked a bit superfluous to me. > > > 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. > > Yeah, that one is clear. Will retain trace_ext4_fc_cleanup() then. -ritesh > > Honza > -- > Jan Kara <jack@suse.com> > SUSE Labs, CR
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),
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> --- fs/ext4/fast_commit.c | 3 ++ include/trace/events/ext4.h | 67 +++++++++++++++++++++++++++++++++++++ 2 files changed, 70 insertions(+)