We have moved at community.getvera.com

Author Topic: UI7: luup overload?  (Read 3878 times)

Offline mszewcz

  • Sr. Newbie
  • *
  • Posts: 43
  • Karma: +1/-0
UI7: luup overload?
« on: October 01, 2014, 05:14:27 pm »
Hi there,

I've just noticed a big problem with my VeraLite. It seems that something is overloading luup engine and causing delays (between 3 & 15 secs.) when executing scenes as well as regular UI/API calls (on/off/etc.). After luup is reloaded everything goes back on track.
I restored factory defaults today & re-included all my devices. The result is the same - after some time (usually about 1-2 hrs) Vera starts to act/respond slowly.

In case of any questions - I don't have any "strange" devices connected (see my signature) and I use only DayOrNight & VirtualSwitch plugin. I'm running 1.7.374 firmware.

Any ideas (excluding the scene that will reload luup every hour)?
VeraLite @ UI7 | 7xFGD-211, 2xFGMS-001, 1xFGK-105, 1xDSC24

Offline Borat

  • Full Member
  • ***
  • Posts: 169
  • Karma: +4/-5
Re: UI7: luup overload?
« Reply #1 on: October 01, 2014, 05:50:47 pm »
How many devices you have? Sounds like memory issues. I am steering clear of ui7 but would hazard a guess it's more memory intensive than ui5 and I struggled to keep things running on a vera lite on ui5 due to lack of memory. Can you ssh to your box and check the memory usage?

Offline mszewcz

  • Sr. Newbie
  • *
  • Posts: 43
  • Karma: +1/-0
Re: UI7: luup overload?
« Reply #2 on: October 01, 2014, 05:57:43 pm »
I've got 11 devices and here's what top says:

Code: [Select]
Mem: 42300K used, 20180K free, 0K shrd, 0K buff, 24532K cached
CPU:   5% usr   5% sys   0% nic  89% idle   0% io   0% irq   0% sirq
Load average: 0.21 0.22 0.22 1/67 29687
  PID  PPID USER     STAT   VSZ %MEM %CPU COMMAND
26416  2673 root     S    51968  83%   0% /usr/bin/LuaUPnP
 2582     1 root     S      748   1%   0% /usr/bin/luci-bwc -d
 3014  2923 root     S     6892  11%   0% /usr/bin/NetworkMonitor
29629 24490 root     R     1680   3%   0% top
    3     2 root     SW       0   0%   0% [ksoftirqd/0]
 6713     1 root     S     4436   7%   0% lighttpd -f /etc/lighttpd.conf
  439     1 root     S     1928   3%   0% syslogd -C256
25330     1 root     S     1836   3%   0% /bin/sh //usr/bin/cmh-ra-daemon.sh 12
 2453     1 root     S     1696   3%   0% crond -c /etc/crontabs -l 5
24490 24431 root     S     1692   3%   0% -ash
 2673     1 root     S     1688   3%   0% /bin/sh /usr/bin/Start_LuaUPnP.sh
 2561     1 root     S     1688   3%   0% udhcpc -t 0 -i eth0:0 -b -p /var/run/
    1     0 root     S     1684   3%   0% init
  404     1 root     S     1684   3%   0% init
 2613     1 root     S     1680   3%   0% watchdog -t 5 /dev/watchdog
 2923     1 root     S     1680   3%   0% /bin/sh /usr/bin/Start_NetworkMonitor
 2696  2673 root     S     1676   3%   0% /bin/sh /usr/bin/Start_serproxy.sh
  441     1 root     S     1672   3%   0% klogd
29397 25330 root     S     1668   3%   0% sleep 58
25354 25330 root     S     1192   2%   0% ssh -p 232 -T -y -i //etc/cmh-ra/keys

And after 25 mins (already have 8 sec delays on switching lights on/off):
Code: [Select]
Mem: 43044K used, 19436K free, 0K shrd, 0K buff, 25020K cached
CPU:   5% usr   5% sys   0% nic  88% idle   0% io   0% irq   0% sirq
Load average: 0.23 0.19 0.20 1/68 16383
  PID  PPID USER     STAT   VSZ %MEM %CPU COMMAND
 3014  2923 root     S     6892  11%   1% /usr/bin/NetworkMonitor
