Re: 2.6.25-mm1: not looking good

Re: 2.6.25-mm1: not looking good

[Andrew Morton]

On Fri, 18 Apr 2008 00:50:34 -0700 Andrew Morton <akpm@linux-foundation.org> wrote:

> dmesg: http://userweb.kernel.org/~akpm/x.txt
> config: http://userweb.kernel.org/~akpm/config-t61p.txt

oop, there's more:


sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
firewire_core: created device fw0: GUID 00016c2000174bad, S400
PM: Device usb4 failed to restore: error -113
eth0: Link is Up 100 Mbps Full Duplex, Flow Control: RX/TX
eth0: 10/100 speed: disabling TSO
PM: Device usb5 failed to restore: error -113
PM: Device usb7 failed to restore: error -113
sd 0:0:0:0: [sda] Starting disk
PM: Image restored successfully.
Restarting tasks ... done.
PM: Basic memory bitmaps freed

Those USB restore failures are new.  They're similar to the ones on the
doesnt-resume-properly-any-more Vaio.  They came out from the machine's
second (successful) resume-from-disk.

Re: 2.6.25-mm1: not looking good

[Andrew Morton]

On Fri, 18 Apr 2008 00:53:23 -0700 Andrew Morton <akpm@linux-foundation.org> wrote:

> oop, there's more:

I found another machine!  This one's an old 4-way Nocona (x86_64)

http://userweb.kernel.org/~akpm/config-x.txt
http://userweb.kernel.org/~akpm/dmesg-x.txt



CPU: Physical Processor ID: 0
CPU: Processor Core ID: 0
CPU0: Thermal monitoring enabled (TM1)
ACPI: Core revision 20080321
Parsing all Control Methods:
Table [DSDT](id 0001) - 461 Objects with 50 Devices 130 Methods 11 Regions
 tbxface-0598 [00] tb_load_namespace     : ACPI Tables successfully acquired
evxfevnt-0091 [00] enable                : Transition to ACPI mode successful
------------[ cut here ]------------
WARNING: at arch/x86/kernel/genapic_64.c:86 read_apic_id+0x31/0x67()
Modules linked in:
Pid: 1, comm: swapper Not tainted 2.6.25-mm1 #16

Call Trace:
 [<ffffffff8025272f>] ? print_modules+0x88/0x8f
 [<ffffffff80233493>] warn_on_slowpath+0x58/0x81
 [<ffffffff80351ceb>] ? debug_spin_lock_after+0x18/0x1f
 [<ffffffff8035217a>] ? _raw_spin_lock+0x116/0x120
 [<ffffffff80228398>] ? sub_preempt_count+0x6d/0x74
 [<ffffffff804e9ba3>] ? _spin_unlock_irqrestore+0x33/0x40
 [<ffffffff803523e6>] ? debug_smp_processor_id+0x32/0xc4
 [<ffffffff8021ede5>] read_apic_id+0x31/0x67
 [<ffffffff8066f7f2>] verify_local_APIC+0xa7/0x163
 [<ffffffff8066e837>] native_smp_prepare_cpus+0x1ed/0x301
 [<ffffffff80669ab2>] kernel_init+0x5a/0x276
 [<ffffffff804e9a1e>] ? _spin_unlock_irq+0x2a/0x35
 [<ffffffff8022b7c2>] ? finish_task_switch+0x68/0x7f
 [<ffffffff8020c1d8>] child_rip+0xa/0x12
 [<ffffffff80669a58>] ? kernel_init+0x0/0x276
 [<ffffffff8020c1ce>] ? child_rip+0x0/0x12

---[ end trace 4eaa2a86a8e2da22 ]---
------------[ cut here ]------------
WARNING: at arch/x86/kernel/genapic_64.c:86 read_apic_id+0x31/0x67()
Modules linked in:
Pid: 1, comm: swapper Tainted: G        W 2.6.25-mm1 #16

Call Trace:
 [<ffffffff8025272f>] ? print_modules+0x88/0x8f
 [<ffffffff80233493>] warn_on_slowpath+0x58/0x81
 [<ffffffff80351ceb>] ? debug_spin_lock_after+0x18/0x1f
 [<ffffffff8035217a>] ? _raw_spin_lock+0x116/0x120
 [<ffffffff80228398>] ? sub_preempt_count+0x6d/0x74
 [<ffffffff804e9ba3>] ? _spin_unlock_irqrestore+0x33/0x40
 [<ffffffff803523e6>] ? debug_smp_processor_id+0x32/0xc4
 [<ffffffff8021ede5>] read_apic_id+0x31/0x67
 [<ffffffff8066f829>] verify_local_APIC+0xde/0x163
 [<ffffffff8066e837>] native_smp_prepare_cpus+0x1ed/0x301
 [<ffffffff80669ab2>] kernel_init+0x5a/0x276
 [<ffffffff804e9a1e>] ? _spin_unlock_irq+0x2a/0x35
 [<ffffffff8022b7c2>] ? finish_task_switch+0x68/0x7f
 [<ffffffff8020c1d8>] child_rip+0xa/0x12
 [<ffffffff80669a58>] ? kernel_init+0x0/0x276
 [<ffffffff8020c1ce>] ? child_rip+0x0/0x12

