2022-03-10 18:00:44

by Ritesh Harjani

[permalink] [raw]
Subject: [PATCHv2 00/10] ext4: Improve FC trace events

Hello,

Please find the v2 of this patch series.

Note:- I still couldn't figure out how to expose EXT4_FC_REASON_MAX in patch-2
which (I think) might be (only) needed by trace-cmd or perf record for trace_ext4_fc_stats.
But it seems "cat /sys/kernel/debug/tracing/trace_pipe" gives the right output
for ext4_fc_stats trace event (as shown below).

So with above reasoning, do you think we should take these patches in?
And we can later see how to provide EXT4_FC_REASON_MAX definition available to
libtraceevent?

Either ways, please let me know your opinion around this.

<output of cat /sys/kernel/debug/tracing/trace_pipe> (shows FALLOC_RANGE:5)
=====================================================
jbd2/loop2-8-2219 [000] ..... 1883.771539: ext4_fc_stats: dev 7,2 fc ineligible reasons:
XATTR:0, CROSS_RENAME:0, JOURNAL_FLAG_CHANGE:0, NO_MEM:0, SWAP_BOOT:0, RESIZE:0, RENAME_DIR:0, FALLOC_RANGE:5, INODE_JOURNAL_DATA:0 num_commits:22, ineligible: 4, numblks: 22


Changes since RFC
================
RFC -> v2
1. Added new patch-5 ("ext4: Return early for non-eligible fast_commit track events")
2. Removed a trace event in ext4_fc_track_template() (which was added in RFC)
from patch-6 and added patch-7 to add the tid info in callers of
ext4_fc_track_template(). (As per review comments from Jan)

Tested this with xfstests -g "quick"


[RFC]: https://lore.kernel.org/linux-ext4/[email protected]/

Ritesh Harjani (10):
ext4: Remove unused enum EXT4_FC_COMMIT_FAILED
ext4: Fix ext4_fc_stats trace point
ext4: Convert ext4_fc_track_dentry type events to use event class
ext4: Do not call FC trace event in ext4_fc_commit() if FS does not support FC
ext4: Return early for non-eligible fast_commit track events
ext4: Add new trace event in ext4_fc_cleanup
ext4: Add transaction tid info in fc_track events
ext4: Add commit_tid info in jbd debug log
ext4: Add commit tid info in ext4_fc_commit_start/stop trace events
ext4: Fix remaining two trace events to use same printk convention

fs/ext4/fast_commit.c | 95 ++++++++----
fs/ext4/fast_commit.h | 1 -
include/trace/events/ext4.h | 297 +++++++++++++++++++++++-------------
3 files changed, 257 insertions(+), 136 deletions(-)

Cc: Steven Rostedt <[email protected]>

--
2.31.1


2022-03-10 19:39:52

by Ritesh Harjani

[permalink] [raw]
Subject: Re: [PATCHv2 00/10] ext4: Improve FC trace events

On 22/03/10 11:05AM, Steven Rostedt wrote:
> On Thu, 10 Mar 2022 21:28:54 +0530
> Ritesh Harjani <[email protected]> wrote:
>
> > Note:- I still couldn't figure out how to expose EXT4_FC_REASON_MAX in patch-2
> > which (I think) might be (only) needed by trace-cmd or perf record for trace_ext4_fc_stats.
> > But it seems "cat /sys/kernel/debug/tracing/trace_pipe" gives the right output
> > for ext4_fc_stats trace event (as shown below).
> >
> > So with above reasoning, do you think we should take these patches in?
> > And we can later see how to provide EXT4_FC_REASON_MAX definition available to
> > libtraceevent?
>
> I don't see EXT4_FC_REASON_MAX being used in the TP_printk(). If it isn't
> used there, it doesn't need to be exposed. Or did I miss something?

I was mentioning about EXT4_FC_REASON_MAX used in TP_STRUCT__entry.
When I hard code EXT4_FC_REASON_MAX to 9 in TP_STRUCT__entry, I could
see proper values using trace-cmd. Otherwise I see all 0 (when using trace-cmd
or perf record).

+ TP_STRUCT__entry(
+ __field(dev_t, dev)
+ __array(unsigned int, fc_ineligible_rc, EXT4_FC_REASON_MAX)

Should we anyway hard code this to 9. Since we are anyway printing all the
9 elements of array values individually.

+ TP_printk("dev %d,%d fc ineligible reasons:\n"
+ "%s:%u, %s:%u, %s:%u, %s:%u, %s:%u, %s:%u, %s:%u, %s:%u, %s:%u "
+ "num_commits:%lu, ineligible: %lu, numblks: %lu",
+ MAJOR(__entry->dev), MINOR(__entry->dev),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_XATTR),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_CROSS_RENAME),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_JOURNAL_FLAG_CHANGE),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_NOMEM),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_SWAP_BOOT),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_RESIZE),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_RENAME_DIR),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_FALLOC_RANGE),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_INODE_JOURNAL_DATA),
+ __entry->fc_commits, __entry->fc_ineligible_commits,
+ __entry->fc_numblks)


