libusb阻塞

這兩天發現手頭一個usb指紋頭出現了一點狀況，若libusb以同步方式發送bulk transfer出現阻塞。經過測試發現跟timeout有些關系：若timeout為0（無timeout），不會阻塞；若timeout為1000或者2000，則會。另外，若采用異步方式傳送bulk transfer，則不會阻塞。

 

同步方式

libusb_bulk_transfer(devh, ep_bulk, buf, CAM_BUF_SZ, &len, timeout);

進入libusb研究，發現libusb是采用異步方式來實現的。在do_sync_bulk_transfer中：

 

 

static int do_sync_bulk_transfer ( struct libusb_device_handle * dev_handle ,

unsigned char endpoint , unsigned char * buffer , int length ,

int * transferred , unsigned int timeout , unsigned char type )

{

libusb_fill_bulk_transfer ( transfer , dev_handle , endpoint , buffer , length ,

bulk_transfer_cb , & completed , timeout );

transfer -> type = type ;

 

r = libusb_submit_transfer ( transfer );

if ( r < 0 ) {

libusb_free_transfer ( transfer );

return r ;

}

 

while (! completed ) {

r = libusb_handle_events ( HANDLE_CTX ( dev_handle ));

}

}

這里libusb_fill_bulk_transfer來填充bulk transfer，然后libusb_submit_transfer提交bulk transfer，最后用libusb_handle_events來等待完成。當收到回應后，bulk_transfer_cb回調設置completed，從而阻塞被接觸，函數返回。

 

分段處理bulk transfer

libusb_submit_transfer最終調到了submit_bulk_transfer。該函數會檢查buffer大小，如果大於MAX_BULK_BUFFER_LENGTH（16K），則分成若干16K大小的urb，每個urb指向用戶buffer的適當位置，然后用ioctl(IOCTL_USBFS_SUBMITURB)提交每個urb。

 

收到數據時會判斷是否收齊所有urb。在handle_bulk_completion中，若urb_idx為最后一個urb，則認為收齊了所有的urb。最終會調用usbi_handle_transfer_completion來調用urb callback。

 

timeout處理

若libusb_bulk_transfer傳入的timeout為0，則沒有timeout，libusb會一直等待數據。在libusb_handle_events中設置了一個2s的poll timeout，libusb會在while中一直poll，每次poll的timeout為2s。

 

若設置了timeout，libusb_submit_transfer會按照timeout升序將transfer插入到libusb_context的flying_transfers列表中，然后提交transfer（當然會分段了，如上所述）

 

libusb_handle_events會根據自己設置的2s timeout和flying_transfers中的timeout得出實際timeout，然后用poll查詢usb fd。

 

問題根源

libusb阻塞的原因就是超時。有時usb指紋頭返回數據較慢，在指定的timeout時間內沒有完成所有urb請求，進入超時處理。handle_timeout()會cancel掉為完成的urb（IOCTL_USBFS_DISCARDURB）。在do_sync_bulk_transfer中，由於未完成所有urb，bulk_transfer_cb沒有被調用，從而會阻塞。libusb_handle_events會繼續以2s超時來查詢fd，但由於urb已經取消，設備會返回-2（ENOENT）。

 

按道理講，即使超時，libusb也應該在超時后返回。libusb為什么沒有返回呢？handle_bulk_completion函數中，若讀到ENOENT，awaiting_discard會遞減至0。與awaiting_discard一起的還有awaiting_reap，若二者均為0，也會調用bulk_transfer_cb通知用戶。

 

awaiting_discard在超時時cancel urb時被設置。若ioctl(IOCTL_USBFS_DISCARDURB)返回EINVAL，則awaiting_reap會遞增。

 

經過打印驗證，發現在cancel urb時，對於已經完成的urb，會返回EINVAL。而未完成的urb，則返回0。我想這大概是一個bug，正確做法應該是不要取消已經完成的urb。

 

附：

阻塞時libusb打印

found usbfs at /dev/bus/usb
found usb devices in sysfs
add fd 9 events 1
created default context

