DataYours - only getting initial change, not duration?

Plugins & Plugin Development DataYours
#1

I’m trying to log run time using the ModeState of the thermostat with DataYours under openLuup. This was working well, but it has recently changed behavior to only logging the start of the change and does not log the entire time the HVAC is running. I’ve attached a picture showing what I mean. You can see by the variable history when the thermostat started the cooling and when it stopped, but the graph shows only the starting time lasting for one minute. It should show the duration of the run time.

Storage-schema has:[hvac] pattern = \.hvac$ retentions = 1m:3d, 24h:1y Storage-aggregation has:[HVAC] pattern = \.hvac$ xFilesFactor = 0 aggregationMethod = sum Data Translation has:[*.urn:micasaverde-com:serviceId:HVAC_OperatingState1.ModeState] Cooling = -1 Idle = 0 Heating = 1

What could I have set incorrectly?

I’m running 2056 of AltUI and openLuup is 2016.12.12, v17.3.3. DataYours: 17.4.17.

#2

Have you changed anything recently (opebLuup version, etc.)?

#3

[quote=“akbooer, post:2, topic:196525”]Have you changed anything recently (opebLuup version, etc.)?[/quote]Same openLuup for quite some time. I have added other variables to the DataYours storage, but nothing that should interfere as far as I can tell (not sure how to tell if I mistakenly did something wrong with this). I believe I’ve updated AltUI a couple of times recently. I’m trying the 2066 as of today - I’ll see if that changes anything.

#4

What does AltUI’s history tell you for the actual value of the variable?

#5

AltUI’s history looks correct in the screenshot I attached to the first post. Goes from Idle to Cooling at 15:10 and back to Idle at 15:21. Then Cooling again at 15:28. That all looks fine. I should be able to find this in the whisper database, correct? It’s just a series of time stamps and data? If so, I should see the 3 in the AltUI history? Or does the database convert those to the once per minute that the database is set to? In which case I’m looking for the time span from 15:10 to 15:28 with one entry per minute?

#6

This is a job for the log file… need to see what is really going on, whether callbacks are made and when, etc.

Are you sure you’ve changed nothing in the configuration?

#7

Let’s answer the latter question first: No, I’m not at all sure I didn’t change something. I’m frequently making changes, but I also don’t know what I did that may have broken this. It’s been relatively cool here until the heat wave that just started, so I didn’t notice the issue because the HVAC hasn’t been running in over a month. Now it’s running way too much to try to keep us cool. I’ve been adding other variables to be stored with different aggregation and schema. I don’t see any overlap. Also, I thought these are only read when starting a new data storage area?

Here’s a sample log showing the switch from Idle to Cool and then later back from Cool to Idle. At 18:42:47.738 the ModeState changes, and I see a call back at 18:42:48.273. It goes from Cool to Idle at 18:48:59.563, call back at 18:49:00.077. AltUI Watch Display shows the single spike for one minute at 18:42, similar to what I put in the initial post. The .wsp file doesn’t seem to be time ordered, so it’s a little hard for me to see what is going on in there.

AltUI history says change from Idle to Cooling at 18:42:47.739 and from Cooling to Idle at 18:48:59.564. Seems remarkably close to ModeState changing in the log file. That seems fine.

Does my usage of ‘sum’ for the aggregation affect this in any way?