26416  2673 root     S    52188  83%   0% /usr/bin/LuaUPnP
29629 24490 root     R     1680   3%   0% top
 2582     1 root     S      748   1%   0% /usr/bin/luci-bwc -d
    3     2 root     SW       0   0%   0% [ksoftirqd/0]
 6713     1 root     S     4436   7%   0% lighttpd -f /etc/lighttpd.conf
  439     1 root     S     1928   3%   0% syslogd -C256
15329     1 root     S     1836   3%   0% /bin/sh //usr/bin/cmh-ra-daemon.sh 12
 2453     1 root     S     1696   3%   0% crond -c /etc/crontabs -l 5
24490 24431 root     S     1692   3%   0% -ash
 2673     1 root     S     1688   3%   0% /bin/sh /usr/bin/Start_LuaUPnP.sh
 2561     1 root     S     1688   3%   0% udhcpc -t 0 -i eth0:0 -b -p /var/run/
    1     0 root     S     1684   3%   0% init
  404     1 root     S     1684   3%   0% init
 2613     1 root     S     1680   3%   0% watchdog -t 5 /dev/watchdog
 2923     1 root     S     1680   3%   0% /bin/sh /usr/bin/Start_NetworkMonitor
 2696  2673 root     S     1676   3%   0% /bin/sh /usr/bin/Start_serproxy.sh
  441     1 root     S     1672   3%   0% klogd
15707 15329 root     S     1668   3%   0% sleep 58
15353 15329 root     S     1192   2%   0% ssh -p 232 -T -y -i //etc/cmh-ra/keys

Luup reloaded, no delays, top results:
Code: [Select]
Mem: 43276K used, 19204K free, 0K shrd, 0K buff, 25148K cached
CPU:   5% usr   6% sys   0% nic  87% idle   0% io   0% irq   0% sirq
Load average: 1.22 0.49 0.30 1/69 21722
  PID  PPID USER     STAT   VSZ %MEM %CPU COMMAND
21421  2673 root     S    52112  83%   1% /usr/bin/LuaUPnP
 3014  2923 root     S     6892  11%   1% /usr/bin/NetworkMonitor
 2582     1 root     S      748   1%   1% /usr/bin/luci-bwc -d
21664 24490 root     R     1680   3%   0% top
 6713     1 root     S     4436   7%   0% lighttpd -f /etc/lighttpd.conf
  439     1 root     S     1928   3%   0% syslogd -C256
15329     1 root     S     1836   3%   0% /bin/sh //usr/bin/cmh-ra-daemon.sh 12
 2453     1 root     S     1696   3%   0% crond -c /etc/crontabs -l 5
24490 24431 root     S     1692   3%   0% -ash
 2673     1 root     S     1688   3%   0% /bin/sh /usr/bin/Start_LuaUPnP.sh
 2561     1 root     S     1688   3%   0% udhcpc -t 0 -i eth0:0 -b -p /var/run/
    1     0 root     S     1684   3%   0% init
  404     1 root     S     1684   3%   0% init
 2613     1 root     S     1680   3%   0% watchdog -t 5 /dev/watchdog
 2923     1 root     S     1680   3%   0% /bin/sh /usr/bin/Start_NetworkMonitor
 2696  2673 root     S     1676   3%   0% /bin/sh /usr/bin/Start_serproxy.sh
  441     1 root     S     1672   3%   0% klogd
19056 15329 root     S     1668   3%   0% sleep 58
15353 15329 root     S     1248   2%   0% ssh -p 232 -T -y -i //etc/cmh-ra/keys
24431  7181 root     S     1168   2%   0% /usr/sbin/dropbear -P /var/run/dropbe

According to above it doesn't seem to be a lack of memory related problem. It's rather something wrong with luup engine.
« Last Edit: October 01, 2014, 06:28:55 pm by mszewcz »
VeraLite @ UI7 | 7xFGD-211, 2xFGMS-001, 1xFGK-105, 1xDSC24

Offline jasperhb

  • Sr. Newbie
  • *
  • Posts: 46
  • Karma: +1/-0
Re: UI7: luup overload?
« Reply #3 on: October 02, 2014, 12:14:48 pm »

Offline SpongeRob

  • Newbie
  • *
  • Posts: 1
  • Karma: +0/-0
Re: UI7: luup overload?
« Reply #4 on: October 02, 2014, 03:18:45 pm »
Take a look at your installed plug-ins/apps on Vera.
I had a simulair issue, and removed an old "app" (Ergy) to get rid of the strange delays.

