Expression freezes

[digitalstone]

So over the last 2 weeks i've been having this bug all of a sudden.

It implies an expression with consisting an ordinary piece of code:

Code: Select all

if (contains(trigger,"Widget"))
{return true;}
else
return false;

Problem is that it just keeps hanging like this:
https://drive.google.com/open?id=1acjiz ... 6rBDV-xexf

Pressing stop is not effective. Executing behaves as should.
Anyone recognizing this bug (if is)?

Note: I first thought it has something to do with executing another flow further on.
But that's not the case since it also happens in another flow with just 1 trigger, this condition and a simpel vibrate function.

[Desmanto]

The expression works me. I never experience hang in the expression evaluation, most of the time it is error exception (from our mistake).

I only experience hang like this in action which utilize timeout, such as HTTP request, Input speech. For input speech, I had it several times, because of the network connection. The flow can't be stopped as your, but will timeout after 20-30 seconds of stuck. That's why I've requested to have option to force it offline recognition.

Try to check if you have another flow in the background, that might interfere with the the expression. Maybe checking the statistic can give you some insight.

Thanks to your bug, during testing I discovered that expression can have "the fourth" branch option, which is doing nothing (flow ends there).

[digitalstone]

Hmm it only happens when this flow (the one in the picture of first post) executes the flow of the worktimeout-profile.
In there i make use of sleep() function.
Apparently the whole shabang of automagic gets paused(??)

[digitalstone]

No hold on... it does NOT only happen in that particular flow at all.

It just happens always at the FIRST condition-block of ANY flow, if any sleepfunction or sleep action -block in ANY other flow is active.

I don't think this is right.

[Desmanto]

@digitalstone

At first I don't got what you mean. I thought it is the same confirmation dialog halting from multiple branch execution. But that happens only in single flow, not over the other flow.
I test with Action sleep, it works properly. I have done more test and yes, the problem exists. And I extend the problem not only to expression, but to script as well. And it happens not only at first block, but anytime the flow run into script/expression. Thanks for noticing this bug.

@Martin : Below is the complete bug report and the test

Flow for test
To reproduce the problem, this is the test that I've done. We need 2 flows
Flow 1 : no trigger
Action/condition 1 : Script/expression

Code: Select all

sleep(10000);

Flow 1.png (26.78 KiB) Viewed 23251 times

You can choose either script or expression. The script is to invoke sleep for 10 seconds (enough for testing and execute the other flow). No elements needed after this.

Flow 2 : no trigger
Action/condition 1 : Script/expression

Code: Select all

t = getDate();
t == 1;

condition 2 : Debug dialog

Flow 2.png (43.24 KiB) Viewed 23251 times

Basically, it just save the current time to variable t and test the t is equal to 1.

Testing Flow 2
Now the testing time. Flow 1 is the culprit, flow 2 is the victim. But first we need to confirm Flow 2 is executing properly. Test Flow 2 and see the debug dialog. t value should not differ much from triggertime. At mine, if I am at flow 2, using hardware rendering since 1.34; it only differ around 40 miliseconds. So t is very close to triggertime.

Testing Flow 1 + Flow 2
Since the bug comes from the script/expression in other flow, we need to execute flow 1 and then quickly execute flow 2 to see if flow 2 got delayed by flow 1. Go to the flow list
- tap 3 dot menu on Flow 1 > execute.
- Then quickly tap Flow 2 to open the flow
- tap 3 dot menu > Execute.
- You can see the execution stall at the script/expression.
- Wait until about 10 seconds passed, and the flow 2 will continue to debug dialog.

The whole script/expression was not executed at all, it was waiting for the sleep function in other flow to finish, before continue executing. It is indicated by the t value, which is 10 second after Flow 1 execution. If the script in flow 2 got executed immediately, the value of t should not differ so much from the triggertime, just like the first run without flow 1.

Happen in All flow
This happen not only for expression in first block, but for all script/expression in every flow, whenever there is a sleep() function executing somewhere. So the script/expression which have sleep function 1 minute at flow ABC element number 34th; it will halt any script/expression at flow XYZ element number 12th for 1 minute too. (basically any script/expression executing in other flow will be paused).

Control UI not affected
But Control UI, which use a very similar scripting doesn't get affected by this. If you replace either script/expression in flow 1 or 2 with control UI, or even both; it won't have the waiting bug. So Control UI is not affected. Action sleep itself also not affected by this. It seems script/expression in all flow share the same thread process in terms of sleep() function.

Real Culprit
However, something intrigue me. I do another test using loop. What if I loop for 100 times and sleep(100) in each? Is it the sleep() function causing the problem? Turns out the result is the same waiting for about 10 seconds more (looping 100 x 100 ms will produce a little more than 10 seconds). Next, I continue again, what if it is the time execution of the script is the culprit, not particularly sleep() function. So I test a very big number of loop. (automagic limit loop at 10000, so I have to amplify it using nested for() to achieve 1 million loops)

Code: Select all

a = 0;
for(i in [1 to 100])
{
  for(j in [1 to 10000])
    a = a + 1;
}

