pipelka/vdr-plugin-xvdr — Issue #17: Freeze during channel playback
Author: manio
Created: 2011-10-15 19:25:08+00:00
State: open

From time to time while watching TV (it is happening to me about 1-2 times a day) I've got channel playback freeze and "Signal Lost" message in log. The signal is definitely not lost, because every time when it occurs it is sufficient to stop playing channel in xbmc and switch to it back again.

On the xbmc it look like this (problem is starting with line 'Stillframe detected'):

14:51:06 T:140497553958656 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
14:51:06 T:140497880303360 WARNING: Previous line repeats 1 times.
14:51:06 T:140497880303360 DEBUG: AddOnLog: VDR XVDR Client: SendPing
14:51:07 T:140497553958656 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
14:51:11 T:140497673889536 WARNING: Previous line repeats 3 times.
14:51:11 T:140497673889536 WARNING: CDVDMessageQueue(video)::Get - asked for new data packet, with nothing available
14:51:11 T:140497673889536 INFO: CDVDPlayerVideo - Stillframe detected, switching to forced 25.000000 fps
14:51:12 T:140497880303360 DEBUG: AddOnLog: VDR XVDR Client: SendPing
14:51:13 T:140497655527168 DEBUG: CAddonCallbacksAddon - QueueNotification - VDR XVDR Client - Info Message : 'TV Signal lost'
14:51:14 T:140498312951744 DEBUG: ------ Window Init (DialogKaiToast.xml) ------
14:51:14 T:140498312951744 DEBUG: Alloc resources: 0.00ms (0.00 ms skin load)
14:51:17 T:140498312951744 DEBUG: ------ Window Deinit (DialogKaiToast.xml) ------
14:51:18 T:140497880303360 DEBUG: AddOnLog: VDR XVDR Client: SendPing
14:51:30 T:140497562351360 DEBUG: Previous line repeats 1 times.
14:51:30 T:140497562351360 DEBUG: Thread Jobworker 140497562351360 terminating (autodelete)
14:51:30 T:140497880303360 DEBUG: AddOnLog: VDR XVDR Client: SendPing
14:52:00 T:140497562351360 DEBUG: Previous line repeats 4 times.
14:52:00 T:140497562351360 DEBUG: Thread Jobworker start, auto delete: 1
14:52:01 T:140497880303360 DEBUG: AddOnLog: VDR XVDR Client: SendPing
14:52:30 T:140497562351360 DEBUG: Previous line repeats 4 times.
14:52:30 T:140497562351360 DEBUG: Thread Jobworker 140497562351360 terminating (autodelete)
14:52:31 T:140497880303360 DEBUG: AddOnLog: VDR XVDR Client: SendPing
14:53:00 T:140497562351360 DEBUG: Previous line repeats 4 times.
14:53:00 T:140497562351360 DEBUG: Thread Jobworker start, auto delete: 1
14:53:01 T:140497880303360 DEBUG: AddOnLog: VDR XVDR Client: SendPing
14:53:10 T:140497880303360 DEBUG: Previous line repeats 1 times.
14:53:10 T:140497880303360 ERROR: AddOnLog: VDR XVDR Client: SignalConnectionLost - connection lost !!!
14:53:10 T:140497880303360 DEBUG: CAddonCallbacksAddon - QueueNotification - VDR XVDR Client - Error Message : 'Lost connection to VDR Server'
14:53:10 T:140497901315840 DEBUG: CPVRTimers - Update - updating timers
14:53:10 T:140497901315840 ERROR: AddOnLog: VDR XVDR Client: GetTimersList - Can't get response packet
14:53:10 T:140497901315840 ERROR: PVRClient - GetTimers - addon 'VDR-XVDR Server:127.0.0.1:34891' returns bad error (-3) from GetTimers()
14:53:10 T:140498312951744 DEBUG: ------ Window Init (DialogKaiToast.xml) ------
14:53:10 T:140498312951744 DEBUG: Alloc resources: 0.00ms (0.00 ms skin load)
14:53:13 T:140497880303360 ERROR: AddOnLog: VDR XVDR Client: Login - failed to read greeting from server
14:53:13 T:140498312951744 DEBUG: ------ Window Deinit (DialogKaiToast.xml) ------
14:53:17 T:140497880303360 ERROR: AddOnLog: VDR XVDR Client: Login - failed to read greeting from server
14:53:30 T:140497562351360 ERROR: Previous line repeats 3 times.
14:53:30 T:140497562351360 DEBUG: Thread Jobworker 140497562351360 terminating (autodelete)
14:53:33 T:140497880303360 ERROR: AddOnLog: VDR XVDR Client: Login - failed to read greeting from server
14:54:00 T:140497562351360 ERROR: Previous line repeats 6 times.
14:54:00 T:140497562351360 DEBUG: Thread Jobworker start, auto delete: 1
14:54:01 T:140497880303360 ERROR: AddOnLog: VDR XVDR Client: Login - failed to read greeting from server
14:54:30 T:140497562351360 ERROR: Previous line repeats 7 times.
14:54:30 T:140497562351360 DEBUG: Thread Jobworker 140497562351360 terminating (autodelete)
14:54:33 T:140497880303360 ERROR: AddOnLog: VDR XVDR Client: Login - failed to read greeting from server
14:55:00 T:140497562351360 ERROR: Previous line repeats 6 times.
14:55:00 T:140497562351360 DEBUG: Thread Jobworker start, auto delete: 1
14:55:01 T:140497880303360 ERROR: AddOnLog: VDR XVDR Client: Login - failed to read greeting from server
14:55:20 T:140497880303360 ERROR: Previous line repeats 4 times.
14:55:20 T:140497880303360 NOTICE: AddOnLog: VDR XVDR Client: Logged in at '1318683320+7200' to 'VDR-XVDR Server' Version: '0.9.0' with protocol version '3'
14:55:20 T:140497880303360 DEBUG: AddOnLog: VDR XVDR Client: TryReconnect - reconnected
14:55:20 T:140497880303360 DEBUG: CAddonCallbacksAddon - QueueNotification - VDR XVDR Client - Info Message : 'Connection to VDR Server restored'
14:55:20 T:140498312951744 DEBUG: ------ Window Init (DialogKaiToast.xml) ------

I was trying to attach gdb to vdr later so it could add something strange to logs, but the first phase of the problem is logged correctly.

On the vdr side it look like this:

Oct 15 14:51:12 draco vdr: [18393] buffer usage: 70% (tid=18392)
Oct 15 14:51:13 draco vdr: [18393] buffer usage: 80% (tid=18392)
Oct 15 14:51:13 draco vdr: [18393] buffer usage: 90% (tid=18392)
Oct 15 14:51:13 draco vdr: [18393] buffer usage: 100% (tid=18392)
Oct 15 14:51:13 draco vdr: [18393] ERROR: 1 ring buffer overflow (89 bytes dropped)
Oct 15 14:51:13 draco vdr: [18392] XVDR: timeout. signal lost!
Oct 15 14:51:19 draco vdr: [18393] ERROR: 10269 ring buffer overflows (1930572 bytes dropped)
Oct 15 14:51:25 draco vdr: [18393] ERROR: 10250 ring buffer overflows (1927000 bytes dropped)
Oct 15 14:51:31 draco vdr: [18393] ERROR: 10296 ring buffer overflows (1935648 bytes dropped)
Oct 15 14:51:37 draco vdr: [18393] ERROR: 11169 ring buffer overflows (2099772 bytes dropped)
Oct 15 14:51:43 draco vdr: [18393] ERROR: 9611 ring buffer overflows (1806868 bytes dropped)
Oct 15 14:51:49 draco vdr: [18393] ERROR: 6604 ring buffer overflows (1241552 bytes dropped)
Oct 15 14:51:55 draco vdr: [18393] ERROR: 8094 ring buffer overflows (1521672 bytes dropped)
Oct 15 14:52:01 draco vdr: [18393] ERROR: 9983 ring buffer overflows (1876804 bytes dropped)
Oct 15 14:52:07 draco vdr: [18393] ERROR: 12012 ring buffer overflows (2258256 bytes dropped)
Oct 15 14:52:13 draco vdr: [18393] ERROR: 11503 ring buffer overflows (2162564 bytes dropped)
Oct 15 14:52:19 draco vdr: [18393] ERROR: 11714 ring buffer overflows (2202232 bytes dropped)
Oct 15 14:52:25 draco vdr: [18393] ERROR: 10809 ring buffer overflows (2032092 bytes dropped)
Oct 15 14:52:31 draco vdr: [18393] ERROR: 9546 ring buffer overflows (1794648 bytes dropped)
Oct 15 14:52:37 draco vdr: [18393] ERROR: 8876 ring buffer overflows (1668688 bytes dropped)
Oct 15 14:52:43 draco vdr: [18393] ERROR: 10378 ring buffer overflows (1951064 bytes dropped)
Oct 15 14:52:49 draco vdr: [18393] ERROR: 10377 ring buffer overflows (1950876 bytes dropped)
Oct 15 14:52:55 draco vdr: [18393] ERROR: 8622 ring buffer overflows (1620936 bytes dropped)
Oct 15 14:53:01 draco vdr: [18393] ERROR: 7792 ring buffer overflows (1464896 bytes dropped)

When this issue is starting happening the vdr is eating 100% of one CPU core. This is definitely wrong. When i stop playing channel in xbmc, then this 100% usage is going back to normal - and as i wrote before it works ok when i manual switch to same channel again.