odroidxu4: Lockups with heavy xhci/SATA load

[scotte]

This is fairly vague at this point, but I have been able to reliably lock up my XU4 when doing heavy I/O load to a hard drive plugged into the cloudshell SATA connector. This is on 4.2-rc1-41.

The best way I've been able to do this consistently is by compiling the kernel on an SSD drive via:

$ make -j9 all

I've been able to reproduce on two different brands/types of SSD. It never happens when running the same command off an SD card.

When it locks up, the fan stays running and I have to unplug/replug the power cable. Oddly, the SATA drive won't be recognized until I reboot a second time. The only interesting bit of kernel log after the first reboot is:
usb 4-1.2: reset SuperSpeed USB device number 3 using xhci-hcd

Again, sorry for the vague issue, but curious if anyone else can reproduce.

[tobetter]

I also have the same issue with my XU4 and CloudShell, and this is the issue what I've looked for long with multiple type of HDD and SDD. Seriously this happens with very heavy I/O especially compile with "-j" more than 4, but this issue does not happen on other purpose like video streaming or disk seek, maybe not heavy over load. I've tried to add more components to CloudShell's LCD board close to SATA and USB connector for signal and power, but still had the same issue. So I am assuming that this might be USB 3.0 issue.

When I tried to revert below commit from odroidxu4-v4.2-rc1 branch, I found XU4 have less error.
66c28f9

[scotte]

Thanks, at least I know it's not just me. It's a plausible theory that's it's a USB 3.0 issue, and since it locks up the whole board it's not going to be an easy one to debug. I'll try with usbmon when I get a chance and see if anything jumps out at me.

[scotte]

Well, I'm not smart enough to do anything with usbmon output, but I did try a few different things and I found something interesting.

If I set scaling_max_freq for all CPUs to 1400000, "make -j9 all" on the LInux kernel completes without any problem on an SSD. I've noticed when it's locked up before that the CPU temp shown on the LCD is ~90C, yet when I run "stress" (with CPUs at max native clock - 1.4Ghz or 2Ghz as appropriate) the temp never goes above ~70C. In my compile with CPUs locked to 1.4Ghz, the max temp was ~60C.

No hotpluggable CPUs or I'd offline half the cores to see what happens.

None of this means it's a thermal issue necessarily, just some curious data.

[Update]
Since "stress" is pretty simple, I tried something a bit more complex - 8 copies of hpcc. I was able to cause a thermal shutdown, but it did not hang:

thermal thermal_zone3: critical temperature reached(121 C),shutting down

[tobetter]

Nice try, so 1.4GHz would make XU4 more stable with heavy load. :)
Why don't you post this to ODROID forum and keep discuss with others? Probably someone else who is smarter than me would help us. :)

[scotte]

I was thinking this probably belongs on the forum too... I'll post over there and see where it goes. Thanks!

[scotte]

Posted here: http://forum.odroid.com/viewtopic.php?f=99&t=15557 feel free to close this github issue if you think this is no longer productive, though adding your comments to that post might be helpful too. :-)

[scotte]

I rebased onto 4.2-rc7, which was trivial, the only conflict is on the RTL8152/RTL8153 driver (r8152.c) which is easily resolved by taking v2.04.0 from the XU4 branch versus v1.08.1 in the official kernel tree.

I got a little bit better debugging info when trying to reproduce my earlier issues, so it might be worth upgrading this experimental kernel with the latest 4.2-rc7 mainline (and perhaps keep up with it from there) just to see if anyone else finds some additional meaningful debug messages.

You can see the additional debug info in my post at http://forum.odroid.com/viewtopic.php?f=99&t=15557&p=102228#p102228

Thanks!

[jobenvil]

MAybe I have the same issue. Kernel 3.10.94-odroidxu4. rootfs on USB3, controller JMICRO Bus 004 Device 003: ID 152d:0551 JMicron Technology Corp. / JMicron USA Technology Corp.

I observed that basic commands doesn't affect, only some related to heavy load. I checked hdparm all possible parameters -y, -S0, for power management, because I though the problem was here...,etc. I was confused because the system was many hours running well but after doing some commands the login shell keeps connected but the command cannot be executed. Its look like the controller hanged up. Only power of/on system helps. Many tests, googling here and there and I could read the same behaviour with same controller here: https://bugzilla.redhat.com/show_bug.cgi?id=895085

I update the jmicron firmware, because I found this as well:
http://www.heise.de/ct/hotline/USB-3-0-Platte-laeuft-nicht-an-Alternative-1155769.html (German)

I came here to see the development of the kernel I found your post.

My question: it is a controller issue (side of JMICRON) or a controller issue (side of Kernel)?

I could see errors on I/O when I had the rootfs on SD card.

[qknight]

just seen this on heavy load:

lsusb:
Bus 003 Device 005: ID 152d:2509 JMicron Technology Corp. / JMicron USA Technology Corp. JMS539 SuperSpeed SATA II 3.0G Bridge