scan usb1
sysfs descriptors available
bus=1 dev=1
busnum 1 devaddr 1 session_id 257
allocating new device for1/1(session 257)
scan 1-1
bus=1 dev=2
busnum 1 devaddr 2 session_id 258
allocating new device for1/2(session 258)
scan 1-1.1
bus=1 dev=3
busnum 1 devaddr 3 session_id 259
allocating new device for1/3(session 259)



open 1.3
add fd 11 events 4
destroy device 1.1
destroy device 1.2
configuration 1
interface0
next timeout in2.499878s
poll()2 fds with timeout in2000ms
poll() returned 1
urb type=2 status=0 transferred=0
handling completion status 0
actual_length=0（control transfer的回調）
next timeout in2.499909s
poll()2 fds with timeout in2000ms
poll() returned 1
urb type=2 status=0 transferred=0
handling completion status 0
actual_length=0（另一個control transfer的回調）
need 10 urbs fornew transfer with length 153600
next timeout in0.997836s（從這里開始查詢bulk）
poll()2 fds with timeout in998ms
poll() returned 1
urb type=3 status=0 transferred=16384
handling completion status 0 of bulk urb 1/10
next timeout in0.379086s
poll()2 fds with timeout in380ms
poll() returned 1
urb type=3 status=0 transferred=16384
handling completion status 0 of bulk urb 2/10
next timeout in0.253080s
poll()2 fds with timeout in254ms
poll() returned 0

all URBs have already been processed for timeouts （超時）
poll()2 fds with timeout in2000ms
poll() returned 1
urb type=3 status=-2 transferred=9728
handling completion status -2 of bulk urb 3/10
CANCEL: detected a cancelled URB
all URBs have already been processed for timeouts
poll()2 fds with timeout in2000ms
poll() returned 1
urb type=3 status=-2 transferred=0
handling completion status -2 of bulk urb 4/10
CANCEL: detected a cancelled URB
all URBs have already been processed for timeouts
poll()2 fds with timeout in2000ms
poll() returned 1
urb type=3 status=-2 transferred=0
handling completion status -2 of bulk urb 5/10
CANCEL: detected a cancelled URB
all URBs have already been processed for timeouts
poll()2 fds with timeout in2000ms
poll() returned 1
urb type=3 status=-2 transferred=0
handling completion status -2 of bulk urb 6/10
CANCEL: detected a cancelled URB
all URBs have already been processed for timeouts
poll()2 fds with timeout in2000ms
poll() returned 1
urb type=3 status=-2 transferred=0
handling completion status -2 of bulk urb 7/10
CANCEL: detected a cancelled URB
all URBs have already been processed for timeouts
poll()2 fds with timeout in2000ms
poll() returned 1
urb type=3 status=-2 transferred=0
handling completion status -2 of bulk urb 8/10
CANCEL: detected a cancelled URB
all URBs have already been processed for timeouts
poll()2 fds with timeout in2000ms
poll() returned 1
urb type=3 status=-2 transferred=0
handling completion status -2 of bulk urb 9/10
CANCEL: detected a cancelled URB
all URBs have already been processed for timeouts
poll()2 fds with timeout in2000ms
poll() returned 1
urb type=3 status=-2 transferred=0
handling completion status -2 of bulk urb 10/10
CANCEL: detected a cancelled URB
all URBs have already been processed for timeouts
poll()2 fds with timeout in2000ms
poll() returned 0
all URBs have already been processed for timeouts
poll()2 fds with timeout in2000ms
poll() returned 0
all URBs have already been processed for timeouts
poll()2 fds with timeout in2000ms
poll() returned 0
all URBs have already been processed for timeouts
poll()2 fds with timeout in2000ms
poll() returned 0
all URBs have already been processed for timeouts
poll()2 fds with timeout in2000ms
poll() returned 0
all URBs have already been processed for timeouts
poll()2 fds with timeout in2000ms
poll() returned 0
all URBs have already been processed for timeouts
poll()2 fds with timeout in2000ms
poll() returned 0
all URBs have already been processed for timeouts
poll()2 fds with timeout in2000ms
^C

