Dive data import error with Hollis DG03

[Jef Driesen]

On 2014-03-26 07:17, Hamish Moffatt wrote:
> On 25/03/14 23:27, Jef Driesen wrote:
>> I have uploaded "universal-atom2-delay" builds with the 100ms delay 
>> (and the flush) removed. Can you give them a try?
>> 
>> http://www.libdivecomputer.org/builds/experimental/
>> 
>> Please include the full logfile, because the timestamps are written to 
>> the logfile, but not the terminal output. So if you copy-and-paste 
>> from the terminal output, these timestamps are lost.
>> 
> 
> It works for me, although the first read times out (3 seconds) with no
> reply at all. I don't remember it before but I just tried your regular
> "universal" build and it does it too. Hmm. It could be the dive
> computer though, which I would have to say is pretty dumb.

I've noticed in the past that many dive computers require some delay 
between open the serial port and sending the first request. That's why 
in most libdivecomputer backends, you'll find a 100ms delay, followed by 
a flush of the input buffer (that's another oddity, because I have no 
idea how there can already be any data in the buffer immediately after 
opening the serial port). Anyway, without that 100ms delay the 
communication just fails. Maybe the dive computer needs some time to 
notice the usb connection? I really don't know.

If you compare the time it takes to setup serial port, you'll notice 
there is quite some difference between Linux (1.113ms) and Windows 
(24.126ms). Maybe that has something to do with it? But on the other 
hand, if that was indeed the problem, I would expect to see a failure 
when sending the very first request, but that's not where it fails for 
you.

(Note that something we noticed with the older Oceanic interfaces (vtpro 
and veo250) is that their pc interface, is not just some dumb cable with 
a usb-serial chip inside, but has a microchip inside. I suspect that 
this is some debug interface that was simply re-used for implementing 
the download protocol. We discovered that some of the initialization 
request are answered by the cable itself and not the dive computer. So 
there might be some overhead there. First we're talking to the 
microchip, then I assume the microchip will do whatever it needs to do 
to initialize the connection to the dive computer, and only then we can 
pass request to the dive computer. But I don't know if this still 
applies to the newer atom2 based models.)

BTW, I think there should be no problem to lower the timeout from 3 
seconds to just 1 second. A packet usually takes only a few 
milliseconds, so that's still plenty of margin.

> Anyway the sleep value stays at 8 for the duration, there's no more
> errors. Low latency flag is still set on the port. Bit of a shame it
> got to 8ms, as 4ms would have been plenty I think.

I think we are moving in the right direction. This is already a very 
nice improvement, compared to the failing downloads we had before.

I wonder if we can get rid of the initial failure by introducing a small 
delay (for example 50ms or something like that) before sending the first 
read request? Can you try that? Just add a serial_sleep call near the 
end of the oceanic_atom2_device_open function

Another thing that's probably worth considering is to set an upper limit 
for the dynamic delay. Otherwise, if someone still suffers from errors 
on every single packet, the delay will grow out of control.

