zmfilter polling slow.

Forum for questions and support relating to the 1.28.x releases only.
segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

zmfilter polling slow.

Post by segordon »

Hi there,

How can I increase the rate at which zmfilter.pl checks for events? I figured it'd be the filter_execute_interval, but that seems to have little effect.
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

segordon wrote:Hi there,

How can I increase the rate at which zmfilter.pl checks for events? I figured it'd be the filter_execute_interval, but that seems to have little effect.
I think you are looking for FILTER_EXECUTE_INTERVAL (Options->System in the web console)

When you say it has 'little effect' what do you mean? You should see a log entry (if you have Debug enabled) at approximately that many seconds saying zmfilter is checking for filters and more logs per filter.

Note that this specifies how often zmfilter will process filters to see if they need to be executed (default in my system is every 60s). Whether each filter executes each time zmfilter processes them will depend on the condition you set in the filter criteria


Some more details:
If you look at the code of zmfilter.pl, its basically a constantly running perl script that sleeps for FILTER_EXECUTE_INTERVAL in an endless loop.

Here is how it gets its delay:
https://github.com/ZoneMinder/ZoneMinde ... pl.in#L134

Here is how it loops endlessly:
https://github.com/ZoneMinder/ZoneMinde ... #L207-L226

So if its not looping, its possible it's crashing frequently - you might want to take a closer look at your logs.
Last edited by asker on Tue Aug 11, 2015 4:44 pm, edited 1 time in total.
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon »

Here's a hyper-active zone I can use as an example. FILTER_EXECUTE_INTERVAL is set to '20' on my system; however each event batch is processed every five minutes (300s).

If I enable debug and extra logging, zmfilter even says ' Sleeping for 20 seconds.. ' after the event check in the weblog; however it is spaced by 5 minutes even with an active event hitting the background filter.

Code: Select all

2015-08-11 09:39:33.221330	zmfilter	6286	INF	Notification email sent	zmfilter.pl	
2015-08-11 09:39:30.953610	zmfilter	6286	INF	Sending notification email 'ZoneMinder: Alarm - frontDoor-56 (61 - 18 35)'	zmfilter.pl	
2015-08-11 09:39:30.919760	zmfilter	6286	INF	Creating notification email	zmfilter.pl	
2015-08-11 09:39:30.838310	zmfilter	6286	INF	Notification email sent	zmfilter.pl	
2015-08-11 09:39:28.608370	zmfilter	6286	INF	Sending notification email 'ZoneMinder: Alarm - frontDoor-55 (57 - 31 42)'	zmfilter.pl	
2015-08-11 09:39:28.556630	zmfilter	6286	INF	Creating notification email	zmfilter.pl	
2015-08-11 09:34:28.368310	zmfilter	6286	INF	Notification email sent	zmfilter.pl	
2015-08-11 09:34:26.049820	zmfilter	6286	INF	Sending notification email 'ZoneMinder: Alarm - driveway-54 (33 - 15 53)'	zmfilter.pl	
2015-08-11 09:34:26.004860	zmfilter	6286	INF	Creating notification email	zmfilter.pl	
2015-08-11 09:34:25.935600	zmfilter	6286	INF	Notification email sent	zmfilter.pl	
2015-08-11 09:34:23.691710	zmfilter	6286	INF	Sending notification email 'ZoneMinder: Alarm - driveway-53 (39 - 39 1)'	zmfilter.pl	
2015-08-11 09:34:23.635170	zmfilter	6286	INF	Creating notification email	zmfilter.pl	
2015-08-11 09:29:43.349340	zmfilter	6286	INF	Notification email sent	zmfilter.pl	
2015-08-11 09:29:41.112790	zmfilter	6286	INF	Sending notification email 'ZoneMinder: Alarm - driveway-52 (32 - 16 32)'	zmfilter.pl	
2015-08-11 09:29:41.068240	zmfilter	6286	INF	Creating notification email	zmfilter.pl	
2015-08-11 09:29:40.972400	zmfilter	6286	INF	Notification email sent	zmfilter.pl	
2015-08-11 09:29:38.766740	zmfilter	6286	INF	Sending notification email 'ZoneMinder: Alarm - frontDoor-51 (42 - 17 30)'	zmfilter.pl	
2015-08-11 09:29:38.721830	zmfilter	6286	INF	Creating notification email	zmfilter.pl	
2015-08-11 09:29:38.622280	zmfilter	6286	INF	Notification email sent	zmfilter.pl	
2015-08-11 09:29:36.365250	zmfilter	6286	INF	Sending notification email 'ZoneMinder: Alarm - driveway-50 (40 - 21 20)'	zmfilter.pl	
2015-08-11 09:29:36.321410	zmfilter	6286	INF	Creating notification email	zmfilter.pl	
2015-08-11 09:29:16.210920	zmfilter	6286	INF	Notification email sent	zmfilter.pl	
2015-08-11 09:29:13.980420	zmfilter	6286	INF	Sending notification email 'ZoneMinder: Alarm - driveway-49 (31 - 14 40)'	zmfilter.pl	
2015-08-11 09:29:13.935700	zmfilter	6286	INF	Creating notification email	zmfilter.pl	
2015-08-11 09:29:13.834170	zmfilter	6286	INF	Notification email sent	zmfilter.pl	
2015-08-11 09:29:11.623430	zmfilter	6286	INF	Sending notification email 'ZoneMinder: Alarm - driveway-48 (59 - 32 83)'	zmfilter.pl	
2015-08-11 09:29:11.578800	zmfilter	6286	INF	Creating notification email	zmfilter.pl	
2015-08-11 09:29:11.404080	zmfilter	6286	INF	Notification email sent	zmfilter.pl	
2015-08-11 09:29:09.166380	zmfilter	6286	INF	Sending notification email 'ZoneMinder: Alarm - driveway-47 (41 - 19 34)'	zmfilter.pl	
2015-08-11 09:29:09.077270	zmfilter	6286	INF	Creating notification email	zmfilter.pl	
2015-08-11 09:29:08.951980	zmfilter	6286	INF	Notification email sent	zmfilter.pl	
2015-08-11 09:29:06.654190	zmfilter	6286	INF	Sending notification email 'ZoneMinder: Alarm - driveway-46 (67 - 31 40)'	zmfilter.pl	
2015-08-11 09:29:06.598090	zmfilter	6286	INF	Creating notification email	zmfilter.pl	
2015-08-11 09:29:06.518370	zmfilter	6286	INF	Notification email sent	zmfilter.pl	
2015-08-11 09:29:04.274660	zmfilter	6286	INF	Sending notification email 'ZoneMinder: Alarm - driveway-45 (52 - 21 48)'	zmfilter.pl	
2015-08-11 09:29:04.210960	zmfilter	6286	INF	Creating notification email	zmfilter.pl	
2015-08-11 09:24:04.042220	zmfilter	6286	INF	Notification email sent	zmfilter.pl	
2015-08-11 09:24:01.728460	zmfilter	6286	INF	Sending notification email 'ZoneMinder: Alarm - driveway-44 (52 - 21 42)'	zmfilter.pl
Some more details:
If you look at the code of zmfilter.pl, its basically a constantly running perl script that sleeps for FILTER_EXECUTE_INTERVAL in an endless loop.

