btmon.py "MySQL server has gone away"

[n8vjp]

I have an HP t5745 thin client with a true serial port and 2GB RAM running Debian 7 and the btmon.py as an rc.local startup service with a source of a single serially connected ECM-1240 and writing the data to a MySQL server on the LAN via 1Gbps wired Ethernet. The ECM-1240 is generating the data in real-time (1/sec) and btmon.py is updating MySQL every minute with a 30 day buffer in case the MySQL server is ever offline (yes that's overkill). I cannot find any capacity planning information to determine whether a buffer-size=2592000 is acceptable or what RAM consumption to expect with such a buffer-size, but it seems to run fine with the supplied parameters.

I am starting btmon as root with the following (IP and password obfuscated):
/home/ecm1240/btmon/btmon.py --quiet --buffer-size=2592000 --serial --serial-port=/dev/ttyS0 --mysql --mysql-host=192.168.n.n --mysql-passwd=********* --mysql-insert-period=60 &

It runs successfully without issue with the following observation and exception (debug mode used to see why the behavior was occurring):

• The buffer info never decrements after successfully writing to mysql. I would expect this to reset to 0 of 2592000 once a mysql write has occured.
• If the mysql service is ever restarted/stopped or the server rebooted (even when btmon is not attempting the write), at the next mysql write cycle, I get the following error, "MySQL server has gone away" and no data is ever again written to MySQL even though btmon continues to collect data.

Questions:

• Since the buffer info never decrements, what happens when btmon reaches the buffer-size (even though it may have been successfully writing the data out to the db every minute)?
• Why does btmon not attempt to reconnect to MySQL, I thought that was the whole point of the buffer?

Here are is the output of the --debug immediately following the successful "service mysql restart" on the remote server:

Code: Select all

2013/12/09 11:42:30 SERIAL: waiting for data
2013/12/09 11:42:30 reading 1 of 1 packets
2013/12/09 11:42:31 buffering packet ts:1386618151 sn:404774
2013/12/09 11:42:31 buffer info:
2013/12/09 11:42:31   404774: 175 of 2592000 (1386618151)
2013/12/09 11:42:31 processing with MySQLProcessor
2013/12/09 11:42:31 waiting 7 seconds to process packets for 404774
2013/12/09 11:42:31 SERIAL: waiting for data
2013/12/09 11:42:31 reading 1 of 1 packets
2013/12/09 11:42:32 buffering packet ts:1386618152 sn:404774
2013/12/09 11:42:32 buffer info:
2013/12/09 11:42:32   404774: 176 of 2592000 (1386618152)
2013/12/09 11:42:32 processing with MySQLProcessor
2013/12/09 11:42:32 waiting 6 seconds to process packets for 404774
2013/12/09 11:42:32 SERIAL: waiting for data
2013/12/09 11:42:32 reading 1 of 1 packets
2013/12/09 11:42:33 buffering packet ts:1386618153 sn:404774
2013/12/09 11:42:33 buffer info:
2013/12/09 11:42:33   404774: 177 of 2592000 (1386618153)
2013/12/09 11:42:33 processing with MySQLProcessor
2013/12/09 11:42:33 waiting 5 seconds to process packets for 404774
2013/12/09 11:42:33 SERIAL: waiting for data
2013/12/09 11:42:33 reading 1 of 1 packets
2013/12/09 11:42:34 buffering packet ts:1386618154 sn:404774
2013/12/09 11:42:34 buffer info:
2013/12/09 11:42:34   404774: 178 of 2592000 (1386618154)
2013/12/09 11:42:34 processing with MySQLProcessor
2013/12/09 11:42:34 waiting 4 seconds to process packets for 404774
2013/12/09 11:42:34 SERIAL: waiting for data
2013/12/09 11:42:34 reading 1 of 1 packets
2013/12/09 11:42:35 buffering packet ts:1386618155 sn:404774
2013/12/09 11:42:35 buffer info:
2013/12/09 11:42:35   404774: 179 of 2592000 (1386618155)
2013/12/09 11:42:35 processing with MySQLProcessor
2013/12/09 11:42:35 waiting 3 seconds to process packets for 404774
2013/12/09 11:42:35 SERIAL: waiting for data
2013/12/09 11:42:35 reading 1 of 1 packets
2013/12/09 11:42:36 buffering packet ts:1386618156 sn:404774
2013/12/09 11:42:36 buffer info:
2013/12/09 11:42:36   404774: 180 of 2592000 (1386618156)
2013/12/09 11:42:36 processing with MySQLProcessor
2013/12/09 11:42:36 waiting 2 seconds to process packets for 404774
2013/12/09 11:42:36 SERIAL: waiting for data
2013/12/09 11:42:36 reading 1 of 1 packets
2013/12/09 11:42:37 buffering packet ts:1386618157 sn:404774
2013/12/09 11:42:37 buffer info:
2013/12/09 11:42:37   404774: 181 of 2592000 (1386618157)
2013/12/09 11:42:37 processing with MySQLProcessor
2013/12/09 11:42:37 waiting 1 seconds to process packets for 404774
2013/12/09 11:42:37 SERIAL: waiting for data
2013/12/09 11:42:37 reading 1 of 1 packets
2013/12/09 11:42:38 buffering packet ts:1386618158 sn:404774
2013/12/09 11:42:38 buffer info:
2013/12/09 11:42:38   404774: 182 of 2592000 (1386618158)
2013/12/09 11:42:38 processing with MySQLProcessor
2013/12/09 11:42:38 61 buffered packets sn:404774
2013/12/09 11:42:38 60 calculated packets sn:404774
2013/12/09 11:42:38 DB: query: INSERT INTO ecm.ecm1240bin_counters (time_created,serial,secs,volts,ch1_a,ch2_a,ch1_aws,ch2_aws,ch1_pws,
ch2_pws,aux1_ws,aux2_ws,aux3_ws,aux4_ws,aux5_ws,aux5_volts) VALUES (1386618099,'404774',173706,118.1,15.7,0.58,67201859,168494,9535
,21831,50,175,276,117,6564,510)
2013/12/09 11:42:38 Exception in MySQLProcessor: (2006, 'MySQL server has gone away')
Traceback (most recent call last):
  File "/home/ecm1240/btmon/btmon.py", line 1986, in process
    p.process_compiled(self.packet_collector.packet_buffer)
  File "/home/ecm1240/btmon/btmon.py", line 2556, in process_compiled
    self.process_calculated(packets)
  File "/home/ecm1240/btmon/btmon.py", line 2605, in process_calculated
    cursor.execute(''.join(sql))
  File "/usr/lib/python2.7/dist-packages/MySQLdb/cursors.py", line 174, in execute
    self.errorhandler(self, exc, value)
  File "/usr/lib/python2.7/dist-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
    raise errorclass, errorvalue
OperationalError: (2006, 'MySQL server has gone away')
2013/12/09 11:42:38 SERIAL: waiting for data
2013/12/09 11:42:38 reading 1 of 1 packets
2013/12/09 11:42:39 buffering packet ts:1386618159 sn:404774
2013/12/09 11:42:39 buffer info:
2013/12/09 11:42:39   404774: 183 of 2592000 (1386618159)
2013/12/09 11:42:39 processing with MySQLProcessor
2013/12/09 11:42:39 waiting 59 seconds to process packets for 404774
2013/12/09 11:42:39 SERIAL: waiting for data
2013/12/09 11:42:39 reading 1 of 1 packets
2013/12/09 11:42:40 buffering packet ts:1386618160 sn:404774
2013/12/09 11:42:40 buffer info:
2013/12/09 11:42:40   404774: 184 of 2592000 (1386618160)
2013/12/09 11:42:40 processing with MySQLProcessor
2013/12/09 11:42:40 waiting 58 seconds to process packets for 404774

[mwall]

Questions:

• Since the buffer info never decrements, what happens when btmon reaches the buffer-size (even though it may have been successfully writing the data out to the db every minute)?
• Why does btmon not attempt to reconnect to MySQL, I thought that was the whole point of the buffer?

it is a rolling buffer - the buffer fills up, then old records simply drop out of the buffer as new records come in.

i'm working on an update to btmon that connects to the mysql server for each upload instead of maintaining an open connection (this has been implemented for the rtmon, edsmon, and tedmon tools but i have a bit more testing before the btmon changes are ready).

you should be able to specify a much smaller buffer. the buffer size is measure in packets. the size of each packet depends on the device you are monitoring and the packet type you are collecting. it is also be affected by the number of channels on the device. i typically set the buffer size to a multiple of the number of packets in each upload (1.5x for low memory systems, or something like 5x to 10x for more memory). for example, if the device samples every 10 seconds and uploads happen nominally every 900 seconds, then a buffer size of 120 provides space for 5 minutes (300s) of samples beyond a single missed upload.

apologies to all for taking so long to get this update to btmon out the door.

m

[n8vjp]

Wow, thanks for the near instant response! I eagerly look forward to the update to btmon mysql connections.

Regarding buffer-size...
I have 1 packet per second coming from the ECM and and no local storage on the device running btmon. Although way overkill, I want up to 30 days of data to be buffered on the collector in case the MySQL server is offline for an extended period.

30 days * 24 hours/day * 60 minutes /hour * 60 seconds/minute * 1 packet/second = 2592000 packets.

How could the buffer be smaller? How much RAM do you expect my 2.6 million packet buffer to consume when all 7 channels of the ECM are in use (16 fields/packet) ? My test setup has only CH1 connected to a set of CTs and with 5223 samples in the database and a summed size of 397830 bytes (doing a sum of all the char_length(s)), that is just under 80 bytes per packet. Is that realistic? That would mean a 30 day buffer might consume 200MB of RAM, or am I looking at this wrong?

[mwall]

btmon 3.0.7 is finally out. the biggest change is that a new connection is established for each upload to mysql database. this makes btmon much more robust when the network is flaky or the server is not always available.

http://lancet.mit.edu/mwall/projects/power

m