| Message ID | 20230404194504.5790b95f@gandalf.local.home (mailing list archive) |
|---|---|
| State | Accepted |
| Commit | 3357c6e429643231e60447b52ffbb7ac895aca22 |
| Headers | show |
| Series | tracing: Free error logs of tracing instances | expand |
On 05. 04. 2023. 01:45, Steven Rostedt wrote: > From: "Steven Rostedt (Google)" <rostedt@goodmis.org> > > 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@alu.unizg.hr/ > > Cc: stable@vger.kernel.org > Fixes: 2f754e771b1a6 ("tracing: Have the error logs show up in the proper instances") > Reported-by: Mirsad Goran Todorovac <mirsad.todorovac@alu.unizg.hr> > Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org> > --- > 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@alu.unizg.hr> 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
On 5.4.2023. 5:57, Mirsad Goran Todorovac wrote: > On 05. 04. 2023. 01:45, Steven Rostedt wrote: >> From: "Steven Rostedt (Google)" <rostedt@goodmis.org> >> >> 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@alu.unizg.hr/ >> >> Cc: stable@vger.kernel.org >> Fixes: 2f754e771b1a6 ("tracing: Have the error logs show up in the proper instances") >> Reported-by: Mirsad Goran Todorovac <mirsad.todorovac@alu.unizg.hr> >> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org> >> --- >> 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@alu.unizg.hr> > > 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 bug. I found the culprit. I have naively classified build 6.1.0-ftrace-06910-g90b12f423d3c as "good", giving me a false negative. It turned out that it takes at least two attempts on # echo scan > /sys/kernel/debug/kmemleak to display the "ftracetest" leak in the # cat /sys/kernel/debug/kmemleak output. First try again showed no leaks. The log shows "looks good". I don't remember what I did on Jan/26th, but it was obviously not good enough. Mea culpa. The leak is present already in the v5.9.0, which is earliest which I can boot with the default kmod v30+20220630-3ubuntu1 and default ZSTD kernel compression. If it mattered, I could proceed bisect on the other device (we'd get Fixes: line, but the bug is already patched). Best regards, Mirsad
On Wed, 5 Apr 2023 12:47:08 +0200 Mirsad Goran Todorovac <mirsad.todorovac@alu.unizg.hr> wrote: > >> Cc: stable@vger.kernel.org > >> Fixes: 2f754e771b1a6 ("tracing: Have the error logs show up in the proper instances") > > > > Please add > > > > Tested-by: Mirsad Todorovac <mirsad.todorovac@alu.unizg.hr> Thanks! > > If it mattered, I could proceed bisect on the other device (we'd get Fixes: > line, but the bug is already patched). I'm pretty sure the above commit listed in the Fixes tag is the culprit. Feel free to test before and after to confirm. -- Steve
On Tue, 4 Apr 2023 19:45:04 -0400 Steven Rostedt <rostedt@goodmis.org> wrote: > From: "Steven Rostedt (Google)" <rostedt@goodmis.org> > > 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@alu.unizg.hr/ > > Cc: stable@vger.kernel.org > Fixes: 2f754e771b1a6 ("tracing: Have the error logs show up in the proper instances") > Reported-by: Mirsad Goran Todorovac <mirsad.todorovac@alu.unizg.hr> > Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org> This looks good to me. Acked-by: Masami Hiramatsu (Google) <mhiramat@kernel.org> Thank you! > --- > 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); > -- > 2.39.2 >
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);