How would you get to root cause for "Excessive time spent in utility loop:"

Third party integrations AppDaemon
1

All of a sudden at the the top of the hour (mostly), I am seeing a lot of “Excessive time spent in utility loop:” warnings from AppDaemon:

/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-23 06:00:04.543737 WARNING AppDaemon: Excessive time spent in utility loop: 969.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-23 09:00:08.574142 WARNING AppDaemon: Excessive time spent in utility loop: 960.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-23 14:00:09.636353 WARNING AppDaemon: Excessive time spent in utility loop: 1656.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-23 15:00:12.440408 WARNING AppDaemon: Excessive time spent in utility loop: 1329.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-23 17:00:10.543526 WARNING AppDaemon: Excessive time spent in utility loop: 1668.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-23 18:00:11.403554 WARNING AppDaemon: Excessive time spent in utility loop: 1566.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-23 22:00:10.362457 WARNING AppDaemon: Excessive time spent in utility loop: 1201.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-23 23:00:08.808421 WARNING AppDaemon: Excessive time spent in utility loop: 1126.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-24 04:00:09.504187 WARNING AppDaemon: Excessive time spent in utility loop: 913.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-24 05:00:08.923695 WARNING AppDaemon: Excessive time spent in utility loop: 955.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-24 07:00:09.972757 WARNING AppDaemon: Excessive time spent in utility loop: 993.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-24 11:00:10.645710 WARNING AppDaemon: Excessive time spent in utility loop: 1673.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-24 12:00:13.380415 WARNING AppDaemon: Excessive time spent in utility loop: 1756.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-24 13:00:13.887463 WARNING AppDaemon: Excessive time spent in utility loop: 1304.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-24 16:00:12.959121 WARNING AppDaemon: Excessive time spent in utility loop: 1055.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-24 20:00:08.573321 WARNING AppDaemon: Excessive time spent in utility loop: 971.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-24 21:00:05.131425 WARNING AppDaemon: Excessive time spent in utility loop: 1022.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-24 23:00:07.304495 WARNING AppDaemon: Excessive time spent in utility loop: 931.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-24 23:00:12.288951 WARNING AppDaemon: Excessive time spent in utility loop: 1838.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-25 05:00:08.420429 WARNING AppDaemon: Excessive time spent in utility loop: 1306.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-25 06:00:05.181801 WARNING AppDaemon: Excessive time spent in utility loop: 942.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-25 06:00:10.223863 WARNING AppDaemon: Excessive time spent in utility loop: 977.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-25 08:00:13.999757 WARNING AppDaemon: Excessive time spent in utility loop: 1623.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-25 12:00:10.816449 WARNING AppDaemon: Excessive time spent in utility loop: 997.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-25 13:00:08.884447 WARNING AppDaemon: Excessive time spent in utility loop: 1035.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-25 13:10:25.607913 WARNING AppDaemon: Excessive time spent in utility loop: 1793.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-25 15:00:06.806388 WARNING AppDaemon: Excessive time spent in utility loop: 1034.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-25 15:00:11.500973 WARNING AppDaemon: Excessive time spent in utility loop: 1467.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-25 17:00:11.963136 WARNING AppDaemon: Excessive time spent in utility loop: 1341.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-25 21:00:04.626792 WARNING AppDaemon: Excessive time spent in utility loop: 948.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-26 01:00:11.667735 WARNING AppDaemon: Excessive time spent in utility loop: 1220.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-26 03:00:10.652047 WARNING AppDaemon: Excessive time spent in utility loop: 1165.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-26 04:00:10.405573 WARNING AppDaemon: Excessive time spent in utility loop: 1465.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-26 05:00:08.878987 WARNING AppDaemon: Excessive time spent in utility loop: 1182.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-26 06:00:12.209203 WARNING AppDaemon: Excessive time spent in utility loop: 1110.0ms
/home/homeassistant/AppdaemonLogs/appdaemon.log:2018-04-26 08:00:10.734355 WARNING AppDaemon: Excessive time spent in utility loop: 974.0ms

Trying to correlate to understand what might be going on. Nothing in the AppDaemon error logs and a quick look at syslog doesn’t show anything too interesting.

