12:28 p.m.
Greetings,
0day kernel testing robot got the below dmesg and the first bad commit is
yhuang/dbg_d6980ef325
commit d3b24f87c85f0c96d7b90af7fb2fd6ddbf4c5dac
Author: Kan Liang <kan.liang(a)intel.com>
AuthorDate: Thu Jan 21 15:52:37 2016 +0000
Commit: Huang Ying <ying.huang(a)intel.com>
CommitDate: Mon Jan 25 11:10:56 2016 +0800
perf/core: find auxiliary events in running pmus list
perf_event_aux funciton goes through pmus list to find proper auxiliary
events to output. The pmus list consists of all possible pmus in the
system, that may or may not be running at the moment, while the
auxiliary events must be from the running pmus. Therefore searching
non-running pmus is unnecessary and expensive especially when there are
many non-running pmus on the list.
For example, the brk test case in lkp triggers many mmap operations,
at the time, perf with cycles:pp is also running on the system. As a
result, many perf_event_aux are invoked, and each would search the whole
pmus list. If we enable the uncore support (even when uncore event are
not really used), dozens of uncore pmus will be added into pmus list,
which can significantly decrease brk_test's ops_per_sec. Based on our
test, the ops_per_sec without uncore patch is 2647573, while the
ops_per_sec with uncore patch is only 1768444, which is a 33.2%
reduction.
This patch introduces a running_pmus list which only tracks the running
pmus in the system. The perf_event_aux uses running_pmus list instead of
pmus list to find auxiliary events.
Reported-by: Huang, Ying <ying.huang(a)linux.intel.com>
Signed-off-by: Kan Liang <kan.liang(a)intel.com>
+-----------------------------------------------------------------------------+------------+------------+------------+
| | 7fdec82af6
| d3b24f87c8 | 43a5a3ac22 |
+-----------------------------------------------------------------------------+------------+------------+------------+
| boot_successes | 63
| 0 | 0 |
| boot_failures | 3
| 22 | 13 |
| BUG:unable_to_handle_kernel | 3
| 0 | 1 |
| Oops | 3
| 0 | 1 |
| EIP_is_at_perf_prepare_sample | 3
| | |
| Kernel_panic-not_syncing:Fatal_exception | 3
| | |
| backtrace:iterate_dir | 2
| | |
| backtrace:SyS_getdents64 | 2
| | |
| INFO:suspicious_RCU_usage | 0
| 22 | 13 |
| BUG:sleeping_function_called_from_invalid_context_at_kernel/locking/mutex.c | 0
| 22 | 13 |
| INFO:lockdep_is_turned_off | 0
| 22 | 13 |
| backtrace:SyS_brk | 0
| 22 | 13 |
| backtrace:do_brk | 0
| 22 | 13 |
| backtrace:do_group_exit | 0
| 1 | 1 |
| backtrace:SyS_exit_group | 0
| 1 | 1 |
+-----------------------------------------------------------------------------+------------+------------+------------+
Kernel tests: Boot OK!
[ 19.556874]
[ 19.557455] ===============================
[ 19.558347] [ INFO: suspicious RCU usage. ]
[ 19.559219] 4.4.0-05594-gd3b24f8 #61 Not tainted
[ 19.560073] -------------------------------
[ 19.560881] include/linux/rcupdate.h:573 Illegal context switch in RCU read-side
critical section!
[ 19.562719]
[ 19.562719] other info that might help us debug this:
[ 19.562719]
[ 19.574393]
[ 19.574393] rcu_scheduler_active = 1, debug_locks = 0
[ 19.575918] 2 locks held by trinity-main/388:
[ 19.576795] #0: (&mm->mmap_sem){++++++}, at: [<c10bb11e>]
SyS_brk+0x23/0x127
[ 19.578616] #1: (rcu_read_lock){......}, at: [<c108ec2c>]
perf_event_aux+0xce/0x233
[ 19.580484]
[ 19.580484] stack backtrace:
[ 19.581675] CPU: 0 PID: 388 Comm: trinity-main Not tainted 4.4.0-05594-gd3b24f8 #61
[ 19.583196] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Debian-1.8.2-1
04/01/2014
[ 19.585088] 00000000 00000001 c011bdf4 c1327e55 c011be10 c1060115 c185b949 d20eb280
[ 19.587991] c185b3b8 00000269 00000000 c011be24 c1051334 d20eb280 00000000 00000000
[ 19.590021] c011be40 c1051514 00000000 c011be64 00000246 c1aae5e0 c011becc c011be74
[ 19.592049] Call Trace:
[ 19.592744] [<c1327e55>] dump_stack+0x16/0x18
[ 19.593582] [<c1060115>] lockdep_rcu_suspicious+0xc6/0xcf
[ 19.594548] [<c1051334>] ___might_sleep+0x47/0x1bd
[ 19.595493] [<c1051514>] __might_sleep+0x6a/0x71
[ 19.596357] [<c165440f>] mutex_lock_nested+0x1e/0x2b8
[ 19.597260] [<c108ec2c>] ? perf_event_aux+0xce/0x233
[ 19.598229] [<c108ec90>] perf_event_aux+0x132/0x233
[ 19.599122] [<c132dc72>] ? strlcpy+0x15/0x35
[ 19.599956] [<c1094f82>] ? perf_event_comm_output+0x147/0x147
[ 19.600968] [<c109610f>] perf_event_mmap+0x28b/0x29e
[ 19.601863] [<c10bb040>] do_brk+0x17b/0x236
[ 19.602718] [<c10bb1d8>] SyS_brk+0xdd/0x127
[ 19.603543] [<c1000e8b>] do_syscall_32_irqs_on+0x43/0xdc
[ 19.604502] [<c165769e>] entry_INT80_32+0x2a/0x2a
[ 19.605473] BUG: sleeping function called from invalid context at
kernel/locking/mutex.c:617
[ 19.607196] in_atomic(): 1, irqs_disabled(): 0, pid: 388, name: trinity-main
[ 19.608344] INFO: lockdep is turned off.
[ 19.609134] CPU: 0 PID: 388 Comm: trinity-main Not tainted 4.4.0-05594-gd3b24f8 #61
[ 19.610650] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Debian-1.8.2-1
04/01/2014
[ 19.612378] 00000000 d20eb280 c011be10 c1327e55 c011be24 c10514a2 d20eb280 00000000
[ 19.614384] 00000000 c011be40 c1051514 00000000 c011be64 00000246 c1aae5e0 c011becc
[ 19.616344] c011be74 c165440f c108ec2c 00000000 00000000 00000246 00000000 c011becc
[ 19.618393] Call Trace:
[ 19.619042] [<c1327e55>] dump_stack+0x16/0x18
[ 19.619887] [<c10514a2>] ___might_sleep+0x1b5/0x1bd
[ 19.620777] [<c1051514>] __might_sleep+0x6a/0x71
[ 19.621641] [<c165440f>] mutex_lock_nested+0x1e/0x2b8
[ 19.622571] [<c108ec2c>] ? perf_event_aux+0xce/0x233
[ 19.623480] [<c108ec90>] perf_event_aux+0x132/0x233
[ 19.624418] [<c132dc72>] ? strlcpy+0x15/0x35
[ 19.625420] [<c1094f82>] ? perf_event_comm_output+0x147/0x147
[ 19.626406] [<c109610f>] perf_event_mmap+0x28b/0x29e
[ 19.627327] [<c10bb040>] do_brk+0x17b/0x236
[ 19.628143] [<c10bb1d8>] SyS_brk+0xdd/0x127
[ 19.628962] [<c1000e8b>] do_syscall_32_irqs_on+0x43/0xdc
[ 19.629927] [<c165769e>] entry_INT80_32+0x2a/0x2a
[ 20.020006] VFS: Warning: trinity-c0 using old stat() call. Recompile your binary.
[ 20.025280] mmap: trinity-c0 (389) uses deprecated remap_file_pages() syscall. See
Documentation/vm/remap_file_pages.txt.
[ 20.611965] BUG: sleeping function called from invalid context at
kernel/locking/mutex.c:617
[ 20.613757] in_atomic(): 1, irqs_disabled(): 0, pid: 391, name: trinity-main
[ 20.614871] INFO: lockdep is turned off.
[ 20.615670] CPU: 0 PID: 391 Comm: trinity-main Not tainted 4.4.0-05594-gd3b24f8 #61
[ 20.617205] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Debian-1.8.2-1
04/01/2014
[ 20.618861] 00000000 d2171940 d215be10 c1327e55 d215be24 c10514a2 d2171940 00000000
[ 20.620845] 00000000 d215be40 c1051514 00000000 d215be64 00000246 c1aae5e0 d215becc
[ 20.622870] d215be74 c165440f c108ec2c 00000000 00000000 00000246 00000000 d215becc
[ 20.624854] Call Trace:
[ 20.625505] [<c1327e55>] dump_stack+0x16/0x18
[ 20.626372] [<c10514a2>] ___might_sleep+0x1b5/0x1bd
[ 20.627269] [<c1051514>] __might_sleep+0x6a/0x71
[ 20.628137] [<c165440f>] mutex_lock_nested+0x1e/0x2b8
[ 20.629067] [<c108ec2c>] ? perf_event_aux+0xce/0x233
[ 20.630018] [<c108ec90>] perf_event_aux+0x132/0x233
[ 20.630927] [<c132dc72>] ? strlcpy+0x15/0x35
[ 20.631769] [<c1094f82>] ? perf_event_comm_output+0x147/0x147
[ 20.632754] [<c109610f>] perf_event_mmap+0x28b/0x29e
[ 20.633673] [<c10bb040>] do_brk+0x17b/0x236
[ 20.634526] [<c10bb1d8>] SyS_brk+0xdd/0x127
[ 20.635361] [<c1000e8b>] do_syscall_32_irqs_on+0x43/0xdc
[ 20.636298] [<c165769e>] entry_INT80_32+0x2a/0x2a
[ 20.865569] VFS: Warning: trinity-c0 using old stat() call. Recompile your binary.
git bisect start 43a5a3ac2281f0f1b3b56533025ca7231b15c810
92e963f50fc74041b5e9e744c330dca48e04f08d --
git bisect bad 1d901e321a5371e9a6f2108a4e214f6725437ae7 # 11:48 0- 11 Merge
'arm-platforms/kvm-arm64/fixes-4.5-rc1' into devel-spot-201601251122
git bisect bad 8fc3dc5927bc073aa2bbe00f47e375f1538df1f7 # 11:51 0- 3 Merge
'nomadik/nhk15-clcd' into devel-spot-201601251122
git bisect bad db5170859dcd8a897c1c793525acca876e21c022 # 11:54 0- 24 Merge
'krzk/for-next' into devel-spot-201601251122
git bisect bad e9cc0be488e0d7c2966450f75e519b37da8b8794 # 11:56 0- 24 Merge
'yhuang/dbg_d6980ef325' into devel-spot-201601251122
git bisect good 073df5bdf000ee23c3e2528b92d0d036ff31a803 # 12:00 22+ 0 0day
base guard for 'devel-spot-201601251122'
git bisect bad d3b24f87c85f0c96d7b90af7fb2fd6ddbf4c5dac # 12:03 0- 22
perf/core: find auxiliary events in running pmus list
# first bad commit: [d3b24f87c85f0c96d7b90af7fb2fd6ddbf4c5dac] perf/core: find auxiliary
events in running pmus list
git bisect good 7fdec82af6a9e190e53d07a1463d2a9ac49a8750 # 12:07 66+ 3 Merge
tag 'xfs-for-linus-4.5' of
git://git.kernel.org/pub/scm/linux/kernel/git/dgc/linux-xfs
# extra tests with DEBUG_INFO
git bisect bad d3b24f87c85f0c96d7b90af7fb2fd6ddbf4c5dac # 12:11 0- 57
perf/core: find auxiliary events in running pmus list
# extra tests on HEAD of linux-devel/devel-spot-201601251122
git bisect bad 43a5a3ac2281f0f1b3b56533025ca7231b15c810 # 12:11 0- 13 0day
head guard for 'devel-spot-201601251122'
# extra tests on tree/branch yhuang/dbg_d6980ef325
git bisect bad d3b24f87c85f0c96d7b90af7fb2fd6ddbf4c5dac # 12:15 0- 22
perf/core: find auxiliary events in running pmus list
# extra tests with first bad commit reverted
git bisect good 352e4b0f6b8a9905372e9f3a363325cbaa8f20ae # 12:20 66+ 1 Revert
"perf/core: find auxiliary events in running pmus list"
# extra tests on tree/branch linus/master
git bisect good 92e963f50fc74041b5e9e744c330dca48e04f08d # 12:22 66+ 13 Linux
4.5-rc1
# extra tests on tree/branch linux-next/master
git bisect good e216cada8e1b4d6c278a2a9af051aeba9b7f1bbe # 12:28 66+ 3 Add
linux-next specific files for 20160125
This script may reproduce the error.
----------------------------------------------------------------------------
#!/bin/bash
kernel=$1
initrd=quantal-core-i386.cgz
wget --no-clobber
https://github.com/fengguang/reproduce-kernel-bug/raw/master/initrd/$initrd
kvm=(
qemu-system-x86_64
-enable-kvm
-cpu kvm64
-kernel $kernel
-initrd $initrd
-m 300
-smp 2
-device e1000,netdev=net0
-netdev user,id=net0
-boot order=nc
-no-reboot
-watchdog i6300esb
-rtc base=localtime
-serial stdio
-display none
-monitor null
)
append=(
hung_task_panic=1
earlyprintk=ttyS0,115200
systemd.log_level=err
debug
apic=debug
sysrq_always_enabled
rcupdate.rcu_cpu_stall_timeout=100
panic=-1
softlockup_panic=1
nmi_watchdog=panic
oops=panic
load_ramdisk=2
prompt_ramdisk=0
console=ttyS0,115200
console=tty0
vga=normal
root=/dev/ram0
rw
drbd.minor_count=8
)
"${kvm[@]}" --append "${append[*]}"
----------------------------------------------------------------------------
---
0-DAY kernel test infrastructure Open Source Technology Center
https://lists.01.org/pipermail/lkp Intel Corporation