OH3 docker: Persistence not acting correctly

binderth · October 21, 2022, 12:19pm

Running OH3.3-stable in my Synology Docker.

I’ve installed and configured the JDBC-MariaDB Persistence AddOn. This one works - sort of.

It can reach my MariaDB
It will create item-tables
It will fill them with values

but:

It does that very … reluctant so to say?
There’s no “onChange” persistence
There’s not all items in there, even though they were at least once updated/commanded

My jdbc.persist

Strategies {
	everyMinute	: "1 * * * * ?"
	everyHour	: "5 1 * * * ?"
	everyDay	: "10 2 1 * * ?"
	default = everyChange, restoreOnStartup
}

Items {
	* : strategy = everyChange, everyHour, restoreOnStartup
}

I activated TRACE for the JDBC-persistence and the logs look like this:

2022-10-21 14:06:48.520 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_Verbrauch' changed from 446 to 447
2022-10-21 14:06:48.522 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'EMS_Ueberschuss' changed from 1115 to 1111
2022-10-21 14:06:48.731 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVString1Leistung' changed from 905 to 903
2022-10-21 14:06:48.745 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVString2Leistung' changed from 654 to 652
2022-10-21 14:06:48.766 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVErzeugung' changed from 1558 to 1556
2022-10-21 14:06:54.405 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_Verbrauch' changed from 447 to 449
2022-10-21 14:06:54.407 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'EMS_Ueberschuss' changed from 1111 to 1107
2022-10-21 14:06:54.520 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVString1Leistung' changed from 903 to 901
2022-10-21 14:06:54.526 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVString2Leistung' changed from 652 to 651
2022-10-21 14:06:54.547 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_Netzeinspeisung' changed from -3 to 24
2022-10-21 14:06:54.565 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVErzeugung' changed from 1556 to 1552
2022-10-21 14:06:59.662 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'EMS_Grundlast' changed from 465.2733694065641 to 451.7088850244364
2022-10-21 14:07:00.083 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_Verbrauch' changed from 449 to 445
2022-10-21 14:07:00.271 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVString1Leistung' changed from 901 to 900
2022-10-21 14:07:00.281 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_Netzeinspeisung' changed from 24 to 20
2022-10-21 14:07:00.308 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVErzeugung' changed from 1552 to 1551
==> /var/log/openhab/openhab.log <==
2022-10-21 14:07:01.916 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::storeItemValue: item=KOS_Verbrauch (Type=NumberItem, State=445, Label=Verbrauch, Category=energy, Tags=[Measurement, Energy], Groups=[PL12Kostal]) state=445 date=null
2022-10-21 14:07:01.916 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO tableName=item0014; newTableName=null; 
2022-10-21 14:07:01.916 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::getItemType: Try to use ItemType NUMBERITEM for Item KOS_Verbrauch
2022-10-21 14:07:01.917 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: item 'KOS_Verbrauch' as Type 'NUMBERITEM' in 'item0014' with state '445'
2022-10-21 14:07:01.917 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: itemState: '445'
2022-10-21 14:07:01.917 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO setValueTypes dbType=DOUBLE; javaType=class java.lang.Double;
2022-10-21 14:07:01.917 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: newVal.doubleValue: '445.0'
2022-10-21 14:07:01.917 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doStoreItemValue sql=INSERT INTO item0014 (TIME, VALUE) VALUES( NOW(3), ? ) ON DUPLICATE KEY UPDATE VALUE= ? value='445.0'
2022-10-21 14:07:02.530 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC: Stored item 'KOS_Verbrauch' as '445' in SQL database at Fri Oct 21 14:07:02 CEST 2022 in 615 ms.
2022-10-21 14:07:02.687 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::storeItemValue: item=KOS_PVString2Leistung (Type=NumberItem, State=651, Label=PV String2 Leistung, Category=energy, Tags=[Measurement, Energy], Groups=[PL12Kostal]) state=651 date=null
2022-10-21 14:07:02.688 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO tableName=item0013; newTableName=null; 
2022-10-21 14:07:02.688 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::getItemType: Try to use ItemType NUMBERITEM for Item KOS_PVString2Leistung
2022-10-21 14:07:02.688 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: item 'KOS_PVString2Leistung' as Type 'NUMBERITEM' in 'item0013' with state '651'
2022-10-21 14:07:02.688 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: itemState: '651'
2022-10-21 14:07:02.688 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO setValueTypes dbType=DOUBLE; javaType=class java.lang.Double;
2022-10-21 14:07:02.688 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: newVal.doubleValue: '651.0'
2022-10-21 14:07:02.689 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doStoreItemValue sql=INSERT INTO item0013 (TIME, VALUE) VALUES( NOW(3), ? ) ON DUPLICATE KEY UPDATE VALUE= ? value='651.0'
2022-10-21 14:07:03.210 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC: Stored item 'KOS_PVString2Leistung' as '651' in SQL database at Fri Oct 21 14:07:03 CEST 2022 in 523 ms.
==> /var/log/openhab/events.log <==
2022-10-21 14:07:05.887 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_Verbrauch' changed from 445 to 467
2022-10-21 14:07:05.890 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'EMS_Ueberschuss' changed from 1107 to 1084
2022-10-21 14:07:06.020 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVString1Leistung' changed from 900 to 897
2022-10-21 14:07:06.028 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVString2Leistung' changed from 651 to 652
2022-10-21 14:07:06.036 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_Netzeinspeisung' changed from 20 to 8

As you can see, there’s loads of item-changes, but only a few INSERTs? Do I miss something?
The same jdbc.persist in my raspberryPi-openHAB works as intended…

rlkoshak · October 21, 2022, 1:43pm

Do you see anything interesting in the MariaDB logs? Whether or not openHAB or MariaDB are running in containers should not matter.

