Message-ID: <20201203071955.GG27350@xsang-OptiPlex-9020>
Date:   Thu, 3 Dec 2020 15:19:55 +0800
From:   kernel test robot <oliver.sang@...el.com>
To:     Fox Chen <foxhlchen@...il.com>
Cc:     0day robot <lkp@...el.com>, LKML <linux-kernel@...r.kernel.org>,
        lkp@...ts.01.org, gregkh@...uxfoundation.org, tj@...nel.org,
        Fox Chen <foxhlchen@...il.com>
Subject: [kernfs]  d680236464:
 BUG:sleeping_function_called_from_invalid_context_at_kernel/locking/mutex.c


Greeting,

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

commit: d68023646451afd98ee33de9cb41b3d05b18079e ("[PATCH 1/2] kernfs: replace the mutex in kernfs_iop_permission with a rwlock")
url: https://github.com/0day-ci/linux/commits/Fox-Chen/kernfs-speed-up-concurrency-performance/20201202-230540
base: https://git.kernel.org/cgit/linux/kernel/git/gregkh/driver-core.git 33c0c9bdf7a59051a654cd98b7d2b48ce0080967

in testcase: locktorture
version: 
with following parameters:

	runtime: 300s
	test: default

test-description: This torture test consists of creating a number of kernel threads which acquire the lock and hold it for specific amount of time, thus simulating different critical region behaviors.
test-url: https://www.kernel.org/doc/Documentation/locking/locktorture.txt


on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 8G

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):


+-----------------------------------------------------------------------------+------------+------------+
|                                                                             | 33c0c9bdf7 | d680236464 |
+-----------------------------------------------------------------------------+------------+------------+
| BUG:sleeping_function_called_from_invalid_context_at_kernel/locking/mutex.c | 0          | 14         |
+-----------------------------------------------------------------------------+------------+------------+


If you fix the issue, kindly add following tag
Reported-by: kernel test robot <oliver.sang@...el.com>


[   35.659582] BUG: sleeping function called from invalid context at kernel/locking/mutex.c:281
[   35.661442] in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 202, name: systemd-udevd
[   35.663290] CPU: 0 PID: 202 Comm: systemd-udevd Not tainted 5.10.0-rc3-00004-gd68023646451 #1
[   35.665081] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[   35.666841] Call Trace:
[   35.667521]  dump_stack+0xa6/0xe0
[   35.668315]  ___might_sleep.cold+0x97/0xba
[   35.669237]  __might_sleep+0x5c/0x110
[   35.670086]  mutex_lock+0x18/0xc0
[   35.670872]  __kernfs_iattrs+0x14/0xd0
[   35.671853]  __kernfs_setattr+0x19/0x160
[   35.672751]  kernfs_iop_setattr+0x70/0xb0
[   35.673663]  notify_change+0x450/0x8b0
[   35.674523]  ? kernfs_xattr_get+0x13/0x50
[   35.675454]  ? __vfs_getxattr+0x68/0xb0
[   35.676332]  do_truncate+0x86/0xf0
[   35.677142]  ? do_truncate+0x86/0xf0
[   35.677996]  do_open+0x178/0x560
[   35.678878]  path_openat+0x152/0x3b0
[   35.679771]  ? trace_hardirqs_on+0x97/0x2a0
[   35.680720]  do_filp_open+0x64/0x110
[   35.681564]  ? __alloc_fd+0x78/0x230
[   35.682389]  do_sys_openat2+0x99/0x210
[   35.683264]  ? perf_reg_value+0x46/0x180
[   35.684133]  do_sys_open+0x5f/0xa0
[   35.684900]  arch_crash_save_vmcoreinfo+0x10/0x10
[   35.685891]  __do_fast_syscall_32+0x82/0xd0
[   35.686785]  do_fast_syscall_32+0x29/0x90
[   35.687685]  do_SYSENTER_32+0x15/0x20
[   35.688500]  entry_SYSENTER_32+0x98/0xe7
[   35.689364] EIP: 0xb7f1d549
[   35.690041] Code: 03 74 c0 01 10 05 03 74 b8 01 10 06 03 74 b4 01 10 07 03 74 b0 01 10 08 03 74 d8 01 00 00 00 00 00 51 52 55 89 e5 0f 34 cd 80 <5d> 5a 59 c3 90 90 90 90 8d b4 26 00 00 00 00 8d b4 26 00 00 00 00
[   35.693543] EAX: ffffffda EBX: bfcf27ec ECX: 00088241 EDX: 000001b6
[   35.694792] ESI: 0141bff8 EDI: 00000004 EBP: b7e28000 ESP: bfcf2228
[   35.696055] DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b EFLAGS: 00000246
[   35.770526] evbug: Connected device: input0 (Power Button at LNXPWRBN/button/input0)
[   35.772390] evbug: Connected device: input1 (AT Translated Set 2 keyboard at isa0060/serio0/input0)
[   35.774296] evbug: Connected device: input4 (VirtualPS/2 VMware VMMouse at isa0060/serio1/input1)
[   35.776239] evbug: Connected device: input3 (VirtualPS/2 VMware VMMouse at isa0060/serio1/input0)
[  OK  ] Started udev Coldplug all Devices.
[  OK  ] Reached target System Initialization.
[  OK  ] Started Daily apt download activities.
[  OK  ] Started Daily apt upgrade and clean activities.
[  OK  ] Started Daily Cleanup of Temporary Directories.
[  OK  ] Reached target Timers.
[  OK  ] Listening on D-Bus System Message Bus Socket.
[  OK  ] Reached target Sockets.
[  OK  ] Reached target Basic System.
         Starting OpenBSD Secure Shell server...
