| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <20170515074200.GA66485@inn.lkp.intel.com>
Date: Mon, 15 May 2017 15:42:00 +0800
From: kernel test robot <xiaolong.ye@...el.com>
To: Steven Rostedt <rostedt@...dmis.org>
Cc: LKML <linux-kernel@...r.kernel.org>,
Steven Rostedt <rostedt@...dmis.org>, lkp@...org
Subject: [perf] ddb06e08fa: INFO:possible_recursive_locking_detected
FYI, we noticed the following commit:
commit: ddb06e08fa10ed5030285267a9b1e25d40c337c8 ("perf: Grab event_mutex before taking get_online_cpus()")
https://git.kernel.org/cgit/linux/kernel/git/rostedt/linux-trace.git tip/cpuhotplug
in testcase: trinity
with following parameters:
runtime: 300s
test-description: Trinity is a linux system call fuzz tester.
test-url: http://codemonkey.org.uk/projects/trinity/
on test machine: qemu-system-x86_64 -enable-kvm -cpu Westmere -m 512M
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+-----------------------------------------------------------------------------------------------------+------------+------------+
| | db4d3deeb5 | ddb06e08fa |
+-----------------------------------------------------------------------------------------------------+------------+------------+
| boot_successes | 0 | 1 |
| boot_failures | 2 | 16 |
| invoked_oom-killer:gfp_mask=0x | 2 | |
| Mem-Info | 2 | |
| Out_of_memory:Kill_process | 2 | |
| page_allocation_failure:order:#,mode:#(GFP_KERNEL_ACCOUNT|__GFP_ZERO|__GFP_NOTRACK),nodemask=(null) | 2 | |
| page_allocation_failure:order:#,mode:#(GFP_KERNEL|__GFP_COMP|__GFP_NOTRACK),nodemask=(null) | 1 | |
| Kernel_panic-not_syncing:Out_of_memory_and_no_killable_processes | 1 | |
| INFO:possible_recursive_locking_detected | 0 | 16 |
| calltrace:SyS_perf_event_open | 0 | 16 |
| INFO:task_blocked_for_more_than#seconds | 0 | 16 |
| INFO:lockdep_is_turned_off | 0 | 16 |
| Kernel_panic-not_syncing:hung_task:blocked_tasks | 0 | 16 |
+-----------------------------------------------------------------------------------------------------+------------+------------+
[ 21.793133] [ INFO: possible recursive locking detected ]
[ 21.794139] 4.11.0-07685-gddb06e0 #1 Not tainted
[ 21.795057] ---------------------------------------------
[ 21.796115] trinity-main/2199 is trying to acquire lock:
[ 21.797136] (event_mutex){+.+.+.}, at: [<ffffffff9c1a4be1>] SyS_perf_event_open+0xb13/0xe0e
[ 21.798848]
[ 21.798848] but task is already holding lock:
[ 21.800353] (event_mutex){+.+.+.}, at: [<ffffffff9c1a4613>] SyS_perf_event_open+0x545/0xe0e
[ 21.802157]
[ 21.802157] other info that might help us debug this:
[ 21.803713] Possible unsafe locking scenario:
[ 21.803713]
[ 21.805310] CPU0
[ 21.806041] ----
[ 21.806760] lock(event_mutex);
[ 21.807563] lock(event_mutex);
[ 21.808424]
[ 21.808424] *** DEADLOCK ***
[ 21.808424]
[ 21.810301] May be due to missing lock nesting notation
[ 21.810301]
[ 21.811959] 1 lock held by trinity-main/2199:
[ 21.813040] #0: (event_mutex){+.+.+.}, at: [<ffffffff9c1a4613>] SyS_perf_event_open+0x545/0xe0e
[ 21.814896]
[ 21.814896] stack backtrace:
[ 21.816338] CPU: 0 PID: 2199 Comm: trinity-main Not tainted 4.11.0-07685-gddb06e0 #1
[ 21.817983] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-20161025_171302-gandalf 04/01/2014
[ 21.819938] Call Trace:
[ 21.820740] dump_stack+0x86/0xc0
[ 21.821555] __lock_acquire+0x86b/0xe43
[ 21.822396] lock_acquire+0x142/0x1dd
[ 21.823258] ? SyS_perf_event_open+0xb13/0xe0e
[ 21.824238] __mutex_lock+0x8a/0x815
[ 21.825120] ? SyS_perf_event_open+0xb13/0xe0e
[ 21.826105] ? __lock_acquire+0xd44/0xe43
[ 21.826960] ? SyS_perf_event_open+0xb13/0xe0e
[ 21.827914] ? kvm_sched_clock_read+0x9/0x12
[ 21.828852] ? SyS_perf_event_open+0xb05/0xe0e
[ 21.829795] mutex_lock_nested+0x1b/0x1d
[ 21.830713] ? mutex_lock_nested+0x1b/0x1d
[ 21.831672] SyS_perf_event_open+0xb13/0xe0e
[ 21.832789] do_int80_syscall_32+0x66/0x113
[ 21.833801] entry_INT80_compat+0x38/0x50
[ 21.834730] RIP: 0023:0x8090aa2
[ 21.835690] RSP: 002b:00000000ffd91718 EFLAGS: 00000282 ORIG_RAX: 0000000000000150
[ 21.837569] RAX: ffffffffffffffda RBX: 0000000008b46258 RCX: 00000000ffffffff
[ 21.838823] RDX: 00000000ffffffff RSI: 00000000ffffffff RDI: 0000000000000000
[ 21.840184] RBP: 000000006d656d0c R08: 0000000000000000 R09: 0000000000000000
[ 21.841573] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[ 21.842948] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 246.812621] INFO: task trinity-main:2199 blocked for more than 120 seconds.
[ 246.814685] Not tainted 4.11.0-07685-gddb06e0 #1
[ 246.816679] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 246.819759] trinity-main D12856 2199 2196 0x20020000
[ 246.821837] Call Trace:
[ 246.823075] __schedule+0x8cd/0xa60
[ 246.824563] schedule+0x89/0x9a
[ 246.825840] schedule_preempt_disabled+0x15/0x1e
[ 246.827417] __mutex_lock+0x595/0x815
[ 246.832245] ? __lock_acquire+0xd44/0xe43
[ 246.833692] ? SyS_perf_event_open+0xb13/0xe0e
[ 246.835159] mutex_lock_nested+0x1b/0x1d
[ 246.836516] ? mutex_lock_nested+0x1b/0x1d
[ 246.837905] SyS_perf_event_open+0xb13/0xe0e
[ 246.839346] do_int80_syscall_32+0x66/0x113
[ 246.840747] entry_INT80_compat+0x38/0x50
[ 246.842185] RIP: 0023:0x8090aa2
[ 246.843460] RSP: 002b:00000000ffd91718 EFLAGS: 00000282 ORIG_RAX: 0000000000000150
[ 246.846051] RAX: ffffffffffffffda RBX: 0000000008b46258 RCX: 00000000ffffffff
[ 246.847941] RDX: 00000000ffffffff RSI: 00000000ffffffff RDI: 0000000000000000
[ 246.849835] RBP: 000000006d656d0c R08: 0000000000000000 R09: 0000000000000000
[ 246.851757] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[ 246.853668] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 246.855639] INFO: lockdep is turned off.
[ 246.857038] NMI backtrace for cpu 0
[ 246.858324] CPU: 0 PID: 642 Comm: khungtaskd Not tainted 4.11.0-07685-gddb06e0 #1
[ 246.860829] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-20161025_171302-gandalf 04/01/2014
[ 246.863767] Call Trace:
[ 246.864863] dump_stack+0x86/0xc0
[ 246.866310] nmi_cpu_backtrace+0x7f/0x9c
[ 246.867641] ? irq_force_complete_move+0xeb/0xeb
[ 246.869144] nmi_trigger_cpumask_backtrace+0x62/0xc6
[ 246.870701] arch_trigger_cpumask_backtrace+0x19/0x1b
[ 246.872273] watchdog+0x46f/0x538
[ 246.873497] ? reset_hung_task_detector+0x15/0x15
[ 246.874953] kthread+0x134/0x13c
[ 246.876174] ? kthread_create_on_node+0x3f/0x3f
[ 246.877605] ret_from_fork+0x31/0x40
[ 246.878918] Kernel panic - not syncing: hung_task: blocked tasks
[ 246.880620] CPU: 0 PID: 642 Comm: khungtaskd Not tainted 4.11.0-07685-gddb06e0 #1
[ 246.883126] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-20161025_171302-gandalf 04/01/2014
[ 246.886076] Call Trace:
[ 246.887174] dump_stack+0x86/0xc0
[ 246.888404] panic+0xdd/0x221
[ 246.889614] watchdog+0x47b/0x538
[ 246.890891] ? reset_hung_task_detector+0x15/0x15
[ 246.892398] kthread+0x134/0x13c
[ 246.893606] ? kthread_create_on_node+0x3f/0x3f
[ 246.895029] ret_from_fork+0x31/0x40
[ 246.896365] Kernel Offset: 0x1b000000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
Elapsed time: 250
initrds=(
/osimage/yocto/yocto-tiny-i386-2016-04-22.cgz
/lkp/scheduled/vm-kbuild-yocto-ia32-4/trinity-300s-yocto-tiny-i386-2016-04-22.cgz-ddb06e08fa10ed5030285267a9b1e25d40c337c8-20170515-76824-r0qdn3-0.cgz
/lkp/lkp/lkp-i386.cgz
/osimage/deps/debian-x86_64-2016-08-31.cgz/run-ipconfig.i386_2016-09-03.cgz
/osimage/pkg/static/trinity-i386.cgz
/pkg/linux/x86_64-nfsroot+CONFIG_DEBUG_INFO_REDUCED/gcc-6/ddb06e08fa10ed5030285267a9b1e25d40c337c8/modules.cgz
)
cat "${initrds[@]}" > /fs/sdd1/initrd-vm-kbuild-yocto-ia32-4
kvm=(
qemu-system-x86_64
-enable-kvm
-cpu Westmere
-kernel /pkg/linux/x86_64-nfsroot+CONFIG_DEBUG_INFO_REDUCED/gcc-6/ddb06e08fa10ed5030285267a9b1e25d40c337c8/vmlinuz-4.11.0-07685-gddb06e0
-initrd /fs/sdd1/initrd-vm-kbuild-yocto-ia32-4
-m 512
-smp 1
-device e1000,netdev=net0
-netdev user,id=net0
-boot order=nc
-no-reboot
-watchdog i6300esb
-watchdog-action debug
-rtc base=localtime
-drive file=/fs/sdd1/disk0-vm-kbuild-yocto-ia32-4,media=disk,if=virtio
-pidfile /dev/shm/kboot/pid-vm-kbuild-yocto-ia32-4
-serial file:/dev/shm/kboot/vm-kbuild-yocto-ia32-4/serial
-serial file:/dev/shm/kboot/vm-kbuild-yocto-ia32-4/kmsg
-daemonize
-display none
-monitor null
)
append=(
ip=::::vm-kbuild-yocto-ia32-4::dhcp
root=/dev/ram0
user=lkp
job=/lkp/scheduled/vm-kbuild-yocto-ia32-4/trinity-300s-yocto-tiny-i386-2016-04-22.cgz-ddb06e08fa10ed5030285267a9b1e25d40c337c8-20170515-76824-r0qdn3-0.yaml
ARCH=x86_64
kconfig=x86_64-nfsroot+CONFIG_DEBUG_INFO_REDUCED
branch=trace/tip/cpuhotplug
commit=ddb06e08fa10ed5030285267a9b1e25d40c337c8
BOOT_IMAGE=/pkg/linux/x86_64-nfsroot+CONFIG_DEBUG_INFO_REDUCED/gcc-6/ddb06e08fa10ed5030285267a9b1e25d40c337c8/vmlinuz-4.11.0-07685-gddb06e0
max_uptime=1500
RESULT_ROOT=/result/trinity/300s/vm-kbuild-yocto-ia32/yocto-tiny-i386-2016-04-22.cgz/x86_64-nfsroot+CONFIG_DEBUG_INFO_REDUCED/gcc-6/ddb06e08fa10ed5030285267a9b1e25d40c337c8/0
LKP_SERVER=inn
debug
apic=debug
sysrq_always_enabled
rcupdate.rcu_cpu_stall_timeout=100
net.ifnames=0
printk.devkmsg=on
panic=-1
softlockup_panic=1
nmi_watchdog=panic
oops=panic
load_ramdisk=2
prompt_ramdisk=0
drbd.minor_count=8
systemd.log_level=err
ignore_loglevel
earlyprintk=ttyS0,115200
console=ttyS0,115200
console=tty0
vga=normal
rw
drbd.minor_count=8
)
To reproduce:
git clone https://github.com/01org/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
Thanks,
Kernel Test Robot
View attachment "config-4.11.0-07685-gddb06e0" of type "text/plain" (123419 bytes)
View attachment "job-script" of type "text/plain" (4017 bytes)
Download attachment "dmesg.xz" of type "application/octet-stream" (14712 bytes)
Powered by blists - more mailing lists