2017-06-20 18:42:00.208 luup.variable_set:0: 2.openLuup.Memory_Mb was: 3.7 now: 4.8 #hooks:1 2017-06-20 18:42:00.208 luup.variable_set:0: 2.openLuup.CpuLoad was: 2.3 now: 2.3 #hooks:1 2017-06-20 18:42:00.208 luup.variable_set:0: 2.openLuup.Uptime_Days was: 2.22 now: 2.22 #hooks:1 2017-06-20 18:42:00.209 luup.variable_set:0: 2.urn:upnp-org:serviceId:altui1.DisplayLine1 was: 4 Mb, cpu 2.3%, 2.22 days now: 5 Mb, cpu 2.3%, 2.22 days #hooks:0 2017-06-20 18:42:00.209 luup_log:0: 5 Mb, cpu 2.3%, 2.22 days 2017-06-20 18:42:00.210 luup.variable_set:0: 2.openLuup.MemFree_Mb was: 103.6 now: 102.2 #hooks:0 2017-06-20 18:42:00.210 luup.variable_set:0: 2.openLuup.MemAvail_Mb was: 389.8 now: 388.4 #hooks:0 2017-06-20 18:42:00.210 luup.variable_set:0: 2.openLuup.MemTotal_Mb was: 947.7 now: 947.7 #hooks:0 2017-06-20 18:42:00.210 luup.watch_callback:: 2.openLuup.Memory_Mb function: 0x907cf8 2017-06-20 18:42:00.221 luup.watch_callback:: 2.openLuup.CpuLoad function: 0x907cf8 2017-06-20 18:42:00.234 luup.watch_callback:: 2.openLuup.Uptime_Days function: 0x907cf8 2017-06-20 18:42:47.648 luup.variable_set:18: 18.urn:upnp-org:serviceId:TemperatureSensor1.CurrentTemperature was: 78.5 now: 79 #hooks:1 2017-06-20 18:42:47.648 luup_log:18: setOpenHabItem payload is 79 2017-06-20 18:42:47.738 luup.variable_set:18: 41.urn:micasaverde-com:serviceId:HVAC_OperatingState1.ModeState was: Idle now: Cooling #hooks:1 2017-06-20 18:42:47.739 luup.call_action:18: 41.urn:upnp-org:serviceId:VSwitch1.SetText2 2017-06-20 18:42:47.740 luup.variable_set:41: 41.urn:upnp-org:serviceId:VSwitch1.Text2 was: Idle now: Cooling #hooks:0 2017-06-20 18:42:47.741 luup.call_action:18: 41.urn:upnp-org:serviceId:VSwitch1.SetTarget 2017-06-20 18:42:47.742 luup.variable_set:41: 41.urn:upnp-org:serviceId:VSwitch1.Status was: 0 now: 1 #hooks:0 2017-06-20 18:42:47.743 luup.variable_set:41: 41.urn:upnp-org:serviceId:SwitchPower1.Status was: 0 now: 1 #hooks:0 2017-06-20 18:42:47.744 luup.call_action:18: 41.urn:upnp-org:serviceId:VSwitch1.SetText1 2017-06-20 18:42:47.745 luup.variable_set:41: 41.urn:upnp-org:serviceId:VSwitch1.Text1 was: OFF now: ON #hooks:0 2017-06-20 18:42:47.746 luup.call_timer:18: interval: time=1m, days={} 2017-06-20 18:42:48.249 luup.watch_callback:: 18.urn:upnp-org:serviceId:TemperatureSensor1.CurrentTemperature function: 0x907cf8 2017-06-20 18:42:48.273 luup.watch_callback:: 41.urn:micasaverde-com:serviceId:HVAC_OperatingState1.ModeState function: 0x907cf8 2017-06-20 18:43:49.466 luup.call_timer:18: interval: time=1m, days={} 2017-06-20 18:43:58.855 luup.variable_set:21: 21.urn:akbooer-com:serviceId:DataYours1.AppMemoryUsed was: 7362 now: 5850 #hooks:0 2017-06-20 18:44:00.454 luup.variable_set:0: 2.openLuup.Memory_Mb was: 4.8 now: 3.1 #hooks:1 2017-06-20 18:44:00.454 luup.variable_set:0: 2.openLuup.CpuLoad was: 2.3 now: 2.4 #hooks:1 2017-06-20 18:44:00.455 luup.variable_set:0: 2.openLuup.Uptime_Days was: 2.22 now: 2.22 #hooks:1 2017-06-20 18:44:00.455 luup.variable_set:0: 2.urn:upnp-org:serviceId:altui1.DisplayLine1 was: 5 Mb, cpu 2.3%, 2.22 days now: 3 Mb, cpu 2.4%, 2.22 days #hooks:0 2017-06-20 18:44:00.456 luup_log:0: 3 Mb, cpu 2.4%, 2.22 days 2017-06-20 18:44:00.457 luup.variable_set:0: 2.openLuup.MemFree_Mb was: 102.2 now: 104.1 #hooks:0 2017-06-20 18:44:00.457 luup.variable_set:0: 2.openLuup.MemAvail_Mb was: 388.4 now: 390.2 #hooks:0 2017-06-20 18:44:00.458 luup.variable_set:0: 2.openLuup.MemTotal_Mb was: 947.7 now: 947.7 #hooks:0 2017-06-20 18:44:00.458 luup.watch_callback:: 2.openLuup.Memory_Mb function: 0x907cf8 2017-06-20 18:44:00.481 luup.watch_callback:: 2.openLuup.CpuLoad function: 0x907cf8 2017-06-20 18:44:00.505 luup.watch_callback:: 2.openLuup.Uptime_Days function: 0x907cf8 2017-06-20 18:44:51.548 luup.call_timer:18: interval: time=1m, days={} 2017-06-20 18:45:46.295 luup.call_timer:20: interval: time=300, days={} 2017-06-20 18:45:47.373 luup.variable_set:20: 20.urn:micasaverde-com:serviceId:EnergyMetering1.PriorKWH was: 33781.221 now: 33781.221 #hooks:0 2017-06-20 18:45:47.374 luup.variable_set:20: 20.urn:micasaverde-com:serviceId:EnergyMetering1.KWH was: 33781.221 now: 33781.541 #hooks:1 2017-06-20 18:45:47.374 luup.variable_set:20: 20.urn:micasaverde-com:serviceId:EnergyMetering1.DeltaKWH was: 0.000 now: 0.320 #hooks:1 2017-06-20 18:45:47.374 luup.variable_set:20: 20.urn:micasaverde-com:serviceId:EnergyMetering1.Watts was: 506 now: 5954 #hooks:1 2017-06-20 18:45:47.875 luup.watch_callback:: 20.urn:micasaverde-com:serviceId:EnergyMetering1.KWH function: 0x907cf8 2017-06-20 18:45:47.887 luup.watch_callback:: 20.urn:micasaverde-com:serviceId:EnergyMetering1.DeltaKWH function: 0x907cf8 2017-06-20 18:45:47.898 luup.watch_callback:: 20.urn:micasaverde-com:serviceId:EnergyMetering1.Watts function: 0x907cf8 2017-06-20 18:45:53.219 luup.variable_set:18: 18.urn:upnp-org:serviceId:TemperatureSensor1.CurrentTemperature was: 79 now: 78.5 #hooks:1 2017-06-20 18:45:53.219 luup_log:18: setOpenHabItem payload is 78.5 2017-06-20 18:45:53.240 luup.call_timer:18: interval: time=1m, days={} 2017-06-20 18:45:53.743 luup.watch_callback:: 18.urn:upnp-org:serviceId:TemperatureSensor1.CurrentTemperature function: 0x907cf8 2017-06-20 18:46:00.541 luup.variable_set:0: 2.openLuup.Memory_Mb was: 3.1 now: 4.8 #hooks:1 2017-06-20 18:46:00.542 luup.variable_set:0: 2.openLuup.CpuLoad was: 2.4 now: 2.3 #hooks:1 2017-06-20 18:46:00.542 luup.variable_set:0: 2.openLuup.Uptime_Days was: 2.22 now: 2.22 #hooks:1 2017-06-20 18:46:00.542 luup.variable_set:0: 2.urn:upnp-org:serviceId:altui1.DisplayLine1 was: 3 Mb, cpu 2.4%, 2.22 days now: 5 Mb, cpu 2.3%, 2.22 days #hooks:0 2017-06-20 18:46:00.543 luup_log:0: 5 Mb, cpu 2.3%, 2.22 days 2017-06-20 18:46:00.544 luup.variable_set:0: 2.openLuup.MemFree_Mb was: 104.1 now: 103.1 #hooks:0 2017-06-20 18:46:00.544 luup.variable_set:0: 2.openLuup.MemAvail_Mb was: 390.2 now: 389.2 #hooks:0 2017-06-20 18:46:00.545 luup.variable_set:0: 2.openLuup.MemTotal_Mb was: 947.7 now: 947.7 #hooks:0 2017-06-20 18:46:00.545 luup.watch_callback:: 2.openLuup.Memory_Mb function: 0x907cf8 2017-06-20 18:46:00.566 luup.watch_callback:: 2.openLuup.CpuLoad function: 0x907cf8 2017-06-20 18:46:00.589 luup.watch_callback:: 2.openLuup.Uptime_Days function: 0x907cf8 2017-06-20 18:46:55.369 luup.call_timer:18: interval: time=1m, days={} 2017-06-20 18:47:57.449 luup.call_timer:18: interval: time=1m, days={} 2017-06-20 18:48:00.039 luup.variable_set:0: 2.openLuup.Memory_Mb was: 4.8 now: 5.3 #hooks:1 2017-06-20 18:48:00.039 luup.variable_set:0: 2.openLuup.CpuLoad was: 2.3 now: 2.2 #hooks:1 2017-06-20 18:48:00.040 luup.variable_set:0: 2.openLuup.Uptime_Days was: 2.22 now: 2.22 #hooks:1 2017-06-20 18:48:00.040 luup.variable_set:0: 2.urn:upnp-org:serviceId:altui1.DisplayLine1 was: 5 Mb, cpu 2.3%, 2.22 days now: 5 Mb, cpu 2.2%, 2.22 days #hooks:0 2017-06-20 18:48:00.040 luup_log:0: 5 Mb, cpu 2.2%, 2.22 days 2017-06-20 18:48:00.041 luup.variable_set:0: 2.openLuup.MemFree_Mb was: 103.1 now: 104.1 #hooks:0 2017-06-20 18:48:00.041 luup.variable_set:0: 2.openLuup.MemAvail_Mb was: 389.2 now: 390.3 #hooks:0 2017-06-20 18:48:00.041 luup.variable_set:0: 2.openLuup.MemTotal_Mb was: 947.7 now: 947.7 #hooks:0 2017-06-20 18:48:00.041 luup.watch_callback:: 2.openLuup.Memory_Mb function: 0x907cf8 2017-06-20 18:48:00.052 luup.watch_callback:: 2.openLuup.CpuLoad function: 0x907cf8 2017-06-20 18:48:00.065 luup.watch_callback:: 2.openLuup.Uptime_Days function: 0x907cf8 2017-06-20 18:48:59.541 luup.variable_set:18: 18.urn:upnp-org:serviceId:TemperatureSensor1.CurrentTemperature was: 78.5 now: 78 #hooks:1 2017-06-20 18:48:59.542 luup_log:18: setOpenHabItem payload is 78 2017-06-20 18:48:59.563 luup.variable_set:18: 41.urn:micasaverde-com:serviceId:HVAC_OperatingState1.ModeState was: Cooling now: Idle #hooks:1 2017-06-20 18:48:59.564 luup.call_action:18: 41.urn:upnp-org:serviceId:VSwitch1.SetText2 2017-06-20 18:48:59.564 luup.variable_set:41: 41.urn:upnp-org:serviceId:VSwitch1.Text2 was: Cooling now: Idle #hooks:0 2017-06-20 18:48:59.564 luup.call_action:18: 41.urn:upnp-org:serviceId:VSwitch1.SetTarget 2017-06-20 18:48:59.564 luup.variable_set:41: 41.urn:upnp-org:serviceId:VSwitch1.Status was: 1 now: 0 #hooks:0 2017-06-20 18:48:59.564 luup.variable_set:41: 41.urn:upnp-org:serviceId:SwitchPower1.Status was: 1 now: 0 #hooks:0 2017-06-20 18:48:59.564 luup.call_action:18: 41.urn:upnp-org:serviceId:VSwitch1.SetText1 2017-06-20 18:48:59.565 luup.variable_set:41: 41.urn:upnp-org:serviceId:VSwitch1.Text1 was: ON now: OFF #hooks:0 2017-06-20 18:48:59.565 luup.call_timer:18: interval: time=1m, days={} 2017-06-20 18:49:00.066 luup.watch_callback:: 18.urn:upnp-org:serviceId:TemperatureSensor1.CurrentTemperature function: 0x907cf8 2017-06-20 18:49:00.077 luup.watch_callback:: 41.urn:micasaverde-com:serviceId:HVAC_OperatingState1.ModeState function: 0x907cf8 2017-06-20 18:49:00.144 luup.variable_set:21: 21.urn:akbooer-com:serviceId:DataYours1.AppMemoryUsed was: 5850 now: 6153 #hooks:0 2017-06-20 18:50:01.282 luup.call_timer:18: interval: time=1m, days={} 2017-06-20 18:50:01.783 luup.variable_set:0: 2.openLuup.Memory_Mb was: 5.3 now: 4 #hooks:1 2017-06-20 18:50:01.784 luup.variable_set:0: 2.openLuup.CpuLoad was: 2.2 now: 2.4 #hooks:1 2017-06-20 18:50:01.784 luup.variable_set:0: 2.openLuup.Uptime_Days was: 2.22 now: 2.22 #hooks:1 2017-06-20 18:50:01.784 luup.variable_set:0: 2.urn:upnp-org:serviceId:altui1.DisplayLine1 was: 5 Mb, cpu 2.2%, 2.22 days now: 4 Mb, cpu 2.4%, 2.22 days #hooks:0 2017-06-20 18:50:01.785 luup_log:0: 4 Mb, cpu 2.4%, 2.22 days

