Execution times increasing


(John) #1

I have a SmartApp that runs twice a day. In the morning it runs one process and in the evening it runs a different process. The evening process is a little more involved, but not significantly. Over the last few weeks (especially the past week) I have noticed that the morning process has increased from around 4 seconds to over 20 seconds. The evening process has increased from around 8 seconds to over 20 seconds. The times do not coincide with sunrise or sunset (in the US).

With 20 seconds (or so) being the magic number for ST killing an app, this has become a major problem. The app was not changed so that cannot account for the increase in time. No new devices have been added either. My internet connection is fine - no issues. The issue is not just isolated to my app, but also seems to be affecting the ecobee app as well. It appears that anything that involves cloud-to-cloud or round-trip-to-cloud (i.e. my app checks the status of one device before making a change to another) is slowly increasing in execution time. Maybe this issue will go away with Hub v2 (and likely replaced with some other issue), although ecobee may still be an issue due to its cloud dependence (if I understand correctly how Hub v2 decides whether or not the app runs locally on the hub).

Once the times increase to the point of critical mass, the apps fail. I understand the need to limit execution time, but execution time is dependent on more than just the app. Has anyone else noticed this?


#2

I’ve noticed that one of my Hello Home phrases has added a very noticeable 10 to 15 seconds to its execution time sometime in the last few weeks.

This is a gate notification. When the gate opens, it should ring a bell in the house.

We were getting the ring almost at the same moment that the gate opens. Now the person usually gets all the way to the front door and knocks before the bell rings. If it’s my housemate coming in, he may have unlocked the door and come in before the bell.

This is a very obvious change, and makes the gate bell much less useful.


(Geko) #3

This is a recurring issue. There’re many discussions on the forum, just search for timeoutException. See for example:


#4

Except mine is a plain vanilla Hello Home Action based on a contact sensor opening. No schedule or unschedule involved that I know of. Gate opens, notification is sent. This is now consistently taking about 10-15 seconds longer than it did a month ago.


(Geko) #5

I believe the root cause is the same though. The message queues got clogged up. Time to call the plumber. :slight_smile: For some bizarre reason it always happens on weekends.


(John) #6

Last night it hit 46 seconds (nearly a 500% increase in execution time). All the app did was check the status of a device, determine who was home, and turn another device on.

Maybe Hub v2 will solve this (it at least eliminates the cloud aspect for this app) and if so, not having a migration utility isn’t enough of a hindrance. This is a bigger issue for me than setting things up again.


(Keith Croshaw) #7

I too have noticed a delay in hello home actions. Perhaps secret backend platform updated for upcoming V2/


(John) #8

@geko @keithcroshaw @tgauchat I was hoping that you might have some insight. So I’ve been watching my app fail today (I set it so it would trigger) and I noticed something that I did not expect. I thought it would fail on some line in the actual scheduled processing that was taking “too” long. However, the line that it complains about taking too long is in the preferences.

	section("Changes to 'away' mode...") {

Why would it fail here when it is executing a block of code from a scheduled event? What am I missing?


(Keith Croshaw) #9

Maybe it’s detecting the ‘away’ as escape quotes. Take 'em out?


(Geko) #10

Can you post the exact error message and the entire section source code?


(John) #11

Here’s the section:

	section("Changes to away mode...") {
		input "modeAway", "mode",title:"When this mode becomes active:", required: true, multiple: true
		input "modeAwayActivate", "enum", title: "Activate the alarm?", metadata: [values: ['Yes','No']], required: true
	}

I made the change suggested by @keithcroshaw - I took out the single quotes. This was before I saw your response. The error message that I was receiving said that the “section” line above exceeded 20 app seconds. It made no sense to me since it shouldn’t be executing that line anyway.

So when I ran it the next time without the single quotes, I got a another strange error referencing a line stating that I can’t add “null + null”. Again this was before I saw your response.

The frustrating part for me is that the app worked perfectly for months. And it still works, sometimes, but when it fails the errors show up at weird locations and up until this last one, always stated that it exceeded 20 app seconds.

Since none of this made any sense (i.e. the “null + null” error message where nothing was being added or concatenated), I tried something different. I copied the code, deleted the app, and then re-added the app. Now the execution times are around 1 second. So far, no new errors, but it’s too early to know for sure.


(Keith Croshaw) #12

Usually when I get null problems like that my data types don’t match. Perhaps we should summon the almighty @tslagle13!


(John) #13

That’s my experience too. Thanks.


(John) #14

As expected, here are the error messages:

java.util.concurrent.TimeoutException: Execution time exceeded 20 app execution seconds: 461842538451231 @ line 63

java.util.concurrent.TimeoutException: Execution time exceeded 20 app execution seconds: 462758065996948 @ line 122

java.util.concurrent.TimeoutException: Execution time exceeded 20 app execution seconds: 462789754635758 @ line 17

java.util.concurrent.TimeoutException: Execution time exceeded 20 app execution seconds: 462820632591649 @ line 585

Line 17 is a comment.
Line 63 sets up a section in preferences.
Line 122 sets up a page in preferences.
Line 585 is a log.trace

Multiple apps are experiencing the problem. It does get horrendously worse around sunrise and sunset (even though the app I initially asked about shouldn’t be hindered by that issue).

@geko made a comment about the message queue getting clogged, and I would agree (especially with respect to line 585).

But I’m confused as to why it references lines that are comments or preferences as taking too long. I don’t understand why it is trying to process comments or preferences (since they’re not needed during execution). Thanks for your help @geko @keithcroshaw.

@tslagle13 Any thoughts?


(Geko) #15

Something smells fishy here. Obviously comments have no executable code, so they can’t “take too long” to execute. And preference sections execute only when you open the app preferences. Are you sure the messages that you see have the correct app id?


(John) #16

Yes, they are correct. Thank you. That’s what I thought. It makes NO sense.

I think this strange behavior may point to a much bigger issue within the platform.