Crash when suspending Lenovo T510 laptop (2.6.39.3)

Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Jesper Juhl]

[-- Attachment #1: Type: TEXT/PLAIN, Size: 2795 bytes --]

Hi

I just experienced a kernel crash when trying to suspend my Lenovo 
Thinkpad T510 (model 4384-GJG) laptop.

Normally I just shut the lid and the little moon icon lights up telling me 
that the laptop has suspended. This time was different; the moon icon 
didn't light up as it usually does, so I opened the lid again and found a 
kernel crash dump on the screen. The machine was completely dead at this 
point, so all I could do was take a photo of the screen - nothing had made 
it to the log files either (checked after a reboot).

The image I took of the screen with the crash info is available here:
 http://personal.chaosbits.net/suspend-crash.jpg

The kernel version is 2.6.39.3
The kernel config is attached as '2.6.39.3-config.gz'
The distribution is Arch Linux 64bit.

Here is a partial transcript of the image (typed in manually, so check the 
image if you suspect an error - I also left out function addresses/offsets 
and other details before/after the backtrace to save me some typing, so 
check the image for the full details) :

Call Trace:
  ? wq_worker_sleeping
  schedule
  ? cfq_put_queue
  ? cic_free_func
  ? kmem_cache_free
  ? put_io_context
  do_exit
  oops_end
  die
  do_trap
  do_invalid_op
  ? free_msi_irqs
  ? find_busiest_group
  ? pci_conf1_write
  pci_disable_msi
  e1000e_reset_interrupt_capabillity
  __e1000_runtime_suspend
  ? __switch_to
  pci_pm_runtime_suspend
  ? pci_legacy_suspend_late
  rpm_callback
  ? schedule
  rpm_suspend
  ? linkwatch_do_dev
  ? pm_schedule_suspend
  pm_runtime_work
  process_one_work
  worker_thread
  ? manage_workers.isra.29
  kthread
  kernel_thread_helper
  ? kthread_worker
  ? gs_change

I've not experienced this before with this kernel, nor with earlier or 
newer ones, so it's not exactely reproducible on demand, so it's anyones 
guess when this was introduced (or if it's been there for ages, just 
triggers rarely)...

One detail that may be relevant; normally when I suspend the laptop I do 
so before unplugging any cables or suspend after not having anything 
plugged in for ages (or at all). This time I was in a hurry, so I quickly 
unplugged the power, 3 usb cables and the ethernet cable and then quickly 
slammed the lid shut. Not sure if that has an impact on triggering this 
though. I tried reproducing that scenario 4-5 times, but the laptop 
suspended fine when I did that.

If you require further information then please let me know and I'll be 
happy to provide it. 

I'll of course try to submit more details if it happens again, but if 
someone has a good guess as to how to provoke it or an idea for a fix I'd 
sure like to know.

-- 
Jesper Juhl <jj@chaosbits.net>       http://www.chaosbits.net/
Don't top-post http://www.catb.org/jargon/html/T/top-post.html
Plain text mails only, please.

[-- Attachment #2: Type: APPLICATION/octet-stream, Size: 30971 bytes --]

Re: Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Rafael J. Wysocki]

On Friday, August 05, 2011, Jesper Juhl wrote:
> Hi
> 
> I just experienced a kernel crash when trying to suspend my Lenovo 
> Thinkpad T510 (model 4384-GJG) laptop.
> 
> Normally I just shut the lid and the little moon icon lights up telling me 
> that the laptop has suspended. This time was different; the moon icon 
> didn't light up as it usually does, so I opened the lid again and found a 
> kernel crash dump on the screen. The machine was completely dead at this 
> point, so all I could do was take a photo of the screen - nothing had made 
> it to the log files either (checked after a reboot).
> 
> The image I took of the screen with the crash info is available here:
>  http://personal.chaosbits.net/suspend-crash.jpg
> 
> The kernel version is 2.6.39.3
> The kernel config is attached as '2.6.39.3-config.gz'
> The distribution is Arch Linux 64bit.
> 
> Here is a partial transcript of the image (typed in manually, so check the 
> image if you suspect an error - I also left out function addresses/offsets 
> and other details before/after the backtrace to save me some typing, so 
> check the image for the full details) :
> 
> Call Trace:
>   ? wq_worker_sleeping
>   schedule
>   ? cfq_put_queue
>   ? cic_free_func
>   ? kmem_cache_free
>   ? put_io_context
>   do_exit
>   oops_end
>   die
>   do_trap
>   do_invalid_op
>   ? free_msi_irqs
>   ? find_busiest_group
>   ? pci_conf1_write
>   pci_disable_msi
>   e1000e_reset_interrupt_capabillity
>   __e1000_runtime_suspend
>   ? __switch_to
>   pci_pm_runtime_suspend
>   ? pci_legacy_suspend_late
>   rpm_callback
>   ? schedule
>   rpm_suspend
>   ? linkwatch_do_dev
>   ? pm_schedule_suspend
>   pm_runtime_work
>   process_one_work
>   worker_thread
>   ? manage_workers.isra.29
>   kthread
>   kernel_thread_helper
>   ? kthread_worker
>   ? gs_change
> 
> I've not experienced this before with this kernel, nor with earlier or 
> newer ones, so it's not exactely reproducible on demand, so it's anyones 
> guess when this was introduced (or if it's been there for ages, just 
> triggers rarely)...
> 
> One detail that may be relevant; normally when I suspend the laptop I do 
> so before unplugging any cables or suspend after not having anything 
> plugged in for ages (or at all). This time I was in a hurry, so I quickly 
> unplugged the power, 3 usb cables and the ethernet cable and then quickly 
> slammed the lid shut. Not sure if that has an impact on triggering this 
> though. I tried reproducing that scenario 4-5 times, but the laptop 
> suspended fine when I did that.
> 
> If you require further information then please let me know and I'll be 
> happy to provide it. 
> 
> I'll of course try to submit more details if it happens again, but if 
> someone has a good guess as to how to provoke it or an idea for a fix I'd 
> sure like to know.

I don't know how to fix it yet, but I think I know what the problem is.
Namely, a runtime suspend of the Ethernet adapter as occured in parallel with
the system-wide suspend and they clashed.  The runtime suspend has probably
been provoked by detaching the Ethernet cable from the box.

Thanks,
Rafael

Re: Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Rafael J. Wysocki]

On Friday, August 05, 2011, Jesper Juhl wrote:
> Hi
> 
> I just experienced a kernel crash when trying to suspend my Lenovo 
> Thinkpad T510 (model 4384-GJG) laptop.
> 
> Normally I just shut the lid and the little moon icon lights up telling me 
> that the laptop has suspended. This time was different; the moon icon 
> didn't light up as it usually does, so I opened the lid again and found a 
> kernel crash dump on the screen. The machine was completely dead at this 
> point, so all I could do was take a photo of the screen - nothing had made 
> it to the log files either (checked after a reboot).
> 
> The image I took of the screen with the crash info is available here:
>  http://personal.chaosbits.net/suspend-crash.jpg
> 
> The kernel version is 2.6.39.3
> The kernel config is attached as '2.6.39.3-config.gz'
> The distribution is Arch Linux 64bit.
> 
> Here is a partial transcript of the image (typed in manually, so check the 
> image if you suspect an error - I also left out function addresses/offsets 
> and other details before/after the backtrace to save me some typing, so 
> check the image for the full details) :
> 
> Call Trace:
>   ? wq_worker_sleeping
>   schedule
>   ? cfq_put_queue
>   ? cic_free_func
>   ? kmem_cache_free
>   ? put_io_context
>   do_exit
>   oops_end
>   die
>   do_trap
>   do_invalid_op
>   ? free_msi_irqs
>   ? find_busiest_group
>   ? pci_conf1_write
>   pci_disable_msi
>   e1000e_reset_interrupt_capabillity
>   __e1000_runtime_suspend
>   ? __switch_to
>   pci_pm_runtime_suspend
>   ? pci_legacy_suspend_late
>   rpm_callback
>   ? schedule
>   rpm_suspend
>   ? linkwatch_do_dev
>   ? pm_schedule_suspend
>   pm_runtime_work
>   process_one_work
>   worker_thread
>   ? manage_workers.isra.29
>   kthread
>   kernel_thread_helper
>   ? kthread_worker
>   ? gs_change
> 
> I've not experienced this before with this kernel, nor with earlier or 
> newer ones, so it's not exactely reproducible on demand, so it's anyones 
> guess when this was introduced (or if it's been there for ages, just 
> triggers rarely)...
> 
> One detail that may be relevant; normally when I suspend the laptop I do 
> so before unplugging any cables or suspend after not having anything 
> plugged in for ages (or at all). This time I was in a hurry, so I quickly 
> unplugged the power, 3 usb cables and the ethernet cable and then quickly 
> slammed the lid shut. Not sure if that has an impact on triggering this 
> though. I tried reproducing that scenario 4-5 times, but the laptop 
> suspended fine when I did that.
> 
> If you require further information then please let me know and I'll be 
> happy to provide it. 
> 
> I'll of course try to submit more details if it happens again, but if 
> someone has a good guess as to how to provoke it or an idea for a fix I'd 
> sure like to know.

I don't know how to fix it yet, but I think I know what the problem is.
Namely, a runtime suspend of the Ethernet adapter as occured in parallel with
the system-wide suspend and they clashed.  The runtime suspend has probably
been provoked by detaching the Ethernet cable from the box.

Thanks,
Rafael

Re: [linux-pm] Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Alan Stern]

On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:

> On Friday, August 05, 2011, Jesper Juhl wrote:
> > Hi
> > 
> > I just experienced a kernel crash when trying to suspend my Lenovo 
> > Thinkpad T510 (model 4384-GJG) laptop.
> > 
> > Normally I just shut the lid and the little moon icon lights up telling me 
> > that the laptop has suspended. This time was different; the moon icon 
> > didn't light up as it usually does, so I opened the lid again and found a 
> > kernel crash dump on the screen. The machine was completely dead at this 
> > point, so all I could do was take a photo of the screen - nothing had made 
> > it to the log files either (checked after a reboot).
> > 
> > The image I took of the screen with the crash info is available here:
> >  http://personal.chaosbits.net/suspend-crash.jpg
> > 
> > The kernel version is 2.6.39.3
> > The kernel config is attached as '2.6.39.3-config.gz'
> > The distribution is Arch Linux 64bit.
> > 
> > Here is a partial transcript of the image (typed in manually, so check the 
> > image if you suspect an error - I also left out function addresses/offsets 
> > and other details before/after the backtrace to save me some typing, so 
> > check the image for the full details) :
> > 
> > Call Trace:
> >   ? wq_worker_sleeping
> >   schedule
> >   ? cfq_put_queue
> >   ? cic_free_func
> >   ? kmem_cache_free
> >   ? put_io_context
> >   do_exit
> >   oops_end
> >   die
> >   do_trap
> >   do_invalid_op
> >   ? free_msi_irqs
> >   ? find_busiest_group
> >   ? pci_conf1_write
> >   pci_disable_msi
> >   e1000e_reset_interrupt_capabillity
> >   __e1000_runtime_suspend
> >   ? __switch_to
> >   pci_pm_runtime_suspend
> >   ? pci_legacy_suspend_late
> >   rpm_callback
> >   ? schedule
> >   rpm_suspend
> >   ? linkwatch_do_dev
> >   ? pm_schedule_suspend
> >   pm_runtime_work
> >   process_one_work
> >   worker_thread
> >   ? manage_workers.isra.29
> >   kthread
> >   kernel_thread_helper
> >   ? kthread_worker
> >   ? gs_change
> > 
> > I've not experienced this before with this kernel, nor with earlier or 
> > newer ones, so it's not exactely reproducible on demand, so it's anyones 
> > guess when this was introduced (or if it's been there for ages, just 
> > triggers rarely)...
> > 
> > One detail that may be relevant; normally when I suspend the laptop I do 
> > so before unplugging any cables or suspend after not having anything 
> > plugged in for ages (or at all). This time I was in a hurry, so I quickly 
> > unplugged the power, 3 usb cables and the ethernet cable and then quickly 
> > slammed the lid shut. Not sure if that has an impact on triggering this 
> > though. I tried reproducing that scenario 4-5 times, but the laptop 
> > suspended fine when I did that.
> > 
> > If you require further information then please let me know and I'll be 
> > happy to provide it. 
> > 
> > I'll of course try to submit more details if it happens again, but if 
> > someone has a good guess as to how to provoke it or an idea for a fix I'd 
> > sure like to know.
> 
> I don't know how to fix it yet, but I think I know what the problem is.
> Namely, a runtime suspend of the Ethernet adapter as occured in parallel with
> the system-wide suspend and they clashed.  The runtime suspend has probably
> been provoked by detaching the Ethernet cable from the box.

For them to clash in that way would mean that the PM workqueue didn't
get frozen.  Is that possible?

Alan Stern

Re: [linux-pm] Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Rafael J. Wysocki]

