Project

General

Profile

Bug #5459

Something is slow in 4.3

Added by Robin Mitra 12 months ago. Updated 5 months ago.

Status:
Fixed
Priority:
Normal
Assignee:
-
Category:
Descrambling
Target version:
-
Start date:
2019-06-16
Due date:
% Done:

100%

Estimated time:
(Total: 0.00 h)
Found in version:
last few commits since october 2018 -- December 2018, current:4.3-1690~gb3899e3fd
Affected Versions:

Description

I am seeing quite a number of descrambling errors.
It seems there is an issue with mesage sequencing/reordering when talking to oscam.
Here is an excerpt of a debug log when such errors happen:

2018-12-26 13:43:33.102 [ INFO]:subscription: 0055: "epggrab" unsubscribing
2018-12-26 13:43:34.103 [ INFO]:mpegts: 11347V in ASTRA 192 - tuning on DD4
2018-12-26 13:43:36.538 [ DEBUG]:descrambler: no key for service='Fox HD'
2018-12-26 13:43:36.538 [WARNING]:TS: ASTRA 192/12304H/Fox HD: H264 #2559 Continuity counter error (total 458)
2018-12-26 13:43:36.538 [WARNING]:TS: ASTRA 192/12304H/Fox HD: AC3
#2564 Continuity counter error (total 175)
2018-12-26 13:43:36.538 [WARNING]:TS: ASTRA 192/12304H/Fox HD: AC3 @ #2563 Continuity counter error (total 168)
2018-12-26 13:43:37.074 [ INFO]:subscription: 006F: "epggrab" subscribing to mux "11347V", weight: 4, adapter: "DD4", network: "ASTRA 192", service: "Raw PID Subscription"
2018-12-26 13:43:37.580 [ DEBUG]:cwc: 192.168.1.10:33002: Reset after unexpected or no reply for service "Fox HD"
2018-12-26 13:43:37.580 [ DEBUG]:cwc: 192.168.1.10:33002: ECM state INIT
2018-12-26 13:43:37.580 [ DEBUG]:cwc: 192.168.1.10:33002: Insert new ECM (PID 6937) for service "Fox HD"
2018-12-26 13:43:37.580 [ DEBUG]:cwc: 192.168.1.10:33002: Sending ECM (PID 6937) section=0/0 for service "Fox HD" (seqno: 471)
2018-12-26 13:43:37.581 [ DEBUG]:cwc: 192.168.1.10:33002: Sending ECM (PID 6937) section=0/0 for service "Fox HD" (seqno: 472)
2018-12-26 13:43:37.589 [WARNING]:cwc: 192.168.1.10:33002: Got unexpected ECM reply (seqno: 471)
2018-12-26 13:43:37.739 [ DEBUG]:cwc: 192.168.1.10:33002: Saving prefered PID 6937 for newcamd-192.168.1.10:33002-09C4
2018-12-26 13:43:37.739 [ DEBUG]:cwc: 192.168.1.10:33002: Received ECM reply (PID 6937) for service "Fox HD" [0] (seqno: 472 Req delay: 156 ms)
2018-12-26 13:43:37.739 [ DEBUG]:cwc: 192.168.1.10:33002: Obtained DES keys for service "Fox HD" in 156 ms, from newcamd-192.168.1.10:33002-09C4
2018-12-26 13:43:37.739 [ DEBUG]:descrambler: Obtained CSA keys from newcamd-192.168.1.10:33002-09C4 for service "Fox HD"
2018-12-26 13:43:37.739 [ DEBUG]:descrambler: info - service='Fox HD' caid=09C4(NDS) provid=000000 ecmtime=156 hops=1 reader='' from='192.168.1.10:33002' protocol='newcamd'
2018-12-26 13:43:39.065 [ ERROR]:descrambler: cannot decode packets for service "Fox HD"
2018-12-26 13:43:39.069 [ ERROR]:tsfix: transport stream H264, DTS discontinuity. DTS = 88357454, last = 88235054
2018-12-26 13:43:39.086 [ ERROR]:tsfix: transport stream AC3, DTS discontinuity. DTS = 88292880, last = 88148880
2018-12-26 13:43:39.087 [ ERROR]:tsfix: transport stream AC3, DTS discontinuity. DTS = 88294814, last = 88150814
2018-12-26 13:43:42.929 [ DEBUG]:cwc: 192.168.1.10:33002: Sending ECM (PID 6937) section=0/0 for service "Fox HD" (seqno: 473)
2018-12-26 13:43:43.078 [ DEBUG]:cwc: 192.168.1.10:33002: Received ECM reply (PID 6937) for service "Fox HD" [0] (seqno: 473 Req delay: 148 ms)
2018-12-26 13:43:43.078 [ DEBUG]:descrambler: info - service='Fox HD' caid=09C4(NDS) provid=000000 ecmtime=148 hops=1 reader='' from='192.168.1.10:33002' protocol='newcamd'

Please let me know what specific other logs(or traces) I should enable to help with this.
Thx.


Files

tvheadend.zip (1.28 MB) tvheadend.zip Robin Mitra, 2019-01-13 16:17
tvheadend.2019-01-20.log.zip (46.9 KB) tvheadend.2019-01-20.log.zip Robin Mitra, 2019-01-20 13:06

Subtasks

Bug #5659: Descrambler issues in 4.3Fixed

Actions

History

#1

Updated by Jaroslav Kysela 12 months ago

It seems like 'no key' issue. --trace descrambler,cwc : https://tvheadend.org/projects/tvheadend/wiki/Traces

#2

Updated by Robin Mitra 12 months ago

