System Slowed To Crawl (UI 5)

clippermiami · October 10, 2014, 1:27am

In the past 24 hours my system has suddenly slowed to a crawl. I have checked everything I can think of, I have reloaded, i power cycled the Vera and it remains the same … It can take up to 30 seconds or more for the system to recognize a motion sensor and up to another 30 seconds before it acts on the motion by turning on the light.

I thought the problem might be related to the Bridged Vera environment so I broke the bridge and my Primary is now running on its own with no improvement.

There have been no ZWave device changes in the past several weeks, Over the past month I have reduced the number of PLEGs by merging a number of individual ones to a few consolidated PLEGs to try to save resources (currently 8 PLEGs running). None of these action have made any significant improvement. My CPU usage rarely drops below 65% and is generally at or above 80%. My AVAIL Memory is generally around 80 MB and the FREE Memory around 50Mb.

And then today it suddenly started running in “molasses mode” and I am at a loss to understand why

clippermiami · October 10, 2014, 11:52am

Further to this I’ve seen a significant increase in RESTARTS. It seems to restart for no apparent reason. This morning it did its normal restart at 02:00 then again just as I was checking the CPU report. CPU had been running around 40% over night and started to spike with the first “lights on” activity.

Yesterday I had the following RESTARTS:

Oct 9 02:27:57 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 02:28:22 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 04:46:28 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 08:06:32 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 08:06:59 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 08:13:42 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 08:14:21 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 08:15:06 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()

Oct 9 18:17:18 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 18:21:56 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 18:25:40 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 18:33:45 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 20:08:23 Vera-30010119 EventWatcher 0e user info EventWatcher: P [228] Alarm System, DetailedArmMode = NotReady ()
Oct 9 20:08:43 Vera-30010119 EventWatcher 0e user info EventWatcher: P [228] Alarm System, DetailedArmMode = Ready ()
Oct 9 20:13:45 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 20:21:18 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 20:30:36 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 20:38:12 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 20:45:41 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 20:49:24 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 20:49:52 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 20:50:25 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 20:51:42 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 20:54:07 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 20:56:16 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 20:58:48 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()
Oct 9 21:06:25 Vera-30010119 EventWatcher 0e user info EventWatcher: E [000] , Vera = RESTART ()

All seemingly for no reason. It looks like the system has developed some serious instability for some reason.

The slow response continues today, it took over 30 seconds for the motion sensor in the Kitchen to trigger the lights.

Z-Waver · October 10, 2014, 1:32pm

Did you make PLEG changes just prior to this problem’s manifestation?

Try SSHing in and running top to see which process if using the most CPU. The Vera process is /usr/bin/LuaUPnP

Are you logging to USB? Is the USB device mounted? Is the USB device failing and causing a lot of write retry attempts?

Look at your logs and determine where/when the delay occurs.

[ul][li]Does it take 30 seconds for Vera to see the trigger and then Vera responds immediately?[/li]
[li]Does Vera receive the trigger immediately, but take 30 seconds to respond?[/li]
[li]Does Vera receive the trigger and issue a response immediately, but then has to retry the command 30 seconds later(i.e. routing)?[/li][/ul]

clippermiami · October 10, 2014, 1:39pm

[quote=“Z-Waver, post:3, topic:183467”]Did you make PLEG changes just prior to this problem’s manifestation?

Try SSHing in and running top to see which process if using the most CPU. The Vera process is /usr/bin/LuaUPnP

Are you logging to USB? Is the USB device mounted? Is the USB device failing and causing a lot of write retry attempts?

Look at your logs and determine where/when the delay occurs.

[ul][list][li]Does it take 30 seconds for Vera to see the trigger and then Vera responds immediately?[/li]
[li]Does Vera receive the trigger immediately, but take 30 seconds to respond?[/li]
[li]Does Vera receive the trigger and issue a response immediately, but then has to retry the command 30 seconds later(i.e. routing)?[/li]
[/list][/quote]

good suggestions, i’ll get working on it.

It is logging to USB and it appears to be fine, no reported error problems

as to the sensor response time if the UI is any indication Vera doesn’t recoginize the sensor right away. ita takes a good 2-30 seconds before the sensor changes state in the UI but that could be other things, PC problems, UI display times, etc. I will say that in the past if if I opened the UI and watched a sensor when I moved it responded almost instantaneously … now it doesn’t.

I have backups obviously — yesterday for example — but I’m not sure if the backup captures only active processes or everything, including any junk left behind from deleted items too. If I were to wipe the VERA back to factory and restore would I get a clean, active process restore or would I get all the leftover junk as well?[/ul]

clippermiami · October 10, 2014, 1:52pm

