Bug #4851

TVH freezes: mpegts: too much queued table input data (over 2MB), discarding new

Added by Christian Eiden 7 months ago. Updated 4 months ago.

Status:NewStart date:2016-09-09
Priority:NormalDue date:
Assignee:-% Done:

100%

Category:-
Target version:-
Found in version:tvheadend_4.3-943~g9b85e7b_amd64 Affected Versions:

Description

After updating to tvheadend_4.3-943~g9b85e7b_amd64, everything seems to be fine. After some time (next day), when the OTA EPG grabber starts, TVH gets stuck, using 100% CPU.

Jan 14 07:15:32 tv systemd[1]: message repeated 23 times: [ Time has been changed]
Jan 14 07:16:35 tv tvheadend[1435]: epgdb: snapshot start
Jan 14 07:16:35 tv tvheadend[1435]: epgdb: queued to save (size 10501373)
Jan 14 07:16:35 tv tvheadend[1435]: epgdb:   brands     0
Jan 14 07:16:35 tv tvheadend[1435]: epgdb:   seasons    0
Jan 14 07:16:35 tv tvheadend[1435]: epgdb:   episodes   17147
Jan 14 07:16:35 tv tvheadend[1435]: epgdb:   broadcasts 16530
Jan 14 07:16:35 tv tvheadend[1435]: epgdb: save start
Jan 14 07:16:35 tv tvheadend[1435]: epgdb: stored (size 1978310)
Jan 14 07:17:01 tv CRON[29539]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jan 14 07:20:18 tv systemd[1]: Time has been changed
....
....
Jan 14 08:04:24 tv tvheadend[1435]: subscription: 0240: "epggrab" unsubscribing
Jan 14 08:04:25 tv tvheadend[1435]: mpegts: 11493.75H in ASTRA - tuning on SAT>IP DVB-S Tuner #4 (10.11.13.18)
Jan 14 08:04:25 tv tvheadend[1435]: subscription: 0246: "epggrab" subscribing to mux "11493.75H", weight: 4, adapter: "SAT>IP DVB-S Tuner #4 (10.11.13.18)", network: "ASTRA", service: "Raw PID Subscription" 
Jan 14 08:04:29 tv tvheadend[1435]: subscription: 023C: "epggrab" unsubscribing
Jan 14 08:04:29 tv tvheadend[1435]: subscription: 0238: "epggrab" unsubscribing
Jan 14 08:04:30 tv tvheadend[1435]: mpegts: 11523.25H in ASTRA - tuning on SAT>IP DVB-S Tuner #8 (10.11.13.18)
Jan 14 08:04:30 tv tvheadend[1435]: subscription: 0248: "epggrab" subscribing to mux "11523.25H", weight: 4, adapter: "SAT>IP DVB-S Tuner #8 (10.11.13.18)", network: "ASTRA", service: "Raw PID Subscription" 
Jan 14 08:04:30 tv tvheadend[1435]: mpegts: 11582.25H in ASTRA - tuning on SAT>IP DVB-S Tuner #6 (10.11.13.18)
Jan 14 08:04:30 tv tvheadend[1435]: subscription: 0249: "epggrab" subscribing to mux "11582.25H", weight: 4, adapter: "SAT>IP DVB-S Tuner #6 (10.11.13.18)", network: "ASTRA", service: "Raw PID Subscription" 
Jan 14 08:04:47 tv tvheadend[1435]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 08:17:01 tv tvheadend[1435]: message repeated 290 times: [ mpegts: too much queued table input data (over 2MB), discarding new]
Jan 14 08:17:02 tv tvheadend[1435]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 09:05:00 tv tvheadend[1435]: message repeated 1141 times: [ mpegts: too much queued table input data (over 2MB), discarding new]

For me, the mpegts: too much queued table input data (over 2MB), discarding new seems to be interesting.

I installed tvheadend-dbg_4.3-943~g9b85e7b_amd64.deb, so that I can provide more information the next time this occurs.

From this version, I'm not able to go back to tvheadend_4.3-907~gfb22b95_amd64 as the configuration has changed and I have no backup of the .hts folder

om_retry_time.patch Magnifier (764 Bytes) Igor Mokrushin, 2018-01-19 23:06

tvheadenddebug.log (3.59 MB) John doe, 2018-04-24 17:52


Subtasks

Bug #3971: Constant "mpegts: too much queued table input data (over ...RejectedAdam Sutton

Bug #4060: mpegts: too much queued table input data (over 2MB), disc...Rejected

Bug #4383: too much queued table input dataRejected

Bug #4584: 100% CPU hang after - mpegts: too much queued table input...Rejected

Bug #4627: mpegts: too much queued table input data (over 2MB), disc...Rejected

Bug #4875: [WARNING] mpegts: too much queued table input data (over ...FixedAdam Sutton

