mycontroller snapshot 22.08.2016 - unresponsive -> errorlog

cimba007 commented 8 years ago

Running the latest snapshot I got some random errors ..

The interface is very unresponsive (up to 5seconds before a page loads) .. my raspberry pi just got freshly installed so there should be very little that should be wrong with the hardware.

jkandasa commented 8 years ago

@cimba007 Thanks to report this error. Looks like my recent change on database ormlite version break this. We will check it. I have reverted to old version(database - ormlite). https://github.com/mycontroller-org/mycontroller-parent-pom/commit/ba4839a110e49916432aa856cebfc5c7d2ef0026

Also I have introduces DB_MAX_FREE_CONNECTION, But i didn't remove that. we will check with database ormlite version. If still face the same issue, we can remove this change too. https://github.com/mycontroller-org/mycontroller/commit/76a59bfa7568077c8c5d7f2703688b29c90d1866

You can download latest version from google drive

cimba007 commented 8 years ago

Thanks, I will try out the snapshot at once!

Edit: Updated to latest snapshot. No issues so far. I will test it further the next few days.

cimba007 commented 8 years ago

Sometimes browsing the mycontroller page becomes still unresponsive .. Could it be that exception/warning handling takes a lot of time and thus make messages "queue" up? When queued messages are processed they gare processed too fast resulting in time stamp collision? just a wild guess.

Also CPU load is a little bit high:

19059 pi 20 0 253384 125836 10880 S 146.4 13.3 10:35.25 java

146% (peak) on my raspberry pi 2 quadcore