And, as always, thanks again for all of your help!

#8

So these logs show that all is as to be expected. However, inspiration has struck…

Can you modify the graphic URL to read:

/data_request?id=lr_render&target={0}&hideLegend=true&height=250&from=-2h&lineMode=staircase&drawNullAs=hold

If this works, then I struggle to see how you can have ever seen any different result.

My recommendation for quantised data (and some others) is always to use staircase mode and to fill any missing gaps with the previous value.

I’m also doubtful of the utility of the “sum” aggregation in this case, but that’s a separate argument.

#9

You are correct, with the options you mention, I see what I consider the correct chart. But there is something else to this. Take a look at the Grafana plot attached to this post. Through April and May it was coalescing the data into daily sums of run time properly. Now it appears to be counting the number of times the hvac turns on instead of total run time. (I’m currently using much more run time than this graph is showing as it is very hot here. The earlier run times in May are correct.) So while I may have altered the graphic URL at some point (although I don’t think I did other than change the time span), I don’t see how I could have affected what Grafana shows in the same graph. Something must have changed in the way the data is getting stored into the database?

#10

Good. Neither I nor openLuup have lost their mind, then.

Take a look at the Grafana plot attached to this post. Through April and May it was coalescing the data into daily sums of run time properly.

Helpful plot, and I see its utility. In normal circumstances, this should show you the total number of hour of heating or cooling. Of course, if there’s a mixture, then it will show you only the excess, one way or the other. However, for most circumstances, perhaps what you want.

