Re: WARNING: at /home/konrad/ssd/linux/kernel/rcutree.c:1547 __rcu_process_callbacks+0x42e/0x440()

Paul E. McKenney
2012-06-19T19:11:12Z

On Tue, Jun 19, 2012 at 11:47:18AM -0700, Paul E. McKenney wrote:
> On Tue, Jun 19, 2012 at 02:22:16PM -0400, Konrad Rzeszutek Wilk wrote:
> >
> > I've been getting this when booting a Xen PV guest with 3 CPUs (of which two are
> > online). Any thoughts?
>
> Maybe... I am assuming that your kernel/rcutree.c:1547 is this line of code:
>
> WARN_ON_ONCE(cpu_is_offline(smp_processor_id()));
>
> This is line 1549 in current mainline.
>
> If my guess is correct, my question is "why on earth is a CPU that has
> marked itself offline taking a timer interrupt???"
>
> I could provide a patch to make RCU work around this problem from its
> viewpoint, but taking timer interrupts on an offline CPU is an extremely
> bad idea. It would be good to fix the underlying problem instead of
> silencing RCU's warning.

And one possible source for the problem might be if queue_stop_cpus_work()
or one of its ancestors in the function-call graph incorrectly enabled
interrupts.

Thanx, Paul

> If my guess on what line is warning you is wrong, please do let me know
> what the line really is -- or even better, the corresponding mainline
> git commit ID.
>
> Thanx, Paul
>
> > Using config file "/test.xm".
> > Started domain latest (id=6)
> > [ 0.000000] console [hvc0] enabled, bootconsole disabled
> > [ 0.000000] Xen: using vcpuop timer interface
> > [ 0.000000] installing Xen timer for CPU 0
> > [ 0.000000] Detected 3093.036 MHz processor.
> > [ 0.000999] Calibrating delay loop (skipped), value calculated using timer frequency.. 6186.07 BogoMIPS (lpj=3093036)
> > [ 0.000999] pid_max: default: 32768 minimum: 301
> > [ 0.000999] Security Framework initialized
> > [ 0.000999] SELinux: Initializing.
> > [ 0.000999] SELinux: Starting in permissive mode
> > [ 0.000999] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes)
> > [ 0.000999] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes)
> > [ 0.000999] Mount-cache hash table entries: 256
> > [ 0.000999] Initializing cgroup subsys cpuacct
> > [ 0.000999] Initializing cgroup subsys freezer
> > [ 0.000999] ENERGY_PERF_BIAS: Set to 'normal', was 'performance'
> > [ 0.000999] ENERGY_PERF_BIAS: View and update with x86_energy_perf_policy(8)
> > [ 0.000999] CPU: Physical Processor ID: 0
> > [ 0.000999] CPU: Processor Core ID: 0
> > [ 0.000999] SMP alternatives: switching to UP code
> > [ 0.026357] cpu 0 spinlock event irq 17
> > [ 0.026377] Performance Events: unsupported p6 CPU model 42 no PMU driver, software events only.
> > [ 0.026462] NMI watchdog: disabled (cpu0): hardware events not enabled
> > [ 0.026567] installing Xen timer for CPU 1
> > [ 0.026580] cpu 1 spinlock event irq 24
> > [ 0.026603] SMP alternatives: switching to SMP code
> > [ 0.049557] NMI watchdog: disabled (cpu1): hardware events not enabled
> > [ 0.049756] installing Xen timer for CPU 2
> > [ 0.049786] cpu 2 spinlock event irq 31
> > [ 0.049996] NMI watchdog: disabled (cpu2): hardware events not enabled
> > [ 0.049996] Brought up 3 CPUs
> > [ 0.050313] kworker/u:0 (20) used greatest stack depth: 6000 bytes left
> > [ 0.051028] Grant tables using version 2 layout.
> > [ 0.051065] Grant table initialized
> > [ 0.069993] RTC time: 165:165:165, date: 165/165/65
> > [ 0.070103] NET: Registered protocol family 16
> > [ 0.070141] kworker/u:0 (24) used greatest stack depth: 5544 bytes left
> > [ 0.073000] ------------[ cut here ]------------
> > [ 0.073006] WARNING: at /home/konrad/ssd/linux/kernel/rcutree.c:1547 __rcu_process_callbacks+0x42e/0x440()
> > [ 0.073008] Modules linked in:
> > [ 0.073010] Pid: 12, comm: migration/2 Not tainted 3.5.0-rc2 #2
> > [ 0.073011] Call Trace:
> > [ 0.073017] <IRQ> [<ffffffff810718ea>] warn_slowpath_common+0x7a/0xb0
> > [ 0.073019] [<ffffffff81071935>] warn_slowpath_null+0x15/0x20
> > [ 0.073021] [<ffffffff810edb1e>] __rcu_process_callbacks+0x42e/0x440
> > [ 0.073023] [<ffffffff810edb50>] rcu_process_callbacks+0x20/0x40
> > [ 0.073025] [<ffffffff810792c9>] __do_softirq+0xa9/0x160
> > [ 0.073028] [<ffffffff810a1065>] ? sched_clock_local+0x25/0x90
> > [ 0.073030] [<ffffffff810d7201>] ? queue_stop_cpus_work+0x51/0xf0
> > [ 0.073033] [<ffffffff815cee1c>] call_softirq+0x1c/0x30
> > [ 0.073034] [<ffffffff81039435>] do_softirq+0x65/0xa0
> > [ 0.073036] [<ffffffff810790c5>] irq_exit+0xd5/0xf0
> > [ 0.073039] [<ffffffff8132347f>] xen_evtchn_do_upcall+0x2f/0x40
> > [ 0.073040] [<ffffffff815cee6e>] xen_do_hypervisor_callback+0x1e/0x30
> > [ 0.073042] <EOI> [<ffffffff810d7201>] ? queue_stop_cpus_work+0x51/0xf0
> > [ 0.073044] [<ffffffff8100122a>] ? hypercall_page+0x22a/0x1000
> > [ 0.073045] [<ffffffff8100122a>] ? hypercall_page+0x22a/0x1000
> > [ 0.073048] [<ffffffff8103361d>] ? xen_force_evtchn_callback+0xd/0x10
> > [ 0.073049] [<ffffffff81033ed2>] ? check_events+0x12/0x20
> > [ 0.073051] [<ffffffff81033ebf>] ? xen_restore_fl_direct_reloc+0x4/0x4
> > [ 0.073053] [<ffffffff810d73aa>] ? stop_machine_cpu_stop+0xba/0xf0
> > [ 0.073054] [<ffffffff810d72f0>] ? stop_one_cpu_nowait+0x50/0x50
> > [ 0.073055] [<ffffffff810d7021>] ? cpu_stopper_thread+0xf1/0x1c0
> > [ 0.073058] [<ffffffff815c5d7e>] ? __schedule+0x3be/0x760
> > [ 0.073060] [<ffffffff815c6d59>] ? _raw_spin_unlock_irqrestore+0x19/0x30
> > [ 0.073061] [<ffffffff810d6f30>] ? res_counter_charge+0x10/0x10
> > [ 0.073064] [<ffffffff81090c46>] ? kthread+0x96/0xa0
> > [ 0.073065] [<ffffffff815ced24>] ? kernel_thread_helper+0x4/0x10
> > [ 0.073067] [<ffffffff815c72b8>] ? retint_restore_args+0x5/0x6
> > [ 0.073069] [<ffffffff815ced20>] ? gs_change+0x13/0x13
> > [ 0.073073] ---[ end trace 4eaa2a86a8e2da22 ]---
> > [ 0.073075] dca service started, version 1.12.1
> > [ 0.074006] PCI: setting up Xen PCI frontend stub
> > [ 0.074015] PCI: pci_cache_line_size set to 64 bytes
> > [ 0.088093] bio: create slab <bio-0> at 0
> > [ 0.089051] ACPI: Interpreter disabled.
> > [ 0.089063] xen/balloon: Initialising balloon driver.
> > [ 0.091124] xen-balloon: Initialising balloon driver.
> > [ 0.092068] vgaarb: loaded
> > [ 0.092068] usbcore: registered new interface driver usbfs
> > [ 0.092087] usbcore: registered new interface driver hub
> > [ 0.093027] usbcore: registered new device driver usb
> > [ 0.093039] PCI: System does not support PCI
> > [ 0.093039] PCI: System does not support PCI
> > [ 0.094043] NetLabel: Initializing
> > [ 0.094052] NetLabel: domain hash size = 128
> > [ 0.094057] NetLabel: protocols = UNLABELED CIPSOv4
> > [ 0.094077] NetLabel: unlabeled traffic allowed by default
> > [ 0.094099] Switching to clocksource xen
> > [ 0.094160] pnp: PnP ACPI: disabled
> > [ 0.101664] NET: Registered protocol family 2
> > [ 0.101866] IP route cache hash table entries: 32768 (order: 6, 262144 bytes)
> > [ 0.102859] TCP established hash table entries: 131072 (order: 9, 2097152 bytes)
> > [ 0.103661] TCP bind hash table entries: 65536 (order: 8, 1048576 bytes)
> > [ 0.103849] TCP: Hash tables configured (established 131072 bind 65536)
> > [ 0.103858] TCP: reno registered
> > [ 0.103873] UDP hash table entries: 512 (order: 2, 16384 bytes)
> > [ 0.103891] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
> > [ 0.104035] NET: Registered protocol family 1
> > [ 0.104333] RPC: Registered named UNIX socket transport module.
> > [ 0.104347] RPC: Registered udp transport module.
> > [ 0.104356] RPC: Registered tcp transport module.
> > [ 0.104362] RPC: Registered tcp NFSv4.1 backchannel transport module.
> > [ 0.104371] PCI: CLS 0 bytes, default 64
> > [ 0.104511] Trying to unpack rootfs image as initramfs...
> > [ 0.337888] Freeing initrd memory: 273152k freed
> > [ 0.383239] platform rtc_cmos: registered platform RTC device (no PNP device found)
> > [ 0.383418] Machine check injector initialized
> > [ 0.384702] microcode: CPU0 sig=0x206a7, pf=0x2, revision=0x12
> > [ 0.384730] microcode: CPU1 sig=0x206a7, pf=0x2, revision=0x12
> > [ 0.384859] microcode: Microcode Update Driver: v2.00 <tigran@aivazian.fsnet.co.uk>, Peter Oruba
> > [ 0.385589] audit: initializing netlink socket (disabled)
> > [ 0.385612] type=2000 audit(1340130254.678:1): initialized
> > [ 0.403267] HugeTLB registered 2 MB page size, pre-allocated 0 pages
> > [ 0.403508] VFS: Disk quotas dquot_6.5.2
> > [ 0.403552] Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
> > [ 0.403720] NFS: Registering the id_resolver key type
> > [ 0.403739] Key type id_resolver registered
> > [ 0.403882] NTFS driver 2.1.30 [Flags: R/W].
> > [ 0.403981] msgmni has been set to 1986
> > [ 0.404021] SELinux: Registering netfilter hooks
> > [ 0.404794] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
> > [ 0.404806] io scheduler noop registered
> > [ 0.404812] io scheduler deadline registered
> > [ 0.404843] io scheduler cfq registered (default)
> > [ 0.404993] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
> > [ 0.405260] ioatdma: Intel(R) QuickData Technology Driver 4.00
> > [ 0.451143] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
> > [ 0.452662] Non-volatile memory driver v1.3
> > [ 0.452673] Linux agpgart interface v0.103
> > [ 0.453294] [drm] Initialized drm 1.1.0 20060810
> > [ 0.457300] brd: module loaded
> > [ 0.459306] loop: module loaded
> > [ 0.459798] Fixed MDIO Bus: probed
> > [ 0.459807] tun: Universal TUN/TAP device driver, 1.6
> > [ 0.459813] tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
> > [ 0.459986] ixgbevf: Intel(R) 10 Gigabit PCI Express Virtual Function Network Driver - version 2.6.0-k
> > [ 0.459998] ixgbevf: Copyright (c) 2009 - 2012 Intel Corporation.
> > [ 0.460777] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
> > [ 0.460788] ehci_hcd: block sizes: qh 112 qtd 96 itd 192 sitd 96
> > [ 0.460891] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
> > [ 0.460901] ohci_hcd: block sizes: ed 80 td 96
> > [ 0.461001] uhci_hcd: USB Universal Host Controller Interface driver
> > [ 0.461293] usbcore: registered new interface driver usblp
> > [ 0.461392] usbcore: registered new interface driver libusual
> > [ 0.461734] i8042: PNP: No PS/2 controller found. Probing ports directly.
> > [ 0.462609] i8042: No controller found
> > [ 0.462737] mousedev: PS/2 mouse device common for all mice
> > [ 0.523312] rtc_cmos rtc_cmos: rtc core: registered rtc_cmos as rtc0
> > [ 0.523440] rtc_cmos: probe of rtc_cmos failed with error -38
> > [ 0.523679] EFI Variables Facility v0.08 2004-May-17
> > [ 0.523734] zram: num_devices not specified. Using default: 1
> > [ 0.523739] zram: Creating 1 devices ...
> > [ 0.523980] xenoprofile_init: ret 0, events 4, xenoprof_is_primary 0
> > [ 0.524019] Netfilter messages via NETLINK v0.30.
> > [ 0.524035] nf_conntrack version 0.5.0 (7944 buckets, 31776 max)
> > [ 0.524099] ctnetlink v0.93: registering with nfnetlink.
> > [ 0.524262] ip_tables: (C) 2000-2006 Netfilter Core Team
> > [ 0.524293] TCP: cubic registered
> > [ 0.524298] Initializing XFRM netlink socket
> > [ 0.524346] NET: Registered protocol family 10
> > [ 0.524486] ip6_tables: (C) 2000-2006 Netfilter Core Team
> > [ 0.524675] sit: IPv6 over IPv4 tunneling driver
> > [ 0.524866] NET: Registered protocol family 17
> > [ 0.524902] Key type dns_resolver registered
> > [ 0.525076] PM: Hibernation image not present or could not be loaded.
> > [ 0.525094] registered taskstats version 1
> > [ 0.525121] XENBUS: Device with no driver: device/vkbd/0
> > [ 0.525127] XENBUS: Device with no driver: device/vfb/0
> > [ 0.525132] XENBUS: Device with no driver: device/vif/0
> > [ 0.525191] Magic number: 1:252:3141
> > [ 0.525898] Freeing unused kernel memory: 716k freed
> > [ 0.526109] Write protecting the kernel read-only data: 8192k
> > [ 0.530939] Freeing unused kernel memory: 172k freed
> > [ 0.531314] Freeing unused kernel memory: 356k freed
> > init started: BusyBox v1.14.3 (2012-06-19 13:33:49 EDT)
> > [ 0.536840] consoletype (1049) used greatest stack depth: 5304 bytes left
> > Mounting directories [ OK ]
> > mount: mount point /proc/bus/usb does not exist
> > [ 0.723241] modprobe (1078) used greatest stack depth: 5064 bytes left
> > mount: mount point /sys/kernel/config does not exist
> > [ 0.731128] core_filesystem (1050) used greatest stack depth: 4984 bytes left
> > [ 0.744953] input: Xen Virtual Keyboard as /devices/virtual/input/input0
> > [ 0.745268] input: Xen Virtual Pointer as /devices/virtual/input/input1
> > [ 0.963843] Initialising Xen virtual ethernet driver.
> > [ 1.085463] udevd (1114): /proc/1114/oom_adj is deprecated, please use /proc/1114/oom_score_adj instead.
> > udevd-work[1125]: error opening ATTR{/sys/devices/system/cpu/cpu0/online} for writing: No such file or directory
> >
> > Waiting for devices [ OK ]
> > [ 1.247709] ip (1927) used greatest stack depth: 3768 bytes left
> > Waiting for init.pre_custom [ OK ]
> > Waiting for fb [ OK ]
> > Starting..[/dev/fb0]
> > /dev/fb0: len:0
> > /dev/fb0: bits/pixel32
> > (7f69b03c2000): Writting .. [800:600]
> > Done!
> > .. blah blah
> >