ext4: Improve FC trace events and discuss one FC failure

RFC Superseded Ritesh Harjani 6 participants 35 messages Feb 22, 2022 – Mar 10, 2022

Subsystems (3)

VFS Tracing ext4 file system

lore

Share & tools

lore

Ritesh Harjani

author

2022-02-22 20:34 UTC #0 lore raw

cover ext4: Improve FC trace events and discuss one FC failure

Hello,

Sending this RFC out for getting some review comments/suggestions on the problem listed in this cover letter. It would be helpful if someone has any pointers around these.

1. Patch-2 fixes the problem reported by Steven about dereferencing pointers from the ring buffer [1].
One of the problem in this patch which I might need some help is, how to expose EXT4_FC_REASON_MAX enum for
+ __array(unsigned int, fc_ineligible_rc, EXT4_FC_REASON_MAX)

My observation is that this trace_event is correctly printing the array values when called from cat /sys/kernel/debug/tracing/trace_pipe.

But when I am using perf record -e ext4:ext4_fc_stats to record these trace events, I am seeing the array values to be all 0.

Do you know what will be the right and easy way to fix above, so that this works properly for perf tools too? And we should be able to backport this too.

2. Patch-9 discusses one of the problem where FC might miss to track/commit inode's update. This also needs some discussion. I have added my observations on the commit log of patch-9 itself.

3. Remaining are FC trace event improvement patches, which I found useful while debugging some of the recent fast_commit issues.

Also a careful review of patches is always helpful :)

[1]: https://lore.kernel.org/linux-ext4/[email protected]/T/#u

Ritesh Harjani (9):
ext4: Remove unused enum EXT4_FC_COMMIT_FAILED
ext4: Fix ext4_fc_stats trace point
ext4: Add couple of more fast_commit tracepoints
ext4: Do not call FC trace event if FS does not support FC
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
ext4: Convert ext4_fc_track_dentry type events to use event class
ext4: fast_commit missing tracking updates to a file

 fs/ext4/fast_commit.c       |  30 +++--
 fs/ext4/fast_commit.h       |   1 -
 include/trace/events/ext4.h | 229 +++++++++++++++++++++++++-----------
 3 files changed, 182 insertions(+), 78 deletions(-)

--
2.31.1

Ritesh Harjani

author

2022-02-22 20:34 UTC #1 lore raw

RFC 1/9 ext4: Remove unused enum EXT4_FC_COMMIT_FAILED

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

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

Jan Kara

reviewer Reviewed-by on v1 1/9

2022-02-23 09:37 UTC #2 lore raw

Re: [RFC 1/9] ext4: Remove unused enum EXT4_FC_COMMIT_FAILED

Quoted 6 lines · 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]>

Sure. Feel free to add:

Reviewed-by Jan Kara <[email protected]>

Honza

Quoted 19 lines

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

Signature · 2 lines

Jan Kara <[email protected]>
SUSE Labs, CR

harshad shirwadkar

Reviewed-by

2022-02-27 18:28 UTC #3 lore raw

Re: [RFC 1/9] ext4: Remove unused enum EXT4_FC_COMMIT_FAILED

Looks good.

Reviewed-by Harshad Shirwadkar <[email protected]>

- Harshad

Quoted 37 lines · Jan Kara

Quoted 6 lines · 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]>
Sure. Feel free to add:
Reviewed-by Jan Kara <[email protected]>
Honza
Quoted 17 lines
---
 fs/ext4/fast_commit.h | 1 -
 1 file changed, 1 deletion(-)
fs/ext4/fast_commit.h +0 -2
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
 };
 
--
Quoted 2 lines
2.31.1
--
Jan Kara <[email protected]>
SUSE Labs, CR

Ritesh Harjani

author

2022-02-22 20:35 UTC #4 lore raw

RFC 2/9 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 encoded in the ftrace ring buffer.

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.

Fixes commit aa75f4d3daae ("ext4: main fast-commit commit path")

Reported-by Steven Rostedt <[email protected]>

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

---
 include/trace/events/ext4.h | 76 +++++++++++++++++++++++--------------
 1 file changed, 47 insertions(+), 29 deletions(-)

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

index 19e957b7f941..17fb9c506e8a 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,49 @@ 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

Steven Rostedt

maintainer Reviewed-by on v1 2/9

2022-02-22 20:52 UTC #5 lore raw

Re: [RFC 2/9] ext4: Fix ext4_fc_stats trace point

Quoted 3 lines · On Wed, 23 Feb 2022 02:04:10 +0530 Ritesh Harjani <[email protected]> wrote:

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 encoded in the ftrace ring buffer.

Actually, you mean "decoded from the ftrace ring buffer by user space tooling".

Quoted 9 lines

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.
Fixes commit aa75f4d3daae ("ext4: main fast-commit commit path")

Should add:

Cc [email protected]

as the commit landed in 5.10.

Quoted 2 lines

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

Looks good with one small nit below.

Quoted 70 lines

---
 include/trace/events/ext4.h | 76 +++++++++++++++++++++++--------------
 1 file changed, 47 insertions(+), 29 deletions(-)

include/trace/events/ext4.h +20 ~~-26~~

index 19e957b7f941..17fb9c506e8a 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,49 @@ 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),

include/trace/events/ext4.h TRACE_EVENT(ext4_fc_commit_stop, · line 2757

Quoted 10 lines

include/trace/events/ext4.h +6 -3

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

As the above line is a continuation of the previous line, it should be indented as such. And since you added a line break, it is recommend to have any blocks use brackets. That is:

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

Other than that:

Reviewed-by Steven Rostedt (Google) <[email protected]>

-- Steve

Quoted 24 lines

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

+		__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)				\

Jan Kara

reviewer Reviewed-by on v1 2/9

2022-02-23 09:54 UTC #6 lore raw

