Getting spikes in emonCMS graph

[borpin (Brian Orpin)]

@djh

You mean I can fudge the results and sweep the bug under the carpet?

Shame on you! I’d rather try to see it fixed.

Bit harsh I feel; if you did, you can prove it solves the problem and that the process does not handle null values as expected and solve your data problems in the short term.

@djh

How to do that is part of the puzzle that goes over my head.

Just add another process line, with the wh_accumulator process to a new feed and select the other engine.

Personally, my next step would be to edit the code and put in a load of log messages with the various values at each stage and spot where the error (or problem with logic) occurs but YMMV.

[djh (Dave Howorth)]

@borpin

Bit harsh I feel; if you did, you can prove it solves the problem and that the process does not handle null values as expected and solve your data problems in the short term.

I don’t think there’s any other hypothesis been proposed has there? It seems pretty clear to me. I don’t care about short term; I want a permanent fix.

@borpin

Just add another process line, with the wh_accumulator process to a new feed and select the other engine.

Sorry, but I don’t understand what you mean.

@borpin

Personally, my next step would be to edit the code and put in a load of log messages with the various values at each stage and spot where the error (or problem with logic) occurs but YMMV.

Me too, but I don’t know how PHP works. Do I need to restart something, and if so what? And what if I cock up the edits and the thing won’t start; how do I recover? I’d rather not experiment on my own production system.

[djh (Dave Howorth)]

I had a thought. Is it possible to run an emoncms system in a simulation mode? I could run a copy on my PC and I already have a load of data that show the problem, if only I can play them back and feed them into a new wh_accumulator. Then I don’t care about the emoncms installation or all the data copies; I can just throw them away afterwards.

[borpin (Brian Orpin)]

@djh

The nulls are not the problem. The whole point of phpfina, as I understand it is to minimise writes and increase efficiency. It does that by writing nulls, which are essential for it to keep the time stamps accurate. So nulls are to be be expected in the underlying data.

Been thinking about this. I had a similar query which was answered very well here (in terms of how a fixed interval feed worked). So in one way you are right about nulls.

@djh

The problem is what wh_accumulator (in conjunction with the phpfina engine) does with those nulls.

I think though, the writing of nulls to the feed by the engine as it realises there are gaps, and the sending of nulls to the process, may have different results. I’ve tried to work through the code and actually cannot reconcile what you are seeing in the feed, with what I think should be written (I think that an input null should result in the last value in the feed being written back to the feed). Without inserting some debug log code it is impossible to do any more (and I do not have a pulse counter).

You could check my theory by skipping incoming nulls…

I’m not sure if the screenshot above is showing the actual data feed values or interpolated values. There is a way of extracting just the values actually written to the feed in the link above to be sure.

[TrystanLea]

This is interesting, it took me until your screenshot yesterday to realise I’d seen similar, I have been meaning to look into it. I had not noticed the correlation with missing datapoints on the source input (null values).

I have an emontx which misses 4-5% of radio packets and you can see the same dips on its kWh feed:

The dips don’t appear to affect the cumulative total, the datapoint after the dip continues as expected.

Adding logging to the power_to_kwh process, highlighting here where a missing datapoint occurs and the interval jumps from 10s to 20s. The result again suggest that the cumulative total is correctly calculated (there is no sign of the dip at this point, the last kwh value carries over to the next kwh increment calculation after the missing datapoint).

2018-12-18 08:56:18.866|ERROR|process_processlist.php|165111 now: 1545123378 1417 last:{"time":1545123368,"value":473.47169667258}
2018-12-18 08:56:18.867|ERROR|process_processlist.php|time_elapsed: 10
2018-12-18 08:56:18.867|ERROR|process_processlist.php|kwh_inc: 0.0039361111111111
2018-12-18 08:56:18.867|ERROR|process_processlist.php|new_kwh: 473.47563278369
2018-12-18 08:56:18.868|ERROR|process_processlist.php|insert: 1545123378 473.47563278369
2018-12-18 08:56:38.894|ERROR|process_processlist.php|165111 now: 1545123398 1391 last:{"time":1545123378,"value":473.47563278369}
2018-12-18 08:56:38.894|ERROR|process_processlist.php|time_elapsed: 20
2018-12-18 08:56:38.895|ERROR|process_processlist.php|kwh_inc: 0.0077277777777778
2018-12-18 08:56:38.895|ERROR|process_processlist.php|new_kwh: 473.48336056147
2018-12-18 08:56:38.895|ERROR|process_processlist.php|insert: 1545123398 473.48336056147
2018-12-18 08:56:48.971|ERROR|process_processlist.php|165111 now: 1545123408 1377 last:{"time":1545123398,"value":473.48336056147}
2018-12-18 08:56:48.971|ERROR|process_processlist.php|time_elapsed: 10
2018-12-18 08:56:48.972|ERROR|process_processlist.php|kwh_inc: 0.003825
2018-12-18 08:56:48.972|ERROR|process_processlist.php|new_kwh: 473.48718556147
2018-12-18 08:56:48.972|ERROR|process_processlist.php|insert: 1545123408 473.48718556147

