Bug#656196: [2.6.39 -> 3.0 regression] kernel stalls every few days (rcu_sched_state detected stall on CPU x)

To: Jonathan Nieder <jrnieder@gmail.com>
Cc: 656196@bugs.debian.org
Subject: Bug#656196: [2.6.39 -> 3.0 regression] kernel stalls every few days (rcu_sched_state detected stall on CPU x)
From: Michael Below <below@judiz.de>
Date: Wed, 15 Aug 2012 14:57:03 +0200
Message-id: <[🔎] 1345035423.4702.7.camel@ossietzky>
Reply-to: Michael Below <below@judiz.de>, 656196@bugs.debian.org
In-reply-to: <[🔎] 20120814162452.GA846@mannheim-rule.local>
References: <1343724921.5402.6.camel@ossietzky> <[🔎] 20120803004116.GB30701@copier> <[🔎] 1344961070.5629.41.camel@ossietzky> <[🔎] 20120814162452.GA846@mannheim-rule.local>
Am Dienstag, den 14.08.2012, 09:24 -0700 schrieb Jonathan Nieder:
> Michael Below wrote:
> 
> > Before I go on to test other kernels, one other possibility has appeared
> > to me: Maybe the 3.2 bug has been fixed through new CPU microcode? Is
> > that likely? Some days after installing the 3.4 kernel I noticed a
> > message about missing microcode and installed the relevant package. The
> > CPU/BIOS has version 0x01000086, the new version is 0x010000db. Should I
> > try if the error reappears when removing the microcode package?
> 
> If you have time, a quick check that you can still reproduce it,
> keeping the microcode and without idle=mwait, would be nice.

Yes, I just reproduced the stall, with the current 3.2 kernel from
testing and microcode installed, see below.

Cheers

Michael

