Bug #4851

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

Added by Christian Eiden 9 months ago. Updated 18 days 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 9 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 9 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 9 months ago

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

#4 Updated by Michael Kerner 9 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 9 months ago

Same here on two different installations...

#6 Updated by Michael Mutschlechner 9 months ago

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

#7 Updated by Jaroslav Kysela 9 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 9 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 9 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 9 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 9 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 9 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 9 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 7 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 7 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 6 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 6 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 6 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 6 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 6 months ago

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

#21 Updated by Flole Systems 6 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 6 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 6 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)

#24 Updated by Ricardo Rocha about 1 month ago

Any news on this? I am still getting this error... Sometimes a couples of times per day... Really annoying...

#25 Updated by Jarmo Kivirinta about 1 month ago

I'm also suffering with this same issue for quite some time. Sometimes it takes few days, and sometimes only few hours until system freezes.
I've tested this with many different version and currently I'm using 4.3-1312~ge38a877.

Jaroslav, if you would like to examine this in live environment which is suffering from these freezes, I can arrange monitored ssh access for you on to my server.
I'm using TBS 6205 -card and just few days ago I updated kernel and rebuild newest drivers for TBS, without luck. I've also tested this issue with other HW and same results.

#26 Updated by T Turner about 1 month ago

I also have this issue but it happens when watching a channel with poor signal, it has nothing to do with the OTA grabber in my case. At least it doesn't seem to.

It has been happening for about a year and I am always running latest master.

#27 Updated by T Turner about 1 month ago

I turned ATSC OTA Grabber off and it's still happening, here is the log (sorry for the length):

