diff mbox series

[v2] tracing: make tracer_init_tracefs initcall asynchronous

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

Commit Message

Mark-PK Tsai (蔡沛剛) March 16, 2022, 3:16 p.m. UTC
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(-)

Comments

kernel test robot March 22, 2022, 1:33 p.m. UTC | #1
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 mbox series

Patch

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;
 }