Bug #4915: Ota epg EitRejectedAdam Sutton

Bug #4925: tvheadend crashesRejected

History

#1 Updated by Jaroslav Kysela 7 months ago

It's a side-effect of a bug which eats the CPU. Do you see this always when the OTA grabber is triggered?

#2 Updated by Christian Eiden 7 months ago

No, not always. I changed the schedule of the OTA Grabber, lets see if it makes a difference

#3 Updated by Christian Eiden 7 months ago

I think this can be closed, did not happen again after changing the schedule

#4 Updated by Michael Kerner 7 months ago

I have experienced a similar issue - unresponsive tvheadend services and eventually "mpegts: too much queued table input data (over 2MB), discarding new" errors in the log always after OTA grabber was triggered.

This was in the most recent 4.2 version, though (4.2.5-14~g1665c355c) - and in a docker environment. See https://github.com/linuxserver/docker-tvheadend/issues/68. I am afraid I therefore can't easily provide a full crashlog.

#5 Updated by Michael Mutschlechner 7 months ago

Same here on two different installations...

#6 Updated by Michael Mutschlechner 7 months ago

Disabling all "EPG Grabber Modules" avoids the problem but is not the solution

#7 Updated by Jaroslav Kysela 7 months ago

I wrote this many times, this log means that the input internal data queue is too big, so something eats too much CPU when some part of tvheadend does not work correctly. There might be a bottleneck in the EIT data processing, but my tests does not show it (tried to map 8000 channels in last two days and I cannot hang tvh in this way receiving data from 4 tuners simultaneously). So if anyone brave wants to join me and try to profile this, I welcome any help.

#8 Updated by Igor Mokrushin 7 months ago

New int64_t om_retry_time in structure epggrab_ota_mux causes race condition....
In src/epggrab/otamux.c om_retry_time is not initialized anywhere. If the condition (r! = SM_CODE_NO_ADAPTERS) is not fulfilled, then om->om_retry_time = 0 always!
This condition is almost always satisfied: if (networks_count < ARRAY_SIZE(networks) && om && om->om_retry_time < mclk()) goto next_one;
If set om->om_retry_time > mclk(), then the problem disappears. I made a fix that solves this problem, it's almost like the previous variant...

#9 Updated by Andreas Rheinklang 7 months ago

Hello Igor, thanks for your support.
This bug is driving me crazy, I'm able to reproduce it on several systems, BananaPi, RasPi3, running jessie, stretch... Whatever.
As I'm new to programming Linux/using Github I'm trying to manage applying your patch. I'm able to build the TVH on my RasPi3, checked out the latest git version of the repo from yesterday (4.3-991~g9718e8e). Now I'm struggling to apply your patch, it's a git-newbie-problem which I will try to solve ASAP; copied the patch to my TVH-Build-folder, trying to apply/check it by git apply --check om_retry_time.patch ends up with an error-message:

[email protected]:~/tvh_build/tvheadend $ git apply --check om_retry_time.patch
error: patch failed: src/epggrab/otamux.c:506
error: src/epggrab/otamux.c: patch does not apply

(for info)
[email protected]:~/tvh_build/tvheadend $ ls
Autobuild data lib Makefile.ffmpeg om_retry_time.patch vendor
Autobuild.sh debian LICENSE.md Makefile.hdhomerun README.md
build.linux docs licenses Makefile.static rpm
configure filelist.txt Makefile Makefile.webui src
CONTRIBUTING.md intl Makefile.common man support

Trying to solve it, tried to copy the patch directly to the /src/epggrab folder does not work as well.
Alternative: Maybe you could you send/post the patched otamux.c to speed up my doing?
Thanks again!

#10 Updated by Andreas Rheinklang 7 months ago

OK, after trying to apply the patch on a PC using git/tortoise with no success as well I've managed to apply the changes manually: analyzed the patch file and seen what has to be changed (Init of om->om_retry_time = 0; and changing the smaller-than-sign in comparison line ~612 ). I will recompile and test TVH with your change; Of course I will feedback!

Best regards, Andreas

#11 Updated by Andreas Rheinklang 7 months ago

