Announcement

Collapse
No announcement yet.

High CPU usage

Collapse
X
 
  • Filter
  • Time
  • Show
Clear All
new posts

  • High CPU usage

    Hi, I have noticed that the plugin is one of the most expensive in terms of CPU usage. Since booting 23 hours ago the plugin has used 113 minutes of CPU time and sites at about 5% all the time between polling the servers (which is set to 5 minutes). I don't see many HS calls occurring during this, so I suspect you may simply have a thread or two in a tight loop waiting for work. I was hoping maybe you could look for that and potentially allow those threads to sleep for say a second or two when they don't have work, I suspect that would dramatically lower the cost.

    I am currently on a SEL box, and they are 2 core (Celeron class) so not too beefy, I see weird manifestations (usually queue full issues) when HSConsole can't get enough CPU time, hence the request.

  • #2
    Aside from the loop in the main thread (which just does a sleep) maintaining the connection to HS, I don't have any other loops at all. The scheduling is all handled via timers. Do you have your logging turned up by chance?

    I'll check on my system tonight and look in more detail, but I've looked before and didn't notice. That being said, several others I'm using are pretty high so maybe I just overlooked this one because it wasn't in the top 2-3!

    Comment


    • #3
      I was just sitting and staring at my task manager, set to High refresh speed on my Windows server (Intel Atom x5-Z8350 @ 1.44GHz quad core - so not much beefier) and the plugin was rock solid at 0% until an update cycle, when I saw it blip to 2%, 4%, and 9% for the first one, and roughly the same for the second thermostat (up to 13%). All those spikes were instantaneous and went right back to 0 afterwards.

      That leads me to believe it's an environmental thing, unless there's some other issue on Linux that I'm not aware of.

      While it might temporarily increase the CPU usage, turning the logging up to TRACE will let me see if the plugin is doing something during that time or not, since I have >>> and <<< messages in every single method.

      Comment


      • #4
        HomeSeer is at warn and the plugin log is at info. I went to check your log, and realized that the plugin is not being able to log into MyTotalComfort and then appears to get into some broken state where its using CPU and calling HS (see the below 18275 calls to SetDeviceValueByRef even though it can't log in, I suspect you might be setting the same device over and over again to the same value, you might want to save it and only set it if its a change). However now that I ensured my passport is correct (not sure what happened) it is logging in and working, but still seeing the high CPU usage (so it wasn't just the error case showing it). I can get you updated timings for the HS calls if that will help after it runs for a few hours but the GetDeviceByRef calls and the SetDeviceValueByRef have used about 1.6975 hours of CPU time in the last 27 hours (last reboot) and that works out to about 6% which is what I am seeing. You can cache the results from GetDeviceByRef (if your paranoid like I am you can flush the cache every hour or so), as well as if you cache the prior changes and don't call SetDeviceValueByRef unless its an actual value change, I think you'll see this evaporate.

        Sorry for assuming it was a loop, still not sure why its not burst around the 5 minute lookup mark, but hopefully these numbers help narrow it down.

        Best
        Bill


        Here are the HS api's I see being called:

        Total timings for HSPI_AmbientWeather at 9/13/2019 4:00:12 PM
        Timing: HSPI_AmbientWeather.IAppCallbackAPI.RegisterConfigLink Total Calls: 1 Invoke: 38ms Deserialization: 0ms Total: 38ms Average: 38ms
        Timing: HSPI_AmbientWeather.IAppCallbackAPI.RegisterLink Total Calls: 1 Invoke: 37ms Deserialization: 0ms Total: 38ms Average: 38ms
        Timing: HSPI_AmbientWeather.IAppCallbackAPI.get_APIVersion Total Calls: 1 Invoke: 133ms Deserialization: 0ms Total: 133ms Average: 133ms
        Timing: HSPI_AmbientWeather.IHSApplication.Connect Total Calls: 1 Invoke: 126ms Deserialization: 0ms Total: 126ms Average: 126ms
        Timing: HSPI_AmbientWeather.IHSApplication.DeviceExistsRef Total Calls: 29 Invoke: 1,382ms Deserialization: 8ms Total: 1,390ms Average: 47ms
        Timing: HSPI_AmbientWeather.IHSApplication.DeviceProperty_String Total Calls: 9135 Invoke: 1,973,406ms Deserialization: 3,787ms Total: 1,977,194ms Average: 216ms
        Timing: HSPI_AmbientWeather.IHSApplication.GetAppPath Total Calls: 2 Invoke: 108ms Deserialization: 0ms Total: 109ms Average: 54ms
        Timing: HSPI_AmbientWeather.IHSApplication.GetDeviceByRef Total Calls: 9136 Invoke: 2,080,734ms Deserialization: 34,950ms Total: 2,115,685ms Average: 231ms
        Timing: HSPI_AmbientWeather.IHSApplication.GetINISetting Total Calls: 14 Invoke: 4,984ms Deserialization: 3ms Total: 4,988ms Average: 356ms
        Timing: HSPI_AmbientWeather.IHSApplication.RegisterHelpLink Total Calls: 1 Invoke: 40ms Deserialization: 0ms Total: 40ms Average: 40ms
        Timing: HSPI_AmbientWeather.IHSApplication.RegisterPage Total Calls: 3 Invoke: 143ms Deserialization: 0ms Total: 144ms Average: 48ms
        Timing: HSPI_AmbientWeather.IHSApplication.SaveINISetting Total Calls: 12 Invoke: 593ms Deserialization: 3ms Total: 596ms Average: 49ms
        Timing: HSPI_AmbientWeather.IHSApplication.SetDeviceString Total Calls: 598 Invoke: 110,606ms Deserialization: 210ms Total: 110,816ms Average: 185ms
        Timing: HSPI_AmbientWeather.IHSApplication.SetDeviceValueByRef Total Calls: 18275 Invoke: 3,989,465ms Deserialization: 5,989ms Total: 3,995,455ms Average: 218ms
        Timing: HSPI_AmbientWeather.IHSApplication.get_APIVersion Total Calls: 1 Invoke: 164ms Deserialization: 74ms Total: 239ms Average: 239ms

        Comment


        • #5
          So... this isn't my plugin...

          Originally posted by bsobel View Post
          Total timings for HSPI_AmbientWeather at 9/13/2019 4:00:12 PM
          Timing: HSPI_AmbientWeather.IAppCallbackAPI.RegisterConfigLink Total Calls: 1 Invoke: 38ms Deserialization: 0ms Total: 38ms Average: 38ms
          Timing: HSPI_AmbientWeather.IAppCallbackAPI.RegisterLink Total Calls: 1 Invoke: 37ms Deserialization: 0ms Total: 38ms Average: 38ms
          Timing: HSPI_AmbientWeather.IAppCallbackAPI.get_APIVersion Total Calls: 1 Invoke: 133ms Deserialization: 0ms Total: 133ms Average: 133ms
          Timing: HSPI_AmbientWeather.IHSApplication.Connect Total Calls: 1 Invoke: 126ms Deserialization: 0ms Total: 126ms Average: 126ms
          Timing: HSPI_AmbientWeather.IHSApplication.DeviceExistsRef Total Calls: 29 Invoke: 1,382ms Deserialization: 8ms Total: 1,390ms Average: 47ms
          Timing: HSPI_AmbientWeather.IHSApplication.DeviceProperty_String Total Calls: 9135 Invoke: 1,973,406ms Deserialization: 3,787ms Total: 1,977,194ms Average: 216ms
          Timing: HSPI_AmbientWeather.IHSApplication.GetAppPath Total Calls: 2 Invoke: 108ms Deserialization: 0ms Total: 109ms Average: 54ms
          Timing: HSPI_AmbientWeather.IHSApplication.GetDeviceByRef Total Calls: 9136 Invoke: 2,080,734ms Deserialization: 34,950ms Total: 2,115,685ms Average: 231ms
          Timing: HSPI_AmbientWeather.IHSApplication.GetINISetting Total Calls: 14 Invoke: 4,984ms Deserialization: 3ms Total: 4,988ms Average: 356ms
          Timing: HSPI_AmbientWeather.IHSApplication.RegisterHelpLink Total Calls: 1 Invoke: 40ms Deserialization: 0ms Total: 40ms Average: 40ms
          Timing: HSPI_AmbientWeather.IHSApplication.RegisterPage Total Calls: 3 Invoke: 143ms Deserialization: 0ms Total: 144ms Average: 48ms
          Timing: HSPI_AmbientWeather.IHSApplication.SaveINISetting Total Calls: 12 Invoke: 593ms Deserialization: 3ms Total: 596ms Average: 49ms
          Timing: HSPI_AmbientWeather.IHSApplication.SetDeviceString Total Calls: 598 Invoke: 110,606ms Deserialization: 210ms Total: 110,816ms Average: 185ms
          Timing: HSPI_AmbientWeather.IHSApplication.SetDeviceValueByRef Total Calls: 18275 Invoke: 3,989,465ms Deserialization: 5,989ms Total: 3,995,455ms Average: 218ms
          Timing: HSPI_AmbientWeather.IHSApplication.get_APIVersion Total Calls: 1 Invoke: 164ms Deserialization: 74ms Total: 239ms Average: 239ms
          I do cache my Refs and I only update devices when they change, except for the "Status" device, which I update every command//poll to show the "as of" time.

          Comment


          • #6
            Doh! Sorry, let me get the right ones and I'll also turn on tracing.

            Total timings for HSPI_SKWARE_HW_WIFI_TSTAT at 9/13/2019 5:07:09 PM
            Timing: HSPI_SKWARE_HW_WIFI_TSTAT.HSPI_SKWARE_HW_WIFI_TSTAT.HSPI.Acc essLevel Total Calls: 1 Invoke: 2ms Deserialization: 17ms Total: 19ms Average: 19ms
            Timing: HSPI_SKWARE_HW_WIFI_TSTAT.HSPI_SKWARE_HW_WIFI_TSTAT.HSPI.Ini tIO Total Calls: 1 Invoke: 54ms Deserialization: 0ms Total: 54ms Average: 54ms
            Timing: HSPI_SKWARE_HW_WIFI_TSTAT.HSPI_SKWARE_HW_WIFI_TSTAT.HSPI.Int erfaceStatus Total Calls: 63 Invoke: 72ms Deserialization: 69ms Total: 142ms Average: 2ms
            Timing: HSPI_SKWARE_HW_WIFI_TSTAT.HSPI_SKWARE_HW_WIFI_TSTAT.HSPI.Sup portsMultipleInstances Total Calls: 1 Invoke: 0ms Deserialization: 0ms Total: 0ms Average: 0ms
            Timing: HSPI_SKWARE_HW_WIFI_TSTAT.HSPI_SKWARE_HW_WIFI_TSTAT.HSPI.get _Name Total Calls: 84 Invoke: 2ms Deserialization: 25ms Total: 27ms Average: 0ms


            Yep, not much there (albeit the plugin hasn't been running long). Let me go generate a trace log...

            Comment


            • #7
              Ok so I set it to Trace but also noticed its dropped back to .3% to .7% which is about the normal baseline for idle plugins. Im guessing the failed logins were somehow causing the additional load (do you retry faster than the poll interval in that case?) and I hadn't given it enough time after startup before thinking it was in the same state. Sorry for the false alarm, I'll report back if it changes (and I suspect if you want to try reproducing, just set your pw to something wrong and you can see the effect)

              Comment


              • #8
                That could be - I'll test it and see if I have an issue there - I know I do some specific handling of "bad login" that's meant to prevent retrying once it's encountered that, but that was dependent on how they communicated that on the website, which might have changed, which would throw it an "unklnown error" that I didn't handle well.

                Comment


                • #9
                  Originally posted by shill View Post
                  do cache my Refs
                  I was thinking more about this and actually I store the refs but don't cache the DeviceClass objects. Something I need to give more though to - trading constant memory usage for CPU spikes every 5 minutes might be a wash, though.

                  Comment

                  Working...
                  X