Bug 31432

On Mar 19 bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=31432
> 
> 
> Rafael J. Wysocki <rjw@sisk.pl> changed:
> 
>            What    |Removed                     |Added
> ----------------------------------------------------------------------------
>                  CC|                            |rjw@sisk.pl
>           Component|Hibernation/Suspend         |IEEE1394
>              Blocks|                            |7216
>          AssignedTo|power-management_other@kern |drivers_ieee1394@kernel-bug
>                    |el-bugs.osdl.org            |s.osdl.org
>             Product|Power Management            |Drivers

Quoting the bug description for linux1394-devel:

> Description From  Jaša  2011-03-19 12:34:00  
> Created an attachment (id=51242) [details]
> dmesg of 2.6.38

[https://bugzilla.kernel.org/attachment.cgi?id=51242]

> 
> I have diagnosed a regression in several kernel versions (at least
> 2.6.35.x and current stable version 2.6.38). 
> 
> After upgrading from 2.6.32 (Ubuntu 10.04) to 2.6.35 (Ubunutu 10.10)
> resume from suspend failed so I came across the /sys/power/pm_trace
> tracing method and with that info I narrowed the issue to a firewire
> device which seems to be the issue. I also tried the recently released
> 2.6.38 mainline version.
> 
> A workaround which confirmed my suspicions is removing firewire modules:
> # modprobe -r firewire_core firewire_ohci
> Then resume works well.
> 
> Here's the evidence:
> 
> $ uname -a
> Linux sendell 2.6.38-020638-generic #201103151303 SMP Tue Mar 15
> 13:08:09 UTC 2011 x86_64 GNU/Linux
> 
> relevant part of dmesg:
> [    1.181998] PM: Hibernation image not present or could not be loaded.
> [    1.182017] registered taskstats version 1
> [    1.182307]   Magic number: 0:117:476
> [    1.182310]   hash matches
> /home/kernel-ppa/COD/linux/drivers/base/power/main.c:514
> [    1.182370] pci 0000:03:05.0: hash matches
> [    1.182442] rtc_cmos 00:05: setting system clock to 2024-03-02 10:28:40
> UTC (1709375320)
> 
> $ lspci | grep 03:05
> 03:05.0 FireWire (IEEE 1394): Texas Instruments TSB43AB22/A IEEE-1394a-2000
> Controller (PHY/Link)
> 
> $ grep 03:05 dmesg-38.txt 
> [    0.360052] pci 0000:03:05.0: [104c:8023] type 0 class 0x000c00
> [    0.360067] pci 0000:03:05.0: reg 10: [mem 0xfdeff000-0xfdeff7ff]
> [    0.360076] pci 0000:03:05.0: reg 14: [mem 0xfdef8000-0xfdefbfff]
> [    0.360123] pci 0000:03:05.0: supports D1 D2
> [    0.360125] pci 0000:03:05.0: PME# supported from D0 D1 D2 D3hot
> [    0.360130] pci 0000:03:05.0: PME# disabled
> 
> I've posted this on Launchpad (Bug #732641) but no responses at all
> there.

Alas there are no messages from the firewire drivers in this log.  Not even
a message from PCI core that a firewire-ohci driver method failed.  Hence
we (linux1394-devel people) have nothing to go on yet.

Can somebody who knows power management explain what should be
investigated next?

The downstream tracker item is:
https://bugs.launchpad.net/ubuntu/+source/linux/+bug/732641

It contains a somewhat different failure description from a 2.6.35 Ubuntu
kernel:

> Since upgrade to 10.10/kernel 2.6.35 kernel doesn't complete resume from
> suspend.
> 
> $ uname -a
> Linux sendell 2.6.35-27-generic #48-Ubuntu SMP Tue Feb 22 20:25:46 UTC
> 2011 x86_64 GNU/Linux
> 
> Xorg vty is blank, I can change to other vtys but when i return to the
> one with Xorg, switching no longer works. Only manual reset remedies
> this situation.
> 
> Tried
>
> https://wiki.ubuntu.com/DebuggingKernelSuspend#%22resume-trace%22%20debugging%20procedure%20for%20finding%20buggy%20drivers
> 
> [ 0.714873] PM: Resume from disk failed.
> [ 0.714886] registered taskstats version 1
> [ 0.715167] Magic number: 0:608:476
> [ 0.715170] hash matches
> /build/buildd/linux-2.6.35/drivers/base/power/main.c:545
> [ 0.715213] pci 0000:03:05.0: hash matches
> [ 0.715281] rtc_cmos 00:05: setting system clock to 1980-09-08 10:27:51 UTC
> (337256871)
> 
> $ lspci | grep 03:05
> 03:05.0 FireWire (IEEE 1394): Texas Instruments TSB43AB22/A IEEE-1394a-2000
> Controller (PHY/Link)
> 
> $ dmesg|grep fire
> [ 0.380065] pci 0000:03:05.0: reg 10: [mem 0xfdeff000-0xfdeff7ff]
> [ 0.380071] pci 0000:03:05.0: reg 14: [mem 0xfdef8000-0xfdefbfff]
> [ 0.380105] pci 0000:03:05.0: supports D1 D2
> [ 0.380107] pci 0000:03:05.0: PME# supported from D0 D1 D2 D3hot
> [ 0.380111] pci 0000:03:05.0: PME# disabled
> [ 0.715213] pci 0000:03:05.0: hash matches
> [ 0.893472] firewire_ohci 0000:03:05.0: PCI INT A -> Link[APC4] -> GSI 19
> (level, low) -> IRQ 19
> [ 0.950061] firewire_ohci: Added fw-ohci device 0000:03:05.0, OHCI v1.10, 4
> IR + 8 IT contexts, quirks 0x2
> 
> $ lsmod|grep fire
> firewire_ohci 24839 0
> firewire_core 54327 1 firewire_ohci
> crc_itu_t 1739 1 firewire_core
> 
> $sudo modprobe -r firewire_core firewire_ohci
> 
> And then resuming from suspend works.
> 

Jaša, are all of the dmesg messages in this report from the same session?

Linux-pm folks, why is the PM Restore failure reported at 0.714873 but the
system proceeds and logs successful attachment of firewire-ohci's pci_probe
to the PCI device?

Also, why is base/power/main.c::device_resume mentioned in the PM trace
but there is no hint in the log that firewire-ohci's pci_resume was called?

Side note:  While firewire-ohci's pci_probe succeeded, the controller
might actually not have become operational.  Usually the success message
from firewire-ohci should be followed on circa 500 ms afterwards by a
message like this: "firewire_core: created device fw0: GUID
00110600000041cc, S400"

Can somebody comment on the phenomenon that VT switching was affected? ...
Well, maybe firewire-core hung in a workqueue job which in turn prevented
subsequent processing of other subsystems' workqueue jobs.  This can be
much more of a problem with a kernel like 2.6.35 than with newer ones
with concurrency managed workqueues (2.6.36 and later).

(Jaša, prefer reply-to-all for responses. Thanks for your reports so far.)

> Alas there are no messages from the firewire drivers in this log.  Not even
> a message from PCI core that a firewire-ohci driver method failed.  Hence
> we (linux1394-devel people) have nothing to go on yet.

This is because I can't get the message buffer from the hung kernel.
The log is from a forcefully rebooted kernel which logs the trace
information which is stored in the RTC between reboots (supposedly
this is the only non-volatile register available). You can see that
overwriting the RTC results in date in the 2020's. More here:
https://wiki.ubuntu.com/DebuggingKernelSuspend#%22resume-trace%22%20debugging%20procedure%20for%20finding%20buggy%20drivers


> The downstream tracker item is:
> https://bugs.launchpad.net/ubuntu/+source/linux/+bug/732641
>
> It contains a somewhat different failure description from a 2.6.35 Ubuntu
> kernel:
>
...
>
> Jaša, are all of the dmesg messages in this report from the same session?

dmesg messages on Launchpad are from 2.6.35 as it is the shipped
kernel in Ubuntu 10.10. In the comment on Launchpad you can also see
dmesg from 2.6.38-rc8 that was latest mainline at the time.
On this kernel bugzilla I posted the dmesg of the just released 2.6.38
stable kernel because I think this version is most relevant at this
time (right?).


> Linux-pm folks, why is the PM Restore failure reported at 0.714873 but the
> system proceeds and logs successful attachment of firewire-ohci's pci_probe
> to the PCI device?

I think you can find an explanation for this in my first paragraph of
this email.


> Can somebody comment on the phenomenon that VT switching was affected? ...
> Well, maybe firewire-core hung in a workqueue job which in turn prevented
> subsequent processing of other subsystems' workqueue jobs.  This can be
> much more of a problem with a kernel like 2.6.35 than with newer ones
> with concurrency managed workqueues (2.6.36 and later).

The VT switching is only possible on 2.6.35 for me. That is why I only
mentioned it on Launchpad. With .38 my display receives no signal
after attempting a resume.


> (Jaša, prefer reply-to-all for responses. Thanks for your reports so far.)

Thanks for your patience, this is my first bug report here. :)

