FreeEMS-Tuner Development Diary - Comments

[Fred]

Just to be clear, those two messages are in separate parts of an if/else pair... IE, they are being run on subsequent loop iterations.

Fred.

[Fred]

Solved, logging reduced and yet another hack introduced!

Code: Select all

fred@rwdlsd:~$ time freeemsParser binary.stream.freeems.2.stops 
The length of file binary.stream.freeems.2.stops is 1560745

Attempting to parse file...

Packet number 1 ending of length 104 at char number 191 failed checksum! Received 166 Calculated 211
Packet number 2 ending of length 8 at char number 202 failed checksum! Received 166 Calculated 253
Packet number 3 ending of length 91 at char number 296 failed checksum! Received 166 Calculated 8
Packet number 4 ending of length 79 at char number 378 failed checksum! Received 166 Calculated 187
Packet number 5 ending of length 82 at char number 463 failed checksum! Received 166 Calculated 129
Packet number 6 ending of length 96 at char number 562 failed checksum! Received 166 Calculated 239

Data stream statistics :

Packets and checksums :
14844 packets were found
14838 had good checksums
6 had incorrect checksums

General issues :
13582 leading characters were dropped
1347 false starts occurred
1347 double start bytes occurred
0 stray part packets occurred
0 chars lost from false starts 

Escaped byte profile :
2121 escape bytes were found
1880 escaped stop bytes were found
194 escaped start bytes were found
47 escaped escape bytes were found
0 escape pairs were mismatched

real    0m0.108s
user    0m0.084s
sys     0m0.008s

We really need to figure out why we are losing bytes before and after packets.

This code works and works well it seems. I'll tidy it and push it after dinner.

Fred.

[Fred]

Ha! You still have issues :-)

And there is no fooling me now ;-)

Code: Select all

Exception in thread comms.default.receive:

Traceback (most recent call last):

  File "/usr/lib/python2.5/threading.py", line 486, in __bootstrap_inner

    self.run()

  File "/home/fred/workspaces/home/freeems-tuner/comms/protocols/IFreeEMS_Vanilla/v0_0_1/receive.py", line 71, in run

    self._process()

  File "/home/fred/workspaces/home/freeems-tuner/comms/protocols/IFreeEMS_Vanilla/v0_0_1/receive.py", line 104, in _process

    packet = self._processBuffer()

  File "/home/fred/workspaces/home/freeems-tuner/comms/protocols/IFreeEMS_Vanilla/v0_0_1/receive.py", line 186, in _processBuffer

    return self._processIncomingPacket(packet)

  File "/home/fred/workspaces/home/freeems-tuner/comms/protocols/IFreeEMS_Vanilla/v0_0_1/receive.py", line 232, in _processIncomingPacket

    response.validate()

  File "/home/fred/workspaces/home/freeems-tuner/comms/protocols/IFreeEMS_Vanilla/v0_0_1/responses.py", line 80, in validate

    raise Exception, 'Packet type %s, payload length of %s does not match parsed length of %s' % (pid, self.getCalculatedPayloadLengthInt(), length)

Exception: Packet type 401, payload length of 97 does not match parsed length of 96

Additionally, it seems to do the reception in blocks and throw a bad packet error every 10 or 20 packets it parses. I don't understand how you can get the messages like you do because the stray stops and starts can only be between real packets...

Code: Select all

09:10:51 comms.default.receive          ERROR processReceiveBuffer could not parse buffer. Bad/incomplete packet found in buffer before start byte 0x00,0x00,0x00,0x00,0x00,0x00,0x00,0x00,0x00,0x00,0x00,0x03,0x4A,0x03,0x3D,0x02,0xE9,0x03,0x04,0x02,0xAB,0x02,0x8F,0x02,0x05,0x03,0xCB,0x00,0xFA,0x00,0xFA,0x00,0xFC,0x00,0xF5,0x01,0x00,0x00,0xFD,0x00,0xFC,0x01,0x01,0x65,0xCC,0xCC 