[tt]root@MiOS_30010119:~# top Mem: 75728K used, 51728K free, 0K shrd, 3920K buff, 29428K cached CPU: 27% usr 27% sys 0% nic 45% idle 0% io 0% irq 0% sirq Load average: 0.56 0.73 0.68 1/126 26079 PID PPID USER STAT VSZ %MEM %CPU COMMAND 26317 2081 root S 175m 141% 36% /usr/bin/LuaUPnP 26079 25902 root R 1676 1% 9% top 1990 1 root S 748 1% 9% /usr/bin/luci-bwc -d 2269 2183 root S 7484 6% 0% /usr/bin/NetworkMonitor 2258 1 root S 3860 3% 0% lighttpd -f /etc/lighttpd.conf 546 1 root S 1928 2% 0% syslogd -C256 3676 1 root S 1792 1% 0% /bin/ash /usr/bin/cmh-ra-daemon.sh 1909 1 root S 1696 1% 0% crond -c /etc/crontabs -l 5 2081 1 root S 1688 1% 0% /bin/ash /usr/bin/Start_LuaUPnP.sh 1 0 root S 1684 1% 0% init 25902 25791 root S 1684 1% 0% -ash 514 1 root S 1684 1% 0% init 2183 1 root S 1680 1% 0% /bin/ash /usr/bin/Start_NetworkMonito 2021 1 root S 1680 1% 0% watchdog -t 5 /dev/watchdog 25664 25546 root S 1676 1% 0% -ash 2104 2081 root S 1676 1% 0% /bin/ash /usr/bin/Start_serproxy.sh 548 1 root S 1672 1% 0% klogd 25609 3676 root S 1668 1% 0% sleep 60 3697 3676 root S 1216 1% 0% ssh -p 232 -T -y -i /etc/cmh-ra/keys/ 25791 1933 root S 1200 1% 0% /usr/sbin/dropbear -P /var/run/dropbe Mem: 75828K used, 51628K free, 0K shrd, 3920K buff, 29440K cached CPU: 51% usr 8% sys 0% nic 39% idle 0% io 0% irq 0% sirq Load average: 0.59 0.73 0.68 2/127 26170 PID PPID USER STAT VSZ %MEM %CPU COMMAND 26317 2081 root S 175m 141% 47% /usr/bin/LuaUPnP 1990 1 root S 748 1% 1% /usr/bin/luci-bwc -d 2269 2183 root S 7484 6% 1% /usr/bin/NetworkMonitor 26079 25902 root R 1680 1% 0% top 2258 1 root S 3860 3% 0% lighttpd -f /etc/lighttpd.conf 546 1 root S 1928 2% 0% syslogd -C256 3676 1 root S 1792 1% 0% /bin/ash /usr/bin/cmh-ra-daemon.sh 1909 1 root S 1696 1% 0% crond -c /etc/crontabs -l 5 2081 1 root S 1688 1% 0% /bin/ash /usr/bin/Start_LuaUPnP.sh 1 0 root S 1684 1% 0% init 25902 25791 root S 1684 1% 0% -ash 514 1 root S 1684 1% 0% init 2183 1 root S 1680 1% 0% /bin/ash /usr/bin/Start_NetworkMonito 2021 1 root S 1680 1% 0% watchdog -t 5 /dev/watchdog 25664 25546 root S 1676 1% 0% -ash 2104 2081 root S 1676 1% 0% /bin/ash /usr/bin/Start_serproxy.sh 548 1 root S 1672 1% 0% klogd 25609 3676 root S 1668 1% 0% sleep 60 3697 3676 root S 1216 1% 0% ssh -p 232 -T -y -i /etc/cmh-ra/keys/ 25791 1933 root S 1200 1% 0% /usr/sbin/dropbear -P /var/run/dropbe Mem: 75820K used, 51636K free, 0K shrd, 3920K buff, 29448K cached CPU: 39% usr 5% sys 0% nic 54% idle 0% io 0% irq 0% sirq Load average: 0.55 0.72 0.68 1/126 26224 PID PPID USER STAT VSZ %MEM %CPU COMMAND 26317 2081 root S 175m 141% 35% /usr/bin/LuaUPnP 2269 2183 root S 7484 6% 1% /usr/bin/NetworkMonitor 1990 1 root S 748 1% 1% /usr/bin/luci-bwc -d 2258 1 root S 3860 3% 0% lighttpd -f /etc/lighttpd.conf 26079 25902 root R 1680 1% 0% top 546 1 root S 1928 2% 0% syslogd -C256 3676 1 root S 1792 1% 0% /bin/ash /usr/bin/cmh-ra-daemon.sh 1909 1 root S 1696 1% 0% crond -c /etc/crontabs -l 5 2081 1 root S 1688 1% 0% /bin/ash /usr/bin/Start_LuaUPnP.sh 1 0 root S 1684 1% 0% init 25902 25791 root S 1684 1% 0% -ash 514 1 root S 1684 1% 0% init 2183 1 root S 1680 1% 0% /bin/ash /usr/bin/Start_NetworkMonito 2021 1 root S 1680 1% 0% watchdog -t 5 /dev/watchdog 25664 25546 root S 1676 1% 0% -ash 2104 2081 root S 1676 1% 0% /bin/ash /usr/bin/Start_serproxy.sh 548 1 root S 1672 1% 0% klogd 25609 3676 root S 1668 1% 0% sleep 60 3697 3676 root S 1216 1% 0% ssh -p 232 -T -y -i /etc/cmh-ra/keys/ 25791 1933 root S 1200 1% 0% /usr/sbin/dropbear -P /var/run/dropbe Mem: 75848K used, 51608K free, 0K shrd, 3920K buff, 29460K cached CPU: 50% usr 7% sys 0% nic 40% idle 1% io 0% irq 0% sirq Load average: 0.74 0.76 0.69 2/126 26285 PID PPID USER STAT VSZ %MEM %CPU COMMAND 26317 2081 root S 175m 141% 48% /usr/bin/LuaUPnP 1990 1 root S 748 1% 1% /usr/bin/luci-bwc -d 2269 2183 root S 7484 6% 1% /usr/bin/NetworkMonitor 2258 1 root S 3860 3% 0% lighttpd -f /etc/lighttpd.conf 26079 25902 root R 1680 1% 0% top 546 1 root S 1928 2% 0% syslogd -C256 3676 1 root S 1792 1% 0% /bin/ash /usr/bin/cmh-ra-daemon.sh 1909 1 root S 1696 1% 0% crond -c /etc/crontabs -l 5 2081 1 root S 1688 1% 0% /bin/ash /usr/bin/Start_LuaUPnP.sh 1 0 root S 1684 1% 0% init 25902 25791 root S 1684 1% 0% -ash 514 1 root S 1684 1% 0% init 2183 1 root S 1680 1% 0% /bin/ash /usr/bin/Start_NetworkMonito 2021 1 root S 1680 1% 0% watchdog -t 5 /dev/watchdog 25664 25546 root S 1676 1% 0% -ash 2104 2081 root S 1676 1% 0% /bin/ash /usr/bin/Start_serproxy.sh 548 1 root S 1672 1% 0% klogd 25609 3676 root S 1668 1% 0% sleep 60 3697 3676 root S 1216 1% 0% ssh -p 232 -T -y -i /etc/cmh-ra/keys/ 25791 1933 root S 1200 1% 0% /usr/sbin/dropbear -P /var/run/dropbe Mem: 75848K used, 51608K free, 0K shrd, 3920K buff, 29468K cached CPU: 39% usr 6% sys 0% nic 53% idle 1% io 0% irq 0% sirq Load average: 0.68 0.75 0.69 1/126 26347 PID PPID USER STAT VSZ %MEM %CPU COMMAND 26317 2081 root S 175m 141% 35% /usr/bin/LuaUPnP 2269 2183 root S 7484 6% 1% /usr/bin/NetworkMonitor 2258 1 root S 3860 3% 1% lighttpd -f /etc/lighttpd.conf 1990 1 root S 748 1% 1% /usr/bin/luci-bwc -d 26079 25902 root R 1680 1% 0% top 546 1 root S 1928 2% 0% syslogd -C256 3676 1 root S 1792 1% 0% /bin/ash /usr/bin/cmh-ra-daemon.sh 1909 1 root S 1696 1% 0% crond -c /etc/crontabs -l 5 2081 1 root S 1688 1% 0% /bin/ash /usr/bin/Start_LuaUPnP.sh 1 0 root S 1684 1% 0% init 25902 25791 root S 1684 1% 0% -ash 514 1 root S 1684 1% 0% init 2183 1 root S 1680 1% 0% /bin/ash /usr/bin/Start_NetworkMonito 2021 1 root S 1680 1% 0% watchdog -t 5 /dev/watchdog 25664 25546 root S 1676 1% 0% -ash 2104 2081 root S 1676 1% 0% /bin/ash /usr/bin/Start_serproxy.sh 548 1 root S 1672 1% 0% klogd 26287 3676 root S 1668 1% 0% sleep 60 3697 3676 root S 1216 1% 0% ssh -p 232 -T -y -i /etc/cmh-ra/keys/ 25791 1933 root S 1200 1% 0% /usr/sbin/dropbear -P /var/run/dropbe Mem: 75848K used, 51608K free, 0K shrd, 3920K buff, 29472K cached CPU: 10% usr 5% sys 0% nic 82% idle 1% io 0% irq 0% sirq Load average: 0.63 0.74 0.68 1/126 26401 PID PPID USER STAT VSZ %MEM %CPU COMMAND 26317 2081 root S 175m 141% 6% /usr/bin/LuaUPnP 1990 1 root S 748 1% 1% /usr/bin/luci-bwc -d 2269 2183 root S 7484 6% 1% /usr/bin/NetworkMonitor 2258 1 root S 3860 3% 0% lighttpd -f /etc/lighttpd.conf 26079 25902 root R 1680 1% 0% top 546 1 root S 1928 2% 0% syslogd -C256 3676 1 root S 1792 1% 0% /bin/ash /usr/bin/cmh-ra-daemon.sh 1909 1 root S 1696 1% 0% crond -c /etc/crontabs -l 5 2081 1 root S 1688 1% 0% /bin/ash /usr/bin/Start_LuaUPnP.sh 1 0 root S 1684 1% 0% init 25902 25791 root S 1684 1% 0% -ash 514 1 root S 1684 1% 0% init 2183 1 root S 1680 1% 0% /bin/ash /usr/bin/Start_NetworkMonito 2021 1 root S 1680 1% 0% watchdog -t 5 /dev/watchdog 25664 25546 root S 1676 1% 0% -ash 2104 2081 root S 1676 1% 0% /bin/ash /usr/bin/Start_serproxy.sh 548 1 root S 1672 1% 0% klogd 26287 3676 root S 1668 1% 0% sleep 60 3697 3676 root S 1216 1% 0% ssh -p 232 -T -y -i /etc/cmh-ra/keys/ 25791 1933 root S 1200 1% 0% /usr/sbin/dropbear -P /var/run/dropbe Mem: 75876K used, 51580K free, 0K shrd, 3920K buff, 29480K cached CPU: 10% usr 6% sys 0% nic 83% idle 0% io 0% irq 0% sirq Load average: 0.58 0.72 0.68 2/126 26519 PID PPID USER STAT VSZ %MEM %CPU COMMAND 26317 2081 root S 175m 141% 6% /usr/bin/LuaUPnP 1990 1 root S 748 1% 1% /usr/bin/luci-bwc -d 2269 2183 root S 7484 6% 1% /usr/bin/NetworkMonitor 2258 1 root S 3860 3% 0% lighttpd -f /etc/lighttpd.conf 546 1 root S 1928 2% 0% syslogd -C256 3676 1 root S 1792 1% 0% /bin/ash /usr/bin/cmh-ra-daemon.sh 1909 1 root S 1696 1% 0% crond -c /etc/crontabs -l 5 2081 1 root S 1688 1% 0% /bin/ash /usr/bin/Start_LuaUPnP.sh 1 0 root S 1684 1% 0% init 25902 25791 root S 1684 1% 0% -ash 514 1 root S 1684 1% 0% init 26079 25902 root R 1680 1% 0% top 2183 1 root S 1680 1% 0% /bin/ash /usr/bin/Start_NetworkMonito 2021 1 root S 1680 1% 0% watchdog -t 5 /dev/watchdog 25664 25546 root S 1676 1% 0% -ash 2104 2081 root S 1676 1% 0% /bin/ash /usr/bin/Start_serproxy.sh 548 1 root S 1672 1% 0% klogd 26287 3676 root S 1668 1% 0% sleep 60 3697 3676 root S 1216 1% 0% ssh -p 232 -T -y -i /etc/cmh-ra/keys/ 25791 1933 root S 1200 1% 0% /usr/sbin/dropbear -P /var/run/dropbe Mem: 75940K used, 51516K free, 0K shrd, 3920K buff, 29488K cached CPU: 5% usr 2% sys 0% nic 90% idle 1% io 0% irq 0% sirq Load average: 0.53 0.71 0.68 5/127 26536 PID PPID USER STAT VSZ %MEM %CPU COMMAND 26317 2081 root S 175m 141% 4% /usr/bin/LuaUPnP 1990 1 root S 748 1% 1% /usr/bin/luci-bwc -d 2269 2183 root S 7484 6% 0% /usr/bin/NetworkMonitor 26079 25902 root R 1680 1% 0% top 2258 1 root S 3860 3% 0% lighttpd -f /etc/lighttpd.conf 546 1 root S 1928 2% 0% syslogd -C256 3676 1 root S 1792 1% 0% /bin/ash /usr/bin/cmh-ra-daemon.sh 1909 1 root S 1696 1% 0% crond -c /etc/crontabs -l 5 2081 1 root S 1688 1% 0% /bin/ash /usr/bin/Start_LuaUPnP.sh 1 0 root S 1684 1% 0% init 514 1 root S 1684 1% 0% init 25902 25791 root S 1684 1% 0% -ash 2183 1 root S 1680 1% 0% /bin/ash /usr/bin/Start_NetworkMonito 2021 1 root S 1680 1% 0% watchdog -t 5 /dev/watchdog 26534 2269 root R 1680 1% 0% /bin/ash /usr/bin/GetNetworkState.sh 26536 26534 root R 1680 1% 0% [GetNetworkState] 25664 25546 root S 1676 1% 0% -ash 2104 2081 root S 1676 1% 0% /bin/ash /usr/bin/Start_serproxy.sh 548 1 root S 1672 1% 0% klogd 26287 3676 root S 1668 1% 0% sleep 60 Mem: 75868K used, 51588K free, 0K shrd, 3920K buff, 29492K cached CPU: 8% usr 5% sys 0% nic 86% idle 0% io 0% irq 0% sirq Load average: 0.49 0.70 0.67 1/125 26574 PID PPID USER STAT VSZ %MEM %CPU COMMAND 26317 2081 root S 175m 141% 5% /usr/bin/LuaUPnP 1990 1 root S 748 1% 1% /usr/bin/luci-bwc -d 2269 2183 root S 7484 6% 1% /usr/bin/NetworkMonitor 26079 25902 root R 1680 1% 0% top 2258 1 root S 3860 3% 0% lighttpd -f /etc/lighttpd.conf 3 2 root SW 0 0% 0% [ksoftirqd/0] 546 1 root S 1928 2% 0% syslogd -C256 3676 1 root S 1792 1% 0% /bin/ash /usr/bin/cmh-ra-daemon.sh 1909 1 root S 1696 1% 0% crond -c /etc/crontabs -l 5 2081 1 root S 1688 1% 0% /bin/ash /usr/bin/Start_LuaUPnP.sh 1 0 root S 1684 1% 0% init 514 1 root S 1684 1% 0% init 25902 25791 root S 1684 1% 0% -ash 2183 1 root S 1680 1% 0% /bin/ash /usr/bin/Start_NetworkMonito 2021 1 root S 1680 1% 0% watchdog -t 5 /dev/watchdog 25664 25546 root S 1676 1% 0% -ash 2104 2081 root S 1676 1% 0% /bin/ash /usr/bin/Start_serproxy.sh 548 1 root S 1672 1% 0% klogd 26287 3676 root S 1668 1% 0% sleep 60 3697 3676 root S 1216 1% 0% ssh -p 232 -T -y -i /etc/cmh-ra/keys/ [/tt]