binderth · October 21, 2022, 1:47pm

No, MariaDB works fine => see below.

I just fired up a vanilla openHABian v1.7.4b and imported the configuration of my docker - and there it works like a charm!?
within seconds not only did I get literally hundreds of itemtables, but also the values get stored onChange…?

So - what is wrong with the docker-openHAB?

Is there a way to “restore” a backup into a Docker-Container? I can’t restore, because:

synologyssh@Synology720:~$ sudo docker exec -it openhab /openhab/runtime/bin/restore
##########################################
          openHAB restore script
##########################################
openHAB is running! Please stop the process before restoring.

So I can’t stop openHAB without stopping the container…? I’d like to start with a vanilla Docker version and my backup…?

rlkoshak · October 21, 2022, 1:57pm

You can write a script to execute the restore and mount the folder to the container to /etc/cont-init.d. The entrypoint to the docker container will execute any scripts found there before starting openHAB itself.

But if you just restore your full config everything’s going to be configured the same so I’m not sure that’s going to show much. There isn’t really anything different about the openHAB software itself running in a container so what ever the problem is has to be a configuration problem.

binderth · October 21, 2022, 2:12pm

and THAT’s the thing. I did not even change one bit after restoring it to a openHABian vanilla installation. I also don’t know, where to look, because I built a new configuration via UI in a vanilla openHAB docker. I did play around a bit with Bridge and Host and kept the same volumes, so perhaps there is some mishap hidden here. So I want to give docker one last chance by restoring my config into a vanilla docker.

hmm. I’m fairly new to docker, can you point me to a readme on how to do that, please?

rlkoshak · October 21, 2022, 2:33pm

Not all configuration is inside the container. There might be something about your overall Docker environment or host OS that is causing problems.

Docker is a little different in that every time you spin up a new container, you are restoring your configs on a brand new instance of openHAB. That’s just the nature of containers. Your data (i.e. configs) live outside of the container and are mounted as a volume. So when you spin up a new container, it’s like you copied your config to a brand new machine with a fresh install of OH on it.

So I’m not sure what running a restore on the container itself is really going to show.

https://hub.docker.com/r/openhab/openhab

Scroll down to “Executing shell scripts before openHAB is started” section (I wish subpage linking were working).

This page is your go-to for all reference information about the docker image.

binderth · October 21, 2022, 2:47pm

Ok, thanks for your insight - as usual!
so, if I understand correctly:

my openHAB configuration “as is” is working on a non-docker openHAB as it should
the configuration inside my synology docker shows no signs of “openHAB”-misconfiguration itself as there are no failed tries to persist items
only thing is: MariaDB gets updated from within the container “lazy” => which in turn is useless for me

perhaps this behaviour is the same as with my rrd4j-“lazyiness” we talked about yesterday?

Docker is running in a fairly idle-prone Synology 720. All container only use ab a few percent CPU - openHAB a bit over 10% of its CPU-time…?

should not be a perfomance issue, I think?

binderth · October 21, 2022, 3:08pm

It’s getting weirder…
If I look into what gets persisted, directly after a container restart, there seems to be a “onChange”-persistance, but then after a while it stops and then it’ll just send items to persistence every few minutes or so? This is the consumption item from my inverter => gets updated every few seconds at least.
grafik

in TRACE mode there’s no error whatsoever, MariaDB Error-Log is empty

rlkoshak · October 21, 2022, 3:44pm

I don’t think it’s the same thing. I believe we determined that rrd4j is working as designed. This is not.

Which container is restarting? OH or MariaDB?

binderth · October 21, 2022, 3:54pm

OH, mariaDB weeks runs as package.
I had to change a few configs like Timezones and Ports…

rlkoshak · October 21, 2022, 3:57pm

I can’t imagine what would cause it to work sometimes but not all the time. It’s a bit of a mystery.

binderth · October 21, 2022, 6:42pm

It works for a few seconds after startup and then stops…
That’s completely weird.

binderth · October 22, 2022, 10:01am

Wanna know something really scary?
Just added a vanilla docker container and added just the thing/item combination for my inverter… and guess what? it works as intended - even though I just installed JDBC MariaDB persistence and the MQTT for my inverter, I didn’t had to drop a jdbc.persist in there - onChange is standard…
grafik

I just stopped my OH-container, extracted the backup to the /conf and /userdata section and started it again. Should be the same outcome I guess?
anyways - as OH3 came up again it created the items-table again - slowly and not at all as it should?
is it the number of items? it’s not only 6 as in my test but > 500 items presently…

binderth · October 22, 2022, 2:50pm

hmm… This going a bit longer.
I have two Synology NAS: DS214play and DS720+. I run MariaDB10 as packages on both NAS.

nope. not true - see next comment
After extensive testing on docker, I just changed the MariaDB-server… and if I chose MariaDB running on the “old” DS214play → everything runs as it should.
If I chose MariaDB on the “new” 720+ → it’s the above mentioned behaviour: persistence every few minutes

So, what’s different between those two?

CPU, RAM, HDD: all WAY better on the 720+
filesystem: ext4 on DS214play vs BtrFS on 720+
720+ runs docker plus MariaDB

MariaDB recommends BtrFS even over ext4: What is the best Linux filesystem for MariaDB? | MariaDB

no, this is not true - see next comment:
So, what’s the deal, then? I mean, honestly, there’s no errors in any logs - but persistence is lame vs no error in any logs - and persistence is doing what it should? The only thing, I change is an IP-address and the password in my Docker-OH3 …?

binderth · October 22, 2022, 3:52pm

nope, the different MariaDB-Server/NAS was not the issue. I did some more testing and it seems unrelated.

