[rrd4j] Write asynchronously to database

[J-N-K]

Related to #14888 #14900

This is completely untested.

[lolodomo]

LGTM, thank you

[lolodomo]

I am using persistence (RRD4J) only for charts.
Of course, I could deploy this change but I don't know exactly what to do to test and validate the change.

[lolodomo]

Noone that could explain how I could test that ?
I don't know if it exists tools to consult RRD4J database.

[lolodomo]

Enabling DEBUG or TRACE logs should be probably a way to test that RRD4J is working as expected.

[lolodomo]

Tested by checking the DEBUG logs. Seems to work perfectly.
@J-N-K : please remove the draft status if this is ok for you and then I will merge the PR.

[J-N-K]

The only reason why I have/had doubts is the logic when an equal timestamp update is received.

[lolodomo]

I see strange behaviour with chart rendering in BasicUI as if the chart was put in cache after its first rendering. Not sure it is related to this PR. I will come back to the official version to check if it is different.

[lolodomo]

It is apparently identical with the current version of the persistence service, so not related to your changes.
I am not sure if there is a problem or not. The first display of a certain chart is a little slow and then it is very fast as if the chart image was in cache. Strange, I have never noticed that until today.

[lolodomo]

The only reason why I have/had doubts is the logic when an equal timestamp update is received.

In fact, I can see that values are still stored in database when the item state is updated or every minute (I see the logs) but I have not checked if they are at the right time. I should probably check that with charts or maybe using the REST API to fetch persisted data.

[lolodomo]

It is apparently identical with the current version of the persistence service, so not related to your changes.
I am not sure if there is a problem or not. The first display of a certain chart is a little slow and then it is very fast as if the chart image was in cache. Strange, I have never noticed that until today.

I was using sitemap visibility to switch between different charts. I believe Basic UI is just hiding/showing a chart when playing with the visibility. If the chart was already loaded, it is of course fast to show it.
If I exit the page and enter again, I can see a delay to build the chart.
So there is probably nothing new here.

[lolodomo]

@J-N-K : in case of massive item state updates, it could lead to the creation of a massive number of threads. Is there no limit that we could reach quickly ? At least, I see we are using a dedicated thread pool.

Previously the method store was synchronized. Now the method internalStore is not synchronized, meaning concurrent updates of DB could now occur. Isn't it a potential problem ?

[J-N-K]

Maybe. Another solution would be to have a queue of entries for each database (similar to what I did in influxdb). I'm just not sure if we can do batch updates in RRD4J.

Comments added after approval

[lolodomo]

When I send a command to a persisted item and then call the GET API with the default parameters, I do not get the value just persisted. It might be the sign of bad timestamps in database or the default ones generated by the REST API ?

10:54:07.795 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'EnConges' received command OFF
10:54:07.804 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'EnConges' changed from ON to OFF
10:54:07.825 [DEBUG] [rd4j.internal.RRD4jPersistenceService] - Stored 'EnConges' as value '1.0' in rrd4j database (again)
10:54:07.829 [DEBUG] [rd4j.internal.RRD4jPersistenceService] - Stored 'EnConges' as value '0.0' in rrd4j database

Request:

Result:

Is it due to your changes or not, I don't know but the result is unexpected.

[lolodomo]

If I restore the unchanged version of rrd4j, suddenly the REST API is showing again updated values.
So I would guess that the timestamps you use to store values are wrong (not in the last day) ?

[lolodomo]

So I would guess that the timestamps you use to store values are wrong (not in the last day) ?

But I don't see what could be wrong in your changed code...

[J-N-K]

I have added the timestamps to the log message, maybe it helps to figure out what is going on.

[lolodomo]

@J-N-K : to restore the previous behavior avoiding concurrent writings to database, you just need to move "synchronized" from method store to method internalStore.

That's being said, this synchronized also avoids concurrent writings to different rrd files while it should be possible. Only concurrent writings to the same database should be avoided. Probably something to enhance in a separate PR (no real idea how to implement that).

[J-N-K]

Probably we could add a per-name-lock for that.

[lolodomo]

With your last version:

19:43:47.119 [DEBUG] [rd4j.internal.RRD4jPersistenceService] - Stored 'EnConges' as value '1.0' with timestamp 1683481427 in rrd4j database (again)
19:43:47.124 [DEBUG] [rd4j.internal.RRD4jPersistenceService] - Stored 'EnConges' as value '0.0' with timestamp 1683481427 in rrd4j database
...
19:45:51.494 [DEBUG] [rd4j.internal.RRD4jPersistenceService] - Stored 'EnConges' as value '0.0' with timestamp 1683481551 in rrd4j database (again)
19:45:51.498 [DEBUG] [rd4j.internal.RRD4jPersistenceService] - Stored 'EnConges' as value '1.0' with timestamp 1683481551 in rrd4j database

And the result of API GET request:

...
    {
      "time": 1683450300000,
      "state": "ON"
    },
    {
      "time": 1683450300000,
      "state": "OFF"
    },
    {
      "time": 1683481500000,
      "state": "OFF"
    },
    {
      "time": 1683481500000,
      "state": "OFF"
    }
  ]
}

It looks like there is a factor 1000 between the logged timestamps and the time returned by REST API. Time 1683481427 and 1683481551 are not returned by the API.

[lolodomo]

It looks like there is a factor 1000 between the logged timestamps and the time returned by REST API. Time 1683481427 and 1683481551 are not returned by the API.