Z-Waver · October 10, 2014, 1:58pm

I don’t think you can rely on the GUI for this. You need to look at the logs and compare time stamps. If it is taking 30 seconds to turn on the light, you should be able to see where the 30 seconds is between when the trigger is received and the light On OK confirmation. If there is no logged delay between trigger and OK confirmation, then you can assume that the trigger(motion sensor event) is taking the 30 seconds to reach Vera. IN that case, the issue might be motion sensor routing or hardware issue.

Restores should restore “junk” too. Backups should backup whatever is there, even if it is an orphaned file. Restores should restore whatever is backed up.

Your top output shows the Vera process as being a little high, but nothing too terrible for a Vera with lots of devices and several plugins.

clippermiami · October 10, 2014, 3:20pm

In looking at the logs I’ve found this so far. Most of what i see are countdown timer messages. I’m still working on isolating a motion sensor and the response but I don’t know what to make of the error in here highlighted in RED

06 10/10/14 11:16:02.103 Device_Variable::m_szValue_set device: 77 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 1004 now: 1003 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2c2fb680>
06 10/10/14 11:16:02.104 Device_Variable::m_szValue_set device: 290 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2563 now: 2562 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2f8fb680>
06 10/10/14 11:16:03.101 Device_Variable::m_szValue_set device: 77 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 1003 now: 1002 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2c2fb680>
06 10/10/14 11:16:03.101 Device_Variable::m_szValue_set device: 132 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2561 now: 2560 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2d4fb680>
06 10/10/14 11:16:03.102 Device_Variable::m_szValue_set device: 290 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2562 now: 2561 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2f8fb680>
06 10/10/14 11:16:03.103 Device_Variable::m_szValue_set device: 129 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2508 now: 2507 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2d0fb680>
01 10/10/14 11:16:03.757 JobHandler_LuaUPnP::REQ_SlaveDataChanged unknown uuid:4d494342-5342-5645-0000-000001c9e69b <0x3353c680>
06 10/10/14 11:16:04.101 Device_Variable::m_szValue_set device: 77 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 1002 now: 1001 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2c2fb680>
06 10/10/14 11:16:04.101 Device_Variable::m_szValue_set device: 290 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2561 now: 2560 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2f8fb680>
06 10/10/14 11:16:04.102 Device_Variable::m_szValue_set device: 129 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2507 now: 2506 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2d0fb680>
06 10/10/14 11:16:04.103 Device_Variable::m_szValue_set device: 132 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2560 now: 2559 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2d4fb680>
06 10/10/14 11:16:05.112 Device_Variable::m_szValue_set device: 132 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2559 now: 2558 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2d4fb680>
06 10/10/14 11:16:05.113 Device_Variable::m_szValue_set device: 129 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2506 now: 2505 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2d0fb680>
06 10/10/14 11:16:05.114 Device_Variable::m_szValue_set device: 290 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2560 now: 2559 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2f8fb680>
06 10/10/14 11:16:05.101 Device_Variable::m_szValue_set device: 77 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 1001 now: 1000 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2c2fb680>
06 10/10/14 11:16:06.101 Device_Variable::m_szValue_set device: 290 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2559 now: 2558 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2f8fb680>
06 10/10/14 11:16:06.102 Device_Variable::m_szValue_set device: 129 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2505 now: 2504 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2d0fb680>
06 10/10/14 11:16:06.103 Device_Variable::m_szValue_set device: 132 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2558 now: 2557 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2d4fb680>
06 10/10/14 11:16:06.103 Device_Variable::m_szValue_set device: 77 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 1000 now: 999 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2c2fb680>
02 10/10/14 11:16:06.106 ZW_Send_Data node 3 USING ROUTE 255.68.101.115 <0x2bcfb680>
04 10/10/14 11:16:06.243 <0x2b8fb680>
06 10/10/14 11:16:07.101 Device_Variable::m_szValue_set device: 129 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2504 now: 2503 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2d0fb680>
06 10/10/14 11:16:07.101 Device_Variable::m_szValue_set device: 132 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2557 now: 2556 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2d4fb680>
06 10/10/14 11:16:07.102 Device_Variable::m_szValue_set device: 77 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 999 now: 998 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2c2fb680>
06 10/10/14 11:16:07.103 Device_Variable::m_szValue_set device: 290 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2558 now: 2557 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2f8fb680>
06 10/10/14 11:16:08.101 Device_Variable::m_szValue_set device: 129 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2503 now: 2502 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2d0fb680>
06 10/10/14 11:16:08.101 Device_Variable::m_szValue_set device: 290 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2557 now: 2556 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2f8fb680>
06 10/10/14 11:16:08.102 Device_Variable::m_szValue_set device: 77 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 998 now: 997 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2c2fb680>
06 10/10/14 11:16:08.103 Device_Variable::m_szValue_set device: 132 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2556 now: 2555 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2d4fb680>
06 10/10/14 11:16:09.101 Device_Variable::m_szValue_set device: 129 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2502 now: 2501 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2d0fb680>
06 10/10/14 11:16:09.102 Device_Variable::m_szValue_set device: 132 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 2555 now: 2554 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2d4fb680>
06 10/10/14 11:16:09.103 Device_Variable::m_szValue_set device: 77 service: urn:futzle-com:serviceId:CountdownTimer1 variable: Remaining was: 997 now: 996 #hooks: 0 upnp: 0 v:0x10cd2f8/NONE duplicate:0 <0x2c2fb680>