> [0.000032] DATETIME 2014-03-26T05:57:14Z (1395813434)
> [0.000059] VERSION 0.5.0-devel 
> (fa90009c293a9ca1a4eaf49a478b381477695c0a)
> [0.000078] Opening the device (Oceanic VT3, /dev/ttyUSB0).
> [0.000088] INFO: Open: name=/dev/ttyUSB0
> [0.000862] INFO: Configure: baudrate=38400, databits=8, parity=0,
> stopbits=1, flowcontrol=0
> [0.001099] INFO: Timeout: value=3000
> [0.001113] INFO: Sleep: value=100
> [0.101191] INFO: Flush: queue=3, input=0, output=0
> [0.101599] INFO: Write: size=2, data=8400
> [0.103020] INFO: Read: size=1, data=5A
> [0.106891] INFO: Read: size=17, data=4F43452056543320523244203531324BBF
> [0.106910] Registering the event handler.
> [0.106916] Registering the cancellation handler.
> [0.106922] Downloading the memory dump.
> [0.106947] Event: vendor=4F43452056543320523244203531324B
> [0.106985] Event: progress 0.00% (0/65536)
> [0.111117] INFO: Write: size=4, data=B1000000
> [0.111133] INFO: Read: size=1, data=A5
> [0.111139] ERROR: Unexpected answer start byte(s). [in
> ../../source/src/oceanic_atom2.c:343 (oceanic_atom2_send)]
> [0.111147] INFO: Sleep: value=4
> [0.119110] INFO: Write: size=4, data=B1000000
> [3.122144] INFO: Read: size=0, data=
> [3.122156] ERROR: Failed to receive the answer. [in
> ../../source/src/oceanic_atom2.c:337 (oceanic_atom2_send)]
> [3.122161] INFO: Sleep: value=8
> [3.131108] INFO: Write: size=4, data=B1000000
> [3.131993] INFO: Read: size=1, data=5A
> [3.142992] INFO: Read: size=17, data=0416041120081001425800730000000075
> [3.143001] Event: progress 0.02% (16/65536)
> [3.143023] INFO: Sleep: value=8
> [3.155146] INFO: Write: size=4, data=B1000100
> [3.155165] INFO: Read: size=1, data=5A
> [3.163873] INFO: Read: size=17, data=6701DA064204E506E206DC06FF0FAAFBF6
> [3.163885] Event: progress 0.05% (32/65536)
> [3.163894] INFO: Sleep: value=8
> [3.175139] INFO: Write: size=4, data=B1000200
> [3.175153] INFO: Read: size=1, data=5A
> [3.184705] INFO: Read: size=17, data=0000DC06FF0FDC06FF0F00000000AA8A14
> [3.184717] Event: progress 0.07% (48/65536)
> [3.184725] INFO: Sleep: value=8
> [3.195163] INFO: Write: size=4, data=B1000300
> [3.195180] INFO: Read: size=1, data=5A
> [3.205734] INFO: Read: size=17, data=890E370D00011B0B670542053250AAE1C2
> [3.205741] Event: progress 0.10% (64/65536)
> [3.205748] INFO: Sleep: value=8
> [3.215108] INFO: Write: size=4, data=B1000400
> [3.215618] INFO: Read: size=1, data=5A
> [3.226616] INFO: Read: size=17, data=300220028003500530BEB0BB0000000085
> 
> And Windows (default latency timer), no initial timeout, no errors at 
> all:
> 
> [0.000011] DATETIME 2014-03-26T06:10:30Z (1395814230)
> [0.000220] VERSION 0.5.0-devel 
> (fa90009c293a9ca1a4eaf49a478b381477695c0a)
> [0.000534] Opening the device (Oceanic VT3, COM3).
> [0.002059] INFO: Open: name=COM3
> [0.019211] INFO: Configure: baudrate=38400, databits=8, parity=0,
> stopbits=1, flowcontrol=0
> [0.024126] INFO: Timeout: value=3000
> [0.024262] INFO: Sleep: value=100
> [0.118962] INFO: Flush: queue=3, input=0, output=0
> [0.121072] INFO: Write: size=2, data=8400
> [0.124054] INFO: Read: size=1, data=5A
> [0.128054] INFO: Read: size=17, data=4F43452056543320523244203531324BBF
> [0.128799] Registering the event handler.
> [0.129153] Registering the cancellation handler.
> [0.130000] Downloading the memory dump.
> [0.130752] Event: vendor=4F43452056543320523244203531324B
> [0.133997] Event: progress 0.00% (0/65536)
> [0.135079] INFO: Write: size=4, data=B1000000
> [0.139079] INFO: Read: size=1, data=5A
> [0.150094] INFO: Read: size=17, data=0416041120081001425800730000000075
> [0.150375] Event: progress 0.02% (16/65536)
> [0.152103] INFO: Write: size=4, data=B1000100
> [0.155092] INFO: Read: size=1, data=5A
> [0.166106] INFO: Read: size=17, data=6701DA064204E506E206DC06FF0FAAFBF6
> [0.166388] Event: progress 0.05% (32/65536)
> [0.168117] INFO: Write: size=4, data=B1000200
> [0.171114] INFO: Read: size=1, data=5A
> [0.182134] INFO: Read: size=17, data=0000DC06FF0FDC06FF0F00000000AA8A14
> [0.182453] Event: progress 0.07% (48/65536)
> [0.184141] INFO: Write: size=4, data=B1000300
> [0.187144] INFO: Read: size=1, data=5A
> [0.198144] INFO: Read: size=17, data=890E370D00011B0B670542053250AAE1C2
> [0.198475] Event: progress 0.10% (64/65536)
> [0.200158] INFO: Write: size=4, data=B1000400
> [0.204144] INFO: Read: size=1, data=5A
> [0.215161] INFO: Read: size=17, data=300220028003500530BEB0BB0000000085
> [0.215448] Event: progress 0.12% (80/65536)
> [0.217170] INFO: Write: size=4, data=B1000500
> [0.220170] INFO: Read: size=1, data=5A
> [0.231182] INFO: Read: size=17, data=A014000300002C01980805A0022100024E
> [0.231470] Event: progress 0.15% (96/65536)
> [0.233196] INFO: Write: size=4, data=B1000600
> [0.237185] INFO: Read: size=1, data=5A
> [0.248197] INFO: Read: size=17, data=3899000099003102E9050400000000008F
> [0.248467] Event: progress 0.17% (112/65536)
> [0.250224] INFO: Write: size=4, data=B1000700
> [0.254203] INFO: Read: size=1, data=5A
> [0.265218] INFO: Read: size=17, data=0906290000000000003C00000100000277
> 
> I can try the Mac later too.

That would be great.

> Total runtime on Linux was 170 seconds, 129 on Windows.

With an 8ms delay on all 4096 packets, that gives a total delay of 32s. 
That explains already most of the difference.

Jef