my “old” OH3-container does not want to do any coherent persistence on either MariaDB-instances
my “new” OH3-container does somewhat “better” with persistence, as it persists at a much higher rate, but it also does not persist “onChange”. it persist more - but the intervals could be 30secs or more (as is a MUCH higher rate as the old one), but it doesn’t persist every change - and this is consistent with both MariaDB-instances.

so, I’m back to square 1 again.

rossko57 · October 23, 2022, 1:16pm

That looks a bit screwy. I should not think it relates to your issue, but I think you may only define one strategy as the default strategy. I’d expect it to ignore the rest of the comma-separated list.
And in any case you will not be using the default with the rest of the given jdbc.persist file

binderth · October 23, 2022, 2:12pm

you’re right. It worked for me since a few years now. I’ll have to take a look! Thanks!
Still bugging me, that the persistence won’t do. So I doubled down on my tests and got something.

If the persistence won’t save every “onChange” - it seems, the DB-Connection is a bit slow
If the persistence does ist, the DB-Connection is faster

I activated the “Activate log time tracking” (or whatever it’s called in english - last entry in JDBC Persistence) and I get these:

2022-10-23 16:00:21.564 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue':
 afterAccess     = 1080 ms
 timeAverage50  = 559 ms
 timeAverage100 = 592 ms
 timeAverage200 = 598 ms
 afterAccessMin  = 2 ms
 afterAccessMax  = 4058 ms
 1000Statements = 0 sec
 statementCount = 480
2022-10-23 16:00:21.703 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue':
 afterAccess     = 133 ms
 timeAverage50  = 551 ms
 timeAverage100 = 588 ms
 timeAverage200 = 597 ms
 afterAccessMin  = 2 ms
 afterAccessMax  = 4058 ms
 1000Statements = 0 sec
 statementCount = 481
2022-10-23 16:00:22.564 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue':
 afterAccess     = 856 ms
 timeAverage50  = 565 ms
 timeAverage100 = 596 ms
 timeAverage200 = 598 ms
 afterAccessMin  = 2 ms
 afterAccessMax  = 4058 ms
 1000Statements = 0 sec
 statementCount = 482
2022-10-23 16:00:22.681 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue':
 afterAccess     = 111 ms
 timeAverage50  = 561 ms
 timeAverage100 = 590 ms
 timeAverage200 = 594 ms
 afterAccessMin  = 2 ms
 afterAccessMax  = 4058 ms
 1000Statements = 0 sec
 statementCount = 483
2022-10-23 16:00:23.964 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue':
 afterAccess     = 1277 ms
 timeAverage50  = 581 ms
 timeAverage100 = 587 ms
 timeAverage200 = 600 ms
 afterAccessMin  = 2 ms
 afterAccessMax  = 4058 ms
 1000Statements = 0 sec
 statementCount = 484
2022-10-23 16:00:26.548 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue':
 afterAccess     = 163 ms
 timeAverage50  = 563 ms
 timeAverage100 = 584 ms
 timeAverage200 = 595 ms
 afterAccessMin  = 2 ms
 afterAccessMax  = 4058 ms
 1000Statements = 0 sec
 statementCount = 485

The run times are waaaay to long.

If I set log-level to TRACE for JDBC:

2022-10-23 16:03:29.462 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC: Stored item 'AS_Daylight_Start' as '2022-10-23T07:52:00.000+0200' in SQL database at Sun Oct 23 16:03:29 CEST 2022 in 5719 ms.
2022-10-23 16:03:29.463 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'EV6_trunkOpen' because it is UnDefType
2022-10-23 16:03:29.464 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'DS_ForecastHours09_Snow' because it is UnDefType
2022-10-23 16:03:29.465 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'PL12Dressing' because it is UnDefType
2022-10-23 16:03:29.465 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'OKT_WWTempSoll' because it is UnDefType
2022-10-23 16:03:29.466 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::storeItemValue: item=AMZ_EchoBasemnt_Sprich (Type=StringItem, State=, Label=Sprich, Category=, Tags=[Point], Groups=[PL12PartyEcho]) state= date=null
2022-10-23 16:03:29.467 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::getTable: no table found for item 'AMZ_EchoBasemnt_Sprich' in sqlTables
2022-10-23 16:03:29.468 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::createNewEntryInItemsTable
2022-10-23 16:03:29.469 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doCreateNewEntryInItemsTable sql=INSERT INTO items (ItemName) VALUES ('AMZ_EchoBasemnt_Sprich')
2022-10-23 16:03:30.130 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'doCreateNewEntryInItemsTable':
 afterAccess     = 661 ms
 timeAverage50  = 1785 ms
 timeAverage100 = 1699 ms
 timeAverage200 = 1145 ms
 afterAccessMin  = 2 ms
 afterAccessMax  = 5902 ms
 1000Statements = 0 sec
 statementCount = 595
2022-10-23 16:03:30.131 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::getTable: getTableName with rowId=41 itemName=AMZ_EchoBasemnt_Sprich
2022-10-23 16:03:30.133 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::getItemType: Try to use ItemType STRINGITEM for Item AMZ_EchoBasemnt_Sprich
2022-10-23 16:03:30.135 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO tableName=item0041; newTableName=AMZ_EchoBasemnt_Sprich;
2022-10-23 16:03:30.136 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::createItemTable
2022-10-23 16:03:30.138 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doCreateItemTable sql=CREATE TABLE IF NOT EXISTS item0041 (time TIMESTAMP(3) NOT NULL, value VARCHAR(16255), PRIMARY KEY(time))
==> /var/log/openhab/events.log <==
2022-10-23 16:03:30.522 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_Verbrauch' changed from 3853 to 3894
2022-10-23 16:03:30.552 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'EMS_Ueberschuss' changed from -1471 to -1542
2022-10-23 16:03:30.807 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVString1Leistung' changed from 1949 to 1936
2022-10-23 16:03:30.812 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVString2Leistung' changed from 403 to 404
2022-10-23 16:03:30.847 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVErzeugung' changed from 2352 to 2340
2022-10-23 16:03:33.619 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KNX_DateTime' changed from 2022-10-23T16:02:33.385+0200 to 2022-10-23T16:03:33.606+0200
==> /var/log/openhab/openhab.log <==
2022-10-23 16:03:34.483 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'createItemTable':
 afterAccess     = 4344 ms
 timeAverage50  = 1850 ms
 timeAverage100 = 1739 ms
 timeAverage200 = 1162 ms
 afterAccessMin  = 2 ms
 afterAccessMax  = 5902 ms
 1000Statements = 0 sec
 statementCount = 596
