[solved] weird: zaptime extremely fast except when coming from a certain mux
[solved] weird: zaptime extremely fast except when coming from a certain mux
Hi,
First of all many thanks for this absolutely great piece of software.
I'm running tvheadend (version 3.9.2301~ge2bd233) on a CuBox-i4pro under debian jessie (headless, kernel 3.14.14).
The tuner is a PCTV DVB-S2 Stick (461e) (em28178 driver card #92, USB id 2013:0258).
On the frontend side I'm using either VLC or Kodi 14.0 on Mac OS X or openelec on a CuBox-i4pro with the tvheadend pvr addon.
I'm currently only using SD channels and the performance is really nice.
Especially the channel switch time (which was my biggest concern) is absolutely amazing: 1 second, perfectly wife proof 
However, in certain situations the zaptime is around 13-15 seconds.
I've tried to isolate the problem and discovered that it does not depend on the channel being switched to but rather on the channel being switched from.
In order to reduce the issue's environment to the max I've only added the following 4 channels:
ZDF ASTRA 19.2E/11953.5H/ZDF
ARD-alpha ASTRA 19.2E/12265.5H/ARD-alpha
tagesschau24 ASTRA 19.2E/10743.75H/tagesschau24
arte ASTRA 19.2E/10743.75H/arte
Here is the zaptime table between these channels:
Time Source Channel Destination Channel 1s: ZDF ARD-alpha 1s: ZDF arte 1s: ZDF tagesschau24 1s: ARD ZDF 1s: ARD-alpha tagesschau24 1s: ARD-alpha arte 1s: tagesschau24 arte 13s: tagesschau24 ZDF 13s: tagesschau24 ARD-alpha 1s: arte tagesschau24 13s: arte ARD-alpha 13s: arte ZDF
So it turns out that if tvheadend is tuned to the mux 10743.75H all switches to a channel on any other mux are extremely slow.
But it is fast when switching from any channel to any service located on this very mux.
I've ruled out Kodi as it also happens with VLC.
Now it gets even weirder:
If I'm tuned in on a channel on the 10743.75H mux and press stop, wait a second and then switch to a channel on another mux stream starts instantly.
With this manual workaround I can reduce the switch time to under 4 seconds but that's not really what I consider usability.
I'd be deeply grateful for any hints !
Cheers,
Vinz
Replies (2)
RE: weird: zaptime extremely fast except when coming from a certain mux
-
Added by Vinz Focker almost 10 years ago
I'm adding the log output which clearly shows issues:
Here the fast zap operation from "ARD-alpha/12265.5H" to "ZDF/11953.5H":
1 2014-12-31 12:55:38.439 [ DEBUG] service: ZDF si 0x6ac533d0 PCTV DVB-S2 Stick 1 weight 100 prio 0 error 0
2 2014-12-31 12:55:38.452 [ INFO] subscription: 0001: "HTTP" unsubscribing from "ARD-alpha"
3 2014-12-31 12:55:38.452 [ DEBUG] mpegts: 12265.5H in ASTRA 19.2E - close PID 0578 (1400) [2/0x73701690]
4 2014-12-31 12:55:38.452 [ DEBUG] mpegts: 12265.5H in ASTRA 19.2E - close PID 0578 (1400) [1/0x1713d90]
5 2014-12-31 12:55:38.452 [ DEBUG] mpegts: 12265.5H in ASTRA 19.2E - close PID 0579 (1401) [1/0x1713d90]
6 2014-12-31 12:55:38.452 [ DEBUG] mpegts: 12265.5H in ASTRA 19.2E - close PID 057A (1402) [1/0x1713d90]
7 2014-12-31 12:55:38.452 [ DEBUG] mpegts: 12265.5H in ASTRA 19.2E - close PID 057B (1403) [1/0x1713d90]
8 2014-12-31 12:55:38.452 [ DEBUG] mpegts: 12265.5H in ASTRA 19.2E - close PID 057C (1404) [1/0x1713d90]
9 2014-12-31 12:55:38.452 [ DEBUG] mpegts: 12265.5H in ASTRA 19.2E - close PID 057E (1406) [1/0x1713d90]
10 2014-12-31 12:55:38.452 [ DEBUG] mpegts: 12265.5H in ASTRA 19.2E - close PID 057D (1405) [1/0x1713d90]
11 2014-12-31 12:55:38.452 [ DEBUG] mpegts: 12265.5H in ASTRA 19.2E - stopping mux
12 2014-12-31 12:55:38.452 [ DEBUG] linuxdvb: PCTV DVB-S2 Stick 1 - stopping 12265.5H in ASTRA 19.2E
13 2014-12-31 12:55:38.453 [ DEBUG] linuxdvb: PCTV DVB-S2 Stick 1 - stopped dvr thread
14 2014-12-31 12:55:38.498 [ DEBUG] mpegts: 12265.5H in ASTRA 19.2E - close PID 0000 (0) [3/0x1b4a118]
15 2014-12-31 12:55:38.498 [ DEBUG] mpegts: 12265.5H in ASTRA 19.2E - close PID 0001 (1) [2/0x1b4be70]
16 2014-12-31 12:55:38.498 [ DEBUG] mpegts: 12265.5H in ASTRA 19.2E - close PID 0010 (16) [2/0x1b403b0]
17 2014-12-31 12:55:38.498 [ DEBUG] mpegts: 12265.5H in ASTRA 19.2E - close PID 0011 (17) [2/0x1b42be0]
18 2014-12-31 12:55:38.498 [ DEBUG] mpegts: 12265.5H in ASTRA 19.2E - close PID 0011 (17) [3/0x1b417c8]
19 2014-12-31 12:55:38.556 [ DEBUG] service: ZDF si 0x6ac533d0 PCTV DVB-S2 Stick 1 weight 0 prio 0 error 0
20 2014-12-31 12:55:38.556 [ INFO] mpegts: 11953.5H in ASTRA 19.2E - tuning on PCTV DVB-S2 Stick 1
21 2014-12-31 12:55:38.634 [ DEBUG] linuxdvb: PCTV DVB-S2 Stick 1 - starting 11953.5H in ASTRA 19.2E
22 2014-12-31 12:55:38.635 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - started
23 2014-12-31 12:55:38.635 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0064 (100) [1/0x1ace910]
24 2014-12-31 12:55:38.635 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 006E (110) [1/0x1ace910]
25 2014-12-31 12:55:38.635 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0078 (120) [1/0x1ace910]
26 2014-12-31 12:55:38.635 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0079 (121) [1/0x1ace910]
27 2014-12-31 12:55:38.635 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 007A (122) [1/0x1ace910]
28 2014-12-31 12:55:38.635 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 007D (125) [1/0x1ace910]
29 2014-12-31 12:55:38.635 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0082 (130) [1/0x1ace910]
30 2014-12-31 12:55:38.635 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0083 (131) [1/0x1ace910]
31 2014-12-31 12:55:38.635 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0064 (100) [2/0x1b4a118]
32 2014-12-31 12:55:38.636 [ INFO] subscription: 0002: "HTTP" subscribing on "ZDF", weight: 100, adapter: "PCTV DVB-S2 Stick 1", network: "ASTRA 19.2E", mux: "11953.5H", provider: "ZDFvision", service: "ZDF"
33 2014-12-31 12:55:39.146 [ DEBUG] linuxdvb: PCTV DVB-S2 Stick 1 - status GOOD (SIGNAL | CARRIER | VITERBI | SYNC | SIGNAL)
34 2014-12-31 12:55:39.146 [ DEBUG] linuxdvb: PCTV DVB-S2 Stick 1 - locked
35 2014-12-31 12:55:39.146 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0000 (0) [3/0x1b4b530]
36 2014-12-31 12:55:39.147 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0001 (1) [2/0x1b4c948]
37 2014-12-31 12:55:39.148 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0010 (16) [2/0x1b403b0]
38 2014-12-31 12:55:39.148 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0011 (17) [3/0x1b417c8]
39 2014-12-31 12:55:39.148 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0011 (17) [2/0x1b42be0]
40 2014-12-31 12:55:39.156 [ DEBUG] service: ASTRA 19.2E/11953.5H/ZDF: Status changed to [Hardware input]
41 2014-12-31 12:55:39.156 [ DEBUG] service: ASTRA 19.2E/11953.5H/ZDF: Status changed to [Hardware input] [Input on service]
42 2014-12-31 12:55:39.156 [ DEBUG] service: ASTRA 19.2E/11953.5H/ZDF: Status changed to [Hardware input] [Input on service] [Demuxed packets]
43 2014-12-31 12:55:39.180 [ DEBUG] service: ASTRA 19.2E/11953.5H/ZDF: Status changed to [Hardware input] [Input on service] [Demuxed packets] [Reassembled packets]
44 2014-12-31 12:55:39.180 [ DEBUG] webui: Start streaming /stream/channelid/180345686?ticket=7EC86B2E83901FC2A8AC16046742742EB6C190C3&profile=pass
Very nice - 0.7 seconds!
Now when switching from tagesschau24/10743.75H" to "ZDF/11953.5H" I get this:
1 2014-12-31 12:58:40.174 [ DEBUG] service: ZDF si 0x74900fb0 PCTV DVB-S2 Stick 1 weight 100 prio 0 error 0
2 2014-12-31 12:58:40.191 [ INFO] subscription: 0003: "HTTP" unsubscribing from "tagesschau24"
3 2014-12-31 12:58:40.191 [ DEBUG] mpegts: 10743.75H in ASTRA 19.2E - close PID 0064 (100) [2/0x6ac50e88]
4 2014-12-31 12:58:40.192 [ DEBUG] mpegts: 10743.75H in ASTRA 19.2E - close PID 0064 (100) [1/0x1733b30]
5 2014-12-31 12:58:40.192 [ DEBUG] mpegts: 10743.75H in ASTRA 19.2E - close PID 0065 (101) [1/0x1733b30]
6 2014-12-31 12:58:40.192 [ DEBUG] mpegts: 10743.75H in ASTRA 19.2E - close PID 0066 (102) [1/0x1733b30]
7 2014-12-31 12:58:40.192 [ DEBUG] mpegts: 10743.75H in ASTRA 19.2E - close PID 0068 (104) [1/0x1733b30]
8 2014-12-31 12:58:40.192 [ DEBUG] mpegts: 10743.75H in ASTRA 19.2E - stopping mux
9 2014-12-31 12:58:40.192 [ DEBUG] linuxdvb: PCTV DVB-S2 Stick 1 - stopping 10743.75H in ASTRA 19.2E
10 2014-12-31 12:58:40.192 [ DEBUG] linuxdvb: PCTV DVB-S2 Stick 1 - stopped dvr thread
11 2014-12-31 12:58:40.229 [ DEBUG] mpegts: 10743.75H in ASTRA 19.2E - close PID 0000 (0) [3/0x1b4a118]
12 2014-12-31 12:58:40.229 [ DEBUG] mpegts: 10743.75H in ASTRA 19.2E - close PID 0001 (1) [2/0x1b4b530]
13 2014-12-31 12:58:40.229 [ DEBUG] mpegts: 10743.75H in ASTRA 19.2E - close PID 0010 (16) [2/0x1b4c948]
14 2014-12-31 12:58:40.230 [ DEBUG] mpegts: 10743.75H in ASTRA 19.2E - close PID 0011 (17) [2/0x1b417c8]
15 2014-12-31 12:58:40.230 [ DEBUG] mpegts: 10743.75H in ASTRA 19.2E - close PID 0011 (17) [3/0x1b403b0]
16 2014-12-31 12:58:40.295 [ DEBUG] service: ZDF si 0x74900fb0 PCTV DVB-S2 Stick 1 weight 0 prio 0 error 0
17 2014-12-31 12:58:40.295 [ INFO] mpegts: 11953.5H in ASTRA 19.2E - tuning on PCTV DVB-S2 Stick 1
18 2014-12-31 12:58:40.377 [ DEBUG] linuxdvb: PCTV DVB-S2 Stick 1 - starting 11953.5H in ASTRA 19.2E
19 2014-12-31 12:58:40.378 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - started
20 2014-12-31 12:58:40.378 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0064 (100) [1/0x1ace910]
21 2014-12-31 12:58:40.378 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 006E (110) [1/0x1ace910]
22 2014-12-31 12:58:40.378 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0078 (120) [1/0x1ace910]
23 2014-12-31 12:58:40.378 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0079 (121) [1/0x1ace910]
24 2014-12-31 12:58:40.378 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 007A (122) [1/0x1ace910]
25 2014-12-31 12:58:40.378 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 007D (125) [1/0x1ace910]
26 2014-12-31 12:58:40.378 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0082 (130) [1/0x1ace910]
27 2014-12-31 12:58:40.378 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0083 (131) [1/0x1ace910]
28 2014-12-31 12:58:40.378 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0064 (100) [2/0x1b4a118]
29 2014-12-31 12:58:40.378 [ INFO] subscription: 0004: "HTTP" subscribing on "ZDF", weight: 100, adapter: "PCTV DVB-S2 Stick 1", network: "ASTRA 19.2E", mux: "11953.5H", provider: "ZDFvision", service: "ZDF"
>>> 30 2014-12-31 12:58:50.000 [ DEBUG] service: ASTRA 19.2E/11953.5H/ZDF: Status changed to [Graceperiod expired] [Data timeout]
After 10 seconds the grace period timer triggered and tvheadend seems to close/reset/reopen the mux ...
31 2014-12-31 12:58:52.000 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - close PID 0064 (100) [2/0x1b4a118]
32 2014-12-31 12:58:52.000 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - close PID 0064 (100) [1/0x1ace910]
33 2014-12-31 12:58:52.000 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - close PID 006E (110) [1/0x1ace910]
34 2014-12-31 12:58:52.000 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - close PID 0078 (120) [1/0x1ace910]
35 2014-12-31 12:58:52.000 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - close PID 0079 (121) [1/0x1ace910]
36 2014-12-31 12:58:52.000 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - close PID 007A (122) [1/0x1ace910]
37 2014-12-31 12:58:52.000 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - close PID 007D (125) [1/0x1ace910]
38 2014-12-31 12:58:52.000 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - close PID 0082 (130) [1/0x1ace910]
39 2014-12-31 12:58:52.000 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - close PID 0083 (131) [1/0x1ace910]
40 2014-12-31 12:58:52.000 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - stopping mux
41 2014-12-31 12:58:52.000 [ DEBUG] linuxdvb: PCTV DVB-S2 Stick 1 - stopping 11953.5H in ASTRA 19.2E
42 2014-12-31 12:58:52.048 [ DEBUG] service: ZDF si 0x74900fb0 PCTV DVB-S2 Stick 1 weight 0 prio 0 error 402
43 2014-12-31 12:58:54.000 [ DEBUG] service: ZDF si 0x74900fb0 PCTV DVB-S2 Stick 1 weight 0 prio 0 error 402
44 2014-12-31 12:58:56.000 [ DEBUG] service: ZDF si 0x74900fb0 PCTV DVB-S2 Stick 1 weight 0 prio 0 error 402
45 2014-12-31 12:58:56.000 [WARNING] webui: Couldn't start streaming /stream/channelid/180345686?ticket=xxxxxxxx&profile=pass, No input detected
46 2014-12-31 12:58:56.000 [ NOTICE] subscription: 0004: No input source available for subscription "HTTP" to channel "ZDF"
47 2014-12-31 12:58:56.000 [ INFO] subscription: 0004: "HTTP" unsubscribing from "ZDF"
48 2014-12-31 12:58:56.002 [ DEBUG] service: ZDF si 0x74901468 PCTV DVB-S2 Stick 1 weight 0 prio 0 error 0
... and tries again and succeeds this time:
49 2014-12-31 12:58:56.002 [ INFO] mpegts: 11953.5H in ASTRA 19.2E - tuning on PCTV DVB-S2 Stick 1
50 2014-12-31 12:58:56.105 [ DEBUG] linuxdvb: PCTV DVB-S2 Stick 1 - starting 11953.5H in ASTRA 19.2E
51 2014-12-31 12:58:56.105 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - started
52 2014-12-31 12:58:56.106 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0064 (100) [1/0x1ace910]
53 2014-12-31 12:58:56.106 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 006E (110) [1/0x1ace910]
54 2014-12-31 12:58:56.106 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0078 (120) [1/0x1ace910]
55 2014-12-31 12:58:56.106 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0079 (121) [1/0x1ace910]
56 2014-12-31 12:58:56.106 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 007A (122) [1/0x1ace910]
57 2014-12-31 12:58:56.106 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 007D (125) [1/0x1ace910]
58 2014-12-31 12:58:56.106 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0082 (130) [1/0x1ace910]
59 2014-12-31 12:58:56.106 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0083 (131) [1/0x1ace910]
60 2014-12-31 12:58:56.106 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0064 (100) [2/0x74901df8]
61 2014-12-31 12:58:56.106 [ INFO] subscription: 0005: "HTTP" subscribing on "ZDF", weight: 100, adapter: "PCTV DVB-S2 Stick 1", network: "ASTRA 19.2E", mux: "11953.5H", provider: "ZDFvision", service: "ZDF"
62 2014-12-31 12:58:56.591 [ DEBUG] linuxdvb: PCTV DVB-S2 Stick 1 - status GOOD (SIGNAL | CARRIER | VITERBI | SYNC | SIGNAL)
63 2014-12-31 12:58:56.591 [ DEBUG] linuxdvb: PCTV DVB-S2 Stick 1 - locked
64 2014-12-31 12:58:56.591 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0000 (0) [3/0x1b4a118]
65 2014-12-31 12:58:56.592 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0001 (1) [2/0x1b4b530]
66 2014-12-31 12:58:56.592 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0010 (16) [2/0x1b4c948]
67 2014-12-31 12:58:56.593 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0011 (17) [3/0x1b403b0]
68 2014-12-31 12:58:56.593 [ DEBUG] mpegts: 11953.5H in ASTRA 19.2E - open PID 0011 (17) [2/0x1b417c8]
69 2014-12-31 12:58:56.601 [ DEBUG] service: ASTRA 19.2E/11953.5H/ZDF: Status changed to [Hardware input]
70 2014-12-31 12:58:56.601 [ DEBUG] service: ASTRA 19.2E/11953.5H/ZDF: Status changed to [Hardware input] [Input on service]
71 2014-12-31 12:58:56.601 [ DEBUG] service: ASTRA 19.2E/11953.5H/ZDF: Status changed to [Hardware input] [Input on service] [Demuxed packets]
72 2014-12-31 12:58:56.633 [ DEBUG] service: ASTRA 19.2E/11953.5H/ZDF: Status changed to [Hardware input] [Input on service] [Demuxed packets] [Reassembled packets]
73 2014-12-31 12:58:56.633 [ DEBUG] webui: Start streaming /stream/channelid/180345686?ticket=xxxxxxxx&profile=pass
There are no other clients and I can reproduce this 100% all the times when switching from any channel on 10743.75H to any other channel on a different mux.
I really hope someone can shed a light on this ...
RE: [solved] weird: zaptime extremely fast except when coming from a certain mux
-
Added by Vinz Focker almost 10 years ago
It turned out that this was caused by a driver bug.
I've looked at the git log of the involved driver files in the upstream kernel and found a very promising commit message here:
https://github.com/torvalds/linux/commit/418a97cbcef9644e36d87140a6962d2cd4743e74
[media] m88ds3103: fix bug on .set_tone()
Band switching didn't worked always reliably as there was one
register bit set wrong.
Thanks to Robert Schlabbach for pointing this bug and solution.
I've cherry-picked this commit in my cloned linaro-stable-mx6 3.14 kernel source and voila all issues gone.