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

Re: zmfilter polling slow.

Post by segordon »

same behavior, everything getting processed in batches. Forced two alarms at 6:34:08 and 6:35:02, neither were processed until 6:38:41.

Here is a snippet from the weblog, the first two event hits were existing when I first created the filter, the second two are the ones that are part of the manual alarm scenario. I included them to show the duration, 5 minutes + 20 s. The 20s is getting added in there somewhere alongside that weird 5 minute tick.

Code: Select all

2015-08-12 06:38:41.852360	zmfilter	6506	INF	Executing '/tmp/eventcatch.sh /usr/share/zoneminder/events/1/15/08/12/06/35/02'	zmfilter.pl	
2015-08-12 06:38:41.740040	zmfilter	6506	INF	Executing '/tmp/eventcatch.sh /usr/share/zoneminder/events/1/15/08/12/06/34/08'	zmfilter.pl	
2015-08-12 06:33:21.545560	zmfilter	6506	INF	Executing '/tmp/eventcatch.sh /usr/share/zoneminder/events/1/15/08/12/06/01/15'	zmfilter.pl	
2015-08-12 06:33:21.439570	zmfilter	6506	INF	Executing '/tmp/eventcatch.sh /usr/share/zoneminder/events/2/15/08/12/05/59/57'   zmfilter.pl 
and the debug info with echoed output that corresponds to the same bulk processing.. event on this one was at 6:51:12, event filter was hit at 6:55:36 with corresponding eventcatch.sh output

pastebin wsCS1fjz (too spammy!)
Last edited by segordon on Wed Aug 12, 2015 1:58 pm, edited 1 time in total.
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

Okay, lets see if its a caching issue. Make a backup of zmfilter.pl, then replace all occurrences of "prepare_cached" with "prepare" and run again. Does that help?
segordon wrote:same behavior, everything getting processed in batches. Forced two alarms at 6:34:08 and 6:35:02, neither were processed until 6:38:41.

Here is a snippet from the weblog, the first two event hits were existing when I first created the filter, the second two are the ones that are part of the manual alarm scenario. I included them to show the duration, 5 minutes + 20 s. The 20s is getting added in there somewhere alongside that weird 5 minute tick.

Code: Select all

2015-08-12 06:38:41.852360	zmfilter	6506	INF	Executing '/tmp/eventcatch.sh /usr/share/zoneminder/events/1/15/08/12/06/35/02'	zmfilter.pl	
2015-08-12 06:38:41.740040	zmfilter	6506	INF	Executing '/tmp/eventcatch.sh /usr/share/zoneminder/events/1/15/08/12/06/34/08'	zmfilter.pl	
2015-08-12 06:33:21.545560	zmfilter	6506	INF	Executing '/tmp/eventcatch.sh /usr/share/zoneminder/events/1/15/08/12/06/01/15'	zmfilter.pl	
2015-08-12 06:33:21.439570	zmfilter	6506	INF	Executing '/tmp/eventcatch.sh /usr/share/zoneminder/events/2/15/08/12/05/59/57'   zmfilter.pl 
getting debug info, will edit post when I see something more interesting than 'Sleeping for 20 seconds'
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, lets see if its a caching issue. Make a backup of zmfilter.pl, then replace all occurrences of "prepare_cached" with "prepare" and run again. Does that help?
segordon wrote:same behavior, everything getting processed in batches. Forced two alarms at 6:34:08 and 6:35:02, neither were processed until 6:38:41.

Here is a snippet from the weblog, the first two event hits were existing when I first created the filter, the second two are the ones that are part of the manual alarm scenario. I included them to show the duration, 5 minutes + 20 s. The 20s is getting added in there somewhere alongside that weird 5 minute tick.

Code: Select all

2015-08-12 06:38:41.852360	zmfilter	6506	INF	Executing '/tmp/eventcatch.sh /usr/share/zoneminder/events/1/15/08/12/06/35/02'	zmfilter.pl	
2015-08-12 06:38:41.740040	zmfilter	6506	INF	Executing '/tmp/eventcatch.sh /usr/share/zoneminder/events/1/15/08/12/06/34/08'	zmfilter.pl	
2015-08-12 06:33:21.545560	zmfilter	6506	INF	Executing '/tmp/eventcatch.sh /usr/share/zoneminder/events/1/15/08/12/06/01/15'	zmfilter.pl	
2015-08-12 06:33:21.439570	zmfilter	6506	INF	Executing '/tmp/eventcatch.sh /usr/share/zoneminder/events/2/15/08/12/05/59/57'   zmfilter.pl 
getting debug info, will edit post when I see something more interesting than 'Sleeping for 20 seconds'

Same behavior. DBG log is showing a filter check along with a 20s sleep.

pastebin AjwqEa6G
event time: 7:03:47
event filter hit: 7:08:32

Should I restore the original zmfilter?
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

Yes, you can restore.

I'm running out of ideas but one more thing to check that ic0n suggested - lets see how long it takes for your event query DB to run:

Can you log into mysql DB and execute this

Code: Select all

SELECT E.Id,
                          E.MonitorId,
                          M.Name as MonitorName,
                          M.DefaultRate,
                          M.DefaultScale,
                          E.Name,
                          E.Cause,
                          E.Notes,
                          E.StartTime,
                          unix_timestamp(E.StartTime) as Time,
                          E.Length,
                          E.Frames,
                          E.AlarmFrames,
                          E.TotScore,
                          E.AvgScore,
                          E.MaxScore,
                          E.Archived,
                          E.Videoed,
                          E.Uploaded,
                          E.Emailed,
                          E.Messaged,
                          E.Executed
                   FROM Events as E
                   INNER JOIN Monitors as M on M.Id = E.MonitorId;