2022-10-23 16:03:34.485 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::getTable: Table created for item 'AMZ_EchoBasemnt_Sprich' with dataType VARCHAR(16255) in SQL database.
2022-10-23 16:03:34.487 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO tableName=item0041; newTableName=null;
2022-10-23 16:03:34.488 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::getItemType: Try to use ItemType STRINGITEM for Item AMZ_EchoBasemnt_Sprich
2022-10-23 16:03:34.490 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: item 'AMZ_EchoBasemnt_Sprich' as Type 'STRINGITEM' in 'item0041' with state ''
2022-10-23 16:03:34.491 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: itemState: ''
2022-10-23 16:03:34.493 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO setValueTypes dbType=VARCHAR(16255); javaType=class java.lang.String;
2022-10-23 16:03:34.495 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: other: itemState: ''
2022-10-23 16:03:34.496 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doStoreItemValue sql=INSERT INTO item0041 (TIME, VALUE) VALUES( NOW(3), ? ) ON DUPLICATE KEY UPDATE VALUE= ? value=''
2022-10-23 16:03:35.120 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue':
 afterAccess     = 633 ms
 timeAverage50  = 1860 ms
 timeAverage100 = 1740 ms
 timeAverage200 = 1161 ms
 afterAccessMin  = 2 ms
 afterAccessMax  = 5902 ms
 1000Statements = 0 sec
 statementCount = 597
2022-10-23 16:03:35.122 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC: Stored item 'AMZ_EchoBasemnt_Sprich' as '' in SQL database at Sun Oct 23 16:03:35 CEST 2022 in 5655 ms.
2022-10-23 16:03:35.123 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'DS_ForecastHours07_Winddirection' because it is UnDefType
2022-10-23 16:03:35.125 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'OKT_SolarprimVorlauf' because it is UnDefType
2022-10-23 16:03:35.127 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'DS_ForecastHours04_Precipprobability' because it is UnDefType
2022-10-23 16:03:35.128 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'DS_ForecastHours05_Pressure' because it is UnDefType
2022-10-23 16:03:35.130 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'AMZ_EchoBasemnt_LetzterSprachbefehl' because it is UnDefType
2022-10-23 16:03:35.131 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'EMS_WaMaEinsparung' because it is UnDefType
2022-10-23 16:03:35.133 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'DS_ForecastHours03_Gustspeed' because it is UnDefType
2022-10-23 16:03:35.134 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'DB_MotionTimestamp' because it is UnDefType
2022-10-23 16:03:35.136 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'DS_ForecastHours05_Apparenttemperature' because it is UnDefType
2022-10-23 16:03:35.137 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'DS_ForecastHours04_Iconid' because it is UnDefType
2022-10-23 16:03:35.139 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'amazonAccount' because it is UnDefType
2022-10-23 16:03:35.140 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'PL12Cellar' because it is UnDefType
2022-10-23 16:03:35.142 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'KNX_ParentsSlat' because it is UnDefType
2022-10-23 16:03:35.144 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::storeItemValue: item=AQ_O3Value (Type=NumberItem, State=10.152 ppb, Label=Ozon Wert, Category=, Tags=[Point], Groups=[AQ]) state=10.152 ppb date=null
2022-10-23 16:03:35.145 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::getTable: no table found for item 'AQ_O3Value' in sqlTables
2022-10-23 16:03:35.147 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::createNewEntryInItemsTable
2022-10-23 16:03:35.148 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doCreateNewEntryInItemsTable sql=INSERT INTO items (ItemName) VALUES ('AQ_O3Value')
2022-10-23 16:03:35.358 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'doCreateNewEntryInItemsTable':
 afterAccess     = 210 ms
 timeAverage50  = 1747 ms
 timeAverage100 = 1698 ms
 timeAverage200 = 1160 ms
 afterAccessMin  = 2 ms
 afterAccessMax  = 5902 ms
 1000Statements = 0 sec
 statementCount = 598
2022-10-23 16:03:35.360 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::getTable: getTableName with rowId=42 itemName=AQ_O3Value
2022-10-23 16:03:35.362 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::getItemType: Try to use ItemType NUMBERITEM for Item AQ_O3Value
2022-10-23 16:03:35.363 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO tableName=item0042; newTableName=AQ_O3Value;
2022-10-23 16:03:35.365 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::createItemTable
2022-10-23 16:03:35.367 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doCreateItemTable sql=CREATE TABLE IF NOT EXISTS item0042 (time TIMESTAMP(3) NOT NULL, value DOUBLE, PRIMARY KEY(time))
==> /var/log/openhab/events.log <==
2022-10-23 16:03:36.602 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_Verbrauch' changed from 3894 to 3901
2022-10-23 16:03:36.632 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'EMS_Ueberschuss' changed from -1542 to -1561
2022-10-23 16:03:36.847 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVString1Leistung' changed from 1936 to 1948
2022-10-23 16:03:36.866 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVString2Leistung' changed from 404 to 401
2022-10-23 16:03:36.902 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVErzeugung' changed from 2340 to 2349
==> /var/log/openhab/openhab.log <==
2022-10-23 16:03:41.845 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'createItemTable':
 afterAccess     = 6478 ms
 timeAverage50  = 1864 ms
 timeAverage100 = 1753 ms
 timeAverage200 = 1190 ms
 afterAccessMin  = 2 ms
 afterAccessMax  = 6478 ms
 1000Statements = 0 sec
 statementCount = 599
