[hmilz]

Hi,

I recently changed the receivers of my VDR from two TeVii S660's to a Digital Devices Cine S2 + Duoflex card. Everything else remained unchanged on the VDR side of things. Since then, I encounter frequent (as in, once per day approx.) buffer overruns and resync probs. As it seems from the thread IDs, the VNSI buffer thread seems to cause the problem.

Software versions:
- Ubuntu 14.04.3 LTS with Wily kernel (4.2.0-latest)
- vdr-2.0.3 (ubuntu)
- vnsiserver-latest from git (from about an hour ago)
- Kodi 6.0 as in Openelec-current on RPi2
- dddvb driver 0.9.21 or 0.9.22 from Digital Devices git (current).

As shown by the kernel log, the DD card is initialized just fine:

Code:

[   14.704506] dvb_core: module verification failed: signature and/or required key missing - tainting kernel
[   14.744728] Digital Devices PCIE bridge driver 0.9.21, Copyright (C) 2010-15 Digital Devices GmbH
[   14.744921] DDBridge driver detected: Digital Devices Cine S2 V6.5 DVB adapter
[   14.744938] DDBridge: HW 0001000d REGMAP 00010004
[   14.744972] DDBridge: using 1 MSI interrupt(s)
[   14.746272] Port 0: Link 0, Link Port 0 (TAB 1): DUAL DVB-S2
[   14.858090] Port 1: Link 0, Link Port 1 (TAB 2): DUAL DVB-S2
[   14.859048] Port 2: Link 0, Link Port 2 (TAB 3): NO MODULE
[   14.860003] Port 3: Link 0, Link Port 3 (TAB 4): NO MODULE
[   14.861739] 0 netstream channels
[   14.861742] DVB: registering new adapter (DDBridge)
[   14.861744] DVB: registering new adapter (DDBridge)
[   14.861745] DVB: registering new adapter (DDBridge)
[   14.861746] DVB: registering new adapter (DDBridge)
...
[   15.407636] LNBx2x attached on addr=a
[   15.436794] stv6110x_attach: Attaching STV6110x
[   15.436799] attach tuner input 0 adr 60
[   15.436871] ddbridge 0000:05:00.0: DVB: registering adapter 0 frontend 0 (STV090x Multistandard)...
...
[   15.472168] LNBx2x attached on addr=8
[   15.472174] stv6110x_attach: Attaching STV6110x
[   15.472176] attach tuner input 1 adr 63
[   15.472256] ddbridge 0000:05:00.0: DVB: registering adapter 1 frontend 0 (STV090x Multistandard)...
...
[   15.491106] LNB25 on 0c
[   15.640527] ddbridge 0000:05:00.0: DVB: registering adapter 2 frontend 0 (STV0910)...
[   15.642001] LNB25 on 0d
[   15.645682] ddbridge 0000:05:00.0: DVB: registering adapter 3 frontend 0 (STV0910)...

When running, after a while these error messages can be seen:

Code:

Jan 23 11:15:46 seneca vdr: [7888] VNSI: Successfully switched to channel 14 - KiKA HD
Jan 23 11:15:46 seneca vdr: [7888] VNSI: Started streaming of channel KiKA HD (timeout 10 seconds)
Jan 23 11:15:46 seneca vdr: [7891] cLiveStreamer stream processor thread started (pid=2593, tid=7891, prio=high)
Jan 23 11:15:46 seneca vdr: [7892] TS buffer on device 2 thread started (pid=2593, tid=7892, prio=high)
Jan 23 11:15:46 seneca vdr: [7890] VNSI: VideoInput: no pat/pmt within timeout, falling back to channel pids
Jan 23 11:15:46 seneca vdr: [7890] VNSI: Video Input - new pmt, attaching receiver
Jan 23 11:15:47 seneca vdr: [7891] VNSI: Created stream for pid=6610 and type=8
Jan 23 11:15:47 seneca vdr: [7891] VNSI: Created stream for pid=6622 and type=1
Jan 23 11:15:47 seneca vdr: [7891] VNSI: Created stream for pid=6620 and type=2
Jan 23 11:15:47 seneca vdr: [7891] VNSI: Created stream for pid=6621 and type=2
Jan 23 11:15:47 seneca vdr: [7891] VNSI: Created stream for pid=6631 and type=9
Jan 23 11:15:47 seneca vdr: [7891] VNSI: Created stream for pid=6630 and type=11
Jan 23 11:15:47 seneca vdr: [2593] connect from 192.168.20.26, port 41887 - accepted
Jan 23 11:15:49 seneca vdr: [7892] i/o throttle activated, count = 1 (tid=7892)
Jan 23 11:15:50 seneca vdr: [7892] buffer usage: 70% (tid=7889)
Jan 23 11:15:50 seneca vdr: [7892] buffer usage: 80% (tid=7889)
Jan 23 11:15:50 seneca vdr: [7892] buffer usage: 60% (tid=7889)
Jan 23 11:15:50 seneca vdr: [2746] VNSI: Timers state changed (13)
Jan 23 11:15:50 seneca vdr: [2746] VNSI: Requesting clients to reload timers
Jan 23 11:15:51 seneca vdr: [2593] connect from 192.168.20.26, port 41888 - accepted
Jan 23 11:15:52 seneca vdr: [7892] buffer usage: 70% (tid=7889)
Jan 23 11:15:52 seneca vdr: [7892] buffer usage: 80% (tid=7889)
Jan 23 11:15:52 seneca vdr: [7892] buffer usage: 90% (tid=7889)
Jan 23 11:15:53 seneca vdr: [7892] buffer usage: 100% (tid=7889)
Jan 23 11:15:54 seneca vdr: [2593] connect from 192.168.20.26, port 41889 - accepted
Jan 23 11:15:54 seneca vdr: [2746] VNSI: Timers state changed (14)
Jan 23 11:15:54 seneca vdr: [2746] VNSI: Requesting clients to reload timers
Jan 23 11:15:54 seneca vdr: [7892] ERROR: driver buffer overflow on device 2
Jan 23 11:15:58 seneca vdr: message repeated 2 times: [ [7892] ERROR: driver buffer overflow on device 2]
Jan 23 11:16:00 seneca vdr: [7889] ERROR: skipped 123 bytes to sync on TS packet on device 2
Jan 23 11:16:03 seneca vdr: [7892] ERROR: driver buffer overflow on device 2
Jan 23 11:16:04 seneca vdr: [7892] buffer usage: 60% (tid=7889)
Jan 23 11:16:04 seneca vdr: [7889] ERROR: skipped 123 bytes to sync on TS packet on device 2
Jan 23 11:16:04 seneca vdr: [7892] i/o throttle released, count = 0 (tid=7892)
Jan 23 11:16:05 seneca vdr: [7892] i/o throttle activated, count = 1 (tid=7892)
Jan 23 11:16:06 seneca vdr: [7892] buffer usage: 70% (tid=7889)
Jan 23 11:16:06 seneca vdr: [7892] buffer usage: 60% (tid=7889)
Jan 23 11:16:06 seneca vdr: [7892] buffer usage: 70% (tid=7889)
Jan 23 11:16:06 seneca vdr: [7892] buffer usage: 60% (tid=7889)
Jan 23 11:16:06 seneca vdr: [7892] buffer usage: 70% (tid=7889)
Jan 23 11:16:06 seneca vdr: [7892] buffer usage: 60% (tid=7889)
Jan 23 11:16:06 seneca vdr: [7892] buffer usage: 70% (tid=7889)
Jan 23 11:16:06 seneca vdr: [7892] buffer usage: 60% (tid=7889)
Jan 23 11:16:06 seneca vdr: [7892] buffer usage: 70% (tid=7889)
Jan 23 11:16:06 seneca vdr: [7892] buffer usage: 60% (tid=7889)
Jan 23 11:16:07 seneca vdr: [7892] buffer usage: 70% (tid=7889)
Jan 23 11:16:07 seneca vdr: [7892] buffer usage: 80% (tid=7889)
Jan 23 11:16:08 seneca vdr: [7892] buffer usage: 60% (tid=7889)
Jan 23 11:16:08 seneca vdr: [7892] buffer usage: 70% (tid=7889)
Jan 23 11:16:08 seneca vdr: [7892] buffer usage: 60% (tid=7889)
Jan 23 11:16:09 seneca vdr: [7892] buffer usage: 70% (tid=7889)

and voilà, decoding errors, blocks, resyncs. The fun part is, it is not enough to restart VDR (and hence, vnsiserver), but I actually need to restart the machine in order to get away with this.

Both device 1 and device 2 are attached to Astra, these are two independent LNBs with no multiswitch or anything inbetween. It makes no difference if the current channel is on 1 or 2, so it should not be the LNBs (how?) or the receiver modules on the DD card.

At the moment I am a bit unsure how to track this down. DD has a ticket open for me, it may be useful to talk to them as well. Please contact me if you want the ticket number.

TIA!

[hmilz]

