Re: [PATCH 07/18 v3] tracing: Add TRACE_DEFINE_ENUM() macro to map enums to their values

[Sasha Levin <sasha.levin@oracle.com>]

On 04/02/2015 09:38 PM, Steven Rostedt wrote:
> From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>
> 
> Several tracepoints use the helper functions __print_symbolic() or
> __print_flags() and pass in enums that do the mapping between the
> binary data stored and the value to print. This works well for reading
> the ASCII trace files, but when the data is read via userspace tools
> such as perf and trace-cmd, the conversion of the binary value to a
> human string format is lost if an enum is used, as userspace does not
> have access to what the ENUM is.
> 
> For example, the tracepoint trace_tlb_flush() has:
> 
>  __print_symbolic(REC->reason,
>     { TLB_FLUSH_ON_TASK_SWITCH, "flush on task switch" },
>     { TLB_REMOTE_SHOOTDOWN, "remote shootdown" },
>     { TLB_LOCAL_SHOOTDOWN, "local shootdown" },
>     { TLB_LOCAL_MM_SHOOTDOWN, "local mm shootdown" })
> 
> Which maps the enum values to the strings they represent. But perf and
> trace-cmd do no know what value TLB_LOCAL_MM_SHOOTDOWN is, and would
> not be able to map it.
> 
> With TRACE_DEFINE_ENUM(), developers can place these in the event header
> files and ftrace will convert the enums to their values:
> 
> By adding:
> 
>  TRACE_DEFINE_ENUM(TLB_FLUSH_ON_TASK_SWITCH);
>  TRACE_DEFINE_ENUM(TLB_REMOTE_SHOOTDOWN);
>  TRACE_DEFINE_ENUM(TLB_LOCAL_SHOOTDOWN);
>  TRACE_DEFINE_ENUM(TLB_LOCAL_MM_SHOOTDOWN);
> 
>  $ cat /sys/kernel/debug/tracing/events/tlb/tlb_flush/format
> [...]
>  __print_symbolic(REC->reason,
>     { 0, "flush on task switch" },
>     { 1, "remote shootdown" },
>     { 2, "local shootdown" },
>     { 3, "local mm shootdown" })
> 
> The above is what userspace expects to see, and tools do not need to
> be modified to parse them.
> 
> Cc: Guilherme Cox <cox@computer.org>
> Cc: Tony Luck <tony.luck@gmail.com>
> Cc: Xie XiuQi <xiexiuqi@huawei.com>
> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> ---

Hey Steven,

I'm seeing the following when booting:

[   10.678876] BUG: KASan: out of bounds access in trace_event_enum_update+0xb1d/0xb70 at addr ffffffffa6c4dc68
[   10.680222] Read of size 1 by task swapper/0/1
[   10.680222] Address belongs to variable print_fmt_9p_client_req+0x848/0x880
[   10.680222] CPU: 19 PID: 1 Comm: swapper/0 Not tainted 4.0.0-next-20150415-sasha-00064-g7858a62 #2147
[   10.680222]  ffffffffa6c4dc68 00000000915e69dc ffff88004e8efb18 ffffffffa1b4f7a6
[   10.680222]  0000000000000000 ffff88004e8efba8 ffff88004e8efb98 ffffffff976544b1
[   10.680222]  ffff88004e8efbd8 ffffffff990134a4 0000000000000282 ffffffffa444e381
[   10.680222] Call Trace:
[   10.680222] dump_stack (lib/dump_stack.c:52)
[   10.680222] kasan_report_error (mm/kasan/report.c:132 mm/kasan/report.c:193)
[   10.680222] ? snprintf (lib/vsprintf.c:2069)
[   10.680222] ? vsprintf (lib/vsprintf.c:2069)
[   10.680222] ? trace_event_enum_update (kernel/trace/trace_events.c:1807)
[   10.680222] __asan_report_load1_noabort (mm/kasan/report.c:230 mm/kasan/report.c:248)
[   10.680222] ? trace_event_enum_update (kernel/trace/trace_events.c:1807)
[   10.680222] trace_event_enum_update (kernel/trace/trace_events.c:1807)
[   10.680222] tracer_init_tracefs (kernel/trace/trace.c:4122 kernel/trace/trace.c:6750 kernel/trace/trace.c:6848)
[   10.680222] ? clear_boot_tracer (kernel/trace/trace.c:6825)
[   10.680222] ? clear_boot_tracer (kernel/trace/trace.c:6825)
[   10.680222] do_one_initcall (init/main.c:788)
[   10.680222] ? try_to_run_init_process (init/main.c:777)
[   10.680222] ? parse_args (kernel/params.c:131 kernel/params.c:216)
[   10.680222] ? trace_hardirqs_on (kernel/locking/lockdep.c:2630)
[   10.680222] kernel_init_freeable (init/main.c:853 init/main.c:861 init/main.c:880 init/main.c:1001)
[   10.680222] ? local_clock (kernel/sched/clock.c:392)
[   10.680222] ? start_kernel (init/main.c:973)
[   10.680222] ? finish_task_switch (kernel/sched/core.c:2249)
[   10.680222] ? finish_task_switch (include/linux/tick.h:186 kernel/sched/core.c:2263)
[   10.680222] ? finish_task_switch (kernel/sched/sched.h:1077 kernel/sched/core.c:2245)
[   10.680222] ? rest_init (init/main.c:928)
[   10.680222] kernel_init (init/main.c:933)
[   10.680222] ? rest_init (init/main.c:928)
[   10.680222] ret_from_fork (arch/x86/kernel/entry_64.S:631)
[   10.680222] ? rest_init (init/main.c:928)
[   10.680222] Memory state around the buggy address:
[   10.680222]  ffffffffa6c4db00: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[   10.680222]  ffffffffa6c4db80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[   10.680222] >ffffffffa6c4dc00: 00 00 00 00 00 00 00 00 00 00 00 00 00 fa fa fa
[   10.680222]                                                           ^
[   10.680222]  ffffffffa6c4dc80: fa fa fa fa 00 00 00 00 fa fa fa fa 00 00 00 00
[   10.680222]  ffffffffa6c4dd00: fa fa fa fa 00 00 00 00 fa fa fa fa 00 00 00 00


Thanks,
Sasha