Discussion:
8.0-RC1: AMD CS5536 (Geode) USB 2.0 controller strange behavour
(too old to reply)
Eugene Grosbein
2009-09-26 04:24:23 UTC
Permalink
Hi!

I have got fanless computer named NICE 3120,
it is based on EBC 420-LX8 motherboard and AMD Geode LX800 processor.

I've installed 8.0-RC1 here and it runs just fine as a router
using internal CompactFlash 256Mb card. Now I'm trying to use USB 2.0 HDD
<Seagate FreeAgent Go 102D> that gives me stable 27 megabyte/sec
write speed to /dev/da0 using dd when connected to another 8.0-RC1 system
with ICH7 but with this CS5536 its behavour is very strange.

"dd if=/dev/zero bs=256k of=/dev/da0 count=100" may result in 1.7MBytes/s
or 16Mbytes/s or 400Kbyte/s (sic!) write speed. dd measures speed right,
very often it writes way too slow.

"systat -vm 1" shows that most of time nothing is written in process;
then suddenly lots of bytes are written, then it sits idle again for long time.

As for timecounting,
kern.timecounter.choice: TSC(800) ACPI-safe(850) i8254(0) dummy(-1000000)

ACPI-safe is non-functional here (3 seconds for 30 minutes of real time),
so I use TSC, it works just fine. I've tried i8254 but found no differences.
Ntpd drift is about 148.331 for both of TSC and i8254 and
ntpd keeps time correct.

"pciconf -lv" shows for EHCI:

***@pci0:0:15:5: class=0x0c0320 card=0x20951022 chip=0x20951022
rev=0x02 hdr=0x00
vendor = 'Advanced Micro Devices (AMD)'
device = 'CS5536 EHCI USB Host Controller (CS5536)'
class = serial bus
subclass = USB


This machine is used as home router only and I'm ready to debug.
Remote access is available on request.

The kernel is built with options:

machine i386
cpu I586_CPU
cpu I686_CPU
options NO_F00F_HACK
options CPU_GEODE
options CPU_SOEKRIS
options SCHED_ULE
options PREEMPTION

$ dmesg -a | fgrep -i Geode
CPU: Geode(TM) Integrated Processor by AMD PCS (499.90-MHz 586-class CPU)
glxsb0: <AMD Geode LX Security Block (AES-128-CBC, RNG)> mem 0xef010000-0xef013fff at device 1.2 on pci0
ehci0: <AMD CS5536 (Geode) USB 2.0 controller> mem 0xef018000-0xef018fff irq 10 at device 15.5 on pci0
usbus1: <AMD CS5536 (Geode) USB 2.0 controller> on ehci0

$ sysctl kern.timecounter
kern.timecounter.tick: 1
kern.timecounter.choice: TSC(800) ACPI-safe(850) i8254(0) dummy(-1000000)
kern.timecounter.hardware: TSC
kern.timecounter.stepwarnings: 0
kern.timecounter.tc.i8254.mask: 4294967295
kern.timecounter.tc.i8254.counter: 3806
kern.timecounter.tc.i8254.frequency: 1193182
kern.timecounter.tc.i8254.quality: 0
kern.timecounter.tc.ACPI-safe.mask: 16777215
kern.timecounter.tc.ACPI-safe.counter: 4294967295
kern.timecounter.tc.ACPI-safe.frequency: 3579545
kern.timecounter.tc.ACPI-safe.quality: 850
kern.timecounter.tc.TSC.mask: 4294967295
kern.timecounter.tc.TSC.counter: 1502810203
kern.timecounter.tc.TSC.frequency: 499904675
kern.timecounter.tc.TSC.quality: 800
kern.timecounter.invariant_tsc: 0

Please help.

Eugene Grosbein
Hans Petter Selasky
2009-09-26 07:08:46 UTC
Permalink
Post by Eugene Grosbein
Hi!
I have got fanless computer named NICE 3120,
it is based on EBC 420-LX8 motherboard and AMD Geode LX800 processor.
I've installed 8.0-RC1 here and it runs just fine as a router
using internal CompactFlash 256Mb card. Now I'm trying to use USB 2.0 HDD
<Seagate FreeAgent Go 102D> that gives me stable 27 megabyte/sec
write speed to /dev/da0 using dd when connected to another 8.0-RC1 system
with ICH7 but with this CS5536 its behavour is very strange.
"dd if=/dev/zero bs=256k of=/dev/da0 count=100" may result in 1.7MBytes/s
or 16Mbytes/s or 400Kbyte/s (sic!) write speed. dd measures speed right,
very often it writes way too slow.
Hi,

