Re: [BUG] 2.6.21-rc1,2,3 regressions on my system that I found so far

On Saturday 17 March 2007 01:19:44 Len Brown wrote:
On Friday 16 March 2007 06:30, Maxim Levitsky wrote:

Good day,

I want to report regressions I have with 2.6.21-rc3 kernel.
I use CONFIG_NO_HZ.

Do any of these issues go away with CONFIG_NO_HZ=n (or boot with nohz=n)
or are they all independent of it?

thanks,
-Len

1) Both suspend to disk and suspend to RAM are completely broken:
On vanilla 2.6.20 suspend to disk works perfectly and suspend to ram works _almost_ perfectly (I will tell about that later).
On 2.6.21-rc1 and later system hangs even before suspend begins (suspend to disk hangs before image write , and after suspend to ram ,
some devices are powered down (disk,power leds) , and some and not(fans, power) , and system hangs).

I did a git-bisect and I found which commit caused that:
e3c7db621bed4afb8e231cb005057f2feb5db557 - [PATCH] [PATCH] PM: Change code ordering in main.c (breaks S3)
ed746e3b18f4df18afa3763155972c5835f284c5 - [PATCH] [PATCH] swsusp: Change code ordering in disk.c (breaks swsusp, I don't use it, but I tested it)
259130526c267550bc365d3015917d90667732f1 - [PATCH] [PATCH] swsusp: Change code ordering in user.c (breaks uswsusp, that I use)

I reverted those commits and now system suspends correctly to disk, but suspend to ram showed some more regressions.


2) ) After suspend to ram I get this

