Bug 10196

Marked as a regression.

alan@singularity:/sys/devices/system/cpu/cpu0/cpufreq$ cat scaling_available_frequencies
1067000 800000
alan@singularity:/sys/devices/system/cpu/cpu0/cpufreq$ cat /proc/cpuinfo
processor       : 0
vendor_id       : GenuineIntel
cpu family      : 6
model           : 15
model name      : Intel(R) Core(TM)2 CPU          6420  @ 2.13GHz
stepping        : 6
cpu MHz         : 1067.000
cache size      : 4096 KB
physical id     : 0
siblings        : 2
core id         : 0
cpu cores       : 2
fpu             : yes
fpu_exception   : yes
cpuid level     : 10
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx lm constant_tsc arch_perfmon pebs bts rep_good pni monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr lahf_lm
bogomips        : 2130.07
clflush size    : 64
cache_alignment : 64
address sizes   : 36 bits physical, 48 bits virtual
power management:

processor       : 1
vendor_id       : GenuineIntel
cpu family      : 6
model           : 15
model name      : Intel(R) Core(TM)2 CPU          6420  @ 2.13GHz
stepping        : 6
cpu MHz         : 800.000
cache size      : 4096 KB
physical id     : 0
siblings        : 2
core id         : 1
cpu cores       : 2
fpu             : yes
fpu_exception   : yes
cpuid level     : 10
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx lm constant_tsc arch_perfmon pebs bts rep_good pni monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr lahf_lm
bogomips        : 2128.08
clflush size    : 64
cache_alignment : 64
address sizes   : 36 bits physical, 48 bits virtual
power management:

alan@singularity:/sys/devices/system/cpu/cpu0/cpufreq$ cat scaling_driver
acpi-cpufreq

please make sure your kernel is compiled with CPU_FREQ_DEBUG=y, and boot with cpufreq.debug=7 This will cause cpufreq to log more information to dmesg on state transitions, which will be useful for diagnosis.

It'd also be interesting to know if this is still a problem with the latest -git tree.

Sorry, I wasn't entirely honest with you and it looks like I've been wasting your time.

I just rebooted and the BIOS messages agreed that the CPU was running at 1Ghz... immediately after claiming it was 8*266, which would give the correct figure (2.13 Ghz).  I was able to resolve the issue by turning the machine off at the plug, and then restarting it.  I've not been able to reproduce it again.  

I suspect this was caused by other problems (regressions) I've been having with 2.6.24.3.  Hibernation doesn't always power off properly; it hangs long after the disk LED goes out.  It resumes successfully though.  I also have large numbers of call traces reported, for no apparent reason.  I don't recognise them as OOPs or BUGs, though I've seen them being interleaved with soft lockup messages.

For completeness, I attach a log which includes two hibernation cycles, after which a number of these unrecognised call traces occur.  I don't think I've got the patience to get to the bottom of this, though I'd like to know what the call traces are supposed to be.

Created attachment 15176 [details]
System log with unrecognised call traces

I haven't worked out how to reproduce these call traces.

However, I was able to reproduce the hang after suspend to disk on version 2.6.25-rc4.  (Again, this apparent hang simply means that the machine does not power off automatically; it will still resume successfully).

Sometimes, but not always, this hang is associated with several screenfuls worth of soft lockup warnings (without call traces).  I cannot extract these warning messages using "dmesg" or similar - presumably because they happen at an awkward time during system suspend, when the system image has already been "frozen".

When I used 2.6.25-rc4 I also experienced at least one spontaneous hang.  The last time this happened:
i) I watched it for over a minute before rebooting - since the most recent soft-lockup warnings suggested that soft lockup detection  had a timeout of 61 seconds.  
ii) I was able to "soft reboot" the machine, i.e. using the reset button.  When it rebooted, the BIOS again claimed that the CPU was running at 1.0Ghz instead of 2.13Ghz.  As before, this resolved itself after a "hard reboot", i.e. after unplugging the machine.