kernel usbmon的打印：

e8c3a240 1032172219 S Co:1:003:0 s 00090001000000000
e8c3a240 1032173347 C Co:1:003:000
e8c3a240 1032174262 S Co:1:003:0 s 40 e0 0000000000000
e8c3a240 1032174597 C Co:1:003:000
e8c3a240 1032175054 S Co:1:003:0 s 02010000008100000
e8c3a240 1032249749 C Co:1:003:000
e8c3a240 1032250298 S Co:1:003:0 s 40 e5 0000000000000
e8c3a240 1032250634 C Co:1:003:000
e8c3a240 1032251121 S Bi:1:003:1-11516384<
e8c3a440 1032251365 S Bi:1:003:1-11516384<
e8c3a1c0 1032252890 S Bi:1:003:1-11516384<
e8c3a2c0 1032254018 S Bi:1:003:1-11516384<
e8c3a740 1032254475 S Bi:1:003:1-11516384<
e8c3a7c0 1032254871 S Bi:1:003:1-11516384<
e8c3a5c0 1032255268 S Bi:1:003:1-11516384<
e8c3a0c0 1032255695 S Bi:1:003:1-11516384<
e8c3a640 1032256091 S Bi:1:003:1-11516384<
e849ce20 1032256518 S Bi:1:003:1-1156144<
e8c3a240 1032561640 C Bi:1:003:1016384=40e5000000000000 a59fa89e b3a3a09c a899989b 8b8a9ba09f9392a0929f8498
e8c3a440 1033162310 C Bi:1:003:1016384=909e8a928d99898d908f94909ba197a18ba5a69d9396959d948d9e9e968c9584
e8c3a1c0 1033653347 C Bi:1:003:1016384= d1d9d0d8 d3cdd2d7 d1d8c5d6 c5cfd1d3 d0ccd0d4 d0cbd1d1 bed2d2d0 d9dad4d9
e8c3a2c0 1034152250 C Bi:1:003:1016384= a79fa0aa ada2bab2 b6b3a5ad aeae9bb0 b2aa9eaa 9396a8a6 afa5af95 9daaa5ba
e8c3a740 1034753624 C Bi:1:003:1-216320= d6d0d5d2 ccd4c7cc cdd6cfc9 d3d2d2ce cfcfd5c8 d0c4cdc7 cdc9c6ca d4d0cec2
e8c3a2c0 1034753776 S Co:1:002:0 s 23089031000100000
e8c3a2c0 1034754111 C Co:1:002:000
e8c3a7c0 1034755026 C Bi:1:003:1-264= a3a9bda3 a5a4a9a5 93a69e98949d9294 aa9d8d9d 9b91a6a4 a793a097 9b8f8f96
e8c3a2c0 1034755117 S Co:1:002:0 s 23089031000100000
e8c3a2c0 1034755483 C Co:1:002:000
e8c3a5c0 1034756215 C Bi:1:003:1-264= d1c7d2d5 dad6d6db ded1d0da d8d2d4da d3d8d8d6 dbd4dedd d2d5ded5 dbd6d7d8
e8c3a2c0 1034756459 S Co:1:002:0 s 23089031000100000
e8c3a2c0 1034756855 C Co:1:002:000
e8c3a0c0 1034757587 C Bi:1:003:1-264= b04a5e59 637c82707f8483787f7e7881838f8497988a8389938c8f928b8ca28c
e8c3a2c0 1034757648 S Co:1:002:0 s 23089031000100000
e8c3a2c0 1034757983 C Co:1:002:000
e8c3a640 1034758715 C Bi:1:003:1-20
e8c3a2c0 1034758776 S Co:1:002:0 s 23089031000100000
e8c3a2c0 1034759111 C Co:1:002:000
e849ce20 1034759569 C Bi:1:003:1-20
e8c3a2c0 1034759630 S Co:1:002:0 s 23089031000100000
e8c3a2c0 1034759995 C Co:1:002:000