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