Wrong Results for some Persistence Functions with JDBC?

Add-ons Persistence Services
1

Hi,

for a long time I am using db4o as my default persistence service, rrd4j for graphs and MySQL for Data I want to evaluate outside openHAB. A few days ago a discovered, that the JDBC persistence service supports SQLite, a database which I like a lot, mainly for embedded projects and which would spare me the overhead of a MySQL server.

To test the binding I exported my MySQL data und converted it to a SQLite database (using the script from this site: https://github.com/dumblob/mysql2sqlite. I configured the jdbc service as described in the “migrating from MySQL section”, assuming, that this would result in maximum database compatibility.

I logged the output of the persistence functions for booth, the db4o and jdbc service to test the new service with my converted database. The item I used for testing represents my water meter reading and is updated at least every 4 minutes and in addition whenever 10l of water have been used.

Here is the logging I use:

//Persistence Test        
	logInfo("SmartSmartMeter.rules", "changedSince (60min) - db4o: " + WaterMeter_Value.changedSince(now.minusMinutes(60)))
	logInfo("SmartSmartMeter.rules", "changedSince (60min) - jdbc: " + WaterMeter_Value.changedSince(now.minusMinutes(60), "jdbc"))
    
    logInfo("SmartSmartMeter.rules", "updatedSince (60min) - db4o: " + WaterMeter_Value.updatedSince(now.minusMinutes(60)))
    logInfo("SmartSmartMeter.rules", "updatedSince (60min) - jdbc: " + WaterMeter_Value.updatedSince(now.minusMinutes(60), "jdbc"))
        
    logInfo("SmartSmartMeter.rules", "minimumSince (1h) - db4o: " + WaterMeter_Value.minimumSince(now.minusMinutes(60) ).state)
    logInfo("SmartSmartMeter.rules", "minimumSince (1h) - jdbc: " + WaterMeter_Value.minimumSince(now.minusMinutes(60), "jdbc").state)
    
    logInfo("SmartSmartMeter.rules", "minimumSince (Anfang Monat) - db4o: " + WaterMeter_Value.minimumSince(now.withTimeAtStartOfDay.withDayOfMonth(1)).state)
    logInfo("SmartSmartMeter.rules", "minimumSince (Anfang Monat) - jdbc: " + WaterMeter_Value.minimumSince(now.withTimeAtStartOfDay.withDayOfMonth(1), "jdbc").state)
        
    logInfo("SmartSmartMeter.rules", "averageSince (1h) - db4o: " + WaterMeter_Value.averageSince(now.minusMinutes(60)))
    logInfo("SmartSmartMeter.rules", "averageSince (1h) - jdbc: " + WaterMeter_Value.averageSince(now.minusMinutes(60), "jdbc"))
    
    logInfo("SmartSmartMeter.rules", "averageSince (Anfang Monat) - db4o: " + WaterMeter_Value.averageSince(now.withTimeAtStartOfDay.withDayOfMonth(1)))
    logInfo("SmartSmartMeter.rules", "averageSince (Anfang Monat) - jdbc: " + WaterMeter_Value.averageSince(now.withTimeAtStartOfDay.withDayOfMonth(1), "jdbc"))
                
    logInfo("SmartSmartMeter.rules", "deltaSince (1h) - db4o: " + WaterMeter_Value.deltaSince(now.minusMinutes(60)))
    logInfo("SmartSmartMeter.rules", "deltaSince (1h) - jdbc: " + WaterMeter_Value.deltaSince(now.minusMinutes(60), "jdbc"))
    
    logInfo("SmartSmartMeter.rules", "deltaSince (Anfang Monat) - db4o: " + WaterMeter_Value.deltaSince(now.withTimeAtStartOfDay.withDayOfMonth(1)))
    logInfo("SmartSmartMeter.rules", "deltaSince (Anfang Monat) - jdbc: " + WaterMeter_Value.deltaSince(now.withTimeAtStartOfDay.withDayOfMonth(1), "jdbc"))
        
    logInfo("SmartSmartMeter.rules", "previousState  - db4o: " + WaterMeter_Value.previousState().state )
    logInfo("SmartSmartMeter.rules", "previousState  - jdbc: " + WaterMeter_Value.previousState(false, "jdbc").state )
    
    logInfo("SmartSmartMeter.rules", "previousState (true)  - db4o: " + WaterMeter_Value.previousState(true).state)
    logInfo("SmartSmartMeter.rules", "previousState (true)  - jdbc: " + WaterMeter_Value.previousState(true, "jdbc").state)
        
    logInfo("SmartSmartMeter.rules", "sumSince (1h) - db4o: " + WaterMeter_Value.sumSince(now.minusMinutes(60)))
    logInfo("SmartSmartMeter.rules", "sumSince (1h) - jdbc: " + WaterMeter_Value.sumSince(now.minusMinutes(60), "jdbc"))
    
    logInfo("SmartSmartMeter.rules", "sumSince (Anfang Monat) - db4o: " + WaterMeter_Value.sumSince(now.withTimeAtStartOfDay.withDayOfMonth(1)))
    logInfo("SmartSmartMeter.rules", "sumSince (Anfang Monat) - jdbc: " + WaterMeter_Value.sumSince(now.withTimeAtStartOfDay.withDayOfMonth(1), "jdbc"))
        
    logInfo("SmartSmartMeter.rules", "historicState (1h) - db4o: " + WaterMeter_Value.historicState(now.minusMinutes(60)).state)
    logInfo("SmartSmartMeter.rules", "historicState (1h) - jdbc: " + WaterMeter_Value.historicState(now.minusMinutes(60), "jdbc").state)
    
    logInfo("SmartSmartMeter.rules", "historicState (24h) - db4o: " + WaterMeter_Value.historicState(now.minusHours(24)).state)
    logInfo("SmartSmartMeter.rules", "historicState (24h) - jdbc: " + WaterMeter_Value.historicState(now.minusHours(24), "jdbc").state)
    
    logInfo("SmartSmartMeter.rules", "historicState (48h) - db4o: " + WaterMeter_Value.historicState(now.minusHours(48)).state)
    logInfo("SmartSmartMeter.rules", "historicState (48) -  jdbc: " + WaterMeter_Value.historicState(now.minusHours(48), "jdbc").state)
    
    logInfo("SmartSmartMeter.rules", "historicState (72h) - db4o: " + WaterMeter_Value.historicState(now.minusHours(72)).state)
    logInfo("SmartSmartMeter.rules", "historicState (72) -  jdbc: " + WaterMeter_Value.historicState(now.minusHours(72), "jdbc").state)
    
        
    if (WaterMeter_Value.historicState(now.withTimeAtStartOfDay.withDayOfMonth(1)) != null) { 
        	logInfo("SmartSmartMeter.rules", "historicState (Anfang Monat) - db4o: " + WaterMeter_Value.historicState(now.withTimeAtStartOfDay.withDayOfMonth(1)).state)
        } else {
        	logInfo("SmartSmartMeter.rules", "historicState (Anfang Monat) - db4o: Null")
        }
        
     if (WaterMeter_Value.historicState(now.withTimeAtStartOfDay.withDayOfMonth(1), "jdbc") != null) { 
        	logInfo("SmartSmartMeter.rules", "historicState (Anfang Monat) - jdbc: " + WaterMeter_Value.historicState(now.withTimeAtStartOfDay.withDayOfMonth(1), "jdbc").state)
        } else {
        	logInfo("SmartSmartMeter.rules", "historicState (Anfang Monat) - jdbc: Null")
        }

This results in the following output:

2016-09-18 15:00:25.672 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- changedSince (60min) - db4o: true
2016-09-18 15:00:25.880 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- changedSince (60min) - jdbc: false
2016-09-18 15:00:25.881 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- updatedSince (60min) - db4o: true
2016-09-18 15:00:25.882 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- updatedSince (60min) - jdbc: false
2016-09-18 15:00:25.883 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- minimumSince (1h) - db4o: 3105
2016-09-18 15:00:25.884 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- minimumSince (1h) - jdbc: 3158
2016-09-18 15:00:25.908 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- minimumSince (Anfang Monat) - db4o: 0
2016-09-18 15:00:25.910 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- minimumSince (Anfang Monat) - jdbc: 0
2016-09-18 15:00:25.912 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- averageSince (1h) - db4o: 3132.0714285714284415007568895816802978515625
2016-09-18 15:00:25.912 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- averageSince (1h) - jdbc: 3158
2016-09-18 15:00:25.931 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- averageSince (Anfang Monat) - db4o: 1649.825396825396865096990950405597686767578125
2016-09-18 15:00:25.933 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- averageSince (Anfang Monat) - jdbc: 1647.236363636363648765836842358112335205078125
2016-09-18 15:00:26.096 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- deltaSince (1h) - db4o: 55
2016-09-18 15:00:26.097 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- deltaSince (1h) - jdbc: 0
2016-09-18 15:00:26.249 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- deltaSince (Anfang Monat) - db4o: null
2016-09-18 15:00:26.250 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- deltaSince (Anfang Monat) - jdbc: null
2016-09-18 15:00:26.258 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- previousState  - db4o: 3158
2016-09-18 15:00:26.259 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- previousState  - jdbc: 3158
2016-09-18 15:00:26.267 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- previousState (true)  - db4o: 3157
2016-09-18 15:00:26.269 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- previousState (true)  - jdbc: 3157
2016-09-18 15:00:26.270 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- sumSince (1h) - db4o: 40691
2016-09-18 15:00:26.271 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- sumSince (1h) - jdbc: 0
2016-09-18 15:00:26.285 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- sumSince (Anfang Monat) - db4o: 724415
2016-09-18 15:00:26.290 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- sumSince (Anfang Monat) - jdbc: 721626
2016-09-18 15:00:26.451 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- historicState (1h) - db4o: 3103
2016-09-18 15:00:26.452 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- historicState (1h) - jdbc: 3158
2016-09-18 15:00:26.674 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- historicState (24h) - db4o: 2625
2016-09-18 15:00:26.675 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- historicState (24h) - jdbc: 2625
2016-09-18 15:00:26.832 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- historicState (48h) - db4o: 1973
2016-09-18 15:00:26.833 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- historicState (48) -  jdbc: 1973
2016-09-18 15:00:26.988 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- historicState (72h) - db4o: 1737
2016-09-18 15:00:26.989 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- historicState (72) -  jdbc: 1737
2016-09-18 15:00:27.140 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- historicState (Anfang Monat) - db4o: Null
2016-09-18 15:00:27.141 INFO  o.o.m.s.SmartSmartMeter.rules[:53]- historicState (Anfang Monat) - jdbc: Null

I did the conversion yesterday, so the historic values for 48h and 72h ago should show, that converting the database worked and the jdbc binding can access the data.

But there are some differences. Mostly the changedSince() and updatedSince() results from the jdbc binding are obviously wrong, as I checked, that the KNX GA is indeed send every 4 minutes and that there have been new meter readings in the last hour.

Some minor differences might be caused by subtle internal differences in updating the data, but probably not e.g. the deltaSince() and sumSince() values, beside others.

I can not full rule out, that converting the old data is the cause for the problem, on the other hand old data is obviously accessed correctly and errors occur in an interval with only new data.

I am still using MySQL in parallel, with the MySQl binding, maybe this is a problem?

My openHAB installation is the 1.8.3 stable version, running on a dedicated server with OSX 10.11.6, 2,3GHz Core i7 and Oracle Java 8 Update 101.

If I can help any further, e.g. provide more data, please let me know.

Thanks for your help in advance!

Juelicher

2

I assume you have the JDBC binding jar file installed an have created a .persist file for the SQLite which matches your MySQL .persist file.

The problem may indeed be the conversion. There is no guarantee that the table structure created by the MySQL binding matches those in the JDBC binding so your imported data may be ignored.

Can you run some queries on the SQLite DB and see if new values are being added?

Do you still have problems if you start from an empty SQLite DB (i.e. don’t transfer the historic data from your MySQL, just let it start to populate itself from scratch)?

3

Thanks for your fast reply!

I just did a short check of the sqlite database and yes, the table with the item gets updated and the last value in the table is correct.

But I noticed, that the timestamp in the table is UTC. The doc of the jdbc binding states, that it used to use UTC but respects local time now, but maybe not jet in the 1.8.3 version I use?

This would explain the problem, with UTC all entries are at least 2h old compared to local time und changedSince(1h) could not return true. But I do not know the persistence interface of openHAB and therefore do not know, if time zone conversion is done when retrieving the data and UTC entries in the database are correct.

If I find some time in the next days I could check with the current snapshot of the jdbc binding. Can I use the 1.9.0 nightly version with my 1.8.3 openHAB stable installation?

4

Yes you can and that is what I would recommend. You can find the latest build at:

https://openhab.ci.cloudbees.com/job/openHAB1-Addons/lastSuccessfulBuild/artifact/

5

Thanks again for the help!

I jus tried to exchange the JFBC persistence binding with the newest snapshot (database driver is still in place).

After starting openHAB I get the following error several times:

2016-09-18 20:21:25.311 INFO  o.o.p.jdbc.internal.JdbcMapper[:170]- JDBC::openConnection: Driver is available::Yank setupDataSource
2016-09-18 20:21:25.559 ERROR org.knowm.yank.Yank[:668]- Error in SQL query!!!
java.sql.SQLException: [SQLITE_ERROR] SQL error or missing database (no such function: DATABASE) Query: SELECT DATABASE() Parameters: []
	at org.apache.commons.dbutils.AbstractQueryRunner.rethrow(AbstractQueryRunner.java:392)
	at org.apache.commons.dbutils.QueryRunner.query(QueryRunner.java:351)
	at org.apache.commons.dbutils.QueryRunner.query(QueryRunner.java:289)
	at org.knowm.yank.Yank.queryScalar(Yank.java:273)
	at org.knowm.yank.Yank.queryScalar(Yank.java:253)
	at org.openhab.persistence.jdbc.db.JdbcBaseDAO.doGetDB(JdbcBaseDAO.java:261)

I reverted to the 1.8.3 JDBC Binding and openHAB starts fine, there are just some warnings from the Binding about items which are currently missing in the database (which should be OK):

2016-09-18 20:26:09.027 WARN  o.o.p.j.i.JdbcPersistenceService[:186]- JDBC::query: unable to find table for query, no Data in Database for Item 'Steckdosen_Garten_Zwang'. Current number of tables in the database: 272
2016-09-18 20:26:09.028 WARN  o.o.p.j.i.JdbcPersistenceService[:191]- JDBC::query: try to generate the table for item 'Steckdosen_Garten_Zwang'

Is there something I am missing?

6

Your reached the extent of my knowledge. I use InfluxDB and have no direct experience with JDBC.

You can try stopping openHAB, move the SQLite db file, restarting openHAB and then see if the error goes away. If it does you can then compare the structure and content of the two to see if you can find differences.

7

The error on startup was a bug in the JDBC binding snapshot, which was fixed by lewie.

With the snapshot version of the binding the issues from my first post seems do be gone, but I will do some more tests in the next few days. Probably the UTC timestamps in the database where indeed the cause of the problem.

@rlkoshak, thanks again for your help!