search

smich123 / open-zwave

Automatically exported from code.google.com/p/open-zwave
0 stars 0 forks source link

Slow performance in latest builds #164

Open GoogleCodeExporter opened 9 years ago

GoogleCodeExporter commented 9 years ago 
See the attached log.  Initial polling time have increase dramatically and 
often All Nodes Queried is never even reached.

Original issue reported on code.google.com by aa...@aarondrabeck.com on 24 Jan 2013 at 6:28

Attachments:

GoogleCodeExporter commented 9 years ago 
I think that's due to the RETRY_TIMEOUT change from 2s to 40s in src/Defs.h
I decreased it in my local copy because I experienced the same slow startup.

Original comment by matthias...@googlemail.com on 24 Jan 2013 at 11:29

GoogleCodeExporter commented 9 years ago 
Nice, this helped a bit.  However the dll is still much slower than in previous 
versions.  Could their be deadlocks or thread issues?

Original comment by aa...@aarondrabeck.com on 25 Jan 2013 at 5:34

GoogleCodeExporter commented 9 years ago 
Looking at your OZW_Log.txt, there -is- a bug in the open-zwave. See below it 
jumps from 23:07:25 to 23:09:19 and nothing happened in between Also it waits 
for another +/- minute, because after the 23:09:19 it only continues at 
23:10:23. The library should continue with it, because it didn't fully 
initialize.

2013-01-23 23:07:25.649 Node036, QueryStage_WakeUp
2013-01-23 23:07:25.652 Node036, QueryStage_ManufacturerSpecific1
2013-01-23 23:07:25.654 Node036, QueryStage_NodeInfo
2013-01-23 23:07:25.657 Node036, Queuing (Query) Request Node Info (Node=36): 
0x01, 0x04, 0x00, 0x60, 0x24, 0xbf
2013-01-23 23:07:25.660 Node036, Queuing (Query) Query Stage Complete (NodeInfo)
2013-01-23 23:07:25.663 contrlr,   Expected reply was received
2013-01-23 23:07:25.665 contrlr,   Message transaction complete
2013-01-23 23:07:25.668 
2013-01-23 23:09:18.728 Node007, Basic::Set - Setting node 7 to level 20
2013-01-23 23:09:18.730 Node007, Queuing (Send) Basic Set (Node=7): 0x01, 0x0a, 
0x00, 0x13, 0x07, 0x03, 0x20, 0x01, 0x14, 0x25, 0x04, 0xf6
2013-01-23 23:09:18.732 Node007, Queuing (Send) BasicCmd_Get (Node=7): 0x01, 
0x09, 0x00, 0x13, 0x07, 0x02, 0x20, 0x02, 0x25, 0x05, 0xe2
2013-01-23 23:09:21.943 Node007, Basic::Set - Setting node 7 to level 0
2013-01-23 23:09:21.945 Node007, Queuing (Send) Basic Set (Node=7): 0x01, 0x0a, 
0x00, 0x13, 0x07, 0x03, 0x20, 0x01, 0x00, 0x25, 0x06, 0xe00
2013-01-23 23:09:21.947 Node007, Queuing (Send) BasicCmd_Get (Node=7): 0x01, 
0x09, 0x00, 0x13, 0
2013-01-23 23:10:23.994 
2013-01-23 23:10:23.997 contrlr, Sending (Command) message (Callback ID=0x00, 
Expected Reply=0x00) - FUNC_ID_SERIAL_API_APPL_NODE_INFORMATION: 0x01, 0x08, 
0x00, 0x03, 0x01, 0x02, 0x01, 0x01, 0x2b, 0xdc
2013-01-23 23:10:24.002 contrlr, Removing current message

Original comment by uAle...@gmail.com on 25 Jan 2013 at 6:46

GoogleCodeExporter commented 9 years ago 
@Greg:

Is the following "delay" of 8-9 seconds normal (was also in the older 
open-zwave):

