Logging @ level 4 can’t hurt…
Looks like the spike occurred this morning when the automation hit to set the thermostats to Home. I did attempt to re-initialize the app, but no change.
Do you have Log Level set to 4? If so, can you see if the Helper, the ES Thermostat, or ES Manager is doing anything when (and after) the spike occurs
I do. I included all the log data for the window, but had to use pastebin because it was too much text for a reply here.
Dumb question time... Where do you find the CPU graph?
The snippet of your logs is for the minute before and after the spike you highlighted at 08:02:13 AM.
A few observations:
- Ecobee Suite Manager is polling at 53 seconds of each minute.
- ESM Completes it poll cycle at 08:01:54am (before the spike), goes to sleep, then polls again at 08:02:53am (after the spike).
- There is an event exactly 1 second prior to your spike - a temperature update from Guest Bathroom Motion at 08:02:12am
- Looking at the complete log, I see very few updates from other sensors BEFORE the spike, but then I see a LOT of reports (relatively speaking) AFTER the spike.
Do you perchance have another automation (Rule Manager, Basic Rules, Simple Automation, etc.) using these sensors? If so, I would guess that they have logging disabled - can you turn on their logging shortly before the "Ugh" switch is turned on, so that you can capture their logs as well.
A suspect that something outside of ESM is burning CPU. It could be CAUSED by ESM, or it could be what is CAUSING ESM to burn CPU cycles. But that the spike occurs 15 minutes after it successfully changes the program on both thermostats, and it happens during a period when ESM is idle (in between polling cycles) makes me suspicious.
Another thing to test would be to see if the spike occurs if you configure the helper to change only ONE of your two thermostats. I doubt it will make a difference, but it might.
app:101 2021-06-09 08:03:57.043 am trace Updates sent (988 / 3839ms)
dev:129 2021-06-09 08:03:57.032 am info Updated 12 objects (544ms)
dev:130 2021-06-09 08:03:56.464 am info Updated 11 objects (356ms)
app:101 2021-06-09 08:03:56.041 am info Polling 411921644635,411907883212 completed
app:101 2021-06-09 08:03:55.811 am info 13 updates for 2 thermostats (Downstairs, Upstairs)
app:101 2021-06-09 08:03:54.161 am info Requesting ( equipmentStatus settings program events audio runtime extendedRuntime weather ) for thermostats Downstairs, Upstairs (411921644635,411907883212) - [true]
app:101 2021-06-09 08:03:54.138 am info Polling 411921644635,411907883212
app:101 2021-06-09 08:03:53.244 am trace Checking for updates...
dev:22 2021-06-09 08:03:30.128 am info Laundry Room Motion temperature is 65.90°F
app:101 2021-06-09 08:02:54.116 am trace No updates
app:101 2021-06-09 08:02:53.231 am trace Checking for updates...
dev:3 2021-06-09 08:02:12.848 am info Guest Bathroom Motion temperature is 73.69°F
dev:64 2021-06-09 08:02:01.393 am info Gabe's Bathroom Motion temperature is 73.98°F
app:101 2021-06-09 08:01:54.075 am trace No updates
app:101 2021-06-09 08:01:53.231 am trace Checking for updates...
dev:52 2021-06-09 08:01:39.344 am info Pantry Motion temperature is 69.12°F
app:101 2021-06-09 08:00:56.723 am trace Updates sent (473 / 3512ms)
dev:129 2021-06-09 08:00:56.713 am info Updated 4 objects (141ms)
dev:130 2021-06-09 08:00:56.554 am info Updated 4 objects (285ms)
app:101 2021-06-09 08:00:56.238 am info Polling 411921644635,411907883212 completed
app:101 2021-06-09 08:00:56.129 am info 8 updates for 2 thermostats (Downstairs, Upstairs)
app:101 2021-06-09 08:00:54.519 am info Requesting ( equipmentStatus runtime extendedRuntime ) for thermostats Downstairs, Upstairs (411921644635,411907883212) - [false]
app:101 2021-06-09 08:00:54.496 am info Polling 411921644635,411907883212
app:101 2021-06-09 08:00:53.251 am trace Checking for updates...
I should have included more output from the dashboard. The spike began at some point between 7:41 and 7:46 a.m. The dashboard is on a five minute update interval. Sorry for the brevity. I'm trying to grab info in between work stuff so I don't miss out on logs like the other day.
app:1012021-06-09 07:53:55.934 am traceUpdates sent (159 / 2637ms)
dev:1302021-06-09 07:53:55.925 am infoUpdated 4 objects (110ms)
app:1012021-06-09 07:53:55.763 am infoPolling 411907883212 completed
app:1012021-06-09 07:53:55.656 am info4 updates for 1 thermostat (Upstairs)
app:1012021-06-09 07:53:54.384 am infoRequesting ( equipmentStatus runtime extendedRuntime ) for thermostat Upstairs (411907883212) - [false]
app:1012021-06-09 07:53:54.366 am infoPolling 411907883212
app:1012021-06-09 07:53:53.334 am traceChecking for updates...
dev:222021-06-09 07:53:25.512 am infoLaundry Room Motion temperature is 61.42°F
app:1012021-06-09 07:52:56.136 am traceUpdates sent (148 / 2949ms)
dev:1292021-06-09 07:52:56.126 am infoUpdated 4 objects (115ms)
app:1012021-06-09 07:52:55.976 am infoPolling 411921644635,411907883212 completed
app:1012021-06-09 07:52:55.869 am info4 updates for 1 thermostat (Downstairs)
app:1012021-06-09 07:52:54.234 am infoRequesting ( equipmentStatus runtime extendedRuntime weather ) for thermostats Downstairs, Upstairs (411921644635,411907883212) - [false]
app:1012021-06-09 07:52:54.211 am infoPolling 411921644635
app:1012021-06-09 07:52:53.225 am traceChecking for updates...
dev:32021-06-09 07:52:07.934 am infoGuest Bathroom Motion temperature is 63.59°F
dev:642021-06-09 07:51:57.466 am infoGabe's Bathroom Motion temperature is 68.20°F
app:1012021-06-09 07:51:56.357 am traceUpdates sent (536 / 3145ms)
dev:1292021-06-09 07:51:56.329 am infoUpdated 5 objects (115ms)
dev:1302021-06-09 07:51:56.191 am infoUpdated 5 objects (346ms)
app:1012021-06-09 07:51:55.808 am infoPolling 411921644635,411907883212 completed
app:1012021-06-09 07:51:55.700 am info10 updates for 2 thermostats (Downstairs, Upstairs)
app:1012021-06-09 07:51:54.219 am infoRequesting ( equipmentStatus runtime extendedRuntime ) for thermostats Downstairs, Upstairs (411921644635,411907883212) - [false]
app:1012021-06-09 07:51:54.196 am infoPolling 411921644635,411907883212
app:1012021-06-09 07:51:53.253 am traceChecking for updates...
app:1012021-06-09 07:50:54.154 am traceNo updates
app:1012021-06-09 07:50:53.247 am traceChecking for updates...
dev:292021-06-09 07:50:04.323 am infoStephanie's Bathroom temperature is 60.16°F
app:1012021-06-09 07:49:55.686 am traceUpdates sent (10 / 2495ms)
app:1012021-06-09 07:49:55.664 am infoPolling 411921644635,411907883212 completed
app:1012021-06-09 07:49:55.557 am info0 updates for 0 thermostats
app:1012021-06-09 07:49:54.270 am infoRequesting ( equipmentStatus settings program events audio ) for thermostats Downstairs, Upstairs (411921644635,411907883212) - [true]
app:1012021-06-09 07:49:54.246 am infoPolling 411921644635,411907883212
app:1012021-06-09 07:49:53.230 am traceChecking for updates...
app:1012021-06-09 07:48:56.910 am traceUpdates sent (848 / 3716ms)
dev:1292021-06-09 07:48:56.901 am infoUpdated 10 objects (482ms)
dev:1302021-06-09 07:48:56.392 am infoUpdated 12 objects (309ms)
app:1012021-06-09 07:48:56.035 am infoPolling 411921644635,411907883212 completed
app:1012021-06-09 07:48:55.925 am info20 updates for 2 thermostats (Downstairs, Upstairs)
app:1012021-06-09 07:48:54.181 am infoRequesting ( equipmentStatus runtime extendedRuntime ) for thermostats Downstairs, Upstairs (411921644635,411907883212) - [false]
app:1012021-06-09 07:48:54.157 am infoPolling 411921644635,411907883212
app:1012021-06-09 07:48:53.232 am traceChecking for updates...
app:1012021-06-09 07:47:57.551 am traceUpdates sent (11 / 2347ms)
app:1012021-06-09 07:47:57.529 am infoPolling 411921644635,411907883212 completed
app:1012021-06-09 07:47:57.422 am info0 updates for 0 thermostats
app:1012021-06-09 07:47:56.305 am traceNo updates
app:1012021-06-09 07:47:56.212 am infoChecking: Auth_token refreshed
app:1012021-06-09 07:47:56.186 am infoRequesting ( equipmentStatus settings program events audio runtime extendedRuntime ) for thermostats Downstairs, Upstairs (411921644635,411907883212) - [false]
app:1012021-06-09 07:47:56.162 am infoPolling 411921644635,411907883212
app:1012021-06-09 07:47:55.242 am traceChecking for updates...
app:1012021-06-09 07:47:53.364 am traceChecking for updates...
app:1012021-06-09 07:46:53.276 am traceprior poll not finished, skipping...
app:1012021-06-09 07:45:54.091 am infoRequesting ( equipmentStatus settings program events audio runtime extendedRuntime ) for thermostats Downstairs, Upstairs (411921644635,411907883212) - [false]
app:1012021-06-09 07:45:54.068 am infoPolling 411921644635,411907883212
app:1012021-06-09 07:45:53.218 am traceChecking for updates...
app:1042021-06-09 07:45:14.448 am infoAnd I turned off Ugh
app:1012021-06-09 07:45:14.156 am traceprior poll not finished, skipping...
dev:1302021-06-09 07:45:14.110 am inforefresh() - calling pollChildren , deviceId = 411907883212
app:1012021-06-09 07:45:14.109 am traceprior poll not finished, skipping...
app:1012021-06-09 07:45:10.231 am traceprior poll not finished, skipping...
dev:1292021-06-09 07:45:10.093 am inforefresh() - calling pollChildren , deviceId = 411921644635
app:1042021-06-09 07:45:09.402 am traceNotification Message (notify=false): I set EcobeeTherm: Upstairs to Hold: Home
dev:1302021-06-09 07:45:09.394 am infoUpdated 2 objects (93ms)
dev:1302021-06-09 07:45:09.299 am infoUpdated 5 objects (182ms)
dev:1302021-06-09 07:45:09.114 am infoThermostat Program is Hold: Home
dev:1302021-06-09 07:45:09.055 am infoUpdated 6 objects (139ms)
dev:1302021-06-09 07:45:08.912 am infoUpdated 1 object (89ms)
dev:1302021-06-09 07:45:08.908 am infosetProgram(home) for EcobeeTherm: Upstairs (411907883212) returned true
app:1012021-06-09 07:45:08.821 am infosetProgram(home) for EcobeeTherm: Upstairs (411907883212) returned true
dev:1302021-06-09 07:45:07.979 am infoUpdated 1 object (8ms)
dev:1302021-06-09 07:45:07.974 am infosetProgram(Home) for EcobeeTherm: Upstairs (411907883212) - holdType: indefinite
app:1012021-06-09 07:45:07.969 am infosetProgram(Home) for EcobeeTherm: Upstairs (411907883212) - holdType: indefinite
dev:1302021-06-09 07:45:07.937 am infoThermostat Program is Home (resumed)
dev:1302021-06-09 07:45:07.935 am inforesumeProgram() - No current hold
app:1012021-06-09 07:45:07.743 am traceprior poll not finished, skipping...
dev:1302021-06-09 07:45:07.617 am inforefresh() - calling pollChildren , deviceId = 411907883212
app:1042021-06-09 07:45:07.600 am debugsendHoldType: indefinite, sendHoldHours: null
app:1042021-06-09 07:45:07.598 am infoUsing holdType indefinite
app:1042021-06-09 07:45:07.595 am infoUsing holdType indefinite
dev:1302021-06-09 07:45:07.571 am inforesumeProgram(true) - succeeded
dev:1302021-06-09 07:45:07.569 am infoUpdated 7 objects (189ms)
dev:1302021-06-09 07:45:07.133 am infoUpdated 9 objects (297ms)
dev:1302021-06-09 07:45:06.821 am infoUpdated 1 object (195ms)
dev:1302021-06-09 07:45:06.817 am inforesumeProgram(Upstairs, true) for EcobeeTherm: Upstairs (411907883212) returned true
app:1012021-06-09 07:45:06.623 am inforesumeProgram(Upstairs, true) for EcobeeTherm: Upstairs (411907883212) returned true
app:1042021-06-09 07:45:05.679 am traceSetting Thermostat Program to programParam: Home and holdType: Ecobee Manager Setting
app:1042021-06-09 07:45:05.675 am debugthermostatHold: hold
app:1042021-06-09 07:45:05.549 am traceIn each loop: Working on stat: EcobeeTherm: Upstairs
app:1042021-06-09 07:45:05.545 am traceNotification Message (notify=false): I set EcobeeTherm: Downstairs to Hold: Home
dev:1292021-06-09 07:45:05.537 am infoUpdated 2 objects (205ms)
dev:1292021-06-09 07:45:05.329 am infoUpdated 5 objects (220ms)
dev:1292021-06-09 07:45:05.105 am infoThermostat Program is Hold: Home
dev:1292021-06-09 07:45:05.033 am infoUpdated 6 objects (152ms)
dev:1292021-06-09 07:45:04.876 am infoUpdated 1 object (97ms)
dev:1292021-06-09 07:45:04.873 am infosetProgram(home) for EcobeeTherm: Downstairs (411921644635) returned true
app:1012021-06-09 07:45:04.776 am infosetProgram(home) for EcobeeTherm: Downstairs (411921644635) returned true
dev:1292021-06-09 07:45:03.847 am infoUpdated 1 object (8ms)
dev:1292021-06-09 07:45:03.843 am infosetProgram(Home) for EcobeeTherm: Downstairs (411921644635) - holdType: indefinite
app:1012021-06-09 07:45:03.837 am infosetProgram(Home) for EcobeeTherm: Downstairs (411921644635) - holdType: indefinite
dev:1292021-06-09 07:45:03.803 am infoThermostat Program is Home (resumed)
dev:1292021-06-09 07:45:03.801 am inforesumeProgram() - No current hold
app:1012021-06-09 07:45:03.693 am infoRequesting ( equipmentStatus settings program events audio runtime extendedRuntime ) for thermostats Downstairs, Upstairs (411921644635,411907883212) - [false]
app:1012021-06-09 07:45:03.669 am infoPolling 411921644635,411907883212
app:1012021-06-09 07:45:02.588 am traceChecking for updates...
dev:1292021-06-09 07:45:02.454 am inforefresh() - calling pollChildren , deviceId = 411921644635
app:1042021-06-09 07:45:02.436 am debugsendHoldType: indefinite, sendHoldHours: null
app:1042021-06-09 07:45:02.435 am infoUsing holdType indefinite
app:1042021-06-09 07:45:02.431 am infoUsing holdType indefinite
dev:1292021-06-09 07:45:02.377 am inforesumeProgram(true) - succeeded
dev:1292021-06-09 07:45:02.375 am infoUpdated 7 objects (118ms)
dev:1292021-06-09 07:45:02.079 am infoUpdated 9 objects (292ms)
dev:1292021-06-09 07:45:01.770 am infoUpdated 1 object (90ms)
dev:1292021-06-09 07:45:01.765 am inforesumeProgram(Downstairs, true) for EcobeeTherm: Downstairs (411921644635) returned true
app:1012021-06-09 07:45:01.676 am inforesumeProgram(Downstairs, true) for EcobeeTherm: Downstairs (411921644635) returned true
app:1042021-06-09 07:45:00.577 am traceSetting Thermostat Program to programParam: Home and holdType: Ecobee Manager Setting
app:1042021-06-09 07:45:00.573 am debugthermostatHold: hold
app:1042021-06-09 07:45:00.445 am traceIn each loop: Working on stat: EcobeeTherm: Downstairs
app:1042021-06-09 07:45:00.441 am tracechangeProgramHandler() entered with evt: switch: on
app:1042021-06-09 07:45:00.433 am tracechangeSwitchHandler() entered with evt: Ugh switch turned on
app:1052021-06-09 07:45:00.281 am infoAction: On: Ugh
app:1052021-06-09 07:45:00.234 am infoUgh on at time Triggered
app:1052021-06-09 07:45:00.225 am infoUgh on at time: Triggered by Periodic Schedule
app:1012021-06-09 07:44:54.155 am traceNo updates
app:1012021-06-09 07:44:53.224 am traceChecking for updates...
app:1012021-06-09 07:43:54.285 am traceNo updates
app:1012021-06-09 07:43:53.281 am traceChecking for updates...
app:1012021-06-09 07:42:55.937 am traceUpdates sent (137 / 2720ms)
dev:1292021-06-09 07:42:55.927 am infoUpdated 4 objects (107ms)
app:1012021-06-09 07:42:55.787 am infoPolling 411921644635,411907883212 completed
app:1012021-06-09 07:42:55.681 am info4 updates for 1 thermostat (Downstairs)
app:1012021-06-09 07:42:54.258 am infoRequesting ( equipmentStatus runtime extendedRuntime weather ) for thermostats Downstairs, Upstairs (411921644635,411907883212) - [false]
app:1012021-06-09 07:42:54.200 am infoPolling 411921644635
app:1012021-06-09 07:42:53.255 am traceChecking for updates...
app:1012021-06-09 07:41:56.168 am traceUpdates sent (331 / 2959ms)
dev:1302021-06-09 07:41:56.158 am infoUpdated 9 objects (300ms)
app:1012021-06-09 07:41:55.825 am infoPolling 411907883212 completed
app:1012021-06-09 07:41:55.718 am info8 updates for 1 thermostat (Upstairs)
app:1012021-06-09 07:41:54.285 am infoRequesting ( equipmentStatus runtime extendedRuntime ) for thermostat Upstairs (411907883212) - [false]
app:1012021-06-09 07:41:54.267 am infoPolling 411907883212
app:1012021-06-09 07:41:53.246 am traceChecking for updates...
app:1012021-06-09 07:40:54.161 am traceNo updates
app:1012021-06-09 07:40:53.269 am traceChecking for updates...
app:1012021-06-09 07:39:54.295 am traceNo updates
1 Like
could you please try with changing only 1 thermostat's program?
I can and have. Sorry, I didn't mean to ignore that ask before.
Sorry if I missed that - I'm trying to narrow down the circumstances that create problems. It seems that perhaps it is related to the cases where the logs say "prior poll not finished, skipping..." - I'm trying to find a case where that doesn't occur to see if the CPU spike happens or not...
The fallacy of strictly communicating via writing.
I made the change today and will monitor to see if it makes a difference. I'll post back one way or the other tomorrow.
What he said.
In case this helps any.....I had an extra C-7 hub lying around. So I loaded HPM and then ESM on it. That's it. Nothing else. When I had just two thermostats selected, all was fine -- no CPU issues. As soon as I added all 5 of my thermostats (2 houses), I get the dreaded CPU load warning. Below I've pasted my app stats view from the hub. Would you imagine that 5 thermostats would, on their own in ESM, bring a hub to its knees? Is there more troubleshooting or testing I can do to help us all get to the bottom of this?
1.5% of 1.5% is 0.02% of the CPU, what does the device stats page look like?
Ditto - what are you trying to say?
Your chart shows ESM using 98.5% of the CPU run time, which is only 1.5% of wall clock time. It also says the average poll cycle takes only about 2ms.
For 5 thermostats, I'd say that is pretty durn efficient!!!
So, what do you mean by "bring a hub to its knees?"
If you are serious:
- What hub type?
- What Hubitat SW version?
- What does the Device runtime page look like?
- What are the symptoms you experience when your hub is "on its knees?"
- What does Live Logging tell you about ESM?
- Are there any errors?
- Do you see any "prior poll not complete" messages
I think he means because he's getting the CPU load warning. I'm wondering if the load warning is set too low in HE.
I'm guessing that the app is doing a "lot" of waiting on device response which will overstate the CPU load (load ≈ running processes + response wait + IO Wait)
Fair question. @jcarreira is correct. I meant that I am getting the CPU severe load warning. And I guess it never dawned on me that the message could be a false positive.
Me too! Which is why I'm stymied by the warning message.
To your other questions:
Hub type: C7
Hubitat SW: the latest 2.2.7.126
Symptoms: only the dreaded warning, AFAIK
Logging: I was getting the "Severe Hub Load Detected" warnings before I even added any helper apps! I'm also getting the following messages in the log:
- warncheckThermostatSummary() - javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake - will retry
- warnpollEcobeeAPICallback() - Poll exception: 408, Remote host closed connection during handshake, null, - will retry
- [trace]prior poll not finished, skipping...
Edit: Also I'm getting the "WARNING" next to the ESM in the Apps view of the hub.
Here's my Hub Information in case it helps to validate @thebearmay's hypothesis:
May want to redact your ZigbeeEui.
The 408 (time out) and handshake retries are "long running" waits (multiple seconds), which would account for the high load reading of 8.77 (219.25%). That plus your stats pages would support this being a false positive from a CPU load perspective, but you may still want to try and determine why your polling is timing out.
1 Like
Hmmm....that would indeed explain things. I'm pretty sure that cpuPct : 219.25 is an overstatement!
Perhaps @bobbyD can comment as to whether this may be a "false positive", given that indeed Ecobee Suite Manager spends a LOT of time waiting (almost all Ecobee API calls are asynchronous HTTP Gets and Puts).
