Ubuntu
linux package

Bug #286285
Comment #44

Comment 44 for bug 286285

Revision history for this message

Robb Topolski (funchords) wrote on 2008-11-02:

#44

Includes the first lines from bootup to two seconds worth of kern.log with info Edit (183.8 KiB, text/plain)

ISSUE: Woke up to fan running, CPUs busy -- TOP showed 'dd' was consuming the CPU. Had to kill tasks 5007 and 5009 to save off enough info to file this report before rebooting. kern.log was over 2 GB in size and last logged events were from 5 hours earlier, the same sequence of 11 lines. Reboot was normal and issue is not reoccuring. Some detailed data is below.

Linux topol015 2.6.27-7-generic #1 SMP Thu Oct 30 04:18:38 UTC 2008 i686 GNU/Linux

robb@topol015:~$ sudo ps auxf
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 5007 66.3 0.0 1940 548 ? R Nov01 347:50 /bin/dd bs 1 if /proc/kmsg of /var/run/klogd/kmsg
klog 5009 42.2 0.1 4240 2976 ? Ss Nov01 221:14 /sbin/klogd -P /var/run/klogd/kmsg

kill 5007
kill 5009

I think the key kern.log lines are these:

Nov 1 23:32:31 topol015 kernel: [ 78.808449] BUG: scheduling while atomic: swapper/0/0x00000100
Nov 1 23:32:31 topol015 kernel: [ 78.808466] Modules linked in: aes_i586 aes_generic af_packet binfmt_misc rfcomm bridge stp bnep sco l2cap bluetooth ppdev acpi_cpufreq cpufreq_ondemand cpufreq_userspace cpufreq_conservative cpufreq_stats freq_table cpufreq_powersave container sbs pci_slot sbshc iptable_filter ip_tables x_tables coretemp sbp2 parport_pc lp parport joydev snd_hda_intel snd_pcm_oss snd_mixer_oss snd_pcm arc4 ecb crypto_blkcipher snd_seq_dummy snd_seq_oss sdhci_pci uvcvideo iwlagn sdhci iwlcore compat_ioctl32 iTCO_wdt psmouse videodev mmc_core rfkill serio_raw evdev v4l1_compat snd_seq_midi iTCO_vendor_support pcspkr snd_rawmidi led_class nvidia(P) ricoh_mmc mac80211 snd_seq_midi_event snd_seq cfg80211 i2c_core snd_timer snd_seq_device snd video wmi button ac output battery soundcore intel_agp agpgart snd_page_alloc shpchp pci_hotplug ext3 jbd mbcache sr_mod cdrom ata_generic sd_mod crc_t10dif sg ata_piix pata_acpi ahci ohci1394 libata r8169 ieee1394 scsi_mod dock uhci_hcd ehci_hcd usbcore therma
Nov 1 23:32:31 topol015 kernel: processor fan fbcon tileblit font bitblit softcursor fuse
Nov 1 23:32:31 topol015 kernel: [ 78.808688]
Nov 1 23:32:31 topol015 kernel: [ 78.808695] Pid: 0, comm: swapper Tainted: P (2.6.27-7-generic #1)
Nov 1 23:32:31 topol015 kernel: [ 78.808703] EIP: 0060:[<f886c582>] EFLAGS: 00000246 CPU: 0
Nov 1 23:32:31 topol015 kernel: [ 78.808720] EIP is at acpi_idle_enter_c1+0x72/0x88 [processor]
Nov 1 23:32:31 topol015 kernel: [ 78.808726] EAX: 009f4d34 EBX: 009f2876 ECX: 00000001 EDX: 009f4d34
Nov 1 23:32:31 topol015 kernel: [ 78.808732] ESI: f7445bdc EDI: f744581c EBP: c04a7f90 ESP: c04a7f88
Nov 1 23:32:31 topol015 kernel: [ 78.808738] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
Nov 1 23:32:31 topol015 kernel: [ 78.808744] CR0: 8005003b CR2: b7ec60c0 CR3: 3581f000 CR4: 00000690
Nov 1 23:32:31 topol015 kernel: [ 78.808750] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
Nov 1 23:32:31 topol015 kernel: [ 78.808755] DR6: ffff0ff0 DR7: 00000400
Nov 1 23:32:31 topol015 kernel: [ 78.808761] [<c02dbf7b>] cpuidle_idle_call+0x7b/0xd0
Nov 1 23:32:31 topol015 kernel: [ 78.808773] [<c010288d>] cpu_idle+0x7d/0x140
Nov 1 23:32:31 topol015 kernel: [ 78.808782] [<c036edd3>] rest_init+0x53/0x60
Nov 1 23:32:31 topol015 kernel: [ 78.808794] =======================
Nov 1 23:32:31 topol015 kernel: [ 78.808801] bad: scheduling from the idle thread!
Nov 1 23:32:31 topol015 kernel: [ 78.808809] Pid: 0, comm: swapper Tainted: P 2.6.27-7-generic #1
Nov 1 23:32:31 topol015 kernel: [ 78.808814] [<c037c406>] ? printk+0x1d/0x1f
Nov 1 23:32:31 topol015 kernel: [ 78.808825] [<c0122b8a>] dequeue_task_idle+0x2a/0x40
Nov 1 23:32:31 topol015 kernel: [ 78.808834] [<c012107f>] dequeue_task+0xcf/0x130
Nov 1 23:32:31 topol015 kernel: [ 78.808844] [<c012112a>] deactivate_task+0x1a/0x30
Nov 1 23:32:31 topol015 kernel: [ 78.808853] [<c037ca23>] schedule+0x4b3/0x790
Nov 1 23:32:31 topol015 kernel: [ 78.808863] [<c012b6ab>] ? default_wake_function+0xb/0x10
Nov 1 23:32:31 topol015 kernel: [ 78.808873] [<c037e511>] ? _spin_lock_irqsave+0x31/0x40
Nov 1 23:32:31 topol015 kernel: [ 78.808884] [<c013c91c>] ? __mod_timer+0xac/0xf0
Nov 1 23:32:31 topol015 kernel: [ 78.808895] [<c037d0a4>] schedule_timeout+0x84/0xf0
Nov 1 23:32:31 topol015 kernel: [ 78.808903] [<c013c260>] ? process_timeout+0x0/0x10
Nov 1 23:32:31 topol015 kernel: [ 78.808913] [<c037d09f>] ? schedule_timeout+0x7f/0xf0
Nov 1 23:32:31 topol015 kernel: [ 78.808922] [<c037d12a>] schedule_timeout_uninterruptible+0x1a/0x20
Nov 1 23:32:31 topol015 kernel: [ 78.808932] [<c013c97d>] msleep+0x1d/0x30
Nov 1 23:32:31 topol015 kernel: [ 78.808941] [<f8b9eceb>] iwl_scan_cancel_timeout+0x4b/0x80 [iwlcore]
Nov 1 23:32:31 topol015 kernel: [ 78.808965] [<f8bceeb2>] iwl4965_mac_update_tkip_key+0x32/0xe0 [iwlagn]
Nov 1 23:32:31 topol015 kernel: [ 78.808984] [<f8aec10e>] ? tkip_mixing_phase1+0xe/0x140 [mac80211]
Nov 1 23:32:31 topol015 kernel: [ 78.809019] [<f8aec59c>] ieee80211_tkip_decrypt_data+0x16c/0x210 [mac80211]
Nov 1 23:32:31 topol015 kernel: [ 78.809051] [<f8ae3013>] ieee80211_crypto_tkip_decrypt+0xd3/0x120 [mac80211]
Nov 1 23:32:31 topol015 kernel: [ 78.809081] [<f8aee667>] ieee80211_rx_h_decrypt+0x187/0x1a0 [mac80211]
Nov 1 23:32:31 topol015 kernel: [ 78.809109] [<f8af0657>] ieee80211_invoke_rx_handlers+0xe7/0x2a0 [mac80211]
Nov 1 23:32:31 topol015 kernel: [ 78.809138] [<f8af010c>] __ieee80211_rx_handle_packet+0x21c/0x320 [mac80211]
Nov 1 23:32:31 topol015 kernel: [ 78.809168] [<f8af08c9>] __ieee80211_rx+0xb9/0x1c0 [mac80211]
Nov 1 23:32:31 topol015 kernel: [ 78.809197] [<f8adf316>] ieee80211_tasklet_handler+0xf6/0x120 [mac80211]
Nov 1 23:32:31 topol015 kernel: [ 78.809223] [<c0137258>] tasklet_action+0x78/0x100
Nov 1 23:32:31 topol015 kernel: [ 78.809232] [<c0137682>] __do_softirq+0x92/0x120
Nov 1 23:32:31 topol015 kernel: [ 78.809241] [<c013776d>] do_softirq+0x5d/0x60
Nov 1 23:32:31 topol015 kernel: [ 78.809249] [<c01378e5>] irq_exit+0x55/0x90
Nov 1 23:32:31 topol015 kernel: [ 78.809257] [<c0106c1a>] do_IRQ+0x4a/0x80
Nov 1 23:32:31 topol015 kernel: [ 78.809265] [<c0380ff5>] ? notifier_call_chain+0x35/0x70
Nov 1 23:32:31 topol015 kernel: [ 78.809276] [<c0105003>] common_interrupt+0x23/0x30
Nov 1 23:32:31 topol015 kernel: [ 78.809286] [<c01100d8>] ? set_mtrr_cache_disable+0x38/0x60
Nov 1 23:32:31 topol015 kernel: [ 78.809300] [<f886c582>] ? acpi_idle_enter_c1+0x72/0x88 [processor]
Nov 1 23:32:31 topol015 kernel: [ 78.809317] [<c02dbf7b>] cpuidle_idle_call+0x7b/0xd0
Nov 1 23:32:31 topol015 kernel: [ 78.809325] [<c010288d>] cpu_idle+0x7d/0x140
Nov 1 23:32:31 topol015 kernel: [ 78.809333] [<c036edd3>] rest_init+0x53/0x60
Nov 1 23:32:31 topol015 kernel: [ 78.809342] =======================
Nov 1 23:32:31 topol015 kernel: [ 78.812376] bad: scheduling from the idle thread!
Nov 1 23:32:31 topol015 kernel: [ 78.812376] Pid: 0, comm: swapper Tainted: P 2.6.27-7-generic #1
Nov 1 23:32:31 topol015 kernel: [ 78.812376] [<c037c406>] ? printk+0x1d/0x1f
Nov 1 23:32:31 topol015 kernel: [ 78.812376] [<c0122b8a>] dequeue_task_idle+0x2a/0x40
Nov 1 23:32:31 topol015 kernel: [ 78.812376] [<c012107f>] dequeue_task+0xcf/0x130
Nov 1 23:32:31 topol015 kernel: [ 78.812376] [<c012112a>] deactivate_task+0x1a/0x30
Nov 1 23:32:31 topol015 kernel: [ 78.812376] [<c037ca23>] schedule+0x4b3/0x790
Nov 1 23:32:31 topol015 kernel: [ 78.812376] [<c014a72d>] ? enqueue_hrtimer+0x7d/0x130
Nov 1 23:32:31 topol015 kernel: [ 78.812376] [<c014b474>] ? hrtimer_start+0xc4/0x1c0
Nov 1 23:32:31 topol015 kernel: [ 78.812376] [<c0153f02>] ? tick_nohz_restart_sched_tick+0x122/0x180
Nov 1 23:32:31 topol015 kernel: [ 78.812376] [<c01028cd>] cpu_idle+0xbd/0x140
Nov 1 23:32:31 topol015 kernel: [ 78.812376] [<c036edd3>] rest_init+0x53/0x60
Nov 1 23:32:31 topol015 kernel: [ 78.812376] =======================
...(these last 11 lines repeat over and over)...

There are some other corrupted-looking "dumps" into this log within a couple of seconds of kern.log, so I will attempt to attach the next few seconds of logs (2+ MB of text). Mostly it's the last 11 lines.

I have not installed the backports. It appears from reading this that I should try. I am using a D-Link DIR-655 (like another poster above). I'm using WPA+WPA2. I was connected at 802.11n when this occurred. I have experienced two "caps lock flashing" hard locks.

ISSUE: Woke up to fan running, CPUs busy -- TOP showed 'dd' was consuming the CPU. Had to kill tasks 5007 and 5009 to save off enough info to file this report before rebooting.  kern.log was over 2 GB in size and last logged events were from 5 hours earlier, the same sequence of 11 lines.  Reboot was normal and issue is not reoccuring.  Some detailed data is below.

Linux topol015 2.6.27-7-generic #1 SMP Thu Oct 30 04:18:38 UTC 2008 i686 GNU/Linux

robb@topol015:~$ sudo ps auxf
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root      5007 66.3  0.0   1940   548 ?        R    Nov01 347:50 /bin/dd bs 1 if /proc/kmsg of /var/run/klogd/kmsg
klog      5009 42.2  0.1   4240  2976 ?        Ss   Nov01 221:14 /sbin/klogd -P /var/run/klogd/kmsg

kill 5007
kill 5009

I think the key kern.log lines are these:

Nov  1 23:32:31 topol015 kernel: [   78.808449] BUG: scheduling while atomic: swapper/0/0x00000100
Nov  1 23:32:31 topol015 kernel: [   78.808466] Modules linked in: aes_i586 aes_generic af_packet binfmt_misc rfcomm bridge stp bnep sco l2cap bluetooth ppdev acpi_cpufreq cpufreq_ondemand cpufreq_userspace cpufreq_conservative cpufreq_stats freq_table cpufreq_powersave container sbs pci_slot sbshc iptable_filter ip_tables x_tables coretemp sbp2 parport_pc lp parport joydev snd_hda_intel snd_pcm_oss snd_mixer_oss snd_pcm arc4 ecb crypto_blkcipher snd_seq_dummy snd_seq_oss sdhci_pci uvcvideo iwlagn sdhci iwlcore compat_ioctl32 iTCO_wdt psmouse videodev mmc_core rfkill serio_raw evdev v4l1_compat snd_seq_midi iTCO_vendor_support pcspkr snd_rawmidi led_class nvidia(P) ricoh_mmc mac80211 snd_seq_midi_event snd_seq cfg80211 i2c_core snd_timer snd_seq_device snd video wmi button ac output battery soundcore intel_agp agpgart snd_page_alloc shpchp pci_hotplug ext3 jbd mbcache sr_mod cdrom ata_generic sd_mod crc_t10dif sg ata_piix pata_acpi ahci ohci1394 libata r8169 ieee1394 scsi_mod dock uhci_hcd ehci_hcd usbcore therma
Nov  1 23:32:31 topol015 kernel:  processor fan fbcon tileblit font bitblit softcursor fuse
Nov  1 23:32:31 topol015 kernel: [   78.808688] 
Nov  1 23:32:31 topol015 kernel: [   78.808695] Pid: 0, comm: swapper Tainted: P          (2.6.27-7-generic #1)
Nov  1 23:32:31 topol015 kernel: [   78.808703] EIP: 0060:[<f886c582>] EFLAGS: 00000246 CPU: 0
Nov  1 23:32:31 topol015 kernel: [   78.808720] EIP is at acpi_idle_enter_c1+0x72/0x88 [processor]
Nov  1 23:32:31 topol015 kernel: [   78.808726] EAX: 009f4d34 EBX: 009f2876 ECX: 00000001 EDX: 009f4d34
Nov  1 23:32:31 topol015 kernel: [   78.808732] ESI: f7445bdc EDI: f744581c EBP: c04a7f90 ESP: c04a7f88
Nov  1 23:32:31 topol015 kernel: [   78.808738]  DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
Nov  1 23:32:31 topol015 kernel: [   78.808744] CR0: 8005003b CR2: b7ec60c0 CR3: 3581f000 CR4: 00000690
Nov  1 23:32:31 topol015 kernel: [   78.808750] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
Nov  1 23:32:31 topol015 kernel: [   78.808755] DR6: ffff0ff0 DR7: 00000400
Nov  1 23:32:31 topol015 kernel: [   78.808761]  [<c02dbf7b>] cpuidle_idle_call+0x7b/0xd0
Nov  1 23:32:31 topol015 kernel: [   78.808773]  [<c010288d>] cpu_idle+0x7d/0x140
Nov  1 23:32:31 topol015 kernel: [   78.808782]  [<c036edd3>] rest_init+0x53/0x60
Nov  1 23:32:31 topol015 kernel: [   78.808794]  =======================
Nov  1 23:32:31 topol015 kernel: [   78.808801] bad: scheduling from the idle thread!
Nov  1 23:32:31 topol015 kernel: [   78.808809] Pid: 0, comm: swapper Tainted: P          2.6.27-7-generic #1
Nov  1 23:32:31 topol015 kernel: [   78.808814]  [<c037c406>] ? printk+0x1d/0x1f
Nov  1 23:32:31 topol015 kernel: [   78.808825]  [<c0122b8a>] dequeue_task_idle+0x2a/0x40
Nov  1 23:32:31 topol015 kernel: [   78.808834]  [<c012107f>] dequeue_task+0xcf/0x130
Nov  1 23:32:31 topol015 kernel: [   78.808844]  [<c012112a>] deactivate_task+0x1a/0x30
Nov  1 23:32:31 topol015 kernel: [   78.808853]  [<c037ca23>] schedule+0x4b3/0x790
Nov  1 23:32:31 topol015 kernel: [   78.808863]  [<c012b6ab>] ? default_wake_function+0xb/0x10
Nov  1 23:32:31 topol015 kernel: [   78.808873]  [<c037e511>] ? _spin_lock_irqsave+0x31/0x40
Nov  1 23:32:31 topol015 kernel: [   78.808884]  [<c013c91c>] ? __mod_timer+0xac/0xf0
Nov  1 23:32:31 topol015 kernel: [   78.808895]  [<c037d0a4>] schedule_timeout+0x84/0xf0
Nov  1 23:32:31 topol015 kernel: [   78.808903]  [<c013c260>] ? process_timeout+0x0/0x10
Nov  1 23:32:31 topol015 kernel: [   78.808913]  [<c037d09f>] ? schedule_timeout+0x7f/0xf0
Nov  1 23:32:31 topol015 kernel: [   78.808922]  [<c037d12a>] schedule_timeout_uninterruptible+0x1a/0x20
Nov  1 23:32:31 topol015 kernel: [   78.808932]  [<c013c97d>] msleep+0x1d/0x30
Nov  1 23:32:31 topol015 kernel: [   78.808941]  [<f8b9eceb>] iwl_scan_cancel_timeout+0x4b/0x80 [iwlcore]
Nov  1 23:32:31 topol015 kernel: [   78.808965]  [<f8bceeb2>] iwl4965_mac_update_tkip_key+0x32/0xe0 [iwlagn]
Nov  1 23:32:31 topol015 kernel: [   78.808984]  [<f8aec10e>] ? tkip_mixing_phase1+0xe/0x140 [mac80211]
Nov  1 23:32:31 topol015 kernel: [   78.809019]  [<f8aec59c>] ieee80211_tkip_decrypt_data+0x16c/0x210 [mac80211]
Nov  1 23:32:31 topol015 kernel: [   78.809051]  [<f8ae3013>] ieee80211_crypto_tkip_decrypt+0xd3/0x120 [mac80211]
Nov  1 23:32:31 topol015 kernel: [   78.809081]  [<f8aee667>] ieee80211_rx_h_decrypt+0x187/0x1a0 [mac80211]
Nov  1 23:32:31 topol015 kernel: [   78.809109]  [<f8af0657>] ieee80211_invoke_rx_handlers+0xe7/0x2a0 [mac80211]
Nov  1 23:32:31 topol015 kernel: [   78.809138]  [<f8af010c>] __ieee80211_rx_handle_packet+0x21c/0x320 [mac80211]
Nov  1 23:32:31 topol015 kernel: [   78.809168]  [<f8af08c9>] __ieee80211_rx+0xb9/0x1c0 [mac80211]
Nov  1 23:32:31 topol015 kernel: [   78.809197]  [<f8adf316>] ieee80211_tasklet_handler+0xf6/0x120 [mac80211]
Nov  1 23:32:31 topol015 kernel: [   78.809223]  [<c0137258>] tasklet_action+0x78/0x100
Nov  1 23:32:31 topol015 kernel: [   78.809232]  [<c0137682>] __do_softirq+0x92/0x120
Nov  1 23:32:31 topol015 kernel: [   78.809241]  [<c013776d>] do_softirq+0x5d/0x60
Nov  1 23:32:31 topol015 kernel: [   78.809249]  [<c01378e5>] irq_exit+0x55/0x90
Nov  1 23:32:31 topol015 kernel: [   78.809257]  [<c0106c1a>] do_IRQ+0x4a/0x80
Nov  1 23:32:31 topol015 kernel: [   78.809265]  [<c0380ff5>] ? notifier_call_chain+0x35/0x70
Nov  1 23:32:31 topol015 kernel: [   78.809276]  [<c0105003>] common_interrupt+0x23/0x30
Nov  1 23:32:31 topol015 kernel: [   78.809286]  [<c01100d8>] ? set_mtrr_cache_disable+0x38/0x60
Nov  1 23:32:31 topol015 kernel: [   78.809300]  [<f886c582>] ? acpi_idle_enter_c1+0x72/0x88 [processor]
Nov  1 23:32:31 topol015 kernel: [   78.809317]  [<c02dbf7b>] cpuidle_idle_call+0x7b/0xd0
Nov  1 23:32:31 topol015 kernel: [   78.809325]  [<c010288d>] cpu_idle+0x7d/0x140
Nov  1 23:32:31 topol015 kernel: [   78.809333]  [<c036edd3>] rest_init+0x53/0x60
Nov  1 23:32:31 topol015 kernel: [   78.809342]  =======================
Nov  1 23:32:31 topol015 kernel: [   78.812376] bad: scheduling from the idle thread!
Nov  1 23:32:31 topol015 kernel: [   78.812376] Pid: 0, comm: swapper Tainted: P          2.6.27-7-generic #1
Nov  1 23:32:31 topol015 kernel: [   78.812376]  [<c037c406>] ? printk+0x1d/0x1f
Nov  1 23:32:31 topol015 kernel: [   78.812376]  [<c0122b8a>] dequeue_task_idle+0x2a/0x40
Nov  1 23:32:31 topol015 kernel: [   78.812376]  [<c012107f>] dequeue_task+0xcf/0x130
Nov  1 23:32:31 topol015 kernel: [   78.812376]  [<c012112a>] deactivate_task+0x1a/0x30
Nov  1 23:32:31 topol015 kernel: [   78.812376]  [<c037ca23>] schedule+0x4b3/0x790
Nov  1 23:32:31 topol015 kernel: [   78.812376]  [<c014a72d>] ? enqueue_hrtimer+0x7d/0x130
Nov  1 23:32:31 topol015 kernel: [   78.812376]  [<c014b474>] ? hrtimer_start+0xc4/0x1c0
Nov  1 23:32:31 topol015 kernel: [   78.812376]  [<c0153f02>] ? tick_nohz_restart_sched_tick+0x122/0x180
Nov  1 23:32:31 topol015 kernel: [   78.812376]  [<c01028cd>] cpu_idle+0xbd/0x140
Nov  1 23:32:31 topol015 kernel: [   78.812376]  [<c036edd3>] rest_init+0x53/0x60
Nov  1 23:32:31 topol015 kernel: [   78.812376]  =======================
...(these last 11 lines repeat over and over)...

I have not installed the backports.  It appears from reading this that I should try.  I am using a D-Link DIR-655 (like another poster above).  I'm using WPA+WPA2. I was connected at 802.11n when this occurred.   I have experienced two "caps lock flashing" hard locks.

Ubuntulinux package

Comment 44 for bug 286285

Ubuntu
linux package