Can you test that with 2.6.25-rc9 (or 2.6.25 final when it's out), please?

I can't right now because I'm in the wrong house.  I'll be back on Saturday, so I'll test it then.

OK, I retested with 2.6.25 final.

I successfully booted and hibernated twice.  I am continuing to use the system with 2.6.25 kernel to post this message.

As before, both times I hibernated, the system hung (requiring me to press the reset button) after writing the hibernation image.  The hard drive LED went out, but the power LED stayed on and the disk/fan noise stayed the same.

I couldn't see any console messages because I ran the buggy version of the Intel X driver shipped by Ubuntu.  When the distro scripts switch to the console, the screen just goes black.

When I checked the system logs, I find that the resume from the *second* hibernation is followed by a busload of these mysterious calltraces.

I also checked the CPU frequency after resume and that wasn't affected this time.

Created attachment 15820 [details]
2.6.25 final kernel config, as tested above

Created attachment 15821 [details]
System log for 2.6.25 (as above)

This is a complete system log showing the two hibernation cycles above.  It includes another spew of mysterious call traces after the second resume.  As before, they don't appear to be tagged as being OOPS/BUG/WARN whatever.

Attaching directly failed (I emailed the error message to bugme-admin@linux-foundation.org as requested).  This time I uploaded it on the web and attached it as a URL.  It is a large file - 271kb, so that may have been the problem.

These call traces apparently are related to a 'less' command.  What did you use 'less' for during the hibernation?

Heh.  Nothing fancy.

I was either using it to view /var/log/messages, or dmesg... in order to look for the mysterious call traces.  I supppose that's a possible explanation for why they didn't happen until after the second hibernation / resume cycle.

I could try hibernating without "less" running if you want.  Or I could boot in rescue mode, so there will be just bash running.  I don't remember whether I was able to reproduce it in rescue mode though.

Well, I'm just wondering why 'less' gave you those symptoms ...

The calltraces I have logged here for v2.6.24.3 show up in ksoftirqd/1.  I had other processes too (when I was trying to narrow down kernel versions).  So my opinion is that it's not significant which process this is happening in.

If you look at them side-by-side it looks more like the key features are
 - apic_timer_interrupt
 - do_softirq

I think that was generally true of the other calltraces I observed, but that there were also a few exceptions.

The plot thickens.

I bisected this a couple of times and got to 2.6.23-g06489b4e.
I tested this kernel by hibernating.  It didn't hang and powered off correctly.
However, the mysterious calltraces started happening when I resumed.  And this time, they didn't stop.  I have Intel C2D running at 2.13 Ghz, and according to top, 74-75% of CPU time is being spent in "si" (interrupt?), in klogd and syslogd - reporting these call traces.

The good thing about this is that a small number of these call traces appear to identify themselves - as soft-lockup reports:

[   83.758745]
[   83.761587] CPU 1:
[   83.761588] Modules linked in: battery ac thermal fan button i915 drm binfmt_misc ipv6 ppdev container acpi_cpufreq
dock cpufreq_stats cpufreq_powersave cpufreq_conservative cpufreq_userspace sbs coretemp it87 hwmon_vid lp snd_hda_intel snd_pcm_oss snd_mixer_oss snd_pcm snd_hwdep snd_seq_dummy snd_seq_oss snd_seq_midi snd_rawmidi snd_seq_mid3.779319] BUG: soft lockup - CPU#1 stuck for 11s! [swapper:0]
[   83.779321] CPU 1:

My guess is that all the calltraces are softlockup reports but that they get corrupted, perhaps because they come so close together.

As further evidence that this is mainly related to timer interrupts/softirq - (not the less program :-), all of these call traces are in the idle thread.

I'll see if I can suspend the system (to ram) in this state of continuous calltraces.  It might be difficult to reproduce, and maybe someone can think of something useful to try while it's doing this?

 [   83.758745]
 [   83.761587] CPU 1:
 [   83.761588] Modules linked in: battery ac thermal fan button i915 drm binfmt_misc ipv6 ppdev container acpi_cpufreq
dock cpufreq_stats cpufreq_powersave cpufreq_conservative cpufreq_userspace sbs coretemp it87 hwmon_vid lp snd_hda_intel snd_pcm_oss snd_mixer_oss snd_pcm

 [   83.779321] CPU 1:
 [   83.779322] Modules linked in: battery ac thermal fan button i915 drm binfmt_misc ipv6 ppdev container acpi_cpufreq
