[PATCH] tracing: don't macro-expand arguments before stringification in TP_printk

[PATCH] tracing: don't macro-expand arguments before stringification in TP_printk

[Rasmus Villemoes]

TL;DR: For the .config I use for my laptop, the bloat-o-meter win is

$ scripts/bloat-o-meter /tmp/vmlinux.{old,new}
add/remove: 0/0 grow/shrink: 187/136 up/down: 3566/-38081 (-34515)

The __stringify macro ensures that its argument is completely
macro-expanded before it is stringified. That is, IMO, not very useful
for the print_fmt_* variables, since it often makes the resulting
string almost, but not quite, entirely unlike the source code. For
example, in ext4/ext4_mballoc_alloc/format one finds

((unsigned int) ((REC->dev) >> 20)), ((unsigned int) ((REC->dev) & ((1U << 20) - 1)))

which came from

MAJOR(__entry->dev), MINOR(__entry->dev),

The latter is much more readable. Moreover, the macro expansion ends
up making the print_fmt_* strings rather bloated:

# find . -name 'format' | xargs grep '^print fmt:' | perl -pe 's/:print fmt: (.*)/" ".length($1)/e' | sort -k2,2n | tail
./kmem/kmem_cache_alloc/format 2160
./kmem/kmalloc_node/format 2179
./kmem/kmem_cache_alloc_node/format 2179
./kmem/mm_page_alloc/format 2241
./vmscan/mm_shrink_slab_start/format 2296
./scsi/scsi_dispatch_cmd_start/format 3102
./scsi/scsi_dispatch_cmd_error/format 3119
./libata/ata_qc_issue/format 5072
./scsi/scsi_dispatch_cmd_done/format 5145
./scsi/scsi_dispatch_cmd_timeout/format 5145

This is mostly caused by the (flag value, symbolic string) arrays used
for __print_symbolic being included verbatim.

The increases in bloat-o-meter are partly due to the simple fact that
__entry is longer than REC, but also because symbolic constants such
as I2C_SMBUS_QUICK no longer gets replaced by small integer literals -
the latter can in many cases profitably be rectified by using a
#define for the __print_symbolic argument (for example, in the i2c
case the same array is repeated four times in
include/trace/events/i2c.h).

Signed-off-by: Rasmus Villemoes <linux@rasmusvillemoes.dk>
---
 include/trace/trace_events.h | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/include/trace/trace_events.h b/include/trace/trace_events.h
index de996cf61053..62daa32527e0 100644
--- a/include/trace/trace_events.h
+++ b/include/trace/trace_events.h
@@ -715,7 +715,7 @@ static inline void ftrace_test_probe_##call(void)			\
 #undef __print_array
 
 #undef TP_printk
-#define TP_printk(fmt, args...) "\"" fmt "\", "  __stringify(args)
+#define TP_printk(fmt, args...) "\"" fmt "\", "  #args
 
 #undef DECLARE_EVENT_CLASS
 #define DECLARE_EVENT_CLASS(call, proto, args, tstruct, assign, print)	\
-- 
2.6.1

Re: [PATCH] tracing: don't macro-expand arguments before stringification in TP_printk

[Rasmus Villemoes]

Bah, just found 0462b5664b (ftrace: Output REC->var instead of
__entry->var for trace format). There's some magic here I don't
understand, but I'm wondering if '__entry' wouldn't do just as well as
'REC' for the tools that try to parse these strings.

Rasmus

Re: [PATCH] tracing: don't macro-expand arguments before stringification in TP_printk

[Steven Rostedt]

On Wed, 16 Dec 2015 01:28:12 +0100
Rasmus Villemoes <linux@rasmusvillemoes.dk> wrote:

> Bah, just found 0462b5664b (ftrace: Output REC->var instead of
> __entry->var for trace format). There's some magic here I don't
> understand, but I'm wondering if '__entry' wouldn't do just as well as
> 'REC' for the tools that try to parse these strings.
> 
>

Sorry for the late reply, but I just found this in my INBOX :-)

Several tools already exist that use REC to parse. It would be ABI
breakage to suddenly convert it to __entry.

Not to mention, even in your example of:

  ((unsigned int) ((REC->dev) >> 20)), ((unsigned int) ((REC->dev) & ((1U << 20) - 1)))

which came from

  MAJOR(__entry->dev), MINOR(__entry->dev),


The parsing tools don't know how to parse MAJOR or MINOR but they do
know how to do the above macro expansions.

Just an FYI,

-- Steve