Here is how it gets its delay:
...
Here is how it loops endlessly:
...
So if its not looping, its possible it's crashing frequently - you might want to take a closer look at your logs.

I too found that delay when looking for the problem linked to FILTER_EXECUTE_INTERVAL. zmfilter isn't reported to be crashing within the weblog, and it doesn't crash when I run it manually with 'zmfilter.pl <filtername>'.

Is 300s the time in which the crashed daemon would be restarted? If so, it's definitely crashing; I just don't see the error anywhere.

The only 300s delay I see right away by default is FILTER_RELOAD_DELAY, but that doesn't seem like it would change anything past the initial filter load.
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

Ok, so I have some thoughts for investigation:

a) Your logs show both situations - cases where zmfilter is "sending notification" followed by "creating notification" within seconds of each other, as well as situations where they are spaced a few minutes apart. Now the thing is in your case, zmfilter will run every (approx) 20 seconds and reports whatever events its finds in the DB. For example, see this line in your log
2015-08-11 09:29:36.321410 zmfilter 6286 INF Creating notification email zmfilter.pl
2015-08-11 09:29:16.210920 zmfilter 6286 INF Notification email sent zmfilter.pl
This is a 20 second delay between Notification email sent (end of one zmfilter run for that filter) and Creating notification email (start of next zmfilter run). The fact that it is 20 seconds apart means its not one run with 2 events. Its 2 runs with 1 event each.

So I doubt if the trend of zmfilter running once in 5 minutes is accurate.

b) Note however that zmfilter will wait for smtpSend or mail->send (depending on which mailer module you use) to either succeed or fail before it continues to the next. See https://github.com/ZoneMinder/ZoneMinde ... l.in#L1191 - I wonder if the delay you are seeing may be some sort of choking/throttling at your mail server? (this is a guess)

c) The other thought I have is when does zmfilter report an event? Is it when an event is first started or when it completes? You might want to check if that plays a factor. I know it makes a DB entry the moment it gets an event - but I'm not sure if there is a db cache delay - let me investigate that angle (update: I don't think that is a problem - the sql query is static, zmfilter uses prepare_cache which is fine for the query)