yes, obviously a key was missing/late, but I think the reason for that might be the sequencing error or the maybe the dts discontinuity?
Where do I put the traces, here?(they tend to become large)

#3

Updated by Robin Mitra 12 months ago

actually it is not a sequencing error. its just that two ecms are sent in rapid succession 471,472 and then the response for 471 triggers a 'unexpected..." before getting the response to 472. Imho a pretty typical async sequencing issue.
Also I keep seeing these DTS discontinuities. I don't know if it is a coincidence that this also is logged when I get a descrambling error, or which one of those two errors is causal to the other.

#4

Updated by Jaroslav Kysela 12 months ago

Show traces. The first problem was 'no key': [ DEBUG]:descrambler: no key for service='Fox HD', all other issues depend on this. If you don't have key in time, tvh cannot do much.

The ECM sequencing issue is another thing: from the log - tvh tries to ask for the previous ECM, but there's immediate ECM change, so two ECM requests are sent to the server. First reply (key for the old ECM) is correctly ignored, the newer ECM key is accepted. All is fine in my eyes.

#5

Updated by Robin Mitra 12 months ago

I finally found the time to let tvh run for more than ca. 30mins.
As it turns out, the glitches I have been observing stop after some time. To be precise, they stop, when there is no tuning going on on other tuners.
Explanation:
I have 4 tuners pointed to Hotbird/astra (disecq).
Whenever I start tvh and start watching a stream, the other 3 tuners start doing a eit grabbing. Whenever one of the other three tuners tune to a new mux, chances are, I get discontinuities and subsequent glitches , maybe even descrambling issues. To verify, I started multiple recordings on all 4 tuners. Sure enough upon start of a new recording I almost always got a discontinuity on one or all of the other streams already running. But after that, I had no errors for a long time (until I decided to stop the streams).

To cross check, I waited again for the system to settle down. Started watching one stream, verified that that there no errors. Then I started a network scan, which uses the the other three tuners.
Sure enough, whenever a new mux is tuned to, I get a discontinuity and the one stream that I was watching became unwatchable to the point that the accumulated errors closed the client connection (Kodi).

I have a rather large log of today, where all this happened. It still has cwc/descrambler traces in it, which I think are important.
Is there some drop site you prefer me to put them in?
Maybe change the subject of this issue, I'm pretty sure descrambling is not the cause, since it works if there are no discontinuities.

#6

Updated by Robin Mitra 12 months ago

correction to above:
...
.. traces in it, which I think are NOT important.
...

#7

Updated by Jaroslav Kysela 11 months ago

It seems that you have some issues with your DVB-S equipment/hardware or drivers.

#8

Updated by Robin Mitra 11 months ago

not in the last 5 years or so,
ivy bridge 4-core 1225 on a intel dq77 board with dd cines2 v6 + duoflex s2

This machine has been running without these issues on windows/dvblink, and I believe also in earlier versions of tvheadend (4.0 or 4.1, or 4.2 timeframe, on ubuntu 1404/1604).
I understand that the linux media drivers for digital devices cards are whimsy, but starting with kernel 4.14 they should be ok (apart from the snr/signal strength issues)
Also if I use dddvb-dkms i have the same issues.

I'm not sure when these issues under linux started, maybe when I switched to ubuntu 1804.

I have been trying to ditch windows for tv for quite some time now, but it just doesn't seem to work. Something is always missing.
I guess I'll have to try vdr then (i know my config works there)

#9

Updated by Robin Mitra 11 months ago

I took the time to install a fresh ubuntu 1804 on another disk.
Here I nstalled the released version of tvh 4.2.81...
Unfortunately the the current config from 4.3 was not usable in 4.2, it caused a crash on startup.
So I set up all channels again.

I can confirm that
- the released version of 4.2.81 has none of the problems mentioned here.
- background EIT grabbers using 3 of tuners is a lot faster (I mean a lot, just a few minutes compared to > 1.5h on 4.3)
- while background EIT grabber no glitches whatsoever
- I can even run network scans on 3 tuners in the background while watching a stream on 1 tuner without any glitches.
- Network scan is also a LOT faster than in 4.3

Some change in 4.3 compared to 4.2 has introduced these glitches. Since the configuration backup seems incompatible it difficult to switch back and forth to find out where the change was introduced.

Any ideas?
Should I create a new issue, since this one has a misleading title?

#10

Updated by Jaroslav Kysela 11 months ago

  • Subject changed from Descrambling glitches to Something is slow in 4.3

Try to attach a log with '--trace mpegts,dvbapi,descrambler,cwc,epggrab' for the start which shows the issue (with the minimal count of tuners).

#11

Updated by Robin Mitra 11 months ago

Here's a trace of a few seconds where it happened pretty often.
BTW dvbapi is not recognized as a trace module

#12

Updated by Robin Mitra 11 months ago

Why is the grabber/scanner so slow compared to 4.2.81?
I have only enabled the dvb eit grabber, all others are disabled. I still seem to see some traces of uk_skyview etc..

#13

Updated by Jaroslav Kysela 11 months ago

No idea, pls, provide the log only for one tuner as requested. Add 'tbl-eit' to traces.

#14

Updated by Robin Mitra 11 months ago

Here's a log of a few minutes today with all traces/debugs enabled.
It's 2 tuners. one (DD1) streaming a service to kodi, the other one (DD2) performing a background epg scan.
Continuity errors errors are around
13:10:16,
13:30:55
13:33:12
13:45:00 .. 13:45:53

#16

Updated by Jaroslav Kysela 5 months ago

  • Status changed from New to Fixed

Fixed in #5659 .

Also available in: Atom PDF