Emoncms calculation errors using redis 3.1.0 and 3.1.2

[pb66]

I have found emoncms will stop accumulating when a limit defined by the update rate and size of increase reaches a certain level.

In my case recording PV using a power to kWh process to record total kWh's has maxed out at 10000kWh's and has not recorded any increase since reaching that threshold.

See the "10000 kWh ceiling in emoncms?" thread on the OEM forum, I can provide more data and screenshots if required.

I'm not sure where to go with this as I'm not good with PHP, this is the "power to kWh" process in question

I know there was a change, way back to make the "value" field in the feeds table (mySQL) a double but I have no idea if the sums are being done using floats or doubles, also is it possible that Redis could cause a "bottle-neck" somewhere?

Any assistance appreciated

[chaveiro]

I remember the cause was adding a very small value to a large float that has lower precision ended up with a close number that when rounded is the same as it started before the add. Are you using redis?

[pb66]

Yes that is exactly the problem I'm seeing and yes I am using Redis but I do not know enough about how it works to debug. Do you have any suggestions?

[joyrider3774]

@pb66 do you have a local installation of emoncms ?

if so make backups first (just to be safe) of mysql database (or preferably use a seperate installation, so copy of the problematic install of emoncs and your mysql database if possible to test) and try this change then update the database:

It's a change i did to my local installation to prevent the problem i had with smaller values and getting the same value after rounding. As soon as i added that a long time ago i never had that problem again (with rounding errors). Also i don't know what it currently is set at, since i'm not using latest emoncms. I have it set to decimal(26,12) instead of double (but not sure if it's currently still set at double) . Also ignore the other change about null that's a leftover from when i was having problems with sql strict mode

[joyrider3774]

sorry it probably is not related to this as i read through the old forum thread describing this problem i had initially it seems the problem did not happen with people using redis. https://openenergymonitor.org/forum-archive/node/11774.html . I did not read thourougly enough

[TrystanLea]

@pb66 I imagine that changing the precision in mysql does not solve your problem as your using redis?

I've been trying to replicate the issue this morning, to no avail so far.
I started by setting up a test in emoncms (master branch, redis enabled, buffered writing enabled) with 2 feeds one starting at 0 kWh the other starting at 9950 kWh. I then setup a power_to_kwh processor on both and pushed the 9950 kWh feed over the 10,000 kWh mark. That seemed to work ok.

For my next step I have tried to isolate the issue down to the bare bones of the power_to_kwh accumulation process.

1. fetch last kwh value from redis
2. calculate the increment in kwh
3. add the increment to the last value
4. save the result in redis

Here is my test script:

<?php

$redis = new Redis();
$connected = $redis->connect("localhost");

// Initial starting values
$redis->set("test:kwh1",0);
$redis->set("test:kwh2",10000);

$seconds = 0;
while (true) {

    $power = 1000;
    $timeelapsed = 10;
    $seconds += $timeelapsed;

    $kwh1 = $redis->get("test:kwh1");
    $kwh2 = $redis->get("test:kwh2");

    $kwhinc = ($power * $timeelapsed) / 3600000;

    $kwh1 += $kwhinc;
    $kwh2 += $kwhinc;

    $redis->set("test:kwh1",$kwh1);
    $redis->set("test:kwh2",$kwh2);

    if (($seconds/86400)>=10.0) {
        print "Days: ".number_format($seconds/86400,1)."\n";
        print "kwhinc: ".$kwhinc."\n";
        print "kWh1: ".$kwh1."\n";
        print "kWh2: ".$kwh2."\n";
        die;
    }
}

Running this script simulating 10 days of accumulation for different power levels: 1W, 10, 100, 1000, 10000, 100000:

trystan@trystan:~/Desktop$ php roundtest.php 
Days: 10.0
kwhinc: 2.7777777777778E-6
kWh1: 0.24000000011927
kWh2: 10000.2400192
trystan@trystan:~/Desktop$ php roundtest.php 
Days: 10.0
kwhinc: 2.7777777777778E-5
kWh1: 2.4000000011927
kWh2: 10002.4000192
trystan@trystan:~/Desktop$ php roundtest.php 
Days: 10.0
kwhinc: 0.00027777777777778
kWh1: 24.000000011927
kWh2: 10024.0000192
trystan@trystan:~/Desktop$ php roundtest.php 
Days: 10.0
kwhinc: 0.0027777777777778
kWh1: 240.00000011927
kWh2: 10240.0000192
trystan@trystan:~/Desktop$ php roundtest.php 
Days: 10.0
kwhinc: 0.027777777777778
kWh1: 2400.0000011927
kWh2: 12400.0000192
trystan@trystan:~/Desktop$ php roundtest.php 
Days: 10.0
kwhinc: 0.27777777777778
kWh1: 24000.000011927
kWh2: 34000.0000192