---[ end trace 4eaa2a86a8e2da22 ]---

That's

	WARN_ON(preemptible());

in read_apic_id().


Now I'll release it all.  heh.

Re: 2.6.25-mm1: not looking good

[Ingo Molnar]

* Andrew Morton <akpm@linux-foundation.org> wrote:

> WARNING: at arch/x86/kernel/genapic_64.c:86 read_apic_id+0x31/0x67()
>
> [<ffffffff803523e6>] ? debug_smp_processor_id+0x32/0xc4
> [<ffffffff8021ede5>] read_apic_id+0x31/0x67
> [<ffffffff8066f7f2>] verify_local_APIC+0xa7/0x163
> [<ffffffff8066e837>] native_smp_prepare_cpus+0x1ed/0x301
> [<ffffffff80669ab2>] kernel_init+0x5a/0x276

that came in via the UV-APIC patchset but the warning is entirely 
harmless. At that point we've got a single CPU running only so 
preemption of that code to another CPU is not possible.

native_smp_prepare_cpus() should probably just disable preemption, that 
way we could remove all those ugly preempt disable-enable calls from the 
called functions - per the patch below. (not boot tested yet - might 
provoke atomic-scheduling warnings if i forgot about some schedule point 
in this rather large codepath)

	Ingo

------------------->
Subject: x86: disable preemption in native_smp_prepare_cpus
From: Ingo Molnar <mingo@elte.hu>
Date: Fri Apr 18 11:07:10 CEST 2008

Signed-off-by: Ingo Molnar <mingo@elte.hu>
---
 arch/x86/kernel/smpboot.c |    2 ++
 1 file changed, 2 insertions(+)