2022-10-23 16:03:41.847 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::getTable: Table created for item 'AQ_O3Value' with dataType DOUBLE in SQL database.
2022-10-23 16:03:41.849 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO tableName=item0042; newTableName=null;
2022-10-23 16:03:41.850 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::getItemType: Try to use ItemType NUMBERITEM for Item AQ_O3Value
2022-10-23 16:03:41.852 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: item 'AQ_O3Value' as Type 'NUMBERITEM' in 'item0042' with state '10.152 ppb'
2022-10-23 16:03:41.854 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: itemState: '10.152 ppb'
2022-10-23 16:03:41.855 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO setValueTypes dbType=DOUBLE; javaType=class java.lang.Double;
2022-10-23 16:03:41.857 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: newVal.doubleValue: '10.152'
2022-10-23 16:03:41.859 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doStoreItemValue sql=INSERT INTO item0042 (TIME, VALUE) VALUES( NOW(3), ? ) ON DUPLICATE KEY UPDATE VALUE= ? value='10.152'
==> /var/log/openhab/events.log <==
2022-10-23 16:03:42.129 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_Verbrauch' changed from 3901 to 4525
2022-10-23 16:03:42.154 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'EMS_Ueberschuss' changed from -1561 to -2176
2022-10-23 16:03:42.463 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVString1Leistung' changed from 1948 to 1947
2022-10-23 16:03:42.476 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVString2Leistung' changed from 401 to 404
2022-10-23 16:03:42.497 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVErzeugung' changed from 2349 to 2351
==> /var/log/openhab/openhab.log <==
2022-10-23 16:03:43.571 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue':
 afterAccess     = 1723 ms
 timeAverage50  = 1883 ms
 timeAverage100 = 1762 ms
 timeAverage200 = 1197 ms
 afterAccessMin  = 2 ms
 afterAccessMax  = 6478 ms
 1000Statements = 0 sec
 statementCount = 600
2022-10-23 16:03:43.573 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC: Stored item 'AQ_O3Value' as '10.152 ppb' in SQL database at Sun Oct 23 16:03:43 CEST 2022 in 8430 ms.
2022-10-23 16:03:43.575 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'OKT_Heizkreis1Pumpe' because it is UnDefType
2022-10-23 16:03:43.576 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'DS_ForecastTomorrow_Minapparenttemperature' because it is UnDefType
2022-10-23 16:03:43.578 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'SC_Day4HighEstimation' because it is UnDefType
2022-10-23 16:03:43.579 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'DS_ForecastHours10_Icon' because it is UnDefType
2022-10-23 16:03:43.581 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'PL12Entrance' because it is UnDefType
2022-10-23 16:03:43.582 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'KNX_LivingLight' because it is UnDefType
2022-10-23 16:03:43.583 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'OKT_SolarSumme' because it is UnDefType
2022-10-23 16:03:43.585 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'DS_ForecastHours06_Cloudiness' because it is UnDefType
2022-10-23 16:03:43.586 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'DS_ForecastHours06_Visibility' because it is UnDefType
2022-10-23 16:03:43.587 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'DS_ForecastHours06_Apparenttemperature' because it is UnDefType
2022-10-23 16:03:43.589 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'KNX_KitchenLight' because it is UnDefType
2022-10-23 16:03:43.591 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::storeItemValue: item=SC_RemainingProductionToday (Type=NumberItem, State=3.082 kWh, Label=Remaining Production Today, Category=, Tags=[Point], Groups=[Solcast]) state=3.082 kWh date=null
2022-10-23 16:03:43.592 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::getTable: no table found for item 'SC_RemainingProductionToday' in sqlTables
2022-10-23 16:03:43.594 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::createNewEntryInItemsTable
2022-10-23 16:03:43.595 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doCreateNewEntryInItemsTable sql=INSERT INTO items (ItemName) VALUES ('SC_RemainingProductionToday')
2022-10-23 16:03:44.435 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'doCreateNewEntryInItemsTable':
 afterAccess     = 840 ms
 timeAverage50  = 1878 ms
 timeAverage100 = 1769 ms
 timeAverage200 = 1197 ms
 afterAccessMin  = 2 ms
 afterAccessMax  = 6478 ms
 1000Statements = 0 sec
 statementCount = 601
2022-10-23 16:03:44.437 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::getTable: getTableName with rowId=43 itemName=SC_RemainingProductionToday
2022-10-23 16:03:44.439 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::getItemType: Try to use ItemType NUMBERITEM for Item SC_RemainingProductionToday
2022-10-23 16:03:44.440 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO tableName=item0043; newTableName=SC_RemainingProductionToday;
2022-10-23 16:03:44.442 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::createItemTable
2022-10-23 16:03:44.443 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doCreateItemTable sql=CREATE TABLE IF NOT EXISTS item0043 (time TIMESTAMP(3) NOT NULL, value DOUBLE, PRIMARY KEY(time))
2022-10-23 16:03:45.967 [WARN ] [okhttp3.OkHttpClient                ] - A connection to https://myopenhab.org/ was leaked. Did you forget to close a response body? To see where this was allocated, set the OkHttpClient logger level to FINE: Logger.getLogger(OkHttpClient.class.getName()).setLevel(Level.FINE);
2022-10-23 16:03:46.068 [ERROR] [io.openhabcloud.internal.CloudClient] - Error connecting to the openHAB Cloud instance. Reconnecting.
==> /var/log/openhab/events.log <==
2022-10-23 16:03:47.861 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_Verbrauch' changed from 4525 to 4890
2022-10-23 16:03:47.890 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'EMS_Ueberschuss' changed from -2176 to -2539
2022-10-23 16:03:48.103 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVString1Leistung' changed from 1947 to 1937
2022-10-23 16:03:48.122 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVString2Leistung' changed from 404 to 401
2022-10-23 16:03:48.168 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVErzeugung' changed from 2351 to 2337
==> /var/log/openhab/openhab.log <==
2022-10-23 16:03:49.025 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'createItemTable':
 afterAccess     = 4581 ms
 timeAverage50  = 1949 ms
 timeAverage100 = 1809 ms
 timeAverage200 = 1218 ms
 afterAccessMin  = 2 ms
 afterAccessMax  = 6478 ms
 1000Statements = 0 sec
 statementCount = 602