Im not really seeing a big difference on the 10,000 kWh mark.
Starting at 1,000,000 kWh the issue starts to become more visible perhaps?

Days: 10.0
kwhinc: 2.7777777777778E-6
kWh1: 0.24000000011927
kWh2: 1000000.24192

[pb66]

Hi Trystan, I just came to post some real data values from the power-to-kwh process having changed the log settings and saw your post, so I haven't digested your tests yet.

These are small samples for a phptimeseries and a phpfina feed (I keep the phpfina just for use in the apps) as you can see they are the same data and results.

2017-04-20 10:21:06.559|WARN|process_processlist.php|power_to_kwh() feedid=100243 last_kwh=10004.3 kwh_inc=0.0070442777777778 new_kwh=10004.307044278 last_time=1492683660 time_now=1492683665
2017-04-20 10:21:12.233|WARN|process_processlist.php|power_to_kwh() feedid=100243 last_kwh=10004.3 kwh_inc=0.0084551333333333 new_kwh=10004.308455133 last_time=1492683665 time_now=1492683671
2017-04-20 10:21:17.927|WARN|process_processlist.php|power_to_kwh() feedid=100243 last_kwh=10004.3 kwh_inc=0.0056348555555556 new_kwh=10004.305634856 last_time=1492683671 time_now=1492683675
2017-04-20 10:21:23.655|WARN|process_processlist.php|power_to_kwh() feedid=100243 last_kwh=10004.3 kwh_inc=0.007020625 new_kwh=10004.307020625 last_time=1492683675 time_now=1492683680
2017-04-20 10:21:29.170|WARN|process_processlist.php|power_to_kwh() feedid=100243 last_kwh=10004.3 kwh_inc=0.008463 new_kwh=10004.308463 last_time=1492683680 time_now=1492683686
2017-04-20 10:21:40.167|WARN|process_processlist.php|power_to_kwh() feedid=100243  last_kwh=10004.3 kwh_inc=0.0084532666666667 new_kwh=10004.308453267 last_time=1492683690 time_now=1492683696

2017-04-20 10:21:06.560|WARN|process_processlist.php|power_to_kwh() feedid=100244 last_kwh=10004.3 kwh_inc=0.0070442777777778 new_kwh=10004.307044278 last_time=1492683660 time_now=1492683665
2017-04-20 10:21:12.235|WARN|process_processlist.php|power_to_kwh() feedid=100244 last_kwh=10004.3 kwh_inc=0.0084551333333333 new_kwh=10004.308455133 last_time=1492683665 time_now=1492683671
2017-04-20 10:21:17.928|WARN|process_processlist.php|power_to_kwh() feedid=100244 last_kwh=10004.3 kwh_inc=0.0056348555555556 new_kwh=10004.305634856 last_time=1492683671 time_now=1492683675
2017-04-20 10:21:23.656|WARN|process_processlist.php|power_to_kwh() feedid=100244 last_kwh=10004.3 kwh_inc=0.007020625 new_kwh=10004.307020625 last_time=1492683675 time_now=1492683680
2017-04-20 10:21:29.172|WARN|process_processlist.php|power_to_kwh() feedid=100244 last_kwh=10004.3 kwh_inc=0.008463 new_kwh=10004.308463 last_time=1492683680 time_now=1492683686
2017-04-20 10:21:40.168|WARN|process_processlist.php|power_to_kwh() feedid=100244 last_kwh=10004.3 kwh_inc=0.0084532666666667 new_kwh=10004.308453267 last_time=1492683690 time_now=1492683696

The problem seems to be the last_kwh=10004.3 never increases due to some rounding of the previous new_kwh value as suspected. But I cannot determine where that value comes from, yes I have redis installed but I would expect the value to also be persisted somewhere to survive a restart.

The "value" field in the mySQL feeds table doesn't seem to alter and the last recorded "value" seems to be 182.38 and last updated on Thu, 18 Aug 2016 14:08:05 GMT.