And tell us how long that takes?
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 »

Sure

Code: Select all

sudo mysql zm --password < test.sql  0.01s user 0.00s system 0% cpu 2.261 total
Practically instant. the huge wait was me typing my password ;)

(out to lunch, replies may be a bit slow for a bit)
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

Was that showing it executed in 0.01s ?

In that case I am currently officially out of ideas :-D
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 »

Okay, I have a theory on this:

The only reason I can think of this is happening is that this line https://github.com/ZoneMinder/ZoneMinde ... pl.in#L638 is returning null till a "filter reload" happens (which is around that 5 min timeline)

This could be three things:
a) DB connection is not working as it should (and not posting an error)
b) the SQL query is mangled
c) Events are not being written into the DB immediately (but a few mins is way too long)

Can you try this: Add the following info log just above this line https://github.com/ZoneMinder/ZoneMinde ... pl.in#L629
Info ("Executing SQL: ".$sql);
Lets see what it prints every 20s


And while we are at it, lets also get out of the way any doubt that the DB is writing late. Please run this script in a separate terminal and see when Event count changes relative to events being added (please replace XXXX and YYYY with your auth)

Code: Select all

#!/bin/bash
oldevtcount=""
while :
do
        evtcount=`mysql -N -uXXXX -pYYYYY zm -e "select count(*) from Events;"`
        if [ "$oldevtcount" != "$evtcount" ] ; then
                echo Event count changed to $evtcount at `date`
                oldevtcount=$evtcount;
        fi
        sleep 1;
done
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 »

Two things :

After info line insertion, zmfilter is failing..

Code: Select all

2015-08-12 12:42:49.427750	zmdc	22138	ERR	'zmfilter.pl ' exited abnormally, exit status 9	zmdc.pl
I think it may be caused by the extraneous space between Info and the parenthesis; but I don't know enough about perl to know if it is white space tolerant, going to try removing it and seeing if zmfilter becomes stable again real fast.

edit: nope, that's not the issue. still crashing.


However, the event count is changing instantly with the manual alarms according to the script.
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

Okay, that eliminates late DB writes.

What remains is
a) zmfilter db handle is going stale without generating errors and magically recovering
b) the sql command is getting mangled

That Info command was to check b.
You might want to check where you changed it. That Info should not cause a crash unless you placed it in a different place. Do this, please post your current zmfilter.pl to gist.github.com, I'll modify it and you can update your copy

BTW, a parallel thought. Try this: change FILTER_RELOAD_DELAY (or whatever that variable is called in ZM Web Console) to say 60s instead of 300s and restart ZM. See if your batch is processing approximately 1 minute late now instead of 3-5


segordon wrote:Two things :

After info line insertion, zmfilter is failing..

Code: Select all

2015-08-12 12:42:49.427750	zmdc	22138	ERR	'zmfilter.pl ' exited abnormally, exit status 9	zmdc.pl
I think it may be caused by the extraneous space between Info and the parenthesis; but I don't know enough about perl to know if it is white space tolerant, going to try removing it and seeing if zmfilter becomes stable again real fast.

edit: nope, that's not the issue. still crashing.


However, the event count is changing instantly with the manual alarms according to the script.
Last edited by asker on Wed Aug 12, 2015 8:15 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 »

Sure, that's easy.

gist github com segordon 05f12db6dad483fca114
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

segordon wrote:Sure, that's easy.

gist github com segordon 05f12db6dad483fca114
This is a non-crashing copy of zmfilter.pl correct?
Also, please take a look at the other suggestion in parallel (in my post above)
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:
segordon wrote:Sure, that's easy.

gist github com segordon 05f12db6dad483fca114
This is a non-crashing copy of zmfilter.pl correct?
Correct.

I also changed the filter reload delay.

Event occured at : 13:20:50, filter hit it at 13:25:16

Code: Select all

2015-08-12 13:25:16.504460	zmfilter	6983	INF	Executing '/tmp/eventcatch.sh /usr/share/zoneminder/events/1/15/08/12/13/20/50'	zmfilter.pl
Last edited by segordon on Wed Aug 12, 2015 8:31 pm, edited 1 time in total.
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

Here is the modified zmfilter.pl --> please keep a backup of the original, replace with this one, restart ZM

https://gist.github.com/pliablepixels/5 ... f595cbd9d7

It adds 2 things:
a) Adds a log of the query
b) Forcibly reconnects to DB every 20 seconds (not a good idea, but lets go with this for now)
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 »

Seems to have sped things up, looks like the test script is getting hit within the minute now. I am going to reduce the filter interval back to 300.

Here's the log.

gist github com segordon 7865cc0dd9db25023b62

The test event was at 13:34:05

edit: looks like its firing around 3 minutes now..

gist github com segordon d9ac614e7ad63542b8b1
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmfilter polling slow.

Post by asker »

So I'm confused - where are we now?
The "PP - Force closing DB just to test" log should occur every 20 seconds. Your latest log seems to show it recurring in minutes. You might have changed the wrong variable.

Please make sure:
FILTER_RELOAD_DELAY = 300
FILTER_EXECUTE_INTERVAL = 20

and restart ZM

If just force closing the DB every 20 seconds is not solving your problem, but reducing FILTER_RELOAD_DELAY is working, then that points to some data structure corruption within zmfilter as opposed to a DB handle state. Either way, I'd think we have a bug in zmfilter.pl - I'll have to understand what it is doing in getFilter - seems to be rebuilding the filter array. But I'll wait for you to confirm for sure

I may not be able to get to this till tomorrow though (I am on ET). Till then please post your analysis with complete logs
Last edited by asker on Wed Aug 12, 2015 8:58 pm, edited 2 times 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
Locked