clippermiami · October 10, 2014, 3:52pm

A snippet of the Lua log covering the period during which the Kitchen Lights were OFF, the motion sensor was triggered and the lights came ON.

Its difficult to follow because it falls into a general purpose PLEG that handles a whole bunch of functions, not just the kitchen lights, suffice to say that it took quite a long while before the motion was registered in the GUI and the lights actually came on. That and i’m not sure what I’m looking for )

Motion Sensor is Device # 171, Node 36
Light Switch is Device # 38, Node 6
Kitchen Countdown Timer is Device #129

clippermiami · October 10, 2014, 6:19pm

More frustration, I ran a Heal Test and Vera restarted in the middle of it so it never completed properly

Z-Waver · October 10, 2014, 6:23pm

Below are the relevant entries:

[code]06 10/10/14 11:45:12.573 Device_Variable::m_szValue_set device: 171 service: urn:micasaverde-com:serviceId:SecuritySensor1 variable: Tripped was: 0 now: 1 #hooks: 2 upnp: 0 v:0x10f5640/NONE duplicate:0 <0x2b8fb680>
06 10/10/14 11:45:12.613 Device_Variable::m_szValue_set device: 414 service: urn:rts-services-com:serviceId:ProgramLogicEG variable: ConditionSatisfied was: None now: Kitchen_Motion_Lights_OFF #hooks: 3 upnp: 0 v:0x1116408/NONE duplicate:0 <0x2b8fb680>