2022-10-23 16:03:49.027 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::getTable: Table created for item 'SC_RemainingProductionToday' with dataType DOUBLE in SQL database.
2022-10-23 16:03:49.029 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO tableName=item0043; newTableName=null;
2022-10-23 16:03:49.030 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::getItemType: Try to use ItemType NUMBERITEM for Item SC_RemainingProductionToday
2022-10-23 16:03:49.032 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: item 'SC_RemainingProductionToday' as Type 'NUMBERITEM' in 'item0043' with state '3.082 kWh'
2022-10-23 16:03:49.033 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: itemState: '3.082 kWh'
2022-10-23 16:03:49.035 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO setValueTypes dbType=DOUBLE; javaType=class java.lang.Double;
2022-10-23 16:03:49.037 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: newVal.doubleValue: '3.082'
2022-10-23 16:03:49.039 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doStoreItemValue sql=INSERT INTO item0043 (TIME, VALUE) VALUES( NOW(3), ? ) ON DUPLICATE KEY UPDATE VALUE= ? value='3.082'
2022-10-23 16:03:49.783 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue':
 afterAccess     = 754 ms
 timeAverage50  = 1962 ms
 timeAverage100 = 1767 ms
 timeAverage200 = 1221 ms
 afterAccessMin  = 2 ms
 afterAccessMax  = 6478 ms
 1000Statements = 0 sec
 statementCount = 603
2022-10-23 16:03:49.785 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC: Stored item 'SC_RemainingProductionToday' as '3.082 kWh' in SQL database at Sun Oct 23 16:03:49 CEST 2022 in 6194 ms.
2022-10-23 16:03:49.786 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'DS_ForecastTomorrow_Windspeed' because it is UnDefType
2022-10-23 16:03:49.788 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'KNX_EntranceOutlet' because it is UnDefType
2022-10-23 16:03:49.790 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'EMS_BBStrombedarf' because it is UnDefType
2022-10-23 16:03:49.791 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'DS_ForecastHours01_Icon' because it is UnDefType
2022-10-23 16:03:49.793 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::storeItemValue: item=KOS_BatteryCharge (Type=NumberItem, State=99, Label=Battery Charge, Category=batterylevel, Tags=[Measurement, Energy], Groups=[PL12Kostal]) state=99 date=null
2022-10-23 16:03:49.795 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO tableName=item0014; newTableName=null;
2022-10-23 16:03:49.796 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::getItemType: Try to use ItemType NUMBERITEM for Item KOS_BatteryCharge
2022-10-23 16:03:49.798 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: item 'KOS_BatteryCharge' as Type 'NUMBERITEM' in 'item0014' with state '99'
2022-10-23 16:03:49.800 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: itemState: '99'
2022-10-23 16:03:49.801 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO setValueTypes dbType=DOUBLE; javaType=class java.lang.Double;
2022-10-23 16:03:49.803 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: newVal.doubleValue: '99.0'
2022-10-23 16:03:49.805 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doStoreItemValue sql=INSERT INTO item0014 (TIME, VALUE) VALUES( NOW(3), ? ) ON DUPLICATE KEY UPDATE VALUE= ? value='99.0'
2022-10-23 16:03:50.890 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue':
 afterAccess     = 1095 ms
 timeAverage50  = 1964 ms
 timeAverage100 = 1774 ms
 timeAverage200 = 1223 ms
 afterAccessMin  = 2 ms
 afterAccessMax  = 6478 ms
 1000Statements = 0 sec
 statementCount = 604
2022-10-23 16:03:50.892 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC: Stored item 'KOS_BatteryCharge' as '99' in SQL database at Sun Oct 23 16:03:50 CEST 2022 in 1099 ms.
2022-10-23 16:03:50.894 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'WS_UVValue' because it is UnDefType
2022-10-23 16:03:50.896 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'Solcast' because it is UnDefType
2022-10-23 16:03:50.897 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'DS_ForecastHours07_Precipprobability' because it is UnDefType
2022-10-23 16:03:50.899 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'DS_ForecastHours06_Timestamp' because it is UnDefType
2022-10-23 16:03:50.900 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'WS_Windspeed' because it is UnDefType
2022-10-23 16:03:50.902 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::storeItemValue: item=AMZ_EchoKitchen_Sprich (Type=StringItem, State=, Label=Sprich, Category=, Tags=[Point], Groups=[PL12KitchenEcho]) state= date=null
2022-10-23 16:03:50.904 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::getTable: no table found for item 'AMZ_EchoKitchen_Sprich' in sqlTables
2022-10-23 16:03:50.905 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::createNewEntryInItemsTable
2022-10-23 16:03:50.907 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doCreateNewEntryInItemsTable sql=INSERT INTO items (ItemName) VALUES ('AMZ_EchoKitchen_Sprich')
2022-10-23 16:03:52.327 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'doCreateNewEntryInItemsTable':
 afterAccess     = 1420 ms
 timeAverage50  = 1899 ms
 timeAverage100 = 1779 ms
 timeAverage200 = 1228 ms
 afterAccessMin  = 2 ms
 afterAccessMax  = 6478 ms
 1000Statements = 0 sec
 statementCount = 605