Mar 14 00:22:23 MAIN kernel: [ 2.072875] caller is check_tsc_sync_source+0x1d/0x100
Mar 14 00:22:23 MAIN kernel: [ 2.072878] [show_trace_log_lvl+26/48] show_trace_log_lvl+0x1a/0x30
Mar 14 00:22:23 MAIN kernel: [ 2.072881] [show_trace+18/32] show_trace+0x12/0x20
Mar 14 00:22:23 MAIN kernel: [ 2.072884] [dump_stack+22/32] dump_stack+0x16/0x20
Mar 14 00:22:23 MAIN kernel: [ 2.072887] [debug_smp_processor_id+173/176] debug_smp_processor_id+0xad/0xb0
Mar 14 00:22:23 MAIN kernel: [ 2.072891] [check_tsc_sync_source+29/256] check_tsc_sync_source+0x1d/0x100
Mar 14 00:22:23 MAIN kernel: [ 2.072894] [__cpu_up+80/384] __cpu_up+0x50/0x180
Mar 14 00:22:23 MAIN kernel: [ 2.072897] [_cpu_up+98/208] _cpu_up+0x62/0xd0
Mar 14 00:22:23 MAIN kernel: [ 2.072901] [cpu_up+46/80] cpu_up+0x2e/0x50
Mar 14 00:22:23 MAIN kernel: [ 2.072903] [enable_nonboot_cpus+110/160] enable_nonboot_cpus+0x6e/0xa0
Mar 14 00:22:23 MAIN kernel: [ 2.072906] [enter_state+326/496] enter_state+0x146/0x1f0
Mar 14 00:22:23 MAIN kernel: [ 2.072909] [state_store+174/192] state_store+0xae/0xc0
Mar 14 00:22:23 MAIN kernel: [ 2.072912] [subsys_attr_store+43/64] subsys_attr_store+0x2b/0x40
Mar 14 00:22:23 MAIN kernel: [ 2.072917] [sysfs_write_file+186/272] sysfs_write_file+0xba/0x110
Mar 14 00:22:23 MAIN kernel: [ 2.072920] [vfs_write+150/352] vfs_write+0x96/0x160
Mar 14 00:22:23 MAIN kernel: [ 2.072923] [sys_write+61/112] sys_write+0x3d/0x70
Mar 14 00:22:23 MAIN kernel: [ 2.072926] [sysenter_past_esp+93/153] sysenter_past_esp+0x5d/0x99
Mar 14 00:22:23 MAIN kernel: [ 2.072929] =======================
Mar 14 00:22:23 MAIN kernel: [ 2.072931] checking TSC synchronization [CPU#0 -> CPU#1]:
Mar 14 00:22:23 MAIN kernel: [ 2.092922] Measured 72051818872 cycles TSC warp between CPUs, turning off

It looks clear that preempt is enabled all the way in second cpu initialization, ( I think that at least in check_tsc_sync_source, it should be disabled,
shouldn't it ? )

Then I did add preempt_disable() / preempt_enable() to this function , and I still got this:

Mar 14 00:22:23 MAIN kernel: [ 2.072931] checking TSC synchronization [CPU#0 -> CPU#1]:
Mar 14 00:22:23 MAIN kernel: [ 2.092922] Measured 72051818872 cycles TSC warp between CPUs, turning off

It happens after second CPU is brought back on-line.

Now I understand that this is TSC sync problem and I tried to do some tests:

I tried to disable/enable second CPU by hand, eg I did number of times,

echo "0" > /sys/devices/system/cpu/cpu1/online
echo "1" > /sys/devices/system/cpu/cpu1/online

and TSC sync was ok.

Then I disabled 2nd CPU, have suspended system to RAM , resumed it , and then enabled 2nd CPU and got same error message.
Then I disabled cpufreq , and did above tests, and got same results.
I think that maybe this error is false, that there is some difference in TSC clock, but this difference is constant, and can be fixed

3) Sometimes I get this (once in three boots or so)

[ 36.217405] ENABLING IO-APIC IRQs
[ 36.217587] ..TIMER: vector=0x31 apic1=0 pin1=2 apic2=-1 pin2=-1
[ 36.433917] APIC timer disabled due to verification failure.

And NO_HZ is disabled due to that (I get 1000/s timer's interrupts)
I haven't investigated that yet.
It looks like another new test that my hardware fails to perform...


And now I want to tell you about that _almost_ working suspend to ram I got in 2.6.20:
To put it simply sometimes system wakes from resume, and sometimes not (about 1 in 5 times)
When it does it works perfectly.

This is quite common problem but ironically my case is very different and harder to solve.

The fact is that I found thanks to RTC tricks , similar to PM_TRACE that system hangs in exactly three places (in one of them of course)

I put between instructions, code like that to save a position in RTC alarm which is not cleared on reboot
Note that this code uses ax, but I checked every time I put it that ax can be used (eg, it is loaded in next instruction)

#define TRACE(val) \
movb $0x01, %al ; \
outb %al, $0x70 ; \
movb $ ## val, %al ; \
outb %al, $0x71

It hangs very early in asm code, and those are places:

1) /home/maxim/software/kernel/linux-2.6.20-mod/arch/i386/kernel/acpi/wakeup.S:wakeup_start:
ljmpl $__KERNEL_CS,$wakeup_pmode_return
As I see that is first time wakeup low page is addressing kernel memory by jumping to it.

2) /home/maxim/software/kernel/linux-2.6.20-mod/arch/i386/kernel/acpi/wakeup.S:do_suspend_lowlevel
call restore_registers
It hangs exacly on that instruction, I can only see that this is first time protected stack is accessed

3) /home/maxim/software/kernel/linux-2.6.20-mod/arch/i386/power/cpu.c :__restore_processor_state(struct saved_context *ctxt)
mtrr_ap_init();

It hangs somewhere inside this function, and because is is long I haven't found where exactly, it is easier to disable MTRR all together.

Note that all three places have different external behavier:

in first case, system powers on -> off -> on -> hangs
I did put test in RTC to see whenever BIOS call kernel twice but I know from this test for sure that it calls it only once,
It actualy makes sense, because exception occures before IDT is loaded, so system has no choice but to power down

in second case I see blinking leds -> almost sure a oops

in third case system just hangs

That's all, I will continue to dig those problems out

Thanks for attention,
Maxim Levitsky
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/