08 10/10/14 11:45:12.842 JobHandler_LuaUPnP::HandleActionRequest device: 38 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2b1c7000>
08 10/10/14 11:45:12.842 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x2b1c7000>
06 10/10/14 11:45:12.842 Device_Variable::m_szValue_set device: 38 service: urn:upnp-org:serviceId:SwitchPower1 variable: Target was: 0 now: 1 #hooks: 0 upnp: 0 v:0x10b7808/NONE duplicate:0 <0x2b1c7000>
02 10/10/14 11:45:12.844 ZWJob_SendData UPDATE MANUAL ROUTE 6=0x1ddcdef <0x2b1c7000>
02 10/10/14 11:45:12.845 UPDATE MANUAL ROUTE2 6=0x1ddcdef <0x2bcfb680>
02 10/10/14 11:45:12.846 ZW_Send_Data node 6 USING ROUTE 255.101.100.27 <0x2bcfb680>[/code]

There should then be a status message(missing), such as this:

Device_Variable::m_szValue_set device: 38 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 0 now: 1

That indicates a successful completion of the switch on command.

Based on what information is present, Vera processes the trigger and issues the (first) command to turn on the light without any real delay(273ms).

So, either the trigger is taking too long to get form the sensor to Vera or there are additional command retries that your snippet does not include.

I’d try a restore(no need to reset) from a known good backup. If that doesn’t work, consider contacting support.

clippermiami · October 10, 2014, 7:58pm

Thanks. I have restored from a backup of 10/08 and I’m now running a Heal so I’ll see how that goes.

About two weeks ago I added a AEON Range Extender which went fine and as I said earlier everything seemed fine until late yesterday. On the off change I decided to remove the Range Extender and used the “Exclude/Full Power”. When I activated the Include/Exclude button on the Aeon Vera reported one device being removed. To my great surprise after the restart the Aeon was still there but a two year old GE/Jasco Wall Switch in the Garage was gone!!

I used the web removal trick on the Aeon and it disappeared. So I tried adding the switch back and its been all down hill since. It APPEARED to add OK but when I defined a Device Property in the PLEG “Garage_Lights” it APPEARED to work but a restart resulted in a PLEG startup error for an Invalid Token “Garage_Lights”. At that point decided to go back to the 10/08 backup.