Re: [RFC 2/9] ext4: Fix ext4_fc_stats trace point

In reply to Ritesh Harjani

Quoted 8 lines · 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 encoded in the ftrace ring buffer.
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.

Quoted 6 lines

Also to avoid checkpatch warnings, this patch removes those whitespaces/tab stops issues.
Fixes commit aa75f4d3daae ("ext4: main fast-commit commit path")
Reported-by Steven Rostedt <[email protected]>
Signed-off-by Ritesh Harjani <[email protected]>

Looks good (modulo Steven's nit). Feel free to add:

Reviewed-by Jan Kara <[email protected]>

Honza

Quoted 107 lines

---
 include/trace/events/ext4.h | 76 +++++++++++++++++++++++--------------
 1 file changed, 47 insertions(+), 29 deletions(-)

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

index 19e957b7f941..17fb9c506e8a 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,49 @@ 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

Signature · 2 lines

Jan Kara <[email protected]>
SUSE Labs, CR

harshad shirwadkar

Reviewed-by

2022-02-27 18:29 UTC #7 lore raw

Re: [RFC 2/9] ext4: Fix ext4_fc_stats trace point

Thanks for reporting this Steven and thanks Ritesh for fixing this.

Looks good.

Reviewed-by Harshad Shirwadkar <[email protected]>

- Harshad

Quoted 134 lines · Jan Kara

Quoted 8 lines · 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 encoded in the ftrace ring buffer.
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.

Quoted 6 lines

Also to avoid checkpatch warnings, this patch removes those whitespaces/tab stops issues.
Fixes commit aa75f4d3daae ("ext4: main fast-commit commit path")
Reported-by Steven Rostedt <[email protected]>
Signed-off-by Ritesh Harjani <[email protected]>

Looks good (modulo Steven's nit). Feel free to add:

Reviewed-by Jan Kara <[email protected]>

Honza

Quoted 105 lines

---
 include/trace/events/ext4.h | 76 +++++++++++++++++++++++--------------
 1 file changed, 47 insertions(+), 29 deletions(-)

include/trace/events/ext4.h +47 ~~-30~~

index 19e957b7f941..17fb9c506e8a 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,49 @@ 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)                            \
--

Quoted 2 lines

2.31.1

--
Jan Kara <[email protected]>
SUSE Labs, CR

Ritesh Harjani

author

2022-02-22 20:35 UTC #8 lore raw

RFC 3/9 ext4: Add couple of more fast_commit tracepoints

In reply to Ritesh Harjani

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 <[email protected]>

---
 fs/ext4/fast_commit.c       |  3 ++
 include/trace/events/ext4.h | 67 +++++++++++++++++++++++++++++++++++++
 2 files changed, 70 insertions(+)

fs/ext4/fast_commit.c +3 -0

index 5ac594e03402..bf70879bb4fe 100644
@@ -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);

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

73 lines not on this page · raw message

Signature · 1 line

2.31.1

Jan Kara

reviewer

2022-02-23 09:41 UTC #9 lore raw

Re: [RFC 3/9] ext4: Add couple of more fast_commit tracepoints

Quoted 4 lines · Ritesh Harjani

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 <[email protected]>

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

Quoted 107 lines

---
 fs/ext4/fast_commit.c       |  3 ++
 include/trace/events/ext4.h | 67 +++++++++++++++++++++++++++++++++++++
 2 files changed, 70 insertions(+)

fs/ext4/fast_commit.c +3 -0

index 5ac594e03402..bf70879bb4fe 100644
@@ -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);

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

index 17fb9c506e8a..cd09dccea502 100644
@@ -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),

Signature · 1 line

2.31.1

Signature · 2 lines

Jan Kara <[email protected]>
SUSE Labs, CR

Ritesh Harjani

author

2022-02-23 10:12 UTC #10 lore raw

Re: [RFC 3/9] ext4: Add couple of more fast_commit tracepoints

Quoted 9 lines · Jan Kara

Quoted 4 lines · Ritesh Harjani
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 <[email protected]>
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

Quoted 113 lines

Honza

Quoted 105 lines

---
 fs/ext4/fast_commit.c       |  3 ++
 include/trace/events/ext4.h | 67 +++++++++++++++++++++++++++++++++++++
 2 files changed, 70 insertions(+)

fs/ext4/fast_commit.c +3 -0

index 5ac594e03402..bf70879bb4fe 100644
@@ -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);

include/trace/events/ext4.h +67 -1

index 17fb9c506e8a..cd09dccea502 100644
@@ -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),
--

Quoted 2 lines

2.31.1

--
Jan Kara <[email protected]>
SUSE Labs, CR

Jan Kara

reviewer

2022-02-23 11:53 UTC #11 lore raw

Re: [RFC 3/9] ext4: Add couple of more fast_commit tracepoints

Quoted 11 lines · Ritesh Harjani

Quoted 9 lines · Jan Kara
Quoted 4 lines · Ritesh Harjani
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 <[email protected]>
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?

Quoted 8 lines

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.

Quoted 2 lines

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

Signature · 2 lines

Jan Kara <[email protected]>
SUSE Labs, CR

Ritesh Harjani

author

2022-02-23 12:05 UTC #12 lore raw

Re: [RFC 3/9] ext4: Add couple of more fast_commit tracepoints

Quoted 18 lines · Jan Kara

Quoted 17 lines · Ritesh Harjani
Quoted 9 lines · Jan Kara
Quoted 4 lines · Ritesh Harjani
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 <[email protected]>
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.

Quoted 7 lines

Quoted 2 lines
(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.

Quoted 6 lines

this tracepoint looked a bit superfluous to me.
Quoted 2 lines
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

Quoted 5 lines

Honza
--
Jan Kara <[email protected]>
SUSE Labs, CR

Ritesh Harjani

author

2022-02-22 20:35 UTC #13 lore raw

RFC 4/9 ext4: Do not call FC trace event 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]>

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