dock cpufreq_stats cpufreq_powersave cpufreq_conservative cpufreq_userspace sbs coretemp it87 hwmon_vid lp snd_hda_intel snd_pcm_oss snd_mixer_oss snd_pcm
snd_hwdep snd_seq_dummy snd_seq_oss snd_seq_midi snd_rawmidi snd_seq_midi_event snd_seq snd_timer snd_seq_device sr_mod cdrom serio_raw snd sg parport_pc p
arport soundcore psmouse floppy pcspkr af_packet evdev ext3 jbd mbcache sd_mod usbhid hid ata_piix iTCO_wdt iTCO_vendor_support ahci ata_generic ehci_hcd u
hci_hcd libata scsi_mod skge usbcore snd_page_alloc intel_agp processor fuse fbcon tileblit font bitblit softcursor
 [   83.779353] Pid: 0, comm: swapper Not tainted 2.6.23-g06489b4e #6
 [   83.779354] RIP: 0010:[__do_softirq+84/224]  [__do_softirq+84/224] __do_softirq+0x54/0xe0
 [   83.779357] RSP: 0018:ffff810001767f30  EFLAGS: 00000206
 [   83.779359] RAX: 0000000000000002 RBX: ffffffff8054dd00 RCX: 000000001350c53a
 [   83.779361] RDX: ffffffffb7f46ce5 RSI: ef39c54939ff773a RDI: 10c63af2c65b84b0
 [   83.779363] RBP: ffff810001767eb0 R08: 0000000016a56cb0 R09: 0000000000000010
 [   83.779364] R10: 0000000000000000 R11: ffffffff802592e0 R12: ffffffff8020ce66
 [   83.779366] R13: ffffffff805b9380 R14: 0000000000000002 R15: 0000000000000001
 [   83.779368] FS:  0000000000000000(0000) GS:ffff810001401300(0000) knlGS:0000000000000000
 [   83.779370] CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
 [   83.779372] CR2: 00002ace171eb040 CR3: 0000000000201000 CR4: 00000000000006a0
 [   83.779373] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
 [   83.779375] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
 [   83.779377]
 [   83.779377] Call Trace:
 [   83.779378]  <IRQ>  [call_softirq+28/48] call_softirq+0x1c/0x30
 [   83.779384]  [do_softirq+53/144] do_softirq+0x35/0x90
 [   83.779386]  [irq_exit+136/144] irq_exit+0x88/0x90
 [   83.779389]  [smp_apic_timer_interrupt+71/112] smp_apic_timer_interrupt+0x47/0x70
 [   83.779391]  [ksoftirqd+0/240] ksoftirqd+0x0/0xf0
 [   83.779394]  [apic_timer_interrupt+102/112] apic_timer_interrupt+0x66/0x70
 [   83.779396]  <EOI>  [lapic_next_event+0/16] lapic_next_event+0x0/0x10
 [   83.779402]  [read_tsc+31/48] read_tsc+0x1f/0x30
 [   83.779406]  [getnstimeofday+54/144] getnstimeofday+0x36/0x90
 [   83.779409]  [ktime_get_ts+30/96] ktime_get_ts+0x1e/0x60
 [   83.779412]  [ktime_get+12/80] ktime_get+0xc/0x50
 [   83.779415]  [tick_nohz_restart_sched_tick+0/320] tick_nohz_restart_sched_tick+0x0/0x140
 [   83.779418]  [tick_nohz_restart_sched_tick+54/320] tick_nohz_restart_sched_tick+0x36/0x140
 [   83.779420]  [mwait_idle+0/80] mwait_idle+0x0/0x50
 [   83.779423]  [cpu_idle+146/208] cpu_idle+0x92/0xd0
 [   83.779430]

Interestingly these calltraces seem to have stopped being written to the system log after the first 217Mb.  "tail -f /var/log/messages" has stopped showing anything (there are now a couple of MARKs after the last calltrace), but "top" still shows it hogging the cpu, and "watch -n 0.1 'dmesg|tail'" is still scrolling furiously.

Well, the monster didn't like STR (it hung).  It's not too difficult to reproduce though.  This time I hibernated twice.  After the first resume, the calltraces were in thunderbird-bin, and stopped very quickly.  On the second resume, the calltraces were in the idle thread again, and they didn't stop.  I now have 379 megs of (mostly) calltraces in /var/log/messages and growing.

So:

1) I've confirmed the existence of softlockup reports amongst the calltraces.  It's not clear cut though - surely you shouldn't get a softlockup report more frequently than once every ten seconds (or whatever the timeout period is)?  Yet these are much more frequent than that.

2) When I have time to continue bisection, I'll count the calltraces as "bad".  Even if, like 2.6.23-g06489b4e, it doesn't hang after hibernation.  The calltraces are bad enough by themselves - garbled, filling the system log, and potentially hogging most of my CPU if they don't stop.

Any other ideas would be very much welcome though.  I'm feeling out of my depth here.

Can you try 2.6.25 with CONFIG_CPU_IDLE unset, please?

The first time I tried it, it looked like it had fixed it (it powered off correctly after hibernating), but then X hung on resume.

When I tried again, it hung after hibernating (and then resumed successfully).
On the other hand, I didn't have calltraces.

I spoke to soon.  Just after I posted it locked up.  I used SysRq keys to reboot.  System log captured lots of backtraces, but no lockup messages.

Have you tried hibernation in the "shutdown" mode?

I think I tried that at some point.

I've just tried it now (on the 2.6.25 kernel with CONFIG_CPU_IDLE unset).  It hung on hibernation and locked up a minute or so after resume, although it didn't leave any calltraces in /var/log/messages.

Please attach the output of acpidump for your system.

Sorry, I'm still getting this attachment submission error on Bugzilla.  Therefore I upload it to <http://www-student.cs.york.ac.uk/~aj504/acpidump>.


You might like to know that this system was affected by Bug 8630.  That is, it has null entries in XDST which broke ACPI P-states.  The fix was to detect this and fall back to the RSDT, which had usable P-state info.  BTW the fix was present in 2.6.23 which is not affected by the current bug.