Thanks
-ritesh

2022-03-10 20:02:59

by Steven Rostedt

[permalink] [raw]
Subject: Re: [PATCHv2 00/10] ext4: Improve FC trace events

On Thu, 10 Mar 2022 21:28:54 +0530
Ritesh Harjani <[email protected]> wrote:

> Note:- I still couldn't figure out how to expose EXT4_FC_REASON_MAX in patch-2
> which (I think) might be (only) needed by trace-cmd or perf record for trace_ext4_fc_stats.
> But it seems "cat /sys/kernel/debug/tracing/trace_pipe" gives the right output
> for ext4_fc_stats trace event (as shown below).
>
> So with above reasoning, do you think we should take these patches in?
> And we can later see how to provide EXT4_FC_REASON_MAX definition available to
> libtraceevent?

I don't see EXT4_FC_REASON_MAX being used in the TP_printk(). If it isn't
used there, it doesn't need to be exposed. Or did I miss something?

-- Steve

2022-03-10 21:40:38

by Ritesh Harjani

[permalink] [raw]
Subject: [PATCHv2 02/10] ext4: Fix ext4_fc_stats trace point

ftrace's __print_symbolic() requires that any enum values used in the
symbol to string translation table be wrapped in a TRACE_DEFINE_ENUM
so that the enum value can be decoded from the ftrace ring buffer by
user space tooling.

This patch also fixes few other problems found in this trace point.
e.g. dereferencing structures in TP_printk which should not be done
at any cost.

Also to avoid checkpatch warnings, this patch removes those
whitespaces/tab stops issues.

Cc: [email protected]
Fixes: commit aa75f4d3daae ("ext4: main fast-commit commit path")
Reported-by: Steven Rostedt <[email protected]>
Signed-off-by: Ritesh Harjani <[email protected]>
Reviewed-by: Jan Kara <[email protected]>
Reviewed-by: Steven Rostedt (Google) <[email protected]>
Reviewed-by: Harshad Shirwadkar <[email protected]>
---
include/trace/events/ext4.h | 77 +++++++++++++++++++++++--------------
1 file changed, 48 insertions(+), 29 deletions(-)

diff --git a/include/trace/events/ext4.h b/include/trace/events/ext4.h
index 19e957b7f941..db404eb9b666 100644
--- a/include/trace/events/ext4.h
+++ b/include/trace/events/ext4.h
@@ -95,6 +95,16 @@ TRACE_DEFINE_ENUM(ES_REFERENCED_B);
{ FALLOC_FL_COLLAPSE_RANGE, "COLLAPSE_RANGE"}, \
{ FALLOC_FL_ZERO_RANGE, "ZERO_RANGE"})

