ext4: Improve FC trace events

PATCH Superseded Ritesh Harjani 2 participants 22 messages Mar 10, 2022 – Mar 11, 2022

Subsystems (3)

VFS Tracing ext4 file system

lore

Share & tools

lore

Ritesh Harjani

author

2022-03-10 15:59 UTC #1 lore raw

PATCH v2 1/10 ext4: Remove unused enum EXT4_FC_COMMIT_FAILED

In reply to Ritesh Harjani

Below commit removed all references of EXT4_FC_COMMIT_FAILED. commit 0915e464cb274 ("ext4: simplify updating of fast commit stats")

Just remove it since it is not used anymore.

Signed-off-by Ritesh Harjani <[email protected]>

Reviewed-by Jan Kara <[email protected]>

Reviewed-by Harshad Shirwadkar <[email protected]>

---
 fs/ext4/fast_commit.h | 1 -
 1 file changed, 1 deletion(-)

fs/ext4/fast_commit.h +0 -1

index 02afa52e8e41..80414dcba6e1 100644
@@ -93,7 +93,6 @@ enum {
 	EXT4_FC_REASON_RENAME_DIR,
 	EXT4_FC_REASON_FALLOC_RANGE,
 	EXT4_FC_REASON_INODE_JOURNAL_DATA,
-	EXT4_FC_COMMIT_FAILED,
 	EXT4_FC_REASON_MAX
 };

Signature · 1 line

2.31.1

Ritesh Harjani

author

2022-03-10 15:59 UTC #3 lore raw

PATCH v2 3/10 ext4: Convert ext4_fc_track_dentry type events to use event class

In reply to Ritesh Harjani

One should use DECLARE_EVENT_CLASS for similar event types instead of defining TRACE_EVENT for each event type. This is helpful in reducing the text section footprint for e.g. [1]

[1]: https://lwn.net/Articles/381064/

Signed-off-by Ritesh Harjani <[email protected]>

Reviewed-by Harshad Shirwadkar <[email protected]>

Reviewed-by Jan Kara <[email protected]>

---
 include/trace/events/ext4.h | 56 ++++++++++++++++++++-----------------
 1 file changed, 31 insertions(+), 25 deletions(-)

include/trace/events/ext4.h +31 ~~-25~~

index db404eb9b666..c3d16dd829aa 100644
@@ -2779,33 +2779,39 @@ TRACE_EVENT(ext4_fc_stats,
 		  __entry->fc_numblks)
 );
 
