I attached log file again for you! Thanks! 2011/5/31 Soho Soho123 <soho123.2012@xxxxxxxxx>: > Dears, > > it seems the attached file is fail to linux-usb. I copy the content > from file below: > ================================================================== > USB mon log: > > 81631c00 1943532448 C Zi:1:002:1 0:1:3567:0 32 0:0:12 > 0:3072:12 0:6144:12 0:9216:12 0:12288:12 384 D > S------>81631c00 1943532448 S Zi:1:002:1 -150:1:3567 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > 81631800 1943542448 C Zi:1:002:1 0:1:3599:0 32 0:0:12 > 0:3072:12 0:6144:12 0:9216:12 0:12288:12 384 D > 81631800 1943542448 S Zi:1:002:1 -150:1:3599 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > 81631400 1943542448 C Zi:1:002:1 0:1:3631:0 32 0:0:12 > 0:3072:12 0:6144:12 0:9216:12 0:12288:12 384 D > 81631400 1943542448 S Zi:1:002:1 -150:1:3631 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > 81631000 1943542448 C Zi:1:002:1 0:1:3663:0 32 0:0:12 > 0:3072:12 0:6144:12 0:9216:12 0:12288:12 384 D > 81631000 1943542448 S Zi:1:002:1 -150:1:3663 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > 81ba2c00 1943552448 C Zi:1:002:1 0:1:3695:0 32 0:0:12 > 0:3072:12 0:6144:12 0:9216:12 0:12288:12 384 D > 81ba2c00 1943552448 S Zi:1:002:1 -150:1:3695 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > 81631c00 1943552448 C Zi:1:002:1 0:1:3727:0 32 0:0:12 > 0:3072:12 0:6144:12 0:9216:12 0:12288:12 384 D > S------->81631c00 1943552448 S Zi:1:002:1 -150:1:3727 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > 81631800 1943562448 C Zi:1:002:1 0:1:3759:0 32 0:0:12 > 0:3072:12 0:6144:12 0:9216:12 0:12288:12 384 D > 81631800 1943562448 S Zi:1:002:1 -150:1:3759 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > 81631400 1943562448 C Zi:1:002:1 0:1:3791:0 32 0:0:12 > 0:3072:12 0:6144:12 0:9216:12 0:12288:12 384 D > 81631400 1943562448 S Zi:1:002:1 -150:1:3791 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > 81631000 1943562448 C Zi:1:002:1 0:1:3823:0 32 0:0:12 > 0:3072:12 0:6144:12 0:9216:12 0:12288:12 384 D > 81631000 1943562448 S Zi:1:002:1 -150:1:3823 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > 81ba2c00 1943582448 C Zi:1:002:1 0:1:3855:0 32 0:0:12 > 0:3072:12 0:6144:12 0:9216:12 0:12288:12 3420 D > 81ba2c00 1943582448 S Zi:1:002:1 -150:1:3855 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > C------->81631c00 1943582448 C Zi:1:002:1 0:1:3887:0 32 0:0:12 > 0:3072:1024 0:6144:1024 0:9216:12 0:12288:1024 21636 D > 81631c00 1943582448 S Zi:1:002:1 -150:1:3887 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > 81631800 1943582448 C Zi:1:002:1 0:1:3919:0 32 0:0:12 > 0:3072:1024 0:6144:1024 0:9216:12 0:12288:1024 21636 D > 81631800 1943582448 S Zi:1:002:1 -150:1:3919 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > 81631400 1943582448 C Zi:1:002:1 0:1:3951:0 32 0:0:1024 > 0:3072:1024 0:6144:12 0:9216:1024 0:12288:1024 24672 D > 81631400 1943582448 S Zi:1:002:1 -150:1:3951 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > 81631000 1943582448 C Zi:1:002:1 0:1:3983:0 32 0:0:1024 > 0:3072:12 0:6144:1024 0:9216:1024 0:12288:12 24672 D > 81631000 1943582448 S Zi:1:002:1 -150:1:3983 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > 81ba2c00 1943582448 C Zi:1:002:1 0:1:4015:0 32 -18:0:0 > -18:3072:0 -18:6144:0 -18:9216:0 -18:12288:0 0 > 81ba2c00 1943582448 S Zi:1:002:1 -150:1:4015 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > 81631c00 1943582448 C Zi:1:002:1 0:1:4047:0 32 -18:0:0 > -18:3072:0 -18:6144:0 -18:9216:0 -18:12288:0 0 > 81631c00 1943582448 S Zi:1:002:1 -150:1:4047 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > 81631c00 0 E Zi:0:002:1 -27 0 > 81631800 1943582448 C Zi:1:002:1 0:1:4079:0 32 -18:0:0 > -18:3072:0 -18:6144:0 -18:9216:0 -18:12288:0 0 > 81631800 1943582448 S Zi:1:002:1 -150:1:4079 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > 81631400 1943582448 C Zi:1:002:1 0:1:15:0 32 -18:0:0 > -18:3072:0 -18:6144:0 -18:9216:0 -18:12288:0 0 > 81631400 1943582448 S Zi:1:002:1 -150:1:15 32 -18:0:3072 > -18:3072:3072 -18:6144:3072 -18:9216:3072 -18:12288:3072 98304 < > ========================================================================================================== > the error log from console: > [1943582448] iso_stream_schedule:line=1514, request 81631c00 would > overflow (3924+31 >= 3936) > [1943582448] iso_stream_schedule > [1943582448] mod=4096, span=32 > [1943582448] now=283 > [1943582448] start=4207 > [1943582448] next=283 > [1943582448] period=1 > [1943582448] excess=3923 > [1943582448] stream->next_uframe=111 > [1943582448] uvcvideo: Failed to resubmit video URB (-27). > > [1943592448] iso_stream_schedule:line=1514, request 81631800 would > overflow (3908+31 >= 3936) > [1943592448] iso_stream_schedule > [1943592448] mod=4096, span=32 > [1943592448] now=1195 > [1943592448] start=5103 > [1943592448] next=1195 > [1943592448] period=1 > [1943592448] excess=3907 > [1943592448] stream->next_uframe=1007 > [1943592448] uvcvideo: Failed to resubmit video URB (-27). > > [1943692448] iso_stream_schedule:line=1514, request 81ba2c00 would > overflow (3926+31 >= 3936) > [1943692448] iso_stream_schedule > [1943692448] mod=4096, span=32 > [1943692448] now=2777 > [1943692448] start=6703 > [1943692448] next=2777 > [1943692448] period=1 > [1943692448] excess=3925 > [1943692448] stream->next_uframe=2607 > [1943692448] uvcvideo: Failed to resubmit video URB (-27). > > [1943792448] iso_stream_schedule:line=1514, request 81631400 would > overflow (3924+31 >= 3936) > [1943792448] iso_stream_schedule > [1943792448] mod=4096, span=32 > [1943792448] now=283 > [1943792448] start=4207 > [1943792448] next=283 > [1943792448] period=1 > [1943792448] excess=3923 > [1943792448] stream->next_uframe=111 > [1943792448] uvcvideo: Failed to resubmit video URB (-27). > > [1943892448] iso_stream_schedule:line=1514, request 81631000 would > overflow (3923+31 >= 3936) > [1943892448] iso_stream_schedule > [1943892448] mod=4096, span=32 > [1943892448] now=1884 > [1943892448] start=5807 > [1943892448] next=1884 > [1943892448] period=1 > [1943892448] excess=3922 > [1943892448] stream->next_uframe=1711 > [1943892448] uvcvideo: Failed to resubmit video URB (-27). > ================================================================================= > > 2011/5/30 Soho Soho123 <soho123.2012@xxxxxxxxx>: >> Dears, >> >> >> The attached is the log from USB mon, and error log. We have question >> about period of uvc driver submit urb. >> in 1.mon_2.out is USB Mon output log, line 8120 is the latest normal >> urb submit, line 8129 is the urb complete after 30 ms. >> in 0530_2log is the output message from console. >> From the output of USB mon, we can see the normally 20ms is period for >> uvc submit urb. >> But when the period is not 20 ms, then ehci host driver will return error. >> Could you kindly help to explain form detail for the mechanism in echi >> ISO schedule? >> We still do not get the point about ehci iso schedule checking criterion. >> 20ms may critical in our embedded system , since usb and wifi will >> share CPU simultaneously. If WiFi is not transmit smoothly, then WiFi >> driver will re-try. Such that USB may not service in at once. >> >> Thanks! >> >> Best Regards, >> Soho >> >> 2011/5/26 Alan Stern <stern@xxxxxxxxxxxxxxxxxxx>: >>> On Thu, 26 May 2011, Soho Soho123 wrote: >>> >>>> Dears, >>>> >>>> let me describe the detail about my testing: >>>> Stream Server is MJPG-Streamer >>>> ================================================================ >>>> A. >>>> Using linux 2.6.30 kernel do the testing, and DO NOT update linux usb >>>> subsystem code (usb core , usb host driver), and DO NOT update UVC >>>> driver >>>> >>>> RESULT: IP Cam stream can work over night >>> >>> This is because the code in 2.6.30 is buggy. It should have stopped >>> with an error, but it didn't. >>> >>>> ------------------------------------------------------------------------------------------------------------------------------ >>>> B. >>>> Using Linux 2.6.30 kernel do the testing, and Update linux usb >>>> subsystem code up to linux 2.6.39 (include the patch that I have >>>> mentioned) and DO NOT update UVC driver >>>> >>>> RESULT: IP cam stream can work for a few minutes only, then UVC driver >>>> will get submit urb error (-27) , error message list below: >>>> # [ 1067.188000] iso_stream_schedule:line=1514, request 812acc00 would >>>> overflow (3914+31 >= 3936) >>>> [ 1067.188000] uvcvideo: Failed to resubmit video URB (-27). >>>> [ 1067.192000] iso_stream_schedule:line=1514, request 8145bc00 would >>>> overflow (3917+31 >= 3936) >>>> [ 1067.192000] uvcvideo: Failed to resubmit video URB (-27). >>>> [ 1067.292000] iso_stream_schedule:line=1514, request 81769000 would >>>> overflow (3919+31 >= 3936) >>>> [ 1067.292000] uvcvideo: Failed to resubmit video URB (-27). >>>> [ 1067.392000] iso_stream_schedule:line=1514, request 81769400 would >>>> overflow (3918+31 >= 3936) >>>> [ 1067.392000] uvcvideo: Failed to resubmit video URB (-27). >>>> [ 1067.492000] iso_stream_schedule:line=1514, request 81769800 would >>>> overflow (3917+31 >= 3936) >>>> [ 1067.492000] uvcvideo: Failed to resubmit video URB (-27). >>> >>> This happens because the uvcvideo driver is falling behind. It is >>> submitting new isochronous URBs too late -- more than 20 ms after the >>> previuos isochronous URB finished. >>> >>>> ------------------------------------------------------------------------------------------------------------------------------- >>>> C. >>>> Using Linux 2.6.30 kernel do the testing, and Update linux usb >>>> subsystem code up to linux 2.6.39 (include the patch that I have >>>> mentioned) and Update UVC driver, we modify the number of URBs in >>>> vuvcideo.h >>>> UVC_URBS 5 >>>> to >>>> UVC_URBS 20 >>>> >>>> RESULT: IP cam stream can work for over night, but there is some urb >>>> submit error occur. The stream can keep working even the urb submit >>>> error. >>> >>> This is because now there is more room for latency. The real problem >>> is that uvcvideo needs to submit new URBs periodically, but on your >>> system it was delayed by 20 ms. In other words, something on your >>> system is causing interrupt latencies that are several tens of >>> milliseconds. >>> >>>> ================================================================ >>>> We would like to figure out the reason about new usb subsystem code >>>> need more UVC_URB for working long time.Coule you provide the hints >>>> for us, such that we can go in depth for tracing the flow in ehci iso >>>> schedule scheme? >>> >>> >>>> the error log is : >>>> ========================================================== >>>> 474.348000] iso_stream_schedule:line=1514, request 8176bc00 would overflow (3936+31 >= 3936) >>>> [ 474.348000] iso_stream_schedule >>>> [ 474.348000] mod=4096, sched->span=32 >>> >>> You should look at span, not sched->span. You should also look at >>> stream->next_uframe. >>> >>>> [ 474.348000] now=773 >>>> [ 474.348000] start=4709 >>>> [ 474.348000] next=773 >>>> [ 474.348000] period=1 >>>> [ 474.348000] uvcvideo: Failed to resubmit video URB (-27). >>>> [ 474.352000] iso_stream_schedule:line=1514, request 8176b000 would overflow (3932+31 >= 3936) >>>> [ 474.352000] iso_stream_schedule >>>> [ 474.352000] mod=4096, sched->span=32 >>>> [ 474.352000] now=784 >>>> [ 474.352000] start=4716 >>>> [ 474.352000] next=784 >>>> [ 474.352000] period=1 >>>> [ 474.352000] uvcvideo: Failed to resubmit video URB (-27). >>>> ========================================================== >>>> it seems the index of schedule list is corrupt, right? >>> >>> No. The schedule list is correct. >>> >>> In iso_stream_schedule(), "now" is the current microframe, and "next" >>> is the earliest microframe a new URB can be added to. "mod" is the >>> length of the schedule. >>> >>> You didn't print out the value of "excess", but I figure it was 3935 >>> for the first URB and 3931 for the second. "excess" is the how many >>> microframes will pass before the currently scheduled URBs are finished. >>> Values greater than 4096 - 160 = 3936 are taken to be negative numbers >>> modulo 4096 (i.e., they indicate the currently scheduled URBs are >>> _already_ finished). >>> >>> In your case, it looks like the currently scheduled URBs are indeed >>> already finished, but more than 160 microframes ago since 3935 and >>> 3931 are both less than 3936. >>> >>> Alan Stern >>> >>> >> >
<<attachment: log.zip>>