+TRACE_DEFINE_ENUM(EXT4_FC_REASON_XATTR);
+TRACE_DEFINE_ENUM(EXT4_FC_REASON_CROSS_RENAME);
+TRACE_DEFINE_ENUM(EXT4_FC_REASON_JOURNAL_FLAG_CHANGE);
+TRACE_DEFINE_ENUM(EXT4_FC_REASON_NOMEM);
+TRACE_DEFINE_ENUM(EXT4_FC_REASON_SWAP_BOOT);
+TRACE_DEFINE_ENUM(EXT4_FC_REASON_RESIZE);
+TRACE_DEFINE_ENUM(EXT4_FC_REASON_RENAME_DIR);
+TRACE_DEFINE_ENUM(EXT4_FC_REASON_FALLOC_RANGE);
+TRACE_DEFINE_ENUM(EXT4_FC_REASON_INODE_JOURNAL_DATA);
+
#define show_fc_reason(reason) \
__print_symbolic(reason, \
{ EXT4_FC_REASON_XATTR, "XATTR"}, \
@@ -2723,41 +2733,50 @@ TRACE_EVENT(ext4_fc_commit_stop,

#define FC_REASON_NAME_STAT(reason) \
show_fc_reason(reason), \
- __entry->sbi->s_fc_stats.fc_ineligible_reason_count[reason]
+ __entry->fc_ineligible_rc[reason]

TRACE_EVENT(ext4_fc_stats,
- TP_PROTO(struct super_block *sb),
-
- TP_ARGS(sb),
+ TP_PROTO(struct super_block *sb),

- TP_STRUCT__entry(
- __field(dev_t, dev)
- __field(struct ext4_sb_info *, sbi)
- __field(int, count)
- ),
+ TP_ARGS(sb),

- TP_fast_assign(
- __entry->dev = sb->s_dev;
- __entry->sbi = EXT4_SB(sb);
- ),
+ TP_STRUCT__entry(
+ __field(dev_t, dev)
+ __array(unsigned int, fc_ineligible_rc, EXT4_FC_REASON_MAX)
+ __field(unsigned long, fc_commits)
+ __field(unsigned long, fc_ineligible_commits)
+ __field(unsigned long, fc_numblks)
+ ),

- TP_printk("dev %d:%d fc ineligible reasons:\n"
- "%s:%d, %s:%d, %s:%d, %s:%d, %s:%d, %s:%d, %s:%d, %s:%d, %s:%d; "
- "num_commits:%ld, ineligible: %ld, numblks: %ld",
- MAJOR(__entry->dev), MINOR(__entry->dev),
- FC_REASON_NAME_STAT(EXT4_FC_REASON_XATTR),
- FC_REASON_NAME_STAT(EXT4_FC_REASON_CROSS_RENAME),
- FC_REASON_NAME_STAT(EXT4_FC_REASON_JOURNAL_FLAG_CHANGE),
- FC_REASON_NAME_STAT(EXT4_FC_REASON_NOMEM),
- FC_REASON_NAME_STAT(EXT4_FC_REASON_SWAP_BOOT),
- FC_REASON_NAME_STAT(EXT4_FC_REASON_RESIZE),
- FC_REASON_NAME_STAT(EXT4_FC_REASON_RENAME_DIR),
- FC_REASON_NAME_STAT(EXT4_FC_REASON_FALLOC_RANGE),
- FC_REASON_NAME_STAT(EXT4_FC_REASON_INODE_JOURNAL_DATA),
- __entry->sbi->s_fc_stats.fc_num_commits,
- __entry->sbi->s_fc_stats.fc_ineligible_commits,
- __entry->sbi->s_fc_stats.fc_numblks)
+ TP_fast_assign(
+ int i;

+ __entry->dev = sb->s_dev;
+ for (i = 0; i < EXT4_FC_REASON_MAX; i++) {
+ __entry->fc_ineligible_rc[i] =
+ EXT4_SB(sb)->s_fc_stats.fc_ineligible_reason_count[i];
+ }
+ __entry->fc_commits = EXT4_SB(sb)->s_fc_stats.fc_num_commits;
+ __entry->fc_ineligible_commits =
+ EXT4_SB(sb)->s_fc_stats.fc_ineligible_commits;
+ __entry->fc_numblks = EXT4_SB(sb)->s_fc_stats.fc_numblks;
+ ),
+
+ TP_printk("dev %d,%d fc ineligible reasons:\n"
+ "%s:%u, %s:%u, %s:%u, %s:%u, %s:%u, %s:%u, %s:%u, %s:%u, %s:%u "
+ "num_commits:%lu, ineligible: %lu, numblks: %lu",
+ MAJOR(__entry->dev), MINOR(__entry->dev),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_XATTR),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_CROSS_RENAME),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_JOURNAL_FLAG_CHANGE),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_NOMEM),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_SWAP_BOOT),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_RESIZE),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_RENAME_DIR),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_FALLOC_RANGE),
+ FC_REASON_NAME_STAT(EXT4_FC_REASON_INODE_JOURNAL_DATA),
+ __entry->fc_commits, __entry->fc_ineligible_commits,
+ __entry->fc_numblks)
);

#define DEFINE_TRACE_DENTRY_EVENT(__type) \
--
2.31.1

2022-03-10 23:45:38

by Ritesh Harjani

[permalink] [raw]
Subject: [PATCHv2 10/10] ext4: Fix remaining two trace events to use same printk convention

All ext4 & jbd2 trace events starts with "dev Major:Minor".
While we are still improving/adding the ftrace events for FC,
let's fix last two remaining trace events to follow the same
convention.

Signed-off-by: Ritesh Harjani <[email protected]>
Reviewed-by: Harshad Shirwadkar <[email protected]>
Reviewed-by: Jan Kara <[email protected]>
---
include/trace/events/ext4.h | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/include/trace/events/ext4.h b/include/trace/events/ext4.h
index 09766eb56988..2137911a9392 100644
--- a/include/trace/events/ext4.h
+++ b/include/trace/events/ext4.h
@@ -2653,7 +2653,7 @@ TRACE_EVENT(ext4_fc_replay_scan,
__entry->off = off;
),

- TP_printk("FC scan pass on dev %d,%d: error %d, off %d",
+ TP_printk("dev %d,%d error %d, off %d",
MAJOR(__entry->dev), MINOR(__entry->dev),
__entry->error, __entry->off)
);
@@ -2679,7 +2679,7 @@ TRACE_EVENT(ext4_fc_replay,
__entry->priv2 = priv2;
),