fs/ext4/fast_commit.c +3 -3

index bf70879bb4fe..7fb1eceef30c 100644
@@ -1167,13 +1167,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

Jan Kara

reviewer Reviewed-by on v1 4/9

2022-02-23 09:41 UTC #14 lore raw

Re: [RFC 4/9] ext4: Do not call FC trace event if FS does not support FC

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

Looks good. Feel free to add:

Reviewed-by Jan Kara <[email protected]>

Honza

Quoted 28 lines

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

fs/ext4/fast_commit.c +3 -3

index bf70879bb4fe..7fb1eceef30c 100644
@@ -1167,13 +1167,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

Signature · 2 lines

Jan Kara <[email protected]>
SUSE Labs, CR

harshad shirwadkar

Reviewed-by

2022-02-27 18:30 UTC #15 lore raw

Re: [RFC 4/9] ext4: Do not call FC trace event if FS does not support FC

Looks good.

Reviewed-by Harshad Shirwadkar <[email protected]>

- Harshad

Quoted 45 lines · Jan Kara

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

Looks good. Feel free to add:

Reviewed-by Jan Kara <[email protected]>

Honza

Quoted 26 lines

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

fs/ext4/fast_commit.c +3 -4

index bf70879bb4fe..7fb1eceef30c 100644
@@ -1167,13 +1167,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) {
--

Quoted 2 lines

2.31.1

--
Jan Kara <[email protected]>
SUSE Labs, CR

Ritesh Harjani

author

2022-02-22 20:35 UTC #16 lore raw

RFC 5/9 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]>

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

fs/ext4/fast_commit.c +9 -6

index 7fb1eceef30c..ee32aac0cbbf 100644
@@ -1127,11 +1127,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;

@@ -1181,14 +1182,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);
 	}

@@ -1220,12 +1223,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

Jan Kara

reviewer Reviewed-by on v1 5/9

2022-02-23 09:43 UTC #17 lore raw

Re: [RFC 5/9] ext4: Add commit_tid info in jbd debug log

Quoted 6 lines · 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]>

Looks good. Feel free to add:

Reviewed-by Jan Kara <[email protected]>

Honza

Quoted 60 lines

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

fs/ext4/fast_commit.c +9 -6

index 7fb1eceef30c..ee32aac0cbbf 100644
@@ -1127,11 +1127,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;

@@ -1181,14 +1182,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);
 	}

@@ -1220,12 +1223,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

Signature · 2 lines

Jan Kara <[email protected]>
SUSE Labs, CR

harshad shirwadkar

Reviewed-by

2022-02-27 18:31 UTC #18 lore raw

Re: [RFC 5/9] ext4: Add commit_tid info in jbd debug log

Looks good.

Reviewed-by Harshad Shirwadkar <[email protected]>

- Harshad

Quoted 78 lines · Jan Kara

Quoted 6 lines · 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]>

Looks good. Feel free to add:

Reviewed-by Jan Kara <[email protected]>

Honza

Quoted 58 lines

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

fs/ext4/fast_commit.c +9 -7

index 7fb1eceef30c..ee32aac0cbbf 100644
@@ -1127,11 +1127,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;

@@ -1181,14 +1182,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);
      }

@@ -1220,12 +1223,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;
 }
 
--

Quoted 2 lines

2.31.1

--
Jan Kara <[email protected]>
SUSE Labs, CR

Ritesh Harjani

author

2022-02-22 20:35 UTC #19 lore raw

RFC 6/9 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]>

---
 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 ee32aac0cbbf..8803ba087b07 100644
@@ -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();

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

index cd09dccea502..6e66cb7ce624 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

Jan Kara

reviewer Reviewed-by on v1 6/9

2022-02-23 09:44 UTC #20 lore raw

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

Quoted 11 lines · 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]>

Looks good. Feel free to add:

Reviewed-by Jan Kara <[email protected]>

Honza

Quoted 94 lines

---
 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 ee32aac0cbbf..8803ba087b07 100644
@@ -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();

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

index cd09dccea502..6e66cb7ce624 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

Signature · 2 lines

Jan Kara <[email protected]>
SUSE Labs, CR

harshad shirwadkar

Reviewed-by

2022-02-27 18:32 UTC #21 lore raw

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

Quoted 117 lines · Jan Kara

Quoted 11 lines · 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]>

Looks good. Feel free to add:

Reviewed-by Jan Kara <[email protected]>

Honza

Quoted 92 lines

---
 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 ee32aac0cbbf..8803ba087b07 100644
@@ -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();

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

index cd09dccea502..6e66cb7ce624 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)                                  \
--

Quoted 2 lines

2.31.1

--
Jan Kara <[email protected]>
SUSE Labs, CR

Ritesh Harjani

author

2022-02-22 20:35 UTC #22 lore raw

RFC 7/9 ext4: Fix remaining two trace events to use same printk convention

In reply to Ritesh Harjani

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

---
 include/trace/events/ext4.h | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

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

index 6e66cb7ce624..233dbffa5ceb 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

Jan Kara

reviewer Reviewed-by on v1 7/9

2022-02-23 09:45 UTC #23 lore raw

Re: [RFC 7/9] ext4: Fix remaining two trace events to use same printk convention

Quoted 6 lines · Ritesh Harjani

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

OK. Feel free to add:

Reviewed-by Jan Kara <[email protected]>

Honza

Quoted 29 lines

---
 include/trace/events/ext4.h | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

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

index 6e66cb7ce624..233dbffa5ceb 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

Signature · 2 lines

Jan Kara <[email protected]>
SUSE Labs, CR

harshad shirwadkar

Reviewed-by

2022-02-27 18:32 UTC #24 lore raw