Offline mszewcz

  • Sr. Newbie
  • *
  • Posts: 43
  • Karma: +1/-0
Re: UI7: luup overload?
« Reply #5 on: October 02, 2014, 06:43:10 pm »
Unfortunately it didn't help me. I don't have any long scene/device names, they don't have any non ascii chars in their names and I don't have any scene that runs every x mins/hours/etc.
Also checked my logs. There's nothing unusual, except TempLogFilesystemFailure every 5-6 minutes:
Code: [Select]
01 10/03/14 0:23:34.157 UserData::WriteUserData saved--before move File Size: 14445 save size 14445 <0x2ba26680>
02 10/03/14 0:23:34.157 UserData::TempLogFileSystemFailure start <0x2ba26680>
02 10/03/14 0:23:34.180 UserData::TempLogFileSystemFailure 4049
-rw-r--r--    1 root     root            33 Sep 26 11:38 /etc/cmh/HW_Key
-rw-r--r--    1 root     root            32 Sep 26 11:39 /etc/cmh/HW_Key2
-rw-r--r--    1 root     root             9 Sep 26 11:38 /etc/cmh/PK_AccessPoint
-rw-r--r--    1 root     root             7 Oct  1 15:15 /etc/cmh/PK_Account
...
VeraLite @ UI7 | 7xFGD-211, 2xFGMS-001, 1xFGK-105, 1xDSC24

Offline Brighters

  • Sr. Newbie
  • *
  • Posts: 43
  • Karma: +1/-0
Re: UI7: luup overload?
« Reply #6 on: October 25, 2014, 06:06:24 pm »
http://shop.brighters.nl De slimste domotica shop van Nederland!

Offline ElGringoCurioso

  • Jr. Member
  • **
  • Posts: 94
  • Karma: +2/-0
Re: UI7: luup hangs !! "ZWaveNode::HandlePollUpdate_... got BUSY for 8"
« Reply #7 on: November 02, 2014, 05:19:43 am »
I think i bumped into your problem on my VeraLt !!!
From /tmp/log/cmh/LuaUpnp.log

11/02/14 1:14:33.443   
<Job ID="247" Name="pollnode #8 1 cmds" Device="8" Created="2014-11-02 1:14:33" Started="2014-11-02 1:14:33" Completed="2014-11-02 1:14:33" Duration="0.342068000" Runtime="0.329141000" Status="Successful" LastNote="" Node="8" NodeType="ZWaveDimmableLight" NodeDescription="LivingRm DimLt"/> <0x2bbbc680>
------------------------ Error Begin:
11/02/14 1:14:33.672   
ZWaveNode::HandlePollUpdate_Application_Status got APPLICATION_BUSY for 8 <0x2bbbc680>
-------------------------- Error End.
11/02/14 1:14:53.232   
Device_Variable::m_szValue_set device: 26 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: CurrentTemperature was: 69 now: 69 #hooks: 0 upnp: 0 skip: 0 v:0xd40e88/NONE duplicate:1 <0x2bbbc680>

(what is before and after that error is just regular polling log data)

in other words it seems that the LuaUpnp hangs for 8secs now and then while runing its ZWave nodes PollingUpdate because of "Status = APPLICATION_BUSY" condition.

Do you get the followign errors as well?

11/02/14 1:07:23.167    UserData::WriteUserData saved--before move File Size: 14883 save size 14883 <0x2bdbc680>

11/02/14 1:07:23.167    UserData::TempLogFileSystemFailure start <0x2bdbc680>

11/02/14 1:07:23.192    UserData::TempLogFileSystemFailure 5069

I believe this TempLogFileSystemFailure is what is triping LuaUPnP engine and screwing the zWave interface:

ZWaveSerial::Send m_iFrameID 1182 got a CAN -- Dongle is in a bad state.  Wait 1 second before continuing to let it try to recover. <0x2bfbc680>

The good thing is that no mater how bad things run, it recovers and keeps going instead of Quiting.

Offline YzRacer

  • Full Member
  • ***
  • Posts: 139
  • Karma: +0/-0
Re: UI7: luup overload?
« Reply #8 on: November 20, 2014, 05:15:58 am »
I get a lot of similar errors in my log, but haven't really had the problem with delayed actions. It does seem that it is fairly routine that it crashes and reloads, but the system keeps working for the most part. I'm new to Vera so I have some catching up to do on these topics.