Maybe it is normal as the API field is a ZonedDateTime.
Maybe due to time zone conversion, the time value returned by the API will not be the same ?

I am going to erase my DB file to see if values are really written.

[J-N-K]

Could it be that the returned values are the boundaries of the bins in the RRD?

[lolodomo]

I tried again and I can confirm that values are stored in DB.

20:11:33.039 [DEBUG] [rd4j.internal.RRD4jPersistenceService] - Stored 'EnConges' as value '0.0' with timestamp 1683483093 in rrd4j database
...
20:12:31.161 [DEBUG] [rd4j.internal.RRD4jPersistenceService] - Stored 'EnConges' as value '0.0' with timestamp 1683483151 in rrd4j database (again)
20:12:31.164 [DEBUG] [rd4j.internal.RRD4jPersistenceService] - Stored 'EnConges' as value '1.0' with timestamp 1683483151 in rrd4j database
...

20:13:58.108 [DEBUG] [rd4j.internal.RRD4jPersistenceService] - Stored 'EnConges' as value '1.0' with timestamp 1683483238 in rrd4j database (again)
20:13:58.112 [DEBUG] [rd4j.internal.RRD4jPersistenceService] - Stored 'EnConges' as value '0.0' with timestamp 1683483238 in rrd4j database
...

20:16:53.055 [DEBUG] [rd4j.internal.RRD4jPersistenceService] - Stored 'EnConges' as value '0.0' with timestamp 1683483413 in rrd4j database (again)
20:16:53.057 [DEBUG] [rd4j.internal.RRD4jPersistenceService] - Stored 'EnConges' as value '1.0' with timestamp 1683483413 in rrd4j database

The result of REST API:

{
  "name": "EnConges",
  "datapoints": "11",
  "data": [
    {
      "time": 1683483060000,
      "state": "OFF"
    },
    {
      "time": 1683483120000,
      "state": "OFF"
    },
    {
      "time": 1683483120000,
      "state": "OFF"
    },
    {
      "time": 1683483180000,
      "state": "OFF"
    },
    {
      "time": 1683483180000,
      "state": "ON"
    },
    {
      "time": 1683483240000,
      "state": "ON"
    },
    {
      "time": 1683483240000,
      "state": "OFF"
    },
    {
      "time": 1683483300000,
      "state": "OFF"
    },
    {
      "time": 1683483300000,
      "state": "OFF"
    },
    {
      "time": 1683483360000,
      "state": "OFF"
    },
    {
      "time": 1683483360000,
      "state": "OFF"
    }
  ]
}

I would expect 7 values in DB but the API is returning 11 values !
I would have expected two values with a difference of 1 second but I got identical times.
I would have expected each time OFF/ON or ON/OFF but sometimes I got OFF/OFF.
The last value is wrong (OFF) while my current item state is ON !

All that looks very bad and I do not understand why. Let me try again the same scenario with the synchronous version.

[J-N-K]

Look at the timestamps: They are exactly 60s apart, which is the bin size of the RRD database. Remember: RRD collects the values in bins, depending on the consolidation function the values are average, max, min, first, last of the values in the bin. My guess would be that we see the first and last value of each bin in this case, which is why we have two values for each timestamp.

[lolodomo]

Look at the timestamps: They are exactly 60s apart, which is the bin size of the RRD database. Remember: RRD collects the values in bins, depending on the consolidation function the values are average, max, min, first, last of the values in the bin. My guess would be that we see the first and last value of each bin in this case, which is why we have two values for each timestamp.

I thought the two values were due we stored two value with oen second diff:

20:16:53.055 [DEBUG] [rd4j.internal.RRD4jPersistenceService] - Stored 'EnConges' as value '0.0' with timestamp 1683483413 in rrd4j database (again)
20:16:53.057 [DEBUG] [rd4j.internal.RRD4jPersistenceService] - Stored 'EnConges' as value '1.0' with timestamp 1683483413 in rrd4j database

Even with the unchanged version, the result of the API still looks strange to me (even if a little less), sometimes the last value does not match my current item state !!!

My current persistence strategy:

// persistence strategies have a name and a definition and are referred to in the "Items" section
Strategies {
        // for rrd charts, we need a cron strategy
        everyMinute : "0 * * * * ?"
}

Items {
        GTemperature*, GSuiviConsoElec* : strategy = everyChange, everyMinute, restoreOnStartup
        GVirtualData*, GParametres* : strategy = everyChange, restoreOnStartup
}

My item is in group GParametres, so I would expect to have a new value stored only when the item state is updated (everyChange).

I am really asking myself if the REST API and/or query method is working ! For me it is just unusable !

Is there another way to check the content of a rrd file ? Your code should work and I feel I am loosing my time testing it using the REST API !

[lolodomo]

Ok, maybe I am starting to understand. When adding a new value, in fact there is first a new value added for each minute before the old value and the new value, so it can be many values. When switching item from OFF to ON, this will generate OFF OFF OFF ... OFF ON
But I have still the feeling that sometimes the REST API does not return the very last value.

[lolodomo]

I will limit my tests to the rendering of charts.
Let's see how the charts evolve until tomorrow morning and if I find nothing strange, I will merge the PR.

[lolodomo]

Code LGTM, thank you

[lolodomo]

Ok, my charts in Main UI and Basic UI look good, and they include apparently the last value.