AppDaemon: 3.0.1 and HASS: 0.67.1

Any ideas on how to track down the issue?

Thanks

2

you probably have an app that uses run_hourly on the hour.

maybe even several?

those apps slow down AD for a short moment, causing the warning.
i have the same problem for some time now, and what i have noticed is that restarting the device can help that the warning dissapears for a while.

it seems that devices slow down over time. developing things does also cause that it appears more.
in my case it has everything to do with HD load. i have a SSD but still that isnt fast enough with everything i have running.

if you do have several run_hourlys, then spread them out over the hour.
in itself its nothing to worry about, but it is a sign that you are overloading your programming on some moment, so its time to start thinking about optimising.

1 Like
3

Thanks @ReneTode - run_hourly is the first thing I thought of also, but I don’t use it in any of my apps. Even after restarts, it seems to consistently keep popping up. Nothing in my cron either.

I agree, does not seem to be causing any issues but my OCD self keeps wanting to resolve :-). I’ll keep looking …

4

it can also be 1 or more websensors in HA that run once every hour.
or other kind off things in HA that occur once every hour.

typical things to think about:
weather, streetviews, distant webcams, saving a picture from local webcams, etc.

1 Like
5

Hadn’t thought about my sensors - good point! I’ll dig a little deeper.

Thanks

6

think also on things like backups.

in my case its all about HD access.
so backups, sensorlogging, logwriting, rewriting logs, automatic dashboard creation, FTP for my cams, etc. etc.
ill probably need to splitt things up in the future.

1 thing that Andrew has recently added is also very helpfull.
production mode.

as soon as you set AD in production mode it will stop looking for changes in the yaml and the py code.
that is the biggest part from AD that uses HD (it checks on the HD every second!)
so when you are not developing you can go into production mode and you probably will never get those warnings.

1 Like
7

Cool - didn’t know that existed…but of course I may never get to production mode - I like to tinker too much! :slight_smile:

8

he added it in the last update on my wish.
i also do tinker almost daily.
but i will test it out by going to production mode when i go to bed and come out of production mode when i start tinkering :wink:

i am creating my own mancave at the moment and when thats ready i will also restart my RPI with AD on it and use that as development area.
if an app is allright i move it to production.

9

I have just added production_mode to appdaemon.yaml and restarted AD, but it doesn’t seem to have made much difference to my cpu usage. I don’t see anything in the log file to indicate that it is being used, is this normal?

log:
  errorfile: /var/log/appdaemon/ha_apps_error.log
  logfile: /var/log/appdaemon/ha_apps.log

appdaemon: 
  app_dir: /home/homeassistant/.homeassistant/apps
  threads: '10'
  production_mode: true
  plugins:
    HASS:
      ha_url: http://localhost:8123
      type: hass

Edit: I figured it out - I had to upgrade to version 3.0.1 :flushed:

1 Like
10

I added it yesterday afternoon just for fun. Have not seen one re-occurrence of the “Excessive time spent …” message. I understand that’s not the fix, but interesting…!

1 Like
11

I think Rene covered this very well but just to summarize - the main thing that happens in the utility loop is checks for yaml changes, file changes etc. These can get quite involved if you have lots of dependencies and lots of apps. But just as importantly, something outside of AD might be hogging the CPU and or Disk I/O to cause this. It’s not the end of the word, and if you can;t track it down but hate the error messages you can also slow down the frequency of the utility loop cycle which gives it more time to complete, at the expense of app reloads and yaml changes taking longer to be recognized.

These aren’t documented, but:

utility_delay: 5 for instance will make the utility loop code run every 5 seconds instead of the default of 1 second

Also, utility_skew: 4 will set the warning for excessive time to 4 seconds instead of the default which is usually 90% of utility_delay.

These both go in the appdaemon section.

6 Likes
12

Thanks for the follow-on explanation and yes I agree that Rene has done his typical great job (as usual) offering help and insight utilizing his extensive AppDaemon experience! Bottom line for me is that I’m not going to obsess over those messages - just something for me to be aware of.

Again thank you for providing such a wonderful tool for us!

3 Likes