search

fboundy / pv_opt

Home Assistant PV Optimisation for Solis Inverters
Other
27 stars 6 forks source link

Optimizer appears to run multiple times per Cycle #308

Closed Pyinthesky99 closed 19 hours ago

Pyinthesky99 commented 4 days ago

Describe the bug Optimizer appears to run multiple times per Cycle

To Reproduce Runs every cycle

Expected behavior a single run of Optimizer per Cycle

Screenshots Word Search of pv_opt.log image

Desktop (please complete the following information):

Smartphone (please complete the following information): N/A

Additional context

pv_opt.log

stevebuk1 commented 3 days ago

Hmm I see what you mean. Every 10 minutes it runs 4 times in quick succession, then waits for the next 10 minute trigger.

12:40:37     INFO: Optimiser triggered by Scheduler
12:41:15     INFO: Optimiser triggered by Scheduler
12:41:53     INFO: Optimiser triggered by Scheduler

12:50:00     INFO: Optimiser triggered by Scheduler
12:50:38     INFO: Optimiser triggered by Scheduler
12:51:16     INFO: Optimiser triggered by Scheduler
12:51:53     INFO: Optimiser triggered by Scheduler

13:00:00     INFO: Optimiser triggered by Scheduler
13:00:40     INFO: Optimiser triggered by Scheduler
13:01:22     INFO: Optimiser triggered by Scheduler
13:02:03     INFO: Optimiser triggered by Scheduler 

13:10:00     INFO: Optimiser triggered by Scheduler
13:10:40     INFO: Optimiser triggered by Scheduler
13:11:21     INFO: Optimiser triggered by Scheduler
13:12:02     INFO: Optimiser triggered by Scheduler 

13:20:00     INFO: Optimiser triggered by Scheduler
13:20:40     INFO: Optimiser triggered by Scheduler
13:21:21     INFO: Optimiser triggered by Scheduler
13:22:02     INFO: Optimiser triggered by Scheduler 

13:30:00     INFO: Optimiser triggered by Scheduler
13:30:37     INFO: Optimiser triggered by Scheduler 
13:31:14     INFO: Optimiser triggered by Scheduler
13:31:51     INFO: Optimiser triggered by Scheduler

13:40:00     INFO: Optimiser triggered by Scheduler
13:40:36     INFO: Optimiser triggered by Scheduler
13:41:13     INFO: Optimiser triggered by Scheduler
13:41:50     INFO: Optimiser triggered by Scheduler
13:42:27     INFO: State change detected for switch.pvopt_read_only [config item: read_only] from off to on:

13:50:00     INFO: Optimiser triggered by Scheduler
13:50:36     INFO: Optimiser triggered by Scheduler
13:51:13     INFO: Optimiser triggered by Scheduler
13:51:49     INFO: Optimiser triggered by Scheduler
13:53:18     INFO: State change detected for switch.pvopt_read_only [config item: read_only] from on to off:

14:00:00     INFO: Optimiser triggered by Scheduler

Dashboard changes don't appear to be the issue - theres only 3 of these in the log, and they all trigger their own optimiser run, as they should, in any case the repeated triggers say they are the Scheduler.

In the most recent log you are showing 4 runs per 10 minutes, but other logs are showing two. However also have seen long periods where you get the desired one run per 10 minutes.

I think the first thing to try is a restart of AppDaemon ( not HA). Give it 1/2 hour to settle down If after that you are still seeing two (or more) iterations every 10 minutes add the letter "S" to the debug_categories in config.yaml, and post a log of that 1/2 hour later.

I suspect this might be going back to where we started on the integration where we were having problems getting Appdaemon up and running as it appeared to be in two different places? i.e. we may have two instances of Pv_opt being initialised that are resulting in duplicate Scheduler triggers.

Pyinthesky99 commented 3 days ago

Hello Steve. Have restarted Appdaemon and still duplicating Just debug: true debug_categories: O S

??

stevebuk1 commented 3 days ago

Not sure if it matters, but no space between O and S......

debug: true
debug_categories: OS
stevebuk1 commented 3 days ago

Also if you can post appdaemon.log (it might be called main.log) alongside Pv_opt.log once you have 1/2 hour of logging after making the debug_categories change above.

Pyinthesky99 commented 3 days ago

Made changes to config.yaml at 14:35 and it appears to have done one cycle OK at 14:40 and behaving itself every 10 minutes since.. typical!

appdaemon.log error.log pv_opt.log

I will flick a switch or slider and see if it changes things.

stevebuk1 commented 3 days ago

I think I know what it is. Flick forced discharge on and then off. (Or the other way around)