First feedback: 2 system are running since >24h with that patch applied. Till now now freezing occurred (although I've noticed Bug #4851 but did not implement that patch mentioned there). To increase the probability of appearance I've schedule to to the EPG-Grabber every 2 hours. So first impression is, that that issue might be fixed with Igors solution as well... I'll keep you informed when one TVH crashes again due to the EPG-Grabber.

#12 Updated by Jaroslav Kysela 7 months ago

The patch from Igor is not correct, the fix for the OTA grabber is discussed in bug #4875 (fixed in the git master). I'm keeping this open, because the original report was for another issue (the OTA grabber bug was introduced recently).

#13 Updated by Andreas Rheinklang 7 months ago

Hi Jaroslav,

thanks for your contribution; I had switched to the patched Version comitted by you this morning right before your posting cause it seems to be the official fix. I have 2 systems using that patch running since 8:00h this morning and I will keep you informed, if the locking appears again.

#14 Updated by Paul M 5 months ago

this is still happening in the latest stable release, 4.2.6-1~g7422018~xenial

CPU pegs one core to 100%, web ui locks out, the syslog is flooded with this message:

Mar 31 06:35:50 mcintyre tvheadend[21653]: mpegts: too much queued table input data (over 2MB), discarding new
Mar 31 06:36:43 mcintyre tvheadend[21653]: message repeated 11 times: [ mpegts: too much queued table input data (over 2MB)
, discarding new]

and strace -f -p on the process just presents a fire-hose of an infinite loop spinning:

[pid 22550] <... futex resumed> )       = 0
[pid 21696] <... futex resumed> )       = -1 EAGAIN (Resource temporarily unavailable)
[pid 22550] epoll_wait(47,  <unfinished ...>
[pid 21696] futex(0x55c2ae8c0d00, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 21696] futex(0x55c2ae8c0d2c, FUTEX_WAIT_PRIVATE, 137467, NULL <unfinished ...>
[pid 22554] <... epoll_wait resumed> [{EPOLLIN, {u32=35, u64=35}}], 1, 150) = 1
[pid 22554] read(35, "GK\273\36\0a\361\206\30\317\317\30\370\7\375\0\2\30a\336\36\343d\t\0\0\0000\0\0\257P"..., 175780) = 8
836
[pid 22554] futex(0x55c2ae958c4c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x55c2ae958c48, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
[pid 21694] <... futex resumed> )       = 0
[pid 21694] futex(0x55c2ae958c20, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 22554] futex(0x55c2ae958c20, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 21694] <... futex resumed> )       = -1 EAGAIN (Resource temporarily unavailable)

#15 Updated by Paul M 5 months ago

I upgraded to unstable version, 4.3-1221~g25dfdb6~xenial, and I still see the same problem with CPU pegged out at 100% of a core (running a core2quad Q6600 with 4GB RAM, and a TBS twin tuner dvb-s2 card).

I see the same thing in /var/log/tvheadend.log:

Apr 1 00:13:55 mcintyre tvheadend30310: mpegts: too much queued input data (over 50MB) for TurboSight TBS 6982SE DVB-S/S2 #1 : DVB-S #0, discarding new
Apr 1 00:13:56 mcintyre tvheadend30310: mpegts: too much queued table input data (over 2MB) for TurboSight TBS 6982SE DVB-S/S2 #0 : DVB-S #0, discarding new

and attaching to the process with strace is a firehose.