Whilst not contesting that you successfully produced this plot, I have to say that I see absolutely no way that it could have been done with exactly the setup you describe. What is being plotted at the moment is the way that it is supposed to work. However, we have to bear in mind that the DataYours plot in AltUI that you showed originally, is not the same as the Grafana plot you’ve just posted, and the processing could be different.

So while I may have altered the graphic URL at some point (although I don't think I did other than change the time span), I don't see how I could have affected what Grafana shows in the same graph.

I very, very much doubt that you did that. The settings are a bit obscure, and there was probably no easy way to know what they should be to give this result in the first place. One thing you could try is to change the duration scale from 2 hours to , say, 30 days, and see what it looks like… (that is, it should cover the period where you saw it working correctly.)

Something must have changed in the way the data is getting stored into the database?

Indeed (if it is, in fact, the database data which has changed.) My only suggestion now, is that you are not logging (with Grafana) the variable that you think you are logging. The only way to get openLuup/Vera/DataYours to write a file with the data that you need to accumulate the run times correctly is to have a separate piece of code (perhaps startup, or scene) which polls the state every minute and writes it to an archive. The ‘trigger-on-change’ behaviour of standard device watches will never do this.

I’ve used, and posted, several time on bits of code to do this sort of thing. Have you got something of the same running somewhere in the background?

What, by the way, are the plotting options you have set in Grafana? Did the AltUI plot ever look the same?

#11

Okay, I know what I changed and I can get the original behavior. But I’m not quite sure why this new way doesn’t work…

Originally I had multiple devices that were polling sensors (this HVAC state, indoor/outdoor temps, etc.) but the openLuup logs were filling up with not very useful log information. So I went on a clean up binge and changed the devices to only set the variables when the values changed. This worked fine for temperature and greatly reduced logging, but you are reading the result for the HVAC state.

So why doesn’t this work for the HVAC state? If the database doesn’t receive a change, doesn’t it assume that the value hasn’t changed? It seems odd to me that it assumes the unlogged values are zeroes. I see that this is what your suggestion to “draw null values as hold” resolves. For my purposes I will restore my older method, but wouldn’t it make sense to be able to only log values when something changes?

Yes, I’m aware that the mixture of these values will result in some getting nulled out, but fortunately I live in a very mild climate and the overlap is minimal. Some day I may separate these into 2 separate plot lines…

#12

Phew!

So why doesn't this work for the HVAC state? If the database doesn't receive a change, doesn't it assume that the value hasn't changed? It seems odd to me that it assumes the unlogged values are zeroes.

What we’re dealing with here is a mixture of three things at least:

[ol][li]Vera/Luup behaviour of variables and logs (which openLuup has to emulate)[/li]
[li]The Whisper database paradigm (an industry standard, which DataYours uses) including aggregation[/li]
[li]Plotting / post-processing and data interpretation[/li][/ol]

Data is logged when variables are written. Variable watch triggers are (generally) activated when data changes. Data may to written to a Whisper archive at any time, but the way it’s handled depends on the storage schema and aggregation function. Crucially, temperature data and the like, I have configured to be averaged across archives by default. The averaging function is only done on non-null values (part of the defined Whisper standard) as is the sum aggregation but this leads to very different behaviour when you come to interpret the result. Plotting the average gives the expected result. Plotting the sum gives, as you have seen, an unexpected result if there are null values present, simply because the interval is not fully populated.

For my purposes I will restore my older method, ...

…for only ‘state’-like variables, i assume.

...but wouldn't it make sense to be able to only log values when something changes?

As described above, that’s exactly what happens. It’s what happens after that which has tripped us up here.

Glad (very glad) you have it sorted.