2022-10-23 16:03:52.329 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::getTable: getTableName with rowId=44 itemName=AMZ_EchoKitchen_Sprich
2022-10-23 16:03:52.330 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::getItemType: Try to use ItemType STRINGITEM for Item AMZ_EchoKitchen_Sprich
2022-10-23 16:03:52.332 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO tableName=item0044; newTableName=AMZ_EchoKitchen_Sprich;
2022-10-23 16:03:52.333 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::createItemTable
2022-10-23 16:03:52.335 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doCreateItemTable sql=CREATE TABLE IF NOT EXISTS item0044 (time TIMESTAMP(3) NOT NULL, value VARCHAR(16255), PRIMARY KEY(time))

what is clear: there’s not for every item-change an attempt to persist it in the Database…?
and - why are there no TRACE-entries on onChange-INSERT, which don’t make it?

binderth · October 23, 2022, 2:14pm

If I chose the “faster” mariaDB, it looks like this:

==> /var/log/openhab/openhab.log <==
2022-10-23 16:10:39.744 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::storeItemValue: item=KOS_Verbrauch (Type=NumberItem, State=2299, Label=Verbrauch, Category=energy, Tags=[Measurement, Energy], Groups=[PL12Kostal]) state=2299 date=null
2022-10-23 16:10:39.745 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO tableName=item0033; newTableName=null; 
2022-10-23 16:10:39.747 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::getItemType: Try to use ItemType NUMBERITEM for Item KOS_Verbrauch
2022-10-23 16:10:39.749 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: item 'KOS_Verbrauch' as Type 'NUMBERITEM' in 'item0033' with state '2299'
2022-10-23 16:10:39.750 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: itemState: '2299'
2022-10-23 16:10:39.753 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO setValueTypes dbType=DOUBLE; javaType=class java.lang.Double;
2022-10-23 16:10:39.754 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: newVal.doubleValue: '2299.0'
2022-10-23 16:10:39.757 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doStoreItemValue sql=INSERT INTO item0033 (TIME, VALUE) VALUES( NOW(3), ? ) ON DUPLICATE KEY UPDATE VALUE= ? value='2299.0'
2022-10-23 16:10:39.765 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue':
 afterAccess     = 19 ms
 timeAverage50  = 22 ms
 timeAverage100 = 22 ms
 timeAverage200 = 19 ms
 afterAccessMin  = 3 ms
 afterAccessMax  = 175 ms
 1000Statements = 0 sec
 statementCount = 594
2022-10-23 16:10:39.766 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC: Stored item 'KOS_Verbrauch' as '2299' in SQL database at Sun Oct 23 16:10:39 CEST 2022 in 23 ms.
2022-10-23 16:10:39.774 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::storeItemValue: item=EMS_Ueberschuss (Type=NumberItem, State=-448, Label=Überschuss, Category=, Tags=[Point], Groups=[PL12EMS]) state=-448 date=null
2022-10-23 16:10:39.775 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO tableName=item0036; newTableName=null; 
2022-10-23 16:10:39.776 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::getItemType: Try to use ItemType NUMBERITEM for Item EMS_Ueberschuss
2022-10-23 16:10:39.777 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: item 'EMS_Ueberschuss' as Type 'NUMBERITEM' in 'item0036' with state '-448'
2022-10-23 16:10:39.779 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: itemState: '-448'
2022-10-23 16:10:39.780 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO setValueTypes dbType=DOUBLE; javaType=class java.lang.Double;
2022-10-23 16:10:39.781 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: newVal.doubleValue: '-448.0'
2022-10-23 16:10:39.782 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doStoreItemValue sql=INSERT INTO item0036 (TIME, VALUE) VALUES( NOW(3), ? ) ON DUPLICATE KEY UPDATE VALUE= ? value='-448.0'
2022-10-23 16:10:39.788 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue':
 afterAccess     = 12 ms
 timeAverage50  = 21 ms
 timeAverage100 = 22 ms
 timeAverage200 = 19 ms
 afterAccessMin  = 3 ms
 afterAccessMax  = 175 ms
 1000Statements = 0 sec
 statementCount = 595
2022-10-23 16:10:39.789 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC: Stored item 'EMS_Ueberschuss' as '-448' in SQL database at Sun Oct 23 16:10:39 CEST 2022 in 16 ms.
==> /var/log/openhab/events.log <==
2022-10-23 16:10:39.744 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_Verbrauch' changed from 2344 to 2299
2022-10-23 16:10:39.772 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'EMS_Ueberschuss' changed from -499 to -448
==> /var/log/openhab/openhab.log <==
2022-10-23 16:10:40.202 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::storeItemValue: item=KOS_PVString1Leistung (Type=NumberItem, State=1531, Label=PV String1 Leistung, Category=energy, Tags=[Measurement, Energy], Groups=[PL12Kostal]) state=1531 date=null
2022-10-23 16:10:40.203 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO tableName=item0029; newTableName=null; 
2022-10-23 16:10:40.204 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::getItemType: Try to use ItemType NUMBERITEM for Item KOS_PVString1Leistung
2022-10-23 16:10:40.204 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: item 'KOS_PVString1Leistung' as Type 'NUMBERITEM' in 'item0029' with state '1531'
2022-10-23 16:10:40.205 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: itemState: '1531'
2022-10-23 16:10:40.205 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO setValueTypes dbType=DOUBLE; javaType=class java.lang.Double;
2022-10-23 16:10:40.206 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: newVal.doubleValue: '1531.0'
2022-10-23 16:10:40.206 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doStoreItemValue sql=INSERT INTO item0029 (TIME, VALUE) VALUES( NOW(3), ? ) ON DUPLICATE KEY UPDATE VALUE= ? value='1531.0'
2022-10-23 16:10:40.234 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue':
 afterAccess     = 30 ms
 timeAverage50  = 21 ms
 timeAverage100 = 23 ms
 timeAverage200 = 19 ms
 afterAccessMin  = 3 ms
 afterAccessMax  = 175 ms
 1000Statements = 0 sec
 statementCount = 596