Try using bs=65536

Any difference.

Output from "usbconfig" would also be nice. Might sound like your device is
sometimes connected at FULL speed.

Have you taken spin-up time into account?

--HPS
Eugene Grosbein
2009-09-26 08:17:33 UTC
Permalink
Post by Hans Petter Selasky
Try using bs=65536
Any difference.
Not better.
Post by Hans Petter Selasky
Output from "usbconfig" would also be nice
%usbconfig
ugen0.1: <OHCI root HUB AMD> at usbus0, cfg=0 md=HOST spd=FULL (12Mbps) pwr=ON
ugen1.1: <EHCI root HUB AMD> at usbus1, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=ON
ugen1.2: <FreeAgent Go Seagate> at usbus1, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=ON

HDD has only one cable connection, so it is powered from USB.
Post by Hans Petter Selasky
Have you taken spin-up time into account?
I made severals tests in a row, speed varies greatly stiil.
And there is no such problem with ICH7-based system (975XBX motherboard).

Please CC: me as I'm not in list.

Eugene Grosbein
Hans Petter Selasky
2009-09-26 08:54:12 UTC
Permalink
Post by Eugene Grosbein
Post by Hans Petter Selasky
Try using bs=65536
Any difference.
Not better.
Post by Hans Petter Selasky
Output from "usbconfig" would also be nice
%usbconfig
ugen0.1: <OHCI root HUB AMD> at usbus0, cfg=0 md=HOST spd=FULL (12Mbps)
pwr=ON ugen1.1: <EHCI root HUB AMD> at usbus1, cfg=0 md=HOST spd=HIGH
(480Mbps) pwr=ON ugen1.2: <FreeAgent Go Seagate> at usbus1, cfg=0 md=HOST
spd=HIGH (480Mbps) pwr=ON
HDD has only one cable connection, so it is powered from USB.
Post by Hans Petter Selasky
Have you taken spin-up time into account?
I made severals tests in a row, speed varies greatly stiil.
And there is no such problem with ICH7-based system (975XBX motherboard).
Hi,

Could you check if these are due to device timeouts in the CAM layer?

There is some debugging you can turn on:

sysctl hw.usb.umass.debug=-1

Probably it will flood the console. Maybe you could add some prints to
/sys/dev/usb/storage/umass.c in all the "default:" cases in the USB callbacks
and print out the "error" code. That would quickly indicate if your device has
an issue with timing, I.E. that the firmware in the USB device part is
hanging.

--HPS
Eugene Grosbein
2009-09-27 14:12:05 UTC
Permalink
Post by Hans Petter Selasky
Could you check if these are due to device timeouts in the CAM layer?
sysctl hw.usb.umass.debug=-1
Probably it will flood the console.
That's not a problem. Anyway, I rlogin to this system
and use syslog to write all console/kernel logs to console.log
and kernel.log

So, I have done:

%sysctl hw.usb.umass.debug=-1
hw.usb.umass.debug: 0 -> -1

Then used another terminal to ran:

%iostat -d -K -w 10 da0
da0
KB/t tps MB/s
2.88 0 0.00

After it started, I switched back to first terminal and ran:

%dd if=/dev/zero bs=64k of=/dev/da0 count=1000

It started to work, meantime iostat output was:

63.62 17 1.05
0.00 0 0.00
0.00 0 0.00
0.00 0 0.00
0.00 0 0.00
0.00 0 0.00
64.00 2 0.15
62.31 83 5.06
0.25 0 0.00
0.00 0 0.00
0.00 0 0.00
^C

To this moment, dd has finished his work and printed:

1000+0 records in
1000+0 records out
65536000 bytes transferred in 78.627073 secs (833504 bytes/sec)

One can see, it sent first chunk of data to the device
than there was quite large period of time without any activity,
more than 50 seconds. Then it has finished.

As for debug log, its uncompressed size is over megabyte
so I've made it available here (25KB compressed):

http://www.grosbein.pp.ru/umass.log.gz

I cannot read/understand it yet.
Post by Hans Petter Selasky
Maybe you could add some prints to
/sys/dev/usb/storage/umass.c in all the "default:" cases in the USB callbacks
and print out the "error" code. That would quickly indicate if your device has
an issue with timing, I.E. that the firmware in the USB device part is hanging.
I still suppose the device is fine because it presents no such problem
being connected to another box with the same 8.0-RC1 (same sources).

Also, I don't feel myself confident with the code to debug it yet...