Index: linux-x86.q/arch/x86/kernel/smpboot.c
===================================================================
--- linux-x86.q.orig/arch/x86/kernel/smpboot.c
+++ linux-x86.q/arch/x86/kernel/smpboot.c
@@ -1181,6 +1181,7 @@ static void __init smp_cpu_index_default
  */
 void __init native_smp_prepare_cpus(unsigned int max_cpus)
 {
+	preempt_disable();
 	nmi_watchdog_default();
 	smp_cpu_index_default();
 	current_cpu_data = boot_cpu_data;
@@ -1237,6 +1238,7 @@ void __init native_smp_prepare_cpus(unsi
 	printk(KERN_INFO "CPU%d: ", 0);
 	print_cpu_info(&cpu_data(0));
 	setup_boot_clock();
+	preempt_enable();
 }
 /*
  * Early setup to make printk work.

Re: 2.6.25-mm1: not looking good

[Pavel Machek]

On Fri 2008-04-18 00:53:23, Andrew Morton wrote:
> On Fri, 18 Apr 2008 00:50:34 -0700 Andrew Morton <akpm@linux-foundation.org> wrote:
> 
> > dmesg: http://userweb.kernel.org/~akpm/x.txt
> > config: http://userweb.kernel.org/~akpm/config-t61p.txt
> 
> oop, there's more:
> 
> 
> sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
> sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> firewire_core: created device fw0: GUID 00016c2000174bad, S400
> PM: Device usb4 failed to restore: error -113
> eth0: Link is Up 100 Mbps Full Duplex, Flow Control: RX/TX
> eth0: 10/100 speed: disabling TSO
> PM: Device usb5 failed to restore: error -113
> PM: Device usb7 failed to restore: error -113
> sd 0:0:0:0: [sda] Starting disk
> PM: Image restored successfully.
> Restarting tasks ... done.
> PM: Basic memory bitmaps freed
> 
> Those USB restore failures are new.  They're similar to the ones on the
> doesnt-resume-properly-any-more Vaio.  They came out from the machine's
> second (successful) resume-from-disk.

Try rmmod usb / insmod usb around suspend to see if it is
usb-specific, or if something went seriously wrong in core.

Or you might just bisect it ;-).
									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Re: 2.6.25-mm1: not looking good

[Pavel Machek]

Hi!

> On Fri, 18 Apr 2008 00:50:34 -0700 Andrew Morton <akpm@linux-foundation.org> wrote:
> 
> > dmesg: http://userweb.kernel.org/~akpm/x.txt
> > config: http://userweb.kernel.org/~akpm/config-t61p.txt
> 
> oop, there's more:
> 
> 
> sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
> sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> firewire_core: created device fw0: GUID 00016c2000174bad, S400
> PM: Device usb4 failed to restore: error -113
> eth0: Link is Up 100 Mbps Full Duplex, Flow Control: RX/TX
> eth0: 10/100 speed: disabling TSO
> PM: Device usb5 failed to restore: error -113
> PM: Device usb7 failed to restore: error -113
> sd 0:0:0:0: [sda] Starting disk
> PM: Image restored successfully.
> Restarting tasks ... done.
> PM: Basic memory bitmaps freed
> 
> Those USB restore failures are new.  They're similar to the ones on the
> doesnt-resume-properly-any-more Vaio.  They came out from the machine's
> second (successful) resume-from-disk.

I got USB messages after s2ram + suspend to disk combination, too, but
machine seems to work.

ata1.00: ACPI cmd ef/10:03:00:00:00:a0 succeeded
ata1.00: configured for UDMA/100
ata1.00: configured for UDMA/100
ata1: EH complete
sd 0:0:0:0: [sda] 117210240 512-byte hardware sectors (60012 MB)
sd 0:0:0:0: [sda] Write Protect is off
sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't
support DPO or FUA
sd 0:0:0:0: [sda] 117210240 512-byte hardware sectors (60012 MB)
sd 0:0:0:0: [sda] Write Protect is off
sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't
support DPO or FUA
PM: Device usb2 failed to restore: error -113
PM: Device usb3 failed to restore: error -113
PM: Device usb4 failed to restore: error -113
PM: Image restored successfully.
Restarting tasks ... done.
PM: Basic memory bitmaps freed
wlan0: RX disassociation from 00:11:2f:0e:95:a0 (reason=7)
wlan0: disassociated

(Apart from some wireless problems, solved by reconnecting...)

(And ipw3945 LED indication now seems to work, good!)
									Pavel 

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Re: 2.6.25-mm1: not looking good

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> Subject: x86: disable preemption in native_smp_prepare_cpus

that should be the patch below.

	Ingo

------------>
Subject: x86: disable preemption in native_smp_prepare_cpus
From: Ingo Molnar <mingo@elte.hu>
Date: Fri Apr 18 11:07:10 CEST 2008

Signed-off-by: Ingo Molnar <mingo@elte.hu>
---
 arch/x86/kernel/smpboot.c |    5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

Index: linux-x86.q/arch/x86/kernel/smpboot.c
===================================================================
--- linux-x86.q.orig/arch/x86/kernel/smpboot.c
+++ linux-x86.q/arch/x86/kernel/smpboot.c
@@ -1181,6 +1181,7 @@ static void __init smp_cpu_index_default
  */
 void __init native_smp_prepare_cpus(unsigned int max_cpus)
 {
+	preempt_disable();
 	nmi_watchdog_default();
 	smp_cpu_index_default();
 	current_cpu_data = boot_cpu_data;
@@ -1197,7 +1198,7 @@ void __init native_smp_prepare_cpus(unsi
 	if (smp_sanity_check(max_cpus) < 0) {
 		printk(KERN_INFO "SMP disabled\n");
 		disable_smp();
-		return;
+		goto out;
 	}
 
 	preempt_disable();
@@ -1237,6 +1238,8 @@ void __init native_smp_prepare_cpus(unsi
 	printk(KERN_INFO "CPU%d: ", 0);
 	print_cpu_info(&cpu_data(0));
 	setup_boot_clock();
+out:
+	preempt_enable();
 }
 /*
  * Early setup to make printk work.

Re: 2.6.25-mm1: not looking good

[Alan Stern]

On Fri, 18 Apr 2008, Pavel Machek wrote:

> On Fri 2008-04-18 00:53:23, Andrew Morton wrote:
> > On Fri, 18 Apr 2008 00:50:34 -0700 Andrew Morton <akpm@linux-foundation.org> wrote:
> > 
> > > dmesg: http://userweb.kernel.org/~akpm/x.txt
> > > config: http://userweb.kernel.org/~akpm/config-t61p.txt
> > 
> > oop, there's more:
> > 
> > 
> > sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
> > sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> > firewire_core: created device fw0: GUID 00016c2000174bad, S400
> > PM: Device usb4 failed to restore: error -113
> > eth0: Link is Up 100 Mbps Full Duplex, Flow Control: RX/TX
> > eth0: 10/100 speed: disabling TSO
> > PM: Device usb5 failed to restore: error -113
> > PM: Device usb7 failed to restore: error -113
> > sd 0:0:0:0: [sda] Starting disk
> > PM: Image restored successfully.
> > Restarting tasks ... done.
> > PM: Basic memory bitmaps freed
> > 
> > Those USB restore failures are new.  They're similar to the ones on the
> > doesnt-resume-properly-any-more Vaio.  They came out from the machine's
> > second (successful) resume-from-disk.
> 
> Try rmmod usb / insmod usb around suspend to see if it is
> usb-specific, or if something went seriously wrong in core.
> 
> Or you might just bisect it ;-).

There's no need to worry about them.  They merely indicate that the 
root hubs didn't resume along with everything else, because they were 
already suspended when the system went to sleep and so they were left 
suspended.  The return codes in usbcore will be changed soon so that 
this won't appear to be an error.

Alan Stern