zmx10.pl script looping?!
Posted: Fri Dec 23, 2005 3:06 pm
Configuration:
Pentium II 350Mhz
256MB
ZM v1.21.3
Apache v1.3.27-4
3 cams
X10 Active
I've mentioned in other threads the problems that I've been having with X10 (Output Alarm String) where the lights do not always turn on, tasks do not always load properly, etc. I have 2 profiles (DayTime: from sunrise - 10:25pm, NightTime: from 10:26pm - sunrise) which are in my crontab. I finally figured out what is causing the problem, but can not figure out why or what it is doing.
At approx. 4:30pm everyday, the zmx10.pl script starts using up 40% of the cpu untill sunrise the next day where the next profile gets loaded (and therefore the zmx10.pl script gets resubmitted). I've enabled verbose to the max in the script; when the script behaves properly - it writes to the logfile, but when it takes off - nothing gets written to the script. I checked my system for other jobs that may hog the cpu, but apart from the backups (which I moved from midnight to 8:00am) and the standard scripts in cron.*, nothing else is running.
I've included portions of some log files that I collected...
SAR...
03:10:00 PM all 52.98 0.00 0.58 46.43
03:20:00 PM all 52.98 0.00 0.59 46.43
03:30:01 PM all 55.20 0.00 0.73 44.07
03:40:00 PM all 54.83 0.00 0.68 44.50
03:50:01 PM all 52.90 0.00 0.52 46.57
04:00:00 PM all 52.69 0.00 0.50 46.81
04:10:00 PM all 52.81 0.00 0.54 46.65
04:20:00 PM all 60.26 0.00 2.12 37.62
04:30:00 PM all 91.61 0.00 8.39 0.00
04:40:01 PM all 92.17 0.00 7.83 0.00
04:50:00 PM all 92.07 0.00 7.93 0.00
05:00:00 PM all 92.09 0.00 7.91 0.00
05:10:00 PM all 91.90 0.00 8.10 0.00
05:20:00 PM all 91.88 0.00 8.12 0.00
05:30:00 PM all 91.79 0.00 8.21 0.00
05:40:00 PM all 91.70 0.00 8.30 0.00
** kill -HUP of the zmx10.pl script here...
05:50:00 PM all 80.62 0.00 6.26 13.11
06:00:00 PM all 52.94 0.00 0.55 46.52
06:10:00 PM all 52.84 0.00 0.52 46.64
06:20:01 PM all 62.16 0.00 1.44 36.41
06:30:00 PM all 55.73 0.00 0.77 43.50
06:40:00 PM all 54.84 0.00 0.94 44.22
06:50:01 PM all 52.83 0.00 0.51 46.65
07:00:00 PM all 55.37 0.00 0.75 43.88
07:10:01 PM all 55.19 0.00 0.70 44.11
07:20:01 PM all 76.37 0.00 2.49 21.14
07:30:00 PM all 55.74 0.00 0.73 43.54
07:40:00 PM all 52.81 0.00 0.54 46.65
07:50:00 PM all 53.62 0.00 0.58 45.80
08:00:01 PM all 53.10 0.00 0.53 46.37
08:10:00 PM all 52.99 0.00 0.55 46.47
08:20:00 PM all 52.83 0.00 0.54 46.64
08:30:00 PM all 52.85 0.00 0.58 46.57
08:40:00 PM all 53.15 0.00 0.53 46.32
08:50:01 PM all 53.11 0.00 0.50 46.39
09:00:00 PM all 52.80 0.00 0.50 46.70
09:10:00 PM all 53.13 0.00 0.49 46.38
09:20:00 PM all 53.12 0.00 0.57 46.31
09:30:00 PM all 52.85 0.00 0.54 46.61
09:40:00 PM all 52.70 0.00 0.57 46.73
09:50:00 PM all 60.76 0.00 2.17 37.07
10:00:00 PM all 91.82 0.00 8.18 0.00
10:10:00 PM all 92.01 0.00 7.99 0.00
10:20:01 PM all 91.92 0.00 8.08 0.00
10:30:00 PM all 77.23 0.00 4.88 17.89
10:40:00 PM all 63.40 0.00 1.07 35.53
10:50:00 PM all 89.71 0.00 8.41 1.88
11:00:00 PM all 92.03 0.00 7.97 0.00
11:10:00 PM all 92.01 0.00 7.99 0.00
11:20:00 PM all 92.07 0.00 7.93 0.00
11:30:00 PM all 91.73 0.00 8.27 0.00
11:40:01 PM all 92.01 0.00 7.99 0.00
11:50:00 PM all 91.98 0.00 8.02 0.00
12:10:00 AM all 92.10 0.00 7.90 0.00
12:20:00 AM all 91.98 0.00 8.02 0.00
12:30:00 AM all 92.05 0.00 7.95 0.00
12:40:00 AM all 92.11 0.00 7.89 0.00
12:50:00 AM all 91.95 0.00 8.05 0.00
01:00:00 AM all 92.22 0.00 7.78 0.00
01:10:00 AM all 92.19 0.00 7.81 0.00
01:20:00 AM all 92.08 0.00 7.92 0.00
01:30:00 AM all 91.99 0.00 8.01 0.00
01:40:00 AM all 91.96 0.00 8.04 0.00
01:50:00 AM all 91.93 0.00 8.07 0.00
02:00:00 AM all 92.06 0.00 7.94 0.00
02:10:00 AM all 92.18 0.00 7.82 0.00
02:20:00 AM all 92.02 0.00 7.98 0.00
02:30:00 AM all 91.84 0.00 8.16 0.00
02:40:01 AM all 92.02 0.00 7.98 0.00
02:50:00 AM all 91.09 0.00 8.91 0.00
03:00:00 AM all 90.71 0.00 9.29 0.00
03:10:00 AM all 90.65 0.00 9.35 0.00
03:20:00 AM all 90.67 0.00 9.33 0.00
03:30:01 AM all 90.65 0.00 9.35 0.00
03:40:01 AM all 90.71 0.00 9.29 0.00
03:50:00 AM all 90.75 0.00 9.25 0.00
04:00:00 AM all 91.14 0.00 8.86 0.00
04:10:00 AM all 91.77 0.05 8.18 0.00
04:20:00 AM all 91.98 0.05 7.96 0.00
04:30:00 AM all 91.74 0.07 8.19 0.00
04:40:00 AM all 91.90 0.05 8.04 0.00
04:50:01 AM all 92.03 0.00 7.97 0.00
05:00:00 AM all 91.98 0.00 8.02 0.00
05:10:00 AM all 91.97 0.00 8.03 0.00
05:20:00 AM all 91.95 0.00 8.05 0.00
05:30:00 AM all 91.68 0.00 8.32 0.00
** kill -HUP of the zmx10.pl script here... again.
05:40:00 AM all 75.10 0.00 5.64 19.27
05:50:00 AM all 53.23 0.00 0.48 46.29
06:00:00 AM all 53.15 0.00 0.45 46.39
06:10:00 AM all 53.11 0.00 0.45 46.44
06:20:00 AM all 52.69 0.00 0.45 46.85
06:30:00 AM all 53.05 0.00 0.48 46.47
06:40:00 AM all 56.31 0.00 0.61 43.07
06:50:00 AM all 53.15 0.00 0.47 46.38
07:00:00 AM all 52.71 0.00 0.48 46.82
07:10:00 AM all 53.69 0.00 0.47 45.84
07:20:01 AM all 53.69 0.00 0.92 45.39
07:30:00 AM all 52.62 0.00 0.46 46.92
07:40:00 AM all 63.41 0.00 1.55 35.04
TOP...
11:50pm up 113 days, 12:12, 1 user, load average: 2.34, 2.32, 2.31
85 processes: 82 sleeping, 3 running, 0 zombie, 0 stopped
CPU states: 92.0% user, 7.9% system, 0.0% nice, 0.0% idle
Mem:288220K av, 251232K used, 36988K free, 0K shrd, 18632K buff
Swap:551872K av, 43116K used, 508756K free 127008K cached
PID USER PRI NI SIZE RSS SHARE STAT %CPU %MEM TIME COMMAND
29141 apache 25 0 6264 6264 1680 R 39.8 2.1 28:13 zmx10.pl
29110 apache 25 0 14568 14M 12080 R 26.3 5.0 21:47 zma
29122 apache 15 0 12200 11M 9832 S 15.9 4.2 13:33 zma
29098 apache 15 0 6808 6808 4720 S 6.6 2.3 5:39 zma
29102 apache 15 0 18584 14M 12016 S 5.7 5.0 4:56 zmc
29114 apache 15 0 16392 11M 9824 S 4.3 4.2 3:57 zmc
29090 apache 15 0 10760 6600 4712 S 0.6 2.2 0:36 zmc
29148 mysql 15 0 7688 4428 2824 S 0.1 1.5 0:06 mysqld
ZMX10.PL LOG...(ZM_X10_DB_RELOAD_INTERVAL = 1800sec)
[Should have 17 "Loading Tasks"]
:
:
X10 server starting at 05/12/21 22:25:42 (NightTime Profile)
Loading tasks
Nite-FrontYard has alarm output string '2'
Adding to monitor list, UnitCode:2, Event:ON, Monitor:HASH(0x853f9c4), Function:on, Limit:0
Adding to monitor list, UnitCode:2, Event:OFF, Monitor:HASH(0x853f9c4), Function:off, Limit:0
Nite-Entrance has alarm output string '6'
Adding to monitor list, UnitCode:6, Event:ON, Monitor:HASH(0x8544edc), Function:on, Limit:0
Adding to monitor list, UnitCode:6, Event:OFF, Monitor:HASH(0x8544edc), Function:off, Limit:0
X10 server starting at 05/12/22 07:12:43 (DayTime Profile)
Loading tasks
:
:
If anyone knows what else I can do to capture more info or where in the script to add more trace statements to find out what the script is doing at this point, would be appreciated or if anyone has seen this problem before.
Thanks.
Pentium II 350Mhz
256MB
ZM v1.21.3
Apache v1.3.27-4
3 cams
X10 Active
I've mentioned in other threads the problems that I've been having with X10 (Output Alarm String) where the lights do not always turn on, tasks do not always load properly, etc. I have 2 profiles (DayTime: from sunrise - 10:25pm, NightTime: from 10:26pm - sunrise) which are in my crontab. I finally figured out what is causing the problem, but can not figure out why or what it is doing.
At approx. 4:30pm everyday, the zmx10.pl script starts using up 40% of the cpu untill sunrise the next day where the next profile gets loaded (and therefore the zmx10.pl script gets resubmitted). I've enabled verbose to the max in the script; when the script behaves properly - it writes to the logfile, but when it takes off - nothing gets written to the script. I checked my system for other jobs that may hog the cpu, but apart from the backups (which I moved from midnight to 8:00am) and the standard scripts in cron.*, nothing else is running.
I've included portions of some log files that I collected...
SAR...
03:10:00 PM all 52.98 0.00 0.58 46.43
03:20:00 PM all 52.98 0.00 0.59 46.43
03:30:01 PM all 55.20 0.00 0.73 44.07
03:40:00 PM all 54.83 0.00 0.68 44.50
03:50:01 PM all 52.90 0.00 0.52 46.57
04:00:00 PM all 52.69 0.00 0.50 46.81
04:10:00 PM all 52.81 0.00 0.54 46.65
04:20:00 PM all 60.26 0.00 2.12 37.62
04:30:00 PM all 91.61 0.00 8.39 0.00
04:40:01 PM all 92.17 0.00 7.83 0.00
04:50:00 PM all 92.07 0.00 7.93 0.00
05:00:00 PM all 92.09 0.00 7.91 0.00
05:10:00 PM all 91.90 0.00 8.10 0.00
05:20:00 PM all 91.88 0.00 8.12 0.00
05:30:00 PM all 91.79 0.00 8.21 0.00
05:40:00 PM all 91.70 0.00 8.30 0.00
** kill -HUP of the zmx10.pl script here...
05:50:00 PM all 80.62 0.00 6.26 13.11
06:00:00 PM all 52.94 0.00 0.55 46.52
06:10:00 PM all 52.84 0.00 0.52 46.64
06:20:01 PM all 62.16 0.00 1.44 36.41
06:30:00 PM all 55.73 0.00 0.77 43.50
06:40:00 PM all 54.84 0.00 0.94 44.22
06:50:01 PM all 52.83 0.00 0.51 46.65
07:00:00 PM all 55.37 0.00 0.75 43.88
07:10:01 PM all 55.19 0.00 0.70 44.11
07:20:01 PM all 76.37 0.00 2.49 21.14
07:30:00 PM all 55.74 0.00 0.73 43.54
07:40:00 PM all 52.81 0.00 0.54 46.65
07:50:00 PM all 53.62 0.00 0.58 45.80
08:00:01 PM all 53.10 0.00 0.53 46.37
08:10:00 PM all 52.99 0.00 0.55 46.47
08:20:00 PM all 52.83 0.00 0.54 46.64
08:30:00 PM all 52.85 0.00 0.58 46.57
08:40:00 PM all 53.15 0.00 0.53 46.32
08:50:01 PM all 53.11 0.00 0.50 46.39
09:00:00 PM all 52.80 0.00 0.50 46.70
09:10:00 PM all 53.13 0.00 0.49 46.38
09:20:00 PM all 53.12 0.00 0.57 46.31
09:30:00 PM all 52.85 0.00 0.54 46.61
09:40:00 PM all 52.70 0.00 0.57 46.73
09:50:00 PM all 60.76 0.00 2.17 37.07
10:00:00 PM all 91.82 0.00 8.18 0.00
10:10:00 PM all 92.01 0.00 7.99 0.00
10:20:01 PM all 91.92 0.00 8.08 0.00
10:30:00 PM all 77.23 0.00 4.88 17.89
10:40:00 PM all 63.40 0.00 1.07 35.53
10:50:00 PM all 89.71 0.00 8.41 1.88
11:00:00 PM all 92.03 0.00 7.97 0.00
11:10:00 PM all 92.01 0.00 7.99 0.00
11:20:00 PM all 92.07 0.00 7.93 0.00
11:30:00 PM all 91.73 0.00 8.27 0.00
11:40:01 PM all 92.01 0.00 7.99 0.00
11:50:00 PM all 91.98 0.00 8.02 0.00
12:10:00 AM all 92.10 0.00 7.90 0.00
12:20:00 AM all 91.98 0.00 8.02 0.00
12:30:00 AM all 92.05 0.00 7.95 0.00
12:40:00 AM all 92.11 0.00 7.89 0.00
12:50:00 AM all 91.95 0.00 8.05 0.00
01:00:00 AM all 92.22 0.00 7.78 0.00
01:10:00 AM all 92.19 0.00 7.81 0.00
01:20:00 AM all 92.08 0.00 7.92 0.00
01:30:00 AM all 91.99 0.00 8.01 0.00
01:40:00 AM all 91.96 0.00 8.04 0.00
01:50:00 AM all 91.93 0.00 8.07 0.00
02:00:00 AM all 92.06 0.00 7.94 0.00
02:10:00 AM all 92.18 0.00 7.82 0.00
02:20:00 AM all 92.02 0.00 7.98 0.00
02:30:00 AM all 91.84 0.00 8.16 0.00
02:40:01 AM all 92.02 0.00 7.98 0.00
02:50:00 AM all 91.09 0.00 8.91 0.00
03:00:00 AM all 90.71 0.00 9.29 0.00
03:10:00 AM all 90.65 0.00 9.35 0.00
03:20:00 AM all 90.67 0.00 9.33 0.00
03:30:01 AM all 90.65 0.00 9.35 0.00
03:40:01 AM all 90.71 0.00 9.29 0.00
03:50:00 AM all 90.75 0.00 9.25 0.00
04:00:00 AM all 91.14 0.00 8.86 0.00
04:10:00 AM all 91.77 0.05 8.18 0.00
04:20:00 AM all 91.98 0.05 7.96 0.00
04:30:00 AM all 91.74 0.07 8.19 0.00
04:40:00 AM all 91.90 0.05 8.04 0.00
04:50:01 AM all 92.03 0.00 7.97 0.00
05:00:00 AM all 91.98 0.00 8.02 0.00
05:10:00 AM all 91.97 0.00 8.03 0.00
05:20:00 AM all 91.95 0.00 8.05 0.00
05:30:00 AM all 91.68 0.00 8.32 0.00
** kill -HUP of the zmx10.pl script here... again.
05:40:00 AM all 75.10 0.00 5.64 19.27
05:50:00 AM all 53.23 0.00 0.48 46.29
06:00:00 AM all 53.15 0.00 0.45 46.39
06:10:00 AM all 53.11 0.00 0.45 46.44
06:20:00 AM all 52.69 0.00 0.45 46.85
06:30:00 AM all 53.05 0.00 0.48 46.47
06:40:00 AM all 56.31 0.00 0.61 43.07
06:50:00 AM all 53.15 0.00 0.47 46.38
07:00:00 AM all 52.71 0.00 0.48 46.82
07:10:00 AM all 53.69 0.00 0.47 45.84
07:20:01 AM all 53.69 0.00 0.92 45.39
07:30:00 AM all 52.62 0.00 0.46 46.92
07:40:00 AM all 63.41 0.00 1.55 35.04
TOP...
11:50pm up 113 days, 12:12, 1 user, load average: 2.34, 2.32, 2.31
85 processes: 82 sleeping, 3 running, 0 zombie, 0 stopped
CPU states: 92.0% user, 7.9% system, 0.0% nice, 0.0% idle
Mem:288220K av, 251232K used, 36988K free, 0K shrd, 18632K buff
Swap:551872K av, 43116K used, 508756K free 127008K cached
PID USER PRI NI SIZE RSS SHARE STAT %CPU %MEM TIME COMMAND
29141 apache 25 0 6264 6264 1680 R 39.8 2.1 28:13 zmx10.pl
29110 apache 25 0 14568 14M 12080 R 26.3 5.0 21:47 zma
29122 apache 15 0 12200 11M 9832 S 15.9 4.2 13:33 zma
29098 apache 15 0 6808 6808 4720 S 6.6 2.3 5:39 zma
29102 apache 15 0 18584 14M 12016 S 5.7 5.0 4:56 zmc
29114 apache 15 0 16392 11M 9824 S 4.3 4.2 3:57 zmc
29090 apache 15 0 10760 6600 4712 S 0.6 2.2 0:36 zmc
29148 mysql 15 0 7688 4428 2824 S 0.1 1.5 0:06 mysqld
ZMX10.PL LOG...(ZM_X10_DB_RELOAD_INTERVAL = 1800sec)
[Should have 17 "Loading Tasks"]
:
:
X10 server starting at 05/12/21 22:25:42 (NightTime Profile)
Loading tasks
Nite-FrontYard has alarm output string '2'
Adding to monitor list, UnitCode:2, Event:ON, Monitor:HASH(0x853f9c4), Function:on, Limit:0
Adding to monitor list, UnitCode:2, Event:OFF, Monitor:HASH(0x853f9c4), Function:off, Limit:0
Nite-Entrance has alarm output string '6'
Adding to monitor list, UnitCode:6, Event:ON, Monitor:HASH(0x8544edc), Function:on, Limit:0
Adding to monitor list, UnitCode:6, Event:OFF, Monitor:HASH(0x8544edc), Function:off, Limit:0
X10 server starting at 05/12/22 07:12:43 (DayTime Profile)
Loading tasks
:
:
If anyone knows what else I can do to capture more info or where in the script to add more trace statements to find out what the script is doing at this point, would be appreciated or if anyone has seen this problem before.
Thanks.