I don't think the XDST fix caused this, just letting you know the acpidump might look a bit odd.

any difference when you hibernate after booted with "nosmp"
and then boot with "maxcpus=1"?

can you clarify what was the latest version that worked
and the earliest that failed, and if the fix for bug 8630
was present in either, neither, or both?

I am highly confident that 2.6.23 worked and 2.6.24 failed.  I checked git and the fix for bug 8630 should be present in 2.6.23 and above.

I'm not so sure about my bisection because the nature of the failures is somewhat variable - although it seems straightforward to reproduce.  So far I've bisected it down to "300 revisions to test", between 

v2.6.23-5176-gfe071d7 and v2.6.23-5476-g5c8e191

Which I think means it started failing somewhere during the 2.6.23 merge window.

It [the 2.6.25 kernel with CONFIG_CPU_IDLE unset] doesn't work with nosmp.  The initrd dumps me at a emergency shell because it can't find the root device.

I'm using ahci, so I assume this is the same issue which came up on lkml recently.  Excuse my url. <http://groups.google.com/group/linux.kernel/browse_thread/thread/533a7c20f4b75b91/562e42ae6f60207b>

I'll retry with nosmp pci=nomsi.

If you were asking me to hibernate with "nosmp pci=nosmp" and resume with "maxcpus=1", then it hibernated fine but hung after resume, before switching back to X.

But hibernating and resuming with "nosmp pci=nomsi" works great.  No hangs or calltraces.  The same is true of "maxcpus=1".

Thanks for working on this.  I'm looking forward to having it fixed.

I did some more bisection.  Unfortunately I didn't pin down the commit responsible.  [It ended with a run of 8 good revisions, which is somewhat improbable.  It blamed v2.6.23-2600-g117494a, but checking out that commit and rebuilding it generated a "good" kernel].

Now I still had the "bad" kernel, as "2.6.23-g117494a.old".  There was one significant difference between "good" and "bad"; at some point during the bisection CONFIG_HIGH_RES_TIMERS had become unset (likely a mistake on my part).

I rebuilt again to be sure (to exclude a couple of other config changes which had crept in).  v2.6.23-2600-g117494a with a certain config and CONFIG_HIGH_RES_TIMERS=y is fine.  But v2.6.23-2600-g117494a with the exact same config except CONFIG_HIGH_RES_TIMERS *unset* is broken.  And the same is true of my 2.6.25; it was only broken because I'd built it with a particular configuration.  I think the problem is that I left CONFIG_HIGH_RES_TIMERS unset but selected CONFIG_NO_HZ=y.  If I deselect CONFIG_NO_HZ then there's no problem.

CONFIG_NO_HZ was added to x86_64 for 2.6.24, disabled by default, so this isn't a basic regression; it looks more like an unusual new configuration that didn't get hibernation tested.  

I don't have an alternative x86_64 machine, so it would be great if someone could reproduce on another machine using the "broken" 2.6.25 config I attached earlier.

BTW the broken kernel hung after hibernation.  It didn't show any calltraces.

Though I did notice processes apparently soft-locked in softirqs.  (I may not have waited long enough for the lockup detection to trigger).  When I resumed, "kicker" (kde panel) was at "9999% CPU" according to top, and 99.9% of CPU time was in state "si" - which I now assume means soft-interrupt.  I killed it, and after maybe 30 seconds it went away and I could restart it without problems.

I also noticed something new.  I started "konqueror" to try and report this.  After another half-minute or so, konqueror locked up in exactly the same way as kicker did.  So the lockup can affect processes started after resuming from hibernation.

Thomas [as hrtimer maintainer]: can you have a look at this please?
It took me a while to get down to the problem, but I think CONFIG_NO_HZ without CONFIG_HIGH_RES_TIMERS is broken with hibernation on x86_64.  The hibernation hangs after writing the image, although it resumes successfully.  After resume I get lockups in timer softirqs.  

The softlockup detector output is confused -  maybe because of other time-related problems?  Sometimes I get nothing.  Sometimes I get floods of calltraces which indicate timer softirqs.  Sometimes these calltraces include the occasional soft-lockup warning message, although most of them are bare calltraces - with no BUG, WARN, OOPS or lockup message.

These lockups can last long enough that the cpu time spent in softirqs is very visible - with top showing 99.9% time in state "si".

Sorry, I forgot one last thing in my summary:
The lockups also seem to go away with "maxcpus=1".  Also I think the calltraces are always on "CPU1".

So, as a wild guess, it might have something to do with the CPU hotplug code used by hibernation.

does the problem still exist in 2.6.27?

No.  Sorry, I lost track of the bug.  Whatever it was, 2.6.27 can hibernate fine with CONFIG_NO_HZ=y and CONFIG_HIGH_RES_TIMERS=n.