Is the failure in resume from suspend(-to-RAM), or in restore from
hibernate (alias resume from suspend-to-disk), or both?

> Is the failure in resume from suspend(-to-RAM), or in restore from
> hibernate (alias resume from suspend-to-disk), or both?

The described failure is from suspend-to-RAM.

I have just tried hibernation with firewire modules loaded and the
kernel does not complete it. It hangs at a VT with only a blinking
cursor on the top left. A hard reset is required to regain control!
Here's what I see in the messages log: http://pastebin.com/rz0c8hKM

Created attachment 51912 [details]
syslog from "firewire-ohci debug=15" before suspend, from Jaša Bartelj

Via IRC, Jaša reported the attached driver messages from a session with firewire-ohci IRQ event logging switched on by "modprobe firewire-ohci debug=15".  There is a never-ending stream of bus reset events at a high frequenncy.  (The logging makes the PC entirely unresponsible.)

This means that the physical interface of the FireWire chip is most probably defective.  Jaša did not notice any issue of this sort until now because (1.) he did not yet use any FireWire devices on this controller, (2.) without flag 8 of firewire-ohci's debug parameter, firewire-ohci does not enable bus reset IRQs.  (Bus reset IRQ events mark the beginning of a bus reset phase; firewire-ohci normally only enables self ID compelete IRQ events which mark the ending of a bus reset phase.)