Re: [RFC 7/9] ext4: Fix remaining two trace events to use same printk convention

Looks good.

Reviewed-by Harshad Shirwadkar <[email protected]>

- Harshad

Quoted 47 lines · Jan Kara

Quoted 6 lines · Ritesh Harjani

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

OK. Feel free to add:

Reviewed-by Jan Kara <[email protected]>

Honza

Quoted 27 lines

---
 include/trace/events/ext4.h | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

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

index 6e66cb7ce624..233dbffa5ceb 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)
 );
--

Quoted 2 lines

2.31.1

--
Jan Kara <[email protected]>
SUSE Labs, CR

Ritesh Harjani

author

2022-02-22 20:36 UTC #25 lore raw

RFC 8/9 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]>

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

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

index 233dbffa5ceb..33a059d845d6 100644
@@ -2783,33 +2783,40 @@ 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(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",
+		  MAJOR(__entry->dev), MINOR(__entry->dev),
+		  __entry->ino, __entry->error
 	)
+);
+
+#define DEFINE_EVENT_CLASS_TYPE(__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_TYPE(create);
+DEFINE_EVENT_CLASS_TYPE(link);
+DEFINE_EVENT_CLASS_TYPE(unlink);
 
 TRACE_EVENT(ext4_fc_track_inode,
 	    TP_PROTO(struct inode *inode, int ret),

Signature · 1 line

2.31.1

Jan Kara

reviewer Reviewed-by on v1 8/9

2022-02-23 09:49 UTC #26 lore raw

Re: [RFC 8/9] ext4: Convert ext4_fc_track_dentry type events to use event class

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

Looks good. Feel free to add:

Reviewed-by Jan Kara <[email protected]>

Honza

Quoted 77 lines

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

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

index 233dbffa5ceb..33a059d845d6 100644
@@ -2783,33 +2783,40 @@ 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(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",
+		  MAJOR(__entry->dev), MINOR(__entry->dev),
+		  __entry->ino, __entry->error
 	)
+);
+
+#define DEFINE_EVENT_CLASS_TYPE(__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_TYPE(create);
+DEFINE_EVENT_CLASS_TYPE(link);
+DEFINE_EVENT_CLASS_TYPE(unlink);
 
 TRACE_EVENT(ext4_fc_track_inode,
 	    TP_PROTO(struct inode *inode, int ret),

Signature · 1 line

2.31.1

Signature · 2 lines

Jan Kara <[email protected]>
SUSE Labs, CR

harshad shirwadkar

Reviewed-by

2022-02-27 18:35 UTC #27 lore raw

Re: [RFC 8/9] ext4: Convert ext4_fc_track_dentry type events to use event class

Nice! Thanks for fixing this.

Reviewed-by Harshad Shirwadkar <[email protected]>

- Harshad

Quoted 96 lines · Jan Kara

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

Looks good. Feel free to add:

Reviewed-by Jan Kara <[email protected]>

Honza

Quoted 75 lines

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

include/trace/events/ext4.h +32 ~~-26~~

index 233dbffa5ceb..33a059d845d6 100644
@@ -2783,33 +2783,40 @@ 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(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",
+               MAJOR(__entry->dev), MINOR(__entry->dev),
+               __entry->ino, __entry->error
      )
+);
+
+#define DEFINE_EVENT_CLASS_TYPE(__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_TYPE(create);
+DEFINE_EVENT_CLASS_TYPE(link);
+DEFINE_EVENT_CLASS_TYPE(unlink);
 
 TRACE_EVENT(ext4_fc_track_inode,
          TP_PROTO(struct inode *inode, int ret),
--

Quoted 2 lines

2.31.1

--
Jan Kara <[email protected]>
SUSE Labs, CR

Ritesh Harjani

author

2022-02-22 20:36 UTC #28 lore raw

RFC 9/9 ext4: fast_commit missing tracking updates to a file

In reply to Ritesh Harjani

Testcase
==========
1. i=0; while [ $i -lt 1000 ]; do xfs_io -f -c "pwrite -S 0xaa -b 32k 0 32k" -c "fsync" /mnt/$i; i=$(($i+1)); done && sudo ./src/godown -v /mnt && sudo umount /mnt && sudo mount /dev/loop2 /mnt'
2. ls -alih /mnt/ -> In this you will observe one such file with 0 bytes (which ideally should not happen)

^^^ say if you don't see the issue because your underlying storage device is very fast, then maybe try with commit=1 mount option.

Analysis
==========
It seems a file's updates can be a part of two transaction tid. Below are the sequence of events which could cause this issue.

jbd2_handle_start -> (t_tid = 38)
__ext4_new_inode
ext4_fc_track_template -> __track_inode -> (i_sync_tid = 38, t_tid = 38) <track more updates>
jbd2_start_commit -> (t_tid = 38)

jbd2_handle_start (tid = 39)
ext4_fc_track_template -> __track_inode -> (i_sync_tid = 38, t_tid 39)

    -> ext4_fc_reset_inode & ei->i_sync_tid = t_tid

ext4_fc_commit_start -> (will wait since jbd2 full commit is in progress) jbd2_end_commit (t_tid = 38)

    -> jbd2_fc_cleanup() -> this will cleanup entries in sbi->s_fc_q[FC_Q_MAIN]
        -> And the above could result inode size as 0 as  after effect.

ext4_fc_commit_stop

You could find the logs for the above behavior for inode 979 at [1].

-> So what is happening here is since the ei->i_fc_list is not empty (because it is already part of sb's MAIN queue), we don't add this inode again into neither sb's MAIN or STAGING queue.
And after jbd2_fc_cleanup() is called from jbd2 full commit, we just remove this inode from the main queue.

So as a simple fix, what I did below was to check if it is a jbd2 full commit in ext4_fc_cleanup(), and if the ei->i_sync_tid > tid, that means we need not remove that from MAIN queue. This is since neither jbd2 nor FC has committed updates of those inodes for this new txn tid yet.

But below are some quick queries on this
=========================================

1. why do we call ext4_fc_reset_inode() when inode tid and running txn tid does not match?

2. Also is this an expected behavior from the design perspective of fast_commit. i.e.
a. the inode can be part of two tids?
b. And that while a full commit is in progress, the inode can still receive updates but using a new transaction tid.

Frankly speaking, since I was also working on other things, so I haven't yet got the chance to completely analyze the situation yet. Once I have those things sorted, I will spend more time on this, to understand it more. Meanwhile if you already have some answers to above queries/observations, please do share those here.

Links
=========
[1] https://raw.githubusercontent.com/riteshharjani/LinuxStudy/master/ext4/fast_commit/fc_inode_missing_updates_ino_979.txt

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

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

fs/ext4/fast_commit.c +2 -0

index 8803ba087b07..769b584c2552 100644
@@ -1252,6 +1252,8 @@ static void ext4_fc_cleanup(journal_t *journal, int full, tid_t tid)
 	spin_lock(&sbi->s_fc_lock);
 	list_for_each_entry_safe(iter, iter_n, &sbi->s_fc_q[FC_Q_MAIN],
 				 i_fc_list) {
+		if (full && iter->i_sync_tid > tid)
+			continue;
 		list_del_init(&iter->i_fc_list);
 		ext4_clear_inode_state(&iter->vfs_inode,
 				       EXT4_STATE_FC_COMMITTING);

Signature · 1 line

2.31.1

Xin Yin

2022-02-23 03:51 UTC #29 lore raw

Re: [External] [RFC 9/9] ext4: fast_commit missing tracking updates to a file

Quoted 45 lines · Ritesh Harjani

<DO NOT MERGE THIS YET>
Testcase
==========
1. i=0; while [ $i -lt 1000 ]; do xfs_io -f -c "pwrite -S 0xaa -b 32k 0 32k" -c "fsync" /mnt/$i; i=$(($i+1)); done && sudo ./src/godown -v /mnt && sudo umount /mnt && sudo mount /dev/loop2 /mnt'
2. ls -alih /mnt/ -> In this you will observe one such file with 0 bytes (which ideally should not happen)
^^^ say if you don't see the issue because your underlying storage device is very fast, then maybe try with commit=1 mount option.
Analysis
==========
It seems a file's updates can be a part of two transaction tid. Below are the sequence of events which could cause this issue.
jbd2_handle_start -> (t_tid = 38)
__ext4_new_inode
ext4_fc_track_template -> __track_inode -> (i_sync_tid = 38, t_tid = 38) <track more updates>
jbd2_start_commit -> (t_tid = 38)
jbd2_handle_start (tid = 39)
ext4_fc_track_template -> __track_inode -> (i_sync_tid = 38, t_tid 39)
    -> ext4_fc_reset_inode & ei->i_sync_tid = t_tid
ext4_fc_commit_start -> (will wait since jbd2 full commit is in progress) jbd2_end_commit (t_tid = 38)
    -> jbd2_fc_cleanup() -> this will cleanup entries in sbi->s_fc_q[FC_Q_MAIN]
        -> And the above could result inode size as 0 as  after effect.
ext4_fc_commit_stop
You could find the logs for the above behavior for inode 979 at [1].
-> So what is happening here is since the ei->i_fc_list is not empty (because it is already part of sb's MAIN queue), we don't add this inode again into neither sb's MAIN or STAGING queue.
And after jbd2_fc_cleanup() is called from jbd2 full commit, we just remove this inode from the main queue.
So as a simple fix, what I did below was to check if it is a jbd2 full commit in ext4_fc_cleanup(), and if the ei->i_sync_tid > tid, that means we need not remove that from MAIN queue. This is since neither jbd2 nor FC has committed updates of those inodes for this new txn tid yet.

Quoted 5 lines

But below are some quick queries on this
=========================================
1. why do we call ext4_fc_reset_inode() when inode tid and running txn tid does not match?

This is part of a change in commit:bdc8a53a6f2f, it fixes the issue for fc tracking logic while jbd2 commit is ongoing.
If the inode tid is bigger than txn tid, that means this inode may be in the STAGING queue, if we reset it then it will lose the tack range. I think it's a similar issue, the difference is this inode is already in the MAIN queue before the jbd2 commit starts.
And yes , I think in this case we can not remove it from the MAIN queue, but still need to clear EXT4_STATE_FC_COMMITTING right? it may block some task still waiting for it.

Thanks,
Xin Yin

Quoted 38 lines

2. Also is this an expected behavior from the design perspective of fast_commit. i.e.
a. the inode can be part of two tids?
b. And that while a full commit is in progress, the inode can still receive updates but using a new transaction tid.
Frankly speaking, since I was also working on other things, so I haven't yet got the chance to completely analyze the situation yet. Once I have those things sorted, I will spend more time on this, to understand it more. Meanwhile if you already have some answers to above queries/observations, please do share those here.
Links
=========
[1] https://raw.githubusercontent.com/riteshharjani/LinuxStudy/master/ext4/fast_commit/fc_inode_missing_updates_ino_979.txt
Signed-off-by Ritesh Harjani <[email protected]>
---
 fs/ext4/fast_commit.c | 2 ++
 1 file changed, 2 insertions(+)
fs/ext4/fast_commit.c +2 -1
index 8803ba087b07..769b584c2552 100644
@@ -1252,6 +1252,8 @@ static void ext4_fc_cleanup(journal_t *journal, int full, tid_t tid)
        spin_lock(&sbi->s_fc_lock);
        list_for_each_entry_safe(iter, iter_n, &sbi->s_fc_q[FC_Q_MAIN],
                                 i_fc_list) {
+               if (full && iter->i_sync_tid > tid)
+                       continue;
                list_del_init(&iter->i_fc_list);
                ext4_clear_inode_state(&iter->vfs_inode,
                                       EXT4_STATE_FC_COMMITTING);
--
2.31.1

Ritesh Harjani

author

2022-02-23 13:59 UTC #30 lore raw

Re: [External] [RFC 9/9] ext4: fast_commit missing tracking updates to a file

Quoted 46 lines · Xin Yin

Quoted 45 lines · Ritesh Harjani
<DO NOT MERGE THIS YET>
Testcase
==========
1. i=0; while [ $i -lt 1000 ]; do xfs_io -f -c "pwrite -S 0xaa -b 32k 0 32k" -c "fsync" /mnt/$i; i=$(($i+1)); done && sudo ./src/godown -v /mnt && sudo umount /mnt && sudo mount /dev/loop2 /mnt'
2. ls -alih /mnt/ -> In this you will observe one such file with 0 bytes (which ideally should not happen)
^^^ say if you don't see the issue because your underlying storage device is very fast, then maybe try with commit=1 mount option.
Analysis
==========
It seems a file's updates can be a part of two transaction tid. Below are the sequence of events which could cause this issue.
jbd2_handle_start -> (t_tid = 38)
__ext4_new_inode
ext4_fc_track_template -> __track_inode -> (i_sync_tid = 38, t_tid = 38) <track more updates>
jbd2_start_commit -> (t_tid = 38)
jbd2_handle_start (tid = 39)
ext4_fc_track_template -> __track_inode -> (i_sync_tid = 38, t_tid 39)
    -> ext4_fc_reset_inode & ei->i_sync_tid = t_tid
ext4_fc_commit_start -> (will wait since jbd2 full commit is in progress) jbd2_end_commit (t_tid = 38)
    -> jbd2_fc_cleanup() -> this will cleanup entries in sbi->s_fc_q[FC_Q_MAIN]
        -> And the above could result inode size as 0 as  after effect.
ext4_fc_commit_stop
You could find the logs for the above behavior for inode 979 at [1].
-> So what is happening here is since the ei->i_fc_list is not empty (because it is already part of sb's MAIN queue), we don't add this inode again into neither sb's MAIN or STAGING queue.
And after jbd2_fc_cleanup() is called from jbd2 full commit, we just remove this inode from the main queue.
So as a simple fix, what I did below was to check if it is a jbd2 full commit in ext4_fc_cleanup(), and if the ei->i_sync_tid > tid, that means we need not remove that from MAIN queue. This is since neither jbd2 nor FC has committed updates of those inodes for this new txn tid yet.

Quoted 7 lines

Quoted 5 lines
But below are some quick queries on this
=========================================
1. why do we call ext4_fc_reset_inode() when inode tid and running txn tid does not match?
This is part of a change in commit:bdc8a53a6f2f, it fixes the issue for fc tracking logic while jbd2 commit is ongoing.

Thanks Xin for pointing the other issue too.
But I think what I was mostly referring to was - calling ext4_fc_reset_inode() in ext4_fc_track_template().

<..>

 391         tid = handle->h_transaction->t_tid;
 392         mutex_lock(&ei->i_fc_lock);
 393         if (tid == ei->i_sync_tid) {
 394                 update = true;
 395         } else {
 396                 ext4_fc_reset_inode(inode);
 397                 ei->i_sync_tid = tid;
 398         }
 399         ret = __fc_track_fn(inode, args, update);
 400         mutex_unlock(&ei->i_fc_lock);

<..>

So, yes these are few corner cases which I want to take a deeper look at. I vaugely understand that this reset inode is done since we anyway might have done the full commit for previous tid, so we can reset the inode track range.

So, yes, we should carefully review this as well that if jbd2 commit happens for an inode which is still part of MAIN_Q, then does it make sense to still call ext4_fc_reset_inode() for that inode in ext4_fc_track_template()?

Quoted 3 lines

If the inode tid is bigger than txn tid, that means this inode may be in the STAGING queue, if we reset it then it will lose the tack range. I think it's a similar issue, the difference is this inode is already

Do you have a test case which was failing for your issue? I would like to test that one too.

Quoted 2 lines

in the MAIN queue before the jbd2 commit starts.
And yes , I think in this case we can not remove it from the MAIN

Yes. I too have a similar thought. But I still wanted to get few queries sorted (like point 1 & 2).

Quoted 2 lines

queue, but still need to clear EXT4_STATE_FC_COMMITTING right? it may block some task still waiting for it.

Sorry I didn't get you here. So I think we will end up in such situation (where ext4_fc_cleanup() is getting called for an inode with i_sync_tid > tid) only from full commit path right ?
And that won't set EXT4_FC_COMMITTING for this inode right anyways no?

Do you mean anything else, or am I missing something here?

-ritesh

Quoted 41 lines

Thanks,
Xin Yin
Quoted 38 lines
2. Also is this an expected behavior from the design perspective of fast_commit. i.e.
a. the inode can be part of two tids?
b. And that while a full commit is in progress, the inode can still receive updates but using a new transaction tid.
Frankly speaking, since I was also working on other things, so I haven't yet got the chance to completely analyze the situation yet. Once I have those things sorted, I will spend more time on this, to understand it more. Meanwhile if you already have some answers to above queries/observations, please do share those here.
Links
=========
[1] https://raw.githubusercontent.com/riteshharjani/LinuxStudy/master/ext4/fast_commit/fc_inode_missing_updates_ino_979.txt
Signed-off-by Ritesh Harjani <[email protected]>
---
 fs/ext4/fast_commit.c | 2 ++
 1 file changed, 2 insertions(+)
fs/ext4/fast_commit.c +2 -1
index 8803ba087b07..769b584c2552 100644
@@ -1252,6 +1252,8 @@ static void ext4_fc_cleanup(journal_t *journal, int full, tid_t tid)
        spin_lock(&sbi->s_fc_lock);
        list_for_each_entry_safe(iter, iter_n, &sbi->s_fc_q[FC_Q_MAIN],
                                 i_fc_list) {
+               if (full && iter->i_sync_tid > tid)
+                       continue;
                list_del_init(&iter->i_fc_list);
                ext4_clear_inode_state(&iter->vfs_inode,
                                       EXT4_STATE_FC_COMMITTING);
--
2.31.1

Xin Yin

2022-02-24 11:44 UTC #31 lore raw

Re: [External] [RFC 9/9] ext4: fast_commit missing tracking updates to a file

Quoted 51 lines · Ritesh Harjani

Quoted 49 lines · Xin Yin
Quoted 48 lines · Ritesh Harjani
<DO NOT MERGE THIS YET>
Testcase
==========
1. i=0; while [ $i -lt 1000 ]; do xfs_io -f -c "pwrite -S 0xaa -b 32k 0 32k" -c "fsync" /mnt/$i; i=$(($i+1)); done && sudo ./src/godown -v /mnt && sudo umount /mnt && sudo mount /dev/loop2 /mnt'
2. ls -alih /mnt/ -> In this you will observe one such file with 0 bytes (which ideally should not happen)
^^^ say if you don't see the issue because your underlying storage device is very fast, then maybe try with commit=1 mount option.
Analysis
==========
It seems a file's updates can be a part of two transaction tid. Below are the sequence of events which could cause this issue.
jbd2_handle_start -> (t_tid = 38)
__ext4_new_inode
ext4_fc_track_template -> __track_inode -> (i_sync_tid = 38, t_tid = 38) <track more updates>
jbd2_start_commit -> (t_tid = 38)
jbd2_handle_start (tid = 39)
ext4_fc_track_template -> __track_inode -> (i_sync_tid = 38, t_tid 39)
    -> ext4_fc_reset_inode & ei->i_sync_tid = t_tid
ext4_fc_commit_start -> (will wait since jbd2 full commit is in progress) jbd2_end_commit (t_tid = 38)
    -> jbd2_fc_cleanup() -> this will cleanup entries in sbi->s_fc_q[FC_Q_MAIN]
        -> And the above could result inode size as 0 as  after effect.
ext4_fc_commit_stop
You could find the logs for the above behavior for inode 979 at [1].
-> So what is happening here is since the ei->i_fc_list is not empty (because it is already part of sb's MAIN queue), we don't add this inode again into neither sb's MAIN or STAGING queue.
And after jbd2_fc_cleanup() is called from jbd2 full commit, we just remove this inode from the main queue.
So as a simple fix, what I did below was to check if it is a jbd2 full commit in ext4_fc_cleanup(), and if the ei->i_sync_tid > tid, that means we need not remove that from MAIN queue. This is since neither jbd2 nor FC has committed updates of those inodes for this new txn tid yet.
But below are some quick queries on this
=========================================

Quoted 9 lines

Quoted 4 lines
Quoted 2 lines
1. why do we call ext4_fc_reset_inode() when inode tid and running txn tid does not match?
This is part of a change in commit:bdc8a53a6f2f, it fixes the issue for fc tracking logic while jbd2 commit is ongoing.
Thanks Xin for pointing the other issue too.
But I think what I was mostly referring to was - calling ext4_fc_reset_inode() in ext4_fc_track_template().

Understood, I missed something here, then maybe Harshad can give some directions for this part.

Quoted 21 lines

<..>
 391         tid = handle->h_transaction->t_tid;
 392         mutex_lock(&ei->i_fc_lock);
 393         if (tid == ei->i_sync_tid) {
 394                 update = true;
 395         } else {
 396                 ext4_fc_reset_inode(inode);
 397                 ei->i_sync_tid = tid;
 398         }
 399         ret = __fc_track_fn(inode, args, update);
 400         mutex_unlock(&ei->i_fc_lock);
<..>
So, yes these are few corner cases which I want to take a deeper look at. I vaugely understand that this reset inode is done since we anyway might have done the full commit for previous tid, so we can reset the inode track range.
So, yes, we should carefully review this as well that if jbd2 commit happens for an inode which is still part of MAIN_Q, then does it make sense to still call ext4_fc_reset_inode() for that inode in ext4_fc_track_template()?

Quoted 6 lines

Quoted 3 lines
If the inode tid is bigger than txn tid, that means this inode may be in the STAGING queue, if we reset it then it will lose the tack range. I think it's a similar issue, the difference is this inode is already
Do you have a test case which was failing for your issue? I would like to test that one too.

This issue can be triggered by generic/455 , but this is one failed case for it. I also do not have a reproducer for this.

Quoted 8 lines

Quoted 4 lines
in the MAIN queue before the jbd2 commit starts.
And yes , I think in this case we can not remove it from the MAIN
Yes. I too have a similar thought. But I still wanted to get few queries sorted (like point 1 & 2).

Quoted 7 lines

Quoted 2 lines
queue, but still need to clear EXT4_STATE_FC_COMMITTING right? it may block some task still waiting for it.
Sorry I didn't get you here. So I think we will end up in such situation (where ext4_fc_cleanup() is getting called for an inode with i_sync_tid > tid) only from full commit path right ?
And that won't set EXT4_FC_COMMITTING for this inode right anyways no?

I am not sure if there are any other cases, But for now we also clear
EXT4_STATE_FC_COMMITTING in the full commit path right? So maybe some further tests are needed.

Thanks,
Xin Yin

Quoted 47 lines

Do you mean anything else, or am I missing something here?
-ritesh
Quoted 41 lines
Thanks,
Xin Yin
Quoted 38 lines
2. Also is this an expected behavior from the design perspective of fast_commit. i.e.
a. the inode can be part of two tids?
b. And that while a full commit is in progress, the inode can still receive updates but using a new transaction tid.
Frankly speaking, since I was also working on other things, so I haven't yet got the chance to completely analyze the situation yet. Once I have those things sorted, I will spend more time on this, to understand it more. Meanwhile if you already have some answers to above queries/observations, please do share those here.
Links
=========
[1] https://raw.githubusercontent.com/riteshharjani/LinuxStudy/master/ext4/fast_commit/fc_inode_missing_updates_ino_979.txt
Signed-off-by Ritesh Harjani <[email protected]>
---
 fs/ext4/fast_commit.c | 2 ++
 1 file changed, 2 insertions(+)
fs/ext4/fast_commit.c +2 -1
index 8803ba087b07..769b584c2552 100644
@@ -1252,6 +1252,8 @@ static void ext4_fc_cleanup(journal_t *journal, int full, tid_t tid)
        spin_lock(&sbi->s_fc_lock);
        list_for_each_entry_safe(iter, iter_n, &sbi->s_fc_q[FC_Q_MAIN],
                                 i_fc_list) {
+               if (full && iter->i_sync_tid > tid)
+                       continue;
                list_del_init(&iter->i_fc_list);
                ext4_clear_inode_state(&iter->vfs_inode,
                                       EXT4_STATE_FC_COMMITTING);
--
2.31.1

harshad shirwadkar

2022-02-27 20:52 UTC #32 lore raw

Re: [External] [RFC 9/9] ext4: fast_commit missing tracking updates to a file

Quoted 7 lines

Quoted 7 lines
So, yes these are few corner cases which I want to take a deeper look at. I vaugely understand that this reset inode is done since we anyway might have done the full commit for previous tid, so we can reset the inode track range.
So, yes, we should carefully review this as well that if jbd2 commit happens for an inode which is still part of MAIN_Q, then does it make sense to still call ext4_fc_reset_inode() for that inode in ext4_fc_track_template()?

What this code assumes here is that if tid != ei->i_sync_tid, then the fast commit information present in the inode cannot be trusted. This is useful when the inode is added to the fast commit queue for the first ever or first time during the current transaction. Also note the "update" parameter, if update is set to false, then the track functions know that this is the first time the track function is called since the last (fast / full) commit.

I think the simple invariant that we need to follow is that, once an inode is committed (either by fast or full commit) ext4_fc_reset_inode() should be called exactly once before any track functions get called. So, if we can ensure that reset gets called on all inodes that were committed by fast commit / full commit exactly once before any track functions update the fc info, then we don't really need this reset call here.

Quoted 3 lines

Quoted 3 lines
Quoted 3 lines
Quoted 3 lines
2. Also is this an expected behavior from the design perspective of fast_commit. i.e.
a. the inode can be part of two tids?

From a design perspective, in fast commits, inode updates are not strictly tied to tids. We reuse i_sync_tid only to detect if the updates to an inode are committed or not. But at a high level, inode can be in 3 states from fc perspective - (1) inode is not modified since last fast commit / full commit (2) inode is modified since last fast commit / full commit (3) inode is being committed by fast commit. Well, this makes me think that these states can also be represented by inode states, and maybe if we do that we can get rid of reliance on i_sync_tid altogether? This needs a bit more thought.

Quoted 2 lines

Quoted 2 lines
Quoted 2 lines
Quoted 2 lines
b. And that while a full commit is in progress, the inode can still receive updates but using a new transaction tid.

Yeah, inode can still receive updates if a full commit is ongoing. If a fast commit is ongoing on a particular update, then the inode will not receive updates. EXT4_FC_STATE_COMMITTING will protect against it. In the new patch that I'm working on (sorry for the delay on that), what I'm doing is that handles that modify inode wait if the inode is being committed.

- Harshad

Quoted 32 lines

Quoted 32 lines
Quoted 32 lines
Quoted 32 lines
Frankly speaking, since I was also working on other things, so I haven't yet got the chance to completely analyze the situation yet. Once I have those things sorted, I will spend more time on this, to understand it more. Meanwhile if you already have some answers to above queries/observations, please do share those here.
Links
=========
[1] https://raw.githubusercontent.com/riteshharjani/LinuxStudy/master/ext4/fast_commit/fc_inode_missing_updates_ino_979.txt
Signed-off-by Ritesh Harjani <[email protected]>
---
 fs/ext4/fast_commit.c | 2 ++
 1 file changed, 2 insertions(+)
fs/ext4/fast_commit.c +2 -1
index 8803ba087b07..769b584c2552 100644
@@ -1252,6 +1252,8 @@ static void ext4_fc_cleanup(journal_t *journal, int full, tid_t tid)
        spin_lock(&sbi->s_fc_lock);
        list_for_each_entry_safe(iter, iter_n, &sbi->s_fc_q[FC_Q_MAIN],
                                 i_fc_list) {
+               if (full && iter->i_sync_tid > tid)
+                       continue;
                list_del_init(&iter->i_fc_list);
                ext4_clear_inode_state(&iter->vfs_inode,
                                       EXT4_STATE_FC_COMMITTING);
--
2.31.1

Theodore Ts'o

maintainer

2022-03-09 17:48 UTC #33 lore raw

In reply to Ritesh Harjani

Ritesh,

Were you going to be sending a revised version of this patch series?

Thanks!

- Ted

Ritesh Harjani

author

2022-03-10 01:22 UTC #34 lore raw

Quoted 3 lines · Theodore Ts'o

Ritesh,
Were you going to be sending a revised version of this patch series?

Hello Ted,

Due to some unexpected guests at home, I was on leave since last weekend. I am starting to work from today. Let me work on the revised version of this patch series. I will try to complete it before end of day i.e. before our call.

-ritesh