Sep 12 16:14:03 localhost tvheadend24854: TS: ATSC/551.028MHz/WKRG-HD Transport error indicator (total 17512)
Sep 12 16:14:04 localhost tvheadend24854: TS: ATSC/551.028MHz/WKRG-HD: MPEG2VIDEO #49 Continuity counter error (total 9495)
Sep 12 16:14:04 localhost tvheadend[24854]: TS: ATSC/551.028MHz/WKRG-HD: AC3
#53 Continuity counter error (total 818)
Sep 12 16:14:05 localhost tvheadend24854: TS: ATSC/551.028MHz/WKRG-HD: MPEG2VIDEO #49: Invalid start code 54:c3:97
Sep 12 16:14:05 localhost tvheadend[24854]: TS: ATSC/551.028MHz/WKRG-HD: AC3
#53: Invalid start code 6a:28:d3
Sep 12 16:14:05 localhost tvheadend24854: TS: ATSC/551.028MHz/WKRG-HD: AC3 #52 Continuity counter error (total 563)
Sep 12 16:14:05 localhost tvheadend[24854]: tsfix: transport stream MPEG2VIDEO, DTS discontinuity. DTS = 42566156, last = 42413003
Sep 12 16:14:05 localhost tvheadend[24854]: tsfix: transport stream AC3, DTS discontinuity. DTS = 42534720, last = 42350400
Sep 12 16:14:06 localhost tvheadend[24854]: tsfix: transport stream AC3, DTS discontinuity. DTS = 42589619, last = 42356339
Sep 12 16:14:10 localhost tvheadend[24854]: TS: ATSC/551.028MHz/WKRG-HD: AC3
#52: Invalid start code c8:fc:16
Sep 12 16:14:11 localhost tvheadend24854: tsfix: transport stream MPEG2VIDEO, DTS discontinuity. DTS = 43049639, last = 42941531
Sep 12 16:14:12 localhost tvheadend24854: tsfix: transport stream AC3, DTS discontinuity. DTS = 43104960, last = 42888960
Sep 12 16:14:12 localhost tvheadend24854: tsfix: transport stream AC3, DTS discontinuity. DTS = 43119539, last = 42863219
Sep 12 16:14:13 localhost tvheadend24854: TS: ATSC/551.028MHz/WKRG-HD Transport error indicator (total 21224)
Sep 12 16:14:13 localhost tvheadend24854: tsfix: transport stream MPEG2VIDEO, DTS discontinuity. DTS = 43328918, last = 43238828
Sep 12 16:14:14 localhost tvheadend24854: TS: ATSC/551.028MHz/WKRG-HD: MPEG2VIDEO #49 Continuity counter error (total 12524)
Sep 12 16:14:14 localhost tvheadend[24854]: TS: ATSC/551.028MHz/WKRG-HD: AC3
#53 Continuity counter error (total 1011)
Sep 12 16:14:15 localhost tvheadend24854: TS: ATSC/551.028MHz/WKRG-HD: MPEG2VIDEO #49 Corrupted PES header (errors 1258)
Sep 12 16:14:15 localhost tvheadend[24854]: TS: ATSC/551.028MHz/WKRG-HD: AC3
#52 Continuity counter error (total 738)
Sep 12 16:14:15 localhost tvheadend24854: TS: ATSC/551.028MHz/WKRG-HD: AC3 #53: Invalid start code a7:24:da
Sep 12 16:14:17 localhost tvheadend[24854]: tsfix: transport stream MPEG2VIDEO, DTS discontinuity. DTS = 43626215, last = 43419008
Sep 12 16:14:18 localhost tvheadend[24854]: tsfix: transport stream AC3, DTS discontinuity. DTS = 43649280, last = 43205760
Sep 12 16:14:18 localhost tvheadend[24854]: tsfix: transport stream AC3, DTS discontinuity. DTS = 43672499, last = 43185779
Sep 12 16:14:20 localhost tvheadend[24854]: tsfix: transport stream MPEG2VIDEO, DTS discontinuity. DTS = 43911500, last = 43818407
Sep 12 16:14:22 localhost tvheadend[24854]: parser: ATSC/551.028MHz/WKRG-HD: AC3
#53: DTS and PCR diff is very big (510190)
Sep 12 16:14:24 localhost tvheadend24854: parser: ATSC/551.028MHz/WKRG-HD: AC3 #53: DTS and PCR diff is very big (373755310)
Sep 12 16:14:26 localhost tvheadend[24854]: parser: ATSC/551.028MHz/WKRG-HD: AC3
#53: DTS and PCR diff is very big (748572910)
Sep 12 16:14:28 localhost tvheadend24854: parser: ATSC/551.028MHz/WKRG-HD: AC3 #53: DTS and PCR diff is very big (1122998830)
Sep 12 16:14:30 localhost tvheadend[24854]: parser: ATSC/551.028MHz/WKRG-HD: AC3
#53: DTS and PCR diff is very big (1497706990)
Sep 12 16:14:32 localhost tvheadend24854: parser: ATSC/551.028MHz/WKRG-HD: AC3 #53: DTS and PCR diff is very big (1872268270)
Sep 12 16:14:34 localhost tvheadend[24854]: parser: ATSC/551.028MHz/WKRG-HD: AC3
#53: DTS and PCR diff is very big (2246734510)
Sep 12 16:14:53 localhost tvheadend24854: mpegts: too much queued input data (over 50MB) for Auvitek AU8522 QAM/8VSB Frontend #0 : ATSC-T #0, discarding new
Sep 12 16:15:01 localhost CRON25017: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Sep 12 16:15:03 localhost tvheadend24854: mpegts: too much queued input data (over 50MB) for Auvitek AU8522 QAM/8VSB Frontend #0 : ATSC-T #0, discarding new
Sep 12 16:15:08 localhost tvheadend24854: tsfix: transport stream AC3, DTS discontinuity. DTS = 44028928, last = 44565120

#28 Updated by Jaroslav Kysela about 1 month ago

It may be helpful to run tvh through valgrind and/or cclang sanitizer in your environment: https://tvheadend.org/projects/tvheadend/wiki/Debugging#Memory-leaks-or-corruption . Perhaps, I can deduce the problem from the errors reported.

#29 Updated by dave albright 18 days ago

I am having this issue also. it seems to happen when an ota signal that is playing goes bad.
kodi hangs, and sometimes reports server unreachable.
inspect the system log shows multiple " DTS and PCR diff is very big " errors followed by " mpegts: too much queued input data (over 50MB) for LG Electronics LGDT3306A VSB/QAM Frontend #2 : ATSC-T #0, discarding new
"
the only fix is to stop tvheadend service (which can take upwards of 5 minutes) and restart.
if kodi was still in the guide and trying to connect, kodi then hangs and needs a restart.
currently running tvheadend 4.3.1391 on ubuntu 18.04 server with a Hauppauge wintv-quad-hd and latest kodi on raspberry pi.
is there a way to detect these errors and either stop whatever is going on or restart the service?
the logging of errors every 2 seconds, sometimes for hours, is bringing everything to a halt.