At the moment, I tend to think this bug should be closed because this is very probably a hardware defect.  (And if it is, it is of a kind that cannot sensibly worked around in the driver.)

To keep the mailinglists in the loop:

This appears to be a hardware defect.  IRQ event logging switched on before
suspend reveals an endless storm of bus reset events which hints to a
damaged PHY.  https://bugzilla.kernel.org/show_bug.cgi?id=31432#c5

Jaša,
one question for posterity:  Do you have a chance to open the case and
have a look what is stamped on the chip?  I wonder whether this is a
TSB43AB22 or TSB43AB22A.

(So far there aren't any differences between these versions
known, at least not to me, nor how common or uncommon each of the two
versions is.  I have a TSB43AB22/A myself but can't check which one
because it is hidden in the metal case of a CardBus card.)

> one question for posterity:  Do you have a chance to open the case and
> have a look what is stamped on the chip?  I wonder whether this is a
> TSB43AB22 or TSB43AB22A.

Sure, the markings on the chip are:
6AA0LTW
TSB43AB22A
_G4_

> At the moment, I tend to think this bug should be closed because this is very
> probably a hardware defect.  (And if it is, it is of a kind that cannot
> sensibly worked around in the driver.)

That's unfortunate to read because on the older ieee1394 stack the
system didn't fail at resume.
Myself, I can just disable the device in BIOS and cease concerning
myself about it in general the old behaviour was better.

Thank you for your time!

On Mar 26 Jaša Bartelj wrote:
> the markings on the chip are:
> 6AA0LTW
> TSB43AB22A
> _G4_

OK.  So we are not tripping over a potential unknown issue with the older
TSB43AB22 (which Texas Instruments still ship but don't recommend to use).

[bug closed]
> That's unfortunate to read because on the older ieee1394 stack the
> system didn't fail at resume.
> Myself, I can just disable the device in BIOS and cease concerning
> myself about it in general the old behaviour was better.
> 
> Thank you for your time!

Bus reset handling and device scanning were fundamentally reworked in the
newer kernel drivers compared to the older ones.  The old code had
races and was ineffective in this department.  That the new code happens to
regress with an apparent defective chip is indeed unfortunate.  But I do
not see how this could be addressed.

Thanks for your good reports and sorry that it did not lead to a
satisfying solution.