[    7.465741] usb 6-1: reset SuperSpeed USB device number 2 using xhci-hcd
[    7.510986] r8152 6-1:1.0 eth0: v2.04.0 (2015/03/06)
[    7.511000] r8152 6-1:1.0 eth0: This product is covered by one or more of the following patents:
                        US6,570,884, US6,115,776, and US6,327,625.
               
[    8.359404] scsi 0:0:0:0: Direct-Access     Jmicron  Corp.                 PQ: 0 ANSI: 2 CCS
[    8.361974] sd 0:0:0:0: [sda] 1953524995 512-byte logical blocks: (1.00 TB/931 GiB)
[    8.362023] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    8.362502] sd 0:0:0:0: [sda] Write Protect is off
[    8.362518] sd 0:0:0:0: [sda] Mode Sense: 28 00 00 00
[    8.362900] sd 0:0:0:0: [sda] No Caching mode page found
[    8.362915] sd 0:0:0:0: [sda] Assuming drive cache: write through
[    8.732395]  sda: sda1 sda2
[    8.735610] sd 0:0:0:0: [sda] Attached SCSI disk
[    9.152874] Adding 4194300k swap on /dev/sda1.  Priority:-1 extents:1 across:4194300k 
[    9.381289] EXT4-fs (sda2): recovery complete
[    9.381313] EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts: (null)
[   10.124210] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[   13.934238] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[27362.248366] usb 3-1.2: reset high-speed USB device number 3 using xhci-hcd
[27431.208260] usb 3-1.2: reset high-speed USB device number 3 using xhci-hcd
[27436.297052] sd 0:0:0:0: [sda] UNKNOWN(0x2003) Result: hostbyte=0x03 driverbyte=0x00
[27436.297120] sd 0:0:0:0: [sda] CDB: opcode=0x28 28 00 6f c0 87 10 00 00 08 00
[27436.297169] blk_update_request: I/O error, dev sda, sector 1874888464
[27436.319194] xhci-hcd xhci-hcd.6.auto: WARN Event TRB for slot 3 ep 2 with no TDs queued?
[27436.319337] sd 0:0:0:0: [sda] UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[27436.319427] sd 0:0:0:0: [sda] CDB: opcode=0x28 28 00 6f c0 87 18 00 00 f0 00
[27436.319475] blk_update_request: I/O error, dev sda, sector 1874888472
[27437.855255] xhci-hcd xhci-hcd.6.auto: WARN Event TRB for slot 3 ep 2 with no TDs queued?
[27439.202027] usb 3-1.2: USB disconnect, device number 3
[27439.208299] sd 0:0:0:0: [sda] UNKNOWN(0x2003) Result: hostbyte=0x01 driverbyte=0x00
[27439.208361] sd 0:0:0:0: [sda] CDB: opcode=0x28 28 00 6f c0 87 20 00 00 e8 00
[27439.208416] blk_update_request: I/O error, dev sda, sector 1874888480
[27439.208846] sd 0:0:0:0: [sda] UNKNOWN(0x2003) Result: hostbyte=0x01 driverbyte=0x00
[27439.208943] sd 0:0:0:0: [sda] CDB: opcode=0x2a 2a 00 3a 45 1e f0 00 00 f0 00
[27439.208995] blk_update_request: I/O error, dev sda, sector 977608432
[27439.209172] EXT4-fs error (device sda2): __ext4_get_inode_loc:3927: inode #58391728: block 233312234: comm svn: unable to read itable block
[27439.209553] Write-error on swap-device (8:0:15512)
[27439.210075] Read-error on swap-device (8:0:4864)
[27439.210937] Aborting journal on device sda2-8.
[27439.212396] Read-error on swap-device (8:0:15296)
[27439.213410] JBD2: Error -5 detected when updating journal superblock for sda2-8.
[27439.218231] Read-error on swap-device (8:0:15304)
[27439.218315] Read-error on swap-device (8:0:15312)
[27439.218564] Read-error on swap-device (8:0:15320)
[27440.166054] Read-error on swap-device (8:0:9192)
[27440.166066] Read-error on swap-device (8:0:9200)
[27440.166074] Read-error on swap-device (8:0:9208)
[27440.166081] Read-error on swap-device (8:0:9216)
[27440.187517] Read-error on swap-device (8:0:9320)

[Obihoernchen]

Maybe related: #166 ?

[uDude]