d) Are you sure its not that your events may be detected in that interval by zone minder as opposed to being reported late? For example, can you compare the zmfilter log to events recorded by ZM and see if the events are being recorded within seconds of each other but reported 5 mins apart? (which is not universally true in your logs)

I don't think zmfilter is crashing - there is a 300 value, but that is the duration between which zmfilter checks the DB for new filters created.
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon »

I am using ssmtp, following the tutorial linked in your sig. I mention this due to the proximity of the line changes to the github line you linked.

Test emails fired off instantly with

Code: Select all

echo "Hello, World" | mail -s "My email check" user@email
zmfilter seems to report the event in batches, regardless of how many events have occurred. The '5 minute tick'. I receive all alert emails as one big batch, so I doubt that the mail provider is throttling; the timestamps match between when they are generated (in one big lump) and sent and the timestamps on the events are usually significantly earlier (3 or 4 minutes, less than the 5 minute tick).

d) can you rephrase the question? If you're curious if an event is continuing for a long time and causing the zmfilter to ignore it, the same behavior exists when I manually force alarms; this zone was just an easy example because of a windy day (and a poor setup modetect) so I used those logs.

If, for example, I have a perfectly clear zone and force a score 255 alarm manually, I can sit and wait sometimes for 3 or 4 minutes before zmfilter log reports the event (which is when I near instantly receive an email). Sometimes it's sooner, but I figure that's because I forced the event earlier in the tick by luck. I know the event is ended, because I force it for only a few seconds. It is eventually emailed, but whenever zmfilters bothers to check for the event.
segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon »

Here's a more clear log. I forced a bunch of events, and added a time-stamp to the email header so that you can see when the event occurs versus when the email is sent.

Code: Select all

2015-08-11 11:13:54.096670	zmfilter	22323	INF	Notification email sent	zmfilter.pl	
2015-08-11 11:13:51.901340	zmfilter	22323	INF	Sending notification email 'ZoneMinder: Alarm - driveway-64 (255 - 255 98)-2015-08-11 11:10:29'	zmfilter.pl	
2015-08-11 11:13:51.868190	zmfilter	22323	INF	Creating notification email	zmfilter.pl	
2015-08-11 11:13:51.799270	zmfilter	22323	INF	Notification email sent	zmfilter.pl	
2015-08-11 11:13:49.588720	zmfilter	22323	INF	Sending notification email 'ZoneMinder: Alarm - frontDoor-63 (255 - 255 110)-2015-08-11 11:10:08'	zmfilter.pl	
2015-08-11 11:13:49.554900	zmfilter	22323	INF	Creating notification email	zmfilter.pl	
2015-08-11 11:13:49.483810	zmfilter	22323	INF	Notification email sent	zmfilter.pl	
2015-08-11 11:13:47.263780	zmfilter	22323	INF	Sending notification email 'ZoneMinder: Alarm - frontDoor-62 (255 - 255 112)-2015-08-11 11:09:49'	zmfilter.pl	
2015-08-11 11:13:47.219160	zmfilter	22323	INF	Creating notification email	zmfilter.pl	
2015-08-11 11:13:47.084650	zmfilter	22323	INF	Notification email sent	zmfilter.pl	
2015-08-11 11:13:44.850860	zmfilter	22323	INF	Sending notification email 'ZoneMinder: Alarm - driveway-61 (255 - 255 124)-2015-08-11 11:09:23'	zmfilter.pl	
2015-08-11 11:13:44.810280	zmfilter	22323	INF	Creating notification email	zmfilter.pl	
2015-08-11 11:08:44.609490	zmfilter	22323	INF	Notification email sent	zmfilter.pl	
2015-08-11 11:08:40.350970	zmfilter	22323	INF	Sending notification email 'ZoneMinder: Alarm - frontDoor-60 (255 - 255 83)-2015-08-11 11:06:38'
So, the worst case in that log file is an event that occured at 11:09:23, but zmfilter didn't create the notification email until 11:13:44.
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

Very interesting. So if I get your situation correctly:

a) IF you run zmfilter manually, everything happens immediately (as expected)

b) If zmfilter is scheduled to run by ZM, you see it run every 20 seconds, but for whatever reason, it does not get into creating a notification email till 3-4 minutes later. And this happens consistently

is that correct? Or is it that irrespective of 20 seconds, zmfilter runs every 3-4 minutes?

(I don't have an answer yet)
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

Also, can you please redo this experiment above with Debug logs on and please post all the logs generated during those times
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon »

a) Correct.

b) Well, it's not that easy it seems. According to when the notifications are created/mailed out, its about 3 to 5 minutes. However, with logging enabled one can see that *something* is hitting the filters every 20 seconds, they just aren't being executed.