ummmmm, I forgot to add that this does not happen when watching live streams with xineliboutput / vdr-sxfe, and not if I watch recordings using vnsiserver / kodi. Only when it's live streams and vnsiserver / kodi.

[hmilz]

Hi all,

over the weekend I upgraded to vdr-2.2.0, and I'm still seeing the same
problems.

- vdr-2.2.0 from tvdr.de ftp server
- vnsiserver from git (from yesterday)
- dddvb-0.9.22 (loaded as ddbridge msi=0)

Everything else is unchanged.

Result: when the problem starts,
1. switching channels does not help
2. restarting VDR does not help
3. stopping VDR, reloading driver, and restarting VDR does not help
4. only restarting the machine seems to help so far, for some time, until the
problem occurs again.

This is after 3.:

Code:

Feb  1 07:56:59 seneca vdr: [31887] VNSI: Client with ID 2 connected: 192.168.20.200:37103
Feb  1 07:56:59 seneca vdr: [31939] VNSI: Welcome client 'XBMC Media Center' with protocol version '8'
Feb  1 07:56:59 seneca vdr: [31939] VNSI: LiveStreamer::Close - close
Feb  1 07:56:59 seneca vdr: [31939] VNSI: close video input ...
Feb  1 07:56:59 seneca vdr: [31939] VNSI: Successfully found following device: 0x8aaee00 (2) for receiving
Feb  1 07:56:59 seneca vdr: [31940] device 2 receiver thread started (pid=31867, tid=31940, prio=high)
Feb  1 07:56:59 seneca vdr: [31939] VNSI: Successfully switched to channel 2 - ZDF HD
Feb  1 07:56:59 seneca vdr: [31939] VNSI: Started streaming of channel ZDF HD (timeout 10 seconds)
Feb  1 07:56:59 seneca vdr: [31943] device 2 TS buffer thread started (pid=31867, tid=31943, prio=high)
Feb  1 07:56:59 seneca vdr: [31942] cLiveStreamer stream processor thread started (pid=31867, tid=31942, prio=high)
Feb  1 07:56:59 seneca vdr: [31941] VNSI: VideoInput: no pat/pmt within timeout, falling back to channel pids
Feb  1 07:56:59 seneca vdr: [31941] VNSI: Video Input - new pmt, attaching receiver
Feb  1 07:57:00 seneca vdr: [31942] VNSI: Created stream for pid=6110 and type=8
Feb  1 07:57:00 seneca vdr: [31942] VNSI: Created stream for pid=6122 and type=1
Feb  1 07:57:00 seneca vdr: [31942] VNSI: Created stream for pid=6120 and type=2
Feb  1 07:57:00 seneca vdr: [31942] VNSI: Created stream for pid=6121 and type=2
Feb  1 07:57:00 seneca vdr: [31942] VNSI: Created stream for pid=6123 and type=2
Feb  1 07:57:00 seneca vdr: [31942] VNSI: Created stream for pid=6131 and type=9
Feb  1 07:57:00 seneca vdr: [31942] VNSI: Created stream for pid=6130 and type=11
Feb  1 07:57:02 seneca vdr: [31943] i/o throttle activated, count = 1 (tid=31943)
Feb  1 07:57:03 seneca vdr: [31943] buffer usage: 70% (tid=31940)
Feb  1 07:57:03 seneca vdr: [31943] buffer usage: 60% (tid=31940)
Feb  1 07:57:03 seneca vdr: [31943] buffer usage: 70% (tid=31940)
Feb  1 07:57:04 seneca vdr: [31943] buffer usage: 80% (tid=31940)
Feb  1 07:57:04 seneca vdr: [31943] buffer usage: 90% (tid=31940)
Feb  1 07:57:05 seneca vdr: [31943] buffer usage: 100% (tid=31940)
Feb  1 07:57:06 seneca vdr: [31943] buffer usage: 60% (tid=31940)
Feb  1 07:57:06 seneca vdr: [31943] buffer usage: 70% (tid=31940)
Feb  1 07:57:06 seneca vdr: [31943] buffer usage: 60% (tid=31940)
Feb  1 07:57:06 seneca vdr: [31943] buffer usage: 70% (tid=31940)
Feb  1 07:57:06 seneca vdr: [31943] buffer usage: 80% (tid=31940)
Feb  1 07:57:07 seneca vdr: [31943] buffer usage: 90% (tid=31940)
Feb  1 07:57:08 seneca vdr: [31943] buffer usage: 100% (tid=31940)
Feb  1 07:57:09 seneca vdr: [31943] ERROR: driver buffer overflow on device 2
Feb  1 07:57:19 seneca vdr: message repeated 6 times: [ [31943] ERROR: driver buffer overflow on device 2]
Feb  1 07:57:20 seneca vdr: [31940] ERROR: skipped 123 bytes to sync on TS packet on device 2
Feb  1 07:57:21 seneca vdr: [31943] ERROR: driver buffer overflow on device 2
Feb  1 07:57:23 seneca vdr: [31943] ERROR: driver buffer overflow on device 2
Feb  1 07:57:23 seneca vdr: [31943] buffer usage: 60% (tid=31940)
Feb  1 07:57:23 seneca vdr: [31943] buffer usage: 70% (tid=31940)
Feb  1 07:57:24 seneca vdr: [31943] buffer usage: 80% (tid=31940)
Feb  1 07:57:25 seneca vdr: [31943] buffer usage: 90% (tid=31940)
Feb  1 07:57:26 seneca vdr: [31943] buffer usage: 100% (tid=31940)
Feb  1 07:57:26 seneca vdr: [31940] ERROR: skipped 123 bytes to sync on TS packet on device 2
Feb  1 07:57:27 seneca vdr: [31943] ERROR: driver buffer overflow on device 2
Feb  1 07:57:35 seneca vdr: message repeated 5 times: [ [31943] ERROR: driver buffer overflow on device 2]
Feb  1 07:57:36 seneca vdr: [31940] ERROR: skipped 51 bytes to sync on TS packet on device 2
Feb  1 07:57:36 seneca vdr: [31940] ERROR: skipped 72 bytes to sync on TS packet on device 2
Feb  1 07:57:37 seneca vdr: [31943] ERROR: driver buffer overflow on device 2
Feb  1 07:57:48 seneca vdr: message repeated 8 times: [ [31943] ERROR: driver buffer overflow on device 2]
Feb  1 07:57:49 seneca vdr: [31940] ERROR: skipped 33 bytes to sync on TS packet on device 2
Feb  1 07:57:49 seneca vdr: [31940] ERROR: skipped 90 bytes to sync on TS packet on device 2
Feb  1 07:57:50 seneca vdr: [31943] ERROR: driver buffer overflow on device 2