Aug 15 14:41:28 ossietzky kernel: [16772.637060] INFO: rcu_sched detected stall on CPU 3 (t=74995 jiffies)
Aug 15 14:41:28 ossietzky kernel: [16772.637069] sending NMI to all CPUs:
Aug 15 14:41:28 ossietzky kernel: [16772.637048] NMI backtrace for cpu 1
Aug 15 14:41:28 ossietzky kernel: [16772.637048] CPU 1 
Aug 15 14:41:28 ossietzky kernel: [16772.637048] Modules linked in: nls_utf8 isofs cpufreq_conservative cpufreq_userspace cpufreq_powersave cpufreq_stats parport_pc ppdev lp parport bnep rfcomm bluetooth crc16 binfmt_misc ip6t_REJECT ip6t_LOG nf_conntrack_ipv6 nf_defrag_ipv6 ip6table_filter ip6_tables ipt_REJECT ipt_LOG xt_limit xt_tcpudp nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack iptable_filter ip_tables x_tables fuse smsc47b397 loop ecryptfs dm_crypt snd_hda_codec_analog snd_hda_intel snd_hda_codec snd_hwdep arc4 snd_pcm_oss snd_mixer_oss snd_pcm snd_page_alloc tpm_infineon snd_seq_midi snd_seq_midi_event snd_rawmidi radeon rt73usb rt2x00usb rt2x00lib mac80211 ttm cfg80211 drm_kms_helper crc_itu_t drm power_supply snd_seq snd_seq_device snd_timer i2c_algo_bit snd joydev hp_wmi soundcore sp5100_tco shpchp usbhid hid edac_mce_amd edac_core powernow_k8 sparse_keymap i2c_piix4 usb_storage uas rfkill i2c_core k10temp mperf button wmi evdev psmouse serio_raw pcspkr tpm_tis tpm tpm_bios processor thermal_sys
Aug 15 14:41:28 ossietzky kernel: ext3 mbcache jbd dm_mod microcode sr_mod sd_mod cdrom crc_t10dif ohci_hcd floppy ahci libahci ehci_hcd tg3 libphy libata scsi_mod usbcore usb_common [last unloaded: scsi_wait_scan]
Aug 15 14:41:28 ossietzky kernel: [16772.637048] 
Aug 15 14:41:28 ossietzky kernel: [16772.637048] Pid: 0, comm: swapper/1 Not tainted 3.2.0-3-amd64 #1 Hewlett-Packard HP Compaq dc5850 Microtower/3029h
Aug 15 14:41:28 ossietzky kernel: [16772.637048] RIP: 0010:[<ffffffff8134abe9>]  [<ffffffff8134abe9>] _raw_spin_lock_irqsave+0x1e/0x25
Aug 15 14:41:28 ossietzky kernel: [16772.637048] RSP: 0018:ffff88006d7d1ea8  EFLAGS: 00000097
Aug 15 14:41:28 ossietzky kernel: [16772.637048] RAX: 0000000000000046 RBX: ffffffff81789584 RCX: 000000000000cf05
Aug 15 14:41:28 ossietzky kernel: [16772.637048] RDX: 00000000cf05cf04 RSI: ffff88006d7d1ef4 RDI: ffffffff81789584
Aug 15 14:41:28 ossietzky kernel: [16772.637048] RBP: 0000000000000005 R08: 0000000000000000 R09: 0000000000000000
Aug 15 14:41:28 ossietzky kernel: [16772.637048] R10: 0000000000000293 R11: ffff88006d7d0000 R12: 0000000000000000
Aug 15 14:41:28 ossietzky kernel: [16772.637048] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
Aug 15 14:41:28 ossietzky kernel: [16772.637048] FS:  00007fa45d7b09a0(0000) GS:ffff88006fc80000(0000) knlGS:00000000f08fab70
Aug 15 14:41:28 ossietzky kernel: [16772.637048] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
Aug 15 14:41:28 ossietzky kernel: [16772.637048] CR2: 00003ebcb9ff4010 CR3: 0000000027259000 CR4: 00000000000006e0
Aug 15 14:41:28 ossietzky kernel: [16772.637048] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Aug 15 14:41:28 ossietzky kernel: [16772.637048] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Aug 15 14:41:28 ossietzky kernel: [16772.637048] Process swapper/1 (pid: 0, threadinfo ffff88006d7d0000, task ffff88006d7c20c0)
Aug 15 14:41:28 ossietzky kernel: [16772.637048] Stack:
Aug 15 14:41:28 ossietzky kernel: [16772.637048]  ffff88006d7d1ef4 ffffffff8106a3e6 0000000000000000 ffff88006d7d0000
Aug 15 14:41:28 ossietzky kernel: [16772.637048]  ffffffff8168d980 0000000000000000 0000000000000000 ffffffff8101461b
Aug 15 14:41:28 ossietzky kernel: [16772.637048]  0000000000000000 0000000100000000 0000000000000000 ffffffff8100d252
Aug 15 14:41:28 ossietzky kernel: [16772.637048] Call Trace:
Aug 15 14:41:28 ossietzky kernel: [16772.637048]  [<ffffffff8106a3e6>] ? clockevents_notify+0x1a/0x157
Aug 15 14:41:28 ossietzky kernel: [16772.637048]  [<ffffffff8101461b>] ? amd_e400_idle+0xd3/0xe4
Aug 15 14:41:28 ossietzky kernel: [16772.637048]  [<ffffffff8100d252>] ? cpu_idle+0xaf/0xf2
Aug 15 14:41:28 ossietzky kernel: [16772.637048]  [<ffffffff8107070e>] ? arch_local_irq_restore+0x2/0x8
Aug 15 14:41:28 ossietzky kernel: [16772.637048]  [<ffffffff8133d00a>] ? start_secondary+0x1d5/0x1db
Aug 15 14:41:28 ossietzky kernel: [16772.637048] Code: c0 0f 95 c0 0f b6 c0 c3 e9 82 5b d2 ff 53 48 89 fb e8 48 5b d2 ff ba 00 00 01 00 f0 0f c1 13 89 d1 c1 e9 10 66 39 ca 74 07 f3 90 <66> 8b 13 eb f4 5b c3 51 48 89 3c 24 e8 1a 5b d2 ff 48 8b 3c 24 
Aug 15 14:41:28 ossietzky kernel: [16772.637048] Call Trace:
Aug 15 14:41:28 ossietzky kernel: [16772.637048]  [<ffffffff8106a3e6>] ? clockevents_notify+0x1a/0x157
Aug 15 14:41:28 ossietzky kernel: [16772.637048]  [<ffffffff8101461b>] ? amd_e400_idle+0xd3/0xe4
Aug 15 14:41:28 ossietzky kernel: [16772.637048]  [<ffffffff8100d252>] ? cpu_idle+0xaf/0xf2
Aug 15 14:41:28 ossietzky kernel: [16772.637048]  [<ffffffff8107070e>] ? arch_local_irq_restore+0x2/0x8
Aug 15 14:41:28 ossietzky kernel: [16772.637048]  [<ffffffff8133d00a>] ? start_secondary+0x1d5/0x1db
Aug 15 14:41:28 ossietzky kernel: [16772.637602] NMI backtrace for cpu 3
Aug 15 14:41:28 ossietzky kernel: [16772.637606] CPU 3 
Aug 15 14:41:28 ossietzky dbus[2023]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper)
Aug 15 14:41:29 ossietzky rtkit-daemon[3079]: The canary thread is apparently starving. Taking action.
Aug 15 14:41:29 ossietzky rtkit-daemon[3079]: Demoting known real-time threads.
Aug 15 14:41:29 ossietzky rtkit-daemon[3079]: Successfully demoted thread 4197 of process 4197 (/usr/bin/pulseaudio).
Aug 15 14:41:29 ossietzky rtkit-daemon[3079]: Demoted 1 threads.
Aug 15 14:41:28 ossietzky kernel: [16772.637610] Modules linked in: nls_utf8 isofs cpufreq_conservative cpufreq_userspace cpufreq_powersave cpufreq_stats parport_pc ppdev lp parport bnep rfcomm bluetooth crc16 binfmt_misc ip6t_REJECT ip6t_LOG nf_conntrack_ipv6 nf_defrag_ipv6 ip6table_filter ip6_tables ipt_REJECT ipt_LOG xt_limit xt_tcpudp nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack iptable_filter ip_tables x_tables fuse smsc47b397 loop ecryptfs dm_crypt snd_hda_codec_analog snd_hda_intel snd_hda_codec snd_hwdep arc4 snd_pcm_oss snd_mixer_oss snd_pcm snd_page_alloc tpm_infineon snd_seq_midi snd_seq_midi_event snd_rawmidi radeon rt73usb rt2x00usb rt2x00lib mac80211 ttm cfg80211 drm_kms_helper crc_itu_t drm power_supply snd_seq snd_seq_device snd_timer i2c_algo_bit snd joydev hp_wmi soundcore sp5100_tco shpchp usbhid hid edac_mce_amd edac_core powernow_k8 sparse_keymap i2c_piix4 usb_storage uas rfkill i2c_core k10temp mperf button wmi evdev psmouse serio_raw pcspkr tpm_tis tpm tpm_bios processor thermal_sys
Aug 15 14:41:29 ossietzky kernel: ext3 mbcache jbd dm_mod microcode sr_mod sd_mod cdrom crc_t10dif ohci_hcd floppy ahci libahci ehci_hcd tg3 libphy libata scsi_mod usbcore usb_common [last unloaded: scsi_wait_scan]
Aug 15 14:41:29 ossietzky kernel: [16772.637789] 
Aug 15 14:41:29 ossietzky kernel: [16772.637796] Pid: 0, comm: swapper/3 Not tainted 3.2.0-3-amd64 #1 Hewlett-Packard HP Compaq dc5850 Microtower/3029h
Aug 15 14:41:29 ossietzky kernel: [16772.637808] RIP: 0010:[<ffffffff811b37e4>]  [<ffffffff811b37e4>] __bitmap_empty+0xc/0x52
Aug 15 14:41:29 ossietzky kernel: [16772.637826] RSP: 0018:ffff88006fd83d00  EFLAGS: 00000046
Aug 15 14:41:29 ossietzky kernel: [16772.637832] RAX: 0000000000000008 RBX: 0000000000002710 RCX: 0000000000000040
Aug 15 14:41:29 ossietzky kernel: [16772.637839] RDX: 0000000000000000 RSI: 0000000000000200 RDI: ffffffff8168d3e0
Aug 15 14:41:29 ossietzky kernel: [16772.637845] RBP: ffffffff81622180 R08: 0000000000000002 R09: 0000000000000001
Aug 15 14:41:29 ossietzky kernel: [16772.637851] R10: ffff88006fd8e980 R11: ffff88006fd8e980 R12: ffffffff81622280
Aug 15 14:41:29 ossietzky kernel: [16772.637858] R13: ffff88006fd83e30 R14: 7fffffffffffffff R15: ffffffff8106baf8
Aug 15 14:41:29 ossietzky kernel: [16772.637866] FS:  00007f15f9ed6720(0000) GS:ffff88006fd80000(0000) knlGS:00000000f601f710
Aug 15 14:41:29 ossietzky kernel: [16772.637873] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
Aug 15 14:41:29 ossietzky kernel: [16772.637879] CR2: 00007f0119750000 CR3: 0000000044cec000 CR4: 00000000000006e0
Aug 15 14:41:29 ossietzky kernel: [16772.637885] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Aug 15 14:41:29 ossietzky kernel: [16772.637892] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Aug 15 14:41:29 ossietzky kernel: [16772.637899] Process swapper/3 (pid: 0, threadinfo ffff88006cc18000, task ffff88006cc14f60)
Aug 15 14:41:29 ossietzky kernel: [16772.637904] Stack:
Aug 15 14:41:29 ossietzky kernel: [16772.637908]  ffffffff81024c0b ffff88006fd8edc0 ffffffff8109545c ffffffff810135ad
Aug 15 14:41:29 ossietzky kernel: [16772.637920]  ffffffff81013a1f ffffffff81013a2c 0000000000000003 0000000000000000
Aug 15 14:41:29 ossietzky kernel: [16772.637929]  0000000000000003 ffff88006fd83e30 7fffffffffffffff ffffffff8106baf8
Aug 15 14:41:29 ossietzky kernel: [16772.637939] Call Trace:
Aug 15 14:41:29 ossietzky kernel: [16772.637943]  <IRQ> 
Aug 15 14:41:29 ossietzky kernel: [16772.637956]  [<ffffffff81024c0b>] ? arch_trigger_all_cpu_backtrace+0x5e/0x7b
Aug 15 14:41:29 ossietzky kernel: [16772.637968]  [<ffffffff8109545c>] ? __rcu_pending+0x82/0x337
Aug 15 14:41:29 ossietzky kernel: [16772.637977]  [<ffffffff810135ad>] ? paravirt_read_tsc+0x5/0x8
Aug 15 14:41:29 ossietzky kernel: [16772.637985]  [<ffffffff81013a1f>] ? native_sched_clock+0x27/0x2f
Aug 15 14:41:29 ossietzky kernel: [16772.637993]  [<ffffffff81013a2c>] ? sched_clock+0x5/0x8
Aug 15 14:41:29 ossietzky kernel: [16772.638004]  [<ffffffff8106baf8>] ? tick_nohz_handler+0xd0/0xd0
Aug 15 14:41:29 ossietzky kernel: [16772.638013]  [<ffffffff81095a3e>] ? rcu_check_callbacks+0x90/0xcc
Aug 15 14:41:29 ossietzky kernel: [16772.638022]  [<ffffffff8105273b>] ? update_process_times+0x31/0x63
Aug 15 14:41:29 ossietzky kernel: [16772.638031]  [<ffffffff8106bb62>] ? tick_sched_timer+0x6a/0x90
Aug 15 14:41:29 ossietzky kernel: [16772.638040]  [<ffffffff81061e72>] ? __run_hrtimer+0xac/0x135
Aug 15 14:41:29 ossietzky kernel: [16772.638049]  [<ffffffff810625a2>] ? hrtimer_interrupt+0xdb/0x195
Aug 15 14:41:29 ossietzky kernel: [16772.638057]  [<ffffffff81013622>] ? read_tsc+0x5/0x14
Aug 15 14:41:29 ossietzky kernel: [16772.638066]  [<ffffffff8106af83>] ? tick_do_broadcast.constprop.4+0x3f/0x85
Aug 15 14:41:29 ossietzky kernel: [16772.638075]  [<ffffffff8106b085>] ? tick_handle_oneshot_broadcast+0xbc/0xfa
Aug 15 14:41:29 ossietzky kernel: [16772.638086]  [<ffffffff8100fecd>] ? timer_interrupt+0x15/0x1c
Aug 15 14:41:29 ossietzky kernel: [16772.638095]  [<ffffffff8109055d>] ? handle_irq_event_percpu+0x50/0x180
Aug 15 14:41:29 ossietzky kernel: [16772.638103]  [<ffffffff810906c1>] ? handle_irq_event+0x34/0x53
Aug 15 14:41:29 ossietzky kernel: [16772.638113]  [<ffffffff81092afa>] ? handle_edge_irq+0xa2/0xc9
Aug 15 14:41:29 ossietzky kernel: [16772.638121]  [<ffffffff8100f8a5>] ? handle_irq+0x1d/0x21
Aug 15 14:41:29 ossietzky kernel: [16772.638130]  [<ffffffff8100f5d5>] ? do_IRQ+0x42/0x98
Aug 15 14:41:29 ossietzky kernel: [16772.638141]  [<ffffffff8134aeae>] ? common_interrupt+0x6e/0x6e
Aug 15 14:41:29 ossietzky kernel: [16772.638146]  <EOI> 
Aug 15 14:41:29 ossietzky kernel: [16772.638154]  [<ffffffff8102b360>] ? native_safe_halt+0x2/0x3
Aug 15 14:41:29 ossietzky kernel: [16772.638163]  [<ffffffff81014510>] ? default_idle+0x47/0x7f
Aug 15 14:41:29 ossietzky kernel: [16772.638171]  [<ffffffff81014607>] ? amd_e400_idle+0xbf/0xe4
Aug 15 14:41:29 ossietzky kernel: [16772.638179]  [<ffffffff8100d252>] ? cpu_idle+0xaf/0xf2
Aug 15 14:41:29 ossietzky kernel: [16772.638188]  [<ffffffff8133d00a>] ? start_secondary+0x1d5/0x1db
Aug 15 14:41:29 ossietzky kernel: [16772.638193] Code: 24 20 4c 89 4c 24 48 c7 44 24 08 10 00 00 00 48 89 44 24 18 e8 5a ff ff ff 48 83 c4 58 c3 90 89 f0 b9 40 00 00 00 99 f7 f9 31 d2 <eb> 0b 48 ff c2 48 83 7c d7 f8 00 75 36 39 c2 7c f1 40 f6 c6 3f 
Aug 15 14:41:29 ossietzky kernel: [16772.638279] Call Trace:
Aug 15 14:41:29 ossietzky kernel: [16772.638282]  <IRQ>  [<ffffffff81024c0b>] ? arch_trigger_all_cpu_backtrace+0x5e/0x7b
Aug 15 14:41:29 ossietzky kernel: [16772.638299]  [<ffffffff8109545c>] ? __rcu_pending+0x82/0x337
Aug 15 14:41:29 ossietzky kernel: [16772.638307]  [<ffffffff810135ad>] ? paravirt_read_tsc+0x5/0x8
Aug 15 14:41:29 ossietzky kernel: [16772.638315]  [<ffffffff81013a1f>] ? native_sched_clock+0x27/0x2f
Aug 15 14:41:29 ossietzky kernel: [16772.638323]  [<ffffffff81013a2c>] ? sched_clock+0x5/0x8
Aug 15 14:41:29 ossietzky kernel: [16772.638332]  [<ffffffff8106baf8>] ? tick_nohz_handler+0xd0/0xd0
Aug 15 14:41:29 ossietzky kernel: [16772.638341]  [<ffffffff81095a3e>] ? rcu_check_callbacks+0x90/0xcc
Aug 15 14:41:29 ossietzky kernel: [16772.638349]  [<ffffffff8105273b>] ? update_process_times+0x31/0x63
Aug 15 14:41:29 ossietzky kernel: [16772.638358]  [<ffffffff8106bb62>] ? tick_sched_timer+0x6a/0x90
Aug 15 14:41:29 ossietzky kernel: [16772.638366]  [<ffffffff81061e72>] ? __run_hrtimer+0xac/0x135
Aug 15 14:41:29 ossietzky kernel: [16772.638375]  [<ffffffff810625a2>] ? hrtimer_interrupt+0xdb/0x195
Aug 15 14:41:29 ossietzky kernel: [16772.638383]  [<ffffffff81013622>] ? read_tsc+0x5/0x14
Aug 15 14:41:29 ossietzky kernel: [16772.638392]  [<ffffffff8106af83>] ? tick_do_broadcast.constprop.4+0x3f/0x85
Aug 15 14:41:29 ossietzky kernel: [16772.638401]  [<ffffffff8106b085>] ? tick_handle_oneshot_broadcast+0xbc/0xfa
Aug 15 14:41:29 ossietzky kernel: [16772.638411]  [<ffffffff8100fecd>] ? timer_interrupt+0x15/0x1c
Aug 15 14:41:29 ossietzky kernel: [16772.638419]  [<ffffffff8109055d>] ? handle_irq_event_percpu+0x50/0x180
Aug 15 14:41:29 ossietzky kernel: [16772.638428]  [<ffffffff810906c1>] ? handle_irq_event+0x34/0x53
Aug 15 14:41:29 ossietzky kernel: [16772.638436]  [<ffffffff81092afa>] ? handle_edge_irq+0xa2/0xc9
Aug 15 14:41:29 ossietzky kernel: [16772.638445]  [<ffffffff8100f8a5>] ? handle_irq+0x1d/0x21
Aug 15 14:41:29 ossietzky kernel: [16772.638454]  [<ffffffff8100f5d5>] ? do_IRQ+0x42/0x98
Aug 15 14:41:29 ossietzky kernel: [16772.638463]  [<ffffffff8134aeae>] ? common_interrupt+0x6e/0x6e
Aug 15 14:41:29 ossietzky kernel: [16772.638467]  <EOI>  [<ffffffff8102b360>] ? native_safe_halt+0x2/0x3
Aug 15 14:41:29 ossietzky kernel: [16772.638481]  [<ffffffff81014510>] ? default_idle+0x47/0x7f
Aug 15 14:41:29 ossietzky kernel: [16772.638490]  [<ffffffff81014607>] ? amd_e400_idle+0xbf/0xe4
Aug 15 14:41:29 ossietzky kernel: [16772.638498]  [<ffffffff8100d252>] ? cpu_idle+0xaf/0xf2
Aug 15 14:41:29 ossietzky kernel: [16772.638506]  [<ffffffff8133d00a>] ? start_secondary+0x1d5/0x1db
Aug 15 14:41:29 ossietzky kernel: [16772.637045] NMI backtrace for cpu 0
Aug 15 14:41:29 ossietzky kernel: [16772.637045] CPU 0 
Aug 15 14:41:29 ossietzky kernel: [16772.637045] Modules linked in: nls_utf8 isofs cpufreq_conservative cpufreq_userspace cpufreq_powersave cpufreq_stats parport_pc ppdev lp parport bnep rfcomm bluetooth crc16 binfmt_misc ip6t_REJECT ip6t_LOG nf_conntrack_ipv6 nf_defrag_ipv6 ip6table_filter ip6_tables ipt_REJECT ipt_LOG xt_limit xt_tcpudp nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack iptable_filter ip_tables x_tables fuse smsc47b397 loop ecryptfs dm_crypt snd_hda_codec_analog snd_hda_intel snd_hda_codec snd_hwdep arc4 snd_pcm_oss snd_mixer_oss snd_pcm snd_page_alloc tpm_infineon snd_seq_midi snd_seq_midi_event snd_rawmidi radeon rt73usb rt2x00usb rt2x00lib mac80211 ttm cfg80211 drm_kms_helper crc_itu_t drm power_supply snd_seq snd_seq_device snd_timer i2c_algo_bit snd joydev hp_wmi soundcore sp5100_tco shpchp usbhid hid edac_mce_amd edac_core powernow_k8 sparse_keymap i2c_piix4 usb_storage uas rfkill i2c_core k10temp mperf button wmi evdev psmouse serio_raw pcspkr tpm_tis tpm tpm_bios processor thermal_sys
Aug 15 14:41:29 ossietzky kernel: ext3 mbcache jbd dm_mod microcode sr_mod sd_mod cdrom crc_t10dif ohci_hcd floppy ahci libahci ehci_hcd tg3 libphy libata scsi_mod usbcore usb_common [last unloaded: scsi_wait_scan]
Aug 15 14:41:29 ossietzky kernel: [16772.637045] 
Aug 15 14:41:29 ossietzky kernel: [16772.637045] Pid: 0, comm: swapper/0 Not tainted 3.2.0-3-amd64 #1 Hewlett-Packard HP Compaq dc5850 Microtower/3029h
Aug 15 14:41:29 ossietzky kernel: [16772.637045] RIP: 0010:[<ffffffff8134abe9>]  [<ffffffff8134abe9>] _raw_spin_lock_irqsave+0x1e/0x25
Aug 15 14:41:29 ossietzky kernel: [16772.637045] RSP: 0018:ffffffff81601e08  EFLAGS: 00000097
Aug 15 14:41:29 ossietzky kernel: [16772.637045] RAX: 0000000000000002 RBX: ffffffff81789600 RCX: 000000000000c653
Aug 15 14:41:29 ossietzky kernel: [16772.637045] RDX: 00000000c653c652 RSI: 0000000000000005 RDI: ffffffff81789600
Aug 15 14:41:29 ossietzky kernel: [16772.637045] RBP: ffff88006fc0dc80 R08: 0000000000000000 R09: 0000000000000000
Aug 15 14:41:29 ossietzky kernel: [16772.637045] R10: 0000000000000293 R11: ffffffff81600000 R12: 0000000000000000
Aug 15 14:41:29 ossietzky kernel: [16772.637045] R13: ffffffff816151c0 R14: 0000000000000005 R15: 0000000000000000
Aug 15 14:41:29 ossietzky kernel: [16772.637045] FS:  00007fa448a4d700(0000) GS:ffff88006fc00000(0000) knlGS:00000000f601f710
Aug 15 14:41:29 ossietzky kernel: [16772.637045] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
Aug 15 14:41:29 ossietzky kernel: [16772.637045] CR2: 00007f0119750000 CR3: 0000000027259000 CR4: 00000000000006f0
Aug 15 14:41:29 ossietzky kernel: [16772.637045] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Aug 15 14:41:29 ossietzky kernel: [16772.637045] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Aug 15 14:41:29 ossietzky kernel: [16772.637045] Process swapper/0 (pid: 0, threadinfo ffffffff81600000, task ffffffff8160d020)
Aug 15 14:41:29 ossietzky kernel: [16772.637045] Stack:
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  ffffffff81601f14 ffffffff8106b410 ffffffff81601f14 0000000000000001
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  00000000ffffffff 0000000000000000 000000000008c800 ffffffff8106adc1
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  00000efb57bd2a4a ffff88006fc0dc80 ffff88006fc0e9c0 ffffffff81601f14
Aug 15 14:41:29 ossietzky kernel: [16772.637045] Call Trace:
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff8106b410>] ? tick_broadcast_oneshot_control+0x54/0x102
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff8106adc1>] ? tick_notify+0x210/0x367
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff8134dbd6>] ? notifier_call_chain+0x2e/0x5b
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff8106a3fb>] ? clockevents_notify+0x2f/0x157
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff8101461b>] ? amd_e400_idle+0xd3/0xe4
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff8100d252>] ? cpu_idle+0xaf/0xf2
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff816aab33>] ? start_kernel+0x3b3/0x3be
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff816aa140>] ? early_idt_handlers+0x140/0x140
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff816aa3c4>] ? x86_64_start_kernel+0x104/0x111
Aug 15 14:41:29 ossietzky kernel: [16772.637045] Code: c0 0f 95 c0 0f b6 c0 c3 e9 82 5b d2 ff 53 48 89 fb e8 48 5b d2 ff ba 00 00 01 00 f0 0f c1 13 89 d1 c1 e9 10 66 39 ca 74 07 f3 90 <66> 8b 13 eb f4 5b c3 51 48 89 3c 24 e8 1a 5b d2 ff 48 8b 3c 24 
Aug 15 14:41:29 ossietzky kernel: [16772.637045] Call Trace:
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff8106b410>] ? tick_broadcast_oneshot_control+0x54/0x102
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff8106adc1>] ? tick_notify+0x210/0x367
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff8134dbd6>] ? notifier_call_chain+0x2e/0x5b
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff8106a3fb>] ? clockevents_notify+0x2f/0x157
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff8101461b>] ? amd_e400_idle+0xd3/0xe4
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff8100d252>] ? cpu_idle+0xaf/0xf2
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff816aab33>] ? start_kernel+0x3b3/0x3be
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff816aa140>] ? early_idt_handlers+0x140/0x140
Aug 15 14:41:29 ossietzky kernel: [16772.637045]  [<ffffffff816aa3c4>] ? x86_64_start_kernel+0x104/0x111
Aug 15 14:41:29 ossietzky kernel: [16472.678096] NMI backtrace for cpu 2
Aug 15 14:41:29 ossietzky kernel: [16472.678096] CPU 2 
Aug 15 14:41:29 ossietzky kernel: [16472.678096] Modules linked in: nls_utf8 isofs cpufreq_conservative cpufreq_userspace cpufreq_powersave cpufreq_stats parport_pc ppdev lp parport bnep rfcomm bluetooth crc16 binfmt_misc ip6t_REJECT ip6t_LOG nf_conntrack_ipv6 nf_defrag_ipv6 ip6table_filter ip6_tables ipt_REJECT ipt_LOG xt_limit xt_tcpudp nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack iptable_filter ip_tables x_tables fuse smsc47b397 loop ecryptfs dm_crypt snd_hda_codec_analog snd_hda_intel snd_hda_codec snd_hwdep arc4 snd_pcm_oss snd_mixer_oss snd_pcm snd_page_alloc tpm_infineon snd_seq_midi snd_seq_midi_event snd_rawmidi radeon rt73usb rt2x00usb rt2x00lib mac80211 ttm cfg80211 drm_kms_helper crc_itu_t drm power_supply snd_seq snd_seq_device snd_timer i2c_algo_bit snd joydev hp_wmi soundcore sp5100_tco shpchp usbhid hid edac_mce_amd edac_core powernow_k8 sparse_keymap i2c_piix4 usb_storage uas rfkill i2c_core k10temp mperf button wmi evdev psmouse serio_raw pcspkr tpm_tis tpm tpm_bios processor thermal_sys
Aug 15 14:41:29 ossietzky kernel: ext3 mbcache jbd dm_mod microcode sr_mod sd_mod cdrom crc_t10dif ohci_hcd floppy ahci libahci ehci_hcd tg3 libphy libata scsi_mod usbcore usb_common [last unloaded: scsi_wait_scan]
Aug 15 14:41:29 ossietzky kernel: [16472.678096] 
Aug 15 14:41:29 ossietzky kernel: [16472.678096] Pid: 0, comm: swapper/2 Not tainted 3.2.0-3-amd64 #1 Hewlett-Packard HP Compaq dc5850 Microtower/3029h
Aug 15 14:41:29 ossietzky kernel: [16472.678096] RIP: 0010:[<ffffffff8102b360>]  [<ffffffff8102b360>] native_safe_halt+0x2/0x3
Aug 15 14:41:29 ossietzky kernel: [16472.678096] RSP: 0018:ffff88006cc05ed0  EFLAGS: 00000246
Aug 15 14:41:29 ossietzky kernel: [16472.678096] RAX: 0000000000000000 RBX: ffff88006cc04000 RCX: 0000000000000000
Aug 15 14:41:29 ossietzky kernel: [16472.678096] RDX: 0000000000000000 RSI: 0000000000000003 RDI: ffff88006cc04000
Aug 15 14:41:29 ossietzky kernel: [16472.678096] RBP: ffffffff8168d980 R08: 0000000000000000 R09: ffffffff8168d9c0
Aug 15 14:41:29 ossietzky kernel: [16472.678096] R10: 0000000000003685 R11: ffff88006cc04000 R12: 0000000000000000
Aug 15 14:41:29 ossietzky kernel: [16472.678096] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
Aug 15 14:41:29 ossietzky kernel: [16472.678096] FS:  00007f0120e87880(0000) GS:ffff88006fd00000(0000) knlGS:00000000f601f710
Aug 15 14:41:29 ossietzky kernel: [16472.678096] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
Aug 15 14:41:29 ossietzky kernel: [16472.678096] CR2: 00007f0119750000 CR3: 0000000036ccf000 CR4: 00000000000006e0
Aug 15 14:41:29 ossietzky kernel: [16472.678096] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Aug 15 14:41:29 ossietzky kernel: [16472.678096] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Aug 15 14:41:29 ossietzky kernel: [16472.678096] Process swapper/2 (pid: 0, threadinfo ffff88006cc04000, task ffff88006cc03610)
Aug 15 14:41:29 ossietzky kernel: [16472.678096] Stack:
Aug 15 14:41:29 ossietzky kernel: [16472.678096]  ffffffff81014510 ffffffff8168d9c0 ffffffff81014607 0000000000000000
Aug 15 14:41:29 ossietzky kernel: [16472.678096]  0000000200000000 0000000000000000 ffffffff8100d252 0000000000000000
Aug 15 14:41:29 ossietzky kernel: [16472.678096]  c7fbc89cd454193f 00000000f3f2782d 0000000000000002 0000000000000000
Aug 15 14:41:29 ossietzky kernel: [16472.678096] Call Trace:
Aug 15 14:41:29 ossietzky kernel: [16472.678096]  [<ffffffff81014510>] ? default_idle+0x47/0x7f
Aug 15 14:41:29 ossietzky kernel: [16472.678096]  [<ffffffff81014607>] ? amd_e400_idle+0xbf/0xe4
Aug 15 14:41:29 ossietzky kernel: [16472.678096]  [<ffffffff8100d252>] ? cpu_idle+0xaf/0xf2
Aug 15 14:41:29 ossietzky kernel: [16472.678096]  [<ffffffff8133d00a>] ? start_secondary+0x1d5/0x1db
Aug 15 14:41:29 ossietzky kernel: [16472.678096] Code: 89 e1 89 ee 48 c7 c7 e8 79 4c 81 31 c0 e8 73 92 31 00 48 83 c4 18 89 d8 5b 5d 41 5c 41 5d c3 9c 58 c3 57 9d c3 fa c3 fb c3 fb f4 <c3> f4 c3 66 66 66 90 66 66 90 c3 66 66 66 90 66 66 90 c3 0f 06 
Aug 15 14:41:29 ossietzky kernel: [16472.678096] Call Trace:
Aug 15 14:41:29 ossietzky kernel: [16472.678096]  [<ffffffff81014510>] ? default_idle+0x47/0x7f
Aug 15 14:41:29 ossietzky kernel: [16472.678096]  [<ffffffff81014607>] ? amd_e400_idle+0xbf/0xe4
Aug 15 14:41:29 ossietzky kernel: [16472.678096]  [<ffffffff8100d252>] ? cpu_idle+0xaf/0xf2
Aug 15 14:41:29 ossietzky kernel: [16472.678096]  [<ffffffff8133d00a>] ? start_secondary+0x1d5/0x1db
Aug 15 14:41:29 ossietzky kernel: [16772.640675] Clocksource tsc unstable (delta = 299966037813 ns)
Aug 15 14:41:29 ossietzky kernel: [16772.660316] Switching to clocksource hpet
Aug 15 14:41:30 ossietzky spamd[4784]: prefork: sysread(7) failed after 300 secs at /usr/share/perl5/Mail/SpamAssassin/SpamdForkScaling.pm line 654.
Aug 15 14:41:30 ossietzky spamd[4769]: Use of uninitialized value $selerr in concatenation (.) or string at /usr/share/perl5/Mail/SpamAssassin/SpamdForkScaling.pm line 332.
Aug 15 14:41:30 ossietzky spamd[10300]: prefork: sysread(7) failed after 300 secs at /usr/share/perl5/Mail/SpamAssassin/SpamdForkScaling.pm line 654.
Aug 15 14:41:30 ossietzky spamd[10299]: Use of uninitialized value $selerr in concatenation (.) or string at /usr/share/perl5/Mail/SpamAssassin/SpamdForkScaling.pm line 332.
Aug 15 14:41:30 ossietzky spamd[4769]: prefork: select returned error on server filehandle: 
Aug 15 14:41:30 ossietzky spamd[10299]: prefork: select returned error on server filehandle: 
Aug 15 14:41:30 ossietzky spamd[10301]: prefork: sysread(8) failed after 300 secs at /usr/share/perl5/Mail/SpamAssassin/SpamdForkScaling.pm line 654.
Aug 15 14:41:30 ossietzky spamd[10299]: prefork: child states: II
Aug 15 14:41:30 ossietzky spamd[4769]: prefork: child states: I
Aug 15 14:41:30 ossietzky spamd[10299]: prefork: child states: II
Aug 15 14:41:32 ossietzky spamd[4769]: spamd: handled cleanup of child pid [4784] due to SIGCHLD: exit 0
Aug 15 14:41:32 ossietzky spamd[4769]: spamd: server successfully spawned child process, pid 13586
Aug 15 14:41:32 ossietzky spamd[4769]: prefork: child states: I
Aug 15 14:41:32 ossietzky spamd[10299]: prefork: cannot ping 10301, file handle not defined, child likely to still be processing SIGCHLD handler after killing itself
Aug 15 14:41:32 ossietzky spamd[10299]: prefork: killing failed child 10301 fd=undefined at /usr/share/perl5/Mail/SpamAssassin/SpamdForkScaling.pm line 172.
Aug 15 14:41:32 ossietzky spamd[10299]: prefork: error closing socket: Bad file descriptor
Aug 15 14:41:32 ossietzky spamd[10299]: prefork: killed child 10301
Aug 15 14:41:32 ossietzky spamd[10299]: prefork: cannot ping 10300, file handle not defined, child likely to still be processing SIGCHLD handler after killing itself
Aug 15 14:41:32 ossietzky spamd[10299]: prefork: killing failed child 10300 fd=undefined at /usr/share/perl5/Mail/SpamAssassin/SpamdForkScaling.pm line 172.
Aug 15 14:41:32 ossietzky spamd[10299]: prefork: error closing socket: Bad file descriptor
Aug 15 14:41:32 ossietzky spamd[10299]: prefork: killed child 10300
Aug 15 14:41:32 ossietzky spamd[10299]: spamd: handled cleanup of child pid [10301] due to SIGCHLD: interrupted, signal 2 (0002)
Aug 15 14:41:32 ossietzky spamd[10299]: spamd: server successfully spawned child process, pid 13587
Aug 15 14:41:32 ossietzky spamd[10299]: spamd: handled cleanup of child pid [10300] due to SIGCHLD: interrupted, signal 2 (0002)
Aug 15 14:41:32 ossietzky spamd[10299]: prefork: child states: I
Aug 15 14:41:32 ossietzky spamd[10299]: spamd: server successfully spawned child process, pid 13588
Aug 15 14:41:32 ossietzky spamd[10299]: prefork: child states: II
Reply to:
References:
- Bug#656196: [2.6.39 -> 3.0 regression] kernel stalls every few days (rcu_sched_state detected stall on CPU x)
  - From: Jonathan Nieder <jrnieder@gmail.com>
- Bug#656196: [2.6.39 -> 3.0 regression] kernel stalls every few days (rcu_sched_state detected stall on CPU x)
  - From: Michael Below <below@judiz.de>
- Bug#656196: [2.6.39 -> 3.0 regression] kernel stalls every few days (rcu_sched_state detected stall on CPU x)
  - From: Jonathan Nieder <jrnieder@gmail.com>
Prev by Date: Bug#684978: Acknowledgement (linux-image-3.2.0-3-orion5x has i2c lock error in dmesg)
Next by Date: Bug#684293: installation-reports: Installer hangs at iso-scan step while mounting an extended partition
Previous by thread: Bug#656196: [2.6.39 -> 3.0 regression] kernel stalls every few days (rcu_sched_state detected stall on CPU x)
Next by thread: Bug#656196: [2.6.39 -> 3.0 regression] kernel stalls every few days (rcu_sched_state detected stall on CPU x)
Index(es):
- Date
- Thread