The 10/8 backup also brought back the Bridged Vera mode that I had removed in desperation yesterday.

My system is well and truly messed up So I’ll see how the Heal does and if all else fails I’ll try Tech Support.

clippermiami · October 11, 2014, 3:26pm

Good News

It APPEARS that everything is back to normal. I ended up going back to a backup from September 29 to get some semblance of control.

I noticed something very interesting in the process of all this. About two weeks ago I added a Aeon Range Extender to try to deal with a “soft spot” at one end of the house. In the course of trying to solve this problem I decided to remove it from the system just in case it might have been contributing to the problem. Using Full Power exclusion I removed the device and after Vera restarted the AEON was still present BUT A GE/JASCH IN THE GARAGE WAS GONE!

Fixing that problem took the better part of last night for some reason. I re-added it and after the restart it was gone again replaced some sort of “Generic I/O” device … This cycle repeated for a least a dozen attempts which is why I finally ended with the September backup before I finally got control again

All in all a very frustrating experience but it did prove I have more patience and persistence than thought I had

Anyway many thanks to Z-Waver for your patience and assistance

clippermiami · November 25, 2014, 7:31pm

The performance problem continues and i’m at wits end with it. I opened a ticket with Tech support which went unanswered for 5 days and then there was an apparent flurry of activity and now they have gone away again … supposedly having enabled detailed logging and collecting data I have not heard anything for four days.

Using EventWatcher I’m seeing normal CPU usage in the 40-50% range with periodic spikes to 200% and higher during the day. My device response time is occasionally very good (like it was even up to early October of this year.) Now I occasionally get response instantaneous response after a sensor activation. If multiple devices are fired from the same sensor the first device response can range from milliseconds to 9-10 seconds with subsequent devices sometimes taking 45+seconds to activate.

I’m searching the logs as best i can without knowing just what i’m looking for. I was trolling the logs today around the time of one of the very high CPU periods and found this:

Extracted from /var/log/cmh/LuAuPnP.log(.gz)

