Hi all
I have two plugins the first one is the ELK M1 plugin and the second is a DALI plugin I am working on. Part of my testing is a scene where a sensor on the ELK M1 switches on a light via the DALI plugin.
Currently this is taking approx 10 sec from when sensor is tripped, does anyone have any ideas on how I can reduce this delay as 10 seconds is too much.
Thanks
Zoot
You’d have to look at the components to see what’s really going on. If you switch Vera into verbose logging, you’ll see when the data arrives, or is sent, from each component along with the various variables being set (that in turn cause the scenes to fire)
For my panels, for example, I typically see a very short lag between the physical event (open a window), the panel itself recognizing it, and Vera detecting it. My sensors are all hard wired though, so wireless sensors will make that worse.
Both plugins have acceptable timing it is looking more like the LUUP engine that is the issue.
ELK-M1 plugin sensor trip → automation scene → DALI plugin light on = 10 to 16 sec. Not good enough for the required purposes 
Not sure if there is much I can do, would a hardware upgrade help, currently have V2 hardware?
John
What else is going on with your unit?
Is it a normal home/production system?
What is the resource usage before you trigger the scene?
Have you have logging to a usb and/virtual swapfile? If not, in doing so you may see some improvements.
Your logs file should indicate if this is the case; ensure, that test are conducted with and without verbose logging enabled as well.
The Vera3 does have a faster CPU and increased memory and therefore, it will should improve response time if it is a resource issue. There is the option available to upgrade and return your old unit at the moment which may be an option but seeing your in Oz, and Smarthome have just reduced their price, it might be worth a look at as well. See offer http://forum.micasaverde.com/index.php/topic,11437.msg82014.html#new
You could also test this by removing some plugin (normal culprit energy monitoring) etc but ensure you do a back up first.
You should get the discrete times for the components of this Scene. If you enable Verbose Logging, you’ll see it all, and be able to determine where this “end-to-end” time is really coming from.
I’ve never seen a single component cause a 10 second delay, so it’s likely that you’re getting nickel’d and dime’d by each transaction (or 5 and 10cent’d in local currencies 8) )
@guessed
I did as you suggested when you originally suggested it but to be honest a lot of it did not make sense.
Would you have a look if I uploaded or give me some pointers on what to look for?
What else is going on with your unit?Currently ELK-M1 with 5 sensors + 3 smokes, 1 x Generic IP Camera, Rain8Net & DALI plugins.
The big users here may be the Rain8Net and DALI plugins as I am polling frequently due to needing to send commands to check state.
Is it a normal home/production system?Both
What is the resource usage before you trigger the scene?Have not actually checked, will do so tonight if I get a chance. Use top I assume?
Have you have logging to a usb and/virtual swapfile? If not, in doing so you may see some improvements.Logging to USB but have not done anything with swap, will also have a look at this.
You could also test this by removing some plugin (normal culprit energy monitoring) etc but ensure you do a back up first.Already removed energy monitoring but will also start from scratch and see if it makes a difference.
I think that instead of throwing my hands in the air and blaming the LUUP engine I better do more investigation.
Thanks
John
Hello John,
You may be able to also get additional feedback if you attach you plugin.
Is the same delay encountered using a scene with the same trigger and a another light that is not process through your plugin?
As you were potentially looking at upgrading (more attractive especially with the deal being offered directly from an Australian supplier) this may give you a different opportunity to Test. E.g. If you ordered one of the Vera 3 there is a time lag between return your Vera 2 and thus, you maybe able to perform this under cleaner conditions and without immediately disrupting your home unit.
Enabled verbose log as suggested by guessed (attached text/cvs) with excerpt below.
What does this mean?
07 08/07/12 20:11:57.601 Event::Evaluate 1 Office occupied scene testScene is false repeat 0/-1 <0x4813>
I have also attached the plugin I am working on for any help in that direction.
52 08/07/12 20:11:57.557 0x30 0x41 0x5a 0x43 0x30 0x30 0x35 0x39 0x30 0x30 0x43 0x34 (0AZC005900C4) <0x4813>
06 08/07/12 20:11:57.559 Device_Variable::m_szValue_set device: 429 service: urn:micasaverde-com:serviceId:SecuritySensor1 variable: Tripped was: 0 now: 1 #hooks: 1 upnp: 0 v:0x872100/NONE duplicate:0 <0x4813>
07 08/07/12 20:11:57.601 Event::Evaluate 1 Office occupied scene testScene is false repeat 0/-1 <0x4813>
07 08/07/12 20:12:42.715 Event::Evaluate 1 Office occupied scene testScene is true users:(null) allow:1 <0x4813>
08 08/07/12 20:12:42.716 Scene::RunScene running 7 testScene <0x4813>
08 08/07/12 20:12:42.718 JobHandler_LuaUPnP::HandleActionRequest device: 435 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x4813>
08 08/07/12 20:12:42.719 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=40 <0x4813>
50 08/07/12 20:12:42.730 luup_log:434: dali: debug: processData: entering, free (entries=1) <0x4813>
01 08/07/12 20:12:42.736 luup_log:434: dali: processQueue: <0x00 0x66 0xC5> <0x4813>
25 08/07/12 20:12:42.737 luup_io_write 434 size: 7 <0x4813>
51 08/07/12 20:12:42.738 0xa3 0x0 0x0 0x0 0x0 0x66 0xc5 (#####f#) <0x4813>
25 08/07/12 20:12:42.739 luup_io_write 434 result: 1 <0x4813>
50 08/07/12 20:12:42.749 luup_log:434: dali: debug: processData: exiting, busy (entries=1) <0x4813>
10 08/07/12 20:12:42.752 Scene::RunScene delay time 120 for scene 7 device 435 group 0 cmd 0 <0x4813>
52 08/07/12 20:12:42.774 0x52 (R) <0x5416>
52 08/07/12 20:12:42.776 0x0 (#) <0x5416>
52 08/07/12 20:12:42.777 0x52 (R) <0x5416>
50 08/07/12 20:12:42.778 luup_log:434: dali: debug: defaultHander: Byte0=0x52 Byte1=0x00 Byte2=0x52 <0x5416>
50 08/07/12 20:12:43.014 luup_log:434: dali: debug: pollQueue: <0x83 0x00 0x00> <0x1c08>
50 08/07/12 20:12:43.015 luup_log:434: dali: debug: processData: entering, free (entries=1) <0x1c08>
01 08/07/12 20:12:43.016 luup_log:434: dali: processQueue: <0x01 0xA0 0x22> <0x1c08>
25 08/07/12 20:12:43.017 luup_io_write 434 size: 7 <0x1c08>
51 08/07/12 20:12:43.018 0x83 0x0 0x0 0x0 0x1 0xa0 0x22 (######") <0x1c08>
25 08/07/12 20:12:43.020 luup_io_write 434 result: 1 <0x1c08>
50 08/07/12 20:12:43.075 luup_log:434: dali: debug: targetStatusHander: Byte0=0x51 Byte1=0x66 Byte2=0x37 <0x5416>
06 08/07/12 20:12:43.076 Device_Variable::m_szValue_set device: 435 service: urn:upnp-org:serviceId:Dimming1 variable: LoadLevelStatus was: 0 now: 41 #hooks: 2 upnp: 0 v:0x80e730/NONE duplicate:0 <0x5416>A few things to look at:
a) You have a device that’s going into a 1-second poll cycle using call_timer()
This shows in the log as:
35,08/07/12 20:12:12.020,LuaInterface::CallFunction_Timer func:pollQueue device:434 <0x1c08>
but at one second intervals, which is very agressive. Look to see if it’s possible to eliminate timer-based polls altogether since they’ll inherently add load, and lag.
This is caused by device 434 on your system, but I can’t tell what that is from the log.
b) What are ZWave Nodes 2 & 4 in your network?
You may want to either fix it, or remove it from your network (and commands/scenes that call it). Is this involved in your Scene definition at all?
02,08/07/12 20:11:58.198,ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
02,08/07/12 20:12:00.408,ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
02,08/07/12 20:12:02.630,ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
02,08/07/12 20:12:26.036,ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02,08/07/12 20:12:28.219,ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02,08/07/12 20:12:30.398,ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02,08/07/12 20:12:32.648,ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
c) This is an example of the Alarm Sensor being tripped.
You can see the IO Line just before it that likely the Alarm panel code is triggering off to then set the variable
52,08/07/12 20:11:57.557,0x30 0x41 0x5a 0x43 0x30 0x30 0x35 0x39 0x30 0x30 0x43 0x34 (0AZC005900C4) <0x4813>
06,08/07/12 20:11:57.559,Device_Variable::m_szValue_set device: 429 service: urn:micasaverde-com:serviceId:SecuritySensor1 variable: Tripped was: 0 now: 1 #hooks: 1 upnp: 0 v:0x872100/NONE duplicate:0 <0x4813>
d) Do you have two different Control Point devices polling Vera?
Or perhaps 2 different browsers running against it simultaneously? These always seem to occur in pairs close together:
12,08/07/12 20:12:01.032,luvd_get_info_data_request starting /data_request?id=lu_status&DataVersion=341433071&MinimumDelay=1000&Timeout=60&LoadTime=1344341433&rand=0.2379114900589816 pMem 0x998000/10059776 diff: 2199552 <0x6017>
12,08/07/12 20:12:01.852,luvd_get_info_data_request starting /data_request?id=lu_status&DataVersion=341433071&MinimumDelay=1000&Timeout=60&LoadTime=1344341433&rand=0.9470684811273994 pMem 0x998000/10059776 diff: 2199552 <0x5c0b>
e) From this it looks like you’re processing the [armed] Sensor Tripped event fairly quickly:
Looking at your logs a little, I’d guess that you set the Scene to only fire for [Armed?] Sensor events moving to the Untripped state. Not sure what’s [programatically?] setting the Armed state of the SecuritySensor device (#429) either, since that looks a little odd, but perhaps that’s the behavior of your Panel’s Plugin.
52,08/07/12 20:12:42.666,0x30 0x41 0x5a 0x43 0x30 0x30 0x35 0x32 0x30 0x30 0x43 0x42 (0AZC005200CB) <0x4813>
06,08/07/12 20:12:42.668,Device_Variable::m_szValue_set device: 429 service: urn:micasaverde-com:serviceId:SecuritySensor1 variable: Armed was: 1 now: 1 #hooks: 0 upnp: 0 v:0x8727a0/NONE duplicate:1 <0x4813>
06,08/07/12 20:12:42.670,Device_Variable::m_szValue_set device: 429 service: urn:micasaverde-com:serviceId:SecuritySensor1 variable: Tripped was: 1 now: 0 #hooks: 1 upnp: 0 v:0x872100/NONE duplicate:0 <0x4813>
07,08/07/12 20:12:42.715,Event::Evaluate 1 Office occupied scene testScene is true users:(null) allow:1 <0x4813>
08,08/07/12 20:12:42.716,Scene::RunScene running 7 testScene <0x4813>
50,08/07/12 20:12:42.730,"luup_log:434: dali: debug: processData: entering, free (entries=1) <0x4813>"
01,08/07/12 20:12:42.736,luup_log:434: dali: processQueue: <0x00 0x66 0xC5> <0x4813>
25,08/07/12 20:12:42.737,luup_io_write 434 size: 7 <0x4813>
51,08/07/12 20:12:42.738,0xa3 0x0 0x0 0x0 0x0 0x66 0xc5 (#####f#) <0x4813>
25,08/07/12 20:12:42.739,luup_io_write 434 result: 1 <0x4813>
50,08/07/12 20:12:42.749,"luup_log:434: dali: debug: processData: exiting, busy (entries=1) <0x4813>"
12,08/07/12 20:12:42.761,luvd_get_info_data_request starting /data_request?id=lu_status&DataVersion=341433075&MinimumDelay=1000&Timeout=60&LoadTime=1344341433&rand=0.2264614942605372 pMem 0x998000/10059776 diff: 2199552 <0x6c14>
52,08/07/12 20:12:42.774,0x52 (R) <0x5416>
52,08/07/12 20:12:42.776,0x0 (#) <0x5416>
52,08/07/12 20:12:42.777,0x52 (R) <0x5416>
50,08/07/12 20:12:42.778,luup_log:434: dali: debug: defaultHander: Byte0=0x52 Byte1=0x00 Byte2=0x52 <0x5416>
12,08/07/12 20:12:42.799,luvd_get_info_data_request starting /data_request?id=lu_status&DataVersion=341433075&MinimumDelay=1000&Timeout=60&LoadTime=1344341433&rand=0.4935834708530268 pMem 0x998000/10059776 diff: 2199552 <0x6017>
35,08/07/12 20:12:43.011,LuaInterface::CallFunction_Timer func:pollQueue device:434 <0x1c08>
50,08/07/12 20:12:43.014,luup_log:434: dali: debug: pollQueue: <0x83 0x00 0x00> <0x1c08>
50,08/07/12 20:12:43.015,"luup_log:434: dali: debug: processData: entering, free (entries=1) <0x1c08>"
01,08/07/12 20:12:43.016,luup_log:434: dali: processQueue: <0x01 0xA0 0x22> <0x1c08>
25,08/07/12 20:12:43.017,luup_io_write 434 size: 7 <0x1c08>
51,08/07/12 20:12:43.018,"0x83 0x0 0x0 0x0 0x1 0xa0 0x22 (######"") <0x1c08>"
25,08/07/12 20:12:43.020,luup_io_write 434 result: 1 <0x1c08>
52,08/07/12 20:12:43.070,0x51 (Q) <0x5416>
52,08/07/12 20:12:43.072,0x66 (f) <0x5416>
52,08/07/12 20:12:43.074,0x37 (7) <0x5416>
50,08/07/12 20:12:43.075,luup_log:434: dali: debug: targetStatusHander: Byte0=0x51 Byte1=0x66 Byte2=0x37 <0x5416>
06,08/07/12 20:12:43.076,Device_Variable::m_szValue_set device: 435 service: urn:upnp-org:serviceId:Dimming1 variable: LoadLevelStatus was: 0 now: 41 #hooks: 2 upnp: 0 v:0x80e730/NONE duplicate:0 <0x5416>
a) You have a device that's going into a 1-second poll cycle using call_timer()This is the serial to DALI protocol converter which has the light connected I want to turn on in the scene.
The polling is more to ensure that commands in the queue are sent promptly to ensure that things are instantaneous ( that didn’t work 
). I will remove command queue and polling and see if it makes a difference.
b) What are ZWave Nodes 2 & 4 in your network?Node 2 is a minimote and node 4 is a bedside lamp (inline zwave device) that is switched off at the power point.
c) This is an example of the Alarm Sensor being tripped. You can see the IO Line just before it that likely the Alarm panel code is triggering off to then set the variable
Correct in both accounts, this is the actual beginning of the scene.
d) Do you have two different Control Point devices polling Vera? Or perhaps 2 different browsers running against it simultaneously? These always seem to occur in pairs close together:
Usually running firefox with two tabs open. One with the devices and one permanently on the “Luup file upload” so I can just go to that tab and hit upload/restart when I am working on the plugin.
e) From this it looks like you're processing the [armed] Sensor Tripped event fairly quickly: Looking at your logs a little, I'd guess that you set the Scene to only fire for [Armed?] Sensor events moving to the Untripped state. Not sure what's [programatically?] setting the Armed state of the SecuritySensor device (#429) either, since that looks a little odd, but perhaps that's the behavior of your Panel's Plugin.
Yes, I agree the processing for the sensor is close enough to real time. The scene was set for “An armed sensor is tripped”. The event in the log for moving to the untripped state is not part of the event just happened as I was testing.
Best Home Automation shopping experience. Shop at Ezlo!
© 2024 Ezlo Innovation, All Rights Reserved. Terms of Use | Privacy Policy | Forum Rules