2022-02-22 21:26:25

by Ritesh Harjani

[permalink] [raw]
Subject: [RFC 6/9] ext4: Add commit tid info in ext4_fc_commit_start/stop trace events

This adds commit_tid info in ext4_fc_commit_start/stop which is helpful
in debugging fast_commit issues.

For e.g. issues where due to jbd2 journal full commit, FC miss to commit
updates to a file.

Also improves TP_prink format string i.e. all ext4 and jbd2 trace events
starts with "dev MAjOR,MINOR". Let's follow the same convention while we
are still at it.

Signed-off-by: Ritesh Harjani <[email protected]>
---
fs/ext4/fast_commit.c | 4 ++--
include/trace/events/ext4.h | 21 +++++++++++++--------
2 files changed, 15 insertions(+), 10 deletions(-)

diff --git a/fs/ext4/fast_commit.c b/fs/ext4/fast_commit.c
index ee32aac0cbbf..8803ba087b07 100644
--- a/fs/ext4/fast_commit.c
+++ b/fs/ext4/fast_commit.c
@@ -1150,7 +1150,7 @@ static void ext4_fc_update_stats(struct super_block *sb, int status,
} else {
stats->fc_skipped_commits++;
}
- trace_ext4_fc_commit_stop(sb, nblks, status);
+ trace_ext4_fc_commit_stop(sb, nblks, status, commit_tid);
}

