Random gaps in capture - [Monitor 8 last captured 6 seconds ago, max is 5]

Forum for questions and support relating to the 1.32.x releases only.
Post Reply
dave_88
Posts: 34
Joined: Mon Feb 25, 2019 6:15 pm
Location: Northamptonshire, England UK

Random gaps in capture - [Monitor 8 last captured 6 seconds ago, max is 5]

Post by dave_88 »

Hi All,

Im new to ZM and relatively new to Linux so I hope you'll forgive me if I'm asking a stupid question, I have installed ZM1.32.3 using this guide:

https://wiki.zoneminder.com/Debian_9_64 ... e_Easy_Way

I am running a fresh install of Debian 9 and have now got everything working quite well after a few teething issues such as missing Number::Bytes::Human perl module and missing .htaccess files causing url rewrites not working for the API. That all now works great with zmNinja.

I only seem to have one issue...and not sure whether it's completely normal or if there's something amiss.

I have 8 H264 camera feeds, they are all set to fixed 10 or 15fps with variable bitrate, at varying resolutions from 1MP up to 4MP. They are all on mocord and are recording using ffmpeg with the H264 passthrough option. I have removed the max fps and max alarm fps setting and this solved an issue with smudging. Now the live images are great and so are the recordings. The only problem is that a few times a day I get chunks of the following in the log file...
2019-02-25 16:52:24zmc_m98458WARUnable to receive frame 326686: Resource temporarily unavailable, continuingzm_ffmpeg_camera.cpp900
2019-02-25 15:43:58zmc_m810130WARUnable to receive frame 0: Resource temporarily unavailable, continuingzm_ffmpeg_camera.cpp900
2019-02-25 15:43:56zmdc754ERR'zma -m 8' exited abnormally, exit status 255zmdc.pl
2019-02-25 15:43:56zma_m810132ERRGot empty memory map file size 0, is the zmc process for this monitor running?zm_monitor.cpp538
2019-02-25 15:43:56zmtrigger844ERRMemory map file '/dev/shm/zm.mmap.8' does not exist. zmc might not be running.zmtrigger.pl2019-02-25 15:43:55zmtrigger844ERRMemory map file '/dev/shm/zm.mmap.8' does not exist. zmc might not be running.zmtrigger.pl
2019-02-25 13:44:14zmdc754ERR'zma -m 7' exited abnormally, exit status 255zmdc.pl
2019-02-25 13:44:14zma_m79482ERRGot empty memory map file size 0, is the zmc process for this monitor running?zm_monitor.cpp538
2019-02-25 13:44:14zmtrigger844ERRMemory map file '/dev/shm/zm.mmap.7' does not exist. zmc might not be running.zmtrigger.pl
2019-02-25 13:44:14zmtrigger844ERRMemory map file '/dev/shm/zm.mmap.7' does not exist. zmc might not be running.zmtrigger.pl
2019-02-25 13:44:13zmtrigger844ERRMemory map file '/dev/shm/zm.mmap.7' does not exist. zmc might not be running.zmtrigger.pl
2019-02-25 13:31:07zmc_m57329WARUnable to receive frame 316568: Resource temporarily unavailable, continuingzm_ffmpeg_camera.cpp900
2019-02-25 13:31:07zmc_m57329WARUnable to receive frame 316568: Resource temporarily unavailable, continuingzm_ffmpeg_camera.cpp900
2019-02-25 13:31:07zmc_m57329WARUnable to receive frame 316568: Resource temporarily unavailable, continuingzm_ffmpeg_camera.cpp900
2019-02-25 13:31:07zmc_m57329WARUnable to receive frame 316568: Resource temporarily unavailable, continuingzm_ffmpeg_camera.cpp900
2019-02-25 13:31:07zmc_m57329WARUnable to receive frame 316568: Resource temporarily unavailable, continuingzm_ffmpeg_camera.cpp900
It seems to happen at random usually about five or six times a day and seems to affect a couple of random cameras at a time. When I view the playback I just get a few messed up frames at the time of the errors, occasionally losing a few seconds of video. It's really bugging me and would love to know if this is a common thing...is it caused by the cameras missing frames or perhaps a problem with my setup?

My system load doesn't go above 4%, and shared memory sits at around 25% used. Only been running a few days so HDD storage only at 3% full so far. Network load is only about 2.5Mbps going through Cisco 3560 12 port POE switches with cameras on a dedicated vlan. No bottlenecks on IP network.