I'm sure when I built my TVH server just over a month ago that I didn't see this problem as often. Now, the TVH server becomes unusable in a matter of hours :-(

#16 Updated by Joel Maxuel 4 months ago

Same issue here (HTS Tvheadend 4.2.6-1~g7422018, Debian 9.4 amd64).
Have turned the crons off for the grabbers in TVheadend, as my zap2xml cron appears to do import the program list anyway:

#!/bin/bash
/home/hts/zap2xml/zap2xml.pl -C /home/hts/zap2xml/zap2xml.conf
/home/hts/tv_grab_file | socat - UNIX-CONNECT://home/hts/.hts/tvheadend/epggrab/xmltv.sock

...will give it a day to see if the situation improves. If not, unsure what to try next.

#17 Updated by Jaroslav Kysela 4 months ago

I added some time profiling to tvh's code:

Update to recent (v4.3-1233-g4fe0af0e8 +) and add --tprofile argument to your start script (/etc/sysconfig/tvheadend or so). Also, enable '--trace tprof,qprof' traces : https://tvheadend.org/projects/tvheadend/wiki/Traces .

#18 Updated by John doe 4 months ago

Same here on debian 9 with 4.9 kernel and tbs card. I tried tvheadend stable and latest unstable.
What can I do to past log ?

#19 Updated by Jaroslav Kysela 4 months ago

Just gather the log as described in the provided wiki page and upload it here or somewhere public.

#20 Updated by John doe 4 months ago

Tv adapter : card is TBS 6909
Tvheadend became irresponsive when we enable more than one adapter.

#21 Updated by Flole Systems 4 months ago

I am also having this issue from time to time, I am using SAT-IP as a source.

#22 Updated by Jaroslav Kysela 4 months ago

@John doe: It seems like a different bug than this (too much queued data). Please, create another issue and add TRACES for "--trace mpegts,subscription" : https://tvheadend.org/projects/tvheadend/wiki/Traces

#23 Updated by Viktor Kuzmin 4 months ago

I've tried to enable traces and got a crash (start options: -S -l /var/log/tvheadend/tvh.log -D --tprofile --trace tprof,qprof,mpegts,subscription)

2018-05-01 09:55:52.680 [ NOTICE]:START: HTS Tvheadend version 4.3-1252~g595fd174f-dirty started, running as PID:6692 UID:112 GID:27, CWD:/tmp CNF:/etc/tvheadend
2018-05-01 09:55:52.680 [ ALERT]:CRASH: Signal: 11 in PRG: /usr/bin/tvheadend (4.3-1252~g595fd174f-dirty) [7d93245f72d6639e435b6d80b1843550ed15d2c3] CWD: /tmp
2018-05-01 09:55:52.680 [ ALERT]:CRASH: Fault address (nil) (Address not mapped)
2018-05-01 09:55:52.680 [ ALERT]:CRASH: Loaded libraries: linux-vdso.so.1 /usr/lib64/libdvbcsa.so.1 /usr/lib64/libssl.so.1.0.0 /usr/lib64/libcrypto.so.1.0.0 /usr/lib64/libpcre2-8.so.0 /usr/lib64/liburiparser.so.1 /usr/lib64/libavfilter.so.6 /usr/lib64/libavformat.so.57 /usr/lib64/libavcodec.so.57 /usr/lib64/libavutil.so.55 /usr/lib64/libva.so.2 /usr/lib64/libdbus-1.so.3 /lib64/libdl.so.2 /lib64/libpthread.so.0 /lib64/libm.so.6 /lib64/librt.so.1 /lib64/libc.so.6 /lib64/libz.so.1 /usr/lib64/libavresample.so.3 /usr/lib64/libswscale.so.4 /usr/lib64/libpostproc.so.54 /usr/lib64/libswresample.so.2 /usr/lib64/libbs2b.so.0 /usr/lib64/libflite_cmu_us_awb.so.1 /usr/lib64/libflite_cmu_us_kal.so.1 /usr/lib64/libflite_cmu_us_kal16.so.1 /usr/lib64/libflite_cmu_us_rms.so.1 /usr/lib64/libflite_cmu_us_slt.so.1 /usr/lib64/libflite_usenglish.so.1 /usr/lib64/libflite_cmulex.so.1 /usr/lib64/libflite.so.1 /usr/lib64/libbluray.so.2 /lib64/libbz2.so.1 /usr/lib64/libwebp.so.7 /usr/lib64/libxvidcore.so.4 /usr/lib64/libx265.so.151 /usr/lib64/libx264.so.152 /usr/lib64
2018-05-01 09:55:52.680 [ ALERT]:CRASH: Register dump [23]: 0000560a9102d9c000007ffe5cb4a080000000127991a74000000000000000010000560a9102d84020c49ba5e353f7cf00007fb0dd4ca97000000000d693a4000000000000000000000000127991a74000000000000000000000560a9102d84000000000000000000000000000000000000000000000000000007fb0dd4ca8f800007fb0e878ee910000000000010283002b0000000000330000000000000004000000000000000efffffffe7ffbba130000000000000000
2018-05-01 09:55:52.680 [ ALERT]:CRASH: STACKTRACE
2018-05-01 09:55:52.686 [ ALERT]:CRASH: /var/tmp/portage/media-tv/tvheadend-9999/work/tvheadend-9999/src/trap.c:148 0x560a90b6ee7d 0x560a909d4000
2018-05-01 09:55:52.694 [ ALERT]:CRASH: ??:0 0x7fb0e8f4b120 0x7fb0e8f37000
2018-05-01 09:55:52.699 [ ALERT]:CRASH: /var/tmp/portage/media-tv/tvheadend-9999/work/tvheadend-9999/src/udp.c:208 0x7fb0e878ee91 0x7fb0e8629000
2018-05-01 09:55:52.699 [ ALERT]:CRASH: __strdup+0x1e (/lib64/libc.so.6)
2018-05-01 09:55:52.704 [ ALERT]:CRASH: /var/tmp/portage/media-tv/tvheadend-9999/work/tvheadend-9999/src/tprofile.c:75 0x560a90b28f73 0x560a909d4000
2018-05-01 09:55:52.710 [ ALERT]:CRASH: /var/tmp/portage/media-tv/tvheadend-9999/work/tvheadend-9999/src/tprofile.h:86 0x560a90b26d6f 0x560a909d4000
2018-05-01 09:55:52.715 [ ALERT]:CRASH: /var/tmp/portage/media-tv/tvheadend-9999/work/tvheadend-9999/src/wrappers.c:181 0x560a90b32b68 0x560a909d4000
2018-05-01 09:55:52.722 [ ALERT]:CRASH: ??:0 0x7fb0e8f3e8ea 0x7fb0e8f37000
2018-05-01 09:55:52.722 [ ALERT]:CRASH: clone+0x3f (/lib64/libc.so.6)

Also available in: Atom PDF