Eugene Grosbein
Eugene Grosbein
2009-09-27 14:31:38 UTC
Permalink
Post by Eugene Grosbein
%dd if=/dev/zero bs=64k of=/dev/da0 count=1000
63.62 17 1.05
0.00 0 0.00
0.00 0 0.00
0.00 0 0.00
0.00 0 0.00
0.00 0 0.00
64.00 2 0.15
62.31 83 5.06
0.25 0 0.00
0.00 0 0.00
0.00 0 0.00
^C
1000+0 records in
1000+0 records out
65536000 bytes transferred in 78.627073 secs (833504 bytes/sec)
After some googling, I've tried sysctl hw.usb.ehci.no_hs=1,
reconnected HDD and retried the test. iostat output was:

%iostat -d -K -w 10 da0
da0
KB/t tps MB/s
2.88 0 0.00
63.19 8 0.49
64.00 11 0.69
64.00 11 0.69
64.00 11 0.68
64.00 11 0.69
64.00 11 0.69
64.00 11 0.69
64.00 11 0.68
64.00 11 0.69
41.81 7 0.28
0.00 0 0.00
^C

%dd if=/dev/zero bs=64k of=/dev/da0 count=1000
1000+0 records in
1000+0 records out
65536000 bytes transferred in 91.364733 secs (717301 bytes/sec)

So, this time no idle periods but I'm still not happy with the speed.

Eugene Grosbein
Eugene Grosbein
2009-09-27 16:14:08 UTC
Permalink
Post by Eugene Grosbein
%dd if=/dev/zero bs=64k of=/dev/da0 count=1000
63.62 17 1.05
0.00 0 0.00
0.00 0 0.00
0.00 0 0.00
0.00 0 0.00
0.00 0 0.00
64.00 2 0.15
62.31 83 5.06
0.25 0 0.00
0.00 0 0.00
0.00 0 0.00
^C
I've repeated the test with my USB flash drive formatted as FAT32.
It gives the same result: for ICH7-based system I get 26 megabyte/s
file writing speed and for AMD CS5536 it suffers from long periods of inactivity
while writing data, hence very low awarage writing speed.

It seems the root of the problem is in the interaction
between USB stack and AMD CS5536 (Geode) USB 2.0 controller
and not in media devices themselves.

Any more hints please?

Eugene Grosbein
Hans Petter Selasky
2009-09-27 17:40:31 UTC
Permalink
Post by Eugene Grosbein
Post by Eugene Grosbein
%dd if=/dev/zero bs=64k of=/dev/da0 count=1000
63.62 17 1.05
0.00 0 0.00
0.00 0 0.00
0.00 0 0.00
0.00 0 0.00
0.00 0 0.00
64.00 2 0.15
62.31 83 5.06
0.25 0 0.00
0.00 0 0.00
0.00 0 0.00
^C
I've repeated the test with my USB flash drive formatted as FAT32.
It gives the same result: for ICH7-based system I get 26 megabyte/s
file writing speed and for AMD CS5536 it suffers from long periods of
inactivity while writing data, hence very low awarage writing speed.
It seems the root of the problem is in the interaction
between USB stack and AMD CS5536 (Geode) USB 2.0 controller
and not in media devices themselves.
Any more hints please?
sysctl hw.usb.ehci.debug=15

If the USB stack puts the new job into the schedule and the USB controller
does not pick it up, it is not an USB stack problem ...

--HPS
Hans Petter Selasky
2009-09-27 14:29:29 UTC
Permalink
Post by Eugene Grosbein
Post by Hans Petter Selasky
Could you check if these are due to device timeouts in the CAM layer?
sysctl hw.usb.umass.debug=-1
Probably it will flood the console.
That's not a problem. Anyway, I rlogin to this system
and use syslog to write all console/kernel logs to console.log
and kernel.log
%sysctl hw.usb.umass.debug=-1
hw.usb.umass.debug: 0 -> -1
%iostat -d -K -w 10 da0
da0
KB/t tps MB/s
2.88 0 0.00
%dd if=/dev/zero bs=64k of=/dev/da0 count=1000
63.62 17 1.05
0.00 0 0.00
0.00 0 0.00
0.00 0 0.00
0.00 0 0.00
0.00 0 0.00
64.00 2 0.15
62.31 83 5.06
0.25 0 0.00
0.00 0 0.00
0.00 0 0.00
^C
1000+0 records in
1000+0 records out
65536000 bytes transferred in 78.627073 secs (833504 bytes/sec)
One can see, it sent first chunk of data to the device
than there was quite large period of time without any activity,
more than 50 seconds. Then it has finished.
As for debug log, its uncompressed size is over megabyte
http://www.grosbein.pp.ru/umass.log.gz
I cannot read/understand it yet.
Post by Hans Petter Selasky
Maybe you could add some prints to
/sys/dev/usb/storage/umass.c in all the "default:" cases in the USB
callbacks and print out the "error" code. That would quickly indicate if
your device has an issue with timing, I.E. that the firmware in the USB
device part is hanging.
I still suppose the device is fine because it presents no such problem
being connected to another box with the same 8.0-RC1 (same sources).
Also, I don't feel myself confident with the code to debug it yet...
Hi,