09:10:51 comms.default.receive          ERROR processReceiveBuffer could not parse buffer. Bad/incomplete packet found in buffer before start byte 0xCC 

09:10:51 comms.default.receive          ERROR processReceiveBuffer could not parse buffer. Bad/incomplete packet found in buffer before start byte 0xCC 

09:10:51 comms.default.receive          ERROR processReceiveBuffer could not parse buffer. Bad/incomplete packet found in buffer before start byte 0xCC 

09:10:51 comms.default.receive          ERROR processReceiveBuffer could not parse buffer. Bad/incomplete packet found in buffer before start byte 0xCC 

09:10:51 comms.default.receive          ERROR processReceiveBuffer could not parse buffer. Bad/incomplete packet found in buffer before start byte 0xCC 

09:10:51 comms.default.receive          ERROR processReceiveBuffer could not parse buffer. Bad/incomplete packet found in buffer before start byte 0xCC 

09:10:51 comms.default.receive          ERROR processReceiveBuffer could not parse buffer. Bad/incomplete packet found in buffer before start byte 0xCC 

09:10:51 comms.default.receive          ERROR processReceiveBuffer could not parse buffer. Bad/incomplete packet found in buffer before start byte 0xCC 

09:10:51 comms.default.receive          ERROR processReceiveBuffer could not parse buffer. Bad/incomplete packet found in buffer before start byte 0xCC 

09:10:51 comms.handleReceivedPackets    DEBUG BasicDatalog packet received and processed 

09:10:51 comms.handleReceivedPackets    DEBUG BasicDatalog packet received and processed 

09:10:51 comms.handleReceivedPackets    DEBUG BasicDatalog packet received and processed 

09:10:51 comms.handleReceivedPackets    DEBUG BasicDatalog packet received and processed 

09:10:51 comms.handleReceivedPackets    DEBUG BasicDatalog packet received and processed 

09:10:51 comms.handleReceivedPackets    DEBUG BasicDatalog packet received and processed 

09:10:51 comms.handleReceivedPackets    DEBUG BasicDatalog packet received and processed 

09:10:51 comms.handleReceivedPackets    DEBUG BasicDatalog packet received and processed 

09:10:51 comms.handleReceivedPackets    DEBUG BasicDatalog packet received and processed 

That repeated many times with varying incomplete packet and varying length/count of good packets.

Fred.

[Fred]

If I didn't know any better I'd say it was a threading issue and somehow the logs are out of order. This could also be responsible for the incomplete packets? Certainly my utility shows me no stray packets on a large run :-) :

Code: Select all

Packets and checksums :
14844 packets were found
14838 had good checksums
6 had incorrect checksums

General issues :
13582 leading characters were dropped
1347 false starts occurred
1347 double start bytes occurred
0 stray part packets occurred
0 chars lost from false starts

Fred.

[Fred]

Parse location for those with a desire to dump binary data from a terminal and parse it :

http://github.com/fredcooke/freeems-van ... msParser.c

This works well, but I may update it, so just click through from the latest commit when you want to use it.

Fred.

[Fred]

Double post :
Retraction :

It's not that slow afterall :-)

10% python cpu usage with my xterm minimised or covered.

This is fine. It's still doing something funny with packets, but it should be fast enough, yay.

I added pysco support to it, but it didn't appear to make much difference really. 6.5% to 7.5% instead of around 10%.

Fred.

[Fred]

CPU usage :

9.0 - 9.8% as is
6.5% with pysco

Code: Select all

import psyco
psyco.full()

Is all that is required to be added to main.py for it to take effect.

I removed all pyc files each time to be certain of what i was running (probably not required).

Fred.

[sry_not4sale]

Good news!!

I just finished logging to file too to see if it was the cause!

[Fred]

That's great!!

(how tf do I use/test it??)

:-p

[sry_not4sale]

Make sure the following is in my_config.ini:

Code: Select all

[Logging]
to_file = True

It writes (not appends) to data/app.log