[PATCH 0/2] ext4: Workaround trace event flag decoding issues

[PATCH 0/2] ext4: Workaround trace event flag decoding issues

[Dmitry Monakhov]

Trace's macro __print_flags() produce raw event's decraration w/o knowing actual
flags value. For example trace_ext4_map_blocks_exit() has two __print_flags
tables, one for EXT4_GET_BLOCKS_XX, and second for EXT4_MAP_XXX

cat /sys/kernel/debug/tracing/events/ext4/ext4_ext_map_blocks_exit/format
..
print fmt: "dev %d,%d ino %lu flags %s lblk %u pblk %llu len %u mflags %s ret %d",
....
 __print_flags(REC->flags, "|", { 0x0001, "CREATE" }, { 0x0002, "UNWRIT" },...
 __print_flags(REC->mflags, "", { (1 << BH_New), "N" }, { (1 << BH_Mapped), "M" }..

First macro expanded w/o issued because EXT4_GET_BLOCKS_XXX flags are explicit
numbers, but second macro stil contains text fields because it depends on
implicit enum values. It is important to note that this is exact representation
of event's binary format. This means that  perf-script can not decode bintrace
file because BH_XXX is just a text token which is unknown to userspace.
As result perf fail to decode it and fallback to dump it as raw hex number.
For example:
  ext4:ext4_ext_map_blocks_exit: dev 253,0 ino 12 flags CREATE lblk 0 pblk 34304 len 1 mflags 0x60 ret 1

I tend to agree that this is likely to be trace API issue, but it looks like that
EXT4 is the only subsystem which is affected. Others already workaround this by
using explicit numbers. Let's do the same trick.
TOC:
   ext4: Use raw numbers for EXT4_MAP_XXX flags
   ext4: Fix extent_status trace events

[PATCH 1/2] ext4: Use raw numbers for EXT4_MAP_XXX flags

[Dmitry Monakhov]

Trace's macro __print_flags() produce raw event's decraration w/o knowing actual flags value

cat /sys/kernel/debug/tracing/events/ext4/ext4_ext_map_blocks_exit/format
..
__print_flags(REC->mflags, "", { (1 << BH_New),
..
This means that  perf-script can not decode bintrace file because BH_XXX is just a text and it is
unknown for perf's userspace. As result perf will dump this field as raw hex number
This patch use explicit numbers to describe EXT4_MAP_XXX flags so __print_flags will works as expected.

#Before patch
ext4:ext4_ext_map_blocks_exit: dev 253,0 ino 2 flags  lblk 0 pblk 4177 len 1 mflags 0x20 ret 1
ext4:ext4_ext_map_blocks_exit: dev 253,0 ino 12 flags CREATE lblk 0 pblk 34304 len 1 mflags 0x60 ret 1

#With patch
ext4:ext4_ext_map_blocks_exit: dev 253,0 ino 2 flags  lblk 0 pblk 4177 len 1 mflags M ret 1
ext4:ext4_ext_map_blocks_exit: dev 253,0 ino 12 flags CREATE lblk 0 pblk 34816 len 1 mflags NM ret 1

Signed-off-by: Dmitry Monakhov <dmonakhov@gmail.com>
---
 fs/ext4/ext4.h | 26 ++++++++++++++++++++++----
 1 file changed, 22 insertions(+), 4 deletions(-)

diff --git a/fs/ext4/ext4.h b/fs/ext4/ext4.h
index bf660aa..9ccf736 100644
--- a/fs/ext4/ext4.h
+++ b/fs/ext4/ext4.h
@@ -169,14 +169,32 @@ struct ext4_allocation_request {
  * This structure is used to pass requests into ext4_map_blocks() as
  * well as to store the information returned by ext4_map_blocks().  It
  * takes less room on the stack than a struct buffer_head.
+ *
+ * Use explicit mapping of EXT4_MAP_XXX flags to corresponding BH_XXX bits
  */
-#define EXT4_MAP_NEW		(1 << BH_New)
-#define EXT4_MAP_MAPPED		(1 << BH_Mapped)
-#define EXT4_MAP_UNWRITTEN	(1 << BH_Unwritten)
-#define EXT4_MAP_BOUNDARY	(1 << BH_Boundary)
+#define EXT4_MAP_NEW		0x40
+#define EXT4_MAP_MAPPED		0x20
+#define EXT4_MAP_UNWRITTEN	0x1000
+#define EXT4_MAP_BOUNDARY	0x400
 #define EXT4_MAP_FLAGS		(EXT4_MAP_NEW | EXT4_MAP_MAPPED |\
 				 EXT4_MAP_UNWRITTEN | EXT4_MAP_BOUNDARY)
 
+/*
+ * Assert that EXT4_MAP_XX is consistent with respect to BH_XXX. If all is well,
+ * the macros will be dropped, so, it won't cost any extra space in the compiled
+ * kernel image, otherwise, the build will fail.
+ */
+#define TEST_MAP_VALUE(FLAG, BIT) (EXT4_MAP_##FLAG == (1 << BH_##BIT))
+#define CHECK_MAP_VALUE(FLAG, BIT) BUILD_BUG_ON(!TEST_MAP_VALUE(FLAG, BIT))
+
+static inline void ext4_check_map_values(void)
+{
+	CHECK_MAP_VALUE(NEW, New);
+	CHECK_MAP_VALUE(MAPPED, Mapped);
+	CHECK_MAP_VALUE(UNWRITTEN, Unwritten);
+	CHECK_MAP_VALUE(BOUNDARY, Boundary);
+}
+
 struct ext4_map_blocks {
 	ext4_fsblk_t m_pblk;
 	ext4_lblk_t m_lblk;
-- 
2.7.4

[PATCH 2/2] ext4: Fix extent_status trace events

[Dmitry Monakhov]

 - show pblock only if it has meaningful value
 - Add missed EXTENT_STATUS_REFERENCED decoder
 - Define status flags as explicit numbers instead of implicit enum ones

# before
   ext4:ext4_es_lookup_extent_exit: dev 253,0 ino 12 found 1 [1/4294967294) 576460752303423487 0x8
   ext4:ext4_es_lookup_extent_exit: dev 253,0 ino 12 found 1 [2/4294967293) 576460752303423487 0x18
   ext4:ext4_es_lookup_extent_exit: dev 253,0 ino 12 found 1 [3/4294967292) 576460752303423487 0x18
   ext4:ext4_es_lookup_extent_exit: dev 253,0 ino 12 found 1 [4/4294967291) 576460752303423487 0x18
# after
   ext4:ext4_es_lookup_extent_exit: dev 253,0 ino 12 found 1 [1/4294967294) 0 H
   ext4:ext4_es_lookup_extent_exit: dev 253,0 ino 12 found 1 [2/4294967293) 0 HR
   ext4:ext4_es_lookup_extent_exit: dev 253,0 ino 12 found 1 [3/4294967292) 0 HR
   ext4:ext4_es_lookup_extent_exit: dev 253,0 ino 12 found 1 [4/4294967291) 0 HR

Signed-off-by: Dmitry Monakhov <dmonakhov@gmail.com>
---
 fs/ext4/extents_status.h    | 21 +++++++++++++--------
 include/trace/events/ext4.h | 11 ++++++-----
 2 files changed, 19 insertions(+), 13 deletions(-)

diff --git a/fs/ext4/extents_status.h b/fs/ext4/extents_status.h
index 131a8b7..64b8fd1 100644
--- a/fs/ext4/extents_status.h
+++ b/fs/ext4/extents_status.h
@@ -30,14 +30,13 @@
 /*
  * These flags live in the high bits of extent_status.es_pblk
  */
-enum {
-	ES_WRITTEN_B,
-	ES_UNWRITTEN_B,
-	ES_DELAYED_B,
-	ES_HOLE_B,
-	ES_REFERENCED_B,
-	ES_FLAGS
-};
+
+#define ES_WRITTEN_B     0
+#define ES_UNWRITTEN_B   1
+#define ES_DELAYED_B     2
+#define ES_HOLE_B        3
+#define ES_REFERENCED_B  4
+#define ES_FLAGS         5
 
 #define ES_SHIFT (sizeof(ext4_fsblk_t)*8 - ES_FLAGS)
 #define ES_MASK (~((ext4_fsblk_t)0) << ES_SHIFT)
@@ -208,6 +207,12 @@ static inline ext4_fsblk_t ext4_es_pblock(struct extent_status *es)
 	return es->es_pblk & ~ES_MASK;
 }
 
+static inline ext4_fsblk_t ext4_es_show_pblock(struct extent_status *es)
+{
+	ext4_fsblk_t pblock = ext4_es_pblock(es);
+	return pblock == ~ES_MASK ? 0 : pblock;
+}
+
 static inline void ext4_es_store_pblock(struct extent_status *es,
 					ext4_fsblk_t pb)
 {
diff --git a/include/trace/events/ext4.h b/include/trace/events/ext4.h
index d68e9e5..bdb5fc4 100644
--- a/include/trace/events/ext4.h
+++ b/include/trace/events/ext4.h
@@ -66,7 +66,8 @@ struct partial_cluster;
 	{ EXTENT_STATUS_WRITTEN,	"W" },			\
 	{ EXTENT_STATUS_UNWRITTEN,	"U" },			\
 	{ EXTENT_STATUS_DELAYED,	"D" },			\
-	{ EXTENT_STATUS_HOLE,		"H" })
+	{ EXTENT_STATUS_HOLE,		"H" },			\
+	{ EXTENT_STATUS_REFERENCED,	"R" })
 
 #define show_falloc_mode(mode) __print_flags(mode, "|",		\
 	{ FALLOC_FL_KEEP_SIZE,		"KEEP_SIZE"},		\
@@ -2262,7 +2263,7 @@ DECLARE_EVENT_CLASS(ext4__es_extent,
 		__entry->ino	= inode->i_ino;
 		__entry->lblk	= es->es_lblk;
 		__entry->len	= es->es_len;
-		__entry->pblk	= ext4_es_pblock(es);
+		__entry->pblk	= ext4_es_show_pblock(es);
 		__entry->status	= ext4_es_status(es);
 	),
 
@@ -2351,7 +2352,7 @@ TRACE_EVENT(ext4_es_find_extent_range_exit,
 		__entry->ino	= inode->i_ino;
 		__entry->lblk	= es->es_lblk;
 		__entry->len	= es->es_len;
-		__entry->pblk	= ext4_es_pblock(es);
+		__entry->pblk	= ext4_es_show_pblock(es);
 		__entry->status	= ext4_es_status(es);
 	),
 
@@ -2405,7 +2406,7 @@ TRACE_EVENT(ext4_es_lookup_extent_exit,
 		__entry->ino	= inode->i_ino;
 		__entry->lblk	= es->es_lblk;
 		__entry->len	= es->es_len;
-		__entry->pblk	= ext4_es_pblock(es);
+		__entry->pblk	= ext4_es_show_pblock(es);
 		__entry->status	= ext4_es_status(es);
 		__entry->found	= found;
 	),
@@ -2573,7 +2574,7 @@ TRACE_EVENT(ext4_es_insert_delayed_block,
 		__entry->ino		= inode->i_ino;
 		__entry->lblk		= es->es_lblk;
 		__entry->len		= es->es_len;
-		__entry->pblk		= ext4_es_pblock(es);
+		__entry->pblk		= ext4_es_show_pblock(es);
 		__entry->status		= ext4_es_status(es);
 		__entry->allocated	= allocated;
 	),
-- 
2.7.4

Re: [PATCH 2/2] ext4: Fix extent_status trace events

[Darrick J. Wong]

On Thu, Nov 14, 2019 at 07:03:30AM +0000, Dmitry Monakhov wrote:
>  - show pblock only if it has meaningful value
>  - Add missed EXTENT_STATUS_REFERENCED decoder
>  - Define status flags as explicit numbers instead of implicit enum ones
> 
> # before
>    ext4:ext4_es_lookup_extent_exit: dev 253,0 ino 12 found 1 [1/4294967294) 576460752303423487 0x8
>    ext4:ext4_es_lookup_extent_exit: dev 253,0 ino 12 found 1 [2/4294967293) 576460752303423487 0x18
>    ext4:ext4_es_lookup_extent_exit: dev 253,0 ino 12 found 1 [3/4294967292) 576460752303423487 0x18
>    ext4:ext4_es_lookup_extent_exit: dev 253,0 ino 12 found 1 [4/4294967291) 576460752303423487 0x18
> # after
>    ext4:ext4_es_lookup_extent_exit: dev 253,0 ino 12 found 1 [1/4294967294) 0 H
>    ext4:ext4_es_lookup_extent_exit: dev 253,0 ino 12 found 1 [2/4294967293) 0 HR
>    ext4:ext4_es_lookup_extent_exit: dev 253,0 ino 12 found 1 [3/4294967292) 0 HR
>    ext4:ext4_es_lookup_extent_exit: dev 253,0 ino 12 found 1 [4/4294967291) 0 HR
> 
> Signed-off-by: Dmitry Monakhov <dmonakhov@gmail.com>
> ---
>  fs/ext4/extents_status.h    | 21 +++++++++++++--------
>  include/trace/events/ext4.h | 11 ++++++-----
>  2 files changed, 19 insertions(+), 13 deletions(-)
> 
> diff --git a/fs/ext4/extents_status.h b/fs/ext4/extents_status.h
> index 131a8b7..64b8fd1 100644
> --- a/fs/ext4/extents_status.h
> +++ b/fs/ext4/extents_status.h
> @@ -30,14 +30,13 @@
>  /*
>   * These flags live in the high bits of extent_status.es_pblk
>   */
> -enum {
> -	ES_WRITTEN_B,
> -	ES_UNWRITTEN_B,
> -	ES_DELAYED_B,
> -	ES_HOLE_B,
> -	ES_REFERENCED_B,
> -	ES_FLAGS

Put:

TRACE_DEFINE_ENUM(ES_WRITTEN_B)
...
TRACE_DEFINE_ENUM(ES_FLAGS)

in include/trace/events/ext4.h and they should work properly.

We found this out the hard way in xfs land by stumbling across the
"documentation" in samples/trace_events/trace_events.h.

(I don't know if that same trick works for the BH flags in the previous
patch.)

--D

> -};
> +
> +#define ES_WRITTEN_B     0
> +#define ES_UNWRITTEN_B   1
> +#define ES_DELAYED_B     2
> +#define ES_HOLE_B        3
> +#define ES_REFERENCED_B  4
> +#define ES_FLAGS         5
>  
>  #define ES_SHIFT (sizeof(ext4_fsblk_t)*8 - ES_FLAGS)
>  #define ES_MASK (~((ext4_fsblk_t)0) << ES_SHIFT)
> @@ -208,6 +207,12 @@ static inline ext4_fsblk_t ext4_es_pblock(struct extent_status *es)
>  	return es->es_pblk & ~ES_MASK;
>  }
>  
> +static inline ext4_fsblk_t ext4_es_show_pblock(struct extent_status *es)
> +{
> +	ext4_fsblk_t pblock = ext4_es_pblock(es);
> +	return pblock == ~ES_MASK ? 0 : pblock;
> +}
> +
>  static inline void ext4_es_store_pblock(struct extent_status *es,
>  					ext4_fsblk_t pb)
>  {
> diff --git a/include/trace/events/ext4.h b/include/trace/events/ext4.h
> index d68e9e5..bdb5fc4 100644
> --- a/include/trace/events/ext4.h
> +++ b/include/trace/events/ext4.h
> @@ -66,7 +66,8 @@ struct partial_cluster;
>  	{ EXTENT_STATUS_WRITTEN,	"W" },			\
>  	{ EXTENT_STATUS_UNWRITTEN,	"U" },			\
>  	{ EXTENT_STATUS_DELAYED,	"D" },			\
> -	{ EXTENT_STATUS_HOLE,		"H" })
> +	{ EXTENT_STATUS_HOLE,		"H" },			\
> +	{ EXTENT_STATUS_REFERENCED,	"R" })
>  
>  #define show_falloc_mode(mode) __print_flags(mode, "|",		\
>  	{ FALLOC_FL_KEEP_SIZE,		"KEEP_SIZE"},		\
> @@ -2262,7 +2263,7 @@ DECLARE_EVENT_CLASS(ext4__es_extent,
>  		__entry->ino	= inode->i_ino;
>  		__entry->lblk	= es->es_lblk;
>  		__entry->len	= es->es_len;
> -		__entry->pblk	= ext4_es_pblock(es);
> +		__entry->pblk	= ext4_es_show_pblock(es);
>  		__entry->status	= ext4_es_status(es);
>  	),
>  
> @@ -2351,7 +2352,7 @@ TRACE_EVENT(ext4_es_find_extent_range_exit,
>  		__entry->ino	= inode->i_ino;
>  		__entry->lblk	= es->es_lblk;
>  		__entry->len	= es->es_len;
> -		__entry->pblk	= ext4_es_pblock(es);
> +		__entry->pblk	= ext4_es_show_pblock(es);
>  		__entry->status	= ext4_es_status(es);
>  	),
>  
> @@ -2405,7 +2406,7 @@ TRACE_EVENT(ext4_es_lookup_extent_exit,
>  		__entry->ino	= inode->i_ino;
>  		__entry->lblk	= es->es_lblk;
>  		__entry->len	= es->es_len;
> -		__entry->pblk	= ext4_es_pblock(es);
> +		__entry->pblk	= ext4_es_show_pblock(es);
>  		__entry->status	= ext4_es_status(es);
>  		__entry->found	= found;
>  	),
> @@ -2573,7 +2574,7 @@ TRACE_EVENT(ext4_es_insert_delayed_block,
>  		__entry->ino		= inode->i_ino;
>  		__entry->lblk		= es->es_lblk;
>  		__entry->len		= es->es_len;
> -		__entry->pblk		= ext4_es_pblock(es);
> +		__entry->pblk		= ext4_es_show_pblock(es);
>  		__entry->status		= ext4_es_status(es);
>  		__entry->allocated	= allocated;
>  	),
> -- 
> 2.7.4
>