[   35.851011] parport_pc 00:04: reported by Plug and Play ACPI
         Starting System Logging Service...
[   35.869761] parport0: PC-style at 0x378, irq 7 [PCSPP,TRISTATE]
[   35.881349] rtc_cmos 00:00: RTC can wake from S4
[   35.883846] rtc rtc0: alarm rollover: day
[   35.885853] rtc_cmos 00:00: char device (0:0)
[   35.885870] rtc_cmos 00:00: registered as rtc0
[   35.886019] rtc_cmos 00:00: setting system clock to 2020-12-03T09:25:59 UTC (1606987559)
[   35.886029] rtc_cmos 00:00: alarms up to one day, y3k, 114 bytes nvram, hpet irqs
[  OK  ] Started Regular background program processing daemon.
         Starting LSB: Start and stop bmc-watchdog...
         Startin
[   35.982201] mousedev: PS/2 mouse device common for all mice
g LSB: Execute the kexec -e command to reboot system...
         Starting Permit User Sessions...
         Starting Login Service...
[  OK  ] Started D-Bus System Message Bus.
[   36.235403] _warn_unseeded_randomness: 189 callbacks suppressed
[   36.235418] random: get_random_u32 called from allocate_slab+0x18a/0x6c0 with crng_init=1
[   36.241003] random: get_random_u32 called from arch_rnd+0x34/0x50 with crng_init=1
[   36.241012] random: get_random_u32 called from randomize_stack_top+0x3c/0x60 with crng_init=1
         Starting /etc/rc.local Compatibility...
         Starting LKP bootstrap...
[  OK  ] Started System Logging Service.
[  OK  ] Started Permit User Sessions.
[   36.221829] rc.local[254]: mkdir: cannot create directory '/var/lock/lkp-bootstrap.lock': File exists
[   36.417574] ppdev: user-space parallel port driver
[  OK  ] Started LKP bootstrap.
[  OK  ] Started OpenBSD Secure Shell server.
[  OK  ] Started LSB: Execute the kexec -e command to reboot system.
[  OK  ] Started LSB: Start and stop bmc-watchdog.
[  OK  ] Started Login Service.
         Starting LSB: Load kernel image with kexec...
         Starting Daily apt download activities...
[  OK  ] Started LSB: Load kernel image with kexec.
LKP: HOSTNAME vm-snb-32, MAC 52:54:00:12:34:56, kernel 5.10.0-rc3-00004-gd68023646451 1, serial console /dev/ttyS0
[   37.240457] _warn_unseeded_randomness: 496 callbacks suppressed
[   37.240505] random: get_random_u32 called from arch_rnd+0x34/0x50 with crng_init=1
[   37.240524] random: get_random_u32 called from randomize_stack_top+0x3c/0x60 with crng_init=1
[   37.240531] random: get_random_u32 called from arch_align_stack+0x3c/0x50 with crng_init=1
[  OK  ] Started Daily apt download activities.
         Starting Daily apt upgrade and clean activities...
[   38.263709] _warn_unseeded_randomness: 418 callbacks suppressed
[   38.263722] random: get_random_u32 called from arch_rnd+0x34/0x50 with crng_init=1
[   38.263733] random: get_random_u32 called from randomize_stack_top+0x3c/0x60 with crng_init=1
[   38.263740] random: get_random_u32 called from arch_align_stack+0x3c/0x50 with crng_init=1
[  OK  ] Started Daily apt upgrade and clean activities.
[   39.277035] _warn_unseeded_randomness: 327 callbacks suppressed
[   39.277049] random: get_random_u32 called from randomize_stack_top+0x3c/0x60 with crng_init=1
[   39.277058] random: get_random_u32 called from arch_align_stack+0x3c/0x50 with crng_init=1
[   39.277084] random: get_random_u32 called from arch_rnd+0x34/0x50 with crng_init=1
[   40.431858] _warn_unseeded_randomness: 218 callbacks suppressed


To reproduce:

        # build kernel
	cd linux
	cp config-5.10.0-rc3-00004-gd68023646451 .config
	make HOSTCC=gcc-9 CC=gcc-9 ARCH=i386 olddefconfig prepare modules_prepare bzImage modules
	make HOSTCC=gcc-9 CC=gcc-9 ARCH=i386 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



Thanks,
Oliver Sang


View attachment "config-5.10.0-rc3-00004-gd68023646451" of type "text/plain" (129135 bytes)

View attachment "job-script" of type "text/plain" (4489 bytes)

Download attachment "dmesg.xz" of type "application/x-xz" (16012 bytes)

Powered by blists - more mailing lists