Again, this happens only when watching live TV with vnsiserver / kodi (on RPi2
with OpenELEC-latest or on Android 5.1.1 using Kodi-latest as from Google
Play). Every other combination (recording, watching recordings, watching live
TV with xineliboutput / vdr-sxfe (on Ubuntu 14.04-x86)) does not exhibit
the problem.


I have no idea what I can do here. Any hint or help is appreciated.

TIA!

[FernetMenta]

I have no clue what code is in OpenElec 6.0. Please try a Milhouse build for Pi that is v17 and post a debug log.

[hmilz]

OpenELEC 6.0.1 has Kodi 15.2. Whether or not they made any patches to the git code I don't know.


OK - I think I have a stable configuration now, albeit weird.

- I upgraded the mobo BIOS to -latest, to no avail (hoping this would change
the MSI interrupt behaviour, but it only appears to add some more CPU
support. But you never know, BIOS changelogs haven't been well known for
being particularly verbose.)
- I set pci=nomsi - no change. Will change this back to default for the next
reboot
- I enlarged PLAYERBUFSIZE (and RECORDERBUFSIZE to be sure) in the vdr-2.2.0 source code to 50 megs, and
voilà, the setup has been stable for the last 4 days or so. I know this only
cures the symptom IF the buffer logic has an actual problem

OK, the WAF has been saved for now, but the fix still does not explain why the
buffer overrun problem only occurs when watching live TV with vnsiserver and
kodi, and can only be cured by rebooting the machine. So ...

[FernetMenta]

OpenELEC 6.0.1 has Kodi 15.2. Whether or not they made any patches to the git code I don't know.

I use v17 that is currently under development. 15.x has never been tested (by me) with current vnsiserver. Of course, it should work, but is is not uncommon that you may experience those kind of issues after an upgrade of a single component in the chain.

OK, the WAF has been saved for now, but the fix still does not explain why the
buffer overrun problem only occurs when watching live TV with vnsiserver and
kodi, and can only be cured by rebooting the machine. So ... Undecided

I think this is more a buffer overrun. If Kodi plays back the stream slightly slower than the time the stream refers to, sooner or later the buffers are full. What you see on screen is probably some seconds behind actual. This may trigger some exceptional path in vdr's ringbuffer and maybe the driver itself. I don't think those code paths are well tested so I am not surprised that something in the kernel/driver get corrupted and requires a reboot.