On Friday, August 05, 2011, Alan Stern wrote:
> On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:
> 
> > On Friday, August 05, 2011, Jesper Juhl wrote:
> > > Hi
> > > 
> > > I just experienced a kernel crash when trying to suspend my Lenovo 
> > > Thinkpad T510 (model 4384-GJG) laptop.
> > > 
> > > Normally I just shut the lid and the little moon icon lights up telling me 
> > > that the laptop has suspended. This time was different; the moon icon 
> > > didn't light up as it usually does, so I opened the lid again and found a 
> > > kernel crash dump on the screen. The machine was completely dead at this 
> > > point, so all I could do was take a photo of the screen - nothing had made 
> > > it to the log files either (checked after a reboot).
> > > 
> > > The image I took of the screen with the crash info is available here:
> > >  http://personal.chaosbits.net/suspend-crash.jpg
> > > 
> > > The kernel version is 2.6.39.3
> > > The kernel config is attached as '2.6.39.3-config.gz'
> > > The distribution is Arch Linux 64bit.
> > > 
> > > Here is a partial transcript of the image (typed in manually, so check the 
> > > image if you suspect an error - I also left out function addresses/offsets 
> > > and other details before/after the backtrace to save me some typing, so 
> > > check the image for the full details) :
> > > 
> > > Call Trace:
> > >   ? wq_worker_sleeping
> > >   schedule
> > >   ? cfq_put_queue
> > >   ? cic_free_func
> > >   ? kmem_cache_free
> > >   ? put_io_context
> > >   do_exit
> > >   oops_end
> > >   die
> > >   do_trap
> > >   do_invalid_op
> > >   ? free_msi_irqs
> > >   ? find_busiest_group
> > >   ? pci_conf1_write
> > >   pci_disable_msi
> > >   e1000e_reset_interrupt_capabillity
> > >   __e1000_runtime_suspend
> > >   ? __switch_to
> > >   pci_pm_runtime_suspend
> > >   ? pci_legacy_suspend_late
> > >   rpm_callback
> > >   ? schedule
> > >   rpm_suspend
> > >   ? linkwatch_do_dev
> > >   ? pm_schedule_suspend
> > >   pm_runtime_work
> > >   process_one_work
> > >   worker_thread
> > >   ? manage_workers.isra.29
> > >   kthread
> > >   kernel_thread_helper
> > >   ? kthread_worker
> > >   ? gs_change
> > > 
> > > I've not experienced this before with this kernel, nor with earlier or 
> > > newer ones, so it's not exactely reproducible on demand, so it's anyones 
> > > guess when this was introduced (or if it's been there for ages, just 
> > > triggers rarely)...
> > > 
> > > One detail that may be relevant; normally when I suspend the laptop I do 
> > > so before unplugging any cables or suspend after not having anything 
> > > plugged in for ages (or at all). This time I was in a hurry, so I quickly 
> > > unplugged the power, 3 usb cables and the ethernet cable and then quickly 
> > > slammed the lid shut. Not sure if that has an impact on triggering this 
> > > though. I tried reproducing that scenario 4-5 times, but the laptop 
> > > suspended fine when I did that.
> > > 
> > > If you require further information then please let me know and I'll be 
> > > happy to provide it. 
> > > 
> > > I'll of course try to submit more details if it happens again, but if 
> > > someone has a good guess as to how to provoke it or an idea for a fix I'd 
> > > sure like to know.
> > 
> > I don't know how to fix it yet, but I think I know what the problem is.
> > Namely, a runtime suspend of the Ethernet adapter as occured in parallel with
> > the system-wide suspend and they clashed.  The runtime suspend has probably
> > been provoked by detaching the Ethernet cable from the box.
> 
> For them to clash in that way would mean that the PM workqueue didn't
> get frozen.

Not necessarily, I think.  It's sufficient that system suspend is started
while the runtime PM operation is in progress.

> Is that possible?

Shouldn't be.

Thanks,
Rafael

Re: [linux-pm] Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Alan Stern]

On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:

> > > I don't know how to fix it yet, but I think I know what the problem is.
> > > Namely, a runtime suspend of the Ethernet adapter as occured in parallel with
> > > the system-wide suspend and they clashed.  The runtime suspend has probably
> > > been provoked by detaching the Ethernet cable from the box.
> > 
> > For them to clash in that way would mean that the PM workqueue didn't
> > get frozen.
> 
> Not necessarily, I think.  It's sufficient that system suspend is started
> while the runtime PM operation is in progress.

How so?  The system suspend doesn't call down to the subsystems or 
drivers until after all the threads are frozen.  In this case the stack 
dump shows that the runtime PM operation was asynchronous, running in a 
workqueue thread (pm_runtime_work is one of the routines near the end 
of the stack dump).  The thread wouldn't have frozen until the runtime 
PM operation was complete.

Alan Stern

Re: Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Rafael J. Wysocki]

On Friday, August 05, 2011, Alan Stern wrote:
> On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:
> 
> > > > I don't know how to fix it yet, but I think I know what the problem is.
> > > > Namely, a runtime suspend of the Ethernet adapter as occured in parallel with
> > > > the system-wide suspend and they clashed.  The runtime suspend has probably
> > > > been provoked by detaching the Ethernet cable from the box.
> > > 
> > > For them to clash in that way would mean that the PM workqueue didn't
> > > get frozen.
> > 
> > Not necessarily, I think.  It's sufficient that system suspend is started
> > while the runtime PM operation is in progress.
> 
> How so?  The system suspend doesn't call down to the subsystems or 
> drivers until after all the threads are frozen.  In this case the stack 
> dump shows that the runtime PM operation was asynchronous, running in a 
> workqueue thread (pm_runtime_work is one of the routines near the end 
> of the stack dump).  The thread wouldn't have frozen until the runtime 
> PM operation was complete.

You're right, sorry.  System suspend was not involved, so the problem
was triggerend by runtime suspend alone, resulting from unplugging the
Ethernet cable.

It looks like the crash started in pci_disable_msi().

Thanks,
Rafael

Re: [linux-pm] Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Rafael J. Wysocki]

On Friday, August 05, 2011, Alan Stern wrote:
> On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:
> 
> > > > I don't know how to fix it yet, but I think I know what the problem is.
> > > > Namely, a runtime suspend of the Ethernet adapter as occured in parallel with
> > > > the system-wide suspend and they clashed.  The runtime suspend has probably
> > > > been provoked by detaching the Ethernet cable from the box.
> > > 
> > > For them to clash in that way would mean that the PM workqueue didn't
> > > get frozen.
> > 
> > Not necessarily, I think.  It's sufficient that system suspend is started
> > while the runtime PM operation is in progress.
> 
> How so?  The system suspend doesn't call down to the subsystems or 
> drivers until after all the threads are frozen.  In this case the stack 
> dump shows that the runtime PM operation was asynchronous, running in a 
> workqueue thread (pm_runtime_work is one of the routines near the end 
> of the stack dump).  The thread wouldn't have frozen until the runtime 
> PM operation was complete.

You're right, sorry.  System suspend was not involved, so the problem
was triggerend by runtime suspend alone, resulting from unplugging the
Ethernet cable.

It looks like the crash started in pci_disable_msi().

Thanks,
Rafael

Re: [linux-pm] Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Rafael J. Wysocki]

On Friday, August 05, 2011, Rafael J. Wysocki wrote:
> On Friday, August 05, 2011, Alan Stern wrote:
> > On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:
> > 
> > > > > I don't know how to fix it yet, but I think I know what the problem is.
> > > > > Namely, a runtime suspend of the Ethernet adapter as occured in parallel with
> > > > > the system-wide suspend and they clashed.  The runtime suspend has probably
> > > > > been provoked by detaching the Ethernet cable from the box.
> > > > 
> > > > For them to clash in that way would mean that the PM workqueue didn't
> > > > get frozen.
> > > 
> > > Not necessarily, I think.  It's sufficient that system suspend is started
> > > while the runtime PM operation is in progress.
> > 
> > How so?  The system suspend doesn't call down to the subsystems or 
> > drivers until after all the threads are frozen.  In this case the stack 
> > dump shows that the runtime PM operation was asynchronous, running in a 
> > workqueue thread (pm_runtime_work is one of the routines near the end 
> > of the stack dump).  The thread wouldn't have frozen until the runtime 
> > PM operation was complete.
> 
> You're right, sorry.  System suspend was not involved, so the problem
> was triggerend by runtime suspend alone, resulting from unplugging the
> Ethernet cable.
> 
> It looks like the crash started in pci_disable_msi().

OTOH, I'm not sure how pci_legacy_suspend_late() was called.
In theory it is only called by the system suspend code and it surely
is not called for e1000e.

Thanks,
Rafael

Re: Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Alan Stern]

On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:

> > You're right, sorry.  System suspend was not involved, so the problem
> > was triggerend by runtime suspend alone, resulting from unplugging the
> > Ethernet cable.
> > 
> > It looks like the crash started in pci_disable_msi().
> 
> OTOH, I'm not sure how pci_legacy_suspend_late() was called.
> In theory it is only called by the system suspend code and it surely
> is not called for e1000e.

The ? indicates that pci_legacy_suspend_late() wasn't necessarily on
the task's call stack; it may simply have been a leftover pointer from
some other operation, sitting somewhere in the middle of the stack
page.

Alan Stern

Re: [linux-pm] Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Alan Stern]

On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:

> > You're right, sorry.  System suspend was not involved, so the problem
> > was triggerend by runtime suspend alone, resulting from unplugging the
> > Ethernet cable.
> > 
> > It looks like the crash started in pci_disable_msi().
> 
> OTOH, I'm not sure how pci_legacy_suspend_late() was called.
> In theory it is only called by the system suspend code and it surely
> is not called for e1000e.

The ? indicates that pci_legacy_suspend_late() wasn't necessarily on
the task's call stack; it may simply have been a leftover pointer from
some other operation, sitting somewhere in the middle of the stack
page.

Alan Stern

Re: Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Jesper Juhl]

On Fri, 5 Aug 2011, Alan Stern wrote:

> On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:
> 
> > > You're right, sorry.  System suspend was not involved, so the problem
> > > was triggerend by runtime suspend alone, resulting from unplugging the
> > > Ethernet cable.
> > > 
> > > It looks like the crash started in pci_disable_msi().
> > 
> > OTOH, I'm not sure how pci_legacy_suspend_late() was called.
> > In theory it is only called by the system suspend code and it surely
> > is not called for e1000e.
> 
> The ? indicates that pci_legacy_suspend_late() wasn't necessarily on
> the task's call stack; it may simply have been a leftover pointer from
> some other operation, sitting somewhere in the middle of the stack
> page.
> 

Not sure if it helps, but I've been trying to reproduce the crash and 
although I've not succeeded doing that yet, I've got something else.

While trying to reproduce by unplugging/replugging ethernet and 
resuming/suspending a lot I found the following in dmesg after one of the 
resumes - the system seems to be working fine though and network works 
as well, so it's not the same complete crash but it looks 
potentially related :

