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