Issues that are caused by those

        e3c7db621bed4afb8e231cb005057f2feb5db557 - [PATCH] [PATCH] PM: Change code ordering in main.c (breaks  S3)
        ed746e3b18f4df18afa3763155972c5835f284c5 - [PATCH] [PATCH] swsusp: Change code ordering in disk.c (breaks swsusp, I don't use it, but I tested it)
        259130526c267550bc365d3015917d90667732f1 - [PATCH] [PATCH] swsusp: Change code ordering in user.c (breaks uswsusp, that I use)

doesn't go away, even worse, I tested latest Linus's git tree, and same hang both is suspend to disk and suspend to ram (before suspending)



Mar 14 00:22:23 MAIN kernel: [    2.072875] caller is check_tsc_sync_source+0x1d/0x100
Mar 14 00:22:23 MAIN kernel: [    2.072878]  [show_trace_log_lvl+26/48] show_trace_log_lvl+0x1a/0x30
Mar 14 00:22:23 MAIN kernel: [    2.072881]  [show_trace+18/32] show_trace+0x12/0x20
Mar 14 00:22:23 MAIN kernel: [    2.072884]  [dump_stack+22/32] dump_stack+0x16/0x20
Mar 14 00:22:23 MAIN kernel: [    2.072887]  [debug_smp_processor_id+173/176] debug_smp_processor_id+0xad/0x


^ This thing is fixed (sorry for bothering you)


Mar 14 00:22:23 MAIN kernel: [    2.072931] checking TSC synchronization [CPU#0 -> CPU#1]:
Mar 14 00:22:23 MAIN kernel: [    2.092922] Measured 72051818872 cycles TSC warp between CPUs, turning off

^ This one I don't think is related to NO_HZ, maybe it is hardware problem, but it exist without NO_HZ


[   36.217405] ENABLING IO-APIC IRQs
[   36.217587] ..TIMER: vector=0x31 apic1=0 pin1=2 apic2=-1 pin2=-1
[   36.433917] APIC timer disabled due to verification failure.

This one is now discussed, I will look at it and it is not related to NO_HZ

And hangs with S3 as I said occur even in 2.6.20


And I forgot to tell about another problem with (now I know ,hi-resolution timers)
That before suspend to ram APIC timer is used and HPET is not used :

root@MAIN:/home/maxim# cat /sys/devices/system/clockevents/clockevents0/registered
lapic F:0007 M:3(periodic) C: 1
hpet F:0003 M:1(shutdown) C: 0
lapic F:0007 M:3(periodic) C: 0
root@MAIN:/home/maxim#


But after suspend to ram HPET is 'woken'

root@MAIN:/home/maxim# cat /sys/devices/system/clockevents/clockevents0/registered
lapic F:0007 M:3(one shoot) C: 1
hpet F:0003 M:3(one shoot) C: 0
lapic F:0007 M:3(one shoot) C: 0

Note that I added those (one shoot), (periodic) descriptions, would be nice to have them in kernel, can I send a patch ? ;-)

and I see average of 18 IRQs/sec on IRQ 0


Best regards,
Maxim Levitsky

-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Relevant Pages

  • Re: [BUG] 2.6.21-rc1,2,3 regressions on my system that I found so far
    ... On vanilla 2.6.20 suspend to disk works perfectly and suspend to ram works _almost_ perfectly. ... It happens after second CPU is brought back on-line. ... The fact is that I found thanks to RTC tricks, similar to PM_TRACE that system hangs in exactly three places ... As I see that is first time wakeup low page is addressing kernel memory by jumping to it. ...
    (Linux-Kernel)
  • Re: [PATCH 0/2] Kexec jump: The first step to kexec base hibernation
    ... before kexec and restore them after kexec. ... is this idea to suspend, write to disk, but leave things in ram so that if you wakeup soon enough you have everything for ram, but if you don't and the battery dies you can restore from disk? ... For example, in the first stage of kernel boot, just first ...
    (Linux-Kernel)
  • Re: Suspend to RAM (FC4)
    ... which is x86_64 based laptop. ... > "suspend to RAM" issue. ... > That kernel parameter helped me to restore the monitor backlit. ...
    (Fedora)
  • [BUG] 2.6.21-rc1,2,3 regressions on my system that I found so far
    ... Both suspend to disk and suspend to RAM are completely broken: ... On vanilla 2.6.20 suspend to disk works perfectly and suspend to ram works _almost_ perfectly. ... The fact is that I found thanks to RTC tricks, similar to PM_TRACE that system hangs in exactly three places ...
    (Linux-Kernel)
  • Re: [linux-pm] Re: [PATCH 0/2] Kexec jump: The first step to kexec base hibernation
    ... leave things in ram so that if you wakeup soon enough you have everything ... when the battery gets low enough do the suspend to disk. ... Suppose the kexec kernel can't handle some device. ...
    (Linux-Kernel)