You should consider switching to the odroidxu4-v4.6.3 kernel. A lot of changes are going on there and I believe @tobetter will be releasing a server OS based on the 4.6 kernel. Any problems in that kernel should be discussed (probably close this and start a new ticket if needed under that code base.

[jobenvil]

yes, indeed, I'm trying to clarify from where it comes this issue. I though, it will be solved with newer kernels, like 4.6.X, etc, but it wasn't. Even with 4.7-rc4 I observe same behaviour. Yesterday I got following error during f.e.: rsync /media/usb1 /media/usb2, during this command the harddisk will be unmounted and the rsync command breaks:

root@hiperborea:~# [ 5796.947852] blk_update_request: I/O error, dev sda, sector 251955144
[ 5796.953522] blk_update_request: I/O error, dev sda, sector 251955400
[ 5797.299869] EXT4-fs error (device sda2): ext4_find_entry:1456: inode #4456451: comm rsync: reading directory lblock 0
[ 5797.309102] Aborting journal on device sda2-8.
[ 5797.313422] Buffer I/O error on dev sda2, logical block 60325888, lost sync page write
[ 5797.321372] JBD2: Error -5 detected when updating journal superblock for sda2-8.
[ 5797.328774] EXT4-fs (sda2): Remounting filesystem read-only

Now I'm doing the same using a Banana Pro for copying the files instead the OdroidXU4. In this case, during the copyng with same rsync command I observe errors on USB, but more intelligent handling reducing the speed of the sata speed link automatically and following the rsync process (still copying in this moment):

[ 1299.408654] usb 2-1: new high-speed USB device number 2 using ehci-platform
[ 1299.590648] usb 2-1: New USB device found, idVendor=152d, idProduct=3562
[ 1299.590681] usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1299.590707] usb 2-1: Product: AD TO BE II
[ 1299.590724] usb 2-1: Manufacturer: ADMKIV
[ 1299.590740] usb 2-1: SerialNumber: DB123456789628
[ 1299.594331] scsi host2: uas
[ 1299.596990] scsi 2:0:0:0: Direct-Access     ADplus   SuperVer         6302 PQ: 0 ANSI: 6
[ 1299.671401] sd 2:0:0:0: Attached scsi generic sg2 type 0
[ 1299.671859] sd 2:0:0:0: [sdc] 976773168 512-byte logical blocks: (500 GB/466 GiB)
[ 1299.671887] sd 2:0:0:0: [sdc] 4096-byte physical blocks
[ 1299.674352] sd 2:0:0:0: [sdc] Write Protect is off
[ 1299.674396] sd 2:0:0:0: [sdc] Mode Sense: 53 00 00 08
[ 1299.675435] sd 2:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 1299.733752]  sdc: sdc1 sdc2
[ 1299.743770] sd 2:0:0:0: [sdc] Attached SCSI disk
[ 1393.488354] EXT4-fs (sdc2): mounted filesystem with ordered data mode. Opts: (null)
[ 3108.943181] ata1: exception Emask 0x10 SAct 0x0 SErr 0x10200 action 0xe frozen
[ 3108.958612] ata1: irq_stat 0x00400000, PHY RDY changed
[ 3108.968376] ata1: SError: { Persist PHYRdyChg }
[ 3108.977295] ata1: hard resetting link
[ 3112.664401] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 3112.703827] ata1.00: configured for UDMA/133
[ 3112.703882] ata1: EH complete
[ 3112.997537] ata1: exception Emask 0x10 SAct 0x0 SErr 0x10200 action 0xe frozen
[ 3113.008408] ata1: irq_stat 0x00400000, PHY RDY changed
[ 3113.017104] ata1: SError: { Persist PHYRdyChg }
[ 3113.025302] ata1: hard resetting link
[ 3115.084371] ata1: SATA link down (SStatus 0 SControl 300)
[ 3115.084409] ata1.00: link offline, clearing class 1 to NONE
[ 3115.112720] ata1: hard resetting link
[ 3120.474327] ata1: link is slow to respond, please be patient (ready=0)
[ 3124.154497] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 3124.156609] ata1.00: failed to IDENTIFY (I/O error, err_mask=0x100)
[ 3124.156637] ata1.00: revalidation failed (errno=-5)
[ 3124.166027] ata1: limiting SATA link speed to 1.5 Gbps
[ 3129.154604] ata1: hard resetting link
[ 3129.478364] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 3129.481557] ata1.00: configured for UDMA/133
[ 3129.481609] ata1: EH complete
[ 4499.520937] ata1.00: exception Emask 0x10 SAct 0x0 SErr 0x10200 action 0xe frozen
[ 4499.537317] ata1.00: irq_stat 0x00400000, PHY RDY changed
[ 4499.547481] ata1: SError: { Persist PHYRdyChg }
[ 4499.556923] ata1.00: failed command: SMART
[ 4499.566013] ata1.00: cmd b0/d5:01:01:4f:c2/00:00:00:00:00/00 tag 20 pio 512 in
                        res 50/00:00:00:4f:c2/00:00:00:00:00/40 Emask 0x10 (ATA bus error)
[ 4499.595255] ata1.00: status: { DRDY }
[ 4499.604053] ata1: hard resetting link
[ 4502.670925] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 4502.694206] ata1.00: configured for UDMA/133
[ 4502.694388] ata1: EH complete
root@locky:/media# uname -a
Linux locky 4.6.2-sunxi #1 SMP Thu Jun 9 02:59:09 PDT 2016 armv7l armv7l armv7l GNU/Linux

Somehow in case of odroidXU4 is using the xhci protocol, uas and the same BUS 04. In case of the Banana Pro is using ehci, uas and different BUSes.

I agree, this can be closed and in case reopened with new Kernel. -but maybe is not kernel relevant-