/*
@@ -1171,7 +1171,7 @@ int ext4_fc_commit(journal_t *journal, tid_t commit_tid)
if (!test_opt2(sb, JOURNAL_FAST_COMMIT))
return jbd2_complete_transaction(journal, commit_tid);

- trace_ext4_fc_commit_start(sb);
+ trace_ext4_fc_commit_start(sb, commit_tid);

start_time = ktime_get();

diff --git a/include/trace/events/ext4.h b/include/trace/events/ext4.h
index cd09dccea502..6e66cb7ce624 100644
--- a/include/trace/events/ext4.h
+++ b/include/trace/events/ext4.h
@@ -2685,26 +2685,29 @@ TRACE_EVENT(ext4_fc_replay,
);

TRACE_EVENT(ext4_fc_commit_start,
- TP_PROTO(struct super_block *sb),
+ TP_PROTO(struct super_block *sb, tid_t commit_tid),

- TP_ARGS(sb),
+ TP_ARGS(sb, commit_tid),

TP_STRUCT__entry(
__field(dev_t, dev)
+ __field(tid_t, tid)
),

TP_fast_assign(
__entry->dev = sb->s_dev;
+ __entry->tid = commit_tid;
),

- TP_printk("fast_commit started on dev %d,%d",
- MAJOR(__entry->dev), MINOR(__entry->dev))
+ TP_printk("dev %d,%d tid %u", MAJOR(__entry->dev), MINOR(__entry->dev),
+ __entry->tid)
);

TRACE_EVENT(ext4_fc_commit_stop,
- TP_PROTO(struct super_block *sb, int nblks, int reason),
+ TP_PROTO(struct super_block *sb, int nblks, int reason,
+ tid_t commit_tid),

- TP_ARGS(sb, nblks, reason),
+ TP_ARGS(sb, nblks, reason, commit_tid),

TP_STRUCT__entry(
__field(dev_t, dev)
@@ -2713,6 +2716,7 @@ TRACE_EVENT(ext4_fc_commit_stop,
__field(int, num_fc)
__field(int, num_fc_ineligible)
__field(int, nblks_agg)
+ __field(tid_t, tid)
),

TP_fast_assign(
@@ -2723,12 +2727,13 @@ TRACE_EVENT(ext4_fc_commit_stop,
__entry->num_fc_ineligible =
EXT4_SB(sb)->s_fc_stats.fc_ineligible_commits;
__entry->nblks_agg = EXT4_SB(sb)->s_fc_stats.fc_numblks;
+ __entry->tid = commit_tid;
),

- TP_printk("fc on [%d,%d] nblks %d, reason %d, fc = %d, ineligible = %d, agg_nblks %d",
+ TP_printk("dev %d,%d nblks %d, reason %d, fc = %d, ineligible = %d, agg_nblks %d, tid %u",
MAJOR(__entry->dev), MINOR(__entry->dev),
__entry->nblks, __entry->reason, __entry->num_fc,
- __entry->num_fc_ineligible, __entry->nblks_agg)
+ __entry->num_fc_ineligible, __entry->nblks_agg, __entry->tid)
);

#define FC_REASON_NAME_STAT(reason) \
--
2.31.1


2022-02-27 20:30:30

by harshad shirwadkar

[permalink] [raw]
Subject: Re: [RFC 6/9] ext4: Add commit tid info in ext4_fc_commit_start/stop trace events

Looks good.

Reviewed-by: Harshad Shirwadkar <[email protected]>

- Harshad

On Wed, 23 Feb 2022 at 01:44, Jan Kara <[email protected]> wrote:
>
> On Wed 23-02-22 02:04:14, Ritesh Harjani wrote:
> > This adds commit_tid info in ext4_fc_commit_start/stop which is helpful
> > in debugging fast_commit issues.
> >
> > For e.g. issues where due to jbd2 journal full commit, FC miss to commit
> > updates to a file.
> >
> > Also improves TP_prink format string i.e. all ext4 and jbd2 trace events
> > starts with "dev MAjOR,MINOR". Let's follow the same convention while we
> > are still at it.
> >
> > Signed-off-by: Ritesh Harjani <[email protected]>
>
> Looks good. Feel free to add:
>
> Reviewed-by: Jan Kara <[email protected]>
>
> Honza
>
> > ---
> > fs/ext4/fast_commit.c | 4 ++--
> > include/trace/events/ext4.h | 21 +++++++++++++--------
> > 2 files changed, 15 insertions(+), 10 deletions(-)
> >
> > diff --git a/fs/ext4/fast_commit.c b/fs/ext4/fast_commit.c
> > index ee32aac0cbbf..8803ba087b07 100644
> > --- a/fs/ext4/fast_commit.c
> > +++ b/fs/ext4/fast_commit.c
> > @@ -1150,7 +1150,7 @@ static void ext4_fc_update_stats(struct super_block *sb, int status,
> > } else {
> > stats->fc_skipped_commits++;
> > }
> > - trace_ext4_fc_commit_stop(sb, nblks, status);
> > + trace_ext4_fc_commit_stop(sb, nblks, status, commit_tid);
> > }
> >
> > /*
> > @@ -1171,7 +1171,7 @@ int ext4_fc_commit(journal_t *journal, tid_t commit_tid)
> > if (!test_opt2(sb, JOURNAL_FAST_COMMIT))
> > return jbd2_complete_transaction(journal, commit_tid);
> >
> > - trace_ext4_fc_commit_start(sb);
> > + trace_ext4_fc_commit_start(sb, commit_tid);
> >
> > start_time = ktime_get();
> >
> > diff --git a/include/trace/events/ext4.h b/include/trace/events/ext4.h
> > index cd09dccea502..6e66cb7ce624 100644
> > --- a/include/trace/events/ext4.h
> > +++ b/include/trace/events/ext4.h
> > @@ -2685,26 +2685,29 @@ TRACE_EVENT(ext4_fc_replay,
> > );
> >
> > TRACE_EVENT(ext4_fc_commit_start,
> > - TP_PROTO(struct super_block *sb),
> > + TP_PROTO(struct super_block *sb, tid_t commit_tid),
> >
> > - TP_ARGS(sb),
> > + TP_ARGS(sb, commit_tid),
> >
> > TP_STRUCT__entry(
> > __field(dev_t, dev)
> > + __field(tid_t, tid)
> > ),
> >
> > TP_fast_assign(
> > __entry->dev = sb->s_dev;
> > + __entry->tid = commit_tid;
> > ),
> >
> > - TP_printk("fast_commit started on dev %d,%d",
> > - MAJOR(__entry->dev), MINOR(__entry->dev))
> > + TP_printk("dev %d,%d tid %u", MAJOR(__entry->dev), MINOR(__entry->dev),
> > + __entry->tid)
> > );
> >
> > TRACE_EVENT(ext4_fc_commit_stop,
> > - TP_PROTO(struct super_block *sb, int nblks, int reason),
> > + TP_PROTO(struct super_block *sb, int nblks, int reason,
> > + tid_t commit_tid),
> >
> > - TP_ARGS(sb, nblks, reason),
> > + TP_ARGS(sb, nblks, reason, commit_tid),
> >
> > TP_STRUCT__entry(
> > __field(dev_t, dev)
> > @@ -2713,6 +2716,7 @@ TRACE_EVENT(ext4_fc_commit_stop,
> > __field(int, num_fc)
> > __field(int, num_fc_ineligible)
> > __field(int, nblks_agg)
> > + __field(tid_t, tid)
> > ),
> >
> > TP_fast_assign(
> > @@ -2723,12 +2727,13 @@ TRACE_EVENT(ext4_fc_commit_stop,
> > __entry->num_fc_ineligible =
> > EXT4_SB(sb)->s_fc_stats.fc_ineligible_commits;
> > __entry->nblks_agg = EXT4_SB(sb)->s_fc_stats.fc_numblks;
> > + __entry->tid = commit_tid;
> > ),
> >
> > - TP_printk("fc on [%d,%d] nblks %d, reason %d, fc = %d, ineligible = %d, agg_nblks %d",
> > + TP_printk("dev %d,%d nblks %d, reason %d, fc = %d, ineligible = %d, agg_nblks %d, tid %u",
> > MAJOR(__entry->dev), MINOR(__entry->dev),
> > __entry->nblks, __entry->reason, __entry->num_fc,
> > - __entry->num_fc_ineligible, __entry->nblks_agg)
> > + __entry->num_fc_ineligible, __entry->nblks_agg, __entry->tid)
> > );
> >
> > #define FC_REASON_NAME_STAT(reason) \
> > --
> > 2.31.1
> >
> --
> Jan Kara <[email protected]>
> SUSE Labs, CR