On Wed, Jul 11, 2012 at 08:55:59PM +0800, Fengguang Wu wrote: > On Wed, Jul 11, 2012 at 08:36:16PM +0800, Fengguang Wu wrote: > > On Wed, Jul 11, 2012 at 12:49:24AM -0700, Paul E. McKenney wrote: > > > On Tue, Jul 10, 2012 at 12:47:00PM +0800, Fengguang Wu wrote: > > > > Hi Paul, > > > > > > > > Fortunately this bug is bisectable and the first bad commit is: > > > > > > > > commit 9b2e4f1880b789be1f24f9684f7a54b90310b5c0 > > > > Author: Paul E. McKenney <paul.mcken...@linaro.org> > > > > Date: Fri Sep 30 12:10:22 2011 -0700 > > > > > > > > rcu: Track idleness independent of idle tasks > > > > > > OK, there is a problem in TINY_RCU's handling of dyntick-idle: it > > > traces while in idle. The confusion on my part was that in TREE_RCU, > > > the nesting and dyntick-idle indication are different, while in > > > TINY_RCU they are one and the same. > > > > > > Does the following patch help? > > > > Not exactly, but the error message is now changed to: > > Then I think it may help to test the linux-next tree that contains > latest RCU fixes. And it somehow helped. There are no warnings in > the linux-next tree 1 or 2 days ago; there is a maybe unrelated warning > in today's linux-next tree. > > [ 0.013241] Performance Events: > [ 0.014222] ------------[ cut here ]------------ > [ 0.014975] WARNING: at /c/wfg/linux/kernel/workqueue.c:1217 > worker_enter_idle+0x2fa/0x37c()
That's bisected to one of Tejun's workqueue commit.. > Both trees freeze after this point: > > modprobe: FATAL: Could not load > /lib/modules/3.5.0-rc6-next-20120710+/modules.dep: No such file or directory > ^M > modprobe: FATAL: Could not load > /lib/modules/3.5.0-rc6-next-20120710+/modules.dep: No such file or directory > ^M And that's bisected to Al's vfs work.. > So I'd better to base the test on one of your RCU branches.. > Which branch would your recommend? And finally I tried the patch on top of rcu/next, and get the attached dmesg and warnings: [ 1.776415] Testing tracer preemptirqsoff: PASSED [ 1.779383] Testing tracer wakeup: [ 2.091320] ftrace-test (15) used greatest stack depth: 7284 bytes left PASSED [ 2.094844] Testing tracer wakeup_rt: [ 2.179052] ------------[ cut here ]------------ [ 2.181087] WARNING: at /c/wfg/linux/kernel/rcutiny.c:92 rcu_idle_enter+0xf0/0x244() [ 2.183023] Hardware name: Bochs [ 2.183023] Modules linked in: [ 2.183023] [ 2.183023] Pid: 0, comm: swapper Not tainted 3.5.0-rc5+ #59 [ 2.183023] Call Trace: [ 2.183023] [<c103704c>] warn_slowpath_common+0xfc/0x13b [ 2.183023] [<c1105d31>] ? rcu_idle_enter+0xf0/0x244 [ 2.183023] [<c1105d31>] ? rcu_idle_enter+0xf0/0x244 [ 2.183023] [<c10370c9>] warn_slowpath_null+0x3e/0x4e [ 2.183023] [<c1105d31>] rcu_idle_enter+0xf0/0x244 [ 2.183023] [<c100fbdb>] cpu_idle+0x159/0x220 [ 2.183023] [<c14165a3>] rest_init+0x2db/0x2ef [ 2.183023] [<c14162c8>] ? reciprocal_value+0x64/0x64 [ 2.183023] [<c171d456>] start_kernel+0x8eb/0x8ff [ 2.183023] [<c171c62f>] ? repair_env_string+0xd3/0xd3 [ 2.183023] [<c171c342>] i386_start_kernel+0xf8/0x10b [ 2.183023] ---[ end trace 44593438a59a9533 ]--- [ 2.195679] ------------[ cut here ]------------ [ 2.196428] WARNING: at /c/wfg/linux/kernel/rcutiny.c:113 rcu_irq_exit+0x100/0x217() [ 2.197633] Hardware name: Bochs [ 2.198183] Modules linked in: [ 2.198695] Pid: 0, comm: swapper Tainted: G W 3.5.0-rc5+ #59 [ 2.199671] Call Trace: [ 2.199671] [<c103704c>] warn_slowpath_common+0xfc/0x13b [ 2.199671] [<c1105b2a>] ? rcu_irq_exit+0x100/0x217 [ 2.199671] [<c1105b2a>] ? rcu_irq_exit+0x100/0x217 [ 2.199671] [<c10370c9>] warn_slowpath_null+0x3e/0x4e [ 2.199671] [<c1105b2a>] rcu_irq_exit+0x100/0x217 [ 2.199671] [<c10469ae>] irq_exit+0x117/0x14d [ 2.199671] [<c1005d31>] do_IRQ+0xe5/0x106 [ 2.199671] [<c10ba77e>] ? trace_hardirqs_off_caller+0x97/0x167 [ 2.199671] [<c1437975>] common_interrupt+0x35/0x3c [ 2.199671] [<c10c00e0>] ? trace_hardirqs_on_caller+0x1b8/0x38c [ 2.199671] [<c1025c7b>] ? native_safe_halt+0x13/0x23 The same rcu/next HEAD w/o patch, the warning is: [ 4.456093] Testing event rcu_dyntick: [ 4.458251] [ 4.458941] =============================== [ 4.459352] [ INFO: suspicious RCU usage. ] [ 4.459352] 3.5.0-rc5+ #60 Not tainted [ 4.459352] ------------------------------- [ 4.459352] /c/wfg/linux/include/trace/events/rcu.h:275 suspicious rcu_dereference_check() usage! [ 4.459352] [ 4.459352] other info that might help us debug this: [ 4.459352] [ 4.459352] [ 4.459352] RCU used illegally from idle CPU! [ 4.459352] rcu_scheduler_active = 1, debug_locks = 0 [ 4.459352] RCU used illegally from extended quiescent state! [ 4.459352] no locks held by swapper/0. [ 4.459352] [ 4.459352] stack backtrace: [ 4.459352] Pid: 0, comm: swapper Not tainted 3.5.0-rc5+ #60 [ 4.459352] Call Trace: [ 4.459352] [ 4.459352] [<c10bbb36>] lockdep_rcu_suspicious+0x1de/0x1f4 [ 4.459352] [<c1103171>] trace_rcu_dyntick+0xd9/0x167 [ 4.459352] [<c1105865>] rcu_idle_enter_common+0x84/0x22d [ 4.459352] [<c10ba77e>] ? trace_hardirqs_off_caller+0x97/0x167 [ 4.459352] [<c1105d98>] rcu_idle_enter+0x16d/0x274 [ 4.459352] [<c100fbdb>] cpu_idle+0x159/0x220 [ 4.459352] [<c14165c3>] rest_init+0x2db/0x2ef [ 4.459352] [<c14162e8>] ? reciprocal_value+0x64/0x64 [ 4.459352] [<c171d456>] start_kernel+0x8eb/0x8ff [ 4.459352] [<c171c62f>] ? repair_env_string+0xd3/0xd3 [ 4.459352] [<c171c342>] i386_start_kernel+0xf8/0x10b [ 4.481163] OK [ 4.481437] Testing event rcu_prep_idle: OK That's a great kconfig (from the testing respective)! :-P Thanks, Fengguang
[ 0.000000] Initializing cgroup subsys cpuset [ 0.000000] Initializing cgroup subsys cpu [ 0.000000] Linux version 3.5.0-rc5+ (wfg@bee) (gcc version 4.7.0 (Debian 4.7.1-1) ) #59 PREEMPT Thu Jul 12 21:54:52 CST 2012 [ 0.000000] KERNEL supported cpus: [ 0.000000] AMD AuthenticAMD [ 0.000000] Centaur CentaurHauls [ 0.000000] Transmeta GenuineTMx86 [ 0.000000] Transmeta TransmetaCPU [ 0.000000] CPU: vendor_id 'GenuineIntel' unknown, using generic init. [ 0.000000] CPU: Your system may be unstable. [ 0.000000] e820: BIOS-provided physical RAM map: [ 0.000000] debug: ignoring loglevel setting. [ 0.000000] Notice: NX (Execute Disable) protection cannot be enabled: non-PAE kernel! [ 0.000000] DMI 2.4 present. [ 0.000000] e820: last_pfn = 0xfffd max_arch_pfn = 0x100000 [ 0.000000] initial memory mapped: [mem 0x00000000-0x023fffff] [ 0.000000] Base memory trampoline at [c009b000] 9b000 size 16384 [ 0.000000] init_memory_mapping: [mem 0x00000000-0x0fffcfff] [ 0.000000] [mem 0x00000000-0x003fffff] page 4k [ 0.000000] [mem 0x00400000-0x0fbfffff] page 2M [ 0.000000] [mem 0x0fc00000-0x0fffcfff] page 4k [ 0.000000] kernel direct mapping tables up to 0xfffcfff @ [mem 0x023fa000-0x023fffff] [ 0.000000] cma: CMA: reserved 16 MiB at 0d000000 [ 0.000000] log_buf_len: 8388608 [ 0.000000] early log buf free: 129056(98%) [ 0.000000] RAMDISK: [mem 0x0e73f000-0x0ffeffff] [ 0.000000] 0MB HIGHMEM available. [ 0.000000] 255MB LOWMEM available. [ 0.000000] mapped low ram: 0 - 0fffd000 [ 0.000000] low ram: 0 - 0fffd000 [ 0.000000] kvm-clock: cpu 0, msr 0:1634b41, boot clock [ 0.000000] Zone ranges: [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x00010000-0x0009efff] [ 0.000000] node 0: [mem 0x00100000-0x0fffcfff] [ 0.000000] On node 0 totalpages: 65420 [ 0.000000] free_area_init_node: node 0, pgdat c16fc648, node_mem_map ce53f200 [ 0.000000] Normal zone: 512 pages used for memmap [ 0.000000] Normal zone: 0 pages reserved [ 0.000000] Normal zone: 64908 pages, LIFO batch:15 [ 0.000000] SFI: Simple Firmware Interface v0.81 http://simplefirmware.org [ 0.000000] PM: Registered nosave memory: 000000000009f000 - 00000000000a0000 [ 0.000000] PM: Registered nosave memory: 00000000000a0000 - 00000000000f0000 [ 0.000000] PM: Registered nosave memory: 00000000000f0000 - 0000000000100000 [ 0.000000] e820: [mem 0x10000000-0xfffbbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 64908 [ 0.000000] Kernel command line: bisect-reboot i386-randconfig run_test= trinity=0 auth_hashtable_size=10 sunrpc.auth_hashtable_size=10 log_buf_len=8M ignore_loglevel debug sched_debug apic=debug dynamic_printk sysrq_always_enabled panic=10 hung_task_panic=1 softlockup_panic=1 unknown_nmi_panic=1 nmi_watchdog=panic,lapic prompt_ramdisk=0 console=ttyS0,115200 console=tty0 vga=normal root=/dev/ram0 rw BOOT_IMAGE=i386/vmlinuz-bisect [ 0.000000] sysrq: sysrq always enabled. [ 0.000000] PID hash table entries: 1024 (order: 0, 4096 bytes) [ 0.000000] Dentry cache hash table entries: 32768 (order: 5, 131072 bytes) [ 0.000000] Inode-cache hash table entries: 16384 (order: 4, 65536 bytes) [ 0.000000] __ex_table already sorted, skipping sort [ 0.000000] Initializing CPU#0 [ 0.000000] Initializing HighMem for node 0 (00000000:00000000) [ 0.000000] Memory: 194540k/262132k available (4320k kernel code, 67140k reserved, 2956k data, 420k init, 0k highmem) [ 0.000000] virtual kernel memory layout: [ 0.000000] fixmap : 0xfffcf000 - 0xfffff000 ( 192 kB) [ 0.000000] pkmap : 0xff800000 - 0xffc00000 (4096 kB) [ 0.000000] vmalloc : 0xd07fd000 - 0xff7fe000 ( 752 MB) [ 0.000000] lowmem : 0xc0000000 - 0xcfffd000 ( 255 MB) [ 0.000000] .init : 0xc171c000 - 0xc1785000 ( 420 kB) [ 0.000000] .data : 0xc14381b5 - 0xc171b2c0 (2956 kB) [ 0.000000] .text : 0xc1000000 - 0xc14381b5 (4320 kB) [ 0.000000] NR_IRQS:16 nr_irqs:16 16 [ 0.000000] CPU 0 irqstacks, hard=ce002000 soft=ce004000 [ 0.000000] console [ttyS0] enabled [ 0.000000] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar [ 0.000000] ... MAX_LOCKDEP_SUBCLASSES: 8 [ 0.000000] ... MAX_LOCK_DEPTH: 48 [ 0.000000] ... MAX_LOCKDEP_KEYS: 8191 [ 0.000000] ... CLASSHASH_SIZE: 4096 [ 0.000000] ... MAX_LOCKDEP_ENTRIES: 16384 [ 0.000000] ... MAX_LOCKDEP_CHAINS: 32768 [ 0.000000] ... CHAINHASH_SIZE: 16384 [ 0.000000] memory used by lock dependency info: 3567 kB [ 0.000000] per task-struct memory footprint: 1152 bytes [ 0.000000] ------------------------ [ 0.000000] | Locking API testsuite: [ 0.000000] ---------------------------------------------------------------------------- [ 0.000000] | spin |wlock |rlock |mutex | wsem | rsem | [ 0.000000] -------------------------------------------------------------------------- [ 0.000000] A-A deadlock: ok | ok | ok | ok | ok | ok | [ 0.000000] A-B-B-A deadlock: ok | ok | ok | ok | ok | ok | [ 0.000000] A-B-B-C-C-A deadlock: ok | ok | ok | ok | ok | ok | [ 0.000000] A-B-C-A-B-C deadlock: ok | ok | ok | ok | ok | ok | [ 0.000000] A-B-B-C-C-D-D-A deadlock: ok | ok | ok | ok | ok | ok | [ 0.000000] A-B-C-D-B-D-D-A deadlock: ok | ok | ok | ok | ok | ok | [ 0.000000] A-B-C-D-B-C-D-A deadlock: ok | ok | ok | ok | ok | ok | [ 0.000000] double unlock: ok | ok | ok | ok | ok | ok | [ 0.000000] initialize held: ok | ok | ok | ok | ok | ok | [ 0.000000] bad unlock order: ok | ok | ok | ok | ok | ok | [ 0.000000] -------------------------------------------------------------------------- [ 0.000000] recursive read-lock: | ok | | ok | [ 0.000000] recursive read-lock #2: | ok | | ok | [ 0.000000] mixed read-write-lock: | ok | | ok | [ 0.000000] mixed write-read-lock: | ok | | ok | [ 0.000000] -------------------------------------------------------------------------- [ 0.000000] hard-irqs-on + irq-safe-A/12: ok | ok | ok | [ 0.000000] soft-irqs-on + irq-safe-A/12: ok | ok | ok | [ 0.000000] hard-irqs-on + irq-safe-A/21: ok | ok | ok | [ 0.000000] soft-irqs-on + irq-safe-A/21: ok | ok | ok | [ 0.000000] sirq-safe-A => hirqs-on/12: ok | ok | ok | [ 0.000000] sirq-safe-A => hirqs-on/21: ok | ok | ok | [ 0.000000] hard-safe-A + irqs-on/12: ok | ok | ok | [ 0.000000] soft-safe-A + irqs-on/12: ok | ok | ok | [ 0.000000] hard-safe-A + irqs-on/21: ok | ok | ok | [ 0.000000] soft-safe-A + irqs-on/21: ok | ok | ok | [ 0.000000] hard-safe-A + unsafe-B #1/123: ok | ok | ok | [ 0.000000] soft-safe-A + unsafe-B #1/123: ok | ok | ok | [ 0.000000] hard-safe-A + unsafe-B #1/132: ok | ok | ok | [ 0.000000] soft-safe-A + unsafe-B #1/132: ok | ok | ok | [ 0.000000] hard-safe-A + unsafe-B #1/213: ok | ok | ok | [ 0.000000] soft-safe-A + unsafe-B #1/213: ok | ok | ok | [ 0.000000] hard-safe-A + unsafe-B #1/231: ok | ok | ok | [ 0.000000] soft-safe-A + unsafe-B #1/231: ok | ok | ok | [ 0.000000] hard-safe-A + unsafe-B #1/312: ok | ok | ok | [ 0.000000] soft-safe-A + unsafe-B #1/312: ok | ok | ok | [ 0.000000] hard-safe-A + unsafe-B #1/321: ok | ok | ok | [ 0.000000] soft-safe-A + unsafe-B #1/321: ok | ok | ok | [ 0.000000] hard-safe-A + unsafe-B #2/123: ok | ok | ok | [ 0.000000] soft-safe-A + unsafe-B #2/123: ok | ok | ok | [ 0.000000] hard-safe-A + unsafe-B #2/132: ok | ok | ok | [ 0.000000] soft-safe-A + unsafe-B #2/132: ok | ok | ok | [ 0.000000] hard-safe-A + unsafe-B #2/213: ok | ok | ok | [ 0.000000] soft-safe-A + unsafe-B #2/213: ok | ok | ok | [ 0.000000] hard-safe-A + unsafe-B #2/231: ok | ok | ok | [ 0.000000] soft-safe-A + unsafe-B #2/231: ok | ok | ok | [ 0.000000] hard-safe-A + unsafe-B #2/312: ok | ok | ok | [ 0.000000] soft-safe-A + unsafe-B #2/312: ok | ok | ok | [ 0.000000] hard-safe-A + unsafe-B #2/321: ok | ok | ok | [ 0.000000] soft-safe-A + unsafe-B #2/321: ok | ok | ok | [ 0.000000] hard-irq lock-inversion/123: ok | ok | ok | [ 0.000000] soft-irq lock-inversion/123: ok | ok | ok | [ 0.000000] hard-irq lock-inversion/132: ok | ok | ok | [ 0.000000] soft-irq lock-inversion/132: ok | ok | ok | [ 0.000000] hard-irq lock-inversion/213: ok | ok | ok | [ 0.000000] soft-irq lock-inversion/213: ok | ok | ok | [ 0.000000] hard-irq lock-inversion/231: ok | ok | ok | [ 0.000000] soft-irq lock-inversion/231: ok | ok | ok | [ 0.000000] hard-irq lock-inversion/312: ok | ok | ok | [ 0.000000] soft-irq lock-inversion/312: ok | ok | ok | [ 0.000000] hard-irq lock-inversion/321: ok | ok | ok | [ 0.000000] soft-irq lock-inversion/321: ok | ok | ok | [ 0.000000] hard-irq read-recursion/123: ok | [ 0.000000] soft-irq read-recursion/123: ok | [ 0.000000] hard-irq read-recursion/132: ok | [ 0.000000] soft-irq read-recursion/132: ok | [ 0.000000] hard-irq read-recursion/213: ok | [ 0.000000] soft-irq read-recursion/213: ok | [ 0.000000] hard-irq read-recursion/231: ok | [ 0.000000] soft-irq read-recursion/231: ok | [ 0.000000] hard-irq read-recursion/312: ok | [ 0.000000] soft-irq read-recursion/312: ok | [ 0.000000] hard-irq read-recursion/321: ok | [ 0.000000] soft-irq read-recursion/321: ok | [ 0.000000] ------------------------------------------------------- [ 0.000000] Good, all 218 testcases passed! | [ 0.000000] --------------------------------- [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ODEBUG: 9 of 9 active objects replaced [ 0.000000] ODEBUG: selftest passed [ 0.000000] kmemleak: Early log buffer exceeded (585), please increase DEBUG_KMEMLEAK_EARLY_LOG_SIZE [ 0.000000] Detected 3299.986 MHz processor. [ 0.004000] Calibrating delay loop (skipped) preset value.. 6599.97 BogoMIPS (lpj=13199944) [ 0.004000] pid_max: default: 4096 minimum: 301 [ 0.004000] Security Framework initialized [ 0.004000] AppArmor: AppArmor initialized [ 0.004081] Mount-cache hash table entries: 512 [ 0.006958] Initializing cgroup subsys debug [ 0.007642] Initializing cgroup subsys devices [ 0.008012] Initializing cgroup subsys freezer [ 0.008728] Initializing cgroup subsys perf_event [ 0.009609] mce: CPU supports 10 MCE banks [ 0.010257] MCE: unknown CPU type - not enabling MCE support. [ 0.011220] CPU: GenuineIntel Common KVM processor stepping 01 [ 0.013743] Performance Events: [ 0.015155] Testing tracer nop: [ 0.015751] PASSED [ 0.017134] EVM: security.capability [ 0.020734] dummy: [ 0.023608] NET: Registered protocol family 16 [ 0.026087] bio: create slab <bio-0> at 0 [ 0.028472] Switching to clocksource kvm-clock [ 0.029925] Warning: could not register annotated branches stats [ 0.082912] AppArmor: AppArmor Filesystem Enabled [ 0.084341] NET: Registered protocol family 1 [ 0.085851] Unpacking initramfs... [ 1.298131] Freeing initrd memory: 25284k freed [ 1.644753] DMA-API: preallocated 32768 debug entries [ 1.645575] DMA-API: debugging enabled by kernel config [ 1.647311] platform rtc_cmos: registered platform RTC device (no PNP device found) [ 1.650616] audit: initializing netlink socket (disabled) [ 1.651587] type=2000 audit(1342101770.648:1): initialized [ 1.660363] Testing tracer function: PASSED [ 1.772155] Testing tracer irqsoff: PASSED [ 1.774336] Testing tracer preemptoff: PASSED [ 1.776415] Testing tracer preemptirqsoff: PASSED [ 1.779383] Testing tracer wakeup: [ 2.091320] ftrace-test (15) used greatest stack depth: 7284 bytes left PASSED [ 2.094844] Testing tracer wakeup_rt: [ 2.179052] ------------[ cut here ]------------ [ 2.181087] WARNING: at /c/wfg/linux/kernel/rcutiny.c:92 rcu_idle_enter+0xf0/0x244() [ 2.183023] Hardware name: Bochs [ 2.183023] Modules linked in: [ 2.183023] [ 2.183023] Pid: 0, comm: swapper Not tainted 3.5.0-rc5+ #59 [ 2.183023] Call Trace: [ 2.183023] [<c103704c>] warn_slowpath_common+0xfc/0x13b [ 2.183023] [<c1105d31>] ? rcu_idle_enter+0xf0/0x244 [ 2.183023] [<c1105d31>] ? rcu_idle_enter+0xf0/0x244 [ 2.183023] [<c10370c9>] warn_slowpath_null+0x3e/0x4e [ 2.183023] [<c1105d31>] rcu_idle_enter+0xf0/0x244 [ 2.183023] [<c100fbdb>] cpu_idle+0x159/0x220 [ 2.183023] [<c14165a3>] rest_init+0x2db/0x2ef [ 2.183023] [<c14162c8>] ? reciprocal_value+0x64/0x64 [ 2.183023] [<c171d456>] start_kernel+0x8eb/0x8ff [ 2.183023] [<c171c62f>] ? repair_env_string+0xd3/0xd3 [ 2.183023] [<c171c342>] i386_start_kernel+0xf8/0x10b [ 2.183023] ---[ end trace 44593438a59a9533 ]--- [ 2.195679] ------------[ cut here ]------------ [ 2.196428] WARNING: at /c/wfg/linux/kernel/rcutiny.c:113 rcu_irq_exit+0x100/0x217() [ 2.197633] Hardware name: Bochs [ 2.198183] Modules linked in: [ 2.198695] Pid: 0, comm: swapper Tainted: G W 3.5.0-rc5+ #59 [ 2.199671] Call Trace: [ 2.199671] [<c103704c>] warn_slowpath_common+0xfc/0x13b [ 2.199671] [<c1105b2a>] ? rcu_irq_exit+0x100/0x217 [ 2.199671] [<c1105b2a>] ? rcu_irq_exit+0x100/0x217 [ 2.199671] [<c10370c9>] warn_slowpath_null+0x3e/0x4e [ 2.199671] [<c1105b2a>] rcu_irq_exit+0x100/0x217 [ 2.199671] [<c10469ae>] irq_exit+0x117/0x14d [ 2.199671] [<c1005d31>] do_IRQ+0xe5/0x106 [ 2.199671] [<c10ba77e>] ? trace_hardirqs_off_caller+0x97/0x167 [ 2.199671] [<c1437975>] common_interrupt+0x35/0x3c [ 2.199671] [<c10c00e0>] ? trace_hardirqs_on_caller+0x1b8/0x38c [ 2.199671] [<c1025c7b>] ? native_safe_halt+0x13/0x23 [ 2.199671] [<c100e52a>] default_idle+0xac/0x14a [ 2.199671] [<c100fbef>] cpu_idle+0x16d/0x220 [ 2.199671] [<c14165a3>] rest_init+0x2db/0x2ef [ 2.199671] [<c14162c8>] ? reciprocal_value+0x64/0x64 [ 2.199671] [<c171d456>] start_kernel+0x8eb/0x8ff [ 2.199671] [<c171c62f>] ? repair_env_string+0xd3/0xd3 [ 2.199671] [<c171c342>] i386_start_kernel+0xf8/0x10b [ 2.199671] ---[ end trace 44593438a59a9534 ]--- [ 2.215264] ------------[ cut here ]------------ [ 2.216013] WARNING: at /c/wfg/linux/kernel/rcutiny.c:149 rcu_idle_exit+0xfa/0x266() [ 2.217199] Hardware name: Bochs [ 2.217716] Modules linked in: [ 2.218232] Pid: 0, comm: swapper Tainted: G W 3.5.0-rc5+ #59 [ 2.219255] Call Trace: [ 2.219255] [<c103704c>] warn_slowpath_common+0xfc/0x13b [ 2.219255] [<c1103b21>] ? rcu_idle_exit+0xfa/0x266 [ 2.219255] [<c1103b21>] ? rcu_idle_exit+0xfa/0x266 [ 2.219255] [<c10370c9>] warn_slowpath_null+0x3e/0x4e [ 2.219255] [<c1103b21>] rcu_idle_exit+0xfa/0x266 [ 2.219255] [<c100fc02>] cpu_idle+0x180/0x220 [ 2.219255] [<c14165a3>] rest_init+0x2db/0x2ef [ 2.219255] [<c14162c8>] ? reciprocal_value+0x64/0x64 [ 2.219255] [<c171d456>] start_kernel+0x8eb/0x8ff [ 2.219255] [<c171c62f>] ? repair_env_string+0xd3/0xd3 [ 2.219255] [<c171c342>] i386_start_kernel+0xf8/0x10b [ 2.219255] ---[ end trace 44593438a59a9535 ]--- [ 2.439202] PASSED [ 2.440272] Testing tracer branch: PASSED [ 2.552720] msgmni has been set to 461 [ 2.555224] cryptomgr_test (20) used greatest stack depth: 7276 bytes left [ 2.556806] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 254) [ 2.558009] io scheduler noop registered (default) [ 2.558771] start plist test [ 2.565269] end plist test [ 2.566156] crc32: CRC_LE_BITS = 32, CRC_BE BITS = 32 [ 2.567072] crc32: self tests passed, processed 225944 bytes in 197792 nsec [ 2.568436] crc32c: CRC_LE_BITS = 32 [ 2.569006] crc32c: self tests passed, processed 225944 bytes in 104239 nsec [ 2.656189] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled [ 2.682074] serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A [ 3.447151] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.451261] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.455394] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0 [ 3.458286] Running tests on trace events: [ 3.458991] Testing event kfree_skb: OK [ 3.468175] Testing event consume_skb: OK [ 3.475825] Testing event skb_copy_datagram_iovec: OK [ 3.483917] Testing event net_dev_xmit: OK [ 3.491767] Testing event net_dev_queue: OK [ 3.499338] Testing event netif_receive_skb: OK [ 3.507871] Testing event netif_rx: OK [ 3.515348] Testing event napi_poll: OK [ 3.523841] Testing event sock_rcvqueue_full: OK [ 3.531939] Testing event sock_exceed_buf_limit: OK [ 3.539837] Testing event udp_fail_queue_rcv_skb: OK [ 3.547924] Testing event regmap_reg_write: OK [ 3.555276] Testing event regmap_reg_read: OK [ 3.563834] Testing event regmap_reg_read_cache: OK [ 3.571771] Testing event regmap_hw_read_start: OK [ 3.579956] Testing event regmap_hw_read_done: OK [ 3.587841] Testing event regmap_hw_write_start: OK [ 3.595275] Testing event regmap_hw_write_done: OK [ 3.603879] Testing event regcache_sync: OK [ 3.611959] Testing event regmap_cache_only: OK [ 3.619850] Testing event regmap_cache_bypass: OK [ 3.627951] Testing event regulator_enable: OK [ 3.635357] Testing event regulator_enable_delay: OK [ 3.643847] Testing event regulator_enable_complete: OK [ 3.652003] Testing event regulator_disable: OK [ 3.659912] Testing event regulator_disable_complete: OK [ 3.667958] Testing event regulator_set_voltage: OK [ 3.675342] Testing event regulator_set_voltage_complete: OK [ 3.683759] Testing event gpio_direction: OK [ 3.692005] Testing event gpio_value: OK [ 3.699942] Testing event block_rq_abort: OK [ 3.707630] Testing event block_rq_requeue: OK [ 3.715350] Testing event block_rq_complete: OK [ 3.723851] Testing event block_rq_insert: OK [ 3.731871] Testing event block_rq_issue: OK [ 3.740007] Testing event block_bio_bounce: OK [ 3.747672] Testing event block_bio_complete: OK [ 3.755289] Testing event block_bio_backmerge: OK [ 3.763882] Testing event block_bio_frontmerge: OK [ 3.771911] Testing event block_bio_queue: OK [ 3.779867] Testing event block_getrq: OK [ 3.787880] Testing event block_sleeprq: OK [ 3.795911] Testing event block_plug: OK [ 3.803865] Testing event block_unplug: OK [ 3.811883] Testing event block_split: OK [ 3.819947] Testing event block_bio_remap: OK [ 3.827670] Testing event block_rq_remap: OK [ 3.835335] Testing event writeback_nothread: OK [ 3.843876] Testing event writeback_queue: OK [ 3.851988] Testing event writeback_exec: OK [ 3.859889] Testing event writeback_start: OK [ 3.867733] Testing event writeback_written: OK [ 3.875295] Testing event writeback_wait: OK [ 3.883858] Testing event writeback_pages_written: OK [ 3.891917] Testing event writeback_nowork: OK [ 3.899870] Testing event writeback_wake_background: OK [ 3.907887] Testing event writeback_wake_thread: OK [ 3.915346] Testing event writeback_wake_forker_thread: OK [ 3.923881] Testing event writeback_bdi_register: OK [ 3.931984] Testing event writeback_bdi_unregister: OK [ 3.939882] Testing event writeback_thread_start: OK [ 3.947723] Testing event writeback_thread_stop: OK [ 3.955345] Testing event wbc_writepage: OK [ 3.963849] Testing event writeback_queue_io: OK [ 3.971883] Testing event global_dirty_state: OK [ 3.980020] Testing event bdi_dirty_ratelimit: OK [ 3.987908] Testing event balance_dirty_pages: OK [ 3.995336] Testing event writeback_sb_inodes_requeue: OK [ 4.003891] Testing event writeback_congestion_wait: OK [ 4.011961] Testing event writeback_wait_iff_congested: OK [ 4.019879] Testing event writeback_single_inode: OK [ 4.027987] Testing event mm_compaction_isolate_migratepages: OK [ 4.035318] Testing event mm_compaction_isolate_freepages: OK [ 4.043879] Testing event mm_compaction_migratepages: OK [ 4.051971] Testing event kmalloc: OK [ 4.059869] Testing event kmem_cache_alloc: OK [ 4.067864] Testing event kmalloc_node: OK [ 4.075353] Testing event kmem_cache_alloc_node: OK [ 4.083919] Testing event kfree: OK [ 4.091888] Testing event kmem_cache_free: OK [ 4.099916] Testing event mm_page_free: OK [ 4.107537] Testing event mm_page_free_batched: OK [ 4.115756] Testing event mm_page_alloc: OK [ 4.123930] Testing event mm_page_alloc_zone_locked: OK [ 4.131739] Testing event mm_page_pcpu_drain: OK [ 4.139909] Testing event mm_page_alloc_extfrag: OK [ 4.147743] Testing event mm_vmscan_kswapd_sleep: OK [ 4.155890] Testing event mm_vmscan_kswapd_wake: OK [ 4.163769] Testing event mm_vmscan_wakeup_kswapd: OK [ 4.171870] Testing event mm_vmscan_direct_reclaim_begin: OK [ 4.179893] Testing event mm_vmscan_memcg_reclaim_begin: OK [ 4.187759] Testing event mm_vmscan_memcg_softlimit_reclaim_begin: OK [ 4.195307] Testing event mm_vmscan_direct_reclaim_end: OK [ 4.203884] Testing event mm_vmscan_memcg_reclaim_end: OK [ 4.211938] Testing event mm_vmscan_memcg_softlimit_reclaim_end: OK [ 4.219886] Testing event mm_shrink_slab_start: OK [ 4.227972] Testing event mm_shrink_slab_end: OK [ 4.235928] Testing event mm_vmscan_lru_isolate: OK [ 4.243994] Testing event mm_vmscan_memcg_isolate: OK [ 4.251879] Testing event mm_vmscan_writepage: OK [ 4.259929] Testing event mm_vmscan_lru_shrink_inactive: OK [ 4.268071] Testing event oom_score_adj_update: OK [ 4.275333] Testing event cpu_idle: OK [ 4.283907] Testing event cpu_frequency: OK [ 4.291907] Testing event machine_suspend: OK [ 4.299991] Testing event wakeup_source_activate: OK [ 4.307923] Testing event wakeup_source_deactivate: OK [ 4.315383] Testing event clock_enable: OK [ 4.323883] Testing event clock_disable: OK [ 4.331934] Testing event clock_set_rate: OK [ 4.339902] Testing event power_domain_target: OK [ 4.347878] Testing event ftrace_test_filter: OK [ 4.355411] Testing event module_load: OK [ 4.363905] Testing event module_free: OK [ 4.371901] Testing event module_get: OK [ 4.379929] Testing event module_put: OK [ 4.387897] Testing event module_request: OK [ 4.395342] Testing event lock_acquire: [ 4.396705] test-events (142) used greatest stack depth: 7248 bytes left OK [ 4.408079] Testing event lock_release: [ 4.410133] test-events (143) used greatest stack depth: 7164 bytes left OK [ 4.420035] Testing event sched_kthread_stop: OK [ 4.427994] Testing event sched_kthread_stop_ret: OK [ 4.435331] Testing event sched_wakeup: OK [ 4.443906] Testing event sched_wakeup_new: OK [ 4.451884] Testing event sched_switch: OK [ 4.460043] Testing event sched_migrate_task: OK [ 4.467900] Testing event sched_process_free: OK [ 4.475353] Testing event sched_process_exit: OK [ 4.483926] Testing event sched_wait_task: OK [ 4.492012] Testing event sched_process_wait: OK [ 4.499900] Testing event sched_process_fork: OK [ 4.508076] Testing event sched_process_exec: OK [ 4.515332] Testing event sched_stat_wait: OK [ 4.523928] Testing event sched_stat_sleep: OK [ 4.531906] Testing event sched_stat_iowait: OK [ 4.539975] Testing event sched_stat_blocked: OK [ 4.547772] Testing event sched_stat_runtime: OK [ 4.555348] Testing event sched_pi_setprio: [ 4.556867] test-events (161) used greatest stack depth: 7084 bytes left OK [ 4.568058] Testing event rcu_utilization: OK [ 4.575903] Testing event rcu_dyntick: OK [ 4.584027] Testing event rcu_prep_idle: OK [ 4.591920] Testing event rcu_callback: OK [ 4.599849] Testing event rcu_kfree_callback: OK [ 4.607889] Testing event rcu_batch_start: OK [ 4.615376] Testing event rcu_invoke_callback: OK [ 4.623937] Testing event rcu_invoke_kfree_callback: OK [ 4.632026] Testing event rcu_batch_end: OK [ 4.639988] Testing event rcu_torture_read: OK [ 4.647760] Testing event rcu_barrier: OK [ 4.655726] Testing event workqueue_queue_work: OK [ 4.663863] Testing event workqueue_activate_work: OK [ 4.671955] Testing event workqueue_execute_start: OK [ 4.679707] Testing event workqueue_execute_end: OK [ 4.687664] Testing event signal_generate: OK [ 4.695705] Testing event signal_deliver: OK [ 4.703735] Testing event timer_init: OK [ 4.711654] Testing event timer_start: OK [ 4.719695] Testing event timer_expire_entry: OK [ 4.727923] Testing event timer_expire_exit: OK [ 4.735763] Testing event timer_cancel: OK [ 4.743679] Testing event hrtimer_init: OK [ 4.751949] Testing event hrtimer_start: OK [ 4.759762] Testing event hrtimer_expire_entry: OK [ 4.767987] Testing event hrtimer_expire_exit: OK [ 4.775677] Testing event hrtimer_cancel: OK [ 4.783948] Testing event itimer_state: OK [ 4.791865] Testing event itimer_expire: OK [ 4.799947] Testing event irq_handler_entry: OK [ 4.808012] Testing event irq_handler_exit: OK [ 4.815975] Testing event softirq_entry: OK [ 4.823930] Testing event softirq_exit: OK [ 4.832016] Testing event softirq_raise: OK [ 4.839873] Testing event console: OK [ 4.847936] Testing event task_newtask: OK [ 4.855412] Testing event task_rename: OK [ 4.863949] Testing event mce_record: OK [ 4.871928] Testing event sys_enter: OK [ 4.880023] Testing event sys_exit: OK [ 4.887959] Running tests on trace event systems: [ 4.889909] Testing event system skb: OK [ 4.900203] Testing event system net: OK [ 4.908238] Testing event system napi: OK [ 4.915990] Testing event system sock: OK [ 4.924143] Testing event system udp: OK [ 4.931945] Testing event system regmap: OK [ 4.940601] Testing event system regulator: OK [ 4.952281] Testing event system gpio: OK [ 4.959397] Testing event system block: OK [ 4.967765] Testing event system writeback: OK [ 4.980014] Testing event system compaction: OK [ 4.988194] Testing event system kmem: OK [ 4.999628] Testing event system vmscan: OK [ 5.012917] Testing event system oom: OK [ 5.020007] Testing event system power: OK [ 5.027583] Testing event system test: OK [ 5.035394] Testing event system module: OK [ 5.044244] Testing event system lock: OK [ 5.052396] Testing event system sched: OK [ 5.065102] Testing event system rcu: OK [ 5.076579] Testing event system workqueue: OK [ 5.087519] Testing event system signal: OK [ 5.096121] Testing event system timer: OK [ 5.108936] Testing event system irq: OK [ 5.120296] Testing event system printk: OK [ 5.128076] Testing event system task: OK [ 5.136102] Testing event system syscalls: OK [ 5.151487] Testing event system mce: OK [ 5.159934] Testing event system raw_syscalls: OK [ 5.168032] Running tests on all trace events: [ 5.169914] Testing all events: OK [ 5.199547] Running tests again, along with the function tracer [ 5.200609] Running tests on trace events: [ 5.201372] Testing event kfree_skb: OK [ 5.213573] Testing event consume_skb: [ 5.215246] test-events (233) used greatest stack depth: 7016 bytes left OK [ 5.226438] Testing event skb_copy_datagram_iovec: OK [ 5.242197] Testing event net_dev_xmit: OK [ 5.253518] Testing event net_dev_queue: OK [ 5.265407] Testing event netif_receive_skb: OK [ 5.282051] Testing event netif_rx: OK [ 5.293104] Testing event napi_poll: OK [ 5.306565] Testing event sock_rcvqueue_full: OK [ 5.321990] Testing event sock_exceed_buf_limit: OK [ 5.333108] Testing event udp_fail_queue_rcv_skb: OK [ 5.346575] Testing event regmap_reg_write: OK [ 5.361518] Testing event regmap_reg_read: OK [ 5.373500] Testing event regmap_reg_read_cache: OK [ 5.386362] Testing event regmap_hw_read_start: OK [ 5.401230] Testing event regmap_hw_read_done: OK [ 5.413178] Testing event regmap_hw_write_start: OK [ 5.425872] Testing event regmap_hw_write_done: OK [ 5.441825] Testing event regcache_sync: OK [ 5.453636] Testing event regmap_cache_only: OK [ 5.466317] Testing event regmap_cache_bypass: OK [ 5.481581] Testing event regulator_enable: OK [ 5.493136] Testing event regulator_enable_delay: OK [ 5.505738] Testing event regulator_enable_complete: OK [ 5.520358] Testing event regulator_disable: OK [ 5.533691] Testing event regulator_disable_complete: OK [ 5.544449] Testing event regulator_set_voltage: OK [ 5.552614] Testing event regulator_set_voltage_complete: OK [ 5.564353] Testing event gpio_direction: OK [ 5.572550] Testing event gpio_value: OK [ 5.580436] Testing event block_rq_abort: OK [ 5.588621] Testing event block_rq_requeue: OK [ 5.596480] Testing event block_rq_complete: OK [ 5.604649] Testing event block_rq_insert: OK [ 5.612427] Testing event block_rq_issue: OK [ 5.620461] Testing event block_bio_bounce: OK [ 5.628637] Testing event block_bio_complete: OK [ 5.636371] Testing event block_bio_backmerge: OK [ 5.644605] Testing event block_bio_frontmerge: OK [ 5.652388] Testing event block_bio_queue: OK [ 5.660562] Testing event block_getrq: OK [ 5.668418] Testing event block_sleeprq: OK [ 5.676453] Testing event block_plug: OK [ 5.684676] Testing event block_unplug: OK [ 5.692511] Testing event block_split: [ 5.694498] test-events (276) used greatest stack depth: 7008 bytes left OK [ 5.704530] Testing event block_bio_remap: OK [ 5.712506] Testing event block_rq_remap: OK [ 5.720534] Testing event writeback_nothread: OK [ 5.728491] Testing event writeback_queue:
