Re: [PATCH] tracing: Free error logs of tracing instances

[Mirsad Goran Todorovac]

On 05. 04. 2023. 01:45, Steven Rostedt wrote:
> From: "Steven Rostedt (Google)" <rostedt@xxxxxxxxxxx>
> 
> When a tracing instance is removed, the error messages that hold errors
> that occurred in the instance needs to be freed. The following reports a
> memory leak:
> 
>  # cd /sys/kernel/tracing
>  # mkdir instances/foo
>  # echo 'hist:keys=x' > instances/foo/events/sched/sched_switch/trigger
>  # cat instances/foo/error_log
>  [  117.404795] hist:sched:sched_switch: error: Couldn't find field
>    Command: hist:keys=x
>                       ^
>  # rmdir instances/foo
> 
> Then check for memory leaks:
> 
>  # echo scan > /sys/kernel/debug/kmemleak
>  # cat /sys/kernel/debug/kmemleak
> unreferenced object 0xffff88810d8ec700 (size 192):
>   comm "bash", pid 869, jiffies 4294950577 (age 215.752s)
>   hex dump (first 32 bytes):
>     60 dd 68 61 81 88 ff ff 60 dd 68 61 81 88 ff ff  `.ha....`.ha....
>     a0 30 8c 83 ff ff ff ff 26 00 0a 00 00 00 00 00  .0......&.......
>   backtrace:
>     [<00000000dae26536>] kmalloc_trace+0x2a/0xa0
>     [<00000000b2938940>] tracing_log_err+0x277/0x2e0
>     [<000000004a0e1b07>] parse_atom+0x966/0xb40
>     [<0000000023b24337>] parse_expr+0x5f3/0xdb0
>     [<00000000594ad074>] event_hist_trigger_parse+0x27f8/0x3560
>     [<00000000293a9645>] trigger_process_regex+0x135/0x1a0
>     [<000000005c22b4f2>] event_trigger_write+0x87/0xf0
>     [<000000002cadc509>] vfs_write+0x162/0x670
>     [<0000000059c3b9be>] ksys_write+0xca/0x170
>     [<00000000f1cddc00>] do_syscall_64+0x3e/0xc0
>     [<00000000868ac68c>] entry_SYSCALL_64_after_hwframe+0x72/0xdc
> unreferenced object 0xffff888170c35a00 (size 32):
>   comm "bash", pid 869, jiffies 4294950577 (age 215.752s)
>   hex dump (first 32 bytes):
>     0a 20 20 43 6f 6d 6d 61 6e 64 3a 20 68 69 73 74  .  Command: hist
>     3a 6b 65 79 73 3d 78 0a 00 00 00 00 00 00 00 00  :keys=x.........
>   backtrace:
>     [<000000006a747de5>] __kmalloc+0x4d/0x160
>     [<000000000039df5f>] tracing_log_err+0x29b/0x2e0
>     [<000000004a0e1b07>] parse_atom+0x966/0xb40
>     [<0000000023b24337>] parse_expr+0x5f3/0xdb0
>     [<00000000594ad074>] event_hist_trigger_parse+0x27f8/0x3560
>     [<00000000293a9645>] trigger_process_regex+0x135/0x1a0
>     [<000000005c22b4f2>] event_trigger_write+0x87/0xf0
>     [<000000002cadc509>] vfs_write+0x162/0x670
>     [<0000000059c3b9be>] ksys_write+0xca/0x170
>     [<00000000f1cddc00>] do_syscall_64+0x3e/0xc0
>     [<00000000868ac68c>] entry_SYSCALL_64_after_hwframe+0x72/0xdc
> 
> The problem is that the error log needs to be freed when the instance is
> removed.
> 
> Link: https://lore.kernel.org/lkml/76134d9f-a5ba-6a0d-37b3-28310b4a1e91@xxxxxxxxxxxx/
> 
> Cc: stable@xxxxxxxxxxxxxxx
> Fixes: 2f754e771b1a6 ("tracing: Have the error logs show up in the proper instances")
> Reported-by: Mirsad Goran Todorovac <mirsad.todorovac@xxxxxxxxxxxx>
> Signed-off-by: Steven Rostedt (Google) <rostedt@xxxxxxxxxxx>
> ---
>  kernel/trace/trace.c | 1 +
>  1 file changed, 1 insertion(+)
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 8ae51f1dea8e..352a804b016d 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -9516,6 +9516,7 @@ static int __remove_instance(struct trace_array *tr)
>  	tracefs_remove(tr->dir);
>  	free_percpu(tr->last_func_repeats);
>  	free_trace_buffers(tr);
> +	clear_tracing_err_log(tr);
>  
>  	for (i = 0; i < tr->nr_topts; i++) {
>  		kfree(tr->topts[i].topts);

Hello,

Apparently, this fixed the issue (leak) with the same config, kernel commit and
HW.

Please add

Tested-by: Mirsad Todorovac <mirsad.todorovac@xxxxxxxxxxxx>

at your convenience.

The bisect was obviously misleading, but not intentionally. This is the first time
my bisect was wrong (out of five or six), so I will thoroughly investigate the fault,
for - needless to say - quality binary search bisect is essential to hunt down bugs.

But they say that "Nobody wins them all."

Thank you very much for patching this at such a short notice.

(I cannot remember why I did not Cc: kernel/trace developers back then on Jan 27th,
probably I thought the test independently triggered vfs_write() bug.)

Have a nice evening, and God bless!!

Best regards,
Mirsad

-- 
Mirsad Goran Todorovac
Sistem inženjer
Grafički fakultet | Akademija likovnih umjetnosti
Sveučilište u Zagrebu
 
System engineer
Faculty of Graphic Arts | Academy of Fine Arts
University of Zagreb, Republic of Croatia
The European Union

"I see something approaching fast ... Will it be friends with me?"