#30 Updated by saen acro 18 days ago

Always update to latest then report.

#31 Updated by holli 73 18 days ago

hello,

since the last pull (today) - i can not get tvh working at all - the log is full of:

2018-10-02 23:45:03.144 [WARNING] mpegts: too much queued table input data (over 2MB) for STV090x #04 - cine 6.5, discarding new
2018-10-02 23:45:04.195 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #12 - cine 7, discarding new
2018-10-02 23:45:04.786 [WARNING] mpegts: too much queued table input data (over 2MB) for STV090x #00 - cine 6.5, discarding new
2018-10-02 23:45:04.887 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #11 - cine 7, discarding new
2018-10-02 23:45:05.351 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #08 - cine 7, discarding new
2018-10-02 23:45:05.859 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #07 - cine 7, discarding new
2018-10-02 23:45:06.728 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #13 - cine 7, discarding new
2018-10-02 23:45:06.896 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #09 - cine 7, discarding new
2018-10-02 23:45:07.974 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #06 - cine 7, discarding new
2018-10-02 23:45:08.975 [WARNING] mpegts: too much queued table input data (over 2MB) for STV090x #02 - cine 6.5, discarding new
2018-10-02 23:45:10.066 [WARNING] mpegts: too much queued table input data (over 2MB) for STV090x #01 - cine 6.5, discarding new
2018-10-02 23:45:12.964 [WARNING] mpegts: too much queued table input data (over 2MB) for STV090x #03 - cine 6.5, discarding new
2018-10-02 23:45:13.183 [WARNING] mpegts: too much queued table input data (over 2MB) for STV090x #04 - cine 6.5, discarding new
2018-10-02 23:45:14.186 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #12 - cine 7, discarding new
2018-10-02 23:45:15.272 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #08 - cine 7, discarding new
2018-10-02 23:45:15.282 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #11 - cine 7, discarding new
2018-10-02 23:45:16.064 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #07 - cine 7, discarding new
2018-10-02 23:45:16.416 [WARNING] mpegts: too much queued table input data (over 2MB) for STV090x #00 - cine 6.5, discarding new
2018-10-02 23:45:16.815 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #13 - cine 7, discarding new
2018-10-02 23:45:18.412 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #06 - cine 7, discarding new
2018-10-02 23:45:19.537 [WARNING] mpegts: too much queued table input data (over 2MB) for STV090x #02 - cine 6.5, discarding new
2018-10-02 23:45:20.474 [WARNING] mpegts: too much queued table input data (over 2MB) for STV090x #01 - cine 6.5, discarding new
2018-10-02 23:45:23.004 [WARNING] mpegts: too much queued table input data (over 2MB) for STV090x #03 - cine 6.5, discarding new
2018-10-02 23:45:23.270 [WARNING] mpegts: too much queued table input data (over 2MB) for STV090x #04 - cine 6.5, discarding new
2018-10-02 23:45:24.325 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #12 - cine 7, discarding new

the box has enough memory:

Mem: 31843016 922052 28691740 6540 2229224 30472140
Swap: 32436220 0 32436220

and the cpu level is verry low below 1% and i have an Intel(R) Core(TM) i7-4770 CPU @ 3.40GHz.

i used sudo ./tvheadend/build.linux/tvheadend -u holli -g holli --logfile tvh.error --debug +all --trace +all --satip_bindaddr 192.168.249.11 --satip_rtsp 554 to start and did compile with clang as found here https://tvheadend.org/projects/tvheadend/wiki/Debugging#Memory-leaks-or-corruption

and within the file created i can see:

2018-10-02 23:51:49.408 [  TRACE]:linuxdvb: STV090x #04 - cine 6.5 - checking FE status (ready)
2018-10-02 23:51:49.549 [  TRACE]:mpegts: input STV090x #03 - cine 6.5 got 5264 bytes
2018-10-02 23:51:49.554 [  TRACE]:mpegts: input STV0910 #06 - cine 7 got 5076 bytes
2018-10-02 23:51:49.559 [  TRACE]:mpegts: input STV090x #02 - cine 6.5 got 4888 bytes
2018-10-02 23:51:49.561 [  TRACE]:mpegts: input STV090x #01 - cine 6.5 got 5640 bytes
2018-10-02 23:51:49.564 [  TRACE]:mpegts: input STV0910 #12 - cine 7 got 2444 bytes
2018-10-02 23:51:49.569 [WARNING]:mpegts: too much queued table input data (over 2MB) for STV090x #04 - cine 6.5, discarding new
2018-10-02 23:51:49.569 [  TRACE]:mpegts: table queue pid=0000 (0) cnt 442 len 83096
2018-10-02 23:51:49.570 [  TRACE]:mpegts: table queue pid=0001 (1) cnt 234 len 45684
2018-10-02 23:51:49.570 [  TRACE]:mpegts: table queue pid=0010 (16) cnt 56 len 12032
2018-10-02 23:51:49.570 [  TRACE]:mpegts: table queue pid=0011 (17) cnt 171 len 40608
2018-10-02 23:51:49.570 [  TRACE]:mpegts: table queue pid=0012 (18) cnt 663 len 1916284
2018-10-02 23:51:49.570 [  TRACE]:mpegts: input STV090x #04 - cine 6.5 got 5264 bytes
2018-10-02 23:51:49.570 [  TRACE]:mpegts: input STV090x #00 - cine 6.5 got 4700 bytes
2018-10-02 23:51:49.571 [  TRACE]:mpegts: input STV0910 #13 - cine 7 got 4888 bytes
2018-10-02 23:51:49.573 [  TRACE]:mpegts: input STV0910 #10 - cine 7 got 2820 bytes
2018-10-02 23:51:49.594 [  TRACE]:mpegts: input STV0910 #09 - cine 7 got 6016 bytes
2018-10-02 23:51:49.599 [  TRACE]:mpegts: input STV0910 #08 - cine 7 got 5452 bytes
2018-10-02 23:51:49.613 [  TRACE]:mpegts: input STV090x #05 - cine 6.5 got 4700 bytes
2018-10-02 23:51:49.623 [  TRACE]:linuxdvb: STV090x #04 - cine 6.5 - status 1 (001F)
2018-10-02 23:51:49.624 [  TRACE]:linuxdvb: STV0910 #12 - cine 7 - checking FE status (ready)
2018-10-02 23:51:49.626 [  TRACE]:linuxdvb: STV0910 #12 - cine 7 - status 1 (001F)
2018-10-02 23:51:49.631 [  TRACE]:linuxdvb: STV0910 #10 - cine 7 - checking FE status (ready)
2018-10-02 23:51:49.634 [  TRACE]:linuxdvb: STV0910 #10 - cine 7 - status 1 (001F)
2018-10-02 23:51:49.640 [  TRACE]:linuxdvb: STV0910 #09 - cine 7 - checking FE status (ready)
2018-10-02 23:51:49.642 [  TRACE]:linuxdvb: STV0910 #09 - cine 7 - status 1 (001F)
2018-10-02 23:51:49.646 [  TRACE]:linuxdvb: STV090x #05 - cine 6.5 - checking FE status (ready)
2018-10-02 23:51:49.683 [  TRACE]:mpegts: input STV0910 #07 - cine 7 got 1128 bytes
2018-10-02 23:51:49.683 [  TRACE]:mpegts: input STV0910 #11 - cine 7 got 1128 bytes
2018-10-02 23:51:49.859 [  TRACE]:linuxdvb: STV090x #05 - cine 6.5 - status 1 (001F)
2018-10-02 23:51:49.860 [  TRACE]:linuxdvb: STV0910 #06 - cine 7 - checking FE status (ready)
2018-10-02 23:51:49.861 [  TRACE]:linuxdvb: STV0910 #06 - cine 7 - status 1 (001F)
2018-10-02 23:51:49.866 [  TRACE]:linuxdvb: STV0910 #08 - cine 7 - checking FE status (ready)
2018-10-02 23:51:49.868 [  TRACE]:linuxdvb: STV0910 #08 - cine 7 - status 1 (001F)
2018-10-02 23:51:49.873 [  TRACE]:linuxdvb: STV090x #02 - cine 6.5 - checking FE status (ready)
2018-10-02 23:51:50.087 [  TRACE]:linuxdvb: STV090x #02 - cine 6.5 - status 1 (001F)
2018-10-02 23:51:50.088 [  TRACE]:linuxdvb: STV090x #03 - cine 6.5 - checking FE status (ready)
2018-10-02 23:51:50.299 [  TRACE]:linuxdvb: STV090x #03 - cine 6.5 - status 1 (001F)
2018-10-02 23:51:50.300 [  TRACE]:linuxdvb: STV0910 #07 - cine 7 - checking FE status (ready)
2018-10-02 23:51:50.302 [  TRACE]:linuxdvb: STV0910 #07 - cine 7 - status 1 (001F)
2018-10-02 23:51:50.309 [  TRACE]:linuxdvb: STV090x #00 - cine 6.5 - checking FE status (ready)
2018-10-02 23:51:50.523 [  TRACE]:linuxdvb: STV090x #00 - cine 6.5 - status 1 (001F)
2018-10-02 23:51:50.524 [  TRACE]:linuxdvb: STV0910 #11 - cine 7 - checking FE status (ready)
2018-10-02 23:51:50.526 [  TRACE]:linuxdvb: STV0910 #11 - cine 7 - status 1 (001F)
2018-10-02 23:51:50.531 [  TRACE]:linuxdvb: STV0910 #13 - cine 7 - checking FE status (ready)
2018-10-02 23:51:50.533 [  TRACE]:linuxdvb: STV0910 #13 - cine 7 - status 1 (001F)
2018-10-02 23:51:50.538 [  TRACE]:linuxdvb: STV090x #01 - cine 6.5 - checking FE status (ready)
2018-10-02 23:51:50.554 [  TRACE]:mpegts: input STV090x #00 - cine 6.5 got 4888 bytes
2018-10-02 23:51:50.560 [  TRACE]:mpegts: input STV0910 #09 - cine 7 got 6392 bytes
2018-10-02 23:51:50.561 [  TRACE]:mpegts: input STV0910 #06 - cine 7 got 5640 bytes
2018-10-02 23:51:50.566 [  TRACE]:mpegts: input STV090x #02 - cine 6.5 got 6204 bytes
2018-10-02 23:51:50.576 [  TRACE]:mpegts: input STV090x #04 - cine 6.5 got 5640 bytes
2018-10-02 23:51:50.578 [  TRACE]:mpegts: input STV0910 #13 - cine 7 got 6016 bytes
2018-10-02 23:51:50.583 [  TRACE]:mpegts: input STV0910 #10 - cine 7 got 2256 bytes
2018-10-02 23:51:50.588 [WARNING]:mpegts: too much queued table input data (over 2MB) for STV090x #01 - cine 6.5, discarding new
2018-10-02 23:51:50.589 [  TRACE]:mpegts: table queue pid=0000 (0) cnt 1640 len 308320
2018-10-02 23:51:50.589 [  TRACE]:mpegts: table queue pid=0001 (1) cnt 1658 len 312832
2018-10-02 23:51:50.589 [  TRACE]:mpegts: table queue pid=0010 (16) cnt 1537 len 396492

on startup i get

2018-10-02 23:57:48.282 [   INFO] epggrab: module xmltv created
2018-10-02 23:57:48.305 [   INFO] tbl-eit: module eit - scraper disabled by config
2018-10-02 23:57:48.331 [  ERROR] idnode: log buffer full
2018-10-02 23:57:48.358 [  ERROR] idnode: log buffer full
2018-10-02 23:57:48.381 [   INFO] epgdb: gzip format detected, inflating (ratio 24.7% deflated size 10713270)
2018-10-02 23:57:48.507 [   INFO] epgdb: parsing 43300114 b

maybe the idnode - log buffer full is the problem
how can i clean this?

so why is this problem showing up with the latest pull?
what should / can i do - to figure out the rca?

thanks
holli

#32 Updated by holli 73 18 days ago

hello,

i did not end/abort tvh and it looks like the "over the air epg module" is causing this. (only one enabled).
once this was finished:

2018-10-03 01:02:56.272 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #13 - cine 7, discarding new
2018-10-03 01:02:56.912 [WARNING] epggrab: EIT: EPG Grabber - data completion timeout for 11508.5V in 19.2
2018-10-03 01:02:56.912 [   INFO] subscription: 0050: "epggrab" unsubscribing
2018-10-03 01:02:56.934 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #06 - cine 7, discarding new
2018-10-03 01:02:57.056 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #08 - cine 7, discarding new
2018-10-03 01:02:57.144 [WARNING] epggrab: EIT: EPG Grabber - data completion timeout for 11538V in 19.2
2018-10-03 01:02:57.144 [   INFO] subscription: 0051: "epggrab" unsubscribing
2018-10-03 01:02:57.261 [WARNING] mpegts: too much queued table input data (over 2MB) for STV090x #00 - cine 6.5, discarding new
2018-10-03 01:02:57.377 [WARNING] epggrab: EIT: EPG Grabber - data completion timeout for 11656V in 19.2
2018-10-03 01:02:57.377 [   INFO] subscription: 0052: "epggrab" unsubscribing
2018-10-03 01:02:57.379 [WARNING] epggrab: EIT: EPG Grabber - data completion timeout for 11685.5V in 19.2
2018-10-03 01:02:57.379 [   INFO] subscription: 0053: "epggrab" unsubscribing
2018-10-03 01:02:57.596 [WARNING] epggrab: EIT: EPG Grabber - data completion timeout for 11817V in 19.2
2018-10-03 01:02:57.596 [   INFO] subscription: 0054: "epggrab" unsubscribing
2018-10-03 01:02:57.823 [WARNING] epggrab: EIT: EPG Grabber - data completion timeout for 11856V in 19.2
2018-10-03 01:02:57.823 [   INFO] subscription: 0055: "epggrab" unsubscribing
2018-10-03 01:02:58.036 [WARNING] epggrab: EIT: EPG Grabber - data completion timeout for 11895V in 19.2
2018-10-03 01:02:58.036 [   INFO] subscription: 0056: "epggrab" unsubscribing
2018-10-03 01:02:58.252 [WARNING] epggrab: EIT: EPG Grabber - data completion timeout for 11934V in 19.2
2018-10-03 01:02:58.252 [   INFO] subscription: 0057: "epggrab" unsubscribing
2018-10-03 01:02:58.656 [WARNING] mpegts: too much queued table input data (over 2MB) for STV090x #05 - cine 6.5, discarding new
2018-10-03 01:02:59.316 [WARNING] epggrab: EIT: EPG Grabber - data completion timeout for 12012V in 19.2
2018-10-03 01:02:59.316 [   INFO] subscription: 0058: "epggrab" unsubscribing
2018-10-03 01:02:59.929 [WARNING] mpegts: too much queued table input data (over 2MB) for STV090x #04 - cine 6.5, discarding new
2018-10-03 01:03:00.390 [WARNING] mpegts: too much queued table input data (over 2MB) for STV090x #03 - cine 6.5, discarding new
2018-10-03 01:03:00.402 [WARNING] mpegts: too much queued table input data (over 2MB) for STV090x #02 - cine 6.5, discarding new
2018-10-03 01:03:00.600 [   INFO] mpegts: 12207V in 19.2 - tuning on STV0910 #13 - cine 7
2018-10-03 01:03:00.773 [   INFO] subscription: 0061: "epggrab" subscribing to mux "12207V", weight: 4, adapter: "STV0910 #13 - cine 7", network: "19.2", service: "Raw PID Subscription" 
2018-10-03 01:03:00.774 [   INFO] mpegts: 12246V in 19.2 - tuning on STV0910 #12 - cine 7
2018-10-03 01:03:00.955 [   INFO] subscription: 0062: "epggrab" subscribing to mux "12246V", weight: 4, adapter: "STV0910 #12 - cine 7", network: "19.2", service: "Raw PID Subscription" 
2018-10-03 01:03:00.956 [   INFO] mpegts: 12285V in 19.2 - tuning on STV0910 #11 - cine 7
2018-10-03 01:03:01.129 [   INFO] subscription: 0063: "epggrab" subscribing to mux "12285V", weight: 4, adapter: "STV0910 #11 - cine 7", network: "19.2", service: "Raw PID Subscription" 
2018-10-03 01:03:01.129 [   INFO] mpegts: 12324V in 19.2 - tuning on STV0910 #10 - cine 7
2018-10-03 01:03:01.311 [   INFO] subscription: 0064: "epggrab" subscribing to mux "12324V", weight: 4, adapter: "STV0910 #10 - cine 7", network: "19.2", service: "Raw PID Subscription" 
2018-10-03 01:03:01.311 [   INFO] mpegts: 12402V in 19.2 - tuning on STV0910 #09 - cine 7
2018-10-03 01:03:01.485 [   INFO] subscription: 0065: "epggrab" subscribing to mux "12402V", weight: 4, adapter: "STV0910 #09 - cine 7", network: "19.2", service: "Raw PID Subscription" 
2018-10-03 01:03:01.486 [   INFO] mpegts: 12441V in 19.2 - tuning on STV0910 #08 - cine 7
2018-10-03 01:03:01.668 [   INFO] subscription: 0066: "epggrab" subscribing to mux "12441V", weight: 4, adapter: "STV0910 #08 - cine 7", network: "19.2", service: "Raw PID Subscription" 
2018-10-03 01:03:01.668 [   INFO] mpegts: 12480V in 19.2 - tuning on STV0910 #07 - cine 7
2018-10-03 01:03:01.835 [WARNING] mpegts: too much queued table input data (over 2MB) for STV090x #01 - cine 6.5, discarding new
2018-10-03 01:03:01.840 [   INFO] subscription: 0067: "epggrab" subscribing to mux "12480V", weight: 4, adapter: "STV0910 #07 - cine 7", network: "19.2", service: "Raw PID Subscription" 
2018-10-03 01:03:01.841 [   INFO] mpegts: 12699V in 19.2 - tuning on STV0910 #06 - cine 7
2018-10-03 01:03:02.021 [   INFO] subscription: 0068: "epggrab" subscribing to mux "12699V", weight: 4, adapter: "STV0910 #06 - cine 7", network: "19.2", service: "Raw PID Subscription" 
2018-10-03 01:03:02.021 [   INFO] mpegts: 12728.5V in 19.2 - tuning on STV090x #05 - cine 6.5
2018-10-03 01:03:03.430 [   INFO] subscription: 0069: "epggrab" subscribing to mux "12728.5V", weight: 4, adapter: "STV090x #05 - cine 6.5", network: "19.2", service: "Raw PID Subscription" 
2018-10-03 01:03:04.617 [WARNING] linuxdvb: STV0910 #13 - cine 7 - poll TIMEOUT
2018-10-03 01:03:05.047 [WARNING] epggrab: EIT: EPG Grabber - data completion timeout for 12051V in 19.2
2018-10-03 01:03:05.047 [   INFO] subscription: 005A: "epggrab" unsubscribing
2018-10-03 01:03:05.417 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #09 - cine 7, discarding new
2018-10-03 01:03:05.641 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #12 - cine 7, discarding new
2018-10-03 01:03:05.642 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #11 - cine 7, discarding new
2018-10-03 01:03:05.730 [WARNING] mpegts: too much queued table input data (over 2MB) for STV0910 #07 - cine 7, discarding new
2018-10-03 01:03:06.188 [WARNING] epggrab: EIT: EPG Grabber - data completion timeout for 12090V in 19.2
2018-10-03 01:03:06.188 [   INFO] subscription: 005B: "epggrab" unsubscribing
2018-10-03 01:03:06.719 [WARNING] epggrab: EIT: EPG Grabber - data completion timeout for 12129V in 19.2
2018-10-03 01:03:06.719 [   INFO] subscription: 005C: "epggrab" unsubscribing
2018-10-03 01:03:07.496 [WARNING] epggrab: EIT: EPG Grabber - data completion timeout for 12168V in 19.2
2018-10-03 01:03:07.496 [   INFO] subscription: 005D: "epggrab" unsubscribing
2018-10-03 01:03:10.208 [WARNING] epggrab: EIT: EPG Grabber - data completion timeout for 12168V in 19.2
2018-10-03 01:03:10.208 [   INFO] subscription: 005F: "epggrab" unsubscribing
2018-10-03 01:03:47.419 [   INFO] subscription: 0067: "epggrab" unsubscribing
2018-10-03 01:04:07.461 [   INFO] subscription: 0063: "epggrab" unsubscribing

once this lines showed up - i was able to access the web interface again - so i'm quite sure the issue is related to the over the air epg grabber.

hope this makes sense
holli

Also available in: Atom PDF