-#define DEFINE_TRACE_DENTRY_EVENT(__type)				\
-	TRACE_EVENT(ext4_fc_track_##__type,				\
-	    TP_PROTO(struct inode *inode, struct dentry *dentry, int ret), \
-									\
-	    TP_ARGS(inode, dentry, ret),				\
-									\
-	    TP_STRUCT__entry(						\
-		    __field(dev_t, dev)					\
-		    __field(int, ino)					\
-		    __field(int, error)					\
-		    ),							\
-									\
-	    TP_fast_assign(						\
-		    __entry->dev = inode->i_sb->s_dev;			\
-		    __entry->ino = inode->i_ino;			\
-		    __entry->error = ret;				\
-		    ),							\
-									\
-	    TP_printk("dev %d:%d, inode %d, error %d, fc_%s",		\
-		      MAJOR(__entry->dev), MINOR(__entry->dev),		\
-		      __entry->ino, __entry->error,			\
-		      #__type)						\
+DECLARE_EVENT_CLASS(ext4_fc_track_dentry,
+
+	TP_PROTO(struct inode *inode, struct dentry *dentry, int ret),
+
+	TP_ARGS(inode, dentry, ret),
+
+	TP_STRUCT__entry(
+		__field(dev_t, dev)
+		__field(ino_t, i_ino)
+		__field(int, error)
+	),
+
+	TP_fast_assign(
+		__entry->dev = inode->i_sb->s_dev;
+		__entry->i_ino = inode->i_ino;
+		__entry->error = ret;
+	),
+
+	TP_printk("dev %d,%d, ino %lu, error %d",
+		  MAJOR(__entry->dev), MINOR(__entry->dev),
+		  __entry->i_ino, __entry->error
 	)
+);
+
+#define DEFINE_EVENT_CLASS_DENTRY(__type)				\
+DEFINE_EVENT(ext4_fc_track_dentry, ext4_fc_track_##__type,		\
+	TP_PROTO(struct inode *inode, struct dentry *dentry, int ret),	\
+	TP_ARGS(inode, dentry, ret)					\
+)
 
-DEFINE_TRACE_DENTRY_EVENT(create);
-DEFINE_TRACE_DENTRY_EVENT(link);
-DEFINE_TRACE_DENTRY_EVENT(unlink);
+DEFINE_EVENT_CLASS_DENTRY(create);
+DEFINE_EVENT_CLASS_DENTRY(link);
+DEFINE_EVENT_CLASS_DENTRY(unlink);
 
 TRACE_EVENT(ext4_fc_track_inode,
 	    TP_PROTO(struct inode *inode, int ret),

Signature · 1 line

2.31.1

Ritesh Harjani

author

2022-03-10 15:59 UTC #4 lore raw

PATCH v2 4/10 ext4: Do not call FC trace event in ext4_fc_commit() if FS does not support FC

In reply to Ritesh Harjani

This just puts trace_ext4_fc_commit_start(sb) & ktime_get() for measuring FC commit time, after the check of whether sb supports JOURNAL_FAST_COMMIT or not.

Signed-off-by Ritesh Harjani <[email protected]>

Reviewed-by Harshad Shirwadkar <[email protected]>

Reviewed-by Jan Kara <[email protected]>

---
 fs/ext4/fast_commit.c | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

fs/ext4/fast_commit.c +3 -3

index 5ac594e03402..55d33f296cae 100644
@@ -1165,13 +1165,13 @@ int ext4_fc_commit(journal_t *journal, tid_t commit_tid)
 	int status = EXT4_FC_STATUS_OK, fc_bufs_before = 0;
 	ktime_t start_time, commit_time;
 
+	if (!test_opt2(sb, JOURNAL_FAST_COMMIT))
+		return jbd2_complete_transaction(journal, commit_tid);
+
 	trace_ext4_fc_commit_start(sb);
 
 	start_time = ktime_get();
 
-	if (!test_opt2(sb, JOURNAL_FAST_COMMIT))
-		return jbd2_complete_transaction(journal, commit_tid);
-
 restart_fc:
 	ret = jbd2_fc_begin_commit(journal, commit_tid);
 	if (ret == -EALREADY) {

Signature · 1 line

2.31.1

Ritesh Harjani

author

2022-03-10 15:59 UTC #5 lore raw

PATCH v2 5/10 ext4: Return early for non-eligible fast_commit track events

In reply to Ritesh Harjani

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(-)

fs/ext4/fast_commit.c +49 ~~-10~~

index 55d33f296cae..6990429daa0e 100644
@@ -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;

Signature · 1 line

2.31.1

Ritesh Harjani

author

2022-03-10 15:59 UTC #6 lore raw

PATCH v2 6/10 ext4: Add new trace event in ext4_fc_cleanup

In reply to Ritesh Harjani

This adds a new trace event in ext4_fc_cleanup() which is helpful in debugging some fast_commit issues.

Signed-off-by Ritesh Harjani <[email protected]>

---
 fs/ext4/fast_commit.c       |  1 +
 include/trace/events/ext4.h | 26 ++++++++++++++++++++++++++
 2 files changed, 27 insertions(+)

fs/ext4/fast_commit.c +1 -0

index 6990429daa0e..f4a56298fd88 100644
@@ -1280,6 +1280,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);

include/trace/events/ext4.h +26 -0

index c3d16dd829aa..46bc644ccd0d 100644
@@ -2862,6 +2862,32 @@ TRACE_EVENT(ext4_fc_track_range,
 		      __entry->end)
 	);
 
+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),

Signature · 1 line

2.31.1

Ritesh Harjani

author

2022-03-10 15:59 UTC #9 lore raw

PATCH v2 9/10 ext4: Add commit tid info in ext4_fc_commit_start/stop trace events

In reply to Ritesh Harjani

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]>

Reviewed-by Jan Kara <[email protected]>

Reviewed-by Harshad Shirwadkar <[email protected]>

---
 fs/ext4/fast_commit.c       |  4 ++--
 include/trace/events/ext4.h | 21 +++++++++++++--------
 2 files changed, 15 insertions(+), 10 deletions(-)

fs/ext4/fast_commit.c +2 -2