The following debug prints clearly show that your device does not respond. And
the USB stack kicks in after a while to fetch the status of the drive.
Previously when I have seen this kind of issues, it was always the USB device
stack that was at failure. I've never seen that it was the fault of the USB
host stack. You would need an USB analyser to figure out for sure. If the
situation is that the USB device hardware is reponding with NAKs to the OUT or
PING tokens (USB term), then the schedule on the USB host is setup correctly
and it is a device problem.

Have you tried contacting the manufacturer of your USB device about this?

What is the CPU speed difference between the two boxes you are running tests
on?

Sep 27 21:50:13 gw kernel: umass0:umass_dump_buffer: 0x
00000000000000000000000000000000 ...
Sep 27 21:50:13 gw kernel: umass0:umass_bbb_dump_cbw: CBW 208: cmd = 10b
(0x2a0000005400...), data = 65536b, lun = 0, dir = out
Sep 27 21:50:13 gw kernel: umass0:umass_transfer_start: transfer index = 6
Sep 27 21:50:13 gw kernel: umass0:umass_t_bbb_data_write_callback:
max_bulk=131072, data_rem=65536
Sep 27 21:51:17 gw kernel: umass0:umass_transfer_start: transfer index = 7
Sep 27 21:51:17 gw kernel: umass0:umass_transfer_start: transfer index = 8
Sep 27 21:51:17 gw kernel: umass0:umass_bbb_dump_csw: CSW 208: sig =
0x53425355 (valid), tag = 0x000000d0, res = 65536, status = 0x01 (failed)
Sep 27 21:51:17 gw kernel: umass0:umass_t_bbb_status_callback: Command failed,
residue = 65536

--HPS
Eugene Grosbein
2009-09-28 00:09:54 UTC
Permalink
Post by Hans Petter Selasky
The following debug prints clearly show that your device does not respond.
And the USB stack kicks in after a while to fetch the status of the drive.
Previously when I have seen this kind of issues, it was always the USB device
stack that was at failure. I've never seen that it was the fault of the USB
host stack.
Then I wonder why both devices (HDD and flash) do not respond being attached
to this CS5536-system and work just fine with another systems.
Post by Hans Petter Selasky
You would need an USB analyser to figure out for sure. If the
situation is that the USB device hardware is reponding with NAKs to the OUT
or PING tokens (USB term), then the schedule on the USB host is setup correctly
and it is a device problem.
What is USB analyser in first place? :-)
Post by Hans Petter Selasky
Have you tried contacting the manufacturer of your USB device about this?
No, because it works with other boxes.
Post by Hans Petter Selasky
What is the CPU speed difference between the two boxes you are running
tests on?
CS5536-based system is uniprocessor and has:

CPU: Geode(TM) Integrated Processor by AMD PCS (499.90-MHz 586-class CPU)
Origin = "AuthenticAMD" Id = 0x5a2 Stepping = 2
Features=0x88a93d<FPU,DE,PSE,TSC,MSR,CX8,SEP,PGE,CMOV,CLFLUSH,MMX>
AMD Features=0xc0400000<MMX+,3DNow!+,3DNow!>

The CPU is idle while dd is running:

CPU: 0.4% user, 0.0% nice, 0.8% system, 1.2% interrupt, 97.7% idle

My ICH7-based desktop is SMP and has:

CPU: Intel(R) Pentium(R) D CPU 2.80GHz (2805.72-MHz 686-class CPU)
Origin = "GenuineIntel" Id = 0xf62 Stepping = 2

Features=0xbfebfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,DTS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE>
Features2=0xe43d<SSE3,DTES64,MON,DS_CPL,VMX,CNXT-ID,CX16,xTPR,PDCM>
AMD Features=0x20100000<NX,LM>
AMD Features2=0x1<LAHF>
TSC: P-state invariant

Eugene Grosbein
Hans Petter Selasky
2009-09-28 06:51:57 UTC
Permalink
Post by Eugene Grosbein
What is USB analyser in first place? :-)
Search for beagle USB analyzer at google.

