| Message ID | 20220316151639.9216-1-mark-pk.tsai@mediatek.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | [v2] tracing: make tracer_init_tracefs initcall asynchronous | expand |
Greeting,
FYI, we noticed the following commit (built with gcc-9):
commit: d9a641b3f52b3dccbb3453410c097252dc991b30 ("[PATCH v2] tracing: make tracer_init_tracefs initcall asynchronous")
url: https://github.com/0day-ci/linux/commits/Mark-PK-Tsai/tracing-make-tracer_init_tracefs-initcall-asynchronous/20220316-232907
base: https://git.kernel.org/cgit/linux/kernel/git/rostedt/linux-trace.git for-next
patch link: https://lore.kernel.org/lkml/20220316151639.9216-1-mark-pk.tsai@mediatek.com
in testcase: kernel-selftests
version:
with following parameters:
group: x86
test-description: The kernel contains a set of "self tests" under the tools/testing/selftests/ directory. These are intended to be small unit tests to exercise individual code paths in the kernel.
test-url: https://www.kernel.org/doc/Documentation/kselftest.txt
on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <oliver.sang@intel.com>
[ 6.680068][ T7] WARNING: CPU: 0 PID: 7 at kernel/trace/trace.c:8899 create_trace_option_files (kernel/trace/trace.c:8899 (discriminator 1))
[ 6.681849][ T7] Modules linked in:
[ 6.682617][ T7] CPU: 0 PID: 7 Comm: kworker/u4:0 Not tainted 5.17.0-rc1-00045-gd9a641b3f52b #1
[ 6.684082][ T7] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[ 6.685625][ T7] Workqueue: eval_map_wq tracer_init_tracefs_work_func
[ 6.686823][ T7] RIP: 0010:create_trace_option_files (kernel/trace/trace.c:8899 (discriminator 1))
[ 6.687984][ T7] Code: 85 07 04 00 00 4c 8b 6d 00 49 8d bd 88 00 00 00 48 89 fa 48 c1 ea 03 80 3c 02 00 0f 85 14 04 00 00 4d 39 a5 88 00 00 00 75 bd <0f> 0b 48 83 c4 28 5b 5d 41 5c 41 5d 41 5e 41 5f c3 49 8d be 95 00
All code
========
0: 85 07 test %eax,(%rdi)
2: 04 00 add $0x0,%al
4: 00 4c 8b 6d add %cl,0x6d(%rbx,%rcx,4)
8: 00 49 8d add %cl,-0x73(%rcx)
b: bd 88 00 00 00 mov $0x88,%ebp
10: 48 89 fa mov %rdi,%rdx
13: 48 c1 ea 03 shr $0x3,%rdx
17: 80 3c 02 00 cmpb $0x0,(%rdx,%rax,1)
1b: 0f 85 14 04 00 00 jne 0x435
21: 4d 39 a5 88 00 00 00 cmp %r12,0x88(%r13)
28: 75 bd jne 0xffffffffffffffe7
2a:* 0f 0b ud2 <-- trapping instruction
2c: 48 83 c4 28 add $0x28,%rsp
30: 5b pop %rbx
31: 5d pop %rbp
32: 41 5c pop %r12
34: 41 5d pop %r13
36: 41 5e pop %r14
38: 41 5f pop %r15
3a: c3 retq
3b: 49 rex.WB
3c: 8d .byte 0x8d
3d: be .byte 0xbe
3e: 95 xchg %eax,%ebp
...
Code starting with the faulting instruction
===========================================
0: 0f 0b ud2
2: 48 83 c4 28 add $0x28,%rsp
6: 5b pop %rbx
7: 5d pop %rbp
8: 41 5c pop %r12
a: 41 5d pop %r13
c: 41 5e pop %r14
e: 41 5f pop %r15
10: c3 retq
11: 49 rex.WB
12: 8d .byte 0x8d
13: be .byte 0xbe
14: 95 xchg %eax,%ebp
...
[ 6.691102][ T7] RSP: 0000:ffffc9000007fca0 EFLAGS: 00010246
[ 6.692174][ T7] RAX: dffffc0000000000 RBX: ffffffffb48c32a0 RCX: ffff8881015f19b0
[ 6.693599][ T7] RDX: 1ffffffff6a3aa95 RSI: ffffffffb51d5420 RDI: ffffffffb51d54a8
[ 6.694906][ T7] RBP: ffff8881015f19a0 R08: 0000000000000000 R09: fffff5200000ff8b
[ 6.696329][ T7] R10: ffffffffb48d9c80 R11: fffff5200000ff8a R12: ffffffffb48d9c40
[ 6.697731][ T7] R13: ffffffffb51d5420 R14: ffffffffb51d5420 R15: ffffffffb48c4fe0
[ 6.699140][ T7] FS: 0000000000000000(0000) GS:ffff88839d400000(0000) knlGS:0000000000000000
[ 6.700616][ T7] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 6.701787][ T7] CR2: ffff88843ffff000 CR3: 000000022e02a000 CR4: 00000000000406f0
[ 6.703144][ T7] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 6.704527][ T7] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 6.705919][ T7] Call Trace:
[ 6.706584][ T7] <TASK>
[ 6.707225][ T7] __update_tracer_options (kernel/trace/trace.c:9165)
[ 6.708179][ T7] tracer_init_tracefs_work_func (kernel/trace/trace.c:9173 kernel/trace/trace.c:9750)
[ 6.709240][ T7] process_one_work (arch/x86/include/asm/jump_label.h:27 include/linux/jump_label.h:212 include/trace/events/workqueue.h:108 kernel/workqueue.c:2312)
[ 6.710149][ T7] ? rcu_read_unlock (include/linux/rcupdate.h:723 (discriminator 5))
[ 6.710965][ T7] ? pwq_dec_nr_in_flight (kernel/workqueue.c:2202)
[ 6.711845][ T7] ? rwlock_bug+0xc0/0xc0
[ 6.712746][ T7] worker_thread (include/linux/list.h:292 kernel/workqueue.c:2455)
[ 6.713581][ T7] ? process_one_work (kernel/workqueue.c:2397)
[ 6.714515][ T7] kthread (kernel/kthread.c:377)
[ 6.715295][ T7] ? kthread_complete_and_exit (kernel/kthread.c:332)
[ 6.716280][ T7] ret_from_fork (arch/x86/entry/entry_64.S:301)
[ 6.717138][ T7] </TASK>
[ 6.717735][ T7] irq event stamp: 124859
[ 6.718539][ T7] hardirqs last enabled at (124869): __up_console_sem (arch/x86/include/asm/irqflags.h:45 (discriminator 1) arch/x86/include/asm/irqflags.h:80 (discriminator 1) arch/x86/include/asm/irqflags.h:138 (discriminator 1) kernel/printk/printk.c:256 (discriminator 1))
[ 6.720206][ T7] hardirqs last disabled at (124878): __up_console_sem (kernel/printk/printk.c:254 (discriminator 1))
[ 6.721840][ T7] softirqs last enabled at (124788): __do_softirq (arch/x86/include/asm/preempt.h:27 kernel/softirq.c:402 kernel/softirq.c:587)
[ 6.723364][ T7] softirqs last disabled at (124783): irq_exit_rcu (kernel/softirq.c:432 kernel/softirq.c:637 kernel/softirq.c:649)
[ 6.724979][ T7] ---[ end trace 0000000000000000 ]---
[ 6.726173][ T1] workingset: timestamp_bits=36 max_order=22 bucket_order=0
[ 6.774762][ T1] zbud: loaded
[ 6.800913][ T1] NET: Registered PF_ALG protocol family
[ 6.802166][ T1] Key type asymmetric registered
[ 6.803072][ T1] Asymmetric key parser 'x509' registered
[ 6.804772][ T1] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 246)
[ 6.806718][ T1] io scheduler mq-deadline registered
[ 6.807676][ T1] io scheduler kyber registered
[ 6.809361][ T1] io scheduler bfq registered
[ 6.814599][ T1] start plist test
[ 6.818740][ T1] end plist test
[ 6.824385][ T1] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
[ 6.827769][ T1] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[ 6.830750][ T1] ACPI: button: Power Button [PWRF]
[ 6.834293][ T1] ERST: Error Record Serialization Table (ERST) support is disabled.
[ 6.836632][ T1] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[ 6.838612][ T1] 00:05: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
[ 6.841619][ T1] 00:06: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A
[ 6.848597][ T1] Non-volatile memory driver v1.3
[ 6.850317][ T1] ACPI: bus type drm_connector registered
[ 6.855914][ T1] [drm] Initialized vgem 1.0.0 20120112 for vgem on minor 0
[ 6.860431][ T1] lkdtm: No crash points registered, enable through debugfs
[ 6.862903][ T1] rdac: device handler registered
[ 6.864119][ T1] hp_sw: device handler registered
[ 6.864878][ T1] emc: device handler registered
[ 6.865969][ T1] alua: device handler registered
[ 6.868290][ T1] MACsec IEEE 802.1AE
[ 6.888321][ T1] e1000: Intel(R) PRO/1000 Network Driver
[ 6.889199][ T1] e1000: Copyright (c) 1999-2006 Intel Corporation.
[ 9.899751][ T1] ACPI: _SB_.LNKC: Enabled at IRQ 11
[ 10.248679][ T1] e1000 0000:00:03.0 eth0: (PCI:33MHz:32-bit) 52:54:00:12:34:56
[ 10.249979][ T1] e1000 0000:00:03.0 eth0: Intel(R) PRO/1000 Network Connection
[ 10.251663][ T1] e1000e: Intel(R) PRO/1000 Network Driver
[ 10.252560][ T1] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
[ 10.253704][ T1] igb: Intel(R) Gigabit Ethernet Network Driver
[ 10.254590][ T1] igb: Copyright (c) 2007-2014 Intel Corporation.
[ 10.255679][ T1] Intel(R) 2.5G Ethernet Linux Driver
[ 10.256490][ T1] Copyright(c) 2018 Intel Corporation.
[ 10.257487][ T1] ixgbe: Intel(R) 10 Gigabit PCI Express Network Driver
[ 10.258453][ T1] ixgbe: Copyright (c) 1999-2016 Intel Corporation.
[ 10.260030][ T1] i40e: Intel(R) Ethernet Connection XL710 Network Driver
[ 10.261032][ T1] i40e: Copyright (c) 2013 - 2019 Intel Corporation.
[ 10.262658][ T1] usbcore: registered new interface driver r8152
[ 10.263698][ T1] usbcore: registered new interface driver asix
[ 10.264701][ T1] usbcore: registered new interface driver ax88179_178a
[ 10.266354][ T1] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[ 10.267553][ T1] ehci-pci: EHCI PCI platform driver
[ 10.268472][ T1] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[ 10.269469][ T1] ohci-pci: OHCI PCI platform driver
[ 10.270370][ T1] uhci_hcd: USB Universal Host Controller Interface driver
[ 10.272815][ T1] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
[ 10.275761][ T1] serio: i8042 KBD port at 0x60,0x64 irq 1
[ 10.276724][ T1] serio: i8042 AUX port at 0x60,0x64 irq 12
[ 10.279463][ T1] mousedev: PS/2 mouse device common for all mice
[ 10.283203][ T11] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1
[ 10.288340][ T1] rtc_cmos 00:00: RTC can wake from S4
[ 10.292983][ T11] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4
[ 10.296611][ T11] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3
[ 10.300314][ T1] rtc_cmos 00:00: registered as rtc0
[ 10.301334][ T1] rtc_cmos 00:00: setting system clock to 2022-03-21T05:29:11 UTC (1647840551)
[ 10.303017][ T1] rtc_cmos 00:00: alarms up to one day, y3k, 114 bytes nvram, hpet irqs
[ 10.307878][ T1] i6300ESB timer 0000:00:04.0: initialized. heartbeat=30 sec (nowayout=0)
[ 10.309393][ T1] iTCO_vendor_support: vendor-support=0
[ 10.310199][ T1] intel_pstate: CPU model not supported
[ 10.336704][ T1] hid: raw HID events driver (C) Jiri Kosina
[ 10.338307][ T1] usbcore: registered new interface driver usbhid
[ 10.339269][ T1] usbhid: USB HID core driver
[ 10.340100][ T1] drop_monitor: Initializing network drop monitor service
[ 10.341379][ T1] netem: version 1.3
[ 10.342269][ T1] ipip: IPv4 and MPLS over IPv4 tunneling driver
To reproduce:
# build kernel
cd linux
cp config-5.17.0-rc1-00045-gd9a641b3f52b .config
make HOSTCC=gcc-9 CC=gcc-9 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage modules
make HOSTCC=gcc-9 CC=gcc-9 ARCH=x86_64 INSTALL_MOD_PATH=<mod-install-dir> modules_install
cd <mod-install-dir>
find lib/ | cpio -o -H newc --quiet | gzip > modules.cgz
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> -m modules.cgz job-script # job-script is attached in this email
# if come across any failure that blocks the test,
# please remove ~/.lkp and /lkp dir to run from a clean state.
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index eb44418574f9..adb37e437a05 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -9564,6 +9564,7 @@ extern struct trace_eval_map *__stop_ftrace_eval_maps[]; static struct workqueue_struct *eval_map_wq __initdata; static struct work_struct eval_map_work __initdata; +static struct work_struct tracerfs_init_work __initdata; static void __init eval_map_work_func(struct work_struct *work) { @@ -9589,6 +9590,8 @@ static int __init trace_eval_init(void) return 0; } +subsys_initcall(trace_eval_init); + static int __init trace_eval_sync(void) { /* Make sure the eval map updates are finished */ @@ -9671,15 +9674,8 @@ static struct notifier_block trace_module_nb = { }; #endif /* CONFIG_MODULES */ -static __init int tracer_init_tracefs(void) +static __init void tracer_init_tracefs_work_func(struct work_struct *work) { - int ret; - - trace_access_lock_init(); - - ret = tracing_init_dentry(); - if (ret) - return 0; event_trace_init(); @@ -9701,8 +9697,6 @@ static __init int tracer_init_tracefs(void) trace_create_file("saved_tgids", TRACE_MODE_READ, NULL, NULL, &tracing_saved_tgids_fops); - trace_eval_init(); - trace_create_eval_file(NULL); #ifdef CONFIG_MODULES @@ -9717,6 +9711,23 @@ static __init int tracer_init_tracefs(void) create_trace_instances(NULL); update_tracer_options(&global_trace); +} + +static __init int tracer_init_tracefs(void) +{ + int ret; + + trace_access_lock_init(); + + ret = tracing_init_dentry(); + if (ret) + return 0; + + INIT_WORK(&tracerfs_init_work, tracer_init_tracefs_work_func); + if (!eval_map_wq) + tracer_init_tracefs_work_func(&tracerfs_init_work); + else + queue_work(eval_map_wq, &tracerfs_init_work); return 0; }
Move trace_eval_init() to subsys_initcall to make it start earlier. And to avoid tracer_init_tracefs being blocked by trace_event_sem which trace_eval_init() hold [1], queue tracer_init_tracefs() to eval_map_wq to let the two works being executed sequentially. It can speed up the initialization of kernel as result of making tracer_init_tracefs asynchronous. On my arm64 platform, it reduce ~20ms of 125ms which total time do_initcalls spend. [1]: https://lore.kernel.org/r/68d7b3327052757d0cd6359a6c9015a85b437232.camel@pengutronix.de Signed-off-by: Mark-PK Tsai <mark-pk.tsai@mediatek.com> --- kernel/trace/trace.c | 31 +++++++++++++++++++++---------- 1 file changed, 21 insertions(+), 10 deletions(-)