Step 0: Tell you about the Piston
I have a smart bulb that I want to slowly dim from 50% to 0%(off). I have tried using the built in function to change the level, but that reduces the level in a linear fashion. But the way that our eyes/brain works for light reception is more logarithmic or exponential, i.e. 1% reduction when it’s dim is a bigger difference than 1% when it’s bright. (2% to 1% is more noticeable than 52% to 51%). SOOO, I crazily decided to simply code up an exponential decaying function (see piston). (1st world problem, I know)
Pre-emptive answers to some programming questions:
I use a virtual light switch to turn on this exponentially decaying function. I run it inside of a while loop so that I can break out of it by turning off the bulb by external smart means (“Alexa, turn off corner bulb”). I turn off the virtual light switch 2 seconds after starting the piston and before the while loop so that I can restart the dimming process mid-way if I wanted. I only send the command to the smart bulb if the level is different from what it currently is to prevent too much traffic on the network.
1) Give a description of the problem
The piston executes generally OK. But I look at the logs and sometimes it “waits at a semaphore”. When looking at the code and logs, it doesn’t make sense why it would do this. Nowhere in the logs does it say to “wake up at this time”. So why is it waking up? Then having to wait at the semaphore…
2) What is the expected behaviour?
I expect it to just keep cycling through the while loop until it finishes lowering the light level. BTW, it does this just fine, it’s just that it “hiccups” sometimes, but I’m curious for the following (question 3)
3) What is happening/not happening?
I don’t understand the semaphore at 8:35:40 PM and 8:35:41 PM.
I compiled a summary of the runs & times starting with the 3 preceding cycles through the piston, starting at 8:34:53 PM, it says:
8:34:41 PM, runs, then sets a job for 8:34:53 PM
8:34:53 PM, runs, then sets a job for 8:35:06 PM
8:35:31 PM, runs, then sets a job for 8:35:44 PM
8:35:40 PM, waits at a semaphore, then sets a job for 8:35:44 PM
8:35:42 PM, runs, then sets a job for 8:35:53 PM
8:35:41 PM, runs, then sets a job for 8:35:54 PM *** NOTES HERE******
8:35:45 PM, waits at a semaphore, then sets a job for 8:35:54 PM
8:35:55 PM, runs, then sets a job for 8:36:07 PM
then continues on as expected.
For the most part, you can see in the logs below that the piston cycles through (gets woken up) about every 10 to 12 seconds. This is because Webcore can only run for 10 seconds at most, and then I’ve programmed 3second waits which means the next wakeup would be at most 13 seconds from the last wakeup. Hence, most wakeups in the 12second range.
But perhaps where the issue is, is where it was supposed to wake up at 8:35:06 PM, but didn’t actually wake up until 8:35:31 PM. Maybe that’s the real issue here. Why did it do that?
OK, also, look at the 2 runs at 8:35:42 and 8:35:41. First of all, these are out of order (look at the logs). Also, it never said to wake up at either of these times. The 2 previous runs (one was a semaphore), said to wake up at 8:35:44. Why did it wake up early?
Oh wait, I just looked, and it says the wakup event is “home.execute =recovery”, whereas most of the other ones are even: “Home.time = xxxxx”. Maybe that has something to do with it?
For the semaphore at 8:34:08 PM, I understand the piston is woken up because the virtual switch is turned off, and that is a trigger. So the piston wakes up, but it has to wait until the end of the next run to realize that it doesn’t need to run again. I don’t really have a question there.
I also understand that pistons can only run in 10second blocks. If what you’re asking the piston to do, takes longer than 10 seconds, it creates a scheduled job for X time in the future (sometimes 3 seconds, sometimes less).
4) Post a Green Snapshot of the piston
5) Attach logs after turning logging level to Full
3/9/2020, 8:45:06 PM +115ms
+0ms ╔Received event [Home].time = 1583801106651 with a delay of -536ms
+503ms ║Time: 624. Level: 1
+3590ms ║Time: 627. Level: 0
+3649ms ╚Event processed successfully (3649ms)
3/9/2020, 8:44:54 PM +110ms
+0ms ╔Received event [Home].time = 1583801094691 with a delay of -582ms
+249ms ║Time: 612. Level: 1
+3338ms ║Time: 615. Level: 1
+6427ms ║Time: 618. Level: 1
+9521ms ║Time: 621. Level: 1
+9545ms ║Setting up scheduled job for Mon, Mar 9 2020 @ 8:45:06 PM EDT (in 2.997s)
+9557ms ╚Event processed successfully (9557ms)
I deleted a bunch for ease of viewing
3/9/2020, 8:36:07 PM +232ms
+1ms ╔Received event [Home].time = 1583800567674 with a delay of -443ms
+301ms ║Time: 96. Level: 25
+3411ms ║Time: 99. Level: 24
+6516ms ║Time: 102. Level: 24
+9647ms ║Time: 105. Level: 23
+9715ms ║Setting up scheduled job for Mon, Mar 9 2020 @ 8:36:19 PM EDT (in 2.992s)
+9725ms ╚Event processed successfully (9725ms)
3/9/2020, 8:35:55 PM +100ms
+1ms ╔Received event [Home].time = 1583800554356 with a delay of 744ms
+244ms ║Time: 84. Level: 27
+3346ms ║Time: 87. Level: 26
+6449ms ║Time: 90. Level: 26
+9537ms ║Time: 93. Level: 25
+9585ms ║Setting up scheduled job for Mon, Mar 9 2020 @ 8:36:07 PM EDT (in 2.99s)
+9595ms ╚Event processed successfully (9595ms)
3/9/2020, 8:35:45 PM +198ms
+0ms ╔Received event [Home].time = 1583800544581 with a delay of 617ms
+7858ms ║Piston waited at a semaphore for 7525ms
+7862ms ║Setting up scheduled job for Mon, Mar 9 2020 @ 8:35:54 PM EDT (in 1.297s)
+7883ms ╚Event processed successfully (7883ms)
3/9/2020, 8:35:41 PM +740ms
+1ms ╔Received event [Home].execute = recovery with a delay of 59ms
+261ms ║Time: 72. Level: 29
+3375ms ║Time: 75. Level: 29
+6468ms ║Time: 78. Level: 28
+9578ms ║Time: 81. Level: 28
+9622ms ║Setting up scheduled job for Mon, Mar 9 2020 @ 8:35:54 PM EDT (in 2.995s)
+9633ms ╚Event processed successfully (9632ms)
3/9/2020, 8:35:42 PM +534ms
+1ms ╔Received event [Home].execute = recovery with a delay of 83ms
+2149ms ║Time: 75. Level: 29
+5236ms ║Time: 78. Level: 28
+8335ms ║Time: 81. Level: 28
+8359ms ║Setting up scheduled job for Mon, Mar 9 2020 @ 8:35:53 PM EDT (in 2.996s)
+8367ms ╚Event processed successfully (8367ms)
3/9/2020, 8:35:40 PM +507ms
+1ms ╔Received event [Home].time = 1583800506207 with a delay of 34300ms
+1848ms ║Piston waited at a semaphore for 1504ms
+1853ms ║Setting up scheduled job for Mon, Mar 9 2020 @ 8:35:44 PM EDT (in 2.222s)
+1865ms ╚Event processed successfully (1865ms)
3/9/2020, 8:35:31 PM +861ms
+0ms ╔Received event [Home].time = 1583800506207 with a delay of 25653ms
+337ms ║Time: 60. Level: 32
+3456ms ║Time: 63. Level: 31
+6590ms ║Time: 66. Level: 31
+9685ms ║Time: 69. Level: 30
+9724ms ║Setting up scheduled job for Mon, Mar 9 2020 @ 8:35:44 PM EDT (in 2.996s)
+9732ms ╚Event processed successfully (9732ms)
3/9/2020, 8:34:53 PM +207ms
+1ms ╔Received event [Home].time = 1583800493726 with a delay of -519ms
+331ms ║Time: 48. Level: 35
+3437ms ║Time: 51. Level: 34
+6875ms ║Time: 54. Level: 34
+9962ms ║Time: 57. Level: 33
+10005ms ║Setting up scheduled job for Mon, Mar 9 2020 @ 8:35:06 PM EDT (in 2.995s)
+10011ms ╚Event processed successfully (10011ms)
3/9/2020, 8:34:41 PM +169ms
+0ms ╔Received event [Home].time = 1583800481676 with a delay of -508ms
+222ms ║Time: 36. Level: 38
+3331ms ║Time: 39. Level: 37
+6433ms ║Time: 42. Level: 37
+9522ms ║Time: 45. Level: 36
+9562ms ║Setting up scheduled job for Mon, Mar 9 2020 @ 8:34:53 PM EDT (in 2.996s)
+9570ms ╚Event processed successfully (9571ms)
3/9/2020, 8:34:29 PM +100ms
+1ms ╔Received event [Home].time = 1583800469810 with a delay of -710ms
+218ms ║Time: 24. Level: 42
+3326ms ║Time: 27. Level: 41
+6429ms ║Time: 30. Level: 40
+9541ms ║Time: 33. Level: 39
+9581ms ║Setting up scheduled job for Mon, Mar 9 2020 @ 8:34:41 PM EDT (in 2.996s)
+9590ms ╚Event processed successfully (9590ms)
3/9/2020, 8:34:17 PM +145ms
+0ms ╔Received event [Home].time = 1583800457379 with a delay of -234ms
+293ms ║Time: 12. Level: 46
+3410ms ║Time: 15. Level: 45
+6513ms ║Time: 18. Level: 44
+9619ms ║Time: 21. Level: 43
+9669ms ║Setting up scheduled job for Mon, Mar 9 2020 @ 8:34:29 PM EDT (in 2.997s)
+9678ms ╚Event processed successfully (9677ms)
3/9/2020, 8:34:08 PM +325ms
+2ms ╔Received event [Virtual Corner light switch].switch = off with a delay of 197ms
+7900ms ║Piston waited at a semaphore for 7763ms
+7911ms ╚Event processed successfully (7911ms)
3/9/2020, 8:34:05 PM +907ms
+1ms ╔Received event [Virtual Corner light switch].switch = on with a delay of 307ms
+2238ms ║Time: 3. Level: 49
+5334ms ║Time: 6. Level: 48
+8432ms ║Time: 9. Level: 47
+8476ms ║Setting up scheduled job for Mon, Mar 9 2020 @ 8:34:17 PM EDT (in 2.996s)
+8486ms ╚Event processed successfully (8486ms)