index 88ed99e670c5..3d72565ec6e8 100644
@@ -1187,7 +1187,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);
 }
 
 /*

@@ -1208,7 +1208,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();

include/trace/events/ext4.h +13 -8

index cff9b67763c4..09766eb56988 100644
@@ -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)					\

Signature · 1 line

2.31.1

Ritesh Harjani

author

2022-03-10 16:00 UTC #0 lore raw

v2 cover 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

Ritesh Harjani

author

2022-03-10 16:00 UTC #10 lore raw

PATCH v2 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(-)

include/trace/events/ext4.h +2 -2

index 09766eb56988..2137911a9392 100644
@@ -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)
 );

Signature · 1 line

2.31.1

Ritesh Harjani

author

2022-03-10 16:00 UTC #2 lore raw

PATCH v2 2/10 ext4: Fix ext4_fc_stats trace point

In reply to Ritesh Harjani

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(-)

include/trace/events/ext4.h +48 ~~-29~~

index 19e957b7f941..db404eb9b666 100644
@@ -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)				\

Signature · 1 line

2.31.1

Ritesh Harjani

author

2022-03-10 16:00 UTC #7 lore raw

PATCH v2 7/10 ext4: Add transaction tid info in fc_track events

In reply to Ritesh Harjani

This patch adds the transaction & inode tid info in trace events for callers of ext4_fc_track_template(). This is helpful in debugging race conditions where an inode could belong to two different transaction tids. It also fixes the checkpatch warnings which says use tabs instead of spaces.

Signed-off-by Ritesh Harjani <[email protected]>

---
 fs/ext4/fast_commit.c       |  10 ++--
 include/trace/events/ext4.h | 113 ++++++++++++++++++++++--------------
 2 files changed, 73 insertions(+), 50 deletions(-)

fs/ext4/fast_commit.c +5 -5

index f4a56298fd88..849fd4dcb825 100644
@@ -487,7 +487,7 @@ void __ext4_fc_track_unlink(handle_t *handle,
 
 	ret = ext4_fc_track_template(handle, inode, __track_dentry_update,
 					(void *)&args, 0);
-	trace_ext4_fc_track_unlink(inode, dentry, ret);
+	trace_ext4_fc_track_unlink(handle, inode, dentry, ret);
 }
 
 void ext4_fc_track_unlink(handle_t *handle, struct dentry *dentry)

@@ -516,7 +516,7 @@ void __ext4_fc_track_link(handle_t *handle,
 
 	ret = ext4_fc_track_template(handle, inode, __track_dentry_update,
 					(void *)&args, 0);
-	trace_ext4_fc_track_link(inode, dentry, ret);
+	trace_ext4_fc_track_link(handle, inode, dentry, ret);
 }
 
 void ext4_fc_track_link(handle_t *handle, struct dentry *dentry)

@@ -545,7 +545,7 @@ void __ext4_fc_track_create(handle_t *handle, struct inode *inode,
 
 	ret = ext4_fc_track_template(handle, inode, __track_dentry_update,
 					(void *)&args, 0);
-	trace_ext4_fc_track_create(inode, dentry, ret);
+	trace_ext4_fc_track_create(handle, inode, dentry, ret);
 }
 
 void ext4_fc_track_create(handle_t *handle, struct dentry *dentry)

@@ -596,7 +596,7 @@ void ext4_fc_track_inode(handle_t *handle, struct inode *inode)
 		return;
 
 	ret = ext4_fc_track_template(handle, inode, __track_inode, NULL, 1);
-	trace_ext4_fc_track_inode(inode, ret);
+	trace_ext4_fc_track_inode(handle, inode, ret);
 }
 
 struct __track_range_args {

@@ -653,7 +653,7 @@ void ext4_fc_track_range(handle_t *handle, struct inode *inode, ext4_lblk_t star
 
 	ret = ext4_fc_track_template(handle, inode,  __track_range, &args, 1);
 
-	trace_ext4_fc_track_range(inode, start, end, ret);
+	trace_ext4_fc_track_range(handle, inode, start, end, ret);
 }
 
 static void ext4_fc_submit_bh(struct super_block *sb, bool is_tail)

include/trace/events/ext4.h +68 ~~-45~~

152 lines not on this page · raw message

Signature · 1 line

2.31.1

Ritesh Harjani

author

2022-03-10 16:00 UTC #8 lore raw

PATCH v2 8/10 ext4: Add commit_tid info in jbd debug log

In reply to Ritesh Harjani

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(-)

fs/ext4/fast_commit.c +9 -6

index 849fd4dcb825..88ed99e670c5 100644
@@ -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;
 }

Signature · 1 line

2.31.1

Steven Rostedt

maintainer

2022-03-10 16:06 UTC #11 lore raw

In reply to Ritesh Harjani

Quoted 8 lines · 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

Ritesh Harjani

author

2022-03-10 17:08 UTC #12 lore raw

Quoted 8 lines · Steven Rostedt

Quoted 5 lines · 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).

Quoted 6 lines

Quoted 3 lines
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

Steven Rostedt

maintainer

2022-03-11 00:39 UTC #13 lore raw

Quoted 21 lines · On Thu, 10 Mar 2022 22:37:31 +0530 Ritesh Harjani <[email protected]> wrote:

Quoted 8 lines · Steven Rostedt
Quoted 5 lines · 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).
Quoted 6 lines
Quoted 3 lines
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).

Review

Quoted 3 lines

(quoted diff) +3 -0

+	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

and show me what it outputs.

Thanks,

-- Steve

Quoted 23 lines

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

(quoted diff) +15 -0

+	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

Ritesh Harjani

author

2022-03-11 02:20 UTC #14 lore raw

Quoted 31 lines · Steven Rostedt

Quoted 21 lines · On Thu, 10 Mar 2022 22:37:31 +0530 Ritesh Harjani <[email protected]> wrote:
Quoted 8 lines · Steven Rostedt
Quoted 5 lines · 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).
Quoted 6 lines
Quoted 3 lines
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).
Review
Quoted 3 lines
(quoted diff) +3 -0
+	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.

Quoted 3 lines

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.

Quoted 2 lines

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

          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

Quoted 30 lines

Thanks,

-- Steve

Quoted 23 lines

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

(quoted diff) +15 -0

+	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

Steven Rostedt

maintainer

2022-03-11 02:34 UTC #15 lore raw

Quoted 3 lines · On Fri, 11 Mar 2022 07:49:31 +0530 Ritesh Harjani <[email protected]> wrote:

Quoted 1 line
# cat /sys/kernel/tracing/events/ext4/ext4_fc_commit_stop/format  
I think you meant ext4_fc_stats.

Sure.

Quoted 13 lines

Quoted 3 lines

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;

Quoted 2 lines

        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;

Bah, the above tells us how many items, and the TRACE_DEFINE_ENUM() doesn't modify this part of the file.

I could update it to do so though.

-- Steve

Quoted 3 lines

        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;

Ritesh Harjani

author

2022-03-11 03:15 UTC #16 lore raw

Quoted 22 lines · Steven Rostedt

Quoted 3 lines · On Fri, 11 Mar 2022 07:49:31 +0530 Ritesh Harjani <[email protected]> wrote:

Quoted 1 line
# cat /sys/kernel/tracing/events/ext4/ext4_fc_commit_stop/format
I think you meant ext4_fc_stats.

Sure.

Quoted 13 lines

Quoted 3 lines

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;

Quoted 5 lines

Quoted 2 lines
        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;
Bah, the above tells us how many items, and the TRACE_DEFINE_ENUM() doesn't modify this part of the file.

Then shall I just define TRACE_DEFINE_ENUM(EXT4_FC_REASON_MAX) in this patch. Would that be the correct approach? Like how we have defined other enums. We haven't yet defined EXT4_FC_REASON_MAX in current patch.
(as I saw it doesn't affect TP_STRUCT__entry())

Quoted 2 lines

I could update it to do so though.

Please let me know if you have any patch for me to try.

Thanks
-ritesh

Quoted 8 lines

-- Steve

Quoted 3 lines

        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;

Steven Rostedt

maintainer

2022-03-11 04:32 UTC #17 lore raw

Quoted 3 lines · On Fri, 11 Mar 2022 08:44:31 +0530 Ritesh Harjani <[email protected]> wrote:

Quoted 1 line
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?

-- 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]/ open here

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(+)

kernel/trace/trace_events.c +28 -0

index 38afd66d80e3..ae9a3b8481f5 100644
@@ -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]);
 			}
 		}
 	}

Signature · 1 line

2.34.1

Ritesh Harjani

author

2022-03-11 05:13 UTC #18 lore raw

Quoted 8 lines · Steven Rostedt

Quoted 3 lines · On Fri, 11 Mar 2022 08:44:31 +0530 Ritesh Harjani <[email protected]> wrote:
Quoted 1 line
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

Quoted 24 lines

-- 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.

Quoted 7 lines

Link https://lore.kernel.org/all/[email protected]/ open here
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

Quoted 50 lines

kernel/trace/trace_events.c +28 -1

index 38afd66d80e3..ae9a3b8481f5 100644
@@ -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

Steven Rostedt

maintainer

2022-03-11 14:45 UTC #19 lore raw

Quoted 3 lines · On Fri, 11 Mar 2022 10:42:49 +0530 Ritesh Harjani <[email protected]> wrote:

You may add below, if you like:-
Reported-and-tested-by Ritesh Harjani <[email protected]>

Will do. Thanks for testing.

I'll be adding this for the next merge window. I don't think this is something that needs to be added to this rc release nor stable. Do you agree?

-- Steve

Ritesh Harjani

author

2022-03-11 15:04 UTC #20 lore raw

Quoted 5 lines · Steven Rostedt

Quoted 2 lines · On Fri, 11 Mar 2022 10:42:49 +0530 Ritesh Harjani <[email protected]> wrote:
You may add below, if you like:-

Quoted 7 lines

Quoted 1 line
Reported-and-tested-by Ritesh Harjani <[email protected]>
Will do. Thanks for testing.
I'll be adding this for the next merge window. I don't think this is something that needs to be added to this rc release nor stable. Do you agree?

If using an enum in TP_STRUCT__entry's __array field doesn't cause any side effect other than it just can't be decoded by userspace perf record / trace-cmd, then I guess it should be ok.

But for this PATCH 2/10 "ext4: Fix ext4_fc_stats trace point", will be needed to be Cc'd to stable tree as discussed before, as it tries to dereference some sbi pointer from the tracing ring buffer. Then hopefully the only problem with previous kernel version would be that ext4_fc_stats(), won't show proper values for array entries in older kernel version where this patch of trace_events is not found.
But cat /sys/kernel/debug/tracing/trace_pipe should be able to show the right values.

From my side, I will send a v3 of this patch series with just EXT4_FC_REASON_MAX defined using TRACE_DEFINE_ENUM.

Thanks again for your help :)

-ritesh

Quoted 2 lines

-- Steve

Steven Rostedt

maintainer

2022-03-11 16:42 UTC #21 lore raw

Quoted 10 lines · On Fri, 11 Mar 2022 20:33:57 +0530 Ritesh Harjani <[email protected]> wrote:

Quoted 9 lines · Steven Rostedt
Quoted 3 lines · On Fri, 11 Mar 2022 10:42:49 +0530 Ritesh Harjani <[email protected]> wrote:
You may add below, if you like:-
Reported-and-tested-by Ritesh Harjani <[email protected]>
Will do. Thanks for testing.

Quoted 7 lines

Quoted 3 lines
I'll be adding this for the next merge window. I don't think this is something that needs to be added to this rc release nor stable. Do you agree?
If using an enum in TP_STRUCT__entry's __array field doesn't cause any side effect other than it just can't be decoded by userspace perf record / trace-cmd, then I guess it should be ok.

Right. It only causes trace-cmd and perf to not be able to parse the field. But that's not really a regression, as it never was able to parse an enum defining an array size.

Quoted 10 lines

But for this PATCH 2/10 "ext4: Fix ext4_fc_stats trace point", will be needed to be Cc'd to stable tree as discussed before, as it tries to dereference some sbi pointer from the tracing ring buffer. Then hopefully the only problem with previous kernel version would be that ext4_fc_stats(), won't show proper values for array entries in older kernel version where this patch of trace_events is not found.
But cat /sys/kernel/debug/tracing/trace_pipe should be able to show the right values.

Quoted 2 lines

Quoted 1 line
From my side, I will send a v3 of this patch series with just EXT4_FC_REASON_MAX
defined using TRACE_DEFINE_ENUM.

OK, I'll just add this for the next merge window. If people complain about the parser not being able to parse this from user space, then we can either backport it, or add a plugin that parses it manually in libtraceevent.

Quoted 3 lines

Thanks again for your help :)

No problem. Thanks for the report.

-- Steve