2013-01-25 08:04:56.228 Node014, Queuing (Send) Get Associations (Node=14): 
0x01, 0x0a, 0x00, 0x13, 0x0e, 0x03, 0x85, 0x02, 0x01, 0x25, 0x09, 0x41
2013-01-25 08:04:56.228 Node014, Queuing (Query) Query Stage Complete 
(Associations)
2013-01-25 08:04:56.229 contrlr,   Expected reply was received
2013-01-25 08:04:56.230 contrlr,   Message transaction complete
2013-01-25 08:04:56.230 
2013-01-25 08:05:04.507 
2013-01-25 08:05:04.511 contrlr, Sending (Command) message (Callback ID=0x00, 
Expected Reply=0x00) - FUNC_ID_SERIAL_API_APPL_NODE_INFORMATION: 0x01, 0x08, 
0x00, 0x03, 0x01, 0x02, 0x01, 0x01, 0x2b, 0xdc
2013-01-25 08:05:04.516 contrlr, Removing current message
2013-01-25 08:05:04.516 
2013-01-25 08:05:04.517 Node001, Sending (Command) message (Callback ID=0x00, 
Expected Reply=0x80) - Get Routing Info (Node=1): 0x01, 0x07, 0x00, 0x80, 0x01, 
0x00, 0x00, 0x03, 0x7a
2013-01-25 08:05:04.524 Node001,   Received: 0x01, 0x20, 0x01, 0x80, 0x82, 
0x11, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 
0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x0
0, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0xcd
2013-01-25 08:05:04.525

Original comment by uAle...@gmail.com on 25 Jan 2013 at 7:18

GoogleCodeExporter commented 9 years ago 
I don't understand the timings here at all but I haven't really looked into 
this one deeply yet. I suspect that Aaron's zwcfg is out of date so that may 
have something to do with it. Also depending on what else the user program is 
doing it can starve the library's threads from running and there isn't much the 
library can do about it. I also don't understand the snippet where the 
SERIAL_API_APPL_NODE_INFO message is happening so late. This should really 
happen right up front as part of the controller initialization. How did the 
Associations query and multiple stages get going before controller 
initialization has finished? Too many things are out of whack.

The two things that did jump out are the missing dead node detection after 
discovery. The challenge with doing dead node detection after discovery is 
marginal nodes could be considered dead. They might work well enough for people 
now but the dead node detection code might stop letting the library talk to 
them. This is code that is going to make some people unhappy somewhere.

The other is not having to wait for the timeout (40s) when the send data 
request is returned correctly.

Original comment by glsatz on 25 Jan 2013 at 9:46

GoogleCodeExporter commented 9 years ago 
[deleted comment]
GoogleCodeExporter commented 9 years ago 
[deleted comment]
GoogleCodeExporter commented 9 years ago 
Here is a fresh log after I removed the zwcfg.  I try to delete it quite often 
as it tends to create problems.  I am using a r635 build w/RETRY_TIMEOUT change 
from 40s to 2s in src/Defs.h as suggested.  Perhaps this change should be 
committed?  Also I am compiling with VS2012 which uses the c++ 2012 compiler, 
although that shouldn't make a difference.

I am the developer for zVirtualScenes and I am using that for testing.  I have 
not significantly changed the code in my OpenZwave plug-in for years, so it 
makes for a relatively stable test environment.

Original comment by aa...@aarondrabeck.com on 26 Jan 2013 at 3:53

Attachments:

GoogleCodeExporter commented 9 years ago 
Here is the Log from the second time run presumably Openzwave is consuming the 
config. 

2013-01-25 20:34:54,671  - Start first time run - initializing driver
2013-01-25 20:44:51,413  - End first time run - All Node Queried

2013-01-25 20:54:44,166 - Start second time run - initializing driver
2013-01-25 21:00:06,083 - Start second time run - All Node Queried

Original comment by aa...@aarondrabeck.com on 26 Jan 2013 at 4:09

Attachments:

GoogleCodeExporter commented 9 years ago 
Issue 162 has been merged into this issue.

Original comment by glsatz on 26 Jan 2013 at 4:50

GoogleCodeExporter commented 9 years ago 

I have the same problem here after updating from r603 to r663.(linux debian5 on 
a slow 486-like cpu)

The problem I see is that the library sometimes hang for (at maximum) 40 
seconds, causing commands to be delayed a lot and other nasty problems.

I tryed to follow the code flow, putting debug msgs here and there, and I found 
that the library is waiting at src/Driver.cpp, around line 390, exacly when it 
does:

int32 res = Wait::Multiple( waitObjects, count, timeout );

As a fast fix/workaround/hack I forced the 'timeout' variable at 2000 (2secs) 
just before that line, now commands are delivered fast as expected but other 
problems raises, like lots of false timeouts from the devices.

Hope this info can be usefull to solve this problem

thanks
davemds

Original comment by dave@gurumeditation.it on 3 Sep 2013 at 2:43