That would mean the root/initial value must be coming direct from the phpfina or phptimeseries datafiles directly does it not? if so since they are restricted to 32bit floats by design, would that dictate the datasize of the Redis field? (I'm guessing a bit here as I do not know how the Redis tables are defined)

I have checked and Redis is still enabled ok.

[TrystanLea]

Thanks @pb66, the power_to_kwh math runs independently of persistent storage most of the time, unless redis is cleared and then at that point emoncms gets the last value from the phpfina/phptimeseries file on disk.

Which means that the kwh accumulation should run independently of any precision limitations on the persistent storage side, it should even work if the resolution of the storage was 1 kWh.

Your logs suggest that the new value is not being saved to redis somehow... although I imagine the issue will be somewhere else..

do you think you could try checking if there is a redis entry for feed 100244 and what it reads?

$ redis-cli
$ hget feed:100244 value

[TrystanLea]

I wonder if you could also try running my test script above on your system to see if there are any underlying differences in the way php and redis handle floats on your system?

[pb66]

It looks like you are onto something there

pi@emoncmsPi:~ $ redis-cli
127.0.0.1:6379> hget feed:100244 value
(nil)
127.0.0.1:6379> hget feed:100243 value
(nil)

I just tried your script and the results for 1000 were

pi@emoncmsPi:~ $ php ./test_redis.php
Days: 10.0
kwhinc: 0.0027777777777778
kWh1: 251.97877777778
kWh2: 10000.002777778

[TrystanLea]

Great, do you see any entries in redis using:

keys *

[pb66]

Yes I have 3848 keys listed, that tallies with the admin page in emoncms too.
here is the last 10, the rest of the list looks much the same

3839) "emoncms:feed:100912"
3840) "emoncms:input:lastvalue:100248"
3841) "emoncms:input:100919"
3842) "emoncms:feed:101055"
3843) "emoncms:input:lastvalue:101137"
3844) "emoncms:feed:101017"
3845) "emoncms:input:100950"
3846) "emoncms:input:151"
3847) "emoncms:feed:100281"
3848) "emoncms:feed:101230"

[TrystanLea]

ah ok, your using the redis prefix. Could you try:

hget emoncms:feed:100244 value
hget emoncms:feed:100244 time

[pb66]

pi@emoncmsPi:~ $ redis-cli
127.0.0.1:6379> hget emoncms:feed:100244 value
"10004.5"
127.0.0.1:6379> hget emoncms:feed:100244 time
"1492688770"
127.0.0.1:6379>

Shouldn't that "feed:100244 value" be equal to the "new_kwh=" eg something like 10004.507044278 ? ie a higher precision?

[TrystanLea]

Ok that appears to be saving ok, although the precision of value is very low and similar to what your log file suggested.

It should look more like:

hget feed:3 value
"40.232192993164"

[pb66]

Running your script (mod'ed slightly to accept the power via command line and print the power to id the test) at 0.001 through to 10000000 gave these results

pi@emoncmsPi:~ $ php ./test_redis.php 0.001
Test Power: 0.001w
Days: 10.0
kwhinc: 2.7777777777778E-9
kWh1: 0.00025197877777778
kWh2: 10000.000000003

pi@emoncmsPi:~ $ php ./test_redis.php 0.01
Test Power: 0.01w
Days: 10.0
kwhinc: 2.7777777777778E-8
kWh1: 0.0025197877777778
kWh2: 10000.000000028

pi@emoncmsPi:~ $ php ./test_redis.php 0.1
Test Power: 0.1w
Days: 10.0
kwhinc: 2.7777777777778E-7
kWh1: 0.025197877777778
kWh2: 10000.000000278

pi@emoncmsPi:~ $ php ./test_redis.php 1
Test Power: 1w
Days: 10.0
kwhinc: 2.7777777777778E-6
kWh1: 0.25197877777778
kWh2: 10000.000002778

pi@emoncmsPi:~ $ php ./test_redis.php 10
Test Power: 10w
Days: 10.0
kwhinc: 2.7777777777778E-5
kWh1: 2.5197877777778
kWh2: 10000.000027778

pi@emoncmsPi:~ $ php ./test_redis.php 100
Test Power: 100w
Days: 10.0
kwhinc: 0.00027777777777778
kWh1: 25.197877777778
kWh2: 10000.000277778

pi@emoncmsPi:~ $ php ./test_redis.php 1000
Test Power: 1000w
Days: 10.0
kwhinc: 0.0027777777777778
kWh1: 251.97877777778
kWh2: 10000.002777778

pi@emoncmsPi:~ $ php ./test_redis.php 10000
Test Power: 10000w
Days: 10.0
kwhinc: 0.027777777777778
kWh1: 2519.7877777778
kWh2: 10000.027777778

pi@emoncmsPi:~ $ php ./test_redis.php 100000
Test Power: 100000w
Days: 10.0
kwhinc: 0.27777777777778
kWh1: 25197.877777778
kWh2: 35919.977777778

pi@emoncmsPi:~ $ php ./test_redis.php 1000000
Test Power: 1000000w
Days: 10.0
kwhinc: 2.7777777777778
kWh1: 251978.77777778
kWh2: 262770.77777778

pi@emoncmsPi:~ $ php ./test_redis.php 10000000
Test Power: 10000000w
Days: 10.0
kwhinc: 27.777777777778
kWh1: 2519787.7777778
kWh2: 2530587.7777778

Looking at these numbers and given the rounding to 2 decimals we're seeing it looks like it would need a power of ~2000w over the 10s period to increment (round up), since I am actually updating at 5s intervals it would probably need ~4000w power. However it wasn't incrementing at over 5500w the other day so I wonder if it's possible it's being truncated rather than rounded?