Here is an interesting debug log. I manually activated an alarm for 5 seconds at 13 39 49. zmfilter finds the filter at 13 43 55, however it is obvious in the log that it has been checking every 20 seconds since the creation of the event.

Pastebin because this forum software thinks the log file 'looks spammy'. pastebin slash nCEJvZf8
segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon »

asker wrote:Also, can you please redo this experiment above with Debug logs on and please post all the logs generated during those times
Sure, here you go. One manual score 255 alarm, waited for notification email to arrive, shut down ZoneMinder, 'cd /var/logs/zm' and 'cat * > merged.txt' .

posted to ubuntu pastebin due to size; above pastebin limit.

paste ubuntu com 12058156

omitted two log files, one 2.1g in size, the other 256m in size. Debug logging at level 9, may be too verbose; what level would you prefer me to log at?
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

So one thing I noticed in that large log file which seems to span around 7 minutes is zmfilter already exited with a signal code of 14.

08/11/2015 14:27:33.041486 zmdc[1378].INF ['zmfilter.pl ' stopping at 15/08/11 14:27:33]
08/11/2015 14:27:33.090275 zmdc[1378].INF ['zmfilter.pl ' exited, signal 14]

Try this please:
Please copy this to a script file (foo.sh), chmod a+x foo.sh and execute it

Code: Select all

#!/bin/bash
oldzmfpid=""
while :
do
        zmfpid=`ps -ae | grep zmfilter.pl | awk '{print $1}'`
        if [ "$oldzmfpid" != "$zmfpid" ] && [ "$zmfpid" != "" ]; then
                echo Zmfilter PID $zmfpid at `date`
                oldzmfpid=$zmfpid;
        fi
        sleep 1;
done
Then please run your scenario and watch the output of the script. I'd like to see how often zmfilter is restarting
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon »

No change in PID throughout the scenario. Event occurs at 18:27:25, zmfilter catches it at 18:32:44

Code: Select all

2015-08-11 18:32:44.342670	zmfilter	22539	INF	Notification email sent	zmfilter.pl	
2015-08-11 18:32:41.848650	zmfilter	22539	INF	Sending notification email 'ZoneMinder: Alarm - frontDoor-92 (255 - 255 80)-2015-08-11 18:27:25'	zmfilter.pl	
2015-08-11 18:32:41.793120	zmfilter	22539	INF	Creating notification email	zmfilter.pl

Code: Select all

╰─$ ./foo.sh 
Zmfilter PID 22539 at Tue Aug 11 18:26:42 PDT 2015
I get some exit code 14s on normal shutdown of ZM, could you be seeing that?
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

Okay so far:
1. Zmfilter is not crashing
2. It is being invoked every 20s but your filter is executing late

So my suspicion then is either alert filter or the sendmail command.

Can you please post how you've defined your filter?

I'll take a look tomorrow.

As a next step lets modify zmfilter to write The alarm to a file. Let's see if that is late too


General q: does the rest of ZM work fine ? No cpu or memory or camera errors?

Also did you install a package? Which one and version?
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
segordon
Posts: 37
Joined: Tue Aug 11, 2015 10:04 am

Re: zmfilter polling slow.

Post by segordon »

asker wrote:Okay so far:
1. Zmfilter is not crashing
2. It is being invoked every 20s but your filter is executing late

So my suspicion then is either alert filter or the sendmail command.

Can you please post how you've defined your filter?

I'll take a look tomorrow.

As a next step lets modify zmfilter to write The alarm to a file. Let's see if that is late too


General q: does the rest of ZM work fine ? No cpu or memory or camera errors?

Also did you install a package? Which one and version?
Everything else is working fine as far as I can tell. Load is staying below 1 on an old low-end tri-core AMD processor while using modect on two 720p cams @ 10fps, and about 1.3 at 20fps, using libvlc and RTSP. Zoneminder is stable memory wise for a day so far, but haven't tested it long-term yet on this computer.

using iconnor ubuntu PPA at version 1.28.2

Here is a screenshot of the filter in question. I have tried many different settings in the 'limit results' field, just to try something. No dice.

imgur RAu9Jcm

( I sure do wish we could post URLs and attach images! )
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

Still going through the process of elimination here. Let's conclude if the problem is with the action of the filter or the process of identifying filters.

Let's do this:
1) Disable your alertEmail filter
2) Create an executable script in /tmp called eventcatch.sh with just this:

Code: Select all

#!/bin/bash
echo "Event received and logged at `date`"
3) Create a new filter called alertFile and instead of "send an email" put in /tmp/eventcatch.sh as the execute action, make sure its background, make sure it has the same conditions as alertEmail

Then let's see if the event file gets updated every 20 seconds (assuming you have continuous events)

(PS: The forum will allow you to post URLs after you reach a certain number of posts. Forgot how many)
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
Locked