2022-10-23 16:10:40.234 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC: Stored item 'KOS_PVString1Leistung' as '1531' in SQL database at Sun Oct 23 16:10:40 CEST 2022 in 32 ms.
2022-10-23 16:10:40.236 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::storeItemValue: item=KOS_PVString2Leistung (Type=NumberItem, State=341, Label=PV String2 Leistung, Category=energy, Tags=[Measurement, Energy], Groups=[PL12Kostal]) state=341 date=null
2022-10-23 16:10:40.237 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO tableName=item0032; newTableName=null; 
2022-10-23 16:10:40.238 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::getItemType: Try to use ItemType NUMBERITEM for Item KOS_PVString2Leistung
2022-10-23 16:10:40.238 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: item 'KOS_PVString2Leistung' as Type 'NUMBERITEM' in 'item0032' with state '341'
2022-10-23 16:10:40.239 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: itemState: '341'
2022-10-23 16:10:40.240 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO setValueTypes dbType=DOUBLE; javaType=class java.lang.Double;
2022-10-23 16:10:40.240 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: newVal.doubleValue: '341.0'
2022-10-23 16:10:40.241 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doStoreItemValue sql=INSERT INTO item0032 (TIME, VALUE) VALUES( NOW(3), ? ) ON DUPLICATE KEY UPDATE VALUE= ? value='341.0'
2022-10-23 16:10:40.259 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue':
 afterAccess     = 21 ms
 timeAverage50  = 21 ms
 timeAverage100 = 23 ms
 timeAverage200 = 19 ms
 afterAccessMin  = 3 ms
 afterAccessMax  = 175 ms
 1000Statements = 0 sec
 statementCount = 597
2022-10-23 16:10:40.259 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC: Stored item 'KOS_PVString2Leistung' as '341' in SQL database at Sun Oct 23 16:10:40 CEST 2022 in 23 ms.
2022-10-23 16:10:40.262 [DEBUG] [persistence.jdbc.internal.JdbcMapper] - JDBC::storeItemValue: item=KOS_PVErzeugung (Type=NumberItem, State=1852, Label=PV Erzeugung, Category=energy, Tags=[Measurement, Energy], Groups=[PL12Kostal]) state=1852 date=null
2022-10-23 16:10:40.262 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO tableName=item0034; newTableName=null; 
2022-10-23 16:10:40.263 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::getItemType: Try to use ItemType NUMBERITEM for Item KOS_PVErzeugung
2022-10-23 16:10:40.263 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: item 'KOS_PVErzeugung' as Type 'NUMBERITEM' in 'item0034' with state '1852'
2022-10-23 16:10:40.264 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: itemState: '1852'
2022-10-23 16:10:40.264 [DEBUG] [.openhab.persistence.jdbc.dto.ItemVO] - JDBC:ItemVO setValueTypes dbType=DOUBLE; javaType=class java.lang.Double;
2022-10-23 16:10:40.265 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::storeItemValueProvider: newVal.doubleValue: '1852.0'
2022-10-23 16:10:40.265 [DEBUG] [nhab.persistence.jdbc.db.JdbcBaseDAO] - JDBC::doStoreItemValue sql=INSERT INTO item0034 (TIME, VALUE) VALUES( NOW(3), ? ) ON DUPLICATE KEY UPDATE VALUE= ? value='1852.0'
2022-10-23 16:10:40.274 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue':
 afterAccess     = 12 ms
 timeAverage50  = 21 ms
 timeAverage100 = 23 ms
 timeAverage200 = 19 ms
 afterAccessMin  = 3 ms
 afterAccessMax  = 175 ms
 1000Statements = 0 sec
 statementCount = 598
2022-10-23 16:10:40.275 [DEBUG] [jdbc.internal.JdbcPersistenceService] - JDBC: Stored item 'KOS_PVErzeugung' as '1852' in SQL database at Sun Oct 23 16:10:40 CEST 2022 in 14 ms.
==> /var/log/openhab/events.log <==
2022-10-23 16:10:40.202 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVString1Leistung' changed from 1516 to 1531
2022-10-23 16:10:40.217 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVString2Leistung' changed from 342 to 341
2022-10-23 16:10:40.256 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KOS_PVErzeugung' changed from 1851 to 1852

There’s

all item changes going to persistence
the time tracker is waaaaay better.

I do get, that a slow database will lead to confusion and not every value persisted, but shouldn’t there be at least ERRORs then in the log?

rlkoshak · October 23, 2022, 9:22pm

It’s been over a decade since I’ve messed with MySQL/MariaDB (which I don’t think even existed the last time I messed with it). It seems like it should throw errors, but sometimes it’s desirable when a system gets overloaded to make a best effort and throw out stuff if it can’t process it. e.g. MQTT QOS 0.

I’ve seen some databases that have that sort of behavior but I’ve no idea if MariaDB has that. I’m pretty sure MySQL never did back then but maybe they added it.

binderth · October 24, 2022, 7:54am

thing is - there’s not even a TRACE log-entry for every change, so you’ll never know OH did not even try to update something. Perhaps I’ll file this on github.

I was under the impression, the MySQL Lead developer learned with the fork from MySQL and MariaDB is more stable and perfomant…