1) Give a description of the problem
One of my pistons is a very simple data logger that simply logs an info line and then dumps the data into an appropriate fuel stream. (I use it for a bunch of temperature sensors and power meters.) By default, I regularly get 10-second semaphore delays that I’m not expecting. If I turn on parallelism, it fixes the problem, but I’d like to understand why it’s happening at all. Multiple simultaneous triggers are expected (e.g., the Smartstrip sends both individual powerX and summed power readings at the same time). But I’d also expect the semaphore to only be held very briefly and the two calls to run rapidly in sequence. Am I misunderstanding?
Many thanks for any assistance!
2) What is the expected behavior?
Short semaphore waits and no warnings.
3) What is happening/not happening?
10-second semaphore wait warnings.
**4) Post a Green Snapshot of the piston
5) Attach any logs (From ST IDE and by turning logging level to Full)
I’ve attempted to capture a single example of the failure, though they happen regularly (2-3 times per minute).
Piston log:
3/12/2018, 10:57:40 AM +641ms
+2ms ╔Received event [Aeon SmartStrip].power4 = 60.21 with a delay of 145ms
+10262ms ║RunTime Analysis CS > 18ms > PS > 10150ms > PE > 94ms > CE
+10263ms ║Piston waited at a semaphore for 10079ms
+10265ms ║Runtime (40208 bytes) successfully initialized in 10150ms (v0.3.000.20180224) (10262ms)
+10266ms ║╔Execution stage started
+10272ms ║║Cancelling statement #2's schedules...
+10281ms ║║Calculating (string) Aeon SmartStrip + (string) - >> (string) Aeon SmartStrip -
+10283ms ║║Calculating (string) Aeon SmartStrip - + (string) power4 >> (string) Aeon SmartStrip - power4
+10285ms ║║Calculating (string) Aeon SmartStrip - power4 + (string) : >> (string) Aeon SmartStrip - power4:
+10287ms ║║Calculating (string) Aeon SmartStrip - power4: + (string) 60.21 >> (string) Aeon SmartStrip - power4: 60.21
+10291ms ║║Aeon SmartStrip - power4: 60.21
+10292ms ║║Executed virtual command log (1ms)
+10298ms ║║Calculating (string) Aeon SmartStrip + (string) - >> (string) Aeon SmartStrip -
+10300ms ║║Calculating (string) Aeon SmartStrip - + (string) power4 >> (string) Aeon SmartStrip - power4
+10305ms ║║Executed virtual command writeToFuelStream (2ms)
+10308ms ║╚Execution stage complete. (43ms)
+10309ms ╚Event processed successfully (10309ms)
3/12/2018, 10:57:40 AM +629ms
+2ms ╔Received event [Aeon SmartStrip].power = 62.16 with a delay of 146ms
+349ms ║RunTime Analysis CS > 19ms > PS > 76ms > PE > 254ms > CE
+352ms ║Runtime (40128 bytes) successfully initialized in 76ms (v0.3.000.20180224) (348ms)
+353ms ║╔Execution stage started
+359ms ║║Cancelling statement #2's schedules...
+369ms ║║Calculating (string) Aeon SmartStrip + (string) - >> (string) Aeon SmartStrip -
+371ms ║║Calculating (string) Aeon SmartStrip - + (string) power >> (string) Aeon SmartStrip - power
+374ms ║║Calculating (string) Aeon SmartStrip - power + (string) : >> (string) Aeon SmartStrip - power:
+376ms ║║Calculating (string) Aeon SmartStrip - power: + (string) 62.16 >> (string) Aeon SmartStrip - power: 62.16
+379ms ║║Aeon SmartStrip - power: 62.16
+380ms ║║Executed virtual command log (1ms)
+387ms ║║Calculating (string) Aeon SmartStrip + (string) - >> (string) Aeon SmartStrip -
+389ms ║║Calculating (string) Aeon SmartStrip - + (string) power >> (string) Aeon SmartStrip - power
+412ms ║║Executed virtual command writeToFuelStream (20ms)
+414ms ║╚Execution stage complete. (62ms)
+415ms ╚Event processed successfully (415ms)
SmartThings log:
85117b08-b505-4c5b-81db-aef513491c41 10:57:49 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
edeceb82-75d9-4c15-b16e-803770fd2c33 10:57:50 AM: trace ║║ Executed virtual command log (1ms)
edeceb82-75d9-4c15-b16e-803770fd2c33 10:57:50 AM: debug ║║ Calculating (string) Aeon SmartStrip - power4: + (string) 60.21 >> (string) Aeon SmartStrip - power4: 60.21
edeceb82-75d9-4c15-b16e-803770fd2c33 10:57:50 AM: debug ║║ Calculating (string) Aeon SmartStrip + (string) - >> (string) Aeon SmartStrip -
edeceb82-75d9-4c15-b16e-803770fd2c33 10:57:50 AM: trace ║ Runtime (40208 bytes) successfully initialized in 10150ms (v0.3.000.20180224) (10262ms)
edeceb82-75d9-4c15-b16e-803770fd2c33 10:57:50 AM: warn ║ Piston waited at a semaphore for 10079ms
85117b08-b505-4c5b-81db-aef513491c41 10:57:46 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:50 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:46 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:49 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:46 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:49 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:49 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:46 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:48 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:45 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:48 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:48 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:45 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:48 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:47 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:47 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:44 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:47 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:44 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:47 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:44 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:44 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:45 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:43 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:45 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:43 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:42 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:43 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:42 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:43 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:42 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:42 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:41 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:41 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:41 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:41 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:40 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
85117b08-b505-4c5b-81db-aef513491c41 10:57:40 AM: info smartapp_pause called by smartAppName=webCoRE, value=250, smartAppVersionId=714bb28a-6f90-4b68-a803-e05d71627112
edeceb82-75d9-4c15-b16e-803770fd2c33 10:57:40 AM: info ╚ Received event [Aeon SmartStrip].power4 = 60.21 with a delay of 145ms
edeceb82-75d9-4c15-b16e-803770fd2c33 10:57:41 AM: debug ║║ Calculating (string) Aeon SmartStrip - power: + (string) 62.16 >> (string) Aeon SmartStrip - power: 62.16
edeceb82-75d9-4c15-b16e-803770fd2c33 10:57:41 AM: debug ║║ Calculating (string) Aeon SmartStrip - power + (string) : >> (string) Aeon SmartStrip - power:
edeceb82-75d9-4c15-b16e-803770fd2c33 10:57:41 AM: trace ║╔ Execution stage complete. (62ms)
edeceb82-75d9-4c15-b16e-803770fd2c33 10:57:40 AM: debug ║║ Calculating (string) Aeon SmartStrip + (string) - >> (string) Aeon SmartStrip -
edeceb82-75d9-4c15-b16e-803770fd2c33 10:57:40 AM: debug ║║ Cancelling statement #2's schedules...
edeceb82-75d9-4c15-b16e-803770fd2c33 10:57:41 AM: debug ║║ Calculating (string) Aeon SmartStrip + (string) - >> (string) Aeon SmartStrip -
edeceb82-75d9-4c15-b16e-803770fd2c33 10:57:40 AM: trace ║╚ Execution stage started
edeceb82-75d9-4c15-b16e-803770fd2c33 10:57:41 AM: trace ║║ Executed virtual command log (1ms)
edeceb82-75d9-4c15-b16e-803770fd2c33 10:57:40 AM: debug ║ RunTime Analysis CS > 19ms > PS > 76ms > PE > 254ms > CE
edeceb82-75d9-4c15-b16e-803770fd2c33 10:57:40 AM: info ╚ Received event [Aeon SmartStrip].power = 62.16 with a delay of 146ms
dd3853aa-b9f1-4099-bb2d-6d6928b2193b 10:57:40 AM: debug Power: oldValue: 59.79, newValue: 62.16, delta: 4.0%, threshold: 15%
dd3853aa-b9f1-4099-bb2d-6d6928b2193b 10:57:40 AM: debug A sensor event occurred: [name:power, deviceId:8d923824-8f8d-4889-9d87-01033bff5d4d, isoDate:2018-03-12T17:57:40.483Z, unit:W, value:62.16]
Thanks again!
Best,
puk
