search

fboundy / pv_opt

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

Errors in AppDaemon Log - PV-Opt ceases to run #299

Closed punkymuzzle closed 6 days ago

punkymuzzle commented 1 week ago

Describe the bug After running for a while, PV-Opt seems to stop running and does not set charging slots. Log extract from AppDaemon:


/homeassistant/appdaemon/apps/pv_opt/pv_opt.py:2385: SettingWithCopyWarning: 
A value is trying to be set on a copy of a slice from a DataFrame.
Try using .loc[row_indexer,col_indexer] = value instead
See the caveats in the documentation: https://pandas.pydata.org/pandas-docs/stable/user_guide/indexing.html#returning-a-view-versus-a-copy
  y["start"] = y.index.tz_convert(self.tz)
/homeassistant/appdaemon/apps/pv_opt/pv_opt.py:2386: SettingWithCopyWarning: 
A value is trying to be set on a copy of a slice from a DataFrame.
Try using .loc[row_indexer,col_indexer] = value instead
See the caveats in the documentation: https://pandas.pydata.org/pandas-docs/stable/user_guide/indexing.html#returning-a-view-versus-a-copy
  y["end"] = y.index.tz_convert(self.tz) + pd.Timedelta(30, "minutes")

Error Log is showing the following:

18:20:05 WARNING pv_opt: ------------------------------------------------------------
09:03:12 WARNING pv_opt: ------------------------------------------------------------
09:03:12 WARNING pv_opt: Unexpected error running initialize() for pv_opt
09:03:12 WARNING pv_opt: ------------------------------------------------------------
09:03:12 WARNING pv_opt: Traceback (most recent call last):
  File "/usr/lib/python3.11/site-packages/appdaemon/app_management.py", line 162, in initialize_app
    await utils.run_in_executor(self, init)
  File "/usr/lib/python3.11/site-packages/appdaemon/utils.py", line 304, in run_in_executor
    response = future.result()
               ^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/appdaemon/adbase.py", line 35, in f_app_lock
    return f(*args, **kw)
           ^^^^^^^^^^^^^^
  File "/homeassistant/appdaemon/apps/pv_opt/pv_opt.py", line 631, in initialize
    self._status(e)
  File "/homeassistant/appdaemon/apps/pv_opt/pv_opt.py", line 2074, in _status
    entity_id = f"sensor.{self.prefix.lower()}_status"
                          ^^^^^^^^^^^
AttributeError: 'PVOpt' object has no attribute 'prefix'

09:03:12 WARNING pv_opt: ------------------------------------------------------------

Logs attached also error.log main.log pv_opt.log

Screenshot attached below:

To Reproduce

Expected behaviour