--HPS
Eugene Grosbein
2009-09-28 03:42:08 UTC
Permalink
Post by Hans Petter Selasky
Post by Eugene Grosbein
I've repeated the test with my USB flash drive formatted as FAT32.
It gives the same result: for ICH7-based system I get 26 megabyte/s
file writing speed and for AMD CS5536 it suffers from long periods of
inactivity while writing data, hence very low awarage writing speed.
It seems the root of the problem is in the interaction
between USB stack and AMD CS5536 (Geode) USB 2.0 controller
and not in media devices themselves.
Any more hints please?
sysctl hw.usb.ehci.debug=15
For USB HDD:

%sysctl hw.usb.ehci.debug=15
hw.usb.ehci.debug: 0 -> 15
%date; dd if=/dev/zero bs=64k of=/dev/da0 count=100; date
Mon Sep 28 11:25:26 KRAST 2009
100+0 records in
100+0 records out
6553600 bytes transferred in 14.912198 secs (439479 bytes/sec)
Mon Sep 28 11:25:43 KRAST 2009

The log is half-megabyte and is available here (13KB compressed):

http://www.grosbein.pp.ru/ehci.log.gz
Post by Hans Petter Selasky
If the USB stack puts the new job into the schedule and the USB controller
does not pick it up, it is not an USB stack problem ...
If so, any workarounds possible?

Eugene Grisbeibn
Hans Petter Selasky
2009-09-28 06:49:21 UTC
Permalink
Post by Eugene Grosbein
Post by Hans Petter Selasky
Post by Eugene Grosbein
I've repeated the test with my USB flash drive formatted as FAT32.
It gives the same result: for ICH7-based system I get 26 megabyte/s
file writing speed and for AMD CS5536 it suffers from long periods of
inactivity while writing data, hence very low awarage writing speed.
It seems the root of the problem is in the interaction
between USB stack and AMD CS5536 (Geode) USB 2.0 controller
and not in media devices themselves.
Any more hints please?
sysctl hw.usb.ehci.debug=15
%sysctl hw.usb.ehci.debug=15
hw.usb.ehci.debug: 0 -> 15
%date; dd if=/dev/zero bs=64k of=/dev/da0 count=100; date
Mon Sep 28 11:25:26 KRAST 2009
100+0 records in
100+0 records out
6553600 bytes transferred in 14.912198 secs (439479 bytes/sec)
Mon Sep 28 11:25:43 KRAST 2009
http://www.grosbein.pp.ru/ehci.log.gz
I don't see any timeouts in there. You need to run the test until you see
something about "timeout".
Post by Eugene Grosbein
Post by Hans Petter Selasky
If the USB stack puts the new job into the schedule and the USB
controller does not pick it up, it is not an USB stack problem ...
If so, any workarounds possible?
None which I know about.

--HPS
Eugene Grosbein
2009-09-28 07:27:26 UTC
Permalink
Post by Hans Petter Selasky
Post by Eugene Grosbein
%sysctl hw.usb.ehci.debug=15
hw.usb.ehci.debug: 0 -> 15
%date; dd if=/dev/zero bs=64k of=/dev/da0 count=100; date
Mon Sep 28 11:25:26 KRAST 2009
100+0 records in
100+0 records out
6553600 bytes transferred in 14.912198 secs (439479 bytes/sec)
Mon Sep 28 11:25:43 KRAST 2009
http://www.grosbein.pp.ru/ehci.log.gz
I don't see any timeouts in there. You need to run the test until you see
something about "timeout".
It's so strange... While hw.usb.ehci.debug=15 idle periods are very seldom,
iostat shows nearly constat (but very slow) data rate:

KB/t tps MB/s
64.00 9 0.57
64.00 9 0.57
64.00 9 0.57
64.00 9 0.57
64.00 9 0.57

No 'timeout' word in the log. It seems that debugging changes something.

Eugene Grosbein
Eugene Grosbein
2009-09-28 17:29:50 UTC
Permalink
Post by Hans Petter Selasky
Post by Eugene Grosbein
Post by Hans Petter Selasky
If the USB stack puts the new job into the schedule and the USB
controller does not pick it up, it is not an USB stack problem ...
If so, any workarounds possible?
None which I know about.
I've just found one. I noticed that USB controller here uses IRQ10
and shares it with NIC and FireWire. This system does not support IO-APIC.
I've disabled ACPI and NIC has moved to another IRQ,
USB and FireWire still share one IRQ but now there are no stalled transfers.
I get stable 16.2 megabyte/s writing speed to USB HDD.

Now I wonder if there is another way to assign distinct IRQ for USB,
BIOS Setup does not help.

Eugene Grosbein.

Loading...