In rrd4j database (again)

Any idea why I am having values stored in rrdb twice? The (again) times look like yesterdays values.

2015-12-02 23:59:00 DEBUG o.o.p.r.internal.RRD4jService[:111]- Stored 'Today_Solar_kWh' with state '4' in rrd4j database (again)
2015-12-02 23:59:00 DEBUG o.o.p.r.internal.RRD4jService[:130]- Stored 'Today_Solar_kWh' with state '0.0' in rrd4j database
2015-12-02 23:59:00 DEBUG o.o.p.r.internal.RRD4jService[:111]- Stored 'Today_Water_Used' with state '154' in rrd4j database (again)
2015-12-02 23:59:00 DEBUG o.o.p.r.internal.RRD4jService[:130]- Stored 'Today_Water_Used' with state '51' in rrd4j database
2015-12-02 23:59:00 DEBUG o.o.p.r.internal.RRD4jService[:111]- Stored 'Today_Generator_Runtime' with state '9.46736054999998799530658288858830928802490234375' in rrd4j database (again)
2015-12-02 23:59:00 DEBUG o.o.p.r.internal.RRD4jService[:130]- Stored 'Today_Generator_Runtime' with state '14.40050220999998113276888034306466579437255859375' in rrd4j database
2015-12-02 23:59:00 DEBUG o.o.p.r.internal.RRD4jService[:111]- Stored 'Today_Out_kWh' with state '28.07000000000000028421709430404007434844970703125' in rrd4j database (again)
2015-12-02 23:59:00 DEBUG o.o.p.r.internal.RRD4jService[:130]- Stored 'Today_Out_kWh' with state '0.95' in rrd4j database
2015-12-02 23:59:00 DEBUG o.o.p.r.internal.RRD4jService[:111]- Stored 'Today_Propane_Used' with state '0.450100000000001554401052317189169116318225860595703125' in rrd4j database (again)
2015-12-02 23:59:00 DEBUG o.o.p.r.internal.RRD4jService[:130]- Stored 'Today_Propane_Used' with state '1.198400000000004032774114648418617434799671173095703125' in rrd4j database

My rrd4j.persist

Strategies {
	everyMinute : "0 * * * * ?"
	everyNight : "0 59 23 * * ?"
}

Items {
	Temperature*,Humidity*,Weather*,Water*,Buy*,Inverter*,Charge_Controller*,Shunt*,HVAC*,CT_Sensor*,Creek_Level,Battery_Charge,Battery_Voltage,TankUtility_Tank : strategy = everyMinute, restoreOnStartup
	Totals* : strategy = everyNight, restoreOnStartup
}

Could this be a bug?

I found the code, but still don’t understand why I am storing the last value (again) and then the real value.

  • public synchronized void store(final Item item, final String alias) {
  •    final String name = alias == null ? item.getName() : alias;
    
  •    RrdDb db = getDB(name);
    
  •    if (db != null) {
    
  •        ConsolFun function = getConsolidationFunction(db);
    
  •        long now = System.currentTimeMillis() / 1000;
    
  •        if (function != ConsolFun.AVERAGE) {
    
  •            try {
    
  •                // we store the last value again, so that the value change in the database is not interpolated, but
    
  •                // happens right at this spot
    
  •                if (now - 1 > db.getLastUpdateTime()) {
    
  •                    // only do it if there is not already a value
    
  •                    double lastValue = db.getLastDatasourceValue(DATASOURCE_STATE);
    
  •                    if (!Double.isNaN(lastValue)) {
    
  •                        Sample sample = db.createSample();
    
  •                        sample.setTime(now - 1);
    
  •                        sample.setValue(DATASOURCE_STATE, lastValue);
    
  •                        sample.update();
    
  •                        logger.debug("Stored '{}' with state '{}' in rrd4j database (again)", name,
    
  •                                mapToState(lastValue, item.getName()));
    
  •                    }

Although I do not understand why, but the code says it is going to store the last value if it is not yet present. At minute 59 this code is executed twice as of the cron strings. The first time there is not yet a value at time now-1, and thus the last value is stored. The second time the code is executed, the value is present, because the first execution stored it, and so the last value is not stored again.

It’s causing error in my data, as you can see from my logs the two samples are very different.

Althought this is an old thread, I’m having the same issue today:

2018-12-31 14:58:00.127 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored ‘EnergyPower’ with state ‘39360’ in rrd4j database (again)
2018-12-31 14:58:00.137 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored ‘EnergyPower’ with state ‘328.0’ in rrd4j database
2018-12-31 14:58:03.220 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored ‘EnergyPower’ with state ‘39360’ in rrd4j database (again)
2018-12-31 14:58:03.252 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored ‘EnergyPower’ with state ‘853.0’ in rrd4j database

Were you able to resolve this?
That I notice is that the wrong value (the ‘again’-value), is always 120 times the previous correct value: 328*120=39360. I have no clue why. The item EnergyPower is updated every 120 secs, but I do not know if it has anything to do with it.