Which suggests that the problem is located in the way padding is written inside PHPFINA.
I may have now found the issue. Testing to see if that’s the case at the moment.

[djh (Dave Howorth)]

@borpin

I had a similar query which was answered very well here (in terms of how a fixed interval feed worked).

Yes, except for the detail that the entries in the file are actually floats, so four bytes long, not single bytes.

@borpin

I think though, the writing of nulls to the feed by the engine as it realises there are gaps, and the sending of nulls to the process, may have different results.

Sorry, I don’t understand what you mean here.

@borpin

I’ve tried to work through the code and actually cannot reconcile what you are seeing in the feed, with what I think should be written (I think that an input null should result in the last value in the feed being written back to the feed). Without inserting some debug log code it is impossible to do any more (and I do not have a pulse counter).

Yes, I haven’t managed to spot the error by reading the code either, and nor has anybody else apparently. So I agree about the need for debugging. Any thoughts about running a simulation?

@borpin

I’m not sure if the screenshot above is showing the actual data feed values or interpolated values. There is a way of extracting just the values actually written to the feed in the link above to be sure.

I wrote a small perl program to read the data files directly, so I’m confident that the data we’re seeing is genuine. All the feeds are written at 10s intervals, so it’s esy to adjust for interpolation if necessary.

[borpin (Brian Orpin)]

@djh

borpin:

I think though, the writing of nulls to the feed by the engine as it realises there are gaps, and the sending of nulls to the process, may have different results.

Sorry, I don’t understand what you mean here.

Stepping through the code, if a null is received by the accumulator process, it writes something to the feed (in theory the last feed value). If the process does not get the null, it obviously does nothing so the feed will be padded with nulls.

[TrystanLea]

I think I’ve managed to fix it, here’s the proposed changes to the code which I will merge after a little more testing: fix padding spikes where input feed has null value by TrystanLea · Pull Request #1140 · emoncms/emoncms · GitHub

Would you be able to test and verify that it fixes the issue as well @djh?

The steps to switch over to this branch are:

cd /var/www/emoncms
git pull
git checkout fix_padding_spikes
sudo service feedwriter restart

[djh (Dave Howorth)]

@TrystanLea

I think I’ve managed to fix it

Thanks Trystan. I’m happy to give it a try after a few questions:
(1) how do I back it out if I mess it up?
(2) do I need to do anything else later to get back to a ‘standard’ system (e.g. at time of next update)?
(3) what’s the point of the $log->error(“Starting feedwriter script”); change? It doesn’t seem like an error situation.

If it works, you probably want to update my bug as well.

[borpin (Brian Orpin)]

@djh

(1) how do I back it out if I mess it up?

Do you know which git branch you are on? If you are new to git, the command git status will tell you that.

If you have made any changes to any files, that command will tell you (other than the settings file) and you’ll need to do some other stuff (I expect not though).

The commands above

• git pull brings any changes down from the emoncms repository.
• git checkout <branch> switches the current code base to a different branch - you will either currently be on master or more likely stable. To get back it is simply git checkout <branch> which takes you back (by the magic of git) to the original code. However, when you do that you will end up without the fix (until it is brought into the main branches).

@djh

(2) do I need to do anything else later to get back to a ‘standard’ system

In the Emoncms GitHub repository, there are 2 main branches: master - the cutting edge branch where there is a slight risk things will break, and stable which is updated less frequently. I’d expect the SD card to be on stable (but I could be wrong). In order to maintain the changes you will need to stay on at least master until a new stable release is made but a git checkout will take you back

You can update at any time with a git pull but this only updates the core emoncms and not all the Modules.

[TrystanLea]

Good description @borpin.

Yes emonSD is on stable. To return to the stable branch the command as @borpin explained is:

git checkout stable

@djh

(3) what’s the point of the $log->error(“Starting feedwriter script”); change? It doesn’t seem like an error situation.

I find it useful to have start events recorded to the log, perhaps ideally we would define another log level e.g important(“Starting feedwriter script”);… but its not a strictly needed change.

[djh (Dave Howorth)]

Thanks both. I’ve switched branch and it appears to be working so far.