This takes around 14 seconds to finish at my phone. And what happen? Same waiting bug! So it is not about the sleep() function, the culprit is the execution time needed for a script/expression. Sleep simply magnify the problem easily, since single line of sleep() can make so much different, depends on the number you put in there.

Separated script
To crosscheck against the single script/expression, I tried to split the sleep() to 10 script elements. So each script only contains sleep(1000) >> 10 x 1 seconds. And Flow 2 now doesn't get stalled by flow 1. Well actually it stalled a little, but less than 1 second, so not noticeable. (can be checked using the t value, is higher than 40 ms, but still lower than 1 second difference). So separating the sleep to another script can helps the execution.

Same flow execution
Then I am curious again, how about single flow execution? The default AEP is parallel, so we can run the flow so many times. Using the separated 10 x script with sleep(1000), I tried to execute it multiple times. First execution I observe the stepping speed is regular, at 1 second per element. Then I execute the second times. The movement of the flow now takes 2 seconds, 1 second from first execution and 1 second from second execution. The script seems to be moving in turn. So if the first execution move, second one stall. The second move, first stall. Adding the 3rd execution, it stalls even more obvious. 1st, 2nd, 3rd all move in turn. So this waiting bug not only happens across flow, but also in the same flow!

Sum up the bug detail
To sum up the bug from the testing above :
1. Script/expression which takes long time to finish in one flow, can halt the execution of script/expression in other flow (or even its own flow)
2. It happens globally in all flow, all script/expression in any place inside the any flow.
3. It happens only when there is another flow is executing and has script/expression stalled, even when it is the same flow (using parallel)
4. sleep() function magnify the problem greatly, as it add execution times significantly.
5. Control UI and action Sleep is not affected
6. Only single script/expression execution time affected. Splitting them to different element will reduce the waiting effect dramatically

I consider this as bug, because every flow execution should be separated from other, even from its own (parallel). Any Script/expression execution should not travel across time and space to halt other script/expression. This bug can create so many unforeseen delay in many flows. I usually don't use high value for sleep(). Even a very long script still only require several ms to finish. Thus can't catch the problem before.

Possible Root Cause
It seems Automagic execute all script/expression in all flow in single thread/process (or whatever it is). So any new execution should wait for previous one to finish first, before new one can use the thread/process. Probably it is designed that way to conserve resources. Since if every script/expression execute in its own memory, probably the memory usage can grow so fast, that Chrome probably will be crying in the corner, as it becomes runner up in term of RAM usage. Martin probably think that most of us won't use script/expression until it takes too long to execute till finish. However as things go by, we found out we can do so many things in script/expression and we tend to load up so many things into single script/expression. Me myself, started to use expression more in my recent project. As expression offer the flexibility to stop execution right at some point and immediately branch to other logic (simply protect using if and use return true or false).

But I don't know the detail, it is just my hypothesis. Hopes Martin can clear up the source of problem.

Possible solution
Using my hypothesis above. I would suggest several fix.
1. Separate the script/expression of each flow execution, pratically sandbox them. Each flow execution should be separated in term of process. But I don't know if this will cause problem when calling other flow, as the variable need to be passed. Glovar probably will be affected too and become a bit slower. But this will also solved the parallel execution from the same flow, since it is the execution got sandboxed, not just the flow.
2. Create more pool for script/expression execution. Currently it seems to be only one execution allowed. Maybe increase the pool to 5 or 10, so there can be 5 script/expression can be running at the same time. It will use more resources, but I don't think most of us will be bothered by that. To be safe, put an option in the Automagic preference - Workaround, add script concurrent execution. Set the default to 5 and we can change as we need. Probably it will be even better if it will give us warning when this limit is reached (something like emergency stop, but only to warn that there are 5 concurrent script execution right now, from flow A, B, D, G, and H)
3. This is just a bug. The original design of the execution already can execute unlimited concurrent script/expression. So only need to be fixed.

Current Workaround
To counter this problem, just make sure the execution of each script/expression is not too long. I never notice this bug, since I never use too high value for sleep(). Most of the sleep are in Control UI, which is not affected by this bug. Each single script/expression usually just take 3-4 ms (which is so fast even if you queue 10 of them). Most of the time, the typical usage of the script won't take longer that 10 ms. So if you have a longer execution script, make sure you split it to several script to make sure it doesn't randomly stall your other flow. If you have sleep() function inside the script which is longer that several seconds (maybe more than 5 seconds), just move it outside for the script. It is better to replace it with Action sleep, which is not affected by this bug.

Hopefull this bug report is clear enough. Thanks for reading till here.

Regards,
Desmanto

[Martin]

Hi,

This is a known problem and "by design". Automagic uses a global lock to execute the scripts since it otherwise could lead to threading problems and race conditions. Unfortunately I once had the bad idea to introduce the sleep function within scripts so this problem can be noticed pretty easily now. I have an idea to mitigate the problem for the sleep calls but I did not yet have the time to implement it. I'll try to add it to the next EAP build so most users should not notice the problem anymore.

Regards,
Martin

[digitalstone]

Hi,

