Hi Steven,
i noticed the following KASAN splat in CI (on s390):
[ 218.586476] /home/svens/linux/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-stack.tc
[ 221.610410] ==================================================================
[ 221.610424] BUG: KASAN: slab-out-of-bounds in print_synth_event+0xa68/0xa78
[ 221.610440] Read of size 8 at addr 0000000087753ebc by task grep/1321
[ 221.610445]
[ 221.610451] CPU: 9 PID: 1321 Comm: grep Not tainted 6.4.0-rc3-00008-g4b512860bdbd #716
[ 221.610457] Hardware name: IBM 3906 M04 704 (z/VM 7.1.0)
[ 221.610462] Call Trace:
[ 221.610466] [<00000000026026e6>] dump_stack_lvl+0x106/0x1c8
[ 221.610479] [<00000000009cdbbc>] print_address_description.constprop.0+0x34/0x378
[ 221.610488] [<00000000009cdfac>] print_report+0xac/0x240
[ 221.610494] [<00000000009ce32a>] kasan_report+0xf2/0x130
[ 221.610501] [<00000000005e4f60>] print_synth_event+0xa68/0xa78
[ 221.610508] [<00000000005809c0>] print_trace_line+0x2a8/0xc00
[ 221.610516] [<0000000000582d4a>] s_show+0xc2/0x3d0
[ 221.610522] [<0000000000b09db2>] seq_read_iter+0x912/0xf88
[ 221.610530] [<0000000000b0a582>] seq_read+0x15a/0x1d8
[ 221.610535] [<0000000000a75f66>] vfs_read+0x186/0x778
[ 221.610551] [<0000000000a77b26>] ksys_read+0x126/0x210
[ 221.610557] [<000000000010d044>] do_syscall+0x22c/0x328
[ 221.610564] [<000000000266ea02>] __do_syscall+0x9a/0xf8
[ 221.610571] [<000000000269f068>] system_call+0x70/0x98
[ 221.610577] 3 locks held by grep/1321:
[ 221.610580] #0: 00000000a99db2f8 (&p->lock){+.+.}-{3:3}, at: seq_read_iter+0xca/0xf88
[ 221.610595] #1: 00000000032d0c18 (trace_event_sem){++++}-{3:3}, at: s_start+0x3c2/0x7c0
[ 221.610606] #2: 00000000032c8cb8 (all_cpu_access_lock){+.+.}-{3:3}, at: s_start+0x502/0x7c0
[ 221.610617]
[ 221.610619] Allocated by task 1:
[ 221.610623] kasan_save_stack+0x40/0x68
[ 221.610628] kasan_set_track+0x36/0x48
[ 221.610632] __kasan_kmalloc+0xbc/0xe8
[ 221.610636] bdi_alloc+0x58/0x160
[ 221.610642] __alloc_disk_node+0x96/0x558
[ 221.610648] __blk_alloc_disk+0x42/0x88
[ 221.610652] brd_alloc+0x2d8/0x730
[ 221.610659] brd_init+0xd4/0x150
[ 221.610668] do_one_initcall+0x17c/0x750
[ 221.610672] do_initcalls+0x256/0x500
[ 221.610677] kernel_init_freeable+0x59a/0xa60
[ 221.610681] kernel_init+0x2e/0x1f8
[ 221.610685] __ret_from_fork+0x8a/0xe8
[ 221.610689] ret_from_fork+0xa/0x30
[ 221.610695] The buggy address belongs to the object at 0000000087754000
[ 221.610695] which belongs to the cache kmalloc-4k of size 4096
[ 221.610700] The buggy address is located 324 bytes to the left of
[ 221.610700] allocated 2464-byte region [0000000087754000, 00000000877549a0)
[ 221.610705]
[ 221.610708] The buggy address belongs to the physical page:
[ 221.610711] page:00004000021dd400 refcount:1 mapcount:0 mapping:0000000000000000 index:0x0 pfn:0x87750
[ 221.610718] head:00004000021dd400 order:3 entire_mapcount:0 nr_pages_mapped:0 pincount:0
[ 221.610722] flags: 0x3ffff00000010200(slab|head|node=0|zone=1|lastcpupid=0x1ffff)
[ 221.610729] page_type: 0xffffffff()
[ 221.610735] raw: 3ffff00000010200 000000008008e800 000040000259cc10 0000000080081470
[ 221.610739] raw: 0000000000000000 0002000400000000 ffffffff00000001 0000000000000000
[ 221.610743] page dumped because: kasan: bad access detected
[ 221.610746]
[ 221.610748] Memory state around the buggy address:
[ 221.610752] 0000000087753d80: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
[ 221.610755] 0000000087753e00: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
[ 221.610759] >0000000087753e80: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
[ 221.610762] ^
[ 221.610766] 0000000087753f00: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
[ 221.610770] 0000000087753f80: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
[ 221.610773] ==================================================================
git bisect says:
% git bisect log git:(eaa2fa66c0a1|…1⚑32
git bisect start
# status: waiting for both good and bad commits
# good: [457391b0380335d5e9a5babdec90ac53928b23b4] Linux 6.3
git bisect good 457391b0380335d5e9a5babdec90ac53928b23b4
# status: waiting for bad commit, 1 good commit known
# bad: [57012c57536f8814dec92e74197ee96c3498d24e] Merge tag 'net-6.5-rc4' of git://git.kernel.org/pub/scm/linux/kernel/git/netdev/net
git bisect bad 57012c57536f8814dec92e74197ee96c3498d24e
# good: [50fb587e6a56dba74c3c56a7a09c48bff25cc5fa] Merge tag 'net-6.4-rc4' of git://git.kernel.org/pub/scm/linux/kernel/git/netdev/net
git bisect good 50fb587e6a56dba74c3c56a7a09c48bff25cc5fa
# bad: [f8824e151fbfa0ac0a258015d606ea6f4a10251b] Merge tag 'sound-6.5-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound
git bisect bad f8824e151fbfa0ac0a258015d606ea6f4a10251b
# bad: [6aeadf7896bff4ca230702daba8788455e6b866e] Merge tag 'docs-arm64-move' of git://git.lwn.net/linux
git bisect bad 6aeadf7896bff4ca230702daba8788455e6b866e
# bad: [e940efa936be65866db9ce20798b13fdc6b3891a] Merge tag 'zonefs-6.5-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/dlemoal/zonefs
git bisect bad e940efa936be65866db9ce20798b13fdc6b3891a
# bad: [8f0e3703571fe771d06235870ccbbf4ad41e63e8] Merge branch 'udplite-dccp-print-deprecation-notice'
git bisect bad 8f0e3703571fe771d06235870ccbbf4ad41e63e8
# bad: [e684ab76afebcaccd428f7d55361d5669ccc3e2d] Merge tag 'wireless-2023-06-06' of git://git.kernel.org/pub/scm/linux/kernel/git/wireless/wireless
git bisect bad e684ab76afebcaccd428f7d55361d5669ccc3e2d
# bad: [1683c329b6a2ee54989811089854a8ac2d5b5fc1] Merge tag 'regmap-fix-v6.4-rc4' of git://git.kernel.org/pub/scm/linux/kernel/git/broonie/regmap
git bisect bad 1683c329b6a2ee54989811089854a8ac2d5b5fc1
# good: [18713e8a689377386f639d9317f958244825bd7b] Merge tag 'arm-fixes-6.4-1' of git://git.kernel.org/pub/scm/linux/kernel/git/soc/soc
git bisect good 18713e8a689377386f639d9317f958244825bd7b
# good: [2d5438f4c6fdaa34c5d7de89a5331b8dbcd920af] Merge tag 'perf-urgent-2023-05-28' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect good 2d5438f4c6fdaa34c5d7de89a5331b8dbcd920af
# good: [7a6c8e512fa072cfe8ad7a3b26666b6f26435870] Merge tag 'v6.4-p3' of git://git.kernel.org/pub/scm/linux/kernel/git/herbert/crypto-2.6
git bisect good 7a6c8e512fa072cfe8ad7a3b26666b6f26435870
# bad: [9da705d432a07927526005a0688d81fbbf30e349] tracing: Have tracer selftests call cond_resched() before running
git bisect bad 9da705d432a07927526005a0688d81fbbf30e349
# good: [dcbd1ac2668b5fa02069ea96d581ca3f70a7543c] tracing/user_events: Rename link fields for clarity
git bisect good dcbd1ac2668b5fa02069ea96d581ca3f70a7543c
# bad: [4b512860bdbdddcf41467ebd394f27cb8dfb528c] tracing: Rename stacktrace field to common_stacktrace
git bisect bad 4b512860bdbdddcf41467ebd394f27cb8dfb528c
# good: [e30fbc618e97b38dbb49f1d44dcd0778d3f23b8c] tracing/histograms: Allow variables to have some modifiers
git bisect good e30fbc618e97b38dbb49f1d44dcd0778d3f23b8c
# first bad commit: [4b512860bdbdddcf41467ebd394f27cb8dfb528c] tracing: Rename stacktrace field to common_stacktrace
I don't see how 4b512860 might cause this, but i haven't spent much time
on it, maybe someone who knows the code recognize the problem much
quicker. I did the bisect twice, and it always ended up at that commit.
manually compiling and testing the revision before also shows that
it happens only with 4b512860.
For reproducing, the following script is good enough to trigger it
reliably on my system:
cd /home/svens/linux/tools/testing/selftests/ftrace
for i in $(seq 1 10); do
./ftracetest -v /home/svens/linux/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-stack.tc
dmesg|grep "BUG: KASAN"
if [ "$?" -eq 0 ]; then
exit 1
fi
done
exit 0
Regards
Sven
On Fri, 04 Aug 2023 08:20:23 +0200
Sven Schnelle <[email protected]> wrote:
> Hi Steven,
>
> i noticed the following KASAN splat in CI (on s390):
>
> [ 218.586476] /home/svens/linux/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-stack.tc
> [ 221.610410] ==================================================================
> [ 221.610424] BUG: KASAN: slab-out-of-bounds in print_synth_event+0xa68/0xa78
> [ 221.610440] Read of size 8 at addr 0000000087753ebc by task grep/1321
> [ 221.610445]
> [ 221.610451] CPU: 9 PID: 1321 Comm: grep Not tainted 6.4.0-rc3-00008-g4b512860bdbd #716
> [ 221.610457] Hardware name: IBM 3906 M04 704 (z/VM 7.1.0)
> [ 221.610462] Call Trace:
> [ 221.610466] [<00000000026026e6>] dump_stack_lvl+0x106/0x1c8
> [ 221.610479] [<00000000009cdbbc>] print_address_description.constprop.0+0x34/0x378
> [ 221.610488] [<00000000009cdfac>] print_report+0xac/0x240
> [ 221.610494] [<00000000009ce32a>] kasan_report+0xf2/0x130
> [ 221.610501] [<00000000005e4f60>] print_synth_event+0xa68/0xa78
Can you show where exactly the above line is?
> [ 221.610508] [<00000000005809c0>] print_trace_line+0x2a8/0xc00
> [ 221.610516] [<0000000000582d4a>] s_show+0xc2/0x3d0
> [ 221.610522] [<0000000000b09db2>] seq_read_iter+0x912/0xf88
> [ 221.610530] [<0000000000b0a582>] seq_read+0x15a/0x1d8
> [ 221.610535] [<0000000000a75f66>] vfs_read+0x186/0x778
> [ 221.610551] [<0000000000a77b26>] ksys_read+0x126/0x210
> [ 221.610557] [<000000000010d044>] do_syscall+0x22c/0x328
> [ 221.610564] [<000000000266ea02>] __do_syscall+0x9a/0xf8
> [ 221.610571] [<000000000269f068>] system_call+0x70/0x98
> [ 221.610577] 3 locks held by grep/1321:
> [ 221.610580] #0: 00000000a99db2f8 (&p->lock){+.+.}-{3:3}, at: seq_read_iter+0xca/0xf88
> [ 221.610595] #1: 00000000032d0c18 (trace_event_sem){++++}-{3:3}, at: s_start+0x3c2/0x7c0
> [ 221.610606] #2: 00000000032c8cb8 (all_cpu_access_lock){+.+.}-{3:3}, at: s_start+0x502/0x7c0
> [ 221.610617]
> [ 221.610619] Allocated by task 1:
> [ 221.610623] kasan_save_stack+0x40/0x68
> [ 221.610628] kasan_set_track+0x36/0x48
> [ 221.610632] __kasan_kmalloc+0xbc/0xe8
> [ 221.610636] bdi_alloc+0x58/0x160
> [ 221.610642] __alloc_disk_node+0x96/0x558
> [ 221.610648] __blk_alloc_disk+0x42/0x88
> [ 221.610652] brd_alloc+0x2d8/0x730
> [ 221.610659] brd_init+0xd4/0x150
> [ 221.610668] do_one_initcall+0x17c/0x750
> [ 221.610672] do_initcalls+0x256/0x500
> [ 221.610677] kernel_init_freeable+0x59a/0xa60
> [ 221.610681] kernel_init+0x2e/0x1f8
> [ 221.610685] __ret_from_fork+0x8a/0xe8
> [ 221.610689] ret_from_fork+0xa/0x30
> [ 221.610695] The buggy address belongs to the object at 0000000087754000
> [ 221.610695] which belongs to the cache kmalloc-4k of size 4096
> [ 221.610700] The buggy address is located 324 bytes to the left of
> [ 221.610700] allocated 2464-byte region [0000000087754000, 00000000877549a0)
> [ 221.610705]
> [ 221.610708] The buggy address belongs to the physical page:
> [ 221.610711] page:00004000021dd400 refcount:1 mapcount:0 mapping:0000000000000000 index:0x0 pfn:0x87750
> [ 221.610718] head:00004000021dd400 order:3 entire_mapcount:0 nr_pages_mapped:0 pincount:0
> [ 221.610722] flags: 0x3ffff00000010200(slab|head|node=0|zone=1|lastcpupid=0x1ffff)
> [ 221.610729] page_type: 0xffffffff()
> [ 221.610735] raw: 3ffff00000010200 000000008008e800 000040000259cc10 0000000080081470
> [ 221.610739] raw: 0000000000000000 0002000400000000 ffffffff00000001 0000000000000000
> [ 221.610743] page dumped because: kasan: bad access detected
> [ 221.610746]
> [ 221.610748] Memory state around the buggy address:
> [ 221.610752] 0000000087753d80: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
> [ 221.610755] 0000000087753e00: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
> [ 221.610759] >0000000087753e80: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
> [ 221.610762] ^
> [ 221.610766] 0000000087753f00: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
> [ 221.610770] 0000000087753f80: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
> [ 221.610773] ==================================================================
>
> git bisect says:
>
> % git bisect log git:(eaa2fa66c0a1|…1⚑32
> git bisect start
> # status: waiting for both good and bad commits
> # good: [457391b0380335d5e9a5babdec90ac53928b23b4] Linux 6.3
> git bisect good 457391b0380335d5e9a5babdec90ac53928b23b4
> # status: waiting for bad commit, 1 good commit known
> # bad: [57012c57536f8814dec92e74197ee96c3498d24e] Merge tag 'net-6.5-rc4' of git://git.kernel.org/pub/scm/linux/kernel/git/netdev/net
> git bisect bad 57012c57536f8814dec92e74197ee96c3498d24e
> # good: [50fb587e6a56dba74c3c56a7a09c48bff25cc5fa] Merge tag 'net-6.4-rc4' of git://git.kernel.org/pub/scm/linux/kernel/git/netdev/net
> git bisect good 50fb587e6a56dba74c3c56a7a09c48bff25cc5fa
> # bad: [f8824e151fbfa0ac0a258015d606ea6f4a10251b] Merge tag 'sound-6.5-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound
> git bisect bad f8824e151fbfa0ac0a258015d606ea6f4a10251b
> # bad: [6aeadf7896bff4ca230702daba8788455e6b866e] Merge tag 'docs-arm64-move' of git://git.lwn.net/linux
> git bisect bad 6aeadf7896bff4ca230702daba8788455e6b866e
> # bad: [e940efa936be65866db9ce20798b13fdc6b3891a] Merge tag 'zonefs-6.5-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/dlemoal/zonefs
> git bisect bad e940efa936be65866db9ce20798b13fdc6b3891a
> # bad: [8f0e3703571fe771d06235870ccbbf4ad41e63e8] Merge branch 'udplite-dccp-print-deprecation-notice'
> git bisect bad 8f0e3703571fe771d06235870ccbbf4ad41e63e8
> # bad: [e684ab76afebcaccd428f7d55361d5669ccc3e2d] Merge tag 'wireless-2023-06-06' of git://git.kernel.org/pub/scm/linux/kernel/git/wireless/wireless
> git bisect bad e684ab76afebcaccd428f7d55361d5669ccc3e2d
> # bad: [1683c329b6a2ee54989811089854a8ac2d5b5fc1] Merge tag 'regmap-fix-v6.4-rc4' of git://git.kernel.org/pub/scm/linux/kernel/git/broonie/regmap
> git bisect bad 1683c329b6a2ee54989811089854a8ac2d5b5fc1
> # good: [18713e8a689377386f639d9317f958244825bd7b] Merge tag 'arm-fixes-6.4-1' of git://git.kernel.org/pub/scm/linux/kernel/git/soc/soc
> git bisect good 18713e8a689377386f639d9317f958244825bd7b
> # good: [2d5438f4c6fdaa34c5d7de89a5331b8dbcd920af] Merge tag 'perf-urgent-2023-05-28' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
> git bisect good 2d5438f4c6fdaa34c5d7de89a5331b8dbcd920af
> # good: [7a6c8e512fa072cfe8ad7a3b26666b6f26435870] Merge tag 'v6.4-p3' of git://git.kernel.org/pub/scm/linux/kernel/git/herbert/crypto-2.6
> git bisect good 7a6c8e512fa072cfe8ad7a3b26666b6f26435870
> # bad: [9da705d432a07927526005a0688d81fbbf30e349] tracing: Have tracer selftests call cond_resched() before running
> git bisect bad 9da705d432a07927526005a0688d81fbbf30e349
> # good: [dcbd1ac2668b5fa02069ea96d581ca3f70a7543c] tracing/user_events: Rename link fields for clarity
> git bisect good dcbd1ac2668b5fa02069ea96d581ca3f70a7543c
> # bad: [4b512860bdbdddcf41467ebd394f27cb8dfb528c] tracing: Rename stacktrace field to common_stacktrace
> git bisect bad 4b512860bdbdddcf41467ebd394f27cb8dfb528c
> # good: [e30fbc618e97b38dbb49f1d44dcd0778d3f23b8c] tracing/histograms: Allow variables to have some modifiers
> git bisect good e30fbc618e97b38dbb49f1d44dcd0778d3f23b8c
> # first bad commit: [4b512860bdbdddcf41467ebd394f27cb8dfb528c] tracing: Rename stacktrace field to common_stacktrace
>
> I don't see how 4b512860 might cause this, but i haven't spent much time
> on it, maybe someone who knows the code recognize the problem much
> quicker. I did the bisect twice, and it always ended up at that commit.
> manually compiling and testing the revision before also shows that
> it happens only with 4b512860.
>
> For reproducing, the following script is good enough to trigger it
> reliably on my system:
>
> cd /home/svens/linux/tools/testing/selftests/ftrace
> for i in $(seq 1 10); do
> ./ftracetest -v /home/svens/linux/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-stack.tc
It's probably because that code has:
#!/bin/sh
# SPDX-License-Identifier: GPL-2.0
# description: event trigger - test inter-event histogram trigger trace action with dynamic string param
# requires: set_event synthetic_events events/sched/sched_process_exec/hist "can be any field, or the special string 'common_stacktrace'":README
Where it looks for "common_stacktrace" in the README file, and will not run
if it does not exist. That "common_stacktrace" was added to the README file
by that commit.
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index ebc59781456a..81801dc31784 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -5752,7 +5752,7 @@ static const char readme_msg[] =
"\t table using the key(s) and value(s) named, and the value of a\n"
"\t sum called 'hitcount' is incremented. Keys and values\n"
"\t correspond to fields in the event's format description. Keys\n"
- "\t can be any field, or the special string 'stacktrace'.\n"
+ "\t can be any field, or the special string 'common_stacktrace'.\n"
"\t Compound keys consisting of up to two fields can be specified\n"
"\t by the 'keys' keyword. Values must correspond to numeric\n"
"\t fields. Sort keys consisting of up to two fields can be\n"
-- Steve
> dmesg|grep "BUG: KASAN"
> if [ "$?" -eq 0 ]; then
> exit 1
> fi
> done
> exit 0
>
> Regards
> Sven
Steven Rostedt <[email protected]> writes:
> On Fri, 04 Aug 2023 08:20:23 +0200
> Sven Schnelle <[email protected]> wrote:
>
>> Hi Steven,
>>
>> i noticed the following KASAN splat in CI (on s390):
>>
>> [ 218.586476] /home/svens/linux/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-stack.tc
>> [ 221.610410] ==================================================================
>> [ 221.610424] BUG: KASAN: slab-out-of-bounds in print_synth_event+0xa68/0xa78
>> [ 221.610440] Read of size 8 at addr 0000000087753ebc by task grep/1321
>> [ 221.610445]
>> [ 221.610451] CPU: 9 PID: 1321 Comm: grep Not tainted 6.4.0-rc3-00008-g4b512860bdbd #716
>> [ 221.610457] Hardware name: IBM 3906 M04 704 (z/VM 7.1.0)
>> [ 221.610462] Call Trace:
>> [ 221.610466] [<00000000026026e6>] dump_stack_lvl+0x106/0x1c8
>> [ 221.610479] [<00000000009cdbbc>] print_address_description.constprop.0+0x34/0x378
>> [ 221.610488] [<00000000009cdfac>] print_report+0xac/0x240
>> [ 221.610494] [<00000000009ce32a>] kasan_report+0xf2/0x130
>> [ 221.610501] [<00000000005e4f60>] print_synth_event+0xa68/0xa78
>
> Can you show where exactly the above line is?
It is:
(gdb) list *(print_synth_event+0xa68)
0x5e4f60 is in print_synth_event (/home/svens/ibmgit/linux/kernel/trace/trace_events_synth.c:410).
405 p = (void *)entry + data_offset;
406 end = (void *)p + len - (sizeof(long) - 1);
407
408 trace_seq_printf(s, "%s=STACK:\n", se->fields[i]->name);
409
410 for (; *p && p < end; p++)
411 trace_seq_printf(s, "=> %pS\n", (void *)*p);
412 n_u64++;
413
414 } else {
>> For reproducing, the following script is good enough to trigger it
>> reliably on my system:
>>
>> cd /home/svens/linux/tools/testing/selftests/ftrace
>> for i in $(seq 1 10); do
>> ./ftracetest -v /home/svens/linux/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-stack.tc
>
> It's probably because that code has:
>
> #!/bin/sh
> # SPDX-License-Identifier: GPL-2.0
> # description: event trigger - test inter-event histogram trigger trace action with dynamic string param
> # requires: set_event synthetic_events events/sched/sched_process_exec/hist "can be any field, or the special string 'common_stacktrace'":README
>
> Where it looks for "common_stacktrace" in the README file, and will not run
> if it does not exist. That "common_stacktrace" was added to the README file
> by that commit.
Thanks, i'll try to bisect again with the changed test.
On Fri, 04 Aug 2023 18:32:48 +0200
Sven Schnelle <[email protected]> wrote:
> > Can you show where exactly the above line is?
>
> It is:
>
> (gdb) list *(print_synth_event+0xa68)
> 0x5e4f60 is in print_synth_event (/home/svens/ibmgit/linux/kernel/trace/trace_events_synth.c:410).
> 405 p = (void *)entry + data_offset;
> 406 end = (void *)p + len - (sizeof(long) - 1);
> 407
> 408 trace_seq_printf(s, "%s=STACK:\n", se->fields[i]->name);
> 409
> 410 for (; *p && p < end; p++)
I think that conditional needs to be swapped. Can you test the following
change and see if the problem disappears?
> 411 trace_seq_printf(s, "=> %pS\n", (void *)*p);
> 412 n_u64++;
> 413
> 414 } else {
-- Steve
diff --git a/kernel/trace/trace_events_synth.c b/kernel/trace/trace_events_synth.c
index dd398afc8e25..1e266e6436a0 100644
--- a/kernel/trace/trace_events_synth.c
+++ b/kernel/trace/trace_events_synth.c
@@ -407,7 +407,7 @@ static enum print_line_t print_synth_event(struct trace_iterator *iter,
trace_seq_printf(s, "%s=STACK:\n", se->fields[i]->name);
- for (; *p && p < end; p++)
+ for (; p < end && *p; p++)
trace_seq_printf(s, "=> %pS\n", (void *)*p);
n_u64++;
Steven Rostedt <[email protected]> writes:
> On Fri, 04 Aug 2023 18:32:48 +0200
> Sven Schnelle <[email protected]> wrote:
>
>> > Can you show where exactly the above line is?
>>
>> It is:
>>
>> (gdb) list *(print_synth_event+0xa68)
>> 0x5e4f60 is in print_synth_event (/home/svens/ibmgit/linux/kernel/trace/trace_events_synth.c:410).
>> 405 p = (void *)entry + data_offset;
>> 406 end = (void *)p + len - (sizeof(long) - 1);
>> 407
>> 408 trace_seq_printf(s, "%s=STACK:\n", se->fields[i]->name);
>> 409
>> 410 for (; *p && p < end; p++)
>
> I think that conditional needs to be swapped. Can you test the following
> change and see if the problem disappears?
Unfortunately that doesn't change anything, still exactly the same splat.
On Fri, 04 Aug 2023 08:20:23 +0200
Sven Schnelle <[email protected]> wrote:
> Hi Steven,
>
> i noticed the following KASAN splat in CI (on s390):
Could this actually be a bug in KASAN?
The reason I ask, is because of the report.
>
> [ 218.586476] /home/svens/linux/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-stack.tc
> [ 221.610410] ==================================================================
> [ 221.610424] BUG: KASAN: slab-out-of-bounds in print_synth_event+0xa68/0xa78
> [ 221.610440] Read of size 8 at addr 0000000087753ebc by task grep/1321
It's saying that there's a "slab-out-of-bounds on address 0x87753ebc
I guess the question is, what slab? But what if there is no slab?
> [ 221.610445]
> [ 221.610451] CPU: 9 PID: 1321 Comm: grep Not tainted 6.4.0-rc3-00008-g4b512860bdbd #716
> [ 221.610457] Hardware name: IBM 3906 M04 704 (z/VM 7.1.0)
> [ 221.610462] Call Trace:
> [ 221.610466] [<00000000026026e6>] dump_stack_lvl+0x106/0x1c8
> [ 221.610479] [<00000000009cdbbc>] print_address_description.constprop.0+0x34/0x378
> [ 221.610488] [<00000000009cdfac>] print_report+0xac/0x240
> [ 221.610494] [<00000000009ce32a>] kasan_report+0xf2/0x130
> [ 221.610501] [<00000000005e4f60>] print_synth_event+0xa68/0xa78
> [ 221.610508] [<00000000005809c0>] print_trace_line+0x2a8/0xc00
> [ 221.610516] [<0000000000582d4a>] s_show+0xc2/0x3d0
> [ 221.610522] [<0000000000b09db2>] seq_read_iter+0x912/0xf88
> [ 221.610530] [<0000000000b0a582>] seq_read+0x15a/0x1d8
> [ 221.610535] [<0000000000a75f66>] vfs_read+0x186/0x778
> [ 221.610551] [<0000000000a77b26>] ksys_read+0x126/0x210
> [ 221.610557] [<000000000010d044>] do_syscall+0x22c/0x328
> [ 221.610564] [<000000000266ea02>] __do_syscall+0x9a/0xf8
> [ 221.610571] [<000000000269f068>] system_call+0x70/0x98
> [ 221.610577] 3 locks held by grep/1321:
> [ 221.610580] #0: 00000000a99db2f8 (&p->lock){+.+.}-{3:3}, at: seq_read_iter+0xca/0xf88
> [ 221.610595] #1: 00000000032d0c18 (trace_event_sem){++++}-{3:3}, at: s_start+0x3c2/0x7c0
> [ 221.610606] #2: 00000000032c8cb8 (all_cpu_access_lock){+.+.}-{3:3}, at: s_start+0x502/0x7c0
> [ 221.610617]
> [ 221.610619] Allocated by task 1:
> [ 221.610623] kasan_save_stack+0x40/0x68
> [ 221.610628] kasan_set_track+0x36/0x48
> [ 221.610632] __kasan_kmalloc+0xbc/0xe8
> [ 221.610636] bdi_alloc+0x58/0x160
> [ 221.610642] __alloc_disk_node+0x96/0x558
> [ 221.610648] __blk_alloc_disk+0x42/0x88
> [ 221.610652] brd_alloc+0x2d8/0x730
> [ 221.610659] brd_init+0xd4/0x150
> [ 221.610668] do_one_initcall+0x17c/0x750
> [ 221.610672] do_initcalls+0x256/0x500
> [ 221.610677] kernel_init_freeable+0x59a/0xa60
> [ 221.610681] kernel_init+0x2e/0x1f8
> [ 221.610685] __ret_from_fork+0x8a/0xe8
> [ 221.610689] ret_from_fork+0xa/0x30
> [ 221.610695] The buggy address belongs to the object at 0000000087754000
> [ 221.610695] which belongs to the cache kmalloc-4k of size 4096
> [ 221.610700] The buggy address is located 324 bytes to the left of
> [ 221.610700] allocated 2464-byte region [0000000087754000, 00000000877549a0)
This is saying that it's allocated to the left of that region. It being:
0x87753ebc
Shows that it's before the slab.
Now, you said that it's triggering at:
} else if (se->fields[i]->is_stack) {
u32 offset, data_offset, len;
unsigned long *p, *end;
offset = (u32)entry->fields[n_u64];
data_offset = offset & 0xffff;
len = offset >> 16;
p = (void *)entry + data_offset;
end = (void *)p + len - (sizeof(long) - 1);
trace_seq_printf(s, "%s=STACK:\n", se->fields[i]->name);
for (; p < end && *p; p++) <<<<------------ BAD ADDR
trace_seq_printf(s, "=> %pS\n", (void *)*p);
n_u64++;
But p is pointing into the ring buffer. The ring buffer is not allocated
via slabs (nor kmalloc) but uses alloc_pages_node() (see __rb_allocate_pages()).
Could it be that KASAN sees an access close to a slab page, that isn't
being examined, and thinks it's a out-of-bounds access?
-- Steve
> [ 221.610705]
> [ 221.610708] The buggy address belongs to the physical page:
> [ 221.610711] page:00004000021dd400 refcount:1 mapcount:0 mapping:0000000000000000 index:0x0 pfn:0x87750
> [ 221.610718] head:00004000021dd400 order:3 entire_mapcount:0 nr_pages_mapped:0 pincount:0
> [ 221.610722] flags: 0x3ffff00000010200(slab|head|node=0|zone=1|lastcpupid=0x1ffff)
> [ 221.610729] page_type: 0xffffffff()
> [ 221.610735] raw: 3ffff00000010200 000000008008e800 000040000259cc10 0000000080081470
> [ 221.610739] raw: 0000000000000000 0002000400000000 ffffffff00000001 0000000000000000
> [ 221.610743] page dumped because: kasan: bad access detected
> [ 221.610746]
> [ 221.610748] Memory state around the buggy address:
> [ 221.610752] 0000000087753d80: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
> [ 221.610755] 0000000087753e00: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
> [ 221.610759] >0000000087753e80: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
> [ 221.610762] ^
> [ 221.610766] 0000000087753f00: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
> [ 221.610770] 0000000087753f80: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
> [ 221.610773] ==================================================================
>
> git bisect says:
>
Steven Rostedt <[email protected]> writes:
> On Fri, 04 Aug 2023 08:20:23 +0200
> Sven Schnelle <[email protected]> wrote:
>
>> Hi Steven,
>>
>> i noticed the following KASAN splat in CI (on s390):
>
> Could this actually be a bug in KASAN?
>
> The reason I ask, is because of the report.
I think the problem is that the code assigns data_offset with:
*(u32 *)&entry->fields[*n_u64] = data_offset;
but reads it with:
offset = (u32)entry->fields[n_u64];
which works on LE, but not BE.
I'm currently preparing the patch below, which also makes the code a bit
easier to read. I'm still seeing no stack traces, but at least the
random memory reads are gone and no KASAN warning anymore. I'll
continue fixing and sent a full patch as soon as everything is fixed.
From 82fc673f0d3b6031b760b4217bebdb1047119041 Mon Sep 17 00:00:00 2001
From: Sven Schnelle <[email protected]>
Date: Tue, 8 Aug 2023 11:35:12 +0200
Subject: [PATCH] tracing/synthetic: use union instead of casts
The current code uses a lot of casts to access the fields
member in struct synth_trace_events with different sizes.
This makes the code hard to read, and had already introduced
an endianess bug. Use a union and struct instead.
Signed-off-by: Sven Schnelle <[email protected]>
---
kernel/trace/trace_events_synth.c | 100 +++++++++++++++---------------
1 file changed, 50 insertions(+), 50 deletions(-)
diff --git a/kernel/trace/trace_events_synth.c b/kernel/trace/trace_events_synth.c
index d6a70aff2410..1f8fe7f2b5b2 100644
--- a/kernel/trace/trace_events_synth.c
+++ b/kernel/trace/trace_events_synth.c
@@ -125,9 +125,22 @@ static bool synth_event_match(const char *system, const char *event,
(!system || strcmp(system, SYNTH_SYSTEM) == 0);
}
+struct synth_trace_data {
+ u16 len;
+ u16 offset;
+};
+
+union synth_trace_field {
+ u8 as8;
+ u16 as16;
+ u32 as32;
+ u64 as64;
+ struct synth_trace_data as_data;
+};
+
struct synth_trace_event {
struct trace_entry ent;
- u64 fields[];
+ union synth_trace_field fields[];
};
static int synth_event_define_fields(struct trace_event_call *call)
@@ -321,19 +334,19 @@ static const char *synth_field_fmt(char *type)
static void print_synth_event_num_val(struct trace_seq *s,
char *print_fmt, char *name,
- int size, u64 val, char *space)
+ int size, union synth_trace_field *val, char *space)
{
switch (size) {
case 1:
- trace_seq_printf(s, print_fmt, name, (u8)val, space);
+ trace_seq_printf(s, print_fmt, name, val->as8, space);
break;
case 2:
- trace_seq_printf(s, print_fmt, name, (u16)val, space);
+ trace_seq_printf(s, print_fmt, name, val->as16, space);
break;
case 4:
- trace_seq_printf(s, print_fmt, name, (u32)val, space);
+ trace_seq_printf(s, print_fmt, name, val->as32, space);
break;
default:
@@ -374,36 +387,26 @@ static enum print_line_t print_synth_event(struct trace_iterator *iter,
/* parameter values */
if (se->fields[i]->is_string) {
if (se->fields[i]->is_dynamic) {
- u32 offset, data_offset;
- char *str_field;
-
- offset = (u32)entry->fields[n_u64];
- data_offset = offset & 0xffff;
-
- str_field = (char *)entry + data_offset;
+ struct synth_trace_data *data = &entry->fields[n_u64].as_data;
trace_seq_printf(s, print_fmt, se->fields[i]->name,
STR_VAR_LEN_MAX,
- str_field,
+ (char *)entry + data->offset,
i == se->n_fields - 1 ? "" : " ");
n_u64++;
} else {
trace_seq_printf(s, print_fmt, se->fields[i]->name,
STR_VAR_LEN_MAX,
- (char *)&entry->fields[n_u64],
+ (char *)&entry->fields[n_u64].as64,
i == se->n_fields - 1 ? "" : " ");
n_u64 += STR_VAR_LEN_MAX / sizeof(u64);
}
} else if (se->fields[i]->is_stack) {
- u32 offset, data_offset, len;
unsigned long *p, *end;
+ struct synth_trace_data *data = &entry->fields[n_u64].as_data;
- offset = (u32)entry->fields[n_u64];
- data_offset = offset & 0xffff;
- len = offset >> 16;
-
- p = (void *)entry + data_offset;
- end = (void *)p + len - (sizeof(long) - 1);
+ p = (void *)entry + data->offset;
+ end = (void *)p + data->len - (sizeof(long) - 1);
trace_seq_printf(s, "%s=STACK:\n", se->fields[i]->name);
@@ -419,13 +422,13 @@ static enum print_line_t print_synth_event(struct trace_iterator *iter,
print_synth_event_num_val(s, print_fmt,
se->fields[i]->name,
se->fields[i]->size,
- entry->fields[n_u64],
+ &entry->fields[n_u64],
space);
if (strcmp(se->fields[i]->type, "gfp_t") == 0) {
trace_seq_puts(s, " (");
trace_print_flags_seq(s, "|",
- entry->fields[n_u64],
+ entry->fields[n_u64].as64,
__flags);
trace_seq_putc(s, ')');
}
@@ -454,21 +457,16 @@ static unsigned int trace_string(struct synth_trace_event *entry,
int ret;
if (is_dynamic) {
- u32 data_offset;
+ struct synth_trace_data *data = &entry->fields[*n_u64].as_data;
- data_offset = struct_size(entry, fields, event->n_u64);
- data_offset += data_size;
-
- len = fetch_store_strlen((unsigned long)str_val);
-
- data_offset |= len << 16;
- *(u32 *)&entry->fields[*n_u64] = data_offset;
+ data->offset = struct_size(entry, fields, event->n_u64) + data_size;
+ data->len = fetch_store_strlen((unsigned long)str_val);
ret = fetch_store_string((unsigned long)str_val, &entry->fields[*n_u64], entry);
(*n_u64)++;
} else {
- str_field = (char *)&entry->fields[*n_u64];
+ str_field = (char *)&entry->fields[*n_u64].as64;
#ifdef CONFIG_ARCH_HAS_NON_OVERLAPPING_ADDRESS_SPACE
if ((unsigned long)str_val < TASK_SIZE)
@@ -492,6 +490,7 @@ static unsigned int trace_stack(struct synth_trace_event *entry,
unsigned int data_size,
unsigned int *n_u64)
{
+ struct synth_trace_data *data = &entry->fields[*n_u64].as_data;
unsigned int len;
u32 data_offset;
void *data_loc;
@@ -515,8 +514,9 @@ static unsigned int trace_stack(struct synth_trace_event *entry,
memcpy(data_loc, stack, len);
/* Fill in the field that holds the offset/len combo */
- data_offset |= len << 16;
- *(u32 *)&entry->fields[*n_u64] = data_offset;
+
+ data->offset = data_offset;
+ data->len = len;
(*n_u64)++;
@@ -592,19 +592,19 @@ static notrace void trace_event_raw_event_synth(void *__data,
switch (field->size) {
case 1:
- *(u8 *)&entry->fields[n_u64] = (u8)val;
+ entry->fields[n_u64].as8 = (u8)val;
break;
case 2:
- *(u16 *)&entry->fields[n_u64] = (u16)val;
+ entry->fields[n_u64].as16 = (u16)val;
break;
case 4:
- *(u32 *)&entry->fields[n_u64] = (u32)val;
+ entry->fields[n_u64].as32 = (u32)val;
break;
default:
- entry->fields[n_u64] = val;
+ entry->fields[n_u64].as64 = val;
break;
}
n_u64++;
@@ -1790,19 +1790,19 @@ int synth_event_trace(struct trace_event_file *file, unsigned int n_vals, ...)
switch (field->size) {
case 1:
- *(u8 *)&state.entry->fields[n_u64] = (u8)val;
+ state.entry->fields[n_u64].as8 = (u8)val;
break;
case 2:
- *(u16 *)&state.entry->fields[n_u64] = (u16)val;
+ state.entry->fields[n_u64].as16 = (u16)val;
break;
case 4:
- *(u32 *)&state.entry->fields[n_u64] = (u32)val;
+ state.entry->fields[n_u64].as32 = (u32)val;
break;
default:
- state.entry->fields[n_u64] = val;
+ state.entry->fields[n_u64].as64 = val;
break;
}
n_u64++;
@@ -1883,19 +1883,19 @@ int synth_event_trace_array(struct trace_event_file *file, u64 *vals,
switch (field->size) {
case 1:
- *(u8 *)&state.entry->fields[n_u64] = (u8)val;
+ state.entry->fields[n_u64].as8 = (u8)val;
break;
case 2:
- *(u16 *)&state.entry->fields[n_u64] = (u16)val;
+ state.entry->fields[n_u64].as16 = (u16)val;
break;
case 4:
- *(u32 *)&state.entry->fields[n_u64] = (u32)val;
+ state.entry->fields[n_u64].as32 = (u32)val;
break;
default:
- state.entry->fields[n_u64] = val;
+ state.entry->fields[n_u64].as64 = val;
break;
}
n_u64++;
@@ -2030,19 +2030,19 @@ static int __synth_event_add_val(const char *field_name, u64 val,
} else {
switch (field->size) {
case 1:
- *(u8 *)&trace_state->entry->fields[field->offset] = (u8)val;
+ trace_state->entry->fields[field->offset].as8 = (u8)val;
break;
case 2:
- *(u16 *)&trace_state->entry->fields[field->offset] = (u16)val;
+ trace_state->entry->fields[field->offset].as16 = (u16)val;
break;
case 4:
- *(u32 *)&trace_state->entry->fields[field->offset] = (u32)val;
+ trace_state->entry->fields[field->offset].as32 = (u32)val;
break;
default:
- trace_state->entry->fields[field->offset] = val;
+ trace_state->entry->fields[field->offset].as64 = val;
break;
}
}
--
2.39.2
Steven Rostedt <[email protected]> writes:
> On Fri, 04 Aug 2023 08:20:23 +0200
> Sven Schnelle <[email protected]> wrote:
>
>> Hi Steven,
>>
>> i noticed the following KASAN splat in CI (on s390):
>
> Could this actually be a bug in KASAN?
>
> The reason I ask, is because of the report.
I don't think so. I looked into the trace file when the problem occurred
yesterday, and it looked like this:
kworker/0:2-83 [000] d..4. 59.260107: wake_lat: pid=2654624 delta=55 stack=STACK:
=> 0x6b6b6b6b6b6b6b6b
=> 0x6b6b6b6b6b6b6b6b
=> 0x6b6b6b6b6b6b6b6b
=> 0x6b6b6b6b6b6b6b6b
=> 0x6b6b6b6b6b6b6b6b
[..]
Somtimes the number is 0xcc, which is POISON_FREE_INITMEM instead of POISON_FREE.
In other entries delta and pid are also wrong:
swapper/0-1 [002] ..... 5.864575: wake_lat: pid=5437496 delta=7880749591624456 stack=STACK:
Of course PID could have gone away, but that delta looks interesting. So
it looks like the whole entry is just random data not owned by tracing,
and not the data that was allocated in the ringbuffer code.
On Tue, 08 Aug 2023 11:44:26 +0200
Sven Schnelle <[email protected]> wrote:
> Steven Rostedt <[email protected]> writes:
>
> > On Fri, 04 Aug 2023 08:20:23 +0200
> > Sven Schnelle <[email protected]> wrote:
> >
> >> Hi Steven,
> >>
> >> i noticed the following KASAN splat in CI (on s390):
> >
> > Could this actually be a bug in KASAN?
> >
> > The reason I ask, is because of the report.
>
> I think the problem is that the code assigns data_offset with:
>
> *(u32 *)&entry->fields[*n_u64] = data_offset;
>
> but reads it with:
>
> offset = (u32)entry->fields[n_u64];
>
> which works on LE, but not BE.
Ah, that makes sense. I didn't realize (or forgot) that s390 was BE. My
PowerPC box that was BE died years ago, and I have stopped testing BE ever
since :-(
>
> I'm currently preparing the patch below, which also makes the code a bit
> easier to read. I'm still seeing no stack traces, but at least the
> random memory reads are gone and no KASAN warning anymore. I'll
> continue fixing and sent a full patch as soon as everything is fixed.
>
> >From 82fc673f0d3b6031b760b4217bebdb1047119041 Mon Sep 17 00:00:00 2001
> From: Sven Schnelle <[email protected]>
> Date: Tue, 8 Aug 2023 11:35:12 +0200
> Subject: [PATCH] tracing/synthetic: use union instead of casts
>
> The current code uses a lot of casts to access the fields
> member in struct synth_trace_events with different sizes.
> This makes the code hard to read, and had already introduced
> an endianess bug. Use a union and struct instead.
>
> Signed-off-by: Sven Schnelle <[email protected]>
> ---
> kernel/trace/trace_events_synth.c | 100 +++++++++++++++---------------
> 1 file changed, 50 insertions(+), 50 deletions(-)
>
> diff --git a/kernel/trace/trace_events_synth.c b/kernel/trace/trace_events_synth.c
> index d6a70aff2410..1f8fe7f2b5b2 100644
> --- a/kernel/trace/trace_events_synth.c
> +++ b/kernel/trace/trace_events_synth.c
> @@ -125,9 +125,22 @@ static bool synth_event_match(const char *system, const char *event,
> (!system || strcmp(system, SYNTH_SYSTEM) == 0);
> }
>
> +struct synth_trace_data {
> + u16 len;
> + u16 offset;
> +};
This is actually common throughout the tracing code (as all dynamic fields
have this). We should probably make this more generic than just for
synthetic events. Although, that would probably break BE user space. Hmm,
we could have it be:
struct trace_dynamic {
#ifdef CONFIG_CPU_BIG_ENDIAN
u16 offset;
u16 len;
#else
u16 len;
u16 offset
#endif
};
So that we don't break user space (which still does the:
offset = value & 0xffff;
len = value >> 16;
The rest seems good to me for just synthetic event.
Thanks!
-- Steve
> +
> +union synth_trace_field {
> + u8 as8;
> + u16 as16;
> + u32 as32;
> + u64 as64;
> + struct synth_trace_data as_data;
> +};
> +
> struct synth_trace_event {
> struct trace_entry ent;
> - u64 fields[];
> + union synth_trace_field fields[];
> };
>
> static int synth_event_define_fields(struct trace_event_call *call)
> @@ -321,19 +334,19 @@ static const char *synth_field_fmt(char *type)
>
> static void print_synth_event_num_val(struct trace_seq *s,
> char *print_fmt, char *name,
> - int size, u64 val, char *space)
> + int size, union synth_trace_field *val, char *space)
> {
> switch (size) {
> case 1:
> - trace_seq_printf(s, print_fmt, name, (u8)val, space);
> + trace_seq_printf(s, print_fmt, name, val->as8, space);
> break;
>
> case 2:
> - trace_seq_printf(s, print_fmt, name, (u16)val, space);
> + trace_seq_printf(s, print_fmt, name, val->as16, space);
> break;
>
> case 4:
> - trace_seq_printf(s, print_fmt, name, (u32)val, space);
> + trace_seq_printf(s, print_fmt, name, val->as32, space);
> break;
>
> default:
> @@ -374,36 +387,26 @@ static enum print_line_t print_synth_event(struct trace_iterator *iter,
> /* parameter values */
> if (se->fields[i]->is_string) {
> if (se->fields[i]->is_dynamic) {
> - u32 offset, data_offset;
> - char *str_field;
> -
> - offset = (u32)entry->fields[n_u64];
> - data_offset = offset & 0xffff;
> -
> - str_field = (char *)entry + data_offset;
> + struct synth_trace_data *data = &entry->fields[n_u64].as_data;
>
> trace_seq_printf(s, print_fmt, se->fields[i]->name,
> STR_VAR_LEN_MAX,
> - str_field,
> + (char *)entry + data->offset,
> i == se->n_fields - 1 ? "" : " ");
> n_u64++;
> } else {
> trace_seq_printf(s, print_fmt, se->fields[i]->name,
> STR_VAR_LEN_MAX,
> - (char *)&entry->fields[n_u64],
> + (char *)&entry->fields[n_u64].as64,
> i == se->n_fields - 1 ? "" : " ");
> n_u64 += STR_VAR_LEN_MAX / sizeof(u64);
> }
> } else if (se->fields[i]->is_stack) {
> - u32 offset, data_offset, len;
> unsigned long *p, *end;
> + struct synth_trace_data *data = &entry->fields[n_u64].as_data;
>
> - offset = (u32)entry->fields[n_u64];
> - data_offset = offset & 0xffff;
> - len = offset >> 16;
> -
> - p = (void *)entry + data_offset;
> - end = (void *)p + len - (sizeof(long) - 1);
> + p = (void *)entry + data->offset;
> + end = (void *)p + data->len - (sizeof(long) - 1);
>
> trace_seq_printf(s, "%s=STACK:\n", se->fields[i]->name);
>
> @@ -419,13 +422,13 @@ static enum print_line_t print_synth_event(struct trace_iterator *iter,
> print_synth_event_num_val(s, print_fmt,
> se->fields[i]->name,
> se->fields[i]->size,
> - entry->fields[n_u64],
> + &entry->fields[n_u64],
> space);
>
> if (strcmp(se->fields[i]->type, "gfp_t") == 0) {
> trace_seq_puts(s, " (");
> trace_print_flags_seq(s, "|",
> - entry->fields[n_u64],
> + entry->fields[n_u64].as64,
> __flags);
> trace_seq_putc(s, ')');
> }
> @@ -454,21 +457,16 @@ static unsigned int trace_string(struct synth_trace_event *entry,
> int ret;
>
> if (is_dynamic) {
> - u32 data_offset;
> + struct synth_trace_data *data = &entry->fields[*n_u64].as_data;
>
> - data_offset = struct_size(entry, fields, event->n_u64);
> - data_offset += data_size;
> -
> - len = fetch_store_strlen((unsigned long)str_val);
> -
> - data_offset |= len << 16;
> - *(u32 *)&entry->fields[*n_u64] = data_offset;
> + data->offset = struct_size(entry, fields, event->n_u64) + data_size;
> + data->len = fetch_store_strlen((unsigned long)str_val);
>
> ret = fetch_store_string((unsigned long)str_val, &entry->fields[*n_u64], entry);
>
> (*n_u64)++;
> } else {
> - str_field = (char *)&entry->fields[*n_u64];
> + str_field = (char *)&entry->fields[*n_u64].as64;
>
> #ifdef CONFIG_ARCH_HAS_NON_OVERLAPPING_ADDRESS_SPACE
> if ((unsigned long)str_val < TASK_SIZE)
> @@ -492,6 +490,7 @@ static unsigned int trace_stack(struct synth_trace_event *entry,
> unsigned int data_size,
> unsigned int *n_u64)
> {
> + struct synth_trace_data *data = &entry->fields[*n_u64].as_data;
> unsigned int len;
> u32 data_offset;
> void *data_loc;
> @@ -515,8 +514,9 @@ static unsigned int trace_stack(struct synth_trace_event *entry,
> memcpy(data_loc, stack, len);
>
> /* Fill in the field that holds the offset/len combo */
> - data_offset |= len << 16;
> - *(u32 *)&entry->fields[*n_u64] = data_offset;
> +
> + data->offset = data_offset;
> + data->len = len;
>
> (*n_u64)++;
>
> @@ -592,19 +592,19 @@ static notrace void trace_event_raw_event_synth(void *__data,
>
> switch (field->size) {
> case 1:
> - *(u8 *)&entry->fields[n_u64] = (u8)val;
> + entry->fields[n_u64].as8 = (u8)val;
> break;
>
> case 2:
> - *(u16 *)&entry->fields[n_u64] = (u16)val;
> + entry->fields[n_u64].as16 = (u16)val;
> break;
>
> case 4:
> - *(u32 *)&entry->fields[n_u64] = (u32)val;
> + entry->fields[n_u64].as32 = (u32)val;
> break;
>
> default:
> - entry->fields[n_u64] = val;
> + entry->fields[n_u64].as64 = val;
> break;
> }
> n_u64++;
> @@ -1790,19 +1790,19 @@ int synth_event_trace(struct trace_event_file *file, unsigned int n_vals, ...)
>
> switch (field->size) {
> case 1:
> - *(u8 *)&state.entry->fields[n_u64] = (u8)val;
> + state.entry->fields[n_u64].as8 = (u8)val;
> break;
>
> case 2:
> - *(u16 *)&state.entry->fields[n_u64] = (u16)val;
> + state.entry->fields[n_u64].as16 = (u16)val;
> break;
>
> case 4:
> - *(u32 *)&state.entry->fields[n_u64] = (u32)val;
> + state.entry->fields[n_u64].as32 = (u32)val;
> break;
>
> default:
> - state.entry->fields[n_u64] = val;
> + state.entry->fields[n_u64].as64 = val;
> break;
> }
> n_u64++;
> @@ -1883,19 +1883,19 @@ int synth_event_trace_array(struct trace_event_file *file, u64 *vals,
>
> switch (field->size) {
> case 1:
> - *(u8 *)&state.entry->fields[n_u64] = (u8)val;
> + state.entry->fields[n_u64].as8 = (u8)val;
> break;
>
> case 2:
> - *(u16 *)&state.entry->fields[n_u64] = (u16)val;
> + state.entry->fields[n_u64].as16 = (u16)val;
> break;
>
> case 4:
> - *(u32 *)&state.entry->fields[n_u64] = (u32)val;
> + state.entry->fields[n_u64].as32 = (u32)val;
> break;
>
> default:
> - state.entry->fields[n_u64] = val;
> + state.entry->fields[n_u64].as64 = val;
> break;
> }
> n_u64++;
> @@ -2030,19 +2030,19 @@ static int __synth_event_add_val(const char *field_name, u64 val,
> } else {
> switch (field->size) {
> case 1:
> - *(u8 *)&trace_state->entry->fields[field->offset] = (u8)val;
> + trace_state->entry->fields[field->offset].as8 = (u8)val;
> break;
>
> case 2:
> - *(u16 *)&trace_state->entry->fields[field->offset] = (u16)val;
> + trace_state->entry->fields[field->offset].as16 = (u16)val;
> break;
>
> case 4:
> - *(u32 *)&trace_state->entry->fields[field->offset] = (u32)val;
> + trace_state->entry->fields[field->offset].as32 = (u32)val;
> break;
>
> default:
> - trace_state->entry->fields[field->offset] = val;
> + trace_state->entry->fields[field->offset].as64 = val;
> break;
> }
> }
On Tue, 08 Aug 2023 16:28:49 +0200
Sven Schnelle <[email protected]> wrote:
> Steven Rostedt <[email protected]> writes:
>
> >> I think the problem is that the code assigns data_offset with:
> >>
> >> *(u32 *)&entry->fields[*n_u64] = data_offset;
> >>
> >> but reads it with:
> >>
> >> offset = (u32)entry->fields[n_u64];
> >>
> >> which works on LE, but not BE.
> >
> > Ah, that makes sense. I didn't realize (or forgot) that s390 was BE. My
> > PowerPC box that was BE died years ago, and I have stopped testing BE ever
> > since :-(
>
> Ok. If you want something for testing BE i could provide you with an
> s390 linux image + the commandline to run that within qemu. Linux on
> s390 is not much different than other platforms, but you would need an
> s390 cross-compiler.
That's fine. I have you to test the BE code ;-)
> >> diff --git a/kernel/trace/trace_events_synth.c b/kernel/trace/trace_events_synth.c
> >> index d6a70aff2410..1f8fe7f2b5b2 100644
> >> --- a/kernel/trace/trace_events_synth.c
> >> +++ b/kernel/trace/trace_events_synth.c
> >> @@ -125,9 +125,22 @@ static bool synth_event_match(const char *system, const char *event,
> >> (!system || strcmp(system, SYNTH_SYSTEM) == 0);
> >> }
> >>
> >> +struct synth_trace_data {
> >> + u16 len;
> >> + u16 offset;
> >> +};
> >
> > This is actually common throughout the tracing code (as all dynamic fields
> > have this). We should probably make this more generic than just for
> > synthetic events. Although, that would probably break BE user space. Hmm,
> > we could have it be:
>
> I'm not familiar with the ftrace code, so I think i would need some more
> time to find all the other locations. Therefore i updated the patch to move
> the structure declaration to trace.h and sent that as a first step.
It's been on my todo list for sometime. Maybe I should just go and do that
part.
-- Steve
Steven Rostedt <[email protected]> writes:
>> I think the problem is that the code assigns data_offset with:
>>
>> *(u32 *)&entry->fields[*n_u64] = data_offset;
>>
>> but reads it with:
>>
>> offset = (u32)entry->fields[n_u64];
>>
>> which works on LE, but not BE.
>
> Ah, that makes sense. I didn't realize (or forgot) that s390 was BE. My
> PowerPC box that was BE died years ago, and I have stopped testing BE ever
> since :-(
Ok. If you want something for testing BE i could provide you with an
s390 linux image + the commandline to run that within qemu. Linux on
s390 is not much different than other platforms, but you would need an
s390 cross-compiler.
>>
>> I'm currently preparing the patch below, which also makes the code a bit
>> easier to read. I'm still seeing no stack traces, but at least the
>> random memory reads are gone and no KASAN warning anymore. I'll
>> continue fixing and sent a full patch as soon as everything is fixed.
>>
>> >From 82fc673f0d3b6031b760b4217bebdb1047119041 Mon Sep 17 00:00:00 2001
>> From: Sven Schnelle <[email protected]>
>> Date: Tue, 8 Aug 2023 11:35:12 +0200
>> Subject: [PATCH] tracing/synthetic: use union instead of casts
>>
>> The current code uses a lot of casts to access the fields
>> member in struct synth_trace_events with different sizes.
>> This makes the code hard to read, and had already introduced
>> an endianess bug. Use a union and struct instead.
>>
>> Signed-off-by: Sven Schnelle <[email protected]>
>> ---
>> kernel/trace/trace_events_synth.c | 100 +++++++++++++++---------------
>> 1 file changed, 50 insertions(+), 50 deletions(-)
>>
>> diff --git a/kernel/trace/trace_events_synth.c b/kernel/trace/trace_events_synth.c
>> index d6a70aff2410..1f8fe7f2b5b2 100644
>> --- a/kernel/trace/trace_events_synth.c
>> +++ b/kernel/trace/trace_events_synth.c
>> @@ -125,9 +125,22 @@ static bool synth_event_match(const char *system, const char *event,
>> (!system || strcmp(system, SYNTH_SYSTEM) == 0);
>> }
>>
>> +struct synth_trace_data {
>> + u16 len;
>> + u16 offset;
>> +};
>
> This is actually common throughout the tracing code (as all dynamic fields
> have this). We should probably make this more generic than just for
> synthetic events. Although, that would probably break BE user space. Hmm,
> we could have it be:
I'm not familiar with the ftrace code, so I think i would need some more
time to find all the other locations. Therefore i updated the patch to move
the structure declaration to trace.h and sent that as a first step.
Thanks,
Sven