On 2014-03-11 00:16, Hamish Moffatt wrote:
On 11/03/14 00:52, Jef Driesen wrote:
The slowness is expected. The attached patch introduces a 100ms delay before each command. With 4096 packets (of only 16 bytes), that means a total delay of at least 409.6 seconds. That alone is already a very good reason not to apply this patch, especially because most users don't need it. But it does give a good indication that the real problem is likely something timing related. The question is of course what and where.
Something else that is worth trying is increasing the 100ms delay in the oceanic_atom2_device_open() function. I don't really understand why, but some interfaces seem to need some extra time between setting up the serial port and sending the first data packet. I suspect that the OS or driver is async and returns before the settings are actually applied, causing us to send data before the device is ready. But I'm not really sure about that. Anyway, adding some extra delay there isn't that much of a problem because it's just a one time delay.
Increasing the delay in the oceanic_atom2_device_open() function didn't help (tried 1 second even). A delay of 1ms inside oceanic_atom2_send() was enough for a perfect transfer, but 0.5ms (via usleep() for hack's sake) was not enough.
Even a sleep of just 1ms per packet is pretty bad. If I remember correctly, the resolution of the Windows Sleep() function is in the order of 10-15ms only. So that would still be a delay of approximately 40.96 seconds.
I wonder if this is another case where the tcdrain() function isn't waiting properly until all bytes have been send out. We had a similar problem with Suunto devices before. There we implemented a workaround with serial_set_halfduplex() function. Could you try that as well? Just call it somewhere in the oceanic_atom2_device_open() function, but before the call to the oceanic_atom2_device_open() function.
How many wires does the Oceanic interface have? Just two or more?
I have been looking at the kernel history for the ftdi usb-serial driver, and there have been some changes related to waiting until the TX buffer is empty, so there could be something there as well. Which kernel version do you have (uname -a)?
PS: Don't forget to attach the logfiles. I want to have a look at the timings.
Jef
On Tue, Mar 11, 2014 at 6:27 AM, Jef Driesen jef@libdivecomputer.org wrote:
I wonder if this is another case where the tcdrain() function isn't waiting properly until all bytes have been send out.
Assuming it is ftdi, we should have at least *tried* to do it since 3.8, but I really won't guarantee that it works. I'm assuming Hamish has something newer than that, but who knows.. As usual, I think Debian "stable" (also known as "bat shit crazy") is some ancient 3.2 kernel still, but all other distros should be much more up-to-date.
We had a similar problem with Suunto devices before.
As you know (but perhaps others don't) this isn't a Suunto problem per se - the actual *real* legacy serial cable should work fine, because on a real UART we generally have an easy way to check whether the send buffer has actually flushed out.
But the USB people originally (consciously) decided to not make USB -> serial be a standard, because their argument was that USB should replace serial lines, and USB serial dongles were thus "invalid". Morons with an agenda. As a result, there is no actual standard USB serial conversion model, and every single USB serial chip is a "hack" pretty much by definition.
And with simplex being *so* unusual, it doesn't get a lot of attention and testing, and since it's not some generic standard, it's always per-dongle-chip-driver.
I have been looking at the kernel history for the ftdi usb-serial driver, and there have been some changes related to waiting until the TX buffer is empty, so there could be something there as well. Which kernel version do you have (uname -a)?
There have been interface changes, but I don't think the functionality should have changed since 3.8 (and before that, we had no "wait for the dongle buffer" code at all for ftdi).
That said, see above about lack of test coverage. Maybe the interface changes broke something by mistake. And maybe it didn't work reliably to begin with ;)
So yeah, kernel version would be interesting, but no guarantees even then. Except for the guarantee that pre-3.8 it certainly didn't wait for the ftdi dongle to drain.
Linus
On 12/03/14 02:59, Linus Torvalds wrote:
On Tue, Mar 11, 2014 at 6:27 AM, Jef Driesen jef@libdivecomputer.org wrote:
I wonder if this is another case where the tcdrain() function isn't waiting properly until all bytes have been send out.
Assuming it is ftdi, we should have at least *tried* to do it since 3.8, but I really won't guarantee that it works. I'm assuming Hamish has something newer than that, but who knows.. As usual, I think Debian "stable" (also known as "bat shit crazy") is some ancient 3.2 kernel still, but all other distros should be much more up-to-date.
I'm indeed running Debian "bat shit crazy", previously 3.2.0. I've updated to 3.12.9 just now and I don't see any change in downloading from the VT3 though.
3.12.9 was the latest I had easy access to from Debian packages; I can build from source if you think a later version might help though.
[0.000052] DATETIME 2014-03-11T23:16:41Z (1394579801) [0.000102] VERSION 0.4.2 [0.000112] DEVICE=/dev/ttyUSB0 [0.000122] oceanic_atom2_device_open [0.000801] INFO: Configure: baudrate=38400, databits=8, parity=0, stopbits=1, flowcontrol=0 [0.000907] INFO: Timeout: value=3000 [0.000918] INFO: Sleep: value=100 [0.101007] INFO: Flush: queue=3, input=1, output=0 [0.101491] INFO: Write: size=2, data=8400 [0.102869] INFO: Read: size=1, data=5A [0.107847] INFO: Read: size=17, data=4F43452056543320523244203531324BBF [0.107882] dc_device_dump [0.111449] INFO: Write: size=4, data=B1000000 [0.111487] INFO: Read: size=1, data=5A [0.120731] INFO: Read: size=17, data=0416041120081001425800730000000075 [0.123448] INFO: Write: size=4, data=B1000100 [0.123488] INFO: Read: size=1, data=A5 [0.123497] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:339 (oceanic_atom2_send)] [0.123505] INFO: Sleep: value=100 [0.223573] INFO: Flush: queue=1, input=0, output=0 [0.227438] INFO: Write: size=4, data=B1000100 [0.227452] INFO: Read: size=1, data=5A [0.236289] INFO: Read: size=17, data=6701DA064204E506E206DC06FF0FAAFBF6 [0.239433] INFO: Write: size=4, data=B1000200 [0.239445] INFO: Read: size=1, data=A5 [0.239449] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:339 (oceanic_atom2_send)]
Hamish
On Tue, Mar 11, 2014 at 4:43 PM, Hamish Moffatt hamish@cloud.net.au wrote:
I'm indeed running Debian "bat shit crazy", previously 3.2.0. I've updated to 3.12.9 just now and I don't see any change in downloading from the VT3 though.
3.12.9 was the latest I had easy access to from Debian packages; I can build from source if you think a later version might help though.
No, 3.12.9 is quite reasonable (in a way that 3.2 is not). There haven't been any ftdi changes in this area since, afaik.
Sounds like some other timing difference between Linux and Windows. Maybe Jef can make sense to the logs (and do you have logs with timing from windows for Jef to compare?)
Linus
On 12/03/14 10:57, Linus Torvalds wrote:
On Tue, Mar 11, 2014 at 4:43 PM, Hamish Moffatt hamish@cloud.net.au wrote:
I'm indeed running Debian "bat shit crazy", previously 3.2.0. I've updated to 3.12.9 just now and I don't see any change in downloading from the VT3 though.
3.12.9 was the latest I had easy access to from Debian packages; I can build from source if you think a later version might help though.
No, 3.12.9 is quite reasonable (in a way that 3.2 is not). There haven't been any ftdi changes in this area since, afaik.
Sounds like some other timing difference between Linux and Windows. Maybe Jef can make sense to the logs (and do you have logs with timing from windows for Jef to compare?)
Here's a log from Windows. There appears to be a whole lot less timing precision so it's a bit hard to compare, other than noting the absence of NAKs from the VT3.
I'd try it on Mac OS too but apparently I have to reboot the thing to get the driver loaded and /dev entry created. Happy to try if it would help.
[0.000] DATETIME 2014-03-12T00:04:02Z (1394582642) [0.000] VERSION 0.5.0-devel (575f2e9016ac9baa2b1b031caa6fe0bc77cdbbee) [0.000] DEVICE=COM3 [0.000] oceanic_atom2_device_open [0.000] INFO: Open: name=COM3 [0.047] INFO: Configure: baudrate=38400, databits=8, parity=0, stopbits=1, flowcontrol=0 [0.047] INFO: Timeout: value=3000 [0.047] INFO: Sleep: value=100 [0.156] INFO: Flush: queue=3, input=0, output=0 [0.156] INFO: Write: size=2, data=8400 [0.156] INFO: Read: size=1, data=5A [0.156] INFO: Read: size=17, data=4F43452056543320523244203531324BBF [0.172] dc_device_dump [0.172] INFO: Write: size=4, data=B1000000 [0.187] INFO: Read: size=1, data=5A [0.187] INFO: Read: size=17, data=0416041120081001425800730000000075 [0.187] INFO: Write: size=4, data=B1000100 [0.187] INFO: Read: size=1, data=5A [0.203] INFO: Read: size=17, data=6701DA064204E506E206DC06FF0FAAFBF6 [0.203] INFO: Write: size=4, data=B1000200 [0.219] INFO: Read: size=1, data=5A [0.219] INFO: Read: size=17, data=0000DC06FF0FDC06FF0F00000000AA8A14 [0.219] INFO: Write: size=4, data=B1000300 [0.234] INFO: Read: size=1, data=5A [0.234] INFO: Read: size=17, data=890E370D00011B0B670542053250AAE1C2 [0.234] INFO: Write: size=4, data=B1000400 [0.250] INFO: Read: size=1, data=5A [0.250] INFO: Read: size=17, data=300220028003500530BEB0BB0000000085 [0.250] INFO: Write: size=4, data=B1000500 [0.265] INFO: Read: size=1, data=5A [0.265] INFO: Read: size=17, data=A014000300002C01980805A0022100024E [0.265] INFO: Write: size=4, data=B1000600 [0.281] INFO: Read: size=1, data=5A [0.281] INFO: Read: size=17, data=3899000099003102E9050400000000008F [0.281] INFO: Write: size=4, data=B1000700 [0.297] INFO: Read: size=1, data=5A [0.297] INFO: Read: size=17, data=0906290000000000003C00000100000277 [0.297] INFO: Write: size=4, data=B1000800 [0.312] INFO: Read: size=1, data=5A [0.312] INFO: Read: size=17, data=A9A6C9AAAAAAAAAAAA0000000000000014 [0.312] INFO: Write: size=4, data=B1000900 [0.328] INFO: Read: size=1, data=5A [0.328] INFO: Read: size=17, data=6400000300001400980805A00251000215 [0.328] INFO: Write: size=4, data=B1000A00 [0.343] INFO: Read: size=1, data=5A [0.343] INFO: Read: size=17, data=0000000000000000000000000000000000 [0.343] INFO: Write: size=4, data=B1000B00 [0.359] INFO: Read: size=1, data=5A [0.359] INFO: Read: size=17, data=42056EA46350460014AA1001438348204F [0.359] INFO: Write: size=4, data=B1000C00 [0.375] INFO: Read: size=1, data=5A [0.375] INFO: Read: size=17, data=43142CA56F40510015AA541324064720DF [0.375] INFO: Write: size=4, data=B1000D00 [0.390] INFO: Read: size=1, data=5A [0.390] INFO: Read: size=17, data=4414FEA35D40450015AA240440114D2080 [0.390] INFO: Write: size=4, data=B1000E00 [0.406] INFO: Read: size=1, data=5A [0.406] INFO: Read: size=17, data=4524B9A46840450015AA530119824B20CC [0.406] INFO: Write: size=4, data=B1000F00 [0.421] INFO: Read: size=1, data=5A [0.421] INFO: Read: size=17, data=4624FEA35D40470015AA080113844920B7 [0.421] INFO: Write: size=4, data=B1001000 [0.437] INFO: Read: size=1, data=5A [0.437] INFO: Read: size=17, data=472336A46040470016AA211322064820AF [0.437] INFO: Write: size=4, data=B1001100 [0.453] INFO: Read: size=1, data=5A [0.453] INFO: Read: size=17, data=482416A45F40510016AA03021309492060 [0.453] INFO: Write: size=4, data=B1001200 [0.468] INFO: Read: size=1, data=5A [0.468] INFO: Read: size=17, data=493460A46350460016AA030109114C20C4 [0.468] INFO: Write: size=4, data=B1001300 [0.484] INFO: Read: size=1, data=5A [0.484] INFO: Read: size=17, data=503441A57140450016AA210217824B2047 [0.484] INFO: Write: size=4, data=B1001400 [0.499] INFO: Read: size=1, data=5A [0.499] INFO: Read: size=17, data=510197A24710460017AA2323268245203C [0.499] INFO: Write: size=4, data=B1001500 [0.515] INFO: Read: size=1, data=5A [0.515] INFO: Read: size=17, data=5203C9A35A30510017AA2201358444209D [0.515] INFO: Write: size=4, data=B1001600 [0.531] INFO: Read: size=1, data=5A [0.531] INFO: Read: size=17, data=531371A46430510018AA56122406422016 [0.531] INFO: Write: size=4, data=B1001700 [0.546] INFO: Read: size=1, data=5A [0.546] INFO: Read: size=17, data=541340A46130460018AA540110094220B4 [0.546] INFO: Write: size=4, data=B1001800 [0.562] INFO: Read: size=1, data=5A [0.562] INFO: Read: size=17, data=5524BBA46840500018AA48004510422091 [0.562] INFO: Write: size=4, data=B1001900 [0.577] INFO: Read: size=1, data=5A [0.577] INFO: Read: size=17, data=7100B6A00000010109CA27000904430013 [0.577] INFO: Write: size=4, data=B1001A00 [0.593] INFO: Read: size=1, data=5A [0.593] INFO: Read: size=17, data=710000A1000029000ACA300143863F0048 [0.593] INFO: Write: size=4, data=B1001B00 [0.609] INFO: Read: size=1, data=5A [0.609] INFO: Read: size=17, data=4201F9A0001051000ACA340150883E005C [0.609] INFO: Write: size=4, data=B1001C00 [0.624] INFO: Read: size=1, data=5A [0.624] INFO: Read: size=17, data=710257A1002002021E1B40000211450060 [0.624] INFO: Write: size=4, data=B1001D00 [0.640] INFO: Read: size=1, data=5A [0.640] INFO: Read: size=17, data=4202A6A1002039011E1B1804268546002B [0.640] INFO: Write: size=4, data=B1001E00 [0.655] INFO: Read: size=1, data=5A [0.655] INFO: Read: size=17, data=7101F760001001011F1647002686460049 [0.655] INFO: Write: size=4, data=B1001F00 [0.671] INFO: Read: size=1, data=5A [0.671] INFO: Read: size=17, data=420144A1001047001F16040233894600BC [0.671] INFO: Write: size=4, data=B1002000 [0.687] INFO: Read: size=1, data=5A [0.687] INFO: Read: size=17, data=71013BA100105700172E330039114200B9 [0.687] INFO: Write: size=4, data=B1002100 [0.702] INFO: Read: size=1, data=5A [0.702] INFO: Read: size=17, data=4201F2A000103800172E49022583430098 [0.702] INFO: Write: size=4, data=B1002200 [0.718] INFO: Read: size=1, data=5A [0.718] INFO: Read: size=17, data=71012FA1001001010316160109054300D5 [0.718] INFO: Write: size=4, data=B1002300 [0.733] INFO: Read: size=1, data=5A [0.733] INFO: Read: size=17, data=71058FA40060480014AA14004581490032 [0.733] INFO: Write: size=4, data=B1002400 [0.749] INFO: Read: size=1, data=5A [0.749] INFO: Read: size=17, data=46111F1569A5A00F50101F1769FB101264 [0.749] INFO: Write: size=4, data=B1002500 [0.765] INFO: Read: size=1, data=5A [0.765] INFO: Read: size=17, data=21810217692261145283031769478117F2 [0.765] INFO: Write: size=4, data=B1002600 [0.780] INFO: Read: size=1, data=5A [0.780] INFO: Read: size=17, data=108704176979511A3106051869A6E11C5F [0.780] INFO: Write: size=4, data=B1002700 [0.796] INFO: Read: size=1, data=5A [0.796] INFO: Read: size=17, data=5608061869CFD12054100718690E0225C6 [0.796] INFO: Write: size=4, data=B1002800 [0.811] INFO: Read: size=1, data=5A [0.811] INFO: Read: size=17, data=338308186951A22720870918697B622A91 [0.811] INFO: Write: size=4, data=B1002900 [0.827] INFO: Read: size=1, data=5A [0.827] INFO: Read: size=17, data=35060A1969A7C22C49080B1969CDB22FE8 [0.827] INFO: Write: size=4, data=B1002A00 [0.843] INFO: Read: size=1, data=5A [0.843] INFO: Read: size=17, data=42100C1969FCF23241830D19693053360C [0.843] INFO: Write: size=4, data=B1002B00 [0.858] INFO: Read: size=1, data=5A [0.858] INFO: Read: size=17, data=16870E196966D33827060F1A698E233C4A [0.858] INFO: Write: size=4, data=B1002C00 [0.874] INFO: Read: size=1, data=5A [0.874] INFO: Read: size=17, data=1209101A69C3233F0011111A69F3934240 [0.889] INFO: Write: size=4, data=B1002D00 [0.889] INFO: Read: size=1, data=5A [0.889] INFO: Read: size=17, data=23811F05792AF446248602057970044C8F [0.905] INFO: Write: size=4, data=B1002E00 [0.921] INFO: Read: size=1, data=5A [0.921] INFO: Read: size=17, data=52921F1279C1444F34881F1779F574540A [0.921] INFO: Write: size=4, data=B1002F00 [0.921] INFO: Read: size=1, data=5A [0.936] INFO: Read: size=17, data=23111F1A794875595884021A7998F55E58 [0.936] INFO: Write: size=4, data=B1003000 [0.936] INFO: Read: size=1, data=5A [0.952] INFO: Read: size=17, data=30921F0289F0A56430860202894BA66902 [0.952] INFO: Write: size=4, data=B1003100 [0.967] INFO: Read: size=1, data=5A [0.967] INFO: Read: size=17, data=02821F0A899B466D54081F0EB9D5167324 [0.967] INFO: Write: size=4, data=B1003200 [0.983] INFO: Read: size=1, data=5A [0.983] INFO: Read: size=17, data=3581020EB932F77710881F12B980977F37 [0.983] INFO: Write: size=4, data=B1003300 [0.999] INFO: Read: size=1, data=5A [0.999] INFO: Read: size=17, data=37881F19B9FA178645881F02C962F88AE2 [0.999] INFO: Write: size=4, data=B1003400 [1.014] INFO: Read: size=1, data=5A [1.014] INFO: Read: size=17, data=15881F09C9B0C89111921F13C91D999580 [1.014] INFO: Write: size=4, data=B1003500 [1.030] INFO: Read: size=1, data=5A [1.030] INFO: Read: size=17, data=27830213C95A699A33881F17C9A7B9A09F [1.030] INFO: Write: size=4, data=B1003600 [1.045] INFO: Read: size=1, data=5A [1.045] INFO: Read: size=17, data=35101F1AC90C1AA84083021AC982FAAFE8 [1.045] INFO: Write: size=4, data=B1003700 [1.061] INFO: Read: size=1, data=5A [1.061] INFO: Read: size=17, data=13891F1B1A00DBB651861F1E1A6E2BBE06 [1.061] INFO: Write: size=4, data=B1003800 [1.077] INFO: Read: size=1, data=5A [1.077] INFO: Read: size=17, data=38881F032AE39BC454091F072A4AACCBBC [1.077] INFO: Write: size=4, data=B1003900 [1.092] INFO: Read: size=1, data=5A [1.092] INFO: Read: size=17, data=188402072ABB2CD208101F142A23CDD4C1 [1.092] INFO: Write: size=4, data=B1003A00 [1.108] INFO: Read: size=1, data=5A [1.108] INFO: Read: size=17, data=009202142A4DFDD6378103142A709DD9D1 [1.108] INFO: Write: size=4, data=B1003B00 [1.123] INFO: Read: size=1, data=5A [1.123] INFO: Read: size=17, data=14101F1B2A9A0DDF2583021B2AF12DE500 [1.123] INFO: Write: size=4, data=B1003C00 [1.139] INFO: Read: size=1, data=5A [1.139] INFO: Read: size=17, data=2888031B2A533EE918881F103A948EEF8C [1.139] INFO: Write: size=4, data=B1003D00 [1.155] INFO: Read: size=1, data=5A [1.155] INFO: Read: size=17, data=23101F143AF92EF4088202143A436FFB42 [1.155] INFO: Write: size=4, data=B1003E00
Hamish
On Tue, Mar 11, 2014 at 5:20 PM, Hamish Moffatt hamish@cloud.net.au wrote:
Here's a log from Windows. There appears to be a whole lot less timing precision so it's a bit hard to compare, other than noting the absence of NAKs from the VT3.
Hmm. The windows log is for 0.5.0-devel, with the Linux one being 0.4.2. But I assume there are no big libdivecomputer changes.
[0.156] INFO: Write: size=2, data=8400 [0.156] INFO: Read: size=1, data=5A [0.156] INFO: Read: size=17, data=4F43452056543320523244203531324BBF [0.172] dc_device_dump [0.172] INFO: Write: size=4, data=B1000000 [0.187] INFO: Read: size=1, data=5A
So the Linux dump sometimes got A5 instead of 5A.
But the *timing* is very vert different. Here's Linux getting the right data:
[0.104540] INFO: Write: size=2, data=8400 [0.104551] INFO: Read: size=1, data=5A
and here's the same thing with the wrong data:
[0.109560] INFO: Sleep: value=1 [0.110624] INFO: Write: size=4, data=B1000000 [0.110634] INFO: Read: size=1, data=A5
Note how it did a two-byte write, and then immediately a read within 10 microseconds.
Which is a bit odd. Jef, shouldn't the sleep be *after* the write, and before the read? If there are any duplex issues, the "read -> write" turnaround isn't the problem (because by the time the read returns, we certainly know the data had been fully sent from the other side), but the "write -> read" turnaround might be problematic if the reader gets confused by DSR coming on while it's still receiving.
Linus
On 12/03/14 13:17, Linus Torvalds wrote:
[0.187] INFO: Read: size=1, data=5A So the Linux dump sometimes got A5 instead of 5A.
But the *timing* is very vert different. Here's Linux getting the right data:
[0.104540] INFO: Write: size=2, data=8400 [0.104551] INFO: Read: size=1, data=5A
and here's the same thing with the wrong data:
[0.109560] INFO: Sleep: value=1 [0.110624] INFO: Write: size=4, data=B1000000 [0.110634] INFO: Read: size=1, data=A5
Note how it did a two-byte write, and then immediately a read within 10 microseconds.
Which is a bit odd. Jef, shouldn't the sleep be *after* the write, and before the read? If there are any duplex issues, the "read -> write" turnaround isn't the problem (because by the time the read returns, we certainly know the data had been fully sent from the other side), but the "write -> read" turnaround might be problematic if the reader gets confused by DSR coming on while it's still receiving.
That log (with sleeps of 1ms) is from my adding the sleep before write as Jef suggested.
It's only a 3 wire interface at the dive computer, so if DSR is used it's internal to the interface cable. I tried adding 1ms delay after write and I didn't see any change in behaviour. Logically there's no reason to sleep after the write, because it's doing a blocking read and it's receiving a reply (5A, a nak) within the timeout period?
Anyway to clarify matters here's a log from a fresh unmodified check out. It's failing the same as 0.4.2.
[0.000025] DATETIME 2014-03-12T02:26:56Z (1394591216) [0.000048] VERSION 0.5.0-devel (575f2e9016ac9baa2b1b031caa6fe0bc77cdbbee) [0.000053] DEVICE=/dev/ttyUSB0 [0.000061] oceanic_atom2_device_open [0.000069] INFO: Open: name=/dev/ttyUSB0 [0.000864] INFO: Configure: baudrate=38400, databits=8, parity=0, stopbits=1, flowcontrol=0 [0.000970] INFO: Timeout: value=3000 [0.000977] INFO: Sleep: value=100 [0.101052] INFO: Flush: queue=3, input=0, output=0 [0.101494] INFO: Write: size=2, data=8400 [0.102418] INFO: Read: size=1, data=5A [0.106364] INFO: Read: size=17, data=4F43452056543320523244203531324BBF [0.106390] dc_device_dump [0.107273] INFO: Write: size=4, data=B1000000 [3.108674] INFO: Read: size=0, data= [3.108685] ERROR: Failed to receive the answer. [in oceanic_atom2.c:332 (oceanic_atom2_send)] [3.108688] INFO: Sleep: value=100 [3.208757] INFO: Flush: queue=1, input=0, output=0 [3.211274] INFO: Write: size=4, data=B1000000 [3.211283] INFO: Read: size=1, data=5A [3.220967] INFO: Read: size=17, data=0416041120081001425800730000000075 [3.223274] INFO: Write: size=4, data=B1000100 [6.226294] INFO: Read: size=0, data= [6.226306] ERROR: Failed to receive the answer. [in oceanic_atom2.c:332 (oceanic_atom2_send)] [6.226309] INFO: Sleep: value=100 [6.326377] INFO: Flush: queue=1, input=0, output=0 [6.327275] INFO: Write: size=4, data=B1000100 [6.327722] INFO: Read: size=1, data=5A [6.338681] INFO: Read: size=17, data=6701DA064204E506E206DC06FF0FAAFBF6 [6.339275] INFO: Write: size=4, data=B1000200 [9.342297] INFO: Read: size=0, data= [9.342309] ERROR: Failed to receive the answer. [in oceanic_atom2.c:332 (oceanic_atom2_send)] [9.342322] INFO: Sleep: value=100 [9.442390] INFO: Flush: queue=1, input=0, output=0 [9.443290] INFO: Write: size=4, data=B1000200 [9.444317] INFO: Read: size=1, data=5A [9.455334] INFO: Read: size=17, data=0000DC06FF0FDC06FF0F00000000AA8A14 [9.459280] INFO: Write: size=4, data=B1000300 [9.459290] INFO: Read: size=1, data=A5 [9.459292] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:338 (oceanic_atom2_send)] [9.459305] INFO: Sleep: value=100 [9.559376] INFO: Flush: queue=1, input=0, output=0 [9.563276] INFO: Write: size=4, data=B1000300 [9.563287] INFO: Read: size=1, data=5A [9.571795] INFO: Read: size=17, data=890E370D00011B0B670542053250AAE1C2 [9.575273] INFO: Write: size=4, data=B1000400 [12.578294] INFO: Read: size=0, data= [12.578306] ERROR: Failed to receive the answer. [in oceanic_atom2.c:332 (oceanic_atom2_send)] [12.578309] INFO: Sleep: value=100 [12.678377] INFO: Flush: queue=1, input=0, output=0 [12.679278] INFO: Write: size=4, data=B1000400 [12.680546] INFO: Read: size=1, data=5A [12.691540] INFO: Read: size=17, data=300220028003500530BEB0BB0000000085 [12.695277] INFO: Write: size=4, data=B1000500 [12.695287] INFO: Read: size=1, data=A5 [12.695289] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:338 (oceanic_atom2_send)] [12.695292] INFO: Sleep: value=100 [12.795364] INFO: Flush: queue=1, input=0, output=0 [12.799274] INFO: Write: size=4, data=B1000500 [12.799284] INFO: Read: size=1, data=5A [12.808012] INFO: Read: size=17, data=A014000300002C01980805A0022100024E [12.811273] INFO: Write: size=4, data=B1000600 [12.811281] INFO: Read: size=1, data=A5 [12.811283] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:338 (oceanic_atom2_send)] [12.811286] INFO: Sleep: value=100 [12.911358] INFO: Flush: queue=1, input=0, output=0 [12.915277] INFO: Write: size=4, data=B1000600 [12.915291] INFO: Read: size=1, data=5A [12.924526] INFO: Read: size=17, data=3899000099003102E9050400000000008F [12.927275] INFO: Write: size=4, data=B1000700 [12.927285] INFO: Read: size=1, data=A5 [12.927287] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:338 (oceanic_atom2_send)] [12.927290] INFO: Sleep: value=100
and here's a log with a 1ms sleep after write:
[0.000029] DATETIME 2014-03-12T02:37:41Z (1394591861) [0.000050] VERSION 0.5.0-devel (575f2e9016ac9baa2b1b031caa6fe0bc77cdbbee) [0.000054] DEVICE=/dev/ttyUSB0 [0.000060] oceanic_atom2_device_open [0.000065] INFO: Open: name=/dev/ttyUSB0 [0.000936] INFO: Configure: baudrate=38400, databits=8, parity=0, stopbits=1, flowcontrol=0 [0.001179] INFO: Timeout: value=3000 [0.001185] INFO: Sleep: value=100 [0.101259] INFO: Flush: queue=3, input=234, output=0 [0.101550] INFO: Write: size=2, data=8400 [0.101557] INFO: Sleep: value=1 [0.103201] INFO: Read: size=1, data=5A [0.107077] INFO: Read: size=17, data=4F43452056543320523244203531324BBF [0.107097] dc_device_dump [0.108720] INFO: Write: size=4, data=B1000000 [0.108727] INFO: Sleep: value=1 [3.112802] INFO: Read: size=0, data= [3.112814] ERROR: Failed to receive the answer. [in oceanic_atom2.c:333 (oceanic_atom2_send)] [3.112817] INFO: Sleep: value=100 [3.212886] INFO: Flush: queue=1, input=0, output=0 [3.216734] INFO: Write: size=4, data=B1000000 [3.216741] INFO: Sleep: value=1 [3.217802] INFO: Read: size=1, data=5A [3.225648] INFO: Read: size=17, data=0416041120081001425800730000000075 [3.228718] INFO: Write: size=4, data=B1000100 [3.228724] INFO: Sleep: value=1 [3.229784] INFO: Read: size=1, data=A5 [3.229787] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:339 (oceanic_atom2_send)] [3.229790] INFO: Sleep: value=100 [3.329855] INFO: Flush: queue=1, input=0, output=0 [3.332716] INFO: Write: size=4, data=B1000100 [3.332721] INFO: Sleep: value=1 [3.333782] INFO: Read: size=1, data=5A [3.342275] INFO: Read: size=17, data=6701DA064204E506E206DC06FF0FAAFBF6 [3.344750] INFO: Write: size=4, data=B1000200 [3.344757] INFO: Sleep: value=1 [6.348834] INFO: Read: size=0, data= [6.348845] ERROR: Failed to receive the answer. [in oceanic_atom2.c:333 (oceanic_atom2_send)] [6.348849] INFO: Sleep: value=100 [6.448920] INFO: Flush: queue=1, input=0, output=0 [6.452722] INFO: Write: size=4, data=B1000200 [6.452728] INFO: Sleep: value=1 [6.453794] INFO: Read: size=1, data=5A [6.461925] INFO: Read: size=17, data=0000DC06FF0FDC06FF0F00000000AA8A14 [6.464720] INFO: Write: size=4, data=B1000300 [6.464727] INFO: Sleep: value=1 [6.465792] INFO: Read: size=1, data=A5 [6.465798] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:339 (oceanic_atom2_send)] [6.465801] INFO: Sleep: value=100 [6.565869] INFO: Flush: queue=1, input=0, output=0 [6.568718] INFO: Write: size=4, data=B1000300 [6.568724] INFO: Sleep: value=1 [6.569784] INFO: Read: size=1, data=5A [6.578391] INFO: Read: size=17, data=890E370D00011B0B670542053250AAE1C2 [6.580718] INFO: Write: size=4, data=B1000400 [6.580724] INFO: Sleep: value=1 [6.581785] INFO: Read: size=1, data=A5 [6.581789] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:339 (oceanic_atom2_send)] [6.581792] INFO: Sleep: value=100 [6.681864] INFO: Flush: queue=1, input=0, output=0 [6.684751] INFO: Write: size=4, data=B1000400 [6.684758] INFO: Sleep: value=1 [6.685823] INFO: Read: size=1, data=5A [6.694910] INFO: Read: size=17, data=300220028003500530BEB0BB0000000085 [6.696738] INFO: Write: size=4, data=B1000500 [6.696745] INFO: Sleep: value=1 [6.697806] INFO: Read: size=1, data=A5 [6.697812] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:339 (oceanic_atom2_send)] [6.697814] INFO: Sleep: value=100 [6.797879] INFO: Flush: queue=1, input=0, output=0 [6.800723] INFO: Write: size=4, data=B1000500 [6.800730] INFO: Sleep: value=1 [6.801823] INFO: Read: size=1, data=5A [6.810503] INFO: Read: size=17, data=A014000300002C01980805A0022100024E [6.812718] INFO: Write: size=4, data=B1000600 [6.812723] INFO: Sleep: value=1 [6.813788] INFO: Read: size=1, data=A5 [6.813794] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:339 (oceanic_atom2_send)] [6.813797] INFO: Sleep: value=100 [6.913866] INFO: Flush: queue=1, input=0, output=0 [6.916722] INFO: Write: size=4, data=B1000600 [6.916728] INFO: Sleep: value=1 [6.917794] INFO: Read: size=1, data=5A [6.927021] INFO: Read: size=17, data=3899000099003102E9050400000000008F
I'd kill for an RS-232 capable logic analyser right now, so I could see what's actually happening at the dive computer.
Hamish
Oops accidentally sent this just to Linus earlier.. Resending to the list.
On 12/03/14 13:40, Hamish Moffatt wrote:
Anyway to clarify matters here's a log from a fresh unmodified check out. It's failing the same as 0.4.2.
[0.000025] DATETIME 2014-03-12T02:26:56Z (1394591216) [0.000048] VERSION 0.5.0-devel (575f2e9016ac9baa2b1b031caa6fe0bc77cdbbee) [0.000053] DEVICE=/dev/ttyUSB0 [0.000061] oceanic_atom2_device_open [0.000069] INFO: Open: name=/dev/ttyUSB0 [0.000864] INFO: Configure: baudrate=38400, databits=8, parity=0, stopbits=1, flowcontrol=0 [0.000970] INFO: Timeout: value=3000 [0.000977] INFO: Sleep: value=100 [0.101052] INFO: Flush: queue=3, input=0, output=0 [0.101494] INFO: Write: size=2, data=8400 [0.102418] INFO: Read: size=1, data=5A [0.106364] INFO: Read: size=17, data=4F43452056543320523244203531324BBF [0.106390] dc_device_dump [0.107273] INFO: Write: size=4, data=B1000000 [3.108674] INFO: Read: size=0, data= [3.108685] ERROR: Failed to receive the answer. [in oceanic_atom2.c:332 (oceanic_atom2_send)] [3.108688] INFO: Sleep: value=100 [3.208757] INFO: Flush: queue=1, input=0, output=0
And here's a from MacOS, where it works. There seems to be a lot more delay in the log entries between read and write on the Mac than on linux:
Linux: [0.101414] INFO: Write: size=2, data=8400 [0.102813] INFO: Read: size=1, data=5A [0.106819] INFO: Read: size=17, data=4F43452056543320523244203531324BBF
Mac: [0.106450] INFO: Write: size=2, data=8400 [0.114123] INFO: Read: size=1, data=5A [0.114137] INFO: Read: size=17, data=4F43452056543320523244203531324BBF
Here's more of the Mac log.
[0.000491] DATETIME 2014-03-12T04:17:10Z (1394597830) [0.000515] VERSION 0.5.0-devel (575f2e9016ac9baa2b1b031caa6fe0bc77cdbbee) [0.000519] DEVICE=/dev/tty.usbserial-20030001 [0.000540] oceanic_atom2_device_open [0.000557] INFO: Open: name=/dev/tty.usbserial-20030001 [0.004850] INFO: Configure: baudrate=38400, databits=8, parity=0, stopbits=1, flowcontrol=0 [0.005042] INFO: Timeout: value=3000 [0.005061] INFO: Sleep: value=100 [0.106152] INFO: Flush: queue=3, input=2, output=0 [0.106450] INFO: Write: size=2, data=8400 [0.114123] INFO: Read: size=1, data=5A [0.114137] INFO: Read: size=17, data=4F43452056543320523244203531324BBF [0.114170] dc_device_dump [0.114411] INFO: Write: size=4, data=B1000000 [0.130090] INFO: Read: size=1, data=5A [0.130110] INFO: Read: size=17, data=0416041120081001425800730000000075 [0.130302] INFO: Write: size=4, data=B1000100 [0.146005] INFO: Read: size=1, data=5A [0.146034] INFO: Read: size=17, data=6701DA064204E506E206DC06FF0FAAFBF6 [0.146180] INFO: Write: size=4, data=B1000200 [0.162008] INFO: Read: size=1, data=5A [0.162029] INFO: Read: size=17, data=0000DC06FF0FDC06FF0F00000000AA8A14 [0.162166] INFO: Write: size=4, data=B1000300 [0.177875] INFO: Read: size=1, data=5A [0.177899] INFO: Read: size=17, data=890E370D00011B0B670542053250AAE1C2 [0.178035] INFO: Write: size=4, data=B1000400 [0.193736] INFO: Read: size=1, data=5A [0.193757] INFO: Read: size=17, data=300220028003500530BEB0BB0000000085 [0.193916] INFO: Write: size=4, data=B1000500 [0.209734] INFO: Read: size=1, data=5A [0.209753] INFO: Read: size=17, data=A014000300002C01980805A0022100024E [0.209917] INFO: Write: size=4, data=B1000600 [0.225757] INFO: Read: size=1, data=5A [0.225795] INFO: Read: size=17, data=3899000099003102E9050400000000008F [0.225926] INFO: Write: size=4, data=B1000700 [0.241591] INFO: Read: size=1, data=5A [0.241610] INFO: Read: size=17, data=0906290000000000003C00000100000277 [0.241793] INFO: Write: size=4, data=B1000800 [0.257485] INFO: Read: size=1, data=5A [0.257507] INFO: Read: size=17, data=A9A6C9AAAAAAAAAAAA0000000000000014 [0.257660] INFO: Write: size=4, data=B1000900 [0.273511] INFO: Read: size=1, data=5A [0.273535] INFO: Read: size=17, data=6400000300001400980805A00251000215 [0.273669] INFO: Write: size=4, data=B1000A00 [0.289361] INFO: Read: size=1, data=5A [0.289400] INFO: Read: size=17, data=0000000000000000000000000000000000 [0.289661] INFO: Write: size=4, data=B1000B00 [0.305350] INFO: Read: size=1, data=5A [0.305373] INFO: Read: size=17, data=42056EA46350460014AA1001438348204F [0.305533] INFO: Write: size=4, data=B1000C00 [0.321207] INFO: Read: size=1, data=5A [0.321227] INFO: Read: size=17, data=43142CA56F40510015AA541324064720DF [0.321382] INFO: Write: size=4, data=B1000D00 [0.337195] INFO: Read: size=1, data=5A [0.337216] INFO: Read: size=17, data=4414FEA35D40450015AA240440114D2080 [0.337389] INFO: Write: size=4, data=B1000E00 [0.353106] INFO: Read: size=1, data=5A [0.353137] INFO: Read: size=17, data=4524B9A46840450015AA530119824B20CC [0.353255] INFO: Write: size=4, data=B1000F00 [0.369093] INFO: Read: size=1, data=5A [0.369115] INFO: Read: size=17, data=4624FEA35D40470015AA080113844920B7 [0.369253] INFO: Write: size=4, data=B1001000 [0.384955] INFO: Read: size=1, data=5A [0.384977] INFO: Read: size=17, data=472336A46040470016AA211322064820AF [0.385137] INFO: Write: size=4, data=B1001100 [0.400858] INFO: Read: size=1, data=5A [0.400881] INFO: Read: size=17, data=482416A45F40510016AA03021309492060 [0.401016] INFO: Write: size=4, data=B1001200 [0.416827] INFO: Read: size=1, data=5A [0.416847] INFO: Read: size=17, data=493460A46350460016AA030109114C20C4 [0.417029] INFO: Write: size=4, data=B1001300 [0.432695] INFO: Read: size=1, data=5A [0.432715] INFO: Read: size=17, data=503441A57140450016AA210217824B2047 [0.432910] INFO: Write: size=4, data=B1001400 [0.448762] INFO: Read: size=1, data=5A [0.448783] INFO: Read: size=17, data=510197A24710460017AA2323268245203C [0.448897] INFO: Write: size=4, data=B1001500 [0.464703] INFO: Read: size=1, data=5A [0.464725] INFO: Read: size=17, data=5203C9A35A30510017AA2201358444209D [0.464875] INFO: Write: size=4, data=B1001600 [0.480621] INFO: Read: size=1, data=5A [0.480648] INFO: Read: size=17, data=531371A46430510018AA56122406422016 [0.480931] INFO: Write: size=4, data=B1001700 [0.496482] INFO: Read: size=1, data=5A [0.496506] INFO: Read: size=17, data=541340A46130460018AA540110094220B4 [0.496651] INFO: Write: size=4, data=B1001800 [0.512475] INFO: Read: size=1, data=5A [0.512498] INFO: Read: size=17, data=5524BBA46840500018AA48004510422091 [0.512664] INFO: Write: size=4, data=B1001900 [0.528314] INFO: Read: size=1, data=5A [0.528331] INFO: Read: size=17, data=7100B6A00000010109CA27000904430013 [0.528531] INFO: Write: size=4, data=B1001A00 [0.544354] INFO: Read: size=1, data=5A [0.544378] INFO: Read: size=17, data=710000A1000029000ACA300143863F0048 [0.544653] INFO: Write: size=4, data=B1001B00 [0.560198] INFO: Read: size=1, data=5A [0.560219] INFO: Read: size=17, data=4201F9A0001051000ACA340150883E005C [0.560373] INFO: Write: size=4, data=B1001C00 [0.576221] INFO: Read: size=1, data=5A [0.576253] INFO: Read: size=17, data=710257A1002002021E1B40000211450060
Hamish
On 2014-03-12 03:17, Linus Torvalds wrote:
On Tue, Mar 11, 2014 at 5:20 PM, Hamish Moffatt hamish@cloud.net.au wrote:
Here's a log from Windows. There appears to be a whole lot less timing precision so it's a bit hard to compare, other than noting the absence of NAKs from the VT3.
Hmm. The windows log is for 0.5.0-devel, with the Linux one being 0.4.2. But I assume there are no big libdivecomputer changes.
[0.156] INFO: Write: size=2, data=8400 [0.156] INFO: Read: size=1, data=5A [0.156] INFO: Read: size=17, data=4F43452056543320523244203531324BBF [0.172] dc_device_dump [0.172] INFO: Write: size=4, data=B1000000 [0.187] INFO: Read: size=1, data=5A
So the Linux dump sometimes got A5 instead of 5A.
But the *timing* is very vert different. Here's Linux getting the right data:
[0.104540] INFO: Write: size=2, data=8400 [0.104551] INFO: Read: size=1, data=5A
and here's the same thing with the wrong data:
[0.109560] INFO: Sleep: value=1 [0.110624] INFO: Write: size=4, data=B1000000 [0.110634] INFO: Read: size=1, data=A5
Note how it did a two-byte write, and then immediately a read within 10 microseconds.
Which is a bit odd. Jef, shouldn't the sleep be *after* the write, and before the read? If there are any duplex issues, the "read -> write" turnaround isn't the problem (because by the time the read returns, we certainly know the data had been fully sent from the other side), but the "write -> read" turnaround might be problematic if the reader gets confused by DSR coming on while it's still receiving.
With the half-duplex workaround, the sleep really does happen after the write. But the logging for the serial_write function happens at the end of the function, but after the call to the serial_sleep() function. The result is that in the log it appears as if the sleep is before the write. This is indeed a bit confusing.
But as Hamish already clarified, this is probably an attempt with a sleep call added before the write. The half-duplex hack always adds a 2ms fudge factor, so if this was the result of enabling the half-duplex hack, the sleep time should always be at least 2ms.
I no longer believe this is a half-duplex problem. The interface has three wires, so that's probably GND, TX and RX. In that case there shouldn't be any problem with starting a read before the write has finished. It would just take a bit longer before the read receives its data. With the Suunto's there were only two wires, which makes the timing of switching between read and write a lot more critical. The Suunto's also need the toggling of the RTS line, which is not the case for the Oceanics.
Hamish already confirmed that if he adds a small delay before the write, then everything starts to work fine. I don't have a good explanation for this. I get the impression that without the extra delay we are sending the next command too fast. Maybe the dive computer is still busy processing the previous command? But it has already send the response to the previous command (because we have already processed it), so I have absolutely no idea what it could be doing. Also why does it need this delay on Linux but not on Windows? Is the Windows driver maybe slower to send out the data, and this extra delay happens to be just enough to make it work?
If you look at the error handling, you'll see that there is already a 100ms delay before sending the command again. Since the second attempt is usually successful, that's another indication that the problem is read->write turnaround rather than the write->read.
Just a thought, but maybe one or more bytes of the command get lost somehow when trying to send too fast? If the dive computer gets no bytes at all, it also doesn't reply and we get a timeout. If only the first few bytes get lost, the dive computer will see an incomplete command and will respond with a NAK to indicate it can't process the request. That would explain the two type of errors (timeout or nak) we get, but then the next question is of course how these bytes disappear?
Jef
On 2014-03-12 11:47, Jef Driesen wrote:
I no longer believe this is a half-duplex problem. The interface has three wires, so that's probably GND, TX and RX. In that case there shouldn't be any problem with starting a read before the write has finished. It would just take a bit longer before the read receives its data. With the Suunto's there were only two wires, which makes the timing of switching between read and write a lot more critical. The Suunto's also need the toggling of the RTS line, which is not the case for the Oceanics.
Hamish already confirmed that if he adds a small delay before the write, then everything starts to work fine. I don't have a good explanation for this. I get the impression that without the extra delay we are sending the next command too fast. Maybe the dive computer is still busy processing the previous command? But it has already send the response to the previous command (because we have already processed it), so I have absolutely no idea what it could be doing. Also why does it need this delay on Linux but not on Windows? Is the Windows driver maybe slower to send out the data, and this extra delay happens to be just enough to make it work?
If you look at the error handling, you'll see that there is already a 100ms delay before sending the command again. Since the second attempt is usually successful, that's another indication that the problem is read->write turnaround rather than the write->read.
Just a thought, but maybe one or more bytes of the command get lost somehow when trying to send too fast? If the dive computer gets no bytes at all, it also doesn't reply and we get a timeout. If only the first few bytes get lost, the dive computer will see an incomplete command and will respond with a NAK to indicate it can't process the request. That would explain the two type of errors (timeout or nak) we get, but then the next question is of course how these bytes disappear?
I just remember something that could matter here. If you look at the commands that are being send, they all end with a 0x00 byte that doesn't really serve any purpose afaik. When I originally reverse engineered the protocol, that byte was send by the Oceanic application, and I just duplicated that. But I now recall that I think I've seen that newer versions of there software no longer do this. Maybe this extra byte is what is causing us trouble now?
Imagine the dive computer expects a 3 byte read command (e.g. B1XXXX). It will first receive the command type 0xB1, and then expect two more bytes for that command. Than it has everything to process the request and send back the response. But if we send that extra 0x00 byte it will probably try to process that as the next command type. This is likely a non-existing type and the device will probably just ignore it. But that might take just enough time to prevent the next command from being received correctly.
I think that's something worth trying. Hamish, can you try without that last 0x00 byte? And maybe also try Oceanlog on Windows and capture the communication to double check whether they send this extra 0x00 byte or not.
The procedure on how to setup Portmon is described here:
http://www.libdivecomputer.org/contribute.html#protocol
Unfortunately you'll need a 32bit Windows version to run Portmon. If you use some other capture application that's of course fine too. Portmon is just convenient because it's freeware and the output is easy to parse with scripts.
Jef
On 12/03/14 22:08, Jef Driesen wrote:
I just remember something that could matter here. If you look at the commands that are being send, they all end with a 0x00 byte that doesn't really serve any purpose afaik. When I originally reverse engineered the protocol, that byte was send by the Oceanic application, and I just duplicated that. But I now recall that I think I've seen that newer versions of there software no longer do this. Maybe this extra byte is what is causing us trouble now?
Imagine the dive computer expects a 3 byte read command (e.g. B1XXXX). It will first receive the command type 0xB1, and then expect two more bytes for that command. Than it has everything to process the request and send back the response. But if we send that extra 0x00 byte it will probably try to process that as the next command type. This is likely a non-existing type and the device will probably just ignore it. But that might take just enough time to prevent the next command from being received correctly.
I think that's something worth trying. Hamish, can you try without that last 0x00 byte? And maybe also try Oceanlog on Windows and capture the communication to double check whether they send this extra 0x00 byte or not.
I can see how the extra 0x00 might confuse the logical state of the serial interface in the dc. I've got good news and bad... I removed the extra 0x00 byte from the read version and read data commands, and the commands work, but the behaviour hasn't changed.
[0.000032] DATETIME 2014-03-12T11:17:39Z (1394623059) [0.000055] VERSION 0.5.0-devel (575f2e9016ac9baa2b1b031caa6fe0bc77cdbbee) [0.000059] DEVICE=/dev/ttyUSB0 [0.000065] oceanic_atom2_device_open [0.000071] INFO: Open: name=/dev/ttyUSB0 [0.000725] INFO: Configure: baudrate=38400, databits=8, parity=0, stopbits=1, flowcontrol=0 [0.000837] INFO: Timeout: value=3000 [0.000839] INFO: Sleep: value=100 [0.100909] INFO: Flush: queue=3, input=23, output=0 [0.101118] INFO: Write: size=1, data=84 [0.103245] INFO: Read: size=1, data=5A [0.107241] INFO: Read: size=17, data=4F43452056543320523244203531324BBF [0.107252] dc_device_dump [0.107858] INFO: Write: size=3, data=B10000 [0.109243] INFO: Read: size=1, data=A5 [0.109249] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:338 (oceanic_atom2_send)] [0.109252] INFO: Sleep: value=100 [0.209320] INFO: Flush: queue=1, input=0, output=0 [0.211906] INFO: Write: size=3, data=B10000 [0.211916] INFO: Read: size=1, data=5A [0.221744] INFO: Read: size=17, data=0416041120081001425800730000000075 [0.223887] INFO: Write: size=3, data=B10001 [3.226909] INFO: Read: size=0, data= [3.226920] ERROR: Failed to receive the answer. [in oceanic_atom2.c:332 (oceanic_atom2_send)] [3.226923] INFO: Sleep: value=100 [3.326992] INFO: Flush: queue=1, input=0, output=0 [3.327861] INFO: Write: size=3, data=B10001 [3.328711] INFO: Read: size=1, data=5A [3.339732] INFO: Read: size=17, data=6701DA064204E506E206DC06FF0FAAFBF6 [3.343861] INFO: Write: size=3, data=B10002 [6.346882] INFO: Read: size=0, data= [6.346893] ERROR: Failed to receive the answer. [in oceanic_atom2.c:332 (oceanic_atom2_send)] [6.346897] INFO: Sleep: value=100
The procedure on how to setup Portmon is described here:
http://www.libdivecomputer.org/contribute.html#protocol
Unfortunately you'll need a 32bit Windows version to run Portmon. If you use some other capture application that's of course fine too. Portmon is just convenient because it's freeware and the output is easy to parse with scripts.
Just to make things slightly more perverse, my only 32 bit Windows handy is a VM on the linux machine. OceanLog runs fine within the VM (letting VirtualBox give the USB device to the VM). But PortMon isn't even giving me a Computer menu so I can't get anywhere with that. I'll look into it more a bit later.
Hamish
On 2014-03-12 01:20, Hamish Moffatt wrote:
On 12/03/14 10:57, Linus Torvalds wrote:
Sounds like some other timing difference between Linux and Windows. Maybe Jef can make sense to the logs (and do you have logs with timing from windows for Jef to compare?)
Here's a log from Windows. There appears to be a whole lot less timing precision so it's a bit hard to compare, other than noting the absence of NAKs from the VT3.
That's due to the limited precision (in the order of several tens of milliseconds) of the Windows GetTickCount() function. Try with the attached patch instead, which uses the QueryPerformanceCounter() function instead. That's the same function I'm using for the half-duplex timing. There is a pre-build binary here:
http://www.libdivecomputer.org/builds/experimental/windows/universal-timings...
Jef
On 12/03/14 21:02, Jef Driesen wrote:
On 2014-03-12 01:20, Hamish Moffatt wrote:
On 12/03/14 10:57, Linus Torvalds wrote:
Sounds like some other timing difference between Linux and Windows. Maybe Jef can make sense to the logs (and do you have logs with timing from windows for Jef to compare?)
Here's a log from Windows. There appears to be a whole lot less timing precision so it's a bit hard to compare, other than noting the absence of NAKs from the VT3.
That's due to the limited precision (in the order of several tens of milliseconds) of the Windows GetTickCount() function. Try with the attached patch instead, which uses the QueryPerformanceCounter() function instead. That's the same function I'm using for the half-duplex timing. There is a pre-build binary here:
http://www.libdivecomputer.org/builds/experimental/windows/universal-timings...
There seems to be a heap of read-write turnaround; there's 14ms+ in some of the early commands although it's as low as 1.5ms later. But there's 100ms sleeps after each read too - that's not in the regular build though?
[0.000026] DATETIME 2014-03-12T11:54:45Z (1394625285) [0.001183] VERSION 0.5.0-devel (a712c8781d0e2065f6e9b7768286546c9495defe) [0.001591] Opening the device (Oceanic VT3, COM3). [0.003046] INFO: Open: name=COM3 [0.042081] INFO: Configure: baudrate=38400, databits=8, parity=0, stopbits=1, flowcontrol=0 [0.047021] INFO: Timeout: value=3000 [0.047352] INFO: Sleep: value=100 [0.147300] INFO: Flush: queue=3, input=0, output=0 [0.147716] INFO: Sleep: value=100 [0.247408] INFO: Write: size=2, data=8400 [0.258620] INFO: Read: size=1, data=5A [0.258969] INFO: Read: size=17, data=4F43452056543320523244203531324BBF [0.259722] Registering the event handler. [0.259994] Registering the cancellation handler. [0.260253] Downloading the memory dump. [0.260571] Event: vendor=4F43452056543320523244203531324B [0.263368] Event: progress 0.00% (0/65536) [0.263657] INFO: Sleep: value=100 [0.357385] INFO: Write: size=4, data=B1000000 [0.370210] INFO: Read: size=1, data=5A [0.370630] INFO: Read: size=17, data=0416041120081001425800730000000075 [0.370905] Event: progress 0.02% (16/65536) [0.371204] INFO: Sleep: value=100 [0.467360] INFO: Write: size=4, data=B1000100 [0.481764] INFO: Read: size=1, data=5A [0.482221] INFO: Read: size=17, data=6701DA064204E506E206DC06FF0FAAFBF6 [0.482495] Event: progress 0.05% (32/65536) [0.482800] INFO: Sleep: value=100 [0.578330] INFO: Write: size=4, data=B1000200 [0.593307] INFO: Read: size=1, data=5A [0.593706] INFO: Read: size=17, data=0000DC06FF0FDC06FF0F00000000AA8A14 [0.593974] Event: progress 0.07% (48/65536) [0.594252] INFO: Sleep: value=100 [0.687366] INFO: Write: size=4, data=B1000300 [0.688852] INFO: Read: size=1, data=5A [0.704842] INFO: Read: size=17, data=890E370D00011B0B670542053250AAE1C2 [0.705245] Event: progress 0.10% (64/65536) [0.705642] INFO: Sleep: value=100 [0.797355] INFO: Write: size=4, data=B1000400 [0.800413] INFO: Read: size=1, data=5A [0.816394] INFO: Read: size=17, data=300220028003500530BEB0BB0000000085 [0.816772] Event: progress 0.12% (80/65536) [0.817042] INFO: Sleep: value=100 [0.917352] INFO: Write: size=4, data=B1000500 [0.927884] INFO: Read: size=1, data=5A [0.943845] INFO: Read: size=17, data=A014000300002C01980805A0022100024E [0.944209] Event: progress 0.15% (96/65536) [0.944489] INFO: Sleep: value=100 [1.037353] INFO: Write: size=4, data=B1000600 [1.039431] INFO: Read: size=1, data=5A [1.055386] INFO: Read: size=17, data=3899000099003102E9050400000000008F [1.055728] Event: progress 0.17% (112/65536) [1.056009] INFO: Sleep: value=100 [1.147369] INFO: Write: size=4, data=B1000700 [1.151004] INFO: Read: size=1, data=5A [1.166952] INFO: Read: size=17, data=0906290000000000003C00000100000277 [1.167412] Event: progress 0.20% (128/65536) [1.167836] INFO: Sleep: value=100 [1.267344] INFO: Write: size=4, data=B1000800 [1.278484] INFO: Read: size=1, data=5A [1.294425] INFO: Read: size=17, data=A9A6C9AAAAAAAAAAAA0000000000000014 [1.294795] Event: progress 0.22% (144/65536) [1.295084] INFO: Sleep: value=100 [1.387361] INFO: Write: size=4, data=B1000900 [1.390006] INFO: Read: size=1, data=5A [1.406022] INFO: Read: size=17, data=6400000300001400980805A00251000215 [1.406352] Event: progress 0.24% (160/65536) [1.406627] INFO: Sleep: value=100 [1.497361] INFO: Write: size=4, data=B1000A00 [1.501549] INFO: Read: size=1, data=5A [1.517551] INFO: Read: size=17, data=0000000000000000000000000000000000 [1.517983] Event: progress 0.27% (176/65536) [1.518277] INFO: Sleep: value=100 [1.617345] INFO: Write: size=4, data=B1000B00 [1.629113] INFO: Read: size=1, data=5A [1.645030] INFO: Read: size=17, data=42056EA46350460014AA1001438348204F [1.645387] Event: progress 0.29% (192/65536) [1.645664] INFO: Sleep: value=100 [1.737342] INFO: Write: size=4, data=B1000C00 [1.740598] INFO: Read: size=1, data=5A [1.756554] INFO: Read: size=17, data=43142CA56F40510015AA541324064720DF [1.756894] Event: progress 0.32% (208/65536) [1.757172] INFO: Sleep: value=100 [1.857351] INFO: Write: size=4, data=B1000D00 [1.868105] INFO: Read: size=1, data=5A [1.884047] INFO: Read: size=17, data=4414FEA35D40450015AA240440114D2080 [1.886750] Event: progress 0.34% (224/65536) [1.887110] INFO: Sleep: value=100 [1.987360] INFO: Write: size=4, data=B1000E00 [1.995558] INFO: Read: size=1, data=5A [2.011552] INFO: Read: size=17, data=4524B9A46840450015AA530119824B20CC [2.011982] Event: progress 0.37% (240/65536) [2.012347] INFO: Sleep: value=100 [2.108153] INFO: Write: size=4, data=B1000F00 [2.123131] INFO: Read: size=1, data=5A [2.123521] INFO: Read: size=17, data=4624FEA35D40470015AA080113844920B7 [2.123794] Event: progress 0.39% (256/65536) [2.124093] INFO: Sleep: value=100
Hamish
On 2014-03-12 13:14, Hamish Moffatt wrote:
On 12/03/14 21:02, Jef Driesen wrote:
On 2014-03-12 01:20, Hamish Moffatt wrote:
On 12/03/14 10:57, Linus Torvalds wrote:
Sounds like some other timing difference between Linux and Windows. Maybe Jef can make sense to the logs (and do you have logs with timing from windows for Jef to compare?)
Here's a log from Windows. There appears to be a whole lot less timing precision so it's a bit hard to compare, other than noting the absence of NAKs from the VT3.
That's due to the limited precision (in the order of several tens of milliseconds) of the Windows GetTickCount() function. Try with the attached patch instead, which uses the QueryPerformanceCounter() function instead. That's the same function I'm using for the half-duplex timing. There is a pre-build binary here:
http://www.libdivecomputer.org/builds/experimental/windows/universal-timings...
There seems to be a heap of read-write turnaround; there's 14ms+ in some of the early commands although it's as low as 1.5ms later. But there's 100ms sleeps after each read too - that's not in the regular build though?
Ah sorry, my mistake. That 100ms delay was a leftover from one of the previous builds. I have removed it now. Just re-download the same file again.
Jef
On 12/03/14 23:29, Jef Driesen wrote:
On 2014-03-12 13:14, Hamish Moffatt wrote:
On 12/03/14 21:02, Jef Driesen wrote:
On 2014-03-12 01:20, Hamish Moffatt wrote:
On 12/03/14 10:57, Linus Torvalds wrote:
Sounds like some other timing difference between Linux and Windows. Maybe Jef can make sense to the logs (and do you have logs with timing from windows for Jef to compare?)
Here's a log from Windows. There appears to be a whole lot less timing precision so it's a bit hard to compare, other than noting the absence of NAKs from the VT3.
That's due to the limited precision (in the order of several tens of milliseconds) of the Windows GetTickCount() function. Try with the attached patch instead, which uses the QueryPerformanceCounter() function instead. That's the same function I'm using for the half-duplex timing. There is a pre-build binary here:
http://www.libdivecomputer.org/builds/experimental/windows/universal-timings...
There seems to be a heap of read-write turnaround; there's 14ms+ in some of the early commands although it's as low as 1.5ms later. But there's 100ms sleeps after each read too - that's not in the regular build though?
Ah sorry, my mistake. That 100ms delay was a leftover from one of the previous builds. I have removed it now. Just re-download the same file again.
Here's the log. As before there's quite a lot of write-read turnaround. The Mac log showed the same, and the linux log doesn't.
[0.000015] DATETIME 2014-03-12T13:16:22Z (1394630182) [0.000622] VERSION 0.5.0-devel (a712c8781d0e2065f6e9b7768286546c9495defe) [0.000946] Opening the device (Oceanic VT3, COM3). [0.002302] INFO: Open: name=COM3 [0.024421] INFO: Configure: baudrate=38400, databits=8, parity=0, stopbits=1, flowcontrol=0 [0.029375] INFO: Timeout: value=3000 [0.029712] INFO: Sleep: value=100 [0.124765] INFO: Flush: queue=3, input=0, output=0 [0.125288] INFO: Write: size=2, data=8400 [0.129447] INFO: Read: size=1, data=5A [0.145393] INFO: Read: size=17, data=4F43452056543320523244203531324BBF [0.146257] Registering the event handler. [0.146698] Registering the cancellation handler. [0.146996] Downloading the memory dump. [0.147333] Event: vendor=4F43452056543320523244203531324B [0.150762] Event: progress 0.00% (0/65536) [0.151195] INFO: Write: size=4, data=B1000000 [0.161318] INFO: Read: size=1, data=5A [0.177263] INFO: Read: size=17, data=0416041120081001425800730000000075 [0.177628] Event: progress 0.02% (16/65536) [0.178262] INFO: Write: size=4, data=B1000100 [0.193202] INFO: Read: size=1, data=5A [0.193509] INFO: Read: size=17, data=6701DA064204E506E206DC06FF0FAAFBF6 [0.193773] Event: progress 0.05% (32/65536) [0.194195] INFO: Write: size=4, data=B1000200 [0.209158] INFO: Read: size=1, data=5A [0.209513] INFO: Read: size=17, data=0000DC06FF0FDC06FF0F00000000AA8A14 [0.209866] Event: progress 0.07% (48/65536) [0.210268] INFO: Write: size=4, data=B1000300 [0.225104] INFO: Read: size=1, data=5A [0.225578] INFO: Read: size=17, data=890E370D00011B0B670542053250AAE1C2 [0.225871] Event: progress 0.10% (64/65536) [0.226282] INFO: Write: size=4, data=B1000400 [0.241057] INFO: Read: size=1, data=5A [0.241476] INFO: Read: size=17, data=300220028003500530BEB0BB0000000085 [0.241787] Event: progress 0.12% (80/65536) [0.242204] INFO: Write: size=4, data=B1000500 [0.256970] INFO: Read: size=1, data=5A [0.257406] INFO: Read: size=17, data=A014000300002C01980805A0022100024E [0.257774] Event: progress 0.15% (96/65536) [0.258190] INFO: Write: size=4, data=B1000600 [0.272930] INFO: Read: size=1, data=5A [0.273329] INFO: Read: size=17, data=3899000099003102E9050400000000008F [0.273598] Event: progress 0.17% (112/65536) [0.273952] INFO: Write: size=4, data=B1000700 [0.288850] INFO: Read: size=1, data=5A [0.289192] INFO: Read: size=17, data=0906290000000000003C00000100000277 [0.289457] Event: progress 0.20% (128/65536) [0.289835] INFO: Write: size=4, data=B1000800 [0.304833] INFO: Read: size=1, data=5A [0.305385] INFO: Read: size=17, data=A9A6C9AAAAAAAAAAAA0000000000000014 [0.305709] Event: progress 0.22% (144/65536) [0.306117] INFO: Write: size=4, data=B1000900 [0.320764] INFO: Read: size=1, data=5A [0.321095] INFO: Read: size=17, data=6400000300001400980805A00251000215 [0.321360] Event: progress 0.24% (160/65536) [0.321871] INFO: Write: size=4, data=B1000A00 [0.336649] INFO: Read: size=1, data=5A [0.337050] INFO: Read: size=17, data=0000000000000000000000000000000000 [0.337360] Event: progress 0.27% (176/65536) [0.337783] INFO: Write: size=4, data=B1000B00 [0.352612] INFO: Read: size=1, data=5A [0.353122] INFO: Read: size=17, data=42056EA46350460014AA1001438348204F [0.353401] Event: progress 0.29% (192/65536) [0.353774] INFO: Write: size=4, data=B1000C00 [0.368514] INFO: Read: size=1, data=5A [0.368848] INFO: Read: size=17, data=43142CA56F40510015AA541324064720DF [0.369146] Event: progress 0.32% (208/65536) [0.369556] INFO: Write: size=4, data=B1000D00 [0.384487] INFO: Read: size=1, data=5A [0.384967] INFO: Read: size=17, data=4414FEA35D40450015AA240440114D2080 [0.385446] Event: progress 0.34% (224/65536) [0.385861] INFO: Write: size=4, data=B1000E00 [0.400392] INFO: Read: size=1, data=5A [0.400735] INFO: Read: size=17, data=4524B9A46840450015AA530119824B20CC [0.401010] Event: progress 0.37% (240/65536) [0.401380] INFO: Write: size=4, data=B1000F00 [0.416324] INFO: Read: size=1, data=5A [0.416748] INFO: Read: size=17, data=4624FEA35D40470015AA080113844920B7 [0.417077] Event: progress 0.39% (256/65536) [0.417526] INFO: Write: size=4, data=B1001000 [0.432294] INFO: Read: size=1, data=5A [0.435167] INFO: Read: size=17, data=472336A46040470016AA211322064820AF [0.435504] Event: progress 0.42% (272/65536) [0.435944] INFO: Write: size=4, data=B1001100 [0.448208] INFO: Read: size=1, data=5A [0.448574] INFO: Read: size=17, data=482416A45F40510016AA03021309492060 [0.448880] Event: progress 0.44% (288/65536) [0.449279] INFO: Write: size=4, data=B1001200 [0.464144] INFO: Read: size=1, data=5A [0.464483] INFO: Read: size=17, data=493460A46350460016AA030109114C20C4 [0.464791] Event: progress 0.46% (304/65536) [0.465233] INFO: Write: size=4, data=B1001300 [0.480081] INFO: Read: size=1, data=5A [0.480446] INFO: Read: size=17, data=503441A57140450016AA210217824B2047 [0.480778] Event: progress 0.49% (320/65536) [0.481134] INFO: Write: size=4, data=B1001400 [0.496032] INFO: Read: size=1, data=5A [0.496512] INFO: Read: size=17, data=510197A24710460017AA2323268245203C [0.496877] Event: progress 0.51% (336/65536) [0.497279] INFO: Write: size=4, data=B1001500
and here's a bit of the Mac log, which I posted earlier (Mac works, btw);
[0.000491] DATETIME 2014-03-12T04:17:10Z (1394597830) [0.000515] VERSION 0.5.0-devel (575f2e9016ac9baa2b1b031caa6fe0bc77cdbbee) [0.000519] DEVICE=/dev/tty.usbserial-20030001 [0.000540] oceanic_atom2_device_open [0.000557] INFO: Open: name=/dev/tty.usbserial-20030001 [0.004850] INFO: Configure: baudrate=38400, databits=8, parity=0, stopbits=1, flowcontrol=0 [0.005042] INFO: Timeout: value=3000 [0.005061] INFO: Sleep: value=100 [0.106152] INFO: Flush: queue=3, input=2, output=0 [0.106450] INFO: Write: size=2, data=8400 [0.114123] INFO: Read: size=1, data=5A [0.114137] INFO: Read: size=17, data=4F43452056543320523244203531324BBF [0.114170] dc_device_dump [0.114411] INFO: Write: size=4, data=B1000000 [0.130090] INFO: Read: size=1, data=5A [0.130110] INFO: Read: size=17, data=0416041120081001425800730000000075 [0.130302] INFO: Write: size=4, data=B1000100 [0.146005] INFO: Read: size=1, data=5A [0.146034] INFO: Read: size=17, data=6701DA064204E506E206DC06FF0FAAFBF6 [0.146180] INFO: Write: size=4, data=B1000200 [0.162008] INFO: Read: size=1, data=5A [0.162029] INFO: Read: size=17, data=0000DC06FF0FDC06FF0F00000000AA8A14 [0.162166] INFO: Write: size=4, data=B1000300 [0.177875] INFO: Read: size=1, data=5A [0.177899] INFO: Read: size=17, data=890E370D00011B0B670542053250AAE1C2 [0.178035] INFO: Write: size=4, data=B1000400 [0.193736] INFO: Read: size=1, data=5A [0.193757] INFO: Read: size=17, data=300220028003500530BEB0BB0000000085 [0.193916] INFO: Write: size=4, data=B1000500 [0.209734] INFO: Read: size=1, data=5A [0.209753] INFO: Read: size=17, data=A014000300002C01980805A0022100024E [0.209917] INFO: Write: size=4, data=B1000600
On 2014-03-11 16:59, Linus Torvalds wrote:
On Tue, Mar 11, 2014 at 6:27 AM, Jef Driesen jef@libdivecomputer.org wrote:
I wonder if this is another case where the tcdrain() function isn't waiting properly until all bytes have been send out.
Assuming it is ftdi, we should have at least *tried* to do it since 3.8, but I really won't guarantee that it works. I'm assuming Hamish has something newer than that, but who knows.. As usual, I think Debian "stable" (also known as "bat shit crazy") is some ancient 3.2 kernel still, but all other distros should be much more up-to-date.
We had a similar problem with Suunto devices before.
As you know (but perhaps others don't) this isn't a Suunto problem per se - the actual *real* legacy serial cable should work fine, because on a real UART we generally have an easy way to check whether the send buffer has actually flushed out.
But the USB people originally (consciously) decided to not make USB -> serial be a standard, because their argument was that USB should replace serial lines, and USB serial dongles were thus "invalid". Morons with an agenda. As a result, there is no actual standard USB serial conversion model, and every single USB serial chip is a "hack" pretty much by definition.
And with simplex being *so* unusual, it doesn't get a lot of attention and testing, and since it's not some generic standard, it's always per-dongle-chip-driver.
With USB being the Universal *Serial* Bus, it's kind of funny that one thing it doesn't do very well is serial communication :-)
Isn't USB CDC-ACM supposed to be the standardized way for emulating legacy serial communication over USB? There are a few dive computer using it (Mares Icon HD and Dive Rite Nitek Q), but these are all using a microchip internally. So although they do present themselves to the outside as a legacy serial port, at no point there is any conversion to real serial communication necessary (because that microchip speaks native usb). So that's quite different from using a usb-serial conversion chip from ftdi or prolific, which really has to emulate serial communication on one end.
Jef
On Wed, Mar 12, 2014 at 7:32 AM, Jef Driesen jef@libdivecomputer.org wrote:
With USB being the Universal *Serial* Bus, it's kind of funny that one thing it doesn't do very well is serial communication :-)
You spelled "sad" wrong.
Isn't USB CDC-ACM supposed to be the standardized way for emulating legacy serial communication over USB?
That is indeed supposed to be the standardized way to implement almost-legacy serial communications over USB. But it's not really a "cable replacement" standard, it tries to go further than that, which is probably why pure cable replacements seem to never use it.
As you mention, it *does* get used by people who actually end up implementing real USB on the other side.
So it is commonly used as a "virtual serial port" by people who actually implement USB natively but I've actually never seen it in an actual *physical* USB to serial port converter.
I'm not 100% sure why, but I suspect it is due to CDC-ACM simply being over-engineered for the solution, resulting in both unnecessarily complex silicon and various driver problems. It may also have been late to the party, and by the time it arrived there were three or four vendors who had solved it their own way. And then it just remained that way.
Linus
On 12/03/14 00:27, Jef Driesen wrote:
Even a sleep of just 1ms per packet is pretty bad. If I remember correctly, the resolution of the Windows Sleep() function is in the order of 10-15ms only. So that would still be a delay of approximately 40.96 seconds.
I wonder if this is another case where the tcdrain() function isn't waiting properly until all bytes have been send out. We had a similar problem with Suunto devices before. There we implemented a workaround with serial_set_halfduplex() function. Could you try that as well? Just call it somewhere in the oceanic_atom2_device_open() function, but before the call to the oceanic_atom2_device_open() function.
I don't see any change.
How many wires does the Oceanic interface have? Just two or more?
Three.
I have been looking at the kernel history for the ftdi usb-serial driver, and there have been some changes related to waiting until the TX buffer is empty, so there could be something there as well. Which kernel version do you have (uname -a)?
I had 3.2.54 but after reading Linus's email as well I upgraded to 3.12.9 but I don't see any change there either. With regard to the FTDI latency issue you mentioned earlier, in 3.12.9 it seems the default is already set to the minimum:
$ cat /sys/bus/usb-serial/devices/ttyUSB0/latency_timer 1
PS: Don't forget to attach the logfiles. I want to have a look at the timings.
Here's it running with the half duplex change:
[0.000032] DATETIME 2014-03-11T23:50:21Z (1394581821) [0.000055] VERSION 0.4.2 [0.000058] DEVICE=/dev/ttyUSB0 [0.000063] oceanic_atom2_device_open [0.000854] INFO: Configure: baudrate=38400, databits=8, parity=0, stopbits=1, flowcontrol=0 [0.001001] INFO: Timeout: value=3000 [0.001011] INFO: Sleep: value=100 [0.101086] INFO: Flush: queue=3, input=0, output=0 [0.101478] INFO: Sleep: value=3 [0.104540] INFO: Write: size=2, data=8400 [0.104551] INFO: Read: size=1, data=5A [0.106774] INFO: Read: size=17, data=4F43452056543320523244203531324BBF [0.106785] dc_device_dump [0.109560] INFO: Sleep: value=1 [0.110624] INFO: Write: size=4, data=B1000000 [0.110634] INFO: Read: size=1, data=A5 [0.110637] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:339 (oceanic_atom2_send)] [0.110639] INFO: Sleep: value=100 [0.210709] INFO: Flush: queue=1, input=0, output=0 [0.213559] INFO: Sleep: value=1 [0.214622] INFO: Write: size=4, data=B1000000 [0.214630] INFO: Read: size=1, data=5A [0.223108] INFO: Read: size=17, data=0416041120081001425800730000000075 [0.225561] INFO: Sleep: value=1 [0.226626] INFO: Write: size=4, data=B1000100 [3.229650] INFO: Read: size=0, data= [3.229662] ERROR: Failed to receive the answer. [in oceanic_atom2.c:333 (oceanic_atom2_send)] [3.229667] INFO: Sleep: value=100 [3.329737] INFO: Flush: queue=1, input=0, output=0 [3.333561] INFO: Write: size=4, data=B1000100 [3.333572] INFO: Read: size=1, data=5A [3.342815] INFO: Read: size=17, data=6701DA064204E506E206DC06FF0FAAFBF6 [3.345590] INFO: Sleep: value=1 [3.346656] INFO: Write: size=4, data=B1000200 [3.346665] INFO: Read: size=1, data=A5 [3.346667] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:339 (oceanic_atom2_send)] [3.346670] INFO: Sleep: value=100 [3.446738] INFO: Flush: queue=1, input=0, output=0 [3.449561] INFO: Sleep: value=1 [3.450627] INFO: Write: size=4, data=B1000200 [3.450637] INFO: Read: size=1, data=5A [3.459179] INFO: Read: size=17, data=0000DC06FF0FDC06FF0F00000000AA8A14 [3.461560] INFO: Sleep: value=1 [3.462625] INFO: Write: size=4, data=B1000300 [6.465647] INFO: Read: size=0, data= [6.465658] ERROR: Failed to receive the answer. [in oceanic_atom2.c:333 (oceanic_atom2_send)] [6.465662] INFO: Sleep: value=100 [6.565732] INFO: Flush: queue=1, input=0, output=0 [6.569559] INFO: Write: size=4, data=B1000300 [6.569570] INFO: Read: size=1, data=5A [6.578829] INFO: Read: size=17, data=890E370D00011B0B670542053250AAE1C2 [6.581562] INFO: Sleep: value=1 [6.582626] INFO: Write: size=4, data=B1000400 [6.582636] INFO: Read: size=1, data=A5 [6.582638] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:339 (oceanic_atom2_send)] [6.582640] INFO: Sleep: value=100 [6.682709] INFO: Flush: queue=1, input=0, output=0 [6.685558] INFO: Sleep: value=1 [6.686618] INFO: Write: size=4, data=B1000400 [6.686626] INFO: Read: size=1, data=5A [6.695494] INFO: Read: size=17, data=300220028003500530BEB0BB0000000085 [6.697557] INFO: Sleep: value=1 [6.698616] INFO: Write: size=4, data=B1000500 [6.698622] INFO: Read: size=1, data=A5 [6.698623] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:339 (oceanic_atom2_send)] [6.698626] INFO: Sleep: value=100 [6.798693] INFO: Flush: queue=1, input=0, output=0 [6.801560] INFO: Sleep: value=1 [6.802626] INFO: Write: size=4, data=B1000500 [6.802636] INFO: Read: size=1, data=5A [6.810993] INFO: Read: size=17, data=A014000300002C01980805A0022100024E [6.813590] INFO: Sleep: value=1 [6.814656] INFO: Write: size=4, data=B1000600 [9.817693] INFO: Read: size=0, data= [9.817717] ERROR: Failed to receive the answer. [in oceanic_atom2.c:333 (oceanic_atom2_send)] [9.817723] INFO: Sleep: value=100 [9.917791] INFO: Flush: queue=1, input=0, output=0 [9.921590] INFO: Write: size=4, data=B1000600 [9.921602] INFO: Read: size=1, data=5A [9.930645] INFO: Read: size=17, data=3899000099003102E9050400000000008F [9.933561] INFO: Sleep: value=1 [9.934620] INFO: Write: size=4, data=B1000700 [9.934626] INFO: Read: size=1, data=A5 [9.934628] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:339 (oceanic_atom2_send)] [9.934631] INFO: Sleep: value=100 [10.034727] INFO: Flush: queue=1, input=0, output=0 [10.037561] INFO: Sleep: value=1 [10.038626] INFO: Write: size=4, data=B1000700 [10.038637] INFO: Read: size=1, data=5A [10.047154] INFO: Read: size=17, data=0906290000000000003C00000100000277 [10.049588] INFO: Sleep: value=1 [10.050663] INFO: Write: size=4, data=B1000800 [13.053576] INFO: Read: size=0, data= [13.053592] ERROR: Failed to receive the answer. [in oceanic_atom2.c:333 (oceanic_atom2_send)] [13.053598] INFO: Sleep: value=100 [13.153679] INFO: Flush: queue=1, input=0, output=0 [13.157561] INFO: Write: size=4, data=B1000800 [13.157571] INFO: Read: size=1, data=5A [13.166564] INFO: Read: size=17, data=A9A6C9AAAAAAAAAAAA0000000000000014 [13.169566] INFO: Sleep: value=1 [13.170625] INFO: Write: size=4, data=B1000900 [13.170632] INFO: Read: size=1, data=A5 [13.170634] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:339 (oceanic_atom2_send)] [13.170637] INFO: Sleep: value=100 [13.270704] INFO: Flush: queue=1, input=0, output=0 [13.273560] INFO: Sleep: value=1 [13.274626] INFO: Write: size=4, data=B1000900 [13.274636] INFO: Read: size=1, data=5A [13.283203] INFO: Read: size=17, data=6400000300001400980805A00251000215 [13.285561] INFO: Sleep: value=1 [13.286626] INFO: Write: size=4, data=B1000A00 [16.289661] INFO: Read: size=0, data= [16.289679] ERROR: Failed to receive the answer. [in oceanic_atom2.c:333 (oceanic_atom2_send)] [16.289693] INFO: Sleep: value=100 [16.389770] INFO: Flush: queue=1, input=0, output=0 [16.393579] INFO: Write: size=4, data=B1000A00 [16.393600] INFO: Read: size=1, data=5A [16.402613] INFO: Read: size=17, data=0000000000000000000000000000000000 [16.405595] INFO: Sleep: value=1 [16.406670] INFO: Write: size=4, data=B1000B00 [16.406689] INFO: Read: size=1, data=A5 [16.406693] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:339 (oceanic_atom2_send)] [16.406698] INFO: Sleep: value=100 [16.506773] INFO: Flush: queue=1, input=0, output=0 [16.509576] INFO: Sleep: value=1 [16.510658] INFO: Write: size=4, data=B1000B00 [16.510680] INFO: Read: size=1, data=5A [16.519117] INFO: Read: size=17, data=42056EA46350460014AA1001438348204F [16.521562] INFO: Sleep: value=1 [16.522627] INFO: Write: size=4, data=B1000C00 [19.525664] INFO: Read: size=0, data= [19.525683] ERROR: Failed to receive the answer. [in oceanic_atom2.c:333 (oceanic_atom2_send)] [19.525689] INFO: Sleep: value=100 [19.625760] INFO: Flush: queue=1, input=0, output=0 [19.629589] INFO: Write: size=4, data=B1000C00 [19.629601] INFO: Read: size=1, data=5A [19.638596] INFO: Read: size=17, data=43142CA56F40510015AA541324064720DF [19.641565] INFO: Sleep: value=1 [19.642636] INFO: Write: size=4, data=B1000D00 [19.642649] INFO: Read: size=1, data=A5 [19.642652] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:339 (oceanic_atom2_send)] [19.642658] INFO: Sleep: value=100 [19.742726] INFO: Flush: queue=1, input=0, output=0 [19.745589] INFO: Sleep: value=1 [19.746655] INFO: Write: size=4, data=B1000D00 [19.746665] INFO: Read: size=1, data=5A [19.755186] INFO: Read: size=17, data=4414FEA35D40450015AA240440114D2080 [19.757560] INFO: Sleep: value=1 [19.758622] INFO: Write: size=4, data=B1000E00 [22.761642] INFO: Read: size=0, data= [22.761653] ERROR: Failed to receive the answer. [in oceanic_atom2.c:333 (oceanic_atom2_send)] [22.761657] INFO: Sleep: value=100 [22.861725] INFO: Flush: queue=1, input=0, output=0 [22.865565] INFO: Write: size=4, data=B1000E00 [22.865575] INFO: Read: size=1, data=5A [22.874812] INFO: Read: size=17, data=4524B9A46840450015AA530119824B20CC [22.877568] INFO: Sleep: value=1 [22.878629] INFO: Write: size=4, data=B1000F00 [22.878635] INFO: Read: size=1, data=A5 [22.878637] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:339 (oceanic_atom2_send)] [22.878640] INFO: Sleep: value=100
Occasionally even the very first command (get version) fails. I have just the original 100 ms delay after open in now.
[0.000044] DATETIME 2014-03-12T00:00:24Z (1394582424) [0.000075] VERSION 0.4.2 [0.000079] DEVICE=/dev/ttyUSB0 [0.000086] oceanic_atom2_device_open [0.000793] INFO: Configure: baudrate=38400, databits=8, parity=0, stopbits=1, flowcontrol=0 [0.000993] INFO: Timeout: value=3000 [0.001001] INFO: Sleep: value=100 [0.101090] INFO: Flush: queue=3, input=263, output=0 [0.101407] INFO: Sleep: value=3 [0.104481] INFO: Write: size=2, data=8400 [0.104504] INFO: Read: size=1, data=00 [0.104508] ERROR: Unexpected answer start byte(s). [in oceanic_atom2.c:339 (oceanic_atom2_send)] [0.104517] INFO: Sleep: value=100 [0.204588] INFO: Flush: queue=1, input=118, output=0 [0.204898] INFO: Sleep: value=3 [0.207960] INFO: Write: size=2, data=8400 [0.207970] INFO: Read: size=1, data=5A [0.209921] INFO: Read: size=17, data=4F43452056543320523244203531324BBF [0.209935] dc_device_dump
Hamish
-
Hamish Moffatt -
Jef Driesen -
Linus Torvalds