On Mon, 25 Nov 2024, 15:22 Pyinthesky99, @.***> wrote:

Made changes to config.yaml at 14:35 and it appears to have done one cycle OK at 14:40 and behaving itself every 10 minutes since.. typical!

appdaemon.log https://github.com/user-attachments/files/17905049/appdaemon.log error.log https://github.com/user-attachments/files/17905051/error.log pv_opt.log https://github.com/user-attachments/files/17905052/pv_opt.log

I will flick a switch or slider and see if it changes things.

— Reply to this email directly, view it on GitHub https://github.com/fboundy/pv_opt/issues/308#issuecomment-2498314562, or unsubscribe https://github.com/notifications/unsubscribe-auth/ASVRJMGDEVF7BJDIMZYRSUL2CM6CXAVCNFSM6AAAAABSMWBTMOVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDIOJYGMYTINJWGI . You are receiving this because you were assigned.Message ID: @.***>

Pyinthesky99 commented 3 days ago

Funnily enough, I flicked it to off just after 15:30, as the default is on and my current disposition is for it to be off, the Inverter at the same time had dropped off the net and it has doubled up ever since.. appdaemon.log error.log pv_opt.log

Pyinthesky99 commented 3 days ago

Apologies, it was optimise discharge off> Flicked it on and off and its now doing 4 optimise every 10 mins appdaemon.log error.log pv_opt.log Result!

stevebuk1 commented 3 days ago

Managed to reproduce it on my system. Its an old bug that schedules an optimiser run every 10 minutes if the Optimise Discharge button is toggled, or indeed any entity with "forced" in the internal variable name. I think its a hangover from a time where charging and discharging routines ran separately on their own schedule and if discharging wasn't needed it wouldn't be scheduled.

Fixed in 3.19.0-Beta-18:

https://github.com/fboundy/pv_opt/blob/dev/apps/pv_opt/pv_opt.py

Pyinthesky99 commented 3 days ago

Sorry, this one stopped on loading tariffs at 21:22:01 then on the 21:30 cycle it stopped on Optimising Charge Plan

pv_opt.log

stevebuk1 commented 3 days ago

Hmmm, strange, can you post error.log please?

Pyinthesky99 commented 3 days ago

Even worse now, copied back 'old' pv_opt.py and it stuck again , restarted HA still same, stopped Optimising Charge Plan, so now something more fundamental? error.log pv_opt.log

Pyinthesky99 commented 3 days ago

Just noticed Battery Capacity 10000, Inverter and Charger Power 3600 all changed. Also EV Charger turned on so reset but still currently no difference, stuck Edit,,, so not loading my Config.yaml? Edit... Stop-started Appdaemon again and now my defaults back

stevebuk1 commented 3 days ago

If Ev_charger was being set to Zappi this sounded more like you'd redownloaded the default config.yaml from the Dev repo. With no config.yaml, Ev_charger should default to none. But a config.yaml problem either way.

Pyinthesky99 commented 3 days ago

Hi Steve As per above did a long re-start of AppDaemon and now my defaults are back presumably from my config.yaml. Gave up on it last night at 11pm, last entry at 22:16 in log, At 1:26 it kicked off again but didn't do much. Turned logging to false in my config.yaml to ensure now using it and it ran but stopped at 09:26:13 INFO: Optimising for Solcast 20% confidence level Flicked logging back to true and saved but it didn't budge. Python key error in error.log at 1:26? appdaemon.log error.log pv_opt.log

Ran a backup of HA on the 19th, may have to go back to that.

Pyinthesky99 commented 2 days ago

Did a reboot of VM and when it came back EV Charger was set to Zappi. Set it back to none and my Inverter defaults came back to Normal as per my config.yaml. Still stopping at 11:29:30 INFO: Optimising for Solcast 50% confidence level forecast from 26-Nov 11:00 UTC to 27-Nov 23:30 UTC

Pyinthesky99 commented 2 days ago

Been out, was prepared to roll it back to 3xpy files you sent a few days ago, but it had gone to Idle! From last message above at 11:29:30 it did nothing until 14:30:08 when it burst into life and been doing 10 minute cycles ever since. pv_opt.log appdaemon.log error.log

stevebuk1 commented 2 days ago

Looking at where the log got to I think it's a problem with the Octopus website giving out Agile prices correctly. Another user also had similar issues.with the log freezing at that same point last night. I might add some more logging so it's a bit clearer what's gone wrong, should it happen again.

On Tue, 26 Nov 2024, 11:39 Pyinthesky99, @.***> wrote:

Did a reboot of VM and when it came back EV Charger was set to Zappi. Set it back to none and my Inverter defaults came back to Normal as per my config.yaml. Still stopping at 11:29:30 INFO: Optimising for Solcast 50% confidence level forecast from 26-Nov 11:00 UTC to 27-Nov 23:30 UTC

— Reply to this email directly, view it on GitHub https://github.com/fboundy/pv_opt/issues/308#issuecomment-2500440767, or unsubscribe https://github.com/notifications/unsubscribe-auth/ASVRJMCVNQAUYOGRBSEZ2OT2CRMXVAVCNFSM6AAAAABSMWBTMOVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDKMBQGQ2DANZWG4 . You are receiving this because you commented.Message ID: @.***>

Pyinthesky99 commented 2 days ago

Thanks Steve, I will give it a day or three to make sure it is stable, then apply Beta 18 again. Apologies for being a pedant, but py script for Beta 18 says at line 17 VERSION = "3.19.0-Beta-17" :-)

stevebuk1 commented 2 days ago

I like the fact you disabled all the logging - you've worked out that's where I make most of my errors ;-)

Good spot on the version number - corrected here, also added some more logging in case it happens again:

https://github.com/fboundy/pv_opt/blob/dev/apps/pv_opt/pv_opt.py https://github.com/fboundy/pv_opt/blob/dev/apps/pv_opt/pvpy.py

stevebuk1 commented 2 days ago

Did a reboot of VM and when it came back EV Charger was set to Zappi. Set it back to none and my Inverter defaults came back to Normal as per my config.yaml.

I'm intrigued about the Ev charger being set to zappi. Can you post your config.yaml please?

Pyinthesky99 commented 2 days ago

Certainly config.yaml.txt I don't think there is anything on there about a Zappi.

stevebuk1 commented 2 days ago

Agreed, nothing in there.

Pyinthesky99 commented 22 hours ago

Hi Steve. I loaded the two beta18 files at around 11:30 yesterday and restored OS logging in my config.yaml. I have toggled Include Export and Optimise Discharging several times and it is doing an optimise cycle just the once every 10 minutes. I am happy for this issue to be closed at this time and will await events.

The only thing left on Solarman V2 that is slightly out are the timing switches, as referenced in #273. They work but always report errors image because it's expecting hours and minutes but as soon as you enter the first number it kicks off a write?

Some sort of local storing of the times and a write button to commit them would be helpful but that would be a while down the road. There was something similar on a Dashboard posted on here but I think that was on a Solax Integration which appears a completely different beast. If you can point me in the right direction I can do some digging.

Thanks again for your help. Alan

Pyinthesky99 commented 22 hours ago

There's interesting, to tidy things up I uncommented the Comparing Tariffs at the bottom of config.yaml and this morning it kicked off good old 11:58! I think I will comment them out and remove the graph from the Dashboard. pv_opt.log

Edit.. It carried on at 12 after apparently stopping at 11:58 so did no harm. May leave it in and remove later if it causes a problem, obviously it's a feature!

stevebuk1 commented 22 hours ago

I've yet to run compare tariffs, but whilst investigating this I note it has its own scheduler separate from the 10 minute runs.

On Thu, 28 Nov 2024, 12:04 Pyinthesky99, @.***> wrote:

There's interesting, to tidy things up I uncommented the Comparing Tariffs at the bottom of config.yaml and this morning it kicked off good old 11:58! I think I will comment them out and remove the graph from the Dashboard. pv_opt.log https://github.com/user-attachments/files/17947732/pv_opt.log

Edit.. It carried on at 12 after apparently stopping at 11:58 so did no harm. May leave it in and remove later if it causes a problem, obviously it's a feature!

— Reply to this email directly, view it on GitHub https://github.com/fboundy/pv_opt/issues/308#issuecomment-2505961368, or unsubscribe https://github.com/notifications/unsubscribe-auth/ASVRJMGB446OSGMFWFIQTWT2C4BFHAVCNFSM6AAAAABSMWBTMOVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDKMBVHE3DCMZWHA . You are receiving this because you commented.Message ID: @.***>

Pyinthesky99 commented 21 hours ago

Have just added Cosy and it's 50p cheaper! image

Agile rates haven't been great the last few days, a lot of users switch from Agile to Cosy in the winter, will have to see how this winter pans out.

stevebuk1 commented 19 hours ago

I am happy for this issue to be closed at this time and will await events.

Ok, will close.

The only thing left on Solarman V2 that is slightly out are the timing switches, as referenced in #273. They work but always report errors image because it's expecting hours and minutes but as soon as you enter the first number it kicks off a write?

The code was changed to combine hours and minutes together so that a single write could be performed, so its not that. Please raise in a fresh issue and attach the complete log from where that screenshot came from and I'll investigate.