I hope I've included enough information for someone to kindly offer me some advice.

Thanks

David
Last edited by dave_88 on Tue Feb 26, 2019 9:37 pm, edited 1 time in total.
dave_88
Posts: 34
Joined: Mon Feb 25, 2019 6:15 pm
Location: Northamptonshire, England UK

Re: Occasional error: Unable to receive frame

Post by dave_88 »

I've been doing some debugging (head hurts now) and this is what I think causes zma to "exit abnormally" and restart...

Code: Select all

26/02/19 20:00:19.589686 zmwatch[4298].DBG [main:127] [Monitor 8 last captured 6 seconds ago, max is 5]
26/02/19 20:00:19.589696 zmwatch[4298].INF [main:130] [Restarting capture daemon for Alley-West, time since last capture 6 seconds (1551211219-1551211213)]
26/02/19 20:00:19.589708 zmwatch[4298].DBG [ZoneMinder::General:67] [Testing valid shell syntax]
26/02/19 20:00:19.640184 zmwatch[4298].DBG [ZoneMinder::General:71] [Running as 'www-data', su commands not needed]
26/02/19 20:00:19.640220 zmwatch[4298].DBG [ZoneMinder::General:144] [Command: /usr/bin/zmdc.pl stop zma -m 8]
The ~6 second gap can be seen in the analysis...

Code: Select all

02/26/19 20:00:13.781416 zma_m8[4273].DB5-zm_zone.cpp/241 [Got 160 alarmed pixels, need 16588 -> 0, avg pixel diff 54]
02/26/19 20:00:13.781424 zma_m8[4273].DB3-zm_monitor.cpp/1399 [After motion detection, last_motion_score(0), new motion score(0)]
02/26/19 20:00:13.781430 zma_m8[4273].DB3-zm_monitor.cpp/1445 [Detected new event at (1551211213.773055)]
02/26/19 20:00:13.781434 zma_m8[4273].DB3-zm_monitor.cpp/1453 [Section length (600) Last Section Mod(13), new section mod(13)]
02/26/19 20:00:20.304008 zma_m8[4273].INF-zm_signal.cpp/40 [Got signal 15 (Terminated), exiting]
02/26/19 20:00:20.304029 zma_m8[4273].INF-zm_monitor.cpp/643 [Alley-West: image_count:16252 - Closing event 6908, shutting down]
02/26/19 20:00:20.304035 zma_m8[4273].DB2-zm_event.cpp/245 [start_time:1551211200.1903 end_time1551211220.304035]
02/26/19 20:00:20.304040 zma_m8[4273].DB1-zm_event.cpp/248 [Adding closing frame 208 to DB]
02/26/19 20:00:20.516669 zma_m8[4273].DB1-zm_event.cpp/256 [Success writing last frame]
02/26/19 20:00:20.642238 zma_m8[4273].DB2-zm_ffmpeg_camera.cpp/637 [CloseFfmpeg called.]
02/26/19 20:00:20.649158 zma_m8[4273].DB1-zm_logger.cpp/255 [Terminating Logger]
And in the capture daemon itself (looks like it just stopped capturing, then got "Signal 15" and restarted)...

Code: Select all

