From: "Steven Rostedt (Google)" <[email protected]>
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/[email protected]/
Cc: [email protected]
Fixes: 2f754e771b1a6 ("tracing: Have the error logs show up in the proper instances")
Reported-by: Mirsad Goran Todorovac <[email protected]>
Signed-off-by: Steven Rostedt (Google) <[email protected]>
---
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
On 05. 04. 2023. 01:45, Steven Rostedt wrote:
> From: "Steven Rostedt (Google)" <[email protected]>
>
> 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/[email protected]/
>
> Cc: [email protected]
> Fixes: 2f754e771b1a6 ("tracing: Have the error logs show up in the proper instances")
> Reported-by: Mirsad Goran Todorovac <[email protected]>
> Signed-off-by: Steven Rostedt (Google) <[email protected]>
> ---
> 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 <[email protected]>
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?"
On 5.4.2023. 5:57, Mirsad Goran Todorovac wrote:
> On 05. 04. 2023. 01:45, Steven Rostedt wrote:
>> From: "Steven Rostedt (Google)" <[email protected]>
>>
>> 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/[email protected]/
>>
>> Cc: [email protected]
>> Fixes: 2f754e771b1a6 ("tracing: Have the error logs show up in the proper instances")
>> Reported-by: Mirsad Goran Todorovac <[email protected]>
>> Signed-off-by: Steven Rostedt (Google) <[email protected]>
>> ---
>> 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 <[email protected]>
>
> 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
--
Mirsad Todorovac
System engineer
Faculty of Graphic Arts | Academy of Fine Arts
University of Zagreb
Republic of Croatia, the European Union
Sistem inženjer
Grafički fakultet | Akademija likovnih umjetnosti
Sveučilište u Zagrebu
On Wed, 5 Apr 2023 12:47:08 +0200
Mirsad Goran Todorovac <[email protected]> wrote:
> >> Cc: [email protected]
> >> Fixes: 2f754e771b1a6 ("tracing: Have the error logs show up in the proper instances")
> >
> > Please add
> >
> > Tested-by: Mirsad Todorovac <[email protected]>
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 <[email protected]> wrote:
> From: "Steven Rostedt (Google)" <[email protected]>
>
> 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/[email protected]/
>
> Cc: [email protected]
> Fixes: 2f754e771b1a6 ("tracing: Have the error logs show up in the proper instances")
> Reported-by: Mirsad Goran Todorovac <[email protected]>
> Signed-off-by: Steven Rostedt (Google) <[email protected]>
This looks good to me.
Acked-by: Masami Hiramatsu (Google) <[email protected]>
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
>
--
Masami Hiramatsu (Google) <[email protected]>