- TP_printk("FC Replay %d,%d: tag %d, ino %d, data1 %d, data2 %d",
+ TP_printk("dev %d,%d: tag %d, ino %d, data1 %d, data2 %d",
MAJOR(__entry->dev), MINOR(__entry->dev),
__entry->tag, __entry->ino, __entry->priv1, __entry->priv2)
);
--
2.31.1

2022-03-11 00:41:22

by Ritesh Harjani

[permalink] [raw]
Subject: [PATCHv2 05/10] ext4: Return early for non-eligible fast_commit track events

Currently ext4_fc_track_template() checks, whether the trace event
path belongs to replay or does sb has ineligible set, if yes it simply
returns. This patch pulls those checks before calling
ext4_fc_track_template() in the callers of ext4_fc_track_template().

Signed-off-by: Ritesh Harjani <[email protected]>
---
fs/ext4/fast_commit.c | 59 +++++++++++++++++++++++++++++++++++--------
1 file changed, 49 insertions(+), 10 deletions(-)

diff --git a/fs/ext4/fast_commit.c b/fs/ext4/fast_commit.c
index 55d33f296cae..6990429daa0e 100644
--- a/fs/ext4/fast_commit.c
+++ b/fs/ext4/fast_commit.c
@@ -379,13 +379,6 @@ static int ext4_fc_track_template(
tid_t tid = 0;
int ret;

- if (!test_opt2(inode->i_sb, JOURNAL_FAST_COMMIT) ||
- (sbi->s_mount_state & EXT4_FC_REPLAY))
- return -EOPNOTSUPP;
-
- if (ext4_test_mount_flag(inode->i_sb, EXT4_MF_FC_INELIGIBLE))
- return -EINVAL;
-
tid = handle->h_transaction->t_tid;
mutex_lock(&ei->i_fc_lock);
if (tid == ei->i_sync_tid) {
@@ -499,7 +492,17 @@ void __ext4_fc_track_unlink(handle_t *handle,

void ext4_fc_track_unlink(handle_t *handle, struct dentry *dentry)
{
- __ext4_fc_track_unlink(handle, d_inode(dentry), dentry);
+ struct inode *inode = d_inode(dentry);
+ struct ext4_sb_info *sbi = EXT4_SB(inode->i_sb);
+
+ if (!test_opt2(inode->i_sb, JOURNAL_FAST_COMMIT) ||
+ (sbi->s_mount_state & EXT4_FC_REPLAY))
+ return;
+
+ if (ext4_test_mount_flag(inode->i_sb, EXT4_MF_FC_INELIGIBLE))
+ return;
+
+ __ext4_fc_track_unlink(handle, inode, dentry);
}

void __ext4_fc_track_link(handle_t *handle,
@@ -518,7 +521,17 @@ void __ext4_fc_track_link(handle_t *handle,

void ext4_fc_track_link(handle_t *handle, struct dentry *dentry)
{
- __ext4_fc_track_link(handle, d_inode(dentry), dentry);
+ struct inode *inode = d_inode(dentry);
+ struct ext4_sb_info *sbi = EXT4_SB(inode->i_sb);
+
+ if (!test_opt2(inode->i_sb, JOURNAL_FAST_COMMIT) ||
+ (sbi->s_mount_state & EXT4_FC_REPLAY))
+ return;
+
+ if (ext4_test_mount_flag(inode->i_sb, EXT4_MF_FC_INELIGIBLE))
+ return;
+
+ __ext4_fc_track_link(handle, inode, dentry);
}

void __ext4_fc_track_create(handle_t *handle, struct inode *inode,
@@ -537,7 +550,17 @@ void __ext4_fc_track_create(handle_t *handle, struct inode *inode,

void ext4_fc_track_create(handle_t *handle, struct dentry *dentry)
{
- __ext4_fc_track_create(handle, d_inode(dentry), dentry);
+ struct inode *inode = d_inode(dentry);
+ struct ext4_sb_info *sbi = EXT4_SB(inode->i_sb);
+
+ if (!test_opt2(inode->i_sb, JOURNAL_FAST_COMMIT) ||
+ (sbi->s_mount_state & EXT4_FC_REPLAY))
+ return;
+
+ if (ext4_test_mount_flag(inode->i_sb, EXT4_MF_FC_INELIGIBLE))
+ return;
+
+ __ext4_fc_track_create(handle, inode, dentry);
}

/* __track_fn for inode tracking */
@@ -553,6 +576,7 @@ static int __track_inode(struct inode *inode, void *arg, bool update)

void ext4_fc_track_inode(handle_t *handle, struct inode *inode)
{
+ struct ext4_sb_info *sbi = EXT4_SB(inode->i_sb);
int ret;

if (S_ISDIR(inode->i_mode))
@@ -564,6 +588,13 @@ void ext4_fc_track_inode(handle_t *handle, struct inode *inode)
return;
}

+ if (!test_opt2(inode->i_sb, JOURNAL_FAST_COMMIT) ||
+ (sbi->s_mount_state & EXT4_FC_REPLAY))
+ return;
+
+ if (ext4_test_mount_flag(inode->i_sb, EXT4_MF_FC_INELIGIBLE))
+ return;
+
ret = ext4_fc_track_template(handle, inode, __track_inode, NULL, 1);
trace_ext4_fc_track_inode(inode, ret);
}
@@ -603,12 +634,20 @@ static int __track_range(struct inode *inode, void *arg, bool update)
void ext4_fc_track_range(handle_t *handle, struct inode *inode, ext4_lblk_t start,
ext4_lblk_t end)
{
+ struct ext4_sb_info *sbi = EXT4_SB(inode->i_sb);
struct __track_range_args args;
int ret;

if (S_ISDIR(inode->i_mode))
return;

+ if (!test_opt2(inode->i_sb, JOURNAL_FAST_COMMIT) ||
+ (sbi->s_mount_state & EXT4_FC_REPLAY))
+ return;
+
+ if (ext4_test_mount_flag(inode->i_sb, EXT4_MF_FC_INELIGIBLE))
+ return;
+
args.start = start;
args.end = end;

--
2.31.1

2022-03-11 03:29:33

by Ritesh Harjani

[permalink] [raw]
Subject: Re: [PATCHv2 00/10] ext4: Improve FC trace events

On 22/03/10 07:39PM, Steven Rostedt wrote:
> On Thu, 10 Mar 2022 22:37:31 +0530
> Ritesh Harjani <[email protected]> wrote:
>
> > On 22/03/10 11:05AM, Steven Rostedt wrote:
> > > On Thu, 10 Mar 2022 21:28:54 +0530
> > > Ritesh Harjani <[email protected]> wrote:
> > >
> > > > Note:- I still couldn't figure out how to expose EXT4_FC_REASON_MAX in patch-2
> > > > which (I think) might be (only) needed by trace-cmd or perf record for trace_ext4_fc_stats.
> > > > But it seems "cat /sys/kernel/debug/tracing/trace_pipe" gives the right output
> > > > for ext4_fc_stats trace event (as shown below).
> > > >
> > > > So with above reasoning, do you think we should take these patches in?
> > > > And we can later see how to provide EXT4_FC_REASON_MAX definition available to
> > > > libtraceevent?
> > >
> > > I don't see EXT4_FC_REASON_MAX being used in the TP_printk(). If it isn't
> > > used there, it doesn't need to be exposed. Or did I miss something?
> >
> > I was mentioning about EXT4_FC_REASON_MAX used in TP_STRUCT__entry.
> > When I hard code EXT4_FC_REASON_MAX to 9 in TP_STRUCT__entry, I could
> > see proper values using trace-cmd. Otherwise I see all 0 (when using trace-cmd
> > or perf record).
> >
> > + TP_STRUCT__entry(
> > + __field(dev_t, dev)
> > + __array(unsigned int, fc_ineligible_rc, EXT4_FC_REASON_MAX)
>
> Ah, I bet it's showing up in the format portion and not the print fmt part
> of the format file.
>
> Just to confirm, can you do the following:
>
> # cat /sys/kernel/tracing/events/ext4/ext4_fc_commit_stop/format

I think you meant ext4_fc_stats.

>
> and show me what it outputs.

root@qemu:/home/qemu# cat /sys/kernel/tracing/events/ext4/ext4_fc_stats/format
name: ext4_fc_stats
ID: 986
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;

field:dev_t dev; offset:8; size:4; signed:0;
field:unsigned int fc_ineligible_rc[EXT4_FC_REASON_MAX]; offset:12; size:36; signed:0;
field:unsigned long fc_commits; offset:48; size:8; signed:0;
field:unsigned long fc_ineligible_commits; offset:56; size:8; signed:0;
field:unsigned long fc_numblks; offset:64; size:8; signed:0;

print fmt: "dev %d,%d fc ineligible reasons:
%s:%u, %s:%u, %s:%u, %s:%u, %s:%u, %s:%u, %s:%u, %s:%u, %s:%u num_commits:%lu, ineligible: %lu, numblks: %lu", ((unsigned int) ((REC->dev) >> 20)), ((unsigned int) ((REC->dev) & ((1U << 20) - 1))), __print_symbolic(0, { 0, "XATTR"}, { 1, "CROSS_RENAME"}, { 2, "JOURNAL_FLAG_CHANGE"}, { 3, "NO_MEM"}, { 4, "SWAP_BOOT"}, { 5, "RESIZE"}, { 6, "RENAME_DIR"}, { 7, "FALLOC_RANGE"}, { 8, "INODE_JOURNAL_DATA"}), REC->fc_ineligible_rc[0], __print_symbolic(1, { 0, "XATTR"}, { 1, "CROSS_RENAME"}, { 2, "JOURNAL_FLAG_CHANGE"}, { 3, "NO_MEM"}, { 4, "SWAP_BOOT"}, { 5, "RESIZE"}, { 6, "RENAME_DIR"}, { 7, "FALLOC_RANGE"}, { 8, "INODE_JOURNAL_DATA"}), REC->fc_ineligible_rc[1], __print_symbolic(2, { 0, "XATTR"}, { 1, "CROSS_RENAME"}, { 2, "JOURNAL_FLAG_CHANGE"}, { 3, "NO_MEM"}, { 4, "SWAP_BOOT"}, { 5, "RESIZE"}, { 6, "RENAME_DIR"}, { 7, "FALLOC_RANGE"}, { 8, "INODE_JOURNAL_DATA"}), REC->fc_ineligible_rc[2], __print_symbolic(3, { 0, "XATTR"}, { 1, "CROSS_RENAME"}, { 2, "JOURNAL_FLAG_CHANGE"}, { 3, "NO_MEM"}, { 4, "SWAP_BOOT"}, { 5, "RESIZE"}, { 6, "RENAME_DIR"}, { 7, "FALLOC_RANGE"}, { 8, "INODE_JOURNAL_DATA"}), REC->fc_ineligible_rc[3], __print_symbolic(4, { 0, "XATTR"}, { 1, "CROSS_RENAME"}, { 2, "JOURNAL_FLAG_CHANGE"}, { 3, "NO_MEM"}, { 4, "SWAP_BOOT"}, { 5, "RESIZE"}, { 6, "RENAME_DIR"}, { 7, "FALLOC_RANGE"}, { 8, "INODE_JOURNAL_DATA"}), REC->fc_ineligible_rc[4], __print_symbolic(5, { 0, "XATTR"}, { 1, "CROSS_RENAME"}, { 2, "JOURNAL_FLAG_CHANGE"}, { 3, "NO_MEM"}, { 4, "SWAP_BOOT"}, { 5, "RESIZE"}, { 6, "RENAME_DIR"}, { 7, "FALLOC_RANGE"}, { 8, "INODE_JOURNAL_DATA"}), REC->fc_ineligible_rc[5], __print_symbolic(6, { 0, "XATTR"}, { 1, "CROSS_RENAME"}, { 2, "JOURNAL_FLAG_CHANGE"}, { 3, "NO_MEM"}, { 4, "SWAP_BOOT"}, { 5, "RESIZE"}, { 6, "RENAME_DIR"}, { 7, "FALLOC_RANGE"}, { 8, "INODE_JOURNAL_DATA"}), REC->fc_ineligible_rc[6], __print_symbolic(7, { 0, "XATTR"}, { 1, "CROSS_RENAME"}, { 2, "JOURNAL_FLAG_CHANGE"}, { 3, "NO_MEM"}, { 4, "SWAP_BOOT"}, { 5, "RESIZE"}, { 6, "RENAME_DIR"}, { 7, "FALLOC_RANGE"}, { 8, "INODE_JOURNAL_DATA"}), REC->fc_ineligible_rc[7], __print_symbolic(8, { 0, "XATTR"}, { 1, "CROSS_RENAME"}, { 2, "JOURNAL_FLAG_CHANGE"}, { 3, "NO_MEM"}, { 4, "SWAP_BOOT"}, { 5, "RESIZE"}, { 6, "RENAME_DIR"}, { 7, "FALLOC_RANGE"}, { 8, "INODE_JOURNAL_DATA"}), REC->fc_ineligible_rc[8], REC->fc_commits, REC->fc_ineligible_commits, REC->fc_numblks


output of ext4_fc_stats (FALLOC_RANGE:0 v/s FALLOC_RANGE:13)
==========================================================================
<perf-report or trace-cmd report>
xfs_io 8336 [003] 42950.923784: ext4:ext4_fc_stats: dev 7,2 fc ineligible reasons:
XATTR:0, CROSS_RENAME:0, JOURNAL_FLAG_CHANGE:0, NO_MEM:0, SWAP_BOOT:0, RESIZE:0, RENAME_DIR:0, FALLOC_RANGE:0, INODE_JOURNAL_DATA:0 num_commits:22, ineligible: 12, numblks: 22



<cat /sys/kernel/debug/tracing/trace_pipe>
xfs_io-8336 [003] ..... 42951.224155: ext4_fc_stats: dev 7,2 fc ineligible reasons:
XATTR:0, CROSS_RENAME:0, JOURNAL_FLAG_CHANGE:0, NO_MEM:0, SWAP_BOOT:0, RESIZE:0, RENAME_DIR:0, FALLOC_RANGE:13, INODE_JOURNAL_DATA:0 num_commits:22, ineligible: 12, numblks: 22


Thanks
-ritesh


>
> Thanks,
>
> -- Steve
>
>
> >
> > Should we anyway hard code this to 9. Since we are anyway printing all the
> > 9 elements of array values individually.
> >
> > + TP_printk("dev %d,%d fc ineligible reasons:\n"
> > + "%s:%u, %s:%u, %s:%u, %s:%u, %s:%u, %s:%u, %s:%u, %s:%u, %s:%u "
> > + "num_commits:%lu, ineligible: %lu, numblks: %lu",
> > + MAJOR(__entry->dev), MINOR(__entry->dev),
> > + FC_REASON_NAME_STAT(EXT4_FC_REASON_XATTR),
> > + FC_REASON_NAME_STAT(EXT4_FC_REASON_CROSS_RENAME),
> > + FC_REASON_NAME_STAT(EXT4_FC_REASON_JOURNAL_FLAG_CHANGE),
> > + FC_REASON_NAME_STAT(EXT4_FC_REASON_NOMEM),
> > + FC_REASON_NAME_STAT(EXT4_FC_REASON_SWAP_BOOT),
> > + FC_REASON_NAME_STAT(EXT4_FC_REASON_RESIZE),
> > + FC_REASON_NAME_STAT(EXT4_FC_REASON_RENAME_DIR),
> > + FC_REASON_NAME_STAT(EXT4_FC_REASON_FALLOC_RANGE),
> > + FC_REASON_NAME_STAT(EXT4_FC_REASON_INODE_JOURNAL_DATA),
> > + __entry->fc_commits, __entry->fc_ineligible_commits,
> > + __entry->fc_numblks)
> >
> >
> > Thanks
> > -ritesh
>

2022-03-11 04:27:31

by Ritesh Harjani

[permalink] [raw]
Subject: [PATCHv2 08/10] ext4: Add commit_tid info in jbd debug log

This adds commit_tid argument in ext4_fc_update_stats()
so that we can add this information too in jbd_debug logs.
This is also required in a later patch to pass the commit_tid info in
ext4_fc_commit_start/stop() trace events.

Signed-off-by: Ritesh Harjani <[email protected]>
Reviewed-by: Jan Kara <[email protected]>
Reviewed-by: Harshad Shirwadkar <[email protected]>
---
fs/ext4/fast_commit.c | 15 +++++++++------
1 file changed, 9 insertions(+), 6 deletions(-)

diff --git a/fs/ext4/fast_commit.c b/fs/ext4/fast_commit.c
index 849fd4dcb825..88ed99e670c5 100644
--- a/fs/ext4/fast_commit.c
+++ b/fs/ext4/fast_commit.c
@@ -1164,11 +1164,12 @@ static int ext4_fc_perform_commit(journal_t *journal)
}

static void ext4_fc_update_stats(struct super_block *sb, int status,
- u64 commit_time, int nblks)
+ u64 commit_time, int nblks, tid_t commit_tid)
{
struct ext4_fc_stats *stats = &EXT4_SB(sb)->s_fc_stats;

- jbd_debug(1, "Fast commit ended with status = %d", status);
+ jbd_debug(1, "Fast commit ended with status = %d for tid %u",
+ status, commit_tid);
if (status == EXT4_FC_STATUS_OK) {
stats->fc_num_commits++;
stats->fc_numblks += nblks;
@@ -1218,14 +1219,16 @@ int ext4_fc_commit(journal_t *journal, tid_t commit_tid)
if (atomic_read(&sbi->s_fc_subtid) <= subtid &&
commit_tid > journal->j_commit_sequence)
goto restart_fc;
- ext4_fc_update_stats(sb, EXT4_FC_STATUS_SKIPPED, 0, 0);
+ ext4_fc_update_stats(sb, EXT4_FC_STATUS_SKIPPED, 0, 0,
+ commit_tid);
return 0;
} else if (ret) {
/*
* Commit couldn't start. Just update stats and perform a
* full commit.
*/
- ext4_fc_update_stats(sb, EXT4_FC_STATUS_FAILED, 0, 0);
+ ext4_fc_update_stats(sb, EXT4_FC_STATUS_FAILED, 0, 0,
+ commit_tid);
return jbd2_complete_transaction(journal, commit_tid);
}

@@ -1257,12 +1260,12 @@ int ext4_fc_commit(journal_t *journal, tid_t commit_tid)
* don't react too strongly to vast changes in the commit time
*/
commit_time = ktime_to_ns(ktime_sub(ktime_get(), start_time));
- ext4_fc_update_stats(sb, status, commit_time, nblks);
+ ext4_fc_update_stats(sb, status, commit_time, nblks, commit_tid);
return ret;

fallback:
ret = jbd2_fc_end_commit_fallback(journal);
- ext4_fc_update_stats(sb, status, 0, 0);
+ ext4_fc_update_stats(sb, status, 0, 0, commit_tid);
return ret;
}

--
2.31.1

2022-03-11 20:54:05

by Ritesh Harjani

[permalink] [raw]
Subject: Re: [PATCHv2 00/10] ext4: Improve FC trace events

On 22/03/10 11:32PM, Steven Rostedt wrote:
> On Fri, 11 Mar 2022 08:44:31 +0530
> Ritesh Harjani <[email protected]> wrote:
>
> > > I could update it to do so though.
> >
> > Please let me know if you have any patch for me to try.
>
> Can you try this?

Thanks a lot Steve for quick patch.
I tested your patch and it seems to be working fine.

Below are the details -

root@qemu:/home/qemu# cat /sys/kernel/tracing/events/ext4/ext4_fc_stats/format
name: ext4_fc_stats
ID: 986
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;

field:dev_t dev; offset:8; size:4; signed:0;
field:unsigned int fc_ineligible_rc[9]; offset:12; size:36; signed:0;
^^^^ It's now taking the enum value of EXT4_FC_REASON_MAX in array field too.

Also output from trace-cmd and perf script shows the right data

xfs_io 1856 [000] 173.411127: ext4:ext4_fc_stats: dev 7,2 fc ineligible reasons:
XATTR:0, CROSS_RENAME:0, JOURNAL_FLAG_CHANGE:0, NO_MEM:0, SWAP_BOOT:0, RESIZE:0, RENAME_DIR:0, FALLOC_RANGE:2, INODE_JOURNAL_DATA:0 num_commits:0, ineligible: 1, numblks: 0

>
> -- Steve
>
> From 392b91c598da2a8c5bbaebad08cd0410f4607bf4 Mon Sep 17 00:00:00 2001
> From: "Steven Rostedt (Google)" <[email protected]>
> Date: Thu, 10 Mar 2022 23:27:38 -0500
> Subject: [PATCH] tracing: Have TRACE_DEFINE_ENUM affect trace event types as
> well
>
> The macro TRACE_DEFINE_ENUM is used to convert enums in the kernel to
> their actual value when they are exported to user space via the trace
> event format file.
>
> Currently only the enums in the "print fmt" (TP_printk in the TRACE_EVENT
> macro) have the enums converted. But the enums can be used to denote array
> size:
>
> field:unsigned int fc_ineligible_rc[EXT4_FC_REASON_MAX]; offset:12; size:36; signed:0;
>
> The EXT4_FC_REASON_MAX has no meaning to userspace but it needs to know
> that information to know how to parse the array.
>
> Have the array indexes also be parsed as well.
>
> Link: https://lore.kernel.org/all/[email protected]/
>
> Reported-by: Ritesh Harjani <[email protected]>
> Signed-off-by: Steven Rostedt (Google) <[email protected]>
> ---
> kernel/trace/trace_events.c | 28 ++++++++++++++++++++++++++++
> 1 file changed, 28 insertions(+)

You may add below, if you like:-

Reported-and-tested-by: Ritesh Harjani <[email protected]>

-ritesh


>
> diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
> index 38afd66d80e3..ae9a3b8481f5 100644
> --- a/kernel/trace/trace_events.c
> +++ b/kernel/trace/trace_events.c
> @@ -2633,6 +2633,33 @@ static void update_event_printk(struct trace_event_call *call,
> }
> }
>
> +static void update_event_fields(struct trace_event_call *call,
> + struct trace_eval_map *map)
> +{
> + struct ftrace_event_field *field;
> + struct list_head *head;
> + char *ptr;
> + int len = strlen(map->eval_string);
> +
> + head = trace_get_fields(call);
> + list_for_each_entry(field, head, link) {
> + ptr = strchr(field->type, '[');
> + if (!ptr)
> + continue;
> + ptr++;
> +
> + if (!isalpha(*ptr) && *ptr != '_')
> + continue;
> +
> + if (strncmp(map->eval_string, ptr, len) != 0)
> + continue;
> +
> + ptr = eval_replace(ptr, map, len);
> + /* enum/sizeof string smaller than value */
> + WARN_ON_ONCE(!ptr);
> + }
> +}
> +
> void trace_event_eval_update(struct trace_eval_map **map, int len)
> {
> struct trace_event_call *call, *p;
> @@ -2668,6 +2695,7 @@ void trace_event_eval_update(struct trace_eval_map **map, int len)
> first = false;
> }
> update_event_printk(call, map[i]);
> + update_event_fields(call, map[i]);
> }
> }
> }
> --
> 2.34.1
>