2022-03-14 12:13:52

by kernel test robot

[permalink] [raw]
Subject: [tracing] 134c5fb991: WARNING:at_kernel/trace/trace.c:#create_trace_option_files



Greeting,

FYI, we noticed the following commit (built with gcc-9):

commit: 134c5fb991a16bf28b500e8e52296447013b5b01 ("[PATCH] 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/20220311-192857
base: https://git.kernel.org/cgit/linux/kernel/git/rostedt/linux-trace.git for-next
patch link: https://lore.kernel.org/lkml/[email protected]

in testcase: kernel-selftests
version: kernel-selftests-x86_64-8acb5247-1_20220312
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 <[email protected]>


[ 3.345705][ T42] WARNING: CPU: 0 PID: 42 at kernel/trace/trace.c:8889 create_trace_option_files (kernel/trace/trace.c:8889 (discriminator 1))
[ 3.346803][ T42] Modules linked in:
[ 3.347251][ T42] CPU: 0 PID: 42 Comm: tracefs_init Not tainted 5.17.0-rc1-00033-g134c5fb991a1 #1
[ 3.348231][ T42] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[ 3.349240][ T42] RIP: 0010:create_trace_option_files (kernel/trace/trace.c:8889 (discriminator 1))
[ 3.349928][ T42] 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
...
[ 3.351870][ T42] RSP: 0000:ffffc900004c7e58 EFLAGS: 00010246
[ 3.352531][ T42] RAX: dffffc0000000000 RBX: ffffffff980c32e0 RCX: ffff888102b86570
[ 3.353398][ T42] RDX: 1ffffffff313aa95 RSI: ffffffff989d5420 RDI: ffffffff989d54a8
[ 3.354260][ T42] RBP: ffff888102b86560 R08: 0000000000000000 R09: fffff52000098fc3
[ 3.355118][ T42] R10: ffffffff980d9c80 R11: fffff52000098fc2 R12: ffffffff980d9c40
[ 3.356060][ T42] R13: ffffffff989d5420 R14: ffffffff989d5420 R15: ffffffff980c5020
[ 3.357211][ T42] FS: 0000000000000000(0000) GS:ffff88839d400000(0000) knlGS:0000000000000000
[ 3.358179][ T42] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 3.358924][ T42] CR2: ffff88843ffff000 CR3: 00000002f0c2a000 CR4: 00000000000406f0
[ 3.359951][ T42] Call Trace:
[ 3.360347][ T42] <TASK>
[ 3.360753][ T42] __update_tracer_options (kernel/trace/trace.c:9155)
[ 3.361340][ T42] tracefs_init (kernel/trace/trace.c:9163 kernel/trace/trace.c:9746 kernel/trace/trace.c:9701)
[ 3.361856][ T42] ? tracing_init_dentry (kernel/trace/trace.c:9702)
[ 3.362490][ T42] kthread (kernel/kthread.c:377)
[ 3.363103][ T42] ? kthread_complete_and_exit (kernel/kthread.c:332)
[ 3.363862][ T42] ret_from_fork (arch/x86/entry/entry_64.S:301)
[ 3.364446][ T42] </TASK>
[ 3.365042][ T42] irq event stamp: 118271
[ 3.365528][ T42] hardirqs last enabled at (118279): __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))
[ 3.366719][ T42] hardirqs last disabled at (118288): __up_console_sem (kernel/printk/printk.c:254 (discriminator 1))
[ 3.367981][ T42] softirqs last enabled at (118146): __do_softirq (arch/x86/include/asm/preempt.h:27 kernel/softirq.c:402 kernel/softirq.c:587)
[ 3.370490][ T42] softirqs last disabled at (118135): irq_exit_rcu (kernel/softirq.c:432 kernel/softirq.c:637 kernel/softirq.c:649)
[ 3.371756][ T42] ---[ end trace 0000000000000000 ]---
[ 3.372515][ T1] workingset: timestamp_bits=36 max_order=22 bucket_order=0
[ 3.473476][ T1] zbud: loaded
[ 3.505848][ T1] NET: Registered PF_ALG protocol family
[ 3.507112][ T1] Key type asymmetric registered
[ 3.508059][ T1] Asymmetric key parser 'x509' registered
[ 3.509814][ T1] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 246)
[ 3.511840][ T1] io scheduler mq-deadline registered
[ 3.512883][ T1] io scheduler kyber registered
[ 3.514716][ T1] io scheduler bfq registered
[ 3.522095][ T1] start plist test
[ 3.525843][ T1] end plist test
[ 3.527448][ T1] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
[ 3.530903][ T1] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[ 3.535139][ T1] ACPI: button: Power Button [PWRF]
[ 3.539880][ T1] ERST: Error Record Serialization Table (ERST) support is disabled.
[ 3.543113][ T1] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[ 3.545264][ T1] 00:05: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
[ 3.548346][ T1] 00:06: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A
[ 3.555173][ T1] Non-volatile memory driver v1.3
[ 3.556965][ T1] ACPI: bus type drm_connector registered
[ 3.563314][ T1] [drm] Initialized vgem 1.0.0 20120112 for vgem on minor 0
[ 3.571831][ T1] lkdtm: No crash points registered, enable through debugfs
[ 3.576236][ T1] rdac: device handler registered
[ 3.578716][ T1] hp_sw: device handler registered
[ 3.579453][ T1] emc: device handler registered
[ 3.582735][ T1] alua: device handler registered
[ 3.585356][ T1] MACsec IEEE 802.1AE
[ 3.597181][ T1] e1000: Intel(R) PRO/1000 Network Driver
[ 3.598099][ T1] e1000: Copyright (c) 1999-2006 Intel Corporation.
[ 6.762061][ T1] ACPI: _SB_.LNKC: Enabled at IRQ 11
[ 7.128556][ T1] e1000 0000:00:03.0 eth0: (PCI:33MHz:32-bit) 52:54:00:12:34:56
[ 7.130015][ T1] e1000 0000:00:03.0 eth0: Intel(R) PRO/1000 Network Connection
[ 7.131545][ T1] e1000e: Intel(R) PRO/1000 Network Driver
[ 7.132384][ T1] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
[ 7.133564][ T1] igb: Intel(R) Gigabit Ethernet Network Driver
[ 7.134422][ T1] igb: Copyright (c) 2007-2014 Intel Corporation.
[ 7.135446][ T1] Intel(R) 2.5G Ethernet Linux Driver
[ 7.136217][ T1] Copyright(c) 2018 Intel Corporation.
[ 7.137229][ T1] ixgbe: Intel(R) 10 Gigabit PCI Express Network Driver
[ 7.138160][ T1] ixgbe: Copyright (c) 1999-2016 Intel Corporation.
[ 7.139824][ T1] i40e: Intel(R) Ethernet Connection XL710 Network Driver
[ 7.140818][ T1] i40e: Copyright (c) 2013 - 2019 Intel Corporation.
[ 7.142562][ T1] usbcore: registered new interface driver r8152
[ 7.143673][ T1] usbcore: registered new interface driver asix
[ 7.144715][ T1] usbcore: registered new interface driver ax88179_178a
[ 7.146561][ T1] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[ 7.147701][ T1] ehci-pci: EHCI PCI platform driver
[ 7.148634][ T1] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[ 7.149576][ T1] ohci-pci: OHCI PCI platform driver
[ 7.150499][ T1] uhci_hcd: USB Universal Host Controller Interface driver
[ 7.153020][ T1] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
[ 7.156079][ T1] serio: i8042 KBD port at 0x60,0x64 irq 1
[ 7.157042][ T1] serio: i8042 AUX port at 0x60,0x64 irq 12
[ 7.160033][ T1] mousedev: PS/2 mouse device common for all mice
[ 7.163415][ T23] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1
[ 7.168882][ T1] rtc_cmos 00:00: RTC can wake from S4
[ 7.172266][ T23] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4
[ 7.175034][ T1] rtc_cmos 00:00: registered as rtc0
[ 7.175586][ T1] rtc_cmos 00:00: setting system clock to 2022-03-12T23:35:44 UTC (1647128144)
[ 7.176582][ T1] rtc_cmos 00:00: alarms up to one day, y3k, 114 bytes nvram, hpet irqs
[ 7.178674][ T23] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3
[ 7.180707][ T1] i6300ESB timer 0000:00:04.0: initialized. heartbeat=30 sec (nowayout=0)
[ 7.181571][ T1] iTCO_vendor_support: vendor-support=0
[ 7.182041][ T1] intel_pstate: CPU model not supported
[ 7.185209][ T1] hid: raw HID events driver (C) Jiri Kosina
[ 7.186074][ T1] usbcore: registered new interface driver usbhid
[ 7.186677][ T1] usbhid: USB HID core driver
[ 7.187795][ T1] drop_monitor: Initializing network drop monitor service
[ 7.188509][ T1] netem: version 1.3
[ 7.189326][ T1] ipip: IPv4 and MPLS over IPv4 tunneling driver
[ 7.191025][ T1] gre: GRE over IPv4 demultiplexor driver
[ 7.191493][ T1] ip_gre: GRE over IPv4 tunneling driver
[ 7.195722][ T1] Initializing XFRM netlink socket
[ 7.199139][ T1] NET: Registered PF_INET6 protocol family
[ 7.203421][ T1] Segment Routing with IPv6
[ 7.203906][ T1] In-situ OAM (IOAM) with IPv6
[ 7.205637][ T1] ip6_gre: GRE over IPv6 tunneling driver
[ 7.207526][ T1] NET: Registered PF_PACKET protocol family


To reproduce:

# build kernel
cd linux
cp config-5.17.0-rc1-00033-g134c5fb991a1 .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.



---
0-DAY CI Kernel Test Service
https://lists.01.org/hyperkitty/list/[email protected]

Thanks,
Oliver Sang


Attachments:
(No filename) (11.77 kB)
config-5.17.0-rc1-00033-g134c5fb991a1 (168.49 kB)
job-script (5.23 kB)
dmesg.xz (41.76 kB)
kernel-selftests (136.92 kB)
Download all attachments