Screenshots Charging schedule (ignore the 1 W charge setting, working with @stevebuk1 on #284) image

Desktop (please complete the following information):

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

Additional context

stevebuk1 commented 1 week ago

Is this with the Beta release that we are testing in #284?

If so, can you install the production version, wait a few hours and repost the logs, especially main.log.

Basically Appdaemon is reporting your system is taking 13 minutes to get through an optimiser run, something it only has 10 minutes to do. The queue entries keep going up and up until I'm guessing Appdeamon can no longer cope:

11:07:36 INFO AppDaemon: pv_opt: Entity sensor.pvopt_tariff_export_OK created in namespace: default
11:20:55 INFO AppDaemon: App initialization complete
11:38:13 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 793.754599 seconds (limit=45.0)
11:51:27 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 794.296503 seconds (limit=45.0)
12:04:40 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 793.532886 seconds (limit=45.0)
12:17:51 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 791.406017 seconds (limit=45.0)
12:31:02 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 791.778398 seconds (limit=45.0)
12:44:16 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 794.364032 seconds (limit=45.0)
12:57:30 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 794.255488 seconds (limit=45.0)
13:10:40 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 790.765245 seconds (limit=45.0)
13:23:55 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 795.536155 seconds (limit=45.0)
13:37:09 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 794.72145 seconds (limit=45.0)
13:50:26 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 797.1933 seconds (limit=45.0)
14:03:35 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 789.971825 seconds (limit=45.0)
14:16:47 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 792.443387 seconds (limit=45.0)
14:30:02 WARNING AppDaemon: Excessive time spent in callback 'optimise_state_change() in pv_opt', Thread 'thread.thread-0' - now complete after 795.732289 seconds (limit=45.0)
14:43:16 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 794.564774 seconds (limit=45.0)
14:56:28 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 792.084029 seconds (limit=45.0)
15:09:39 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 791.487343 seconds (limit=45.0)
15:22:54 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 795.662917 seconds (limit=45.0)
15:36:10 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 796.733991 seconds (limit=45.0)
15:49:22 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 792.890014 seconds (limit=45.0)
16:02:37 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 795.869117 seconds (limit=45.0)
16:16:02 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 805.44237 seconds (limit=45.0)
16:29:22 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 800.447455 seconds (limit=45.0)
16:42:41 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 799.908844 seconds (limit=45.0)
16:56:04 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 803.047657 seconds (limit=45.0)
17:09:23 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 799.986675 seconds (limit=45.0)
17:22:44 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 801.444613 seconds (limit=45.0)
17:36:03 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 799.694248 seconds (limit=45.0)
17:49:24 WARNING AppDaemon: Excessive time spent in callback 'optimise_time() in pv_opt', Thread 'thread.thread-0' - now complete after 801.226717 seconds (limit=45.0)
18:00:10 WARNING AppDaemon: Queue size for thread thread-0 is 51, callback is 'optimise_time() in pv_opt' called at 2024-11-17 17:49:24+00:00 - possible thread starvation
18:00:10 INFO AppDaemon: --------------------------------------------------
18:00:10 INFO AppDaemon: Threads
18:00:10 INFO AppDaemon: --------------------------------------------------
18:00:10 INFO AppDaemon: Currently busy threads: 1
18:00:10 INFO AppDaemon: Most used threads: 1 at 2024-11-17 11:25:00+00:00
18:00:10 INFO AppDaemon: Last activity: 2024-11-17T11:25:00+00:00
18:00:10 INFO AppDaemon: Total Q Entries: 51

The log ends with a queue building to 87 optimiser runs yet to process.......

22:59:01 WARNING AppDaemon: Queue size for thread thread-0 is 87, callback is 'optimise_time() in pv_opt' called at 2024-11-17 22:55:28+00:00 - possible thread starvation

Compounding the issue is that the optimiser is being continuously retriggered, rather than being regularly done every 10 minutes. This will be an issue in an entity being updated by Pv_opt that also is set to trigger PV_opt to optimise, resulting in an infinite loop. Other users have reported this on the Beta release, hence my request to try the production release.

punkymuzzle commented 1 week ago

No I hadn't installed the beta when this happened. I'm installing it now so will let you know what happens

stevebuk1 commented 6 days ago

As we discussed in issue #284, I'm fairly certain this is related to the value set for "update_cycle_seconds". This is a time delay added by Pv_opt for the inverter to accept the last write made to it. All activity stops whilst this delay is counted. The current value of update_cycle_seconds is set to 300, which Pv_opt uses as 360. Along with computation time this is going to equate to delays of 13 minutes if an inverter write is necessary. As can be seen from main.log, times of 45 seconds are expected, yet we are seeing delays of 800ish seconds:

Thread 'thread.thread-0' - now complete after 790.765245 seconds (limit=45.0

Given that Pv_opt is adding an optimiser run every 10 minutes, this just ends up as one big queue of optimiser runs. Add a state change in there as well, and it can be 10s of minutes befoe that they will be acted on. Pv_opt will "catch up" a bit on optimiser runs that don't involve inverter writes, as these are taking a minute or two, but if we add entity changes that need their own optimiser run (like read only), these all get added to the queue. We need to get the optimiser runs down to a minute or two.

Now you've set update_cycle_seconds to 60, we should see optimiser runs of approx 3 minutes/. The entries in main.log as above will still be generated, but should now be in the 300seconds mark. Most importantly, we should no longer see these errors:

22:52:52 INFO AppDaemon: thread-0 - qsize: 87 | current callback: optimise_time() in pv_opt | since 2024-11-17T22:42:12+00:00, | alive: True, | pinned apps: ['pv_opt'] 22:52:52 INFO AppDaemon: -------------------------------------------------- 22:53:53 WARNING AppDaemon: Queue size for thread thread-0 is 87, callback is 'optimise_time() in pv_opt' called at 2024-11-17 22:42:12+00:00 - possible thread starvation

If everything appears to settle down and work on the production release of Pv_opt, please post a pv_opt.log and main.log ideally just after a charge window completes and we can take it from there.

Note: the SettingWithCopyWarnings are unrelated, non fatal, and anyway now fixed in the Beta release.

punkymuzzle commented 6 days ago

Thanks very much for this, really appreciate it. As discussed earlier, I have set the optimiser to run every 120 seconds and PV-Opt has now settled down and is running with no errors. The AppDaemon Log has zero errors showing and the battery is happily charging / discharging ( and has been for approx. 6 hours). So I think we can close this issue down and mark as complete.

Please let me know if you need me to upload any logs etc. Thanks once again, your help is really appreciated.