On Wednesday November 16, [EMAIL PROTECTED] wrote: > On Wed, 16 Nov 2005, Neil Brown wrote: > > > I've got piles of usbmon logs, and I'm happy to create more. Could > > you be specific about that would help, and different setting show > > different things differently :-) > > > > For example, I have a rather nice log with 64 byte writes (so there is > > one packet per UDB). If I take the completion time stamps, find the > > remainder after dividing by 111838(microseconds) and graph that I get > > a really interesting graph!! I cannot explain all the features, but > > I'm sure they correlate significantly to some aspect of the printer > > hardware > > If it's so interesting, post it!
Well, seeing you asked... This trace was with 64byte writes, and I think NO_FSBR was set by usblp at the time. I took the timestamp of the completion of urbs from usbmon output and took the remainder after dividing by 111838. That number was chosen by starting with 112000 which seemed to be the approximate length of the strange delays, and the making small changes until I got a nice graph. The graph is
This has several interesting features. 1/ Packets complete only during a 10msec band every 112msecs (approx). 2/ There seems to be a repeating pattern within that 10msec band. 3/ There is a large jump about packet 11000 4/ There is a distinct change around packets 12900 - 13100. 3 is due to the microsecond counter wrapping and is not related to the usb traffic at all. 2 - if we zoom in on the repeating pattern we get:
This shows a regular saw-tooth, with a subsidiary sawtooth on it. If we take just one of those teeth - 4019 to 4082, go back to the data, and get the times between packets completion, we get
3 packets take 2 msecs, several take 112msecs, others take 224msecs. These gaps are actually about 111.98, slightly longer than the overall average of 111.84 4 - if we zoom in on this noise, we see
We see that in the middle of a rather long sawtooth, we start getting completion times that are completely out of sync with the 111838 'clock'. Going back to the data for this time range, and plotting inter-completion time again we get
This shows packets being completed is much less than 112msecs. The actually numbers are all very close to whole milliseconds, ranging from 2 to 21msec, with modes around 7msec and 25msec. So for this short burst, the printer is accepting data at a reasonable speed (But still well short of 1 packet per msec). Interpretation? Who knows..... Maybe there is a clock that ticks every 111.98msec and has a duty cycle that allows packets to arrive during a 1msec period every 111.98msecs. Depending on how that 1msec period aligns with the 1msec usb frame cycle, you get 0, 1, or 2 packets through every 112msecs. But the printer wants that clock to run at 111.84msecs, so it keeps adjusting it. But then why things go crazy and start working better for 200 packets, I have no idea. So... interesting, but very hard to explain. NeilBrown