This is a known problem and "by design". Automagic uses a global lock to execute the scripts since it otherwise could lead to threading problems and race conditions. Unfortunately I once had the bad idea to introduce the sleep function within scripts so this problem can be noticed pretty easily now. I have an idea to mitigate the problem for the sleep calls but I did not yet have the time to implement it. I'll try to add it to the next EAP build so most users should not notice the problem anymore.

Regards,
Martin

That would be very great!
I have more flow ideas that would make use of a sleep function for prolonged times.
At the same time i'm wondering why i'm the first one to report this bug.
It seems really crucial.

[Desmanto]

Hi,

This is a known problem and "by design". Automagic uses a global lock to execute the scripts since it otherwise could lead to threading problems and race conditions. Unfortunately I once had the bad idea to introduce the sleep function within scripts so this problem can be noticed pretty easily now. I have an idea to mitigate the problem for the sleep calls but I did not yet have the time to implement it. I'll try to add it to the next EAP build so most users should not notice the problem anymore.

Regards,
Martin

Thanks for the clarification. Yeah, the race condition. I ever read it somewhere, and reread it just now. It will be more distatrous to let the script run simultaneously. It is ok then, don't change current global lock.

BTW, why the Control UI doesn't exhibit this problem? If script/expression has the global lock, wouldn't Control UI which derived from them also should show the same problem? It seems the race problem maybe only affects the glovar and when the flow is executed from other flow. If the flow only use local variable from its own flow, It shouldn't contradict with other same name local variable in other variable, right? Or maybe it is still too risky to let the script/expression run in parallel.

And regarding the race condition, does it also happen in other elements too? such as those elements which has input/output, or dynamic variable. Maybe something like trigger file observer will be waiting for action write to file to finish first before trying to check. Knowing the group of elements which use the same global lock, will help us to design the flow better. So we can avoid the lock which is sometimes untraceable if we don't test it out.

That would be very great!
I have more flow ideas that would make use of a sleep function for prolonged times.
At the same time i'm wondering why i'm the first one to report this bug.
It seems really crucial.

I just recheck all my script and found out I mostly only use sleep() in Control UI part. I found out several inproper use of sleep() inside my script (logic flaw), but never realize it. I should remove the sleep and check it outside of the script instead.

I usually want the script to execute as fast as possible. Only when there is a unnecessary separate sleep action after it, then I will just combine it to the script, usually only sleep for several hundreds miliseconds though. I wonder what kind of the usage of sleep() inside the script. Can you give example of the usage?

[digitalstone]

I usually want the script to execute as fast as possible. Only when there is a unnecessary separate sleep action after it, then I will just combine it to the script, usually only sleep for several hundreds miliseconds though. I wonder what kind of the usage of sleep() inside the script. Can you give example of the usage?

Well the flow that caused me to place this topic is a flow where i'm making use of sleep in between certain settings, creating an automated break for when i'm at work.

Simplistic example:
Airplane mode off, 15min sleep, airplane mode on.

Another example would be to have a profile for going to bed whereby the screen-orientation or something stays fixed... then 30 minutes later the actual sleep-profile goes active even when i'm asleep and thus unable to do so myself.

[Desmanto]

That is separated by different action, should have use Action sleep instead of script (unless you want to do something in the middle too). Looking the problem above, you should really split the sleep out from the script. But I consider any sleep longer than 1 minute inefficient (or 5 minutes max for tolerance). Similar to what I mention in this thread : viewtopic.php?f=5&t=7181

I have faced the same problem from the beginning of using automagic. When I am downloading something, I want to make sure I keep the screen on. I have faced too many failed download caused by the screen off, even though I have excluded all downloader from the power save. So I make a flow where I can choose 30 minutes, 1 hour, 2 hours or 4 hours. After the time passed, it will switched back to original display timeout.

I use Trigger Glovar Date/time for this, not sleep. Since if I make the sleep for 4 hours, the flow keep running for those sleep time, wasting CPU cycle for almost nothing. To set the timer, I simply add current time with the timeout I needed. Example

Code: Select all

global_display_timeout_reset = addMinutes(getDate(), timeout); //timeout can be 30, 60, 120 or any value we set

Then in the same flow, I branch out the trigger Glovar Date/time to set back the display timeout to original. So the flow has two trigger, Shortcut to set the timeout and Glovar Date/time to set back the timeout. Have been using it since beginning.

If you afraid it will drain more battery, you can split out the flow which reset the state, and only enable the flow after the first set (airplane mode on) from main flow. The second flow only active and when timeout reached, it will disable itself and set back the state (airplane mode off). Thus wasting no battery when inactive.

This weekend, I just finish 2 of my long term flow, screenshot collage and TWRP reminder. (ah, the feel). The lastest trick I use in the TWRP reminder; when I tap on postpone reminder, it will create the glovar date/time. Then when the glovar date/time triggered, it will remove the glovar itself, thus wasting almost no glovar space. It will only appear during the postpone time. If I backup immediately, the glovar never created, never occupy unnecessary precious glovar space there.

I planned to renew some of my other flow using this new trick. I have a temporary flow disabler, but currently only work for single flow at one moment. I should reserve 5 glovar, and then delete them after triggered; thus never occupy the glovar space unless it is activated.