On Thu, 27 Apr 2006, Christian Haul wrote:

> Alan Stern wrote:
> 
> > I was hoping to see more than one cycle of this.  Although I could do a
> 
> I did a
> # /etc/dbus-1/event.d/20hal start ; \
>   sleep 60 ; /etc/dbus-1/event.d/20hal stop
> and this is all that dmesg outputs (if it doesn't suffice, I would need
> to enlarge the kernel buffer).

This looks like enough.  Here are all the "thread awakened" and "thread 
sleeping" lines:

[  440.396584] usb-storage: *** thread awakened.
[  440.415035] usb-storage: *** thread sleeping.
[  440.415504] usb-storage: *** thread awakened.
[  440.430978] usb-storage: *** thread sleeping.
[  440.432636] usb-storage: *** thread awakened.
[  440.450978] usb-storage: *** thread sleeping.
[  440.836276] usb-storage: *** thread awakened.
[  440.854652] usb-storage: *** thread sleeping.
[  440.858096] usb-storage: *** thread awakened.
[  440.877617] usb-storage: *** thread sleeping.
[  440.879148] usb-storage: *** thread awakened.
[  440.895587] usb-storage: *** thread sleeping.
[  440.896722] usb-storage: *** thread awakened.
[  440.911559] usb-storage: *** thread sleeping.

Notice that there is very little time between one command ending
("sleeping") and the next command starting ("awakened").  Apart from the
one big interval between 440.450 and 440.836, the vast majority of the
time in this log is spent carrying out the commands.

This clearly indicates a problem in hald.  It has managed to poll an empty
card reader 7 times during 515 ms.  That's a far cry from once every two
seconds!

As for the performance of the usb-storage driver, let's take a closer look 
at one cycle of polling.  Some of the time intervals don't involve the 
driver actually doing any work; it's just waiting for the device to 
respond.  Other processes could execute during those intervals.  I'll 
indicate the intervals where usb-storage was really running.

[  440.396584] usb-storage: *** thread awakened.
[  440.396589] usb-storage: Command TEST_UNIT_READY (6 bytes)
[  440.396591] usb-storage:  00 40 00 00 00 00
[  440.396598] usb-storage: Bulk Command S 0x43425355 T 0xfcf L 0 F 0 Trg 0 LUN 
2 CL 6
[  440.396602] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes

That was 0.018 ms.  Now we wait for the device to receive the TEST UNIT
READY command.

[  440.399025] usb-storage: Status code 0; transferred 31/31
[  440.399029] usb-storage: -- transfer complete
[  440.399032] usb-storage: Bulk command transfer result=0
[  440.399035] usb-storage: Attempting to get CSW...
[  440.399038] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes

Another 0.013 ms.  Now we wait for the device to transfer the status 
information from the command.

[  440.403014] usb-storage: Status code 0; transferred 13/13
[  440.403018] usb-storage: -- transfer complete
[  440.403021] usb-storage: Bulk status result = 0
[  440.403025] usb-storage: Bulk Status S 0x53425355 T 0xfcf R 0 Stat 0x1
[  440.404020] usb-storage: -- transport indicates command failure
[  440.404023] usb-storage: Issuing auto-REQUEST_SENSE
[  440.404029] usb-storage: Bulk Command S 0x43425355 T 0xfd0 L 18 F 128 Trg 0 
LUN 2 CL 6
[  440.404033] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes

This was 1.019 ms, including an unexplained 0.95 ms gap.  Perhaps
something else was running during that time, but I'll count it toward
usb-storage anyway.  Now we wait for the device to receive the REQUEST 
SENSE command.

[  440.407057] usb-storage: Status code 0; transferred 31/31
[  440.407062] usb-storage: -- transfer complete
[  440.407064] usb-storage: Bulk command transfer result=0
[  440.407068] usb-storage: usb_stor_bulk_transfer_buf: xfer 18 bytes

That was 0.011 ms.  Now we wait for the device to transfer the sense data.

[  440.411008] usb-storage: Status code 0; transferred 18/18
[  440.411012] usb-storage: -- transfer complete
[  440.411015] usb-storage: Bulk data transfer result 0x0
[  440.412010] usb-storage: Attempting to get CSW...
[  440.412013] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes

That took 1.005 ms, including another suspicious-looking 0.95 ms gap.  Now 
we wait for the device to transfer the status information.

[  440.414999] usb-storage: Status code 0; transferred 13/13
[  440.415003] usb-storage: -- transfer complete
[  440.415006] usb-storage: Bulk status result = 0
[  440.415009] usb-storage: Bulk Status S 0x53425355 T 0xfd0 R 0 Stat 0x0
[  440.415013] usb-storage: -- Result from auto-sense is 0
[  440.415017] usb-storage: -- code: 0x70, key: 0x2, ASC: 0x3a, ASCQ: 0x0
[  440.415025] usb-storage: Not Ready: Medium not present
[  440.415030] usb-storage: scsi cmd done, result=0x2
[  440.415035] usb-storage: *** thread sleeping.

The remainder of the processing takes 0.036 ms.  Putting it all together, 
usb-storage required 0.018 + 0.013 + 1.019 + 0.011 + 1.005 + 0.036 =
2.102 ms.  That's in line with what I expected.  Notice that the actual 
CPU runtime here is 2.1 ms out of 19.4 ms; the rest of the time was spent 
waiting for the device.

If hald were working correctly, the load imposed on your system by
usb-storage would be about 1 part in 1000.  Without the usb-storage
debugging option, it would be even less.

Alan Stern



-------------------------------------------------------
Using Tomcat but need to do more? Need to support web services, security?
Get stuff done quickly with pre-integrated technology to make your job easier
Download IBM WebSphere Application Server v.1.0.1 based on Apache Geronimo
http://sel.as-us.falkag.net/sel?cmd=lnk&kid=120709&bid=263057&dat=121642
_______________________________________________
Linux-usb-users@lists.sourceforge.net
To unsubscribe, use the last form field at:
https://lists.sourceforge.net/lists/listinfo/linux-usb-users

Reply via email to