10	11/25/14 9:47:36.735	XXX-UpdateSystemMessagesTasks StartupTask #0 = 4 OK / ZWave <0x2b8e1680>
10	11/25/14 9:47:36.735	XXX-UpdateSystemMessagesTasks StartupTask #1 = 4 OK / Study Timer (30 Min)[77] <0x2b8e1680>
10	11/25/14 9:47:36.736	XXX-UpdateSystemMessagesTasks StartupTask #2 = 4 OK / Garage Light Timer (15 Min)[88] <0x2b8e1680>
10	11/25/14 9:47:36.736	XXX-UpdateSystemMessagesTasks StartupTask #3 = 4 OK / Master Bedroom Timer (20 Min)[89] <0x2b8e1680>
10	11/25/14 9:47:36.736	XXX-UpdateSystemMessagesTasks StartupTask #4 = 4 OK / VeraAlerts[91] <0x2b8e1680>
10	11/25/14 9:47:36.737	XXX-UpdateSystemMessagesTasks StartupTask #5 = 4 OK / Master Dressing Timer (20 Min)[93] <0x2b8e1680>
10	11/25/14 9:47:36.737	XXX-UpdateSystemMessagesTasks StartupTask #6 = 4 OK / Master Closet Time (15 Min)[105] <0x2b8e1680>
10	11/25/14 9:47:36.737	XXX-UpdateSystemMessagesTasks StartupTask #7 = 4 OK / Guest Bath Timer (10 Min)[112] <0x2b8e1680>
10	11/25/14 9:47:36.738	XXX-UpdateSystemMessagesTasks StartupTask #8 = 4 OK / Kitchen Timer (45 Min)[129] <0x2b8e1680>
10	11/25/14 9:47:36.738	XXX-UpdateSystemMessagesTasks StartupTask #9 = 4 OK / Front Door ReLock Timer (5 Min)[131] <0x2b8e1680>
10	11/25/14 9:47:36.738	XXX-UpdateSystemMessagesTasks StartupTask #10 = 4 OK / Family Room Light Timer (45 Min)[132] <0x2b8e1680>
10	11/25/14 9:47:36.739	XXX-UpdateSystemMessagesTasks StartupTask #11 = 4 OK / Master Bath Timer (5 Min)[133] <0x2b8e1680>
10	11/25/14 9:47:36.739	XXX-UpdateSystemMessagesTasks StartupTask #12 = 4 OK / Hallway Timer (5 Min)[134] <0x2b8e1680>
10	11/25/14 9:47:36.739	XXX-UpdateSystemMessagesTasks StartupTask #13 = 4 OK / Front Entry Light Timer (5 Min)[138] <0x2b8e1680>
10	11/25/14 9:47:36.740	XXX-UpdateSystemMessagesTasks StartupTask #14 = 4 OK / MiOS Update Utility[139] <0x2b8e1680>
10	11/25/14 9:47:36.740	XXX-UpdateSystemMessagesTasks StartupTask #15 = 4 OK / . PLEG Family Room[173] <0x2b8e1680>
10	11/25/14 9:47:36.740	XXX-UpdateSystemMessagesTasks StartupTask #16 = 4 OK / . PLEG Garage[175] <0x2b8e1680>
10	11/25/14 9:47:36.741	XXX-UpdateSystemMessagesTasks StartupTask #17 = 4 OK / . PLEG Study[176] <0x2b8e1680>
10	11/25/14 9:47:36.741	XXX-UpdateSystemMessagesTasks StartupTask #18 = 4 OK / . PLEG Front Entry[179] <0x2b8e1680>
10	11/25/14 9:47:36.741	XXX-UpdateSystemMessagesTasks StartupTask #19 = 4 OK / . PLEG Master Bedroom Suite[185] <0x2b8e1680>
10	11/25/14 9:47:36.742	XXX-UpdateSystemMessagesTasks StartupTask #20 = 4 OK / . PLEG Master Bedroom Variables[213] <0x2b8e1680>
10	11/25/14 9:47:36.742	XXX-UpdateSystemMessagesTasks StartupTask #21 = 4 OK / Study Closet Timer (10 Min)[272] <0x2b8e1680>
10	11/25/14 9:47:36.742	XXX-UpdateSystemMessagesTasks StartupTask #22 = 4 OK / . PLEG Family Room Variables[281] <0x2b8e1680>
10	11/25/14 9:47:36.743	XXX-UpdateSystemMessagesTasks StartupTask #23 = 4 OK / Family Room Fan Timer (45 Min)[290] <0x2b8e1680>
10	11/25/14 9:47:36.743	XXX-UpdateSystemMessagesTasks StartupTask #24 = 4 OK / Ping Sensor - Vera 2 [329] <0x2b8e1680>
10	11/25/14 9:47:36.743	XXX-UpdateSystemMessagesTasks StartupTask #25 = 4 OK / MailBox Flag[334] <0x2b8e1680>
10	11/25/14 9:47:36.743	XXX-UpdateSystemMessagesTasks StartupTask #26 = 4 OK / Day or Night[412] <0x2b8e1680>
10	11/25/14 9:47:36.744	XXX-UpdateSystemMessagesTasks StartupTask #27 = 4 OK / . PLEG Common[414] <0x2b8e1680>
10	11/25/14 9:47:36.744	XXX-UpdateSystemMessagesTasks StartupTask #28 = 4 OK / . Status Master Bedroom[438] <0x2b8e1680>
10	11/25/14 9:47:36.744	XXX-UpdateSystemMessagesTasks StartupTask #29 = 4 OK / . Status Family Room[439] <0x2b8e1680>
10	11/25/14 9:47:36.745	XXX-UpdateSystemMessagesTasks StartupTask #30 = 4 OK / Event Watcher[440] <0x2b8e1680>
10	11/25/14 9:47:36.745	XXX-UpdateSystemMessagesTasks StartupTask #31 = 4 OK / Master Bedroom Fan Timer (30 Min)[484] <0x2b8e1680>
10	11/25/14 9:47:36.745	XXX-UpdateSystemMessagesTasks StartupTask #32 = 4 OK / Travel_Active[543] <0x2b8e1680>
10	11/25/14 9:47:36.746	XXX-UpdateSystemMessagesTasks StartupTask #33 = 4 OK / AutoVera[614] <0x2b8e1680>
10	11/25/14 9:47:36.746	XXX-UpdateSystemMessagesTasks StartupTask #34 = 4 OK / . Temporary MBR Override[623] <0x2b8e1680>
10	11/25/14 9:47:36.746	XXX-UpdateSystemMessagesTasks StartupTask #35 = 4 OK / Power Fail Flag[625] <0x2b8e1680>
10	11/25/14 9:47:36.746	XXX-UpdateSystemMessagesTasks StartupTask #36 = 4 OK / Last Known State[629] <0x2b8e1680>
10	11/25/14 9:47:36.747	XXX-UpdateSystemMessagesTasks StartupTask #37 = 4 OK / GCal3 Sensor[630] <0x2b8e1680>
10	11/25/14 9:47:36.747	XXX-UpdateSystemMessagesTasks StartupTask #38 = 4 OK / Testing[631] <0x2b8e1680>
10	11/25/14 9:47:36.747	XXX-UpdateSystemMessagesTasks StartupTask #39 = 4 OK / ImperiHome: Living Room[634] <0x2b8e1680>
10	11/25/14 9:47:36.748	XXX-UpdateSystemMessagesTasks StartupTask #40 = 4 OK / ImperiHome:Master Bedroom[636] <0x2b8e1680>
10	11/25/14 9:47:36.748	XXX-UpdateSystemMessagesTasks StartupTask #41 = 4 OK / ImperiHome: Kitchen[637] <0x2b8e1680>
10	11/25/14 9:47:36.748	XXX-UpdateSystemMessagesTasks StartupTask #42 = 4 OK / All OK <0x2b8e1680>
10	11/25/14 9:47:36.749	XXX-UpdateSystemMessagesTasks StartupTask #43 = 4 OK / . PLEG Kitchen[642] <0x2b8e1680>
10	11/25/14 9:47:36.749	XXX-UpdateSystemMessagesTasks StartupTask #44 = 4 OK / . PLEG Outside[643] <0x2b8e1680>
10	11/25/14 9:47:36.749	XXX-UpdateSystemMessagesTasks StartupTask #45 = 4 OK / . PLEG Guest Bath & Hallway[644] <0x2b8e1680>
10	11/25/14 9:47:36.750	XXX-UpdateSystemMessagesTasks StartupTask #46 = 4 OK / . PLEG Living Room[645] <0x2b8e1680>
10	11/25/14 9:47:36.750	XXX-UpdateSystemMessagesTasks now 4=Heal Stage: Heal successful timeout 1416927114 (258) count: 47pend:(null)/err:(null)/done:Heal successful

This particular sequence is repeated again at 11/25/14 9:47:36.789, 11/25/14 9:47:36.830 and roughly EVERY 50 milliseconds interminably. Is this normal? I would think that a StartupTask would not repeat time and time again for hours at a time. During this period I was running a Heal on a specific device but I don’t see it as related to that activity, the CPU usage and poor performance are all day every day.

Between these constant StartUPTask messages it manages to squeeqe in a few other activities:

10	11/25/14 9:47:36.749	XXX-UpdateSystemMessagesTasks StartupTask #45 = 4 OK / . PLEG Guest Bath & Hallway[644] <0x2b8e1680>
10	11/25/14 9:47:36.750	XXX-UpdateSystemMessagesTasks StartupTask #46 = 4 OK / . PLEG Living Room[645] <0x2b8e1680>
10	11/25/14 9:47:36.750	XXX-UpdateSystemMessagesTasks now 4=Heal Stage: Heal successful timeout 1416927114 (258) count: 47pend:(null)/err:(null)/done:Heal successful <0x2b8e1680>
10	11/25/14 9:47:36.751	AlarmManager::AddRelativeAlarm current time 1416926856 delay 3 type 21 <0x2b8e1680>
31	11/25/14 9:47:36.751	AlarmManager::CancelAlarmByType_DoIt 0x9f12c8 type 21/21 id 36160 entry 0x1c99b00 deleted 0 waiting 1 <0x2b8e1680>
10	11/25/14 9:47:36.751	AlarmManager::AddAbsoluteAlarm alarm 0x9f12c8 entry 0x1d4d988 id 36162 type 21 param=(nil) entry->when: 1416926859 time: 1416926856 bCancelFirst 1=1 <0x2b8e1680>
31	11/25/14 9:47:36.752	AlarmManager::Run 0x9f12c8 notified of a change entry 0x1c99b00 id 36160 deleted 1 <0x2bae1680>
10	11/25/14 9:47:36.752	UserData::m_iDataVersion_Variables_incr short sys message user data 921544004 variables 921570840 <0x2b8e1680>
10	11/25/14 9:47:36.752	AlarmManager::AddRelativeAlarm current time 1416926856 delay 0 type 24 <0x2b8e1680>
10	11/25/14 9:47:36.753	AlarmManager::AddAbsoluteAlarm alarm 0x9f12c8 entry 0x1b1a3c8 id 36163 type 24 param=(nil) entry->when: 1416926856 time: 1416926856 bCancelFirst 0=0 <0x2b8e1680>
31	11/25/14 9:47:36.753	AlarmManager::Run 0x9f12c8 notified of a change entry 0x1d4d988 id 36162 deleted 0 <0x2bae1680>
31	11/25/14 9:47:36.754	AlarmManager::Run finish callback for alarm 0x9f12c8 entry 0x1adf5c8 type 24 id 36161 param=(nil) entry->when: 1416926856 time: 1416926856 tnum: 1 slow 0 duration 0 <0x2b8e1680>
31	11/25/14 9:47:36.754	AlarmManager::Run callback for alarm 0x9f12c8 entry 0x1b1a3c8 type 24 id 36163 param=(nil) entry->when: 1416926856 time: 1416926856 tnum: 1 slow 0 tardy 0 <0x2b8e1680>
10	11/25/14 9:47:36.754	XXX-UpdateSystemMessagesTasks StartupTask #0 = 4 OK / ZWave <0x2b8e1680>
10	11/25/14 9:47:36.755	XXX-UpdateSystemMessagesTasks StartupTask #1 = 4 OK / Study Timer (30 Min)[77] <0x2b8e1680>

But this appears to be what it manages to do

Can anyone shed any light on this? My wife has about given up on Vera HA
Thanks
John

parkerc · November 25, 2014, 11:54pm

It’s always difficult to try and troubleshoot from afar, but I wonder if there is a saturations of events occurring, to many things going on or off at around the same time (maybe a loop or something is occurring) - you talked about doing more with PLEG etc.

As you have back ups, have you considered removing all plugin/apps and seeing how it works/performs as a just a z-wave mesh network, running basic scenes/triggers from the controller?

For me, the mesh network is always the important bit, the apps/plugins come later and run ontop.

You also mentioned that you had two Veras (as you were using them in bridge mode) - - you could explore restoring a recent back up onto one, so you have two the same, then take one offline and have a go at taking it back to a very basic state again.

Not ideal I know, but i want to try and help…

clippermiami · November 26, 2014, 12:14am

[quote=“parkerc, post:14, topic:183467”]It’s always difficult to try and troubleshoot from afar, but I wonder if there is a saturations of events occurring, to many things going on or off at around the same time (maybe a loop or something is occurring) - you talked about doing more with PLEG etc.

As you have back ups, have you considered removing all plugin/apps and seeing how it works/performs as a just a z-wave mesh network, running basic scenes/triggers from the controller?

For me, the mesh network is always the important bit, the apps/plugins come later and run ontop.

You also mentioned that you had two Veras (as you were using them in bridge mode) - - you could explore restoring a recent back up onto one, so you have two the same, then take one offline and have a go at taking it back to a very basic state again.

Not ideal I know, but i want to try and help…[/quote]

I appreciate your interest. After I posted this I heard back from Tech Support and had not had a chance to update this thread as yet. Support said it looked like the problem was due to the Variable Container Plug In and asked me to remove it and continue monitoring. I had to rework several PLEG which I completed about an hour ago.

Performance APPEARS at first blush to be much much better but I’m reserving judgment for a few days to be sure

RichardTSchaefer · November 26, 2014, 1:05am

The following looks bad:

175m 141% 36% /usr/bin/LuaUPnP

You need to turn off your AR bit … but the Virtual Memory requirements at 141% of available memory is probably the problem!

It can be over 100% a little, but not by 141%. Once you start interacting with the the Plugin Devices you are going to have problems!
What is this value right after a reboot ?

clippermiami · November 26, 2014, 1:10am

[quote=“RichardTSchaefer, post:16, topic:183467”]The following looks bad:

175m 141% 36% /usr/bin/LuaUPnP

You need to turn off your AR bit … but the Virtual Memory requirements at 141% of available memory is probably the problem!

It can be over 100% a little, but not by 141%. Once you start interacting with the the Plugin Devices you are going to have problems!
What is this value right after a reboot ?[/quote]

Richard thanks for the input. First off what is the “AR bit”, what does it do and now fires one turn it off?

Did you see my previous post about the reply from Tech Support and the Variable Container Plug-In? I did as they asked and things APPEAR to be significantly better,

RichardTSchaefer · November 26, 2014, 1:26am

AR is anal retentive … you have to use fuzzy math when looking at memory on Linux … because there no single number that tells you if you are out of memory.
But there are fuzzy ranges … and 141% is most likely a problem.

clippermiami · November 26, 2014, 2:44am

[quote=“RichardTSchaefer, post:18, topic:183467”]AR is anal retentive … you have to use fuzzy math when looking at memory on Linux … because there no single number that tells you if you are out of memory.
But there are fuzzy ranges … and 141% is most likely a problem.[/quote]

Tech Support didn’t mention it ion conjunction with his diagnosis but I will ask him about it when I update him tomorrow.