2016-08-25 00:51:59,043 ERROR [Thread-13741] [org.mycontroller.standalone.db.dao.BaseAbstractDaoImpl:187] unable to add new item:[MetricsDoubleTypeDevice(sensorVariable=SensorVariable(id=2, sensor=Sensor(id=2, sensorId=0, type=S_MOTION, name=, lastSeen=1472079115687, node=Node(id=2, eui=20, gatewayTable=GatewayTable(id=1, enabled=true, name=mosquitto, networkType=MY_SENSORS, timestamp=1472065324018, state=UP, statusMessage=Connected Successfully, statusSince=1472078288689, type=MQTT, properties={p=, u=, bh=tcp://localhost:1883, tp=mygateway-in, cid=mycontroller_mqtt_client, ts=mygateway-out}), name=MicrowaveTest, version=Aug 25 2016 | 00:51:10, type=S_ARDUINO_NODE, libVersion=2.0.0, batteryLevel=null, eraseConfig=null, firmware=null, state=UP, lastSeen=1472079104913, rssi=52|52|0|52, properties={}, parentNodeEui=0, registrationState=REGISTERED), room=null, variableTypes=[Variable 1, Variable 2]), variableType=V_VAR1, metricType=DOUBLE, timestamp=1472079118275, value=16.13, previousValue=220.28, unitType=U_NONE, readOnly=false, offset=0.0, priority=100, graphProperties={color=#ff7f0e, interpolate=linear, subType=line, useGlobal=true, type=lineChart}), timestamp=1472079118275, samples=1, min=16.13, max=16.13, avg=16.13, aggregationType=RAW, timestampFrom=null, timestampTo=null)]
java.sql.SQLException: Unable to run insert stmt on object MetricsDoubleTypeDevice(sensorVariable=SensorVariable(id=2, sensor=Sensor(id=2, sensorId=0, type=S_MOTION, name=, lastSeen=1472079115687, node=Node(id=2, eui=20, gatewayTable=GatewayTable(id=1, enabled=true, name=mosquitto, networkType=MY_SENSORS, timestamp=1472065324018, state=UP, statusMessage=Connected Successfully, statusSince=1472078288689, type=MQTT, properties={p=, u=, bh=tcp://localhost:1883, tp=mygateway-in, cid=mycontroller_mqtt_client, ts=mygateway-out}), name=MicrowaveTest, version=Aug 25 2016 | 00:51:10, type=S_ARDUINO_NODE, libVersion=2.0.0, batteryLevel=null, eraseConfig=null, firmware=null, state=UP, lastSeen=1472079104913, rssi=52|52|0|52, properties={}, parentNodeEui=0, registrationState=REGISTERED), room=null, variableTypes=[Variable 1, Variable 2]), variableType=V_VAR1, metricType=DOUBLE, timestamp=1472079118275, value=16.13, previousValue=220.28, unitType=U_NONE, readOnly=false, offset=0.0, priority=100, graphProperties={color=#ff7f0e, interpolate=linear, subType=line, useGlobal=true, type=lineChart}), timestamp=1472079118275, samples=1, min=16.13, max=16.13, avg=16.13, aggregationType=RAW, timestampFrom=null, timestampTo=null): INSERT INTO `metrics_double_type_device` (`sensorVariableId` ,`timestamp` ,`samples` ,`min` ,`max` ,`avg` ,`aggregationType` ) VALUES (?,?,?,?,?,?,?)
    at com.j256.ormlite.misc.SqlExceptionUtil.create(SqlExceptionUtil.java:22)
    at com.j256.ormlite.stmt.mapped.MappedCreate.insert(MappedCreate.java:135)
    at com.j256.ormlite.stmt.StatementExecutor.create(StatementExecutor.java:450)
    at com.j256.ormlite.dao.BaseDaoImpl.create(BaseDaoImpl.java:310)
    at org.mycontroller.standalone.db.dao.BaseAbstractDaoImpl.create(BaseAbstractDaoImpl.java:184)
    at org.mycontroller.standalone.message.McMessageEngine.recordSetTypeData(McMessageEngine.java:847)
    at org.mycontroller.standalone.message.McMessageEngine.execute(McMessageEngine.java:116)
    at org.mycontroller.standalone.message.McMessageEngine.run(McMessageEngine.java:973)
    at java.lang.Thread.run(Thread.java:745)
Caused by: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "CONSTRAINT_INDEX_4B ON PUBLIC.METRICS_DOUBLE_TYPE_DEVICE(SENSORVARIABLEID, TIMESTAMP, AGGREGATIONTYPE) VALUES ( /* key:63052 */ 2, 1472079118275, null, null, null, null, 0)"; SQL statement:
INSERT INTO `metrics_double_type_device` (`sensorVariableId` ,`timestamp` ,`samples` ,`min` ,`max` ,`avg` ,`aggregationType` ) VALUES (?,?,?,?,?,?,?) [23505-176]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:344)
    at org.h2.message.DbException.get(DbException.java:178)
    at org.h2.message.DbException.get(DbException.java:154)
    at org.h2.index.BaseIndex.getDuplicateKeyException(BaseIndex.java:103)
    at org.h2.index.PageBtree.find(PageBtree.java:121)
    at org.h2.index.PageBtreeLeaf.addRow(PageBtreeLeaf.java:151)
    at org.h2.index.PageBtreeLeaf.addRowTry(PageBtreeLeaf.java:104)
    at org.h2.index.PageBtreeNode.addRowTry(PageBtreeNode.java:206)
    at org.h2.index.PageBtreeNode.addRowTry(PageBtreeNode.java:206)
    at org.h2.index.PageBtreeIndex.addRow(PageBtreeIndex.java:97)
    at org.h2.index.PageBtreeIndex.add(PageBtreeIndex.java:88)
    at org.h2.table.RegularTable.addRow(RegularTable.java:120)
    at org.h2.command.dml.Insert.insertRows(Insert.java:157)
    at org.h2.command.dml.Insert.update(Insert.java:115)
    at org.h2.command.CommandContainer.update(CommandContainer.java:79)
    at org.h2.command.Command.executeUpdate(Command.java:254)
    at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:158)
    at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:144)
    at com.j256.ormlite.jdbc.JdbcDatabaseConnection.insert(JdbcDatabaseConnection.java:170)
    at com.j256.ormlite.stmt.mapped.MappedCreate.insert(MappedCreate.java:91)
    ... 7 common frames omitted
2016-08-25 00:52:06,487 WARN [Thread-13960] [org.mycontroller.standalone.message.McMessageEngine:417] Internal Message[type:I_RSSI,payload:10002|10002|0|2], This type may not be supported (or) not implemented yet
2016-08-25 00:52:14,591 WARN [Thread-14112] [org.mycontroller.standalone.message.McMessageEngine:417] Internal Message[type:I_RSSI,payload:10052|10052|0|52], This type may not be supported (or) not implemented yet
2016-08-25 00:52:22,849 WARN [Thread-14261] [org.mycontroller.standalone.message.McMessageEngine:417] Internal Message[type:I_RSSI,payload:10102|10102|0|102], This type may not be supported (or) not implemented yet
2016-08-25 00:52:34,781 WARN [Thread-14285] [org.mycontroller.standalone.message.McMessageEngine:417] Internal Message[type:I_RSSI,payload:10002|10002|10000|], This type may not be supported (or) not implemented yet
2016-08-25 00:52:42,927 WARN [Thread-14441] [org.mycontroller.standalone.message.McMessageEngine:417] Internal Message[type:I_RSSI,payload:100%|100%], This type may not be supported (or) not implemented yet
2016-08-25 00:52:56,616 WARN [Thread-14519] [org.mycontroller.standalone.message.McMessageEngine:417] Internal Message[type:I_RSSI,payload:100%|100%], This type may not be supported (or) not implemented yet
2016-08-25 00:53:00,273 WARN [Thread-14588] [org.mycontroller.standalone.message.McMessageEngine:417] Internal Message[type:I_RSSI,payload:100%|100%], This type may not be supported (or) not implemented yet
2016-08-25 00:53:00,747 ERROR [Thread-14523] [org.mycontroller.standalone.db.dao.BaseAbstractDaoImpl:187] unable to add new item:[MetricsDoubleTypeDevice(sensorVariable=SensorVariable(id=3, sensor=Sensor(id=2, sensorId=0, type=S_MOTION, name=, lastSeen=1472079176717, node=Node(id=2, eui=20, gatewayTable=GatewayTable(id=1, enabled=true, name=mosquitto, networkType=MY_SENSORS, timestamp=1472065324018, state=UP, statusMessage=Connected Successfully, statusSince=1472078288689, type=MQTT, properties={p=, u=, bh=tcp://localhost:1883, tp=mygateway-in, cid=mycontroller_mqtt_client, ts=mygateway-out}), name=MicrowaveTest, version=Aug 25 2016 | 00:52:22, type=S_ARDUINO_NODE, libVersion=2.0.0, batteryLevel=null, eraseConfig=null, firmware=null, state=UP, lastSeen=1472079174284, rssi=100%|100%, properties={}, parentNodeEui=0, registrationState=REGISTERED), room=null, variableTypes=[Variable 1, Variable 2]), variableType=V_VAR2, metricType=DOUBLE, timestamp=1472079176762, value=1.0, previousValue=4.0, unitType=U_NONE, readOnly=false, offset=0.0, priority=100, graphProperties={color=#ff7f0e, interpolate=linear, subType=line, useGlobal=true, type=lineChart}), timestamp=1472079176762, samples=1, min=1.0, max=1.0, avg=1.0, aggregationType=RAW, timestampFrom=null, timestampTo=null)]
java.sql.SQLException: Unable to run insert stmt on object MetricsDoubleTypeDevice(sensorVariable=SensorVariable(id=3, sensor=Sensor(id=2, sensorId=0, type=S_MOTION, name=, lastSeen=1472079176717, node=Node(id=2, eui=20, gatewayTable=GatewayTable(id=1, enabled=true, name=mosquitto, networkType=MY_SENSORS, timestamp=1472065324018, state=UP, statusMessage=Connected Successfully, statusSince=1472078288689, type=MQTT, properties={p=, u=, bh=tcp://localhost:1883, tp=mygateway-in, cid=mycontroller_mqtt_client, ts=mygateway-out}), name=MicrowaveTest, version=Aug 25 2016 | 00:52:22, type=S_ARDUINO_NODE, libVersion=2.0.0, batteryLevel=null, eraseConfig=null, firmware=null, state=UP, lastSeen=1472079174284, rssi=100%|100%, properties={}, parentNodeEui=0, registrationState=REGISTERED), room=null, variableTypes=[Variable 1, Variable 2]), variableType=V_VAR2, metricType=DOUBLE, timestamp=1472079176762, value=1.0, previousValue=4.0, unitType=U_NONE, readOnly=false, offset=0.0, priority=100, graphProperties={color=#ff7f0e, interpolate=linear, subType=line, useGlobal=true, type=lineChart}), timestamp=1472079176762, samples=1, min=1.0, max=1.0, avg=1.0, aggregationType=RAW, timestampFrom=null, timestampTo=null): INSERT INTO `metrics_double_type_device` (`sensorVariableId` ,`timestamp` ,`samples` ,`min` ,`max` ,`avg` ,`aggregationType` ) VALUES (?,?,?,?,?,?,?)
    at com.j256.ormlite.misc.SqlExceptionUtil.create(SqlExceptionUtil.java:22)
    at com.j256.ormlite.stmt.mapped.MappedCreate.insert(MappedCreate.java:135)
    at com.j256.ormlite.stmt.StatementExecutor.create(StatementExecutor.java:450)
    at com.j256.ormlite.dao.BaseDaoImpl.create(BaseDaoImpl.java:310)
    at org.mycontroller.standalone.db.dao.BaseAbstractDaoImpl.create(BaseAbstractDaoImpl.java:184)
    at org.mycontroller.standalone.message.McMessageEngine.recordSetTypeData(McMessageEngine.java:847)
    at org.mycontroller.standalone.message.McMessageEngine.execute(McMessageEngine.java:116)
    at org.mycontroller.standalone.message.McMessageEngine.run(McMessageEngine.java:973)
    at java.lang.Thread.run(Thread.java:745)
Caused by: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "CONSTRAINT_INDEX_4B ON PUBLIC.METRICS_DOUBLE_TYPE_DEVICE(SENSORVARIABLEID, TIMESTAMP, AGGREGATIONTYPE) VALUES ( /* key:63298 */ 3, 1472079176762, null, null, null, null, 0)"; SQL statement:
INSERT INTO `metrics_double_type_device` (`sensorVariableId` ,`timestamp` ,`samples` ,`min` ,`max` ,`avg` ,`aggregationType` ) VALUES (?,?,?,?,?,?,?) [23505-176]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:344)
    at org.h2.message.DbException.get(DbException.java:178)
    at org.h2.message.DbException.get(DbException.java:154)
    at org.h2.index.BaseIndex.getDuplicateKeyException(BaseIndex.java:103)
    at org.h2.index.PageBtree.find(PageBtree.java:121)
    at org.h2.index.PageBtreeLeaf.addRow(PageBtreeLeaf.java:151)
    at org.h2.index.PageBtreeLeaf.addRowTry(PageBtreeLeaf.java:104)
    at org.h2.index.PageBtreeNode.addRowTry(PageBtreeNode.java:206)
    at org.h2.index.PageBtreeNode.addRowTry(PageBtreeNode.java:206)
    at org.h2.index.PageBtreeIndex.addRow(PageBtreeIndex.java:97)
    at org.h2.index.PageBtreeIndex.add(PageBtreeIndex.java:88)
    at org.h2.table.RegularTable.addRow(RegularTable.java:120)
    at org.h2.command.dml.Insert.insertRows(Insert.java:157)
    at org.h2.command.dml.Insert.update(Insert.java:115)
    at org.h2.command.CommandContainer.update(CommandContainer.java:79)
    at org.h2.command.Command.executeUpdate(Command.java:254)
    at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:158)
    at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:144)
    at com.j256.ormlite.jdbc.JdbcDatabaseConnection.insert(JdbcDatabaseConnection.java:170)
    at com.j256.ormlite.stmt.mapped.MappedCreate.insert(MappedCreate.java:91)
    ... 7 common frames omitted
2016-08-25 00:53:07,985 WARN [Thread-14900] [org.mycontroller.standalone.message.McMessageEngine:417] Internal Message[type:I_RSSI,payload:100%|100%], This type may not be supported (or) not implemented yet
2016-08-25 00:53:16,362 WARN [Thread-15058] [org.mycontroller.standalone.message.McMessageEngine:417] Internal Message[type:I_RSSI,payload:100%|100%], This type may not be supported (or) not implemented yet
2016-08-25 00:53:24,752 WARN [Thread-15214] [org.mycontroller.standalone.message.McMessageEngine:417] Internal Message[type:I_RSSI,payload:100%|100%], This type may not be supported (or) not implemented yet
2016-08-25 00:53:33,139 WARN [Thread-15369] [org.mycontroller.standalone.message.McMessageEngine:417] Internal Message[type:I_RSSI,payload:100%|100%], This type may not be supported (or) not implemented yet
2016-08-25 00:53:41,552 WARN [Thread-15525] [org.mycontroller.standalone.message.McMessageEngine:417] Internal Message[type:I_RSSI,payload:100%|100%], This type may not be supported (or) not implemented yet
2016-08-25 00:53:58,522 WARN [Thread-15550] [org.mycontroller.standalone.message.McMessageEngine:417] Internal Message[type:I_RSSI,payload:2|2|0|2], This type may not be supported (or) not implemented yet
2016-08-25 00:53:59,758 ERROR [Thread-15578] [org.mycontroller.standalone.db.dao.BaseAbstractDaoImpl:187] unable to add new item:[MetricsDoubleTypeDevice(sensorVariable=SensorVariable(id=2, sensor=Sensor(id=2, sensorId=0, type=S_MOTION, name=, lastSeen=1472079238564, node=Node(id=2, eui=20, gatewayTable=GatewayTable(id=1, enabled=true, name=mosquitto, networkType=MY_SENSORS, timestamp=1472065324018, state=UP, statusMessage=Connected Successfully, statusSince=1472078288689, type=MQTT, properties={p=, u=, bh=tcp://localhost:1883, tp=mygateway-in, cid=mycontroller_mqtt_client, ts=mygateway-out}), name=MicrowaveTest, version=Aug 25 2016 | 00:52:22, type=S_ARDUINO_NODE, libVersion=2.0.0, batteryLevel=null, eraseConfig=null, firmware=null, state=UP, lastSeen=1472079238406, rssi=2|2|0|2, properties={}, parentNodeEui=0, registrationState=REGISTERED), room=null, variableTypes=[Variable 1, Variable 2]), variableType=V_VAR1, metricType=DOUBLE, timestamp=1472079239476, value=3.41, previousValue=3.4, unitType=U_NONE, readOnly=false, offset=0.0, priority=100, graphProperties={color=#ff7f0e, interpolate=linear, subType=line, useGlobal=true, type=lineChart}), timestamp=1472079239476, samples=1, min=3.41, max=3.41, avg=3.41, aggregationType=RAW, timestampFrom=null, timestampTo=null)]
java.sql.SQLException: Unable to run insert stmt on object MetricsDoubleTypeDevice(sensorVariable=SensorVariable(id=2, sensor=Sensor(id=2, sensorId=0, type=S_MOTION, name=, lastSeen=1472079238564, node=Node(id=2, eui=20, gatewayTable=GatewayTable(id=1, enabled=true, name=mosquitto, networkType=MY_SENSORS, timestamp=1472065324018, state=UP, statusMessage=Connected Successfully, statusSince=1472078288689, type=MQTT, properties={p=, u=, bh=tcp://localhost:1883, tp=mygateway-in, cid=mycontroller_mqtt_client, ts=mygateway-out}), name=MicrowaveTest, version=Aug 25 2016 | 00:52:22, type=S_ARDUINO_NODE, libVersion=2.0.0, batteryLevel=null, eraseConfig=null, firmware=null, state=UP, lastSeen=1472079238406, rssi=2|2|0|2, properties={}, parentNodeEui=0, registrationState=REGISTERED), room=null, variableTypes=[Variable 1, Variable 2]), variableType=V_VAR1, metricType=DOUBLE, timestamp=1472079239476, value=3.41, previousValue=3.4, unitType=U_NONE, readOnly=false, offset=0.0, priority=100, graphProperties={color=#ff7f0e, interpolate=linear, subType=line, useGlobal=true, type=lineChart}), timestamp=1472079239476, samples=1, min=3.41, max=3.41, avg=3.41, aggregationType=RAW, timestampFrom=null, timestampTo=null): INSERT INTO `metrics_double_type_device` (`sensorVariableId` ,`timestamp` ,`samples` ,`min` ,`max` ,`avg` ,`aggregationType` ) VALUES (?,?,?,?,?,?,?)
    at com.j256.ormlite.misc.SqlExceptionUtil.create(SqlExceptionUtil.java:22)
    at com.j256.ormlite.stmt.mapped.MappedCreate.insert(MappedCreate.java:135)
    at com.j256.ormlite.stmt.StatementExecutor.create(StatementExecutor.java:450)
    at com.j256.ormlite.dao.BaseDaoImpl.create(BaseDaoImpl.java:310)
    at org.mycontroller.standalone.db.dao.BaseAbstractDaoImpl.create(BaseAbstractDaoImpl.java:184)
    at org.mycontroller.standalone.message.McMessageEngine.recordSetTypeData(McMessageEngine.java:847)
    at org.mycontroller.standalone.message.McMessageEngine.execute(McMessageEngine.java:116)
    at org.mycontroller.standalone.message.McMessageEngine.run(McMessageEngine.java:973)
    at java.lang.Thread.run(Thread.java:745)
Caused by: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "CONSTRAINT_INDEX_4B ON PUBLIC.METRICS_DOUBLE_TYPE_DEVICE(SENSORVARIABLEID, TIMESTAMP, AGGREGATIONTYPE) VALUES ( /* key:63641 */ 2, 1472079239476, null, null, null, null, 0)"; SQL statement:
INSERT INTO `metrics_double_type_device` (`sensorVariableId` ,`timestamp` ,`samples` ,`min` ,`max` ,`avg` ,`aggregationType` ) VALUES (?,?,?,?,?,?,?) [23505-176]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:344)
    at org.h2.message.DbException.get(DbException.java:178)
    at org.h2.message.DbException.get(DbException.java:154)
    at org.h2.index.BaseIndex.getDuplicateKeyException(BaseIndex.java:103)
    at org.h2.index.PageBtree.find(PageBtree.java:121)
    at org.h2.index.PageBtreeLeaf.addRow(PageBtreeLeaf.java:151)
    at org.h2.index.PageBtreeLeaf.addRowTry(PageBtreeLeaf.java:104)
    at org.h2.index.PageBtreeNode.addRowTry(PageBtreeNode.java:206)
    at org.h2.index.PageBtreeNode.addRowTry(PageBtreeNode.java:206)
    at org.h2.index.PageBtreeIndex.addRow(PageBtreeIndex.java:97)
    at org.h2.index.PageBtreeIndex.add(PageBtreeIndex.java:88)
    at org.h2.table.RegularTable.addRow(RegularTable.java:120)
    at org.h2.command.dml.Insert.insertRows(Insert.java:157)
    at org.h2.command.dml.Insert.update(Insert.java:115)
    at org.h2.command.CommandContainer.update(CommandContainer.java:79)
    at org.h2.command.Command.executeUpdate(Command.java:254)
    at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:158)
    at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:144)
    at com.j256.ormlite.jdbc.JdbcDatabaseConnection.insert(JdbcDatabaseConnection.java:170)
    at com.j256.ormlite.stmt.mapped.MappedCreate.insert(MappedCreate.java:91)
    ... 7 common frames omitted

jkandasa commented 8 years ago

@cimba007 how many nodes/sensors are you using and what is the gateway are you using? Can you enable debug log for the following components? mycontroller/conf/logback.xml

<logger level="DEBUG" name="org.mycontroller.standalone.message" />
<logger level="DEBUG" name="org.mycontroller.standalone.mysensors" />

and post the mycontroller.log. Thank you!

cimba007 commented 8 years ago

I am currently running 2 nodes. The one node only sends data very sparse, i would guess only once every 10 seconds.

My second node is an microwave motion sensor I am building and currently very frequently sending messages. I would say every 200ms. Ofc. this will result in lots of messages (15.000 per hour?) Is this too much? I thought that 1ghz quadcore with 1gb ram would be enough to process like 5 messages per second.

I will enable debug log, clear my logfile and have a look if I can find anything new ..

Normal load is this:

19059 pi        20   0  255432 129628  10880 S  23.1 13.7 353:26.98 java

Only spikes and becomes unresponsive from time to time. I will try to evaluate 0.0.3alpha2 to try to compare this version with the current snapshot.

cimba007 commented 8 years ago

please rename to "*.zip" .. although github says that it supports ZIP it somehow does not

logfiles.zip.pdf

jkandasa commented 8 years ago

@cimba007 Thank you for the log. Looks like you do not face issue when debug mode is enabled. I believe due to System.currentTimeMillis() accuracy, we are facing this issue. I will find out a solution.

cimba007 commented 8 years ago

Still the website seems unresponsive and the cpu load is high? Somestimes 250% (top). Is this normal?

jkandasa commented 8 years ago

@cimba007 No, this is not normal. I never face issue like this. We have to find out the root cause.

jkandasa commented 8 years ago

@cimba007 can you check on your PRI, does MyController eats all the resource? or someone else there?

cimba007 commented 8 years ago

What can I do to track it down?

I double checked my code and I am sure my node sends 2 messages every 300ms-500ms .. having a closer look athe the debug output:

It seems the values are added multiple times to the queue? (line 17-25) Im addition to the processing time of 22ms per message with only 300/2 = 150ms between messages might there be some congestion?

Queue size:2584, suggests there are quite a lot meesage which do not get processed (or added multiple times)

2016-08-25 19:05:47,278 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=62, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,278 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:19, Message:[RawMessage(gatewayId=1, data=3.46, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,280 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:20, Message:[RawMessage(gatewayId=1, data=3.46, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,280 DEBUG [Thread-1137449] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 2, acknowledge=true, payload=62, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747280)
2016-08-25 19:05:47,281 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:21, Message:[RawMessage(gatewayId=1, data=3.46, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,282 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:22, Message:[RawMessage(gatewayId=1, data=46, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,283 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:23, Message:[RawMessage(gatewayId=1, data=17.52, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,283 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:24, Message:[RawMessage(gatewayId=1, data=17.52, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,284 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:25, Message:[RawMessage(gatewayId=1, data=51, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,284 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:26, Message:[RawMessage(gatewayId=1, data=14.28, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,285 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:27, Message:[RawMessage(gatewayId=1, data=53, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,286 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:28, Message:[RawMessage(gatewayId=1, data=53, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,286 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:29, Message:[RawMessage(gatewayId=1, data=53, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,287 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:30, Message:[RawMessage(gatewayId=1, data=53, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,287 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:31, Message:[RawMessage(gatewayId=1, data=53, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,288 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:32, Message:[RawMessage(gatewayId=1, data=53, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,288 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:33, Message:[RawMessage(gatewayId=1, data=2.92, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,289 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:34, Message:[RawMessage(gatewayId=1, data=2.92, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,290 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:35, Message:[RawMessage(gatewayId=1, data=2.92, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,290 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:36, Message:[RawMessage(gatewayId=1, data=2.92, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,291 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:37, Message:[RawMessage(gatewayId=1, data=2.92, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,291 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:38, Message:[RawMessage(gatewayId=1, data=2.92, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,292 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:39, Message:[RawMessage(gatewayId=1, data=2.92, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,292 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:40, Message:[RawMessage(gatewayId=1, data=2.92, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,293 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:41, Message:[RawMessage(gatewayId=1, data=2.92, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,293 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:42, Message:[RawMessage(gatewayId=1, data=44, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,294 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:43, Message:[RawMessage(gatewayId=1, data=44, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,294 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:44, Message:[RawMessage(gatewayId=1, data=44, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,294 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:45, Message:[RawMessage(gatewayId=1, data=44, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,301 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:44, Message:[RawMessage(gatewayId=1, data=62, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,302 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=62, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,303 DEBUG [Thread-1137450] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 2, acknowledge=true, payload=62, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747303)
2016-08-25 19:05:47,323 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:43, Message:[RawMessage(gatewayId=1, data=62, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,324 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=62, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,325 DEBUG [Thread-1137451] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 2, acknowledge=true, payload=62, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747325)
2016-08-25 19:05:47,345 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:42, Message:[RawMessage(gatewayId=1, data=62, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,346 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=62, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,347 DEBUG [Thread-1137452] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 2, acknowledge=true, payload=62, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747348)
2016-08-25 19:05:47,367 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:41, Message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,368 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,370 DEBUG [Thread-1137453] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 1, acknowledge=true, payload=4.21, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747370)
2016-08-25 19:05:47,387 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:42, Message:[RawMessage(gatewayId=1, data=5.20, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,390 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:41, Message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,390 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,392 DEBUG [Thread-1137454] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 1, acknowledge=true, payload=4.21, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747392)
2016-08-25 19:05:47,403 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:42, Message:[RawMessage(gatewayId=1, data=5.20, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,412 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:41, Message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,412 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,414 DEBUG [Thread-1137455] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 1, acknowledge=true, payload=4.21, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747414)
2016-08-25 19:05:47,422 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:42, Message:[RawMessage(gatewayId=1, data=5.20, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,434 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:41, Message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,434 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,434 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:42, Message:[RawMessage(gatewayId=1, data=5.20, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,436 DEBUG [Thread-1137456] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 1, acknowledge=true, payload=4.21, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747436)
2016-08-25 19:05:47,452 DEBUG [MQTT Call: mycontroller_mqtt_client] [org.mycontroller.standalone.message.RawMessageQueue:51] Added new message, Queue size:43, Message:[RawMessage(gatewayId=1, data=39, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,456 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:42, Message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,456 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,458 DEBUG [Thread-1137457] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 1, acknowledge=true, payload=4.21, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747458)
2016-08-25 19:05:47,478 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:41, Message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,479 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,480 DEBUG [Thread-1137458] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 1, acknowledge=true, payload=4.21, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747480)
2016-08-25 19:05:47,500 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:40, Message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,501 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,502 DEBUG [Thread-1137459] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 1, acknowledge=true, payload=4.21, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747502)
2016-08-25 19:05:47,522 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:39, Message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,523 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,524 DEBUG [Thread-1137460] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 1, acknowledge=true, payload=4.21, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747524)
2016-08-25 19:05:47,544 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:38, Message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,545 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,547 DEBUG [Thread-1137461] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 1, acknowledge=true, payload=4.21, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747547)
2016-08-25 19:05:47,567 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:37, Message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,568 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,569 DEBUG [Thread-1137462] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 1, acknowledge=true, payload=4.21, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747569)
2016-08-25 19:05:47,589 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:36, Message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,590 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=4.21, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,591 DEBUG [Thread-1137463] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 1, acknowledge=true, payload=4.21, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747591)
2016-08-25 19:05:47,611 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:35, Message:[RawMessage(gatewayId=1, data=54, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,612 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=54, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,613 DEBUG [Thread-1137464] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 2, acknowledge=true, payload=54, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747613)
2016-08-25 19:05:47,633 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:34, Message:[RawMessage(gatewayId=1, data=54, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,634 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=54, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,636 DEBUG [Thread-1137465] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 2, acknowledge=true, payload=54, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747636)
2016-08-25 19:05:47,656 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:33, Message:[RawMessage(gatewayId=1, data=54, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,656 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=54, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,658 DEBUG [Thread-1137466] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 2, acknowledge=true, payload=54, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747658)
2016-08-25 19:05:47,678 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:32, Message:[RawMessage(gatewayId=1, data=54, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,679 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=54, subData=mygateway-out/20/0/1/0/25, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,680 DEBUG [Thread-1137467] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 2, acknowledge=true, payload=54, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747680)
2016-08-25 19:05:47,700 DEBUG [Thread-4] [org.mycontroller.standalone.message.RawMessageQueue:62] Removed a message, Queue size:31, Message:[RawMessage(gatewayId=1, data=3.46, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,701 DEBUG [Thread-4] [org.mycontroller.standalone.message.MessageMonitorThread:63] Processing message:[RawMessage(gatewayId=1, data=3.46, subData=mygateway-out/20/0/1/0/24, isTxMessage=false, networkType=MY_SENSORS)]
2016-08-25 19:05:47,702 DEBUG [Thread-1137468] [org.mycontroller.standalone.message.McMessageEngine:98] McMessage(gatewayId=1, nodeEui=20, sensorId=0, type=C_SET, subType=Variable 1, acknowledge=true, payload=3.46, isTxMessage=false, networkType=MY_SENSORS, isScreeningDone=true, timestamp=1472144747702)

cimba007 commented 8 years ago

mycontroller (java) is eating quite some resources. load-average is 1.66 .. nothing is running as the rpi is frehsly installed.

I have an idea but I am still investigating .. due to my gateway node fell of the shelf I got a pretty bad reception and many retrys on the sensor side .. maybe there is a reception problem with the ack resulting in the node sending duplicate messages which congest the controller.

cimba007 commented 8 years ago

I rolled back to 0.0.3alpha2 and noticed something similar.

No node sending:

One node sending 2 messages per 300ms ..

I still guess processing the messages takes too long. After I had the reception problem sending too many retries .. resulting in a "flood" of information I guess mycontroller just piled up a long message queue it could not work on fast enough.

This is only one node .. adding more nodes might result in problems even without retries and better reception .. still no guarantee the reception might become bad and having more messages caused by retry.

jkandasa commented 8 years ago

@cimba007 can you try with inbuilt MQTT broker? Inside it's using QOS = 0.

cimba007 commented 8 years ago

ok, i will try with inbuild mqtt brokrer

No big changes so far (0.0.3Alpha2) 6messages per second =

My only explanation so far:

1 Message takes ~23ms to process 6 Messages take ~138ms to process 138ms of 1000ms = 13,8% load which is still a little bit lower as my system load of 22,1% Some overload might come from file

Lowering from 6 messages per second to 2 messages per second lowered the load from 22% to 15%

I think you are already using multiple threads for the webserver/database and mqtt-client and mqtt-broker? If not there might be the risk of congestions on too many messages.

jkandasa commented 8 years ago

@cimba007 Yes, Already everything on multi thread. I will make some changes on logger and log message on db. I will check locally and update you.

Thank you for your great effort!

jkandasa commented 8 years ago

@cimba007 I have added some improvements on performance. For now MyController supports ~48 messages per second on RPI.

I do not face any huge latency on page load. Just now remember that in RPI we should use Oracle JDK NOT Open JDK. With open JDK on RPI MyController works too slowly. You can see here for more details If you are in Open JDK kindly update to Oracle JDK.

I have added support to monitor Message Engine Statistics on dashboard. If you want to configure on dashboard, follow this,

Add new script (JavaScript)

JavaScript Code:

var statistics = mcApi.system().getMessageEngineStatistics();

Template:

<table class="table table-hover table-bordered table-striped" style="width:100%">
  <tr>
    <td>Status on</td>
   <td><span uib-tooltip="{{ ${(statistics.timestamp?c)!"Never"} | date:mchelper.cfg.dateFormat:mchelper.cfg.timezone}}" tooltip-placement="left" am-time-ago="${(statistics.timestamp?c)!"Never"}"></span></td>
  </tr>
  <tr>
    <td>Processing rate last minute</td>
    <td>${(statistics.processingRateLastMinute)!}/m, ${(statistics.processingRateLastMinute/60)?int}/s</td>
  </tr>
  <tr>
    <td>Processing rate average</td>
    <td>${(statistics.processingRateAvgPerMinute)!}/m, ${(statistics.processingRateAvgPerMinute/60)?int}/s</td>
  </tr>
  <tr>
    <td>Processing rate samples</td>
    <td>${(statistics.processingRateSamples)!}</td>
  </tr>
  <tr>
    <td>Processing time last message</td>
    <td>${(statistics.processingTimeLastMessage)!} ms</td>
  </tr>
  <tr>
    <td>Processing time average</td>
    <td>${(statistics.processingTimeAverage)!} ms</td>
  </tr>
  <tr>
  <td>Processing time samples</td>
    <td>${(statistics.processingTimeSamples)!}</td>
  </tr>
  <tr>
    <td>Messages in queue</td>
    <td>${(statistics.messagesInQueue)!}</td>
  </tr>
  <tr>
    <td>Tx message processing delay</td>
    <td>${(statistics.txMessageProcessingDelay)!} ms</td>
  </tr>
</table>

Dashboard widget:

cimba007 commented 8 years ago

Okay .. I did some further testing .. sadly the improvement was not that big as I expected. I tried to narrow down the issue.

First observation: CPU load increases drom 10-20% to 100% or more every minute for 20seconds. This repeats every 60 seconds.

I recorded 2 videos. On the right side you can see CPU utilization graph .. every minutes it goes up .. then down .. then up again. Clicking on the WEB GUI is especialy slow during high utilization and almost every time only the FIRST page load is slow. The delay in the video is 5 seconds .. sometimes up to 10-15seconds (not recorded).

I double checked and I got the JDK installed the same as in this link ( http://forum.mycontroller.org/topic/34/mycontroller-on-raspberry-pi-rpi )

Have a look at the last video first!! There u can see a very long hang up! IN the beginning and at ~1:00

Again .. rename .pdf to .mp4 to play the video.

20160826_221345.mp4.pdf

20160826_220254.mp4.pdf

So to sum up .. the problem is .. every minute there are 20seconds where something is happening that is slowing down my whole raspberry and the mycontroller web interface .. and it is caused by the mycontroller java process.

I also noticed that most of my exceptions happen when the second counter of the systemclock is near 00 .. eg. 23:03:00 or 23:02:00 .. this falls in the middle of the time of each peak which lasts from around e.g. 23:02:50 - 23:03:05

jkandasa commented 8 years ago

From this commit message queue moved to off-heap. Now there is no fixed limit for messages queue. However it is limited as Integer.MAX_VALUE.

https://github.com/mycontroller-org/mycontroller/commit/6cd8da74471e82c7fa04022df5f8c6ffb67e5f21

jkandasa commented 8 years ago

@cimba007 Thank you for the detailed analysis. i can see the issue from your videos. But I could not reproduce in my RPI. Still working on code level for improvements. Thank you for your great time with performance analysis :+1:

cimba007 commented 8 years ago

I will now try a clean installation of mycontroller and observe every step i make and the impact on load spikes:

EVERYTHING VANILLA FROM LATEST SNAPSHOT as of 27.09.2016 19:12 default java vm of latest raspbian image

CPU = max cpu usage noticed over several minutes (without peaks by actively browsing the webpage with the exception of 20seconds refresh intervall of statistics) spikes = 10-15seconds of 100% cpu load or more

fresh installation, updated coordinates and switched from 12 to 24 hours: no spikes, <3% cpu & 8% mem
adding gateway, only gateway publishs V_ARMES every 10 seconds: no spikes, <8% cpu & 8,4% mem
adding statistics dashboard and open it in a 2nd window: <11% cpu, 9,9%mem, i notice some periodes with <2% cpu and some other with 5-10% cpu usage
adding seconds node with very low message rate: <14,7% CPU
increasing message rate of 2nd node by factor ~10: no spikes, 10-24% cpu load all time time, no periodes of low cpu load
increasing 2nd node update rate to the one it was on default: no spikes, CPU load never less then 17%, max peak 35%
increase 2nd node update rate even further: 50-90% cpu, 11% mem, still no spikes

For now I got no performance issues in the form of long periodes of super high cpu load in combination with unresponsive web interface. I will run this setup until tomorrow so the database can pile up some messages. Will check then again.

cimba007 commented 8 years ago

In the latest snapshot the resourcelog is broken?!

jkandasa commented 8 years ago

@cimba007 Great! Thank you! I have checked in my raspberry pi 2 model b performance of MyController. It is able to perform 30~40 messages per second without any delay. I sent 50 messages per second for 2:30 hours. around 30K messages was in queue. I stopped message sending and it takes about 10 minutes to insert queued messages(30K messages). So it looks like in RPI 30~40 messages recommended per second. If it goes more than that it will be processed but with some delay.

In the latest snapshot the resourcelog is broken?!

No I do not see it's broken. Could you please refresh your browser(clear cache)? If you face still please post error log from mycontroller.log

Thank you!

cimba007 commented 8 years ago

Clearing the cache solved the issue with resource log. Thanks!

jkandasa commented 8 years ago

@cimba007

I will run this setup until tomorrow so the database can pile up some messages. Will check then again.

You can always backup your old database and use it for new version. backup and restore supported between SNAPSHOT versions too. In this way you can have countable data immediately.

cimba007 commented 8 years ago

Okay .. I have a short update .. I bombarded mycontroller with 42messages per second for like 30minutes. I now got 132713 items in the database. Even after lowering the rate to ~6messages per seconds I started again to notice spikes.

Every 60 seconds for 10-15seconds.

My only conclusion is that mycontroller performs some kind of task every 60 seconds to aggregate data or something like this and this becomes very slowly and very CPU heavy (at least on my setup).

Having only few messages this process is no big deal but it is taking very long with 130000 messages in the database.

This is just speculation but I am around 20% CPU load and now every 60seconds I got spikes @ 100% again and an unresponsive web gui.

jkandasa commented 8 years ago

@cimba007 can you find out the exact time rage when CPU spikes? Aggregation happening on every 5th second.

cimba007 commented 8 years ago

From my observation the spikes begin every minutes at around 45seconds and last 15seconds. Even in my latest fresh installation with the changes noted before the spikes come again every minute at around 45seconds (+/- 2 seconds). I could even calibrate my clock from this :D

So this "should" be a cron task which is running every 60 seconds but not arbitrary .. it is running 45 seconds after the full minute.

jkandasa commented 8 years ago

@cimba007 Thank you for the info. ResourcesLogs Aggregation Job is running on every 45th second. I will think about this.

cimba007 commented 8 years ago

This might be a very good lead! The ResourceLogs is very big in my case (130.000messages). Maybe every 45second the whole resourcelog is processed and not only the data that changed since the last aggregation?!

Edit: I used the web interface to completely PURGE the ResourceLog .. the spikes are completely gone! And from what I can see the resorucelog is not connected to the actual sensor-data ..

Nevertheless I think the resourcelog is a very important tool for debugging but in my case it brings down my whole mycontroller ;-)

jkandasa commented 8 years ago

@cimba007 You you input and hard-work helped me lot to narrow down the issue. Thank you so much! You are awesome!!

You may change Resources log level to Warning to avoid bulk insertion. (I will findout some other solution for this).

cimba007 commented 8 years ago

I changed the settings and purged the log again to start very clean.

But now it is late, I will have a look tomorrow again ;-)

Thanks for your hard work!! Make mycontroller.org even better is very satisfying

jkandasa commented 8 years ago

@cimba007 I have done some changes on resources logs aggregation and general aggregation and retrieval. Hope with this change we can see some level of performance improvements.

By default resources logs retention will be 60 minutes. If you want to change this level. have a look at,

Thank you!

cimba007 commented 8 years ago

With the introduction of the "Resources logs retention duration" with the default of 60 minutes I experienced no performance issues for 2 weeks. I think this topic can be closed for now. Good job!

mycontroller-org / mycontroller-v1-legacy