02/26/19 20:00:13.769039 zmc_m8[4260].DB4-zm_ffmpeg_camera.cpp/869 [about to decode video]
02/26/19 20:00:13.772280 zmc_m8[4260].DB4-zm_ffmpeg_camera.cpp/921 [Got frame 16270]
02/26/19 20:00:13.773044 zmc_m8[4260].DB4-zm_monitor.cpp/2400 [Return from Capture (16271)]
02/26/19 20:00:20.596168 zmc_m8[4260].INF-zm_signal.cpp/40 [Got signal 15 (Terminated), exiting]
02/26/19 20:00:20.596214 zmc_m8[4260].DB2-zm_ffmpeg.cpp/462 [/build/zoneminder-1.32.3/src/zm_ffmpeg.cpp:462:DEBUG:  pts: 97631126, dts: 97631126, data: 0x555766a2f300, size: 11328, stream_index: 0, flags: 0000,$
I have it set to record in chunks of 10 minutes and this event happened 20 seconds into a chunk (it happens anywhere), causing it to start recording a new chunk.

This seems to happen completely at random, to any camera (I have various manufacturers). What could cause capture to stop? Does this means it isnt receiving any frames from ffmpeg for those 6 seconds? I did try to put loglevel=debug in the ffmpeg options on the monitor source page, but i get an error in the log saying that it ffmpeg doesnt recognise the loglevel option. Is this because I a using H264 passthrough? If you think the issue is ffmpeg related, how do I debug it?

Any advice would be really appreciated as been on this a few days now and I know its only causing me to loose a few seconds here and there, but in my experience, these things always seem to happen when you really need that few seconds of the recording.

Thanks for reading,

David
User avatar
iconnor
Posts: 2862
Joined: Fri Oct 29, 2010 1:43 am
Location: Toronto
Contact:

Re: Random gaps in capture - [Monitor 8 last captured 6 seconds ago, max is 5]

Post by iconnor »

zmwatch will restart the capture process if it hasn't captured in a certain period of time. You can adjust these periods under options -> System -> WATCH_MAX_DELAY

However, if the capture process is pausing for long periods of time, this is a BIG PROBLEM. It basically means that either your I/O or mysql or both are overloaded. You might want to enable the mysql slow log and watch it.
Also use iotop etc to see what your system is doing.
dave_88
Posts: 34
Joined: Mon Feb 25, 2019 6:15 pm
Location: Northamptonshire, England UK

Re: Random gaps in capture - [Monitor 8 last captured 6 seconds ago, max is 5]

Post by dave_88 »

Hi,

Thanks a lot for the reply...

First thing I have noticed after using iotop -o is the following process using a very high IO percentage all of the time (80% up to 99%): [jbd2/sda2-8]

After a quick Google, this seems to be the file system journaling process. sda2 is the root partition on my "OS" hard drive, so assuming this will be the one that runs the SQL database too.

Is this normal?

I can see the jbd2 process pop up on iotop for my ZM storage raid array (md0) every few seconds, but is very low IO usage and dissappears very quickly.

I will also enable the mysql slow log as you suggested and see what I get. I am running mariadb if this is relevant.

Thanks
dave_88
Posts: 34
Joined: Mon Feb 25, 2019 6:15 pm
Location: Northamptonshire, England UK

Re: Random gaps in capture - [Monitor 8 last captured 6 seconds ago, max is 5]

Post by dave_88 »

Hi,

After around 24hrs, I reviewed the slow query log and there were no events apart from the SLEEP queries I issued to test it was logging OK. I have tried changing the mount options to my root partition to include noatime, to try and reduce writes. My storage RAID0 array that I use solely for ZM storage doesn't seem to be having any issues, could I maybe try moving the ZM database to that and see what difference it makes? Or is this perhaps a bad idea? Just wondering if I maybe have a bad HDD?

Just to add - if I stop ZM/Mysql, the constant high IO usage for jbd2 does go away. Does anyone else have such IO levels for jbd2 showing up on iotop?
dave_88
Posts: 34
Joined: Mon Feb 25, 2019 6:15 pm
Location: Northamptonshire, England UK

Re: Random gaps in capture - [Monitor 8 last captured 6 seconds ago, max is 5]

Post by dave_88 »

Another update....

Moved database to a faster drive... didn't make a great deal of difference, the jbd2 process just moved with it as expected and ran slightly better.

Adding innodb_flush_log_at_trx_commit = 2 to the mariadb config made a huge difference, IO wait on jbd2 is now down to constantly under 40% according to iotop.

One thing I have noticed is the volume of data written to the disk by the mysql process (around 1M/second constantly). It only reads a matter of kilobytes.

Using iotop in accumulated mode shows that in the same amount of time:
-Mysql had written 1987M to disk (although size of actual database folder on disk isn't significantly growing)
-A constant recording of a 4MP camera at 10 fps has only wrote 1233M

Does this sound right that mysql is writing so much data? System load is under 2%, /dev/shm is 43%, DB is 26/151 (not sure what that means!) I have 8 cameras, 7 on mocord, 1 on modect. All on H264 passthrough. Write speed total average around 2.5mbps.

This is iotop running in accumulated mode for something like 40mins, showing total disk writes in descending order...

Code: Select all

Total DISK READ:         0.00 B/s | Total DISK WRITE:         2.55 M/s
Current DISK READ:       0.00 B/s | Current DISK WRITE:     777.72 K/s
  TID  PRIO  USER     DISK READ DISK WRITE>  SWAPIN      IO    COMMAND                                    
 1530 be/4 mysql         0.00 B   1987.40 M  0.00 %  0.15 % mysqld
 1645 be/4 www-data      0.00 B   1233.69 M  0.00 %  0.00 % zmc -m 3
 1688 be/4 www-data      0.00 B    379.61 M  0.00 %  0.00 % zmc -m 8
 1697 be/4 www-data      0.00 B    370.16 M  0.00 %  0.00 % zmc -m 9
 1670 be/4 www-data      0.00 B    362.22 M  0.00 %  0.00 % zmc -m 6
 1653 be/4 www-data      0.00 B    327.79 M  0.00 %  0.00 % zmc -m 4
 1679 be/4 www-data      0.00 B    197.17 M  0.00 %  0.00 % zmc -m 7
 1661 be/4 www-data      0.00 B    104.70 M  0.00 %  0.00 % zmc -m 5
 1637 be/4 www-data      0.00 B     35.62 M  0.00 %  0.00 % zmc -m 1
This is iotop -o showing instantaneous disk write bandwidth in descending order showing mysql top of the list:

Code: Select all

Total DISK READ:         0.00 B/s | Total DISK WRITE:         2.63 M/s
Current DISK READ:       0.00 B/s | Current DISK WRITE:    1296.08 K/s
  TID  PRIO  USER     DISK READ DISK WRITE>  SWAPIN      IO    COMMAND                                    
 1530 be/4 mysql       0.00 B/s 1162.55 K/s  0.00 %  0.16 % mysqld
 1645 be/4 www-data    0.00 B/s  502.72 K/s  0.00 %  0.00 % zmc -m 3
 1653 be/4 www-data    0.00 B/s  251.36 K/s  0.00 %  0.00 % zmc -m 4
 1670 be/4 www-data    0.00 B/s  251.36 K/s  0.00 %  0.00 % zmc -m 6
 1688 be/4 www-data    0.00 B/s  251.36 K/s  0.00 %  0.00 % zmc -m 8
 1697 be/4 www-data    0.00 B/s  251.36 K/s  0.00 %  0.00 % zmc -m 9
 1667 be/4 mysql       0.00 B/s   23.57 K/s  0.00 %  0.00 % mysqld
  302 be/3 root        0.00 B/s    0.00 B/s  0.00 %  3.15 % [jbd2/sda2-8]
  484 be/3 root        0.00 B/s    0.00 B/s  0.00 % 21.69 % [jbd2/md0-8]
 1526 be/4 mysql       0.00 B/s    0.00 B/s  0.00 %  0.06 % mysqld
 1529 be/4 mysql       0.00 B/s    0.00 B/s  0.00 %  1.67 % mysqld
 1537 be/4 mysql       0.00 B/s    0.00 B/s  0.00 %  0.02 % mysqld

So assuming this is why the journalling process (jbd2/md0-8 above) has so much IO wait time if mysql is writing so much data that it must journal?

Any thoughts would be great,

Thanks for reading.
lightguy48
Posts: 101
Joined: Sun Nov 15, 2015 7:19 pm

Re: Random gaps in capture - [Monitor 8 last captured 6 seconds ago, max is 5]

Post by lightguy48 »

I'm curious if you found any solution to this? I have a machine with 16GB of ram and a 500GB SSD and the jbd2/dm-0-8 keeps slamming up at 99% utilization.

I'm running ZM 1.34.x so maybe I need to move this to that forum but it seems to be a common issue.

This is on Ubuntu 20.0.4 LTS server. I can find all sorts of people posting about similar issues on other forums but no solution to the problem.
User avatar
iconnor
Posts: 2862
Joined: Fri Oct 29, 2010 1:43 am
Location: Toronto
Contact:

Re: Random gaps in capture - [Monitor 8 last captured 6 seconds ago, max is 5]

Post by iconnor »

So... yeah this is old but...

mysql writing to disk is likely frame data, frame stats data and/or logs.

ls -l /var/lib/mysql/zm and see which tables are huge. Likely it will be Frames, Stats, Logs.

You can turn off stats in Options->Logging->stats down near the bottom.
You can reduce logging to only warnings...

And you use mysqltuner to mysql
Post Reply