[ 6564.921192] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100103, writing 0x100107)
[ 6564.921222] ehci_hcd 0000:00:1a.0: restoring config space at offset 0xf (was 0x400, writing 0x40b)
[ 6564.921240] ehci_hcd 0000:00:1a.0: restoring config space at offset 0x4 (was 0x0, writing 0xf2828000)
[ 6564.921247] ehci_hcd 0000:00:1a.0: restoring config space at offset 0x1 (was 0x2900000, writing 0x2900102)
[ 6564.937545] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
[ 6564.937554] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
[ 6564.937708] pcieport 0000:00:1c.1: restoring config space at offset 0x7 (was 0xf0, writing 0x200000f0)
[ 6564.937805] pcieport 0000:00:1c.4: restoring config space at offset 0xf (was 0x100, writing 0x4010b)
[ 6564.937815] pcieport 0000:00:1c.4: restoring config space at offset 0x9 (was 0x10001, writing 0x1fff1)
[ 6564.937820] pcieport 0000:00:1c.4: restoring config space at offset 0x8 (was 0x0, writing 0xf250f250)
[ 6564.937824] pcieport 0000:00:1c.4: restoring config space at offset 0x7 (was 0x20000000, writing 0x200000f0)
[ 6564.937832] pcieport 0000:00:1c.4: restoring config space at offset 0x3 (was 0x810000, writing 0x810010)
[ 6564.937838] pcieport 0000:00:1c.4: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
[ 6564.937872] ehci_hcd 0000:00:1d.0: restoring config space at offset 0xf (was 0x400, writing 0x40b)
[ 6564.937890] ehci_hcd 0000:00:1d.0: restoring config space at offset 0x4 (was 0x0, writing 0xf2828400)
[ 6564.937897] ehci_hcd 0000:00:1d.0: restoring config space at offset 0x1 (was 0x2900000, writing 0x2900102)
[ 6564.937915] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[ 6564.937918] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[ 6564.938019] ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00007, writing 0x2b00407)
[ 6564.938085] intel ips 0000:00:1f.6: restoring config space at offset 0xf (was 0x400, writing 0x40b)
[ 6564.938107] intel ips 0000:00:1f.6: restoring config space at offset 0x1 (was 0x100000, writing 0x100002)
[ 6564.938674] PM: early resume of devices complete after 17.784 msecs[ 6564.939048] sdhci-pci 0000:0d:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[ 6564.939053] iwlagn 0000:03:00.0: RF_KILL bit toggled to disable radio.
[ 6564.939118] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
[ 6564.942219] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
[ 6564.942229] pci 0000:00:1e.0: setting latency timer to 64
[ 6564.942236] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[ 6564.942246] HDA Intel 0000:00:1b.0: PCI INT B -> GSI 17 (level, low) -> IRQ 17
[ 6564.942253] HDA Intel 0000:00:1b.0: setting latency timer to 64
[ 6564.942261] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
[ 6564.942265] ahci 0000:00:1f.2: setting latency timer to 64
[ 6564.942276] ehci_hcd 0000:00:1a.0: PCI INT D -> GSI 23 (level, low) -> IRQ 23
[ 6564.942344] ehci_hcd 0000:00:1a.0: setting latency timer to 64
[ 6564.942360] HDA Intel 0000:00:1b.0: irq 44 for MSI/MSI-X
[ 6564.942436] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[ 6564.942444] ehci_hcd 0000:00:1d.0: PCI INT D -> GSI 19 (level, low) -> IRQ 19
[ 6564.942452] ehci_hcd 0000:00:1d.0: setting latency timer to 64
[ 6564.942456] sd 0:0:0:0: [sda] Starting disk
[ 6564.942458] i915 0000:00:02.0: power state changed by ACPI to D0
[ 6564.942463] i915 0000:00:02.0: power state changed by ACPI to D0
[ 6564.942466] i915 0000:00:02.0: setting latency timer to 64
[ 6564.997449] firewire_ohci 0000:0d:00.3: irq 45 for MSI/MSI-X
[ 6564.997785] firewire_core: skipped bus generations, destroying all nodes
[ 6565.123881] usb 2-1.1: reset full speed USB device number 3 using ehci_hcd
[ 6565.256738] ata6: SATA link down (SStatus 0 SControl 300)
[ 6565.256782] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[ 6565.259348] ata2.00: ACPI cmd e3/00:1f:00:00:00:a0 (IDLE) succeeded
[ 6565.259563] ata2.00: ACPI cmd e3/00:02:00:00:00:a0 (IDLE) succeeded
[ 6565.263747] ata2.00: ACPI cmd e3/00:1f:00:00:00:a0 (IDLE) succeeded
[ 6565.263990] ata2.00: ACPI cmd e3/00:02:00:00:00:a0 (IDLE) succeeded
[ 6565.265544] ata2.00: configured for UDMA/66
[ 6565.276723] ata5: SATA link down (SStatus 0 SControl 300)
[ 6565.439619] sdhci-pci 0000:0d:00.0: Will use DMA mode even though HW doesn't fully claim to support it.
[ 6565.439631] sdhci-pci 0000:0d:00.0: setting latency timer to 64
[ 6565.463009] usb 1-1.2: reset low speed USB device number 3 using ehci_hcd
[ 6565.496163] firewire_core: rediscovered device fw0
[ 6565.802321] usb 1-1.3: reset full speed USB device number 4 using ehci_hcd
[ 6565.951782] usb 1-1.6: reset high speed USB device number 6 using ehci_hcd
[ 6566.014871] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 6566.021871] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[ 6566.021877] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[ 6566.022178] ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 (SET FEATURES) succeeded
[ 6566.022183] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[ 6566.024813] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[ 6566.024819] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[ 6566.025080] ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 (SET FEATURES) succeeded
[ 6566.025085] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[ 6566.026327] ata1.00: configured for UDMA/100
[ 6566.104911] usb 2-1.1.4: reset full speed USB device number 4 using ehci_hcd
[ 6566.190354] PM: resume of devices complete after 1254.565 msecs
[ 6566.191321] PM: Finishing wakeup.
[ 6566.191323] Restarting tasks ... done.
[ 6566.199706] video LNXVIDEO:00: Restoring backlight state
[ 6566.661832] e1000e: eth0 NIC Link is Up 100 Mbps Full Duplex, Flow Control: Rx
[ 6566.661839] e1000e 0000:00:19.0: eth0: 10/100 speed: disabling TSO
[ 6566.662160] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[ 6568.525731] e1000e 0000:00:19.0: PME# enabled
[ 6568.551863] e1000e 0000:00:19.0: BAR 0: set to [mem 0xf2600000-0xf261ffff] (PCI address [0xf2600000-0xf261ffff])
[ 6568.551876] e1000e 0000:00:19.0: BAR 1: set to [mem 0xf2625000-0xf2625fff] (PCI address [0xf2625000-0xf2625fff])
[ 6568.551886] e1000e 0000:00:19.0: BAR 2: set to [io  0x1820-0x183f] (PCI address [0x1820-0x183f])
[ 6568.551909] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[ 6568.551936] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
[ 6568.551999] e1000e 0000:00:19.0: PME# disabled
[ 6568.645183] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
[ 6568.698271] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
[ 6568.699163] ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 6568.814811] e1000e 0000:00:19.0: PME# enabled
[ 6568.844535] e1000e 0000:00:19.0: BAR 0: set to [mem 0xf2600000-0xf261ffff] (PCI address [0xf2600000-0xf261ffff])
[ 6568.844548] e1000e 0000:00:19.0: BAR 1: set to [mem 0xf2625000-0xf2625fff] (PCI address [0xf2625000-0xf2625fff])
[ 6568.844558] e1000e 0000:00:19.0: BAR 2: set to [io  0x1820-0x183f] (PCI address [0x1820-0x183f])
[ 6568.844580] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[ 6568.844607] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100507)
[ 6568.844668] e1000e 0000:00:19.0: PME# disabled
[ 6568.937809] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
[ 6568.990871] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
[ 6568.991756] ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 6569.991674] ------------[ cut here ]------------
[ 6569.991694] WARNING: at drivers/net/e1000e/netdev.c:5221 __e1000_shutdown+0x43f/0x4c0 [e1000e]()
[ 6569.991698] Hardware name: 4384GJG
[ 6569.991699] Modules linked in: snd_seq snd_seq_device aesni_intel cryptd aes_x86_64 aes_generic ipv6 uvcvideo videodev media v4l2_compat_ioctl32 usbhid hid snd_hda_codec_hdmi btusb bluetooth snd_hda_codec_conexant arc4 ecb snd_hda_intel snd_hda_codec snd_hwdep e1000e i915 snd_pcm iwlagn ehci_hcd snd_timer drm_kms_helper usbcore snd_page_alloc sdhci_pci sdhci pcspkr mmc_core sg drm vboxnetadp vboxnetflt evdev tpm_tis i2c_algo_bit mac80211 serio_raw psmouse iTCO_wdt vboxdrv firewire_ohci firewire_core i2c_i801 crc_itu_t i2c_core iTCO_vendor_support cfg80211 battery thermal intel_ips wmi tpm intel_agp video ac tpm_bios button intel_gtt cpufreq_ondemand msr acpi_cpufreq freq_table processor mperf thinkpad_acpi rfkill snd soundcore nvram ext4 mbcache jbd2 crc16 sr_mod sd_mod cdrom ahci libah
 ci libata scsi_mod
[ 6569.991778] Pid: 7847, comm: kworker/1:0 Not tainted 2.6.39-ARCH #1
[ 6569.991781] Call Trace:
[ 6569.991792]  [<ffffffff8105b90f>] warn_slowpath_common+0x7f/0xc0
[ 6569.991797]  [<ffffffff8105b96a>] warn_slowpath_null+0x1a/0x20
[ 6569.991804]  [<ffffffffa064df7f>] __e1000_shutdown+0x43f/0x4c0 [e1000e]
[ 6569.991816]  [<ffffffff81012fc9>] ? sched_clock+0x9/0x10
[ 6569.991819]  [<ffffffffa064e039>] e1000_runtime_suspend+0x39/0x50 [e1000e]
[ 6569.991823]  [<ffffffff8100a6cf>] ? __switch_to+0xbf/0x2f0
[ 6569.991828]  [<ffffffff812392dd>] pci_pm_runtime_suspend+0x4d/0x100
[ 6569.991830]  [<ffffffff81239290>] ? pci_legacy_suspend_late+0x100/0x100
[ 6569.991834]  [<ffffffff812e7d52>] rpm_callback+0x42/0x80
[ 6569.991837]  [<ffffffff813e4faf>] ? schedule+0x33f/0xad0
[ 6569.991839]  [<ffffffff812e82fa>] rpm_suspend+0x1da/0x3f0
[ 6569.991843]  [<ffffffff8107701c>] ? queue_delayed_work_on+0xbc/0x150
[ 6569.991846]  [<ffffffff812e9380>] ? pm_schedule_suspend+0xe0/0xe0
[ 6569.991848]  [<ffffffff812e941a>] pm_runtime_work+0x9a/0xc0
[ 6569.991850]  [<ffffffff81077f6e>] process_one_work+0x11e/0x4c0
[ 6569.991852]  [<ffffffff810788ff>] worker_thread+0x15f/0x350
[ 6569.991854]  [<ffffffff810787a0>] ? manage_workers.isra.29+0x230/0x230
[ 6569.991857]  [<ffffffff8107d6ec>] kthread+0x8c/0xa0
[ 6569.991860]  [<ffffffff813e9fe4>] kernel_thread_helper+0x4/0x10
[ 6569.991862]  [<ffffffff8107d660>] ? kthread_worker_fn+0x190/0x190
[ 6569.991864]  [<ffffffff813e9fe0>] ? gs_change+0x13/0x13
[ 6569.991865] ---[ end trace c54917cde5791882 ]---
[ 6570.221032] e1000e 0000:00:19.0: PME# enabled
[ 6570.464118] EXT4-fs (sda3): re-mounted. Opts: commit=0
[ 6570.466279] EXT4-fs (sda1): re-mounted. Opts: commit=0
[ 6570.644945] EXT4-fs (sda4): re-mounted. Opts: commit=0
[ 6571.823780] e1000e 0000:00:19.0: BAR 0: set to [mem 0xf2600000-0xf261ffff] (PCI address [0xf2600000-0xf261ffff])
[ 6571.823791] e1000e 0000:00:19.0: BAR 1: set to [mem 0xf2625000-0xf2625fff] (PCI address [0xf2625000-0xf2625fff])
[ 6571.823800] e1000e 0000:00:19.0: BAR 2: set to [io  0x1820-0x183f] (PCI address [0x1820-0x183f])
[ 6571.823821] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[ 6571.823847] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
[ 6571.823885] e1000e 0000:00:19.0: PME# disabled
[ 6571.823965] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
[ 6571.826445] e1000e 0000:00:19.0: eth0: PHY Wakeup cause - Link Status  Change
[ 6573.521494] e1000e: eth0 NIC Link is Up 100 Mbps Full Duplex, Flow Control: Rx
[ 6573.521500] e1000e 0000:00:19.0: eth0: 10/100 speed: disabling TSO
[ 6573.521814] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready

The kernel is still the same 2.6.39.3

Hope that helps.

I'll keep trying to reproduce the crash - will probably build a 3.0.1 with 
lots of debug options enabled and try to reproduce with that.

-- 
Jesper Juhl <jj@chaosbits.net>       http://www.chaosbits.net/
Don't top-post http://www.catb.org/jargon/html/T/top-post.html
Plain text mails only, please.

Re: [linux-pm] Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Jesper Juhl]

On Fri, 5 Aug 2011, Alan Stern wrote:

> On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:
> 
> > > You're right, sorry.  System suspend was not involved, so the problem
> > > was triggerend by runtime suspend alone, resulting from unplugging the
> > > Ethernet cable.
> > > 
> > > It looks like the crash started in pci_disable_msi().
> > 
> > OTOH, I'm not sure how pci_legacy_suspend_late() was called.
> > In theory it is only called by the system suspend code and it surely
> > is not called for e1000e.
> 
> The ? indicates that pci_legacy_suspend_late() wasn't necessarily on
> the task's call stack; it may simply have been a leftover pointer from
> some other operation, sitting somewhere in the middle of the stack
> page.
> 

Not sure if it helps, but I've been trying to reproduce the crash and 
although I've not succeeded doing that yet, I've got something else.

While trying to reproduce by unplugging/replugging ethernet and 
resuming/suspending a lot I found the following in dmesg after one of the 
resumes - the system seems to be working fine though and network works 
as well, so it's not the same complete crash but it looks 
potentially related :

[ 6564.921192] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100103, writing 0x100107)
[ 6564.921222] ehci_hcd 0000:00:1a.0: restoring config space at offset 0xf (was 0x400, writing 0x40b)
[ 6564.921240] ehci_hcd 0000:00:1a.0: restoring config space at offset 0x4 (was 0x0, writing 0xf2828000)
[ 6564.921247] ehci_hcd 0000:00:1a.0: restoring config space at offset 0x1 (was 0x2900000, writing 0x2900102)
[ 6564.937545] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
[ 6564.937554] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
[ 6564.937708] pcieport 0000:00:1c.1: restoring config space at offset 0x7 (was 0xf0, writing 0x200000f0)
[ 6564.937805] pcieport 0000:00:1c.4: restoring config space at offset 0xf (was 0x100, writing 0x4010b)
[ 6564.937815] pcieport 0000:00:1c.4: restoring config space at offset 0x9 (was 0x10001, writing 0x1fff1)
[ 6564.937820] pcieport 0000:00:1c.4: restoring config space at offset 0x8 (was 0x0, writing 0xf250f250)
[ 6564.937824] pcieport 0000:00:1c.4: restoring config space at offset 0x7 (was 0x20000000, writing 0x200000f0)
[ 6564.937832] pcieport 0000:00:1c.4: restoring config space at offset 0x3 (was 0x810000, writing 0x810010)
[ 6564.937838] pcieport 0000:00:1c.4: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
[ 6564.937872] ehci_hcd 0000:00:1d.0: restoring config space at offset 0xf (was 0x400, writing 0x40b)
[ 6564.937890] ehci_hcd 0000:00:1d.0: restoring config space at offset 0x4 (was 0x0, writing 0xf2828400)
[ 6564.937897] ehci_hcd 0000:00:1d.0: restoring config space at offset 0x1 (was 0x2900000, writing 0x2900102)
[ 6564.937915] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[ 6564.937918] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[ 6564.938019] ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00007, writing 0x2b00407)
[ 6564.938085] intel ips 0000:00:1f.6: restoring config space at offset 0xf (was 0x400, writing 0x40b)
[ 6564.938107] intel ips 0000:00:1f.6: restoring config space at offset 0x1 (was 0x100000, writing 0x100002)
[ 6564.938674] PM: early resume of devices complete after 17.784 msecs[ 6564.939048] sdhci-pci 0000:0d:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[ 6564.939053] iwlagn 0000:03:00.0: RF_KILL bit toggled to disable radio.
[ 6564.939118] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
[ 6564.942219] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
[ 6564.942229] pci 0000:00:1e.0: setting latency timer to 64
[ 6564.942236] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[ 6564.942246] HDA Intel 0000:00:1b.0: PCI INT B -> GSI 17 (level, low) -> IRQ 17
[ 6564.942253] HDA Intel 0000:00:1b.0: setting latency timer to 64
[ 6564.942261] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
[ 6564.942265] ahci 0000:00:1f.2: setting latency timer to 64
[ 6564.942276] ehci_hcd 0000:00:1a.0: PCI INT D -> GSI 23 (level, low) -> IRQ 23
[ 6564.942344] ehci_hcd 0000:00:1a.0: setting latency timer to 64
[ 6564.942360] HDA Intel 0000:00:1b.0: irq 44 for MSI/MSI-X
[ 6564.942436] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[ 6564.942444] ehci_hcd 0000:00:1d.0: PCI INT D -> GSI 19 (level, low) -> IRQ 19
[ 6564.942452] ehci_hcd 0000:00:1d.0: setting latency timer to 64
[ 6564.942456] sd 0:0:0:0: [sda] Starting disk
[ 6564.942458] i915 0000:00:02.0: power state changed by ACPI to D0
[ 6564.942463] i915 0000:00:02.0: power state changed by ACPI to D0
[ 6564.942466] i915 0000:00:02.0: setting latency timer to 64
[ 6564.997449] firewire_ohci 0000:0d:00.3: irq 45 for MSI/MSI-X
[ 6564.997785] firewire_core: skipped bus generations, destroying all nodes
[ 6565.123881] usb 2-1.1: reset full speed USB device number 3 using ehci_hcd
[ 6565.256738] ata6: SATA link down (SStatus 0 SControl 300)
[ 6565.256782] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[ 6565.259348] ata2.00: ACPI cmd e3/00:1f:00:00:00:a0 (IDLE) succeeded
[ 6565.259563] ata2.00: ACPI cmd e3/00:02:00:00:00:a0 (IDLE) succeeded
[ 6565.263747] ata2.00: ACPI cmd e3/00:1f:00:00:00:a0 (IDLE) succeeded
[ 6565.263990] ata2.00: ACPI cmd e3/00:02:00:00:00:a0 (IDLE) succeeded
[ 6565.265544] ata2.00: configured for UDMA/66
[ 6565.276723] ata5: SATA link down (SStatus 0 SControl 300)
[ 6565.439619] sdhci-pci 0000:0d:00.0: Will use DMA mode even though HW doesn't fully claim to support it.
[ 6565.439631] sdhci-pci 0000:0d:00.0: setting latency timer to 64
[ 6565.463009] usb 1-1.2: reset low speed USB device number 3 using ehci_hcd
[ 6565.496163] firewire_core: rediscovered device fw0
[ 6565.802321] usb 1-1.3: reset full speed USB device number 4 using ehci_hcd
[ 6565.951782] usb 1-1.6: reset high speed USB device number 6 using ehci_hcd
[ 6566.014871] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 6566.021871] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[ 6566.021877] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[ 6566.022178] ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 (SET FEATURES) succeeded
[ 6566.022183] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[ 6566.024813] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[ 6566.024819] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[ 6566.025080] ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 (SET FEATURES) succeeded
[ 6566.025085] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[ 6566.026327] ata1.00: configured for UDMA/100
[ 6566.104911] usb 2-1.1.4: reset full speed USB device number 4 using ehci_hcd
[ 6566.190354] PM: resume of devices complete after 1254.565 msecs
[ 6566.191321] PM: Finishing wakeup.
[ 6566.191323] Restarting tasks ... done.
[ 6566.199706] video LNXVIDEO:00: Restoring backlight state
[ 6566.661832] e1000e: eth0 NIC Link is Up 100 Mbps Full Duplex, Flow Control: Rx
[ 6566.661839] e1000e 0000:00:19.0: eth0: 10/100 speed: disabling TSO
[ 6566.662160] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[ 6568.525731] e1000e 0000:00:19.0: PME# enabled
[ 6568.551863] e1000e 0000:00:19.0: BAR 0: set to [mem 0xf2600000-0xf261ffff] (PCI address [0xf2600000-0xf261ffff])
[ 6568.551876] e1000e 0000:00:19.0: BAR 1: set to [mem 0xf2625000-0xf2625fff] (PCI address [0xf2625000-0xf2625fff])
[ 6568.551886] e1000e 0000:00:19.0: BAR 2: set to [io  0x1820-0x183f] (PCI address [0x1820-0x183f])
[ 6568.551909] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[ 6568.551936] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
[ 6568.551999] e1000e 0000:00:19.0: PME# disabled
[ 6568.645183] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
[ 6568.698271] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
[ 6568.699163] ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 6568.814811] e1000e 0000:00:19.0: PME# enabled
[ 6568.844535] e1000e 0000:00:19.0: BAR 0: set to [mem 0xf2600000-0xf261ffff] (PCI address [0xf2600000-0xf261ffff])
[ 6568.844548] e1000e 0000:00:19.0: BAR 1: set to [mem 0xf2625000-0xf2625fff] (PCI address [0xf2625000-0xf2625fff])
[ 6568.844558] e1000e 0000:00:19.0: BAR 2: set to [io  0x1820-0x183f] (PCI address [0x1820-0x183f])
[ 6568.844580] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[ 6568.844607] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100507)
[ 6568.844668] e1000e 0000:00:19.0: PME# disabled
[ 6568.937809] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
[ 6568.990871] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
[ 6568.991756] ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 6569.991674] ------------[ cut here ]------------
[ 6569.991694] WARNING: at drivers/net/e1000e/netdev.c:5221 __e1000_shutdown+0x43f/0x4c0 [e1000e]()
[ 6569.991698] Hardware name: 4384GJG
[ 6569.991699] Modules linked in: snd_seq snd_seq_device aesni_intel cryptd aes_x86_64 aes_generic ipv6 uvcvideo videodev media v4l2_compat_ioctl32 usbhid hid snd_hda_codec_hdmi btusb bluetooth snd_hda_codec_conexant arc4 ecb snd_hda_intel snd_hda_codec snd_hwdep e1000e i915 snd_pcm iwlagn ehci_hcd snd_timer drm_kms_helper usbcore snd_page_alloc sdhci_pci sdhci pcspkr mmc_core sg drm vboxnetadp vboxnetflt evdev tpm_tis i2c_algo_bit mac80211 serio_raw psmouse iTCO_wdt vboxdrv firewire_ohci firewire_core i2c_i801 crc_itu_t i2c_core iTCO_vendor_support cfg80211 battery thermal intel_ips wmi tpm intel_agp video ac tpm_bios button intel_gtt cpufreq_ondemand msr acpi_cpufreq freq_table processor mperf thinkpad_acpi rfkill snd soundcore nvram ext4 mbcache jbd2 crc16 sr_mod sd_mod cdrom ahci libahci libata scsi_mod
[ 6569.991778] Pid: 7847, comm: kworker/1:0 Not tainted 2.6.39-ARCH #1
[ 6569.991781] Call Trace:
[ 6569.991792]  [<ffffffff8105b90f>] warn_slowpath_common+0x7f/0xc0
[ 6569.991797]  [<ffffffff8105b96a>] warn_slowpath_null+0x1a/0x20
[ 6569.991804]  [<ffffffffa064df7f>] __e1000_shutdown+0x43f/0x4c0 [e1000e]
[ 6569.991816]  [<ffffffff81012fc9>] ? sched_clock+0x9/0x10
[ 6569.991819]  [<ffffffffa064e039>] e1000_runtime_suspend+0x39/0x50 [e1000e]
[ 6569.991823]  [<ffffffff8100a6cf>] ? __switch_to+0xbf/0x2f0
[ 6569.991828]  [<ffffffff812392dd>] pci_pm_runtime_suspend+0x4d/0x100
[ 6569.991830]  [<ffffffff81239290>] ? pci_legacy_suspend_late+0x100/0x100
[ 6569.991834]  [<ffffffff812e7d52>] rpm_callback+0x42/0x80
[ 6569.991837]  [<ffffffff813e4faf>] ? schedule+0x33f/0xad0
[ 6569.991839]  [<ffffffff812e82fa>] rpm_suspend+0x1da/0x3f0
[ 6569.991843]  [<ffffffff8107701c>] ? queue_delayed_work_on+0xbc/0x150
[ 6569.991846]  [<ffffffff812e9380>] ? pm_schedule_suspend+0xe0/0xe0
[ 6569.991848]  [<ffffffff812e941a>] pm_runtime_work+0x9a/0xc0
[ 6569.991850]  [<ffffffff81077f6e>] process_one_work+0x11e/0x4c0
[ 6569.991852]  [<ffffffff810788ff>] worker_thread+0x15f/0x350
[ 6569.991854]  [<ffffffff810787a0>] ? manage_workers.isra.29+0x230/0x230
[ 6569.991857]  [<ffffffff8107d6ec>] kthread+0x8c/0xa0
[ 6569.991860]  [<ffffffff813e9fe4>] kernel_thread_helper+0x4/0x10
[ 6569.991862]  [<ffffffff8107d660>] ? kthread_worker_fn+0x190/0x190
[ 6569.991864]  [<ffffffff813e9fe0>] ? gs_change+0x13/0x13
[ 6569.991865] ---[ end trace c54917cde5791882 ]---
[ 6570.221032] e1000e 0000:00:19.0: PME# enabled
[ 6570.464118] EXT4-fs (sda3): re-mounted. Opts: commit=0
[ 6570.466279] EXT4-fs (sda1): re-mounted. Opts: commit=0
[ 6570.644945] EXT4-fs (sda4): re-mounted. Opts: commit=0
[ 6571.823780] e1000e 0000:00:19.0: BAR 0: set to [mem 0xf2600000-0xf261ffff] (PCI address [0xf2600000-0xf261ffff])
[ 6571.823791] e1000e 0000:00:19.0: BAR 1: set to [mem 0xf2625000-0xf2625fff] (PCI address [0xf2625000-0xf2625fff])
[ 6571.823800] e1000e 0000:00:19.0: BAR 2: set to [io  0x1820-0x183f] (PCI address [0x1820-0x183f])
[ 6571.823821] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[ 6571.823847] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
[ 6571.823885] e1000e 0000:00:19.0: PME# disabled
[ 6571.823965] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
[ 6571.826445] e1000e 0000:00:19.0: eth0: PHY Wakeup cause - Link Status  Change
[ 6573.521494] e1000e: eth0 NIC Link is Up 100 Mbps Full Duplex, Flow Control: Rx
[ 6573.521500] e1000e 0000:00:19.0: eth0: 10/100 speed: disabling TSO
[ 6573.521814] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready

The kernel is still the same 2.6.39.3

Hope that helps.

I'll keep trying to reproduce the crash - will probably build a 3.0.1 with 
lots of debug options enabled and try to reproduce with that.

-- 
Jesper Juhl <jj@chaosbits.net>       http://www.chaosbits.net/
Don't top-post http://www.catb.org/jargon/html/T/top-post.html
Plain text mails only, please.

Re: [linux-pm] Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Jesper Juhl]

On Sat, 6 Aug 2011, Jesper Juhl wrote:

> On Fri, 5 Aug 2011, Alan Stern wrote:
> 
> > On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:
> > 
> > > > You're right, sorry.  System suspend was not involved, so the problem
> > > > was triggerend by runtime suspend alone, resulting from unplugging the
> > > > Ethernet cable.
> > > > 
> > > > It looks like the crash started in pci_disable_msi().
> > > 
> > > OTOH, I'm not sure how pci_legacy_suspend_late() was called.
> > > In theory it is only called by the system suspend code and it surely
> > > is not called for e1000e.
> > 
> > The ? indicates that pci_legacy_suspend_late() wasn't necessarily on
> > the task's call stack; it may simply have been a leftover pointer from
> > some other operation, sitting somewhere in the middle of the stack
> > page.
> > 
> 
> Not sure if it helps, but I've been trying to reproduce the crash and 
> although I've not succeeded doing that yet, I've got something else.
> 
> While trying to reproduce by unplugging/replugging ethernet and 
> resuming/suspending a lot I found the following in dmesg after one of the 
> resumes - the system seems to be working fine though and network works 
> as well, so it's not the same complete crash but it looks 
> potentially related :
> 
> [ 6564.921192] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100103, writing 0x100107)
> [ 6564.921222] ehci_hcd 0000:00:1a.0: restoring config space at offset 0xf (was 0x400, writing 0x40b)
> [ 6564.921240] ehci_hcd 0000:00:1a.0: restoring config space at offset 0x4 (was 0x0, writing 0xf2828000)
> [ 6564.921247] ehci_hcd 0000:00:1a.0: restoring config space at offset 0x1 (was 0x2900000, writing 0x2900102)
> [ 6564.937545] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
> [ 6564.937554] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
> [ 6564.937708] pcieport 0000:00:1c.1: restoring config space at offset 0x7 (was 0xf0, writing 0x200000f0)
> [ 6564.937805] pcieport 0000:00:1c.4: restoring config space at offset 0xf (was 0x100, writing 0x4010b)
> [ 6564.937815] pcieport 0000:00:1c.4: restoring config space at offset 0x9 (was 0x10001, writing 0x1fff1)
> [ 6564.937820] pcieport 0000:00:1c.4: restoring config space at offset 0x8 (was 0x0, writing 0xf250f250)
> [ 6564.937824] pcieport 0000:00:1c.4: restoring config space at offset 0x7 (was 0x20000000, writing 0x200000f0)
> [ 6564.937832] pcieport 0000:00:1c.4: restoring config space at offset 0x3 (was 0x810000, writing 0x810010)
> [ 6564.937838] pcieport 0000:00:1c.4: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
> [ 6564.937872] ehci_hcd 0000:00:1d.0: restoring config space at offset 0xf (was 0x400, writing 0x40b)
> [ 6564.937890] ehci_hcd 0000:00:1d.0: restoring config space at offset 0x4 (was 0x0, writing 0xf2828400)
> [ 6564.937897] ehci_hcd 0000:00:1d.0: restoring config space at offset 0x1 (was 0x2900000, writing 0x2900102)
> [ 6564.937915] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
> [ 6564.937918] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
> [ 6564.938019] ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00007, writing 0x2b00407)
> [ 6564.938085] intel ips 0000:00:1f.6: restoring config space at offset 0xf (was 0x400, writing 0x40b)
> [ 6564.938107] intel ips 0000:00:1f.6: restoring config space at offset 0x1 (was 0x100000, writing 0x100002)
> [ 6564.938674] PM: early resume of devices complete after 17.784 msecs[ 6564.939048] sdhci-pci 0000:0d:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
> [ 6564.939053] iwlagn 0000:03:00.0: RF_KILL bit toggled to disable radio.
> [ 6564.939118] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
> [ 6564.942219] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
> [ 6564.942229] pci 0000:00:1e.0: setting latency timer to 64
> [ 6564.942236] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
> [ 6564.942246] HDA Intel 0000:00:1b.0: PCI INT B -> GSI 17 (level, low) -> IRQ 17
> [ 6564.942253] HDA Intel 0000:00:1b.0: setting latency timer to 64
> [ 6564.942261] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
> [ 6564.942265] ahci 0000:00:1f.2: setting latency timer to 64
> [ 6564.942276] ehci_hcd 0000:00:1a.0: PCI INT D -> GSI 23 (level, low) -> IRQ 23
> [ 6564.942344] ehci_hcd 0000:00:1a.0: setting latency timer to 64
> [ 6564.942360] HDA Intel 0000:00:1b.0: irq 44 for MSI/MSI-X
> [ 6564.942436] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
> [ 6564.942444] ehci_hcd 0000:00:1d.0: PCI INT D -> GSI 19 (level, low) -> IRQ 19
> [ 6564.942452] ehci_hcd 0000:00:1d.0: setting latency timer to 64
> [ 6564.942456] sd 0:0:0:0: [sda] Starting disk
> [ 6564.942458] i915 0000:00:02.0: power state changed by ACPI to D0
> [ 6564.942463] i915 0000:00:02.0: power state changed by ACPI to D0
> [ 6564.942466] i915 0000:00:02.0: setting latency timer to 64
> [ 6564.997449] firewire_ohci 0000:0d:00.3: irq 45 for MSI/MSI-X
> [ 6564.997785] firewire_core: skipped bus generations, destroying all nodes
> [ 6565.123881] usb 2-1.1: reset full speed USB device number 3 using ehci_hcd
> [ 6565.256738] ata6: SATA link down (SStatus 0 SControl 300)
> [ 6565.256782] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [ 6565.259348] ata2.00: ACPI cmd e3/00:1f:00:00:00:a0 (IDLE) succeeded
> [ 6565.259563] ata2.00: ACPI cmd e3/00:02:00:00:00:a0 (IDLE) succeeded
> [ 6565.263747] ata2.00: ACPI cmd e3/00:1f:00:00:00:a0 (IDLE) succeeded
> [ 6565.263990] ata2.00: ACPI cmd e3/00:02:00:00:00:a0 (IDLE) succeeded
> [ 6565.265544] ata2.00: configured for UDMA/66
> [ 6565.276723] ata5: SATA link down (SStatus 0 SControl 300)
> [ 6565.439619] sdhci-pci 0000:0d:00.0: Will use DMA mode even though HW doesn't fully claim to support it.
> [ 6565.439631] sdhci-pci 0000:0d:00.0: setting latency timer to 64
> [ 6565.463009] usb 1-1.2: reset low speed USB device number 3 using ehci_hcd
> [ 6565.496163] firewire_core: rediscovered device fw0
> [ 6565.802321] usb 1-1.3: reset full speed USB device number 4 using ehci_hcd
> [ 6565.951782] usb 1-1.6: reset high speed USB device number 6 using ehci_hcd
> [ 6566.014871] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
> [ 6566.021871] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
> [ 6566.021877] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
> [ 6566.022178] ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 (SET FEATURES) succeeded
> [ 6566.022183] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
> [ 6566.024813] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
> [ 6566.024819] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
> [ 6566.025080] ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 (SET FEATURES) succeeded
> [ 6566.025085] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
> [ 6566.026327] ata1.00: configured for UDMA/100
> [ 6566.104911] usb 2-1.1.4: reset full speed USB device number 4 using ehci_hcd
> [ 6566.190354] PM: resume of devices complete after 1254.565 msecs
> [ 6566.191321] PM: Finishing wakeup.
> [ 6566.191323] Restarting tasks ... done.
> [ 6566.199706] video LNXVIDEO:00: Restoring backlight state
> [ 6566.661832] e1000e: eth0 NIC Link is Up 100 Mbps Full Duplex, Flow Control: Rx
> [ 6566.661839] e1000e 0000:00:19.0: eth0: 10/100 speed: disabling TSO
> [ 6566.662160] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
> [ 6568.525731] e1000e 0000:00:19.0: PME# enabled
> [ 6568.551863] e1000e 0000:00:19.0: BAR 0: set to [mem 0xf2600000-0xf261ffff] (PCI address [0xf2600000-0xf261ffff])
> [ 6568.551876] e1000e 0000:00:19.0: BAR 1: set to [mem 0xf2625000-0xf2625fff] (PCI address [0xf2625000-0xf2625fff])
> [ 6568.551886] e1000e 0000:00:19.0: BAR 2: set to [io  0x1820-0x183f] (PCI address [0x1820-0x183f])
> [ 6568.551909] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
> [ 6568.551936] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
> [ 6568.551999] e1000e 0000:00:19.0: PME# disabled
> [ 6568.645183] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
> [ 6568.698271] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
> [ 6568.699163] ADDRCONF(NETDEV_UP): eth0: link is not ready
> [ 6568.814811] e1000e 0000:00:19.0: PME# enabled
> [ 6568.844535] e1000e 0000:00:19.0: BAR 0: set to [mem 0xf2600000-0xf261ffff] (PCI address [0xf2600000-0xf261ffff])
> [ 6568.844548] e1000e 0000:00:19.0: BAR 1: set to [mem 0xf2625000-0xf2625fff] (PCI address [0xf2625000-0xf2625fff])
> [ 6568.844558] e1000e 0000:00:19.0: BAR 2: set to [io  0x1820-0x183f] (PCI address [0x1820-0x183f])
> [ 6568.844580] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
> [ 6568.844607] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100507)
> [ 6568.844668] e1000e 0000:00:19.0: PME# disabled
> [ 6568.937809] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
> [ 6568.990871] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
> [ 6568.991756] ADDRCONF(NETDEV_UP): eth0: link is not ready
> [ 6569.991674] ------------[ cut here ]------------
> [ 6569.991694] WARNING: at drivers/net/e1000e/netdev.c:5221 __e1000_shutdown+0x43f/0x4c0 [e1000e]()
> [ 6569.991698] Hardware name: 4384GJG
> [ 6569.991699] Modules linked in: snd_seq snd_seq_device aesni_intel cryptd aes_x86_64 aes_generic ipv6 uvcvideo videodev media v4l2_compat_ioctl32 usbhid hid snd_hda_codec_hdmi btusb bluetooth snd_hda_codec_conexant arc4 ecb snd_hda_intel snd_hda_codec snd_hwdep e1000e i915 snd_pcm iwlagn ehci_hcd snd_timer drm_kms_helper usbcore snd_page_alloc sdhci_pci sdhci pcspkr mmc_core sg drm vboxnetadp vboxnetflt evdev tpm_tis i2c_algo_bit mac80211 serio_raw psmouse iTCO_wdt vboxdrv firewire_ohci firewire_core i2c_i801 crc_itu_t i2c_core iTCO_vendor_support cfg80211 battery thermal intel_ips wmi tpm intel_agp video ac tpm_bios button intel_gtt cpufreq_ondemand msr acpi_cpufreq freq_table processor mperf thinkpad_acpi rfkill snd soundcore nvram ext4 mbcache jbd2 crc16 sr_mod sd_mod cdrom ahci libahci libata scsi_mod
> [ 6569.991778] Pid: 7847, comm: kworker/1:0 Not tainted 2.6.39-ARCH #1
> [ 6569.991781] Call Trace:
> [ 6569.991792]  [<ffffffff8105b90f>] warn_slowpath_common+0x7f/0xc0
> [ 6569.991797]  [<ffffffff8105b96a>] warn_slowpath_null+0x1a/0x20
> [ 6569.991804]  [<ffffffffa064df7f>] __e1000_shutdown+0x43f/0x4c0 [e1000e]
> [ 6569.991816]  [<ffffffff81012fc9>] ? sched_clock+0x9/0x10
> [ 6569.991819]  [<ffffffffa064e039>] e1000_runtime_suspend+0x39/0x50 [e1000e]
> [ 6569.991823]  [<ffffffff8100a6cf>] ? __switch_to+0xbf/0x2f0
> [ 6569.991828]  [<ffffffff812392dd>] pci_pm_runtime_suspend+0x4d/0x100
> [ 6569.991830]  [<ffffffff81239290>] ? pci_legacy_suspend_late+0x100/0x100
> [ 6569.991834]  [<ffffffff812e7d52>] rpm_callback+0x42/0x80
> [ 6569.991837]  [<ffffffff813e4faf>] ? schedule+0x33f/0xad0
> [ 6569.991839]  [<ffffffff812e82fa>] rpm_suspend+0x1da/0x3f0
> [ 6569.991843]  [<ffffffff8107701c>] ? queue_delayed_work_on+0xbc/0x150
> [ 6569.991846]  [<ffffffff812e9380>] ? pm_schedule_suspend+0xe0/0xe0
> [ 6569.991848]  [<ffffffff812e941a>] pm_runtime_work+0x9a/0xc0
> [ 6569.991850]  [<ffffffff81077f6e>] process_one_work+0x11e/0x4c0
> [ 6569.991852]  [<ffffffff810788ff>] worker_thread+0x15f/0x350
> [ 6569.991854]  [<ffffffff810787a0>] ? manage_workers.isra.29+0x230/0x230
> [ 6569.991857]  [<ffffffff8107d6ec>] kthread+0x8c/0xa0
> [ 6569.991860]  [<ffffffff813e9fe4>] kernel_thread_helper+0x4/0x10
> [ 6569.991862]  [<ffffffff8107d660>] ? kthread_worker_fn+0x190/0x190
> [ 6569.991864]  [<ffffffff813e9fe0>] ? gs_change+0x13/0x13
> [ 6569.991865] ---[ end trace c54917cde5791882 ]---
> [ 6570.221032] e1000e 0000:00:19.0: PME# enabled
> [ 6570.464118] EXT4-fs (sda3): re-mounted. Opts: commit=0
> [ 6570.466279] EXT4-fs (sda1): re-mounted. Opts: commit=0
> [ 6570.644945] EXT4-fs (sda4): re-mounted. Opts: commit=0
> [ 6571.823780] e1000e 0000:00:19.0: BAR 0: set to [mem 0xf2600000-0xf261ffff] (PCI address [0xf2600000-0xf261ffff])
> [ 6571.823791] e1000e 0000:00:19.0: BAR 1: set to [mem 0xf2625000-0xf2625fff] (PCI address [0xf2625000-0xf2625fff])
> [ 6571.823800] e1000e 0000:00:19.0: BAR 2: set to [io  0x1820-0x183f] (PCI address [0x1820-0x183f])
> [ 6571.823821] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
> [ 6571.823847] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
> [ 6571.823885] e1000e 0000:00:19.0: PME# disabled
> [ 6571.823965] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
> [ 6571.826445] e1000e 0000:00:19.0: eth0: PHY Wakeup cause - Link Status  Change
> [ 6573.521494] e1000e: eth0 NIC Link is Up 100 Mbps Full Duplex, Flow Control: Rx
> [ 6573.521500] e1000e 0000:00:19.0: eth0: 10/100 speed: disabling TSO
> [ 6573.521814] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
> 
> The kernel is still the same 2.6.39.3
> 
> Hope that helps.
> 
> I'll keep trying to reproduce the crash - will probably build a 3.0.1 with 
> lots of debug options enabled and try to reproduce with that.
> 
> 

Just happened again, this time with 3.0.1 :

[30377.372749] ------------[ cut here ]------------
[30377.372779] WARNING: at drivers/net/e1000e/netdev.c:5235 __e1000_shutdown+0x43f/0x4c0 [e1000e]()
[30377.372783] Hardware name: 4384GJG
[30377.372786] Modules linked in: vboxnetadp vboxnetflt vboxdrv appletalk ipx p8022 psnap llc p8023 ipv6 snd_hda_codec_hdmi snd_hda_codec_conexant uvcvideo videodev media v4l2_compat_ioctl32 snd_hda_intel snd_hda_codec snd_hwdep snd_pcm cpufreq_ondemand serio_raw arc4 snd_timer snd_page_alloc psmouse i915 drm_kms_helper sg msr drm acpi_cpufreq iwlagn i2c_algo_bit mac80211 freq_table video evdev e1000e firewire_ohci i2c_i801 battery mxm_wmi i2c_core cfg80211 mei(C) tpm_tis firewire_core iTCO_wdt ac iTCO_vendor_support tpm intel_agp crc_itu_t sdhci_pci sdhci mmc_core intel_ips intel_gtt tpm_bios thermal pcspkr wmi mperf processor button thinkpad_acpi rfkill snd soundcore nvram ext4 mbcache jbd2 crc16 sr_mod cdrom sd_mod usbhid hid ahci libahci libata ehci_hcd scsi_mod usbcore [last unloaded: vboxdrv]
[30377.372876] Pid: 17558, comm: kworker/1:0 Tainted: G         C  3.0-ARCH #1
[30377.372879] Call Trace:
[30377.372895]  [<ffffffff8105c7bf>] warn_slowpath_common+0x7f/0xc0
[30377.372898]  [<ffffffff8105c81a>] warn_slowpath_null+0x1a/0x20
[30377.372902]  [<ffffffffa02603cf>] __e1000_shutdown+0x43f/0x4c0 [e1000e]
[30377.372906]  [<ffffffffa0260489>] e1000_runtime_suspend+0x39/0x50 [e1000e]
[30377.372911]  [<ffffffff81240b9d>] pci_pm_runtime_suspend+0x4d/0x100
[30377.372913]  [<ffffffff81240b50>] ? pci_legacy_suspend_late+0x100/0x100
[30377.372918]  [<ffffffff812f26e2>] rpm_callback+0x42/0x80
[30377.372920]  [<ffffffff812f2c7c>] rpm_suspend+0x1cc/0x3e0
[30377.372922]  [<ffffffff812f3c80>] ? pm_schedule_suspend+0xe0/0xe0
[30377.372925]  [<ffffffff812f3d1a>] pm_runtime_work+0x9a/0xc0
[30377.372929]  [<ffffffff81079576>] process_one_work+0x116/0x4d0
[30377.372932]  [<ffffffff81079f1f>] worker_thread+0x15f/0x350
[30377.372934]  [<ffffffff81079dc0>] ? manage_workers.isra.29+0x230/0x230
[30377.372936]  [<ffffffff8107ed2c>] kthread+0x8c/0xa0
[30377.372940]  [<ffffffff813f4ea4>] kernel_thread_helper+0x4/0x10
[30377.372942]  [<ffffffff8107eca0>] ? kthread_worker_fn+0x190/0x190
[30377.372947]  [<ffffffff813f4ea0>] ? gs_change+0x13/0x13
[30377.372949] ---[ end trace 91bf31e3c70d5224 ]---
[30377.672896] e1000e 0000:00:19.0: PME# enabled
[30379.316301] e1000e 0000:00:19.0: BAR 0: set to [mem 0xf2600000-0xf261ffff] (PCI address [0xf2600000-0xf261ffff])
[30379.316308] e1000e 0000:00:19.0: BAR 1: set to [mem 0xf2625000-0xf2625fff] (PCI address [0xf2625000-0xf2625fff])
[30379.316313] e1000e 0000:00:19.0: BAR 2: set to [io  0x1820-0x183f] (PCI address [0x1820-0x183f])
[30379.316337] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[30379.316358] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
[30379.316391] e1000e 0000:00:19.0: PME# disabled
[30379.316463] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
[30379.318956] e1000e 0000:00:19.0: eth0: PHY Wakeup cause - Link Status  Change

-- 
Jesper Juhl <jj@chaosbits.net>       http://www.chaosbits.net/
Don't top-post http://www.catb.org/jargon/html/T/top-post.html
Plain text mails only, please.

Re: Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Alan Stern]

On Tue, 9 Aug 2011, Jesper Juhl wrote:

> Just happened again, this time with 3.0.1 :
> 
> [30377.372749] ------------[ cut here ]------------
> [30377.372779] WARNING: at drivers/net/e1000e/netdev.c:5235 __e1000_shutdown+0x43f/0x4c0 [e1000e]()
> [30377.372783] Hardware name: 4384GJG
> [30377.372786] Modules linked in: vboxnetadp vboxnetflt vboxdrv appletalk ipx p8022 psnap llc p8023 ipv6 snd_hda_codec_hdmi snd_hda_codec_conexant uvcvideo videodev media v4l2_compat_ioctl32 snd_hda_intel snd_hda_codec snd_hwdep snd_pcm cpufreq_ondemand serio_raw arc4 snd_timer snd_page_alloc psmouse i915 drm_kms_helper sg msr drm acpi_cpufreq iwlagn i2c_algo_bit mac80211 freq_table video evdev e1000e firewire_ohci i2c_i801 battery mxm_wmi i2c_core cfg80211 mei(C) tpm_tis firewire_core iTCO_wdt ac iTCO_vendor_support tpm intel_agp crc_itu_t sdhci_pci sdhci mmc_core intel_ips intel_gtt tpm_bios thermal pcspkr wmi mperf processor button thinkpad_acpi rfkill snd soundcore nvram ext4 mbcache jbd2 crc16 sr_mod cdrom sd_mod usbhid hid ahci libahci libata ehci_hcd scsi_mod usbcore [last unloade
 d: vboxdrv]
> [30377.372876] Pid: 17558, comm: kworker/1:0 Tainted: G         C  3.0-ARCH #1
> [30377.372879] Call Trace:
> [30377.372895]  [<ffffffff8105c7bf>] warn_slowpath_common+0x7f/0xc0
> [30377.372898]  [<ffffffff8105c81a>] warn_slowpath_null+0x1a/0x20
> [30377.372902]  [<ffffffffa02603cf>] __e1000_shutdown+0x43f/0x4c0 [e1000e]
> [30377.372906]  [<ffffffffa0260489>] e1000_runtime_suspend+0x39/0x50 [e1000e]
> [30377.372911]  [<ffffffff81240b9d>] pci_pm_runtime_suspend+0x4d/0x100

It seems to me that this is a bug in the e1000e driver.  Therefore you 
should CC: the maintainer for that driver; that's who is most likely to 
be able to fix it.

Alan Stern

Re: [linux-pm] Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Alan Stern]

On Tue, 9 Aug 2011, Jesper Juhl wrote:

> Just happened again, this time with 3.0.1 :
> 
> [30377.372749] ------------[ cut here ]------------
> [30377.372779] WARNING: at drivers/net/e1000e/netdev.c:5235 __e1000_shutdown+0x43f/0x4c0 [e1000e]()
> [30377.372783] Hardware name: 4384GJG
> [30377.372786] Modules linked in: vboxnetadp vboxnetflt vboxdrv appletalk ipx p8022 psnap llc p8023 ipv6 snd_hda_codec_hdmi snd_hda_codec_conexant uvcvideo videodev media v4l2_compat_ioctl32 snd_hda_intel snd_hda_codec snd_hwdep snd_pcm cpufreq_ondemand serio_raw arc4 snd_timer snd_page_alloc psmouse i915 drm_kms_helper sg msr drm acpi_cpufreq iwlagn i2c_algo_bit mac80211 freq_table video evdev e1000e firewire_ohci i2c_i801 battery mxm_wmi i2c_core cfg80211 mei(C) tpm_tis firewire_core iTCO_wdt ac iTCO_vendor_support tpm intel_agp crc_itu_t sdhci_pci sdhci mmc_core intel_ips intel_gtt tpm_bios thermal pcspkr wmi mperf processor button thinkpad_acpi rfkill snd soundcore nvram ext4 mbcache jbd2 crc16 sr_mod cdrom sd_mod usbhid hid ahci libahci libata ehci_hcd scsi_mod usbcore [last unloaded: vboxdrv]
> [30377.372876] Pid: 17558, comm: kworker/1:0 Tainted: G         C  3.0-ARCH #1
> [30377.372879] Call Trace:
> [30377.372895]  [<ffffffff8105c7bf>] warn_slowpath_common+0x7f/0xc0
> [30377.372898]  [<ffffffff8105c81a>] warn_slowpath_null+0x1a/0x20
> [30377.372902]  [<ffffffffa02603cf>] __e1000_shutdown+0x43f/0x4c0 [e1000e]
> [30377.372906]  [<ffffffffa0260489>] e1000_runtime_suspend+0x39/0x50 [e1000e]
> [30377.372911]  [<ffffffff81240b9d>] pci_pm_runtime_suspend+0x4d/0x100

It seems to me that this is a bug in the e1000e driver.  Therefore you 
should CC: the maintainer for that driver; that's who is most likely to 
be able to fix it.

Alan Stern

Re: Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Jesper Juhl]

On Sat, 6 Aug 2011, Jesper Juhl wrote:

> On Fri, 5 Aug 2011, Alan Stern wrote:
> 
> > On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:
> > 
> > > > You're right, sorry.  System suspend was not involved, so the problem
> > > > was triggerend by runtime suspend alone, resulting from unplugging the
> > > > Ethernet cable.
> > > > 
> > > > It looks like the crash started in pci_disable_msi().
> > > 
> > > OTOH, I'm not sure how pci_legacy_suspend_late() was called.
> > > In theory it is only called by the system suspend code and it surely
> > > is not called for e1000e.
> > 
> > The ? indicates that pci_legacy_suspend_late() wasn't necessarily on
> > the task's call stack; it may simply have been a leftover pointer from
> > some other operation, sitting somewhere in the middle of the stack
> > page.
> > 
> 
> Not sure if it helps, but I've been trying to reproduce the crash and 
> although I've not succeeded doing that yet, I've got something else.
> 
> While trying to reproduce by unplugging/replugging ethernet and 
> resuming/suspending a lot I found the following in dmesg after one of the 
> resumes - the system seems to be working fine though and network works 
> as well, so it's not the same complete crash but it looks 
> potentially related :
> 
> [ 6564.921192] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100103, writing 0x100107)
> [ 6564.921222] ehci_hcd 0000:00:1a.0: restoring config space at offset 0xf (was 0x400, writing 0x40b)
> [ 6564.921240] ehci_hcd 0000:00:1a.0: restoring config space at offset 0x4 (was 0x0, writing 0xf2828000)
> [ 6564.921247] ehci_hcd 0000:00:1a.0: restoring config space at offset 0x1 (was 0x2900000, writing 0x2900102)
> [ 6564.937545] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
> [ 6564.937554] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
> [ 6564.937708] pcieport 0000:00:1c.1: restoring config space at offset 0x7 (was 0xf0, writing 0x200000f0)
> [ 6564.937805] pcieport 0000:00:1c.4: restoring config space at offset 0xf (was 0x100, writing 0x4010b)
> [ 6564.937815] pcieport 0000:00:1c.4: restoring config space at offset 0x9 (was 0x10001, writing 0x1fff1)
> [ 6564.937820] pcieport 0000:00:1c.4: restoring config space at offset 0x8 (was 0x0, writing 0xf250f250)
> [ 6564.937824] pcieport 0000:00:1c.4: restoring config space at offset 0x7 (was 0x20000000, writing 0x200000f0)
> [ 6564.937832] pcieport 0000:00:1c.4: restoring config space at offset 0x3 (was 0x810000, writing 0x810010)
> [ 6564.937838] pcieport 0000:00:1c.4: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
> [ 6564.937872] ehci_hcd 0000:00:1d.0: restoring config space at offset 0xf (was 0x400, writing 0x40b)
> [ 6564.937890] ehci_hcd 0000:00:1d.0: restoring config space at offset 0x4 (was 0x0, writing 0xf2828400)
> [ 6564.937897] ehci_hcd 0000:00:1d.0: restoring config space at offset 0x1 (was 0x2900000, writing 0x2900102)
> [ 6564.937915] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
> [ 6564.937918] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
> [ 6564.938019] ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00007, writing 0x2b00407)
> [ 6564.938085] intel ips 0000:00:1f.6: restoring config space at offset 0xf (was 0x400, writing 0x40b)
> [ 6564.938107] intel ips 0000:00:1f.6: restoring config space at offset 0x1 (was 0x100000, writing 0x100002)
> [ 6564.938674] PM: early resume of devices complete after 17.784 msecs[ 6564.939048] sdhci-pci 0000:0d:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
> [ 6564.939053] iwlagn 0000:03:00.0: RF_KILL bit toggled to disable radio.
> [ 6564.939118] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
> [ 6564.942219] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
> [ 6564.942229] pci 0000:00:1e.0: setting latency timer to 64
> [ 6564.942236] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
> [ 6564.942246] HDA Intel 0000:00:1b.0: PCI INT B -> GSI 17 (level, low) -> IRQ 17
> [ 6564.942253] HDA Intel 0000:00:1b.0: setting latency timer to 64
> [ 6564.942261] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
> [ 6564.942265] ahci 0000:00:1f.2: setting latency timer to 64
> [ 6564.942276] ehci_hcd 0000:00:1a.0: PCI INT D -> GSI 23 (level, low) -> IRQ 23
> [ 6564.942344] ehci_hcd 0000:00:1a.0: setting latency timer to 64
> [ 6564.942360] HDA Intel 0000:00:1b.0: irq 44 for MSI/MSI-X
> [ 6564.942436] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
> [ 6564.942444] ehci_hcd 0000:00:1d.0: PCI INT D -> GSI 19 (level, low) -> IRQ 19
> [ 6564.942452] ehci_hcd 0000:00:1d.0: setting latency timer to 64
> [ 6564.942456] sd 0:0:0:0: [sda] Starting disk
> [ 6564.942458] i915 0000:00:02.0: power state changed by ACPI to D0
> [ 6564.942463] i915 0000:00:02.0: power state changed by ACPI to D0
> [ 6564.942466] i915 0000:00:02.0: setting latency timer to 64
> [ 6564.997449] firewire_ohci 0000:0d:00.3: irq 45 for MSI/MSI-X
> [ 6564.997785] firewire_core: skipped bus generations, destroying all nodes
> [ 6565.123881] usb 2-1.1: reset full speed USB device number 3 using ehci_hcd
> [ 6565.256738] ata6: SATA link down (SStatus 0 SControl 300)
> [ 6565.256782] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [ 6565.259348] ata2.00: ACPI cmd e3/00:1f:00:00:00:a0 (IDLE) succeeded
> [ 6565.259563] ata2.00: ACPI cmd e3/00:02:00:00:00:a0 (IDLE) succeeded
> [ 6565.263747] ata2.00: ACPI cmd e3/00:1f:00:00:00:a0 (IDLE) succeeded
> [ 6565.263990] ata2.00: ACPI cmd e3/00:02:00:00:00:a0 (IDLE) succeeded
> [ 6565.265544] ata2.00: configured for UDMA/66
> [ 6565.276723] ata5: SATA link down (SStatus 0 SControl 300)
> [ 6565.439619] sdhci-pci 0000:0d:00.0: Will use DMA mode even though HW doesn't fully claim to support it.
> [ 6565.439631] sdhci-pci 0000:0d:00.0: setting latency timer to 64
> [ 6565.463009] usb 1-1.2: reset low speed USB device number 3 using ehci_hcd
> [ 6565.496163] firewire_core: rediscovered device fw0
> [ 6565.802321] usb 1-1.3: reset full speed USB device number 4 using ehci_hcd
> [ 6565.951782] usb 1-1.6: reset high speed USB device number 6 using ehci_hcd
> [ 6566.014871] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
> [ 6566.021871] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
> [ 6566.021877] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
> [ 6566.022178] ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 (SET FEATURES) succeeded
> [ 6566.022183] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
> [ 6566.024813] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
> [ 6566.024819] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
> [ 6566.025080] ata1.00: ACPI cmd ef/5f:00:00:00:00:a0 (SET FEATURES) succeeded
> [ 6566.025085] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
> [ 6566.026327] ata1.00: configured for UDMA/100
> [ 6566.104911] usb 2-1.1.4: reset full speed USB device number 4 using ehci_hcd
> [ 6566.190354] PM: resume of devices complete after 1254.565 msecs
> [ 6566.191321] PM: Finishing wakeup.
> [ 6566.191323] Restarting tasks ... done.
> [ 6566.199706] video LNXVIDEO:00: Restoring backlight state
> [ 6566.661832] e1000e: eth0 NIC Link is Up 100 Mbps Full Duplex, Flow Control: Rx
> [ 6566.661839] e1000e 0000:00:19.0: eth0: 10/100 speed: disabling TSO
> [ 6566.662160] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
> [ 6568.525731] e1000e 0000:00:19.0: PME# enabled
> [ 6568.551863] e1000e 0000:00:19.0: BAR 0: set to [mem 0xf2600000-0xf261ffff] (PCI address [0xf2600000-0xf261ffff])
> [ 6568.551876] e1000e 0000:00:19.0: BAR 1: set to [mem 0xf2625000-0xf2625fff] (PCI address [0xf2625000-0xf2625fff])
> [ 6568.551886] e1000e 0000:00:19.0: BAR 2: set to [io  0x1820-0x183f] (PCI address [0x1820-0x183f])
> [ 6568.551909] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
> [ 6568.551936] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
> [ 6568.551999] e1000e 0000:00:19.0: PME# disabled
> [ 6568.645183] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
> [ 6568.698271] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
> [ 6568.699163] ADDRCONF(NETDEV_UP): eth0: link is not ready
> [ 6568.814811] e1000e 0000:00:19.0: PME# enabled
> [ 6568.844535] e1000e 0000:00:19.0: BAR 0: set to [mem 0xf2600000-0xf261ffff] (PCI address [0xf2600000-0xf261ffff])
> [ 6568.844548] e1000e 0000:00:19.0: BAR 1: set to [mem 0xf2625000-0xf2625fff] (PCI address [0xf2625000-0xf2625fff])
> [ 6568.844558] e1000e 0000:00:19.0: BAR 2: set to [io  0x1820-0x183f] (PCI address [0x1820-0x183f])
> [ 6568.844580] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
> [ 6568.844607] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100507)
> [ 6568.844668] e1000e 0000:00:19.0: PME# disabled
> [ 6568.937809] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
> [ 6568.990871] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
> [ 6568.991756] ADDRCONF(NETDEV_UP): eth0: link is not ready
> [ 6569.991674] ------------[ cut here ]------------
> [ 6569.991694] WARNING: at drivers/net/e1000e/netdev.c:5221 __e1000_shutdown+0x43f/0x4c0 [e1000e]()
> [ 6569.991698] Hardware name: 4384GJG
> [ 6569.991699] Modules linked in: snd_seq snd_seq_device aesni_intel cryptd aes_x86_64 aes_generic ipv6 uvcvideo videodev media v4l2_compat_ioctl32 usbhid hid snd_hda_codec_hdmi btusb bluetooth snd_hda_codec_conexant arc4 ecb snd_hda_intel snd_hda_codec snd_hwdep e1000e i915 snd_pcm iwlagn ehci_hcd snd_timer drm_kms_helper usbcore snd_page_alloc sdhci_pci sdhci pcspkr mmc_core sg drm vboxnetadp vboxnetflt evdev tpm_tis i2c_algo_bit mac80211 serio_raw psmouse iTCO_wdt vboxdrv firewire_ohci firewire_core i2c_i801 crc_itu_t i2c_core iTCO_vendor_support cfg80211 battery thermal intel_ips wmi tpm intel_agp video ac tpm_bios button intel_gtt cpufreq_ondemand msr acpi_cpufreq freq_table processor mperf thinkpad_acpi rfkill snd soundcore nvram ext4 mbcache jbd2 crc16 sr_mod sd_mod cdrom ahci lib
 ahci libata scsi_mod
> [ 6569.991778] Pid: 7847, comm: kworker/1:0 Not tainted 2.6.39-ARCH #1
> [ 6569.991781] Call Trace:
> [ 6569.991792]  [<ffffffff8105b90f>] warn_slowpath_common+0x7f/0xc0
> [ 6569.991797]  [<ffffffff8105b96a>] warn_slowpath_null+0x1a/0x20
> [ 6569.991804]  [<ffffffffa064df7f>] __e1000_shutdown+0x43f/0x4c0 [e1000e]
> [ 6569.991816]  [<ffffffff81012fc9>] ? sched_clock+0x9/0x10
> [ 6569.991819]  [<ffffffffa064e039>] e1000_runtime_suspend+0x39/0x50 [e1000e]
> [ 6569.991823]  [<ffffffff8100a6cf>] ? __switch_to+0xbf/0x2f0
> [ 6569.991828]  [<ffffffff812392dd>] pci_pm_runtime_suspend+0x4d/0x100
> [ 6569.991830]  [<ffffffff81239290>] ? pci_legacy_suspend_late+0x100/0x100
> [ 6569.991834]  [<ffffffff812e7d52>] rpm_callback+0x42/0x80
> [ 6569.991837]  [<ffffffff813e4faf>] ? schedule+0x33f/0xad0
> [ 6569.991839]  [<ffffffff812e82fa>] rpm_suspend+0x1da/0x3f0
> [ 6569.991843]  [<ffffffff8107701c>] ? queue_delayed_work_on+0xbc/0x150
> [ 6569.991846]  [<ffffffff812e9380>] ? pm_schedule_suspend+0xe0/0xe0
> [ 6569.991848]  [<ffffffff812e941a>] pm_runtime_work+0x9a/0xc0
> [ 6569.991850]  [<ffffffff81077f6e>] process_one_work+0x11e/0x4c0
> [ 6569.991852]  [<ffffffff810788ff>] worker_thread+0x15f/0x350
> [ 6569.991854]  [<ffffffff810787a0>] ? manage_workers.isra.29+0x230/0x230
> [ 6569.991857]  [<ffffffff8107d6ec>] kthread+0x8c/0xa0
> [ 6569.991860]  [<ffffffff813e9fe4>] kernel_thread_helper+0x4/0x10
> [ 6569.991862]  [<ffffffff8107d660>] ? kthread_worker_fn+0x190/0x190
> [ 6569.991864]  [<ffffffff813e9fe0>] ? gs_change+0x13/0x13
> [ 6569.991865] ---[ end trace c54917cde5791882 ]---
> [ 6570.221032] e1000e 0000:00:19.0: PME# enabled
> [ 6570.464118] EXT4-fs (sda3): re-mounted. Opts: commit=0
> [ 6570.466279] EXT4-fs (sda1): re-mounted. Opts: commit=0
> [ 6570.644945] EXT4-fs (sda4): re-mounted. Opts: commit=0
> [ 6571.823780] e1000e 0000:00:19.0: BAR 0: set to [mem 0xf2600000-0xf261ffff] (PCI address [0xf2600000-0xf261ffff])
> [ 6571.823791] e1000e 0000:00:19.0: BAR 1: set to [mem 0xf2625000-0xf2625fff] (PCI address [0xf2625000-0xf2625fff])
> [ 6571.823800] e1000e 0000:00:19.0: BAR 2: set to [io  0x1820-0x183f] (PCI address [0x1820-0x183f])
> [ 6571.823821] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
> [ 6571.823847] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
> [ 6571.823885] e1000e 0000:00:19.0: PME# disabled
> [ 6571.823965] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
> [ 6571.826445] e1000e 0000:00:19.0: eth0: PHY Wakeup cause - Link Status  Change
> [ 6573.521494] e1000e: eth0 NIC Link is Up 100 Mbps Full Duplex, Flow Control: Rx
> [ 6573.521500] e1000e 0000:00:19.0: eth0: 10/100 speed: disabling TSO
> [ 6573.521814] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
> 
> The kernel is still the same 2.6.39.3
> 
> Hope that helps.
> 
> I'll keep trying to reproduce the crash - will probably build a 3.0.1 with 
> lots of debug options enabled and try to reproduce with that.
> 
> 

Just happened again, this time with 3.0.1 :

[30377.372749] ------------[ cut here ]------------
[30377.372779] WARNING: at drivers/net/e1000e/netdev.c:5235 __e1000_shutdown+0x43f/0x4c0 [e1000e]()
[30377.372783] Hardware name: 4384GJG
[30377.372786] Modules linked in: vboxnetadp vboxnetflt vboxdrv appletalk ipx p8022 psnap llc p8023 ipv6 snd_hda_codec_hdmi snd_hda_codec_conexant uvcvideo videodev media v4l2_compat_ioctl32 snd_hda_intel snd_hda_codec snd_hwdep snd_pcm cpufreq_ondemand serio_raw arc4 snd_timer snd_page_alloc psmouse i915 drm_kms_helper sg msr drm acpi_cpufreq iwlagn i2c_algo_bit mac80211 freq_table video evdev e1000e firewire_ohci i2c_i801 battery mxm_wmi i2c_core cfg80211 mei(C) tpm_tis firewire_core iTCO_wdt ac iTCO_vendor_support tpm intel_agp crc_itu_t sdhci_pci sdhci mmc_core intel_ips intel_gtt tpm_bios thermal pcspkr wmi mperf processor button thinkpad_acpi rfkill snd soundcore nvram ext4 mbcache jbd2 crc16 sr_mod cdrom sd_mod usbhid hid ahci libahci libata ehci_hcd scsi_mod usbcore [last unloaded:
  vboxdrv]
[30377.372876] Pid: 17558, comm: kworker/1:0 Tainted: G         C  3.0-ARCH #1
[30377.372879] Call Trace:
[30377.372895]  [<ffffffff8105c7bf>] warn_slowpath_common+0x7f/0xc0
[30377.372898]  [<ffffffff8105c81a>] warn_slowpath_null+0x1a/0x20
[30377.372902]  [<ffffffffa02603cf>] __e1000_shutdown+0x43f/0x4c0 [e1000e]
[30377.372906]  [<ffffffffa0260489>] e1000_runtime_suspend+0x39/0x50 [e1000e]
[30377.372911]  [<ffffffff81240b9d>] pci_pm_runtime_suspend+0x4d/0x100
[30377.372913]  [<ffffffff81240b50>] ? pci_legacy_suspend_late+0x100/0x100
[30377.372918]  [<ffffffff812f26e2>] rpm_callback+0x42/0x80
[30377.372920]  [<ffffffff812f2c7c>] rpm_suspend+0x1cc/0x3e0
[30377.372922]  [<ffffffff812f3c80>] ? pm_schedule_suspend+0xe0/0xe0
[30377.372925]  [<ffffffff812f3d1a>] pm_runtime_work+0x9a/0xc0
[30377.372929]  [<ffffffff81079576>] process_one_work+0x116/0x4d0
[30377.372932]  [<ffffffff81079f1f>] worker_thread+0x15f/0x350
[30377.372934]  [<ffffffff81079dc0>] ? manage_workers.isra.29+0x230/0x230
[30377.372936]  [<ffffffff8107ed2c>] kthread+0x8c/0xa0
[30377.372940]  [<ffffffff813f4ea4>] kernel_thread_helper+0x4/0x10
[30377.372942]  [<ffffffff8107eca0>] ? kthread_worker_fn+0x190/0x190
[30377.372947]  [<ffffffff813f4ea0>] ? gs_change+0x13/0x13
[30377.372949] ---[ end trace 91bf31e3c70d5224 ]---
[30377.672896] e1000e 0000:00:19.0: PME# enabled
[30379.316301] e1000e 0000:00:19.0: BAR 0: set to [mem 0xf2600000-0xf261ffff] (PCI address [0xf2600000-0xf261ffff])
[30379.316308] e1000e 0000:00:19.0: BAR 1: set to [mem 0xf2625000-0xf2625fff] (PCI address [0xf2625000-0xf2625fff])
[30379.316313] e1000e 0000:00:19.0: BAR 2: set to [io  0x1820-0x183f] (PCI address [0x1820-0x183f])
[30379.316337] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[30379.316358] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
[30379.316391] e1000e 0000:00:19.0: PME# disabled
[30379.316463] e1000e 0000:00:19.0: irq 41 for MSI/MSI-X
[30379.318956] e1000e 0000:00:19.0: eth0: PHY Wakeup cause - Link Status  Change

-- 
Jesper Juhl <jj@chaosbits.net>       http://www.chaosbits.net/
Don't top-post http://www.catb.org/jargon/html/T/top-post.html
Plain text mails only, please.

Re: [linux-pm] Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Rafael J. Wysocki]

On Friday, August 05, 2011, Alan Stern wrote:
> On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:
> 
> > > You're right, sorry.  System suspend was not involved, so the problem
> > > was triggerend by runtime suspend alone, resulting from unplugging the
> > > Ethernet cable.
> > > 
> > > It looks like the crash started in pci_disable_msi().
> > 
> > OTOH, I'm not sure how pci_legacy_suspend_late() was called.
> > In theory it is only called by the system suspend code and it surely
> > is not called for e1000e.
> 
> The ? indicates that pci_legacy_suspend_late() wasn't necessarily on
> the task's call stack; it may simply have been a leftover pointer from
> some other operation, sitting somewhere in the middle of the stack
> page.

However, Jesper said the crash happend during suspend, so I wonder how
that might be present on the stack while executing runtime PM routines?

Rafael

Re: Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Rafael J. Wysocki]

On Friday, August 05, 2011, Alan Stern wrote:
> On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:
> 
> > > You're right, sorry.  System suspend was not involved, so the problem
> > > was triggerend by runtime suspend alone, resulting from unplugging the
> > > Ethernet cable.
> > > 
> > > It looks like the crash started in pci_disable_msi().
> > 
> > OTOH, I'm not sure how pci_legacy_suspend_late() was called.
> > In theory it is only called by the system suspend code and it surely
> > is not called for e1000e.
> 
> The ? indicates that pci_legacy_suspend_late() wasn't necessarily on
> the task's call stack; it may simply have been a leftover pointer from
> some other operation, sitting somewhere in the middle of the stack
> page.

However, Jesper said the crash happend during suspend, so I wonder how
that might be present on the stack while executing runtime PM routines?

Rafael

Re: Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Rafael J. Wysocki]

On Friday, August 05, 2011, Rafael J. Wysocki wrote:
> On Friday, August 05, 2011, Alan Stern wrote:
> > On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:
> > 
> > > > > I don't know how to fix it yet, but I think I know what the problem is.
> > > > > Namely, a runtime suspend of the Ethernet adapter as occured in parallel with
> > > > > the system-wide suspend and they clashed.  The runtime suspend has probably
> > > > > been provoked by detaching the Ethernet cable from the box.
> > > > 
> > > > For them to clash in that way would mean that the PM workqueue didn't
> > > > get frozen.
> > > 
> > > Not necessarily, I think.  It's sufficient that system suspend is started
> > > while the runtime PM operation is in progress.
> > 
> > How so?  The system suspend doesn't call down to the subsystems or 
> > drivers until after all the threads are frozen.  In this case the stack 
> > dump shows that the runtime PM operation was asynchronous, running in a 
> > workqueue thread (pm_runtime_work is one of the routines near the end 
> > of the stack dump).  The thread wouldn't have frozen until the runtime 
> > PM operation was complete.
> 
> You're right, sorry.  System suspend was not involved, so the problem
> was triggerend by runtime suspend alone, resulting from unplugging the
> Ethernet cable.
> 
> It looks like the crash started in pci_disable_msi().

OTOH, I'm not sure how pci_legacy_suspend_late() was called.
In theory it is only called by the system suspend code and it surely
is not called for e1000e.

Thanks,
Rafael

Re: Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Alan Stern]

On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:

> > > I don't know how to fix it yet, but I think I know what the problem is.
> > > Namely, a runtime suspend of the Ethernet adapter as occured in parallel with
> > > the system-wide suspend and they clashed.  The runtime suspend has probably
> > > been provoked by detaching the Ethernet cable from the box.
> > 
> > For them to clash in that way would mean that the PM workqueue didn't
> > get frozen.
> 
> Not necessarily, I think.  It's sufficient that system suspend is started
> while the runtime PM operation is in progress.

How so?  The system suspend doesn't call down to the subsystems or 
drivers until after all the threads are frozen.  In this case the stack 
dump shows that the runtime PM operation was asynchronous, running in a 
workqueue thread (pm_runtime_work is one of the routines near the end 
of the stack dump).  The thread wouldn't have frozen until the runtime 
PM operation was complete.

Alan Stern

Re: Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Rafael J. Wysocki]

On Friday, August 05, 2011, Alan Stern wrote:
> On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:
> 
> > On Friday, August 05, 2011, Jesper Juhl wrote:
> > > Hi
> > > 
> > > I just experienced a kernel crash when trying to suspend my Lenovo 
> > > Thinkpad T510 (model 4384-GJG) laptop.
> > > 
> > > Normally I just shut the lid and the little moon icon lights up telling me 
> > > that the laptop has suspended. This time was different; the moon icon 
> > > didn't light up as it usually does, so I opened the lid again and found a 
> > > kernel crash dump on the screen. The machine was completely dead at this 
> > > point, so all I could do was take a photo of the screen - nothing had made 
> > > it to the log files either (checked after a reboot).
> > > 
> > > The image I took of the screen with the crash info is available here:
> > >  http://personal.chaosbits.net/suspend-crash.jpg
> > > 
> > > The kernel version is 2.6.39.3
> > > The kernel config is attached as '2.6.39.3-config.gz'
> > > The distribution is Arch Linux 64bit.
> > > 
> > > Here is a partial transcript of the image (typed in manually, so check the 
> > > image if you suspect an error - I also left out function addresses/offsets 
> > > and other details before/after the backtrace to save me some typing, so 
> > > check the image for the full details) :
> > > 
> > > Call Trace:
> > >   ? wq_worker_sleeping
> > >   schedule
> > >   ? cfq_put_queue
> > >   ? cic_free_func
> > >   ? kmem_cache_free
> > >   ? put_io_context
> > >   do_exit
> > >   oops_end
> > >   die
> > >   do_trap
> > >   do_invalid_op
> > >   ? free_msi_irqs
> > >   ? find_busiest_group
> > >   ? pci_conf1_write
> > >   pci_disable_msi
> > >   e1000e_reset_interrupt_capabillity
> > >   __e1000_runtime_suspend
> > >   ? __switch_to
> > >   pci_pm_runtime_suspend
> > >   ? pci_legacy_suspend_late
> > >   rpm_callback
> > >   ? schedule
> > >   rpm_suspend
> > >   ? linkwatch_do_dev
> > >   ? pm_schedule_suspend
> > >   pm_runtime_work
> > >   process_one_work
> > >   worker_thread
> > >   ? manage_workers.isra.29
> > >   kthread
> > >   kernel_thread_helper
> > >   ? kthread_worker
> > >   ? gs_change
> > > 
> > > I've not experienced this before with this kernel, nor with earlier or 
> > > newer ones, so it's not exactely reproducible on demand, so it's anyones 
> > > guess when this was introduced (or if it's been there for ages, just 
> > > triggers rarely)...
> > > 
> > > One detail that may be relevant; normally when I suspend the laptop I do 
> > > so before unplugging any cables or suspend after not having anything 
> > > plugged in for ages (or at all). This time I was in a hurry, so I quickly 
> > > unplugged the power, 3 usb cables and the ethernet cable and then quickly 
> > > slammed the lid shut. Not sure if that has an impact on triggering this 
> > > though. I tried reproducing that scenario 4-5 times, but the laptop 
> > > suspended fine when I did that.
> > > 
> > > If you require further information then please let me know and I'll be 
> > > happy to provide it. 
> > > 
> > > I'll of course try to submit more details if it happens again, but if 
> > > someone has a good guess as to how to provoke it or an idea for a fix I'd 
> > > sure like to know.
> > 
> > I don't know how to fix it yet, but I think I know what the problem is.
> > Namely, a runtime suspend of the Ethernet adapter as occured in parallel with
> > the system-wide suspend and they clashed.  The runtime suspend has probably
> > been provoked by detaching the Ethernet cable from the box.
> 
> For them to clash in that way would mean that the PM workqueue didn't
> get frozen.

Not necessarily, I think.  It's sufficient that system suspend is started
while the runtime PM operation is in progress.

> Is that possible?

Shouldn't be.

Thanks,
Rafael

Re: Crash when suspending Lenovo T510 laptop (2.6.39.3)

[Alan Stern]

On Fri, 5 Aug 2011, Rafael J. Wysocki wrote:

> On Friday, August 05, 2011, Jesper Juhl wrote:
> > Hi
> > 
> > I just experienced a kernel crash when trying to suspend my Lenovo 
> > Thinkpad T510 (model 4384-GJG) laptop.
> > 
> > Normally I just shut the lid and the little moon icon lights up telling me 
> > that the laptop has suspended. This time was different; the moon icon 
> > didn't light up as it usually does, so I opened the lid again and found a 
> > kernel crash dump on the screen. The machine was completely dead at this 
> > point, so all I could do was take a photo of the screen - nothing had made 
> > it to the log files either (checked after a reboot).
> > 
> > The image I took of the screen with the crash info is available here:
> >  http://personal.chaosbits.net/suspend-crash.jpg
> > 
> > The kernel version is 2.6.39.3
> > The kernel config is attached as '2.6.39.3-config.gz'
> > The distribution is Arch Linux 64bit.
> > 
> > Here is a partial transcript of the image (typed in manually, so check the 
> > image if you suspect an error - I also left out function addresses/offsets 
> > and other details before/after the backtrace to save me some typing, so 
> > check the image for the full details) :
> > 
> > Call Trace:
> >   ? wq_worker_sleeping
> >   schedule
> >   ? cfq_put_queue
> >   ? cic_free_func
> >   ? kmem_cache_free
> >   ? put_io_context
> >   do_exit
> >   oops_end
> >   die
> >   do_trap
> >   do_invalid_op
> >   ? free_msi_irqs
> >   ? find_busiest_group
> >   ? pci_conf1_write
> >   pci_disable_msi
> >   e1000e_reset_interrupt_capabillity
> >   __e1000_runtime_suspend
> >   ? __switch_to
> >   pci_pm_runtime_suspend
> >   ? pci_legacy_suspend_late
> >   rpm_callback
> >   ? schedule
> >   rpm_suspend
> >   ? linkwatch_do_dev
> >   ? pm_schedule_suspend
> >   pm_runtime_work
> >   process_one_work
> >   worker_thread
> >   ? manage_workers.isra.29
> >   kthread
> >   kernel_thread_helper
> >   ? kthread_worker
> >   ? gs_change
> > 
> > I've not experienced this before with this kernel, nor with earlier or 
> > newer ones, so it's not exactely reproducible on demand, so it's anyones 
> > guess when this was introduced (or if it's been there for ages, just 
> > triggers rarely)...
> > 
> > One detail that may be relevant; normally when I suspend the laptop I do 
> > so before unplugging any cables or suspend after not having anything 
> > plugged in for ages (or at all). This time I was in a hurry, so I quickly 
> > unplugged the power, 3 usb cables and the ethernet cable and then quickly 
> > slammed the lid shut. Not sure if that has an impact on triggering this 
> > though. I tried reproducing that scenario 4-5 times, but the laptop 
> > suspended fine when I did that.
> > 
> > If you require further information then please let me know and I'll be 
> > happy to provide it. 
> > 
> > I'll of course try to submit more details if it happens again, but if 
> > someone has a good guess as to how to provoke it or an idea for a fix I'd 
> > sure like to know.
> 
> I don't know how to fix it yet, but I think I know what the problem is.
> Namely, a runtime suspend of the Ethernet adapter as occured in parallel with
> the system-wide suspend and they clashed.  The runtime suspend has probably
> been provoked by detaching the Ethernet cable from the box.

For them to clash in that way would mean that the PM workqueue didn't
get frozen.  Is that possible?

Alan Stern