[Nachteule]

@FernetMenta
I'm currently testing your timeshift (xbmc from your osd branch, addon from your timeshift branch), using vdr 1.7.27

LiveTV sometimes stops, xbmc responds on any key or mouse - or gets in slowmotion mode with no sound. It seems that it happens after timeshift buffer is full (used 2GB)
I have added two logs (vdr.log and xbmc.log). In this situation, screen freezes after i played a little bit with (Big)StepForward/Back, but i was able to change the channel and then it was ok again.

vdr.log: http://pastebin.com/7CQLeP20
xbmc.log: http://pastebin.com/dPYnRE3p

Today afternoon, "slomotion" effect occurs without any user interactions, i was still able to stop live tv.

I tried to use a larger buffer (changing the source), but this fails because it seems you are using 32bit singed for all buffer variables. Now i'm testing with 1GB buffersize

[FernetMenta]

Nachteule, are you running vdr on a 32 or 64bit system. The buffer variables are of size_t which is 64bit on 64bit systems.

I have done most test with a small buffer and HD in order to force many wraps of the buffer. Interestingly you hit this: VNSI-Error: ------------- skipping data
can you duplicate it?

[Nachteule]

Nachteule, are you running vdr on a 32 or 64bit system. The buffer variables are of size_t which is 64bit on 64bit systems.

Look to my signature , 64 bit

I tested it with 4GB, here my logs

Jan 23 16:06:53 kmxbmc vdr: [9773] VNSI: Welcome client 'XBMC Media Center' with protocol version '3'
Jan 23 16:06:53 kmxbmc vdr: [9773] VNSI: allocated timeshift buffer with size: -294967296
Jan 23 16:06:53 kmxbmc vdr: [9773] VNSI: Successfully switched to channel 1 - Das Erste
Jan 23 16:06:53 kmxbmc vdr: [9773] VNSI: Started streaming of channel Das Erste (timeout 10 seconds)

Code:

and

Jan 23 16:06:53 T:139885284308736 DEBUG: PVRManager - OpenLiveStream - opening live stream on channel 'Das Erste'
Jan 23 16:06:53 T:139885284308736 DEBUG: opening live stream for channel 'Das Erste'
Jan 23 16:06:53 T:139885284308736 NOTICE: AddOnLog: VDR VNSI Client: Logged in at '1358953613+3600' to 'VDR-Network-Streaming-Interface (VNSI) Server' Version: '0.9.0' with protocol version '3'
Jan 23 16:06:53 T:139885284308736 DEBUG: AddOnLog: VDR VNSI Client: changing to channel 1
Jan 23 16:06:53 T:139885780342528 ERROR: AddOnLog: VDR VNSI Client: SignalConnectionLost - connection lost !!!
Jan 23 16:06:53 T:139885780342528 DEBUG: CAddonCallbacksAddon - QueueNotification - VDR VNSI Client - Error Message : 'Verbindung zum VDR Server unterbrochen'
Jan 23 16:06:53 T:139885809760000 DEBUG: CPVRTimers - Update - updating timers
Jan 23 16:06:53 T:139885809760000 ERROR: AddOnLog: VDR VNSI Client: GetTimersList - Can't get response packed
Jan 23 16:06:53 T:139885809760000 ERROR: PVR - GetTimers - addon 'VDR-Network-Streaming-Interface (VNSI) Server:kmxbmc.kmhome.com:34890' returned an error: server error
Jan 23 16:06:53 T:139885809760000 ERROR: PVR - GetTimers - cannot get timers from client '1': server error
Jan 23 16:06:53 T:139886976542784 DEBUG: ------ Window Init (DialogBusy.xml) ------
Jan 23 16:06:53 T:139886976542784 DEBUG: ------ Window Init (DialogKaiToast.xml) ------
Jan 23 16:06:53 T:139885284308736 DEBUG: PVRFile - Open - playback has started on filename pvr://channels/tv/Alle TV-Kanäle/0.pvr
Jan 23 16:06:53 T:139885284308736 DEBUG: CDVDInputStreamPVRManager::Open - stream opened: pvr://channels/tv/Alle TV-Kanäle/0.pvr
Jan 23 16:06:53 T:139885284308736 NOTICE: Creating Demuxer
Jan 23 16:06:53 T:139885284308736 DEBUG: SECTION:LoadDLL(special://xbmcbin/system/players/dvdplayer/avcodec-53-x86_64-linux.so)
Jan 23 16:06:53 T:139885284308736 DEBUG: Loading: /home/xbmc/xbmc-12.0/lib64/xbmc/system/players/dvdplayer/avcodec-53-x86_64-linux.so

I have done most test with a small buffer and HD in order to force many wraps of the buffer. Interestingly you hit this: VNSI-Error: ------------- skipping data
can you duplicate it?

Yes

Code:

kmxbmc:/srv/p2p/DDLs # cat /var/log/vdr.log | grep skipping
Jan 23 02:33:01 kmxbmc vdr: [17365] VNSI-Error: ------------- skipping data
Jan 23 18:27:43 kmxbmc vdr: [11384] VNSI-Error: ------------- skipping data

18:27: I played again with BigStepForward/Back, but livetv did not stop

[Nachteule]

Nachteule, are you running vdr on a 32 or 64bit system. The buffer variables are of size_t which is 64bit on 64bit systems.

Yes, you are right, with one exception: TimeshiftBufferSize

If you use m_BufferSize = (size_t)TimeshiftBufferSize*100*1000*1000; in videobuffer.c, buffersize can be larger than 2GB

[FernetMenta]

Thanks, will change the code. I need to fix seeking in XBMC which is broken for all pvr clients (small step). There's only an preliminary fix in my osd branch.

There is a macro MARGIN in videobuffer which is actually the proximity allowed for read and write pointer. Currently it's defined to 4k which might be too small. Can you try setting it to 40k or even 400k?

[Nachteule]

There is a macro MARGIN in videobuffer which is actually the proximity allowed for read and write pointer. Currently it's defined to 4k which might be too small. Can you try setting it to 40k or even 400k?

Yes, i did it, changed value to 400000. But makes no difference. Slowmotion occured again without user interactions. I can send you logs if you wish

[FernetMenta]

Thanks, obviously something wrong there. Do you have instructions how to duplicate this, buffer size, SD or HD, when does this happen, have you identified a pattern?

[Nachteule]

Thanks, obviously something wrong there. Do you have instructions how to duplicate this, buffer size, SD or HD, when does this happen, have you identified a pattern?

Yes, i agree. For me, it looks like an issue in the xbmc code, not in the addon and not in the vnsiserver. But this code is too high for me.

Unfortunately i have no idea how to reproduce it. It simply happens. Last days i tested with 2GB buffer, today with 700MB. I wait until buffer was filled completely, went through the buffer and then leave xbmc alone. After i came back, livetv was played in slowmotion again.

I'm using DVB-T and testing always on the same channel ("Das Erste", SD). Tomorrow i will take another channel from another provider, will see what happens.

IMHO, here begins the problem:

Code:

It's the first time "audio stream stalled. start buffering" appears.
Jan 24 18:11:10 T:139667249153792    INFO: EPG - UpdateFromScraper - updating EPG for channel 'München TV' from client '1'
Jan 24 18:11:10 T:139667257546496   DEBUG: CPVRTimers - Update - updating timers
Jan 24 18:11:10 T:139666037233408 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
Jan 24 18:13:14 T:139666324870912   DEBUG: CDVDPlayer::CheckContinuity - resync backward :2, prev:95443721478.000000, curr:43789.000000, diff:-95443677689.000000
Jan 24 18:13:14 T:139666037233408 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
Jan 24 18:13:14 T:139666037233408   DEBUG: CSoftAEStream::Flush
Jan 24 18:13:15 T:139666324870912   DEBUG: audio stream stalled. start buffering
Jan 24 18:13:15 T:139666324870912   DEBUG: CDVDPlayer::SetCaching - caching state 2
Jan 24 18:13:15 T:139666324870912   DEBUG: CDVDPlayer::CheckContinuity - resync backward :2, prev:190887559167.000000, curr:95443881478.000000, diff:-95443677689.000000
Jan 24 18:13:15 T:139666324870912   DEBUG: set caching from pvr to done. audio (1) = 100. video (1) = 0
Jan 24 18:13:15 T:139666070804224   DEBUG: CPullupCorrection: pattern lost on diff 95443757689.000000
Jan 24 18:13:15 T:139667417306880   DEBUG: CSoftAE::Run - Sink restart flagged
Jan 24 18:13:15 T:139667417306880    INFO: CSoftAE::InternalOpenSink - keeping old sink with : AE_FMT_FLOAT, FL,FR, 48000hz
Jan 24 18:13:15 T:139667417306880   DEBUG: CSoftAE::InternalOpenSink - Using speaker layout: 2.0
Jan 24 18:13:15 T:139667417306880   DEBUG: CSoftAE::InternalOpenSink - Internal Buffer Size: 4096
Jan 24 18:13:15 T:139666324870912   DEBUG: CDVDPlayer::SetCaching - caching state 0
Jan 24 18:13:15 T:139667417306880   DEBUG: CSoftAE::Run - Sink restart flagged
Jan 24 18:13:15 T:139667417306880    INFO: CSoftAE::InternalOpenSink - keeping old sink with : AE_FMT_FLOAT, FL,FR, 48000hz
Jan 24 18:13:15 T:139667417306880   DEBUG: CSoftAE::InternalOpenSink - Using speaker layout: 2.0
Jan 24 18:13:15 T:139667417306880   DEBUG: CSoftAE::InternalOpenSink - Internal Buffer Size: 4096
Jan 24 18:13:15 T:139666037233408   DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:95443740070.710510, should be:190886926718.465698, error:95443186647.755188
Jan 24 18:13:15 T:139666037233408 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
Jan 24 18:13:15 T:139666324870912   DEBUG: CDVDPlayer::HandleMessages - player started 1
Jan 24 18:13:15 T:139666324870912   DEBUG: CDVDPlayer::HandleMessages - player started 2
Jan 24 18:13:16 T:139666324870912   DEBUG: CDVDPlayer::CheckContinuity - resync backward :2, prev:286331396856.000000, curr:190887719167.000000, diff:-95443677689.000000
Jan 24 18:13:16 T:139666324870912   DEBUG: CDVDPlayer::CheckContinuity - resync forward :2, prev:286331436856.000000, curr:381775194545.000000, diff:95443717689.000000
Jan 24 18:13:16 T:139666037233408   DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:190887567522.936707, should be:190887200422.000000, error:-367100.936707
Jan 24 18:13:16 T:139666324870912   DEBUG: CDVDPlayer::CheckContinuity - resync backward :2, prev:286331516856.000000, curr:190887839167.000000, diff:-95443677689.000000
Jan 24 18:13:16 T:139666037233408 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available

It's the first time "audio stream stalled. start buffering" appears

[FernetMenta]

What exactly do you meant by "went through the buffer"?

95443721478.000000, curr:43789.000000, diff:-95443677689.000000

The problem is clearly in the backend, there is a big jump in timestamp.

[Nachteule]

What exactly do you meant by "went through the buffer"?

Oh sorry, moving to the beginning of the live buffer by pressing BIG_STEP_BACK, moving to the end of buffer by BIG_STEP_FORWARD, repeated this more than one time. Currently i never use FF, FR, because it is terrible slow on my machine

95443721478.000000, curr:43789.000000, diff:-95443677689.000000

The problem is clearly in the backend, there is a big jump in timestamp.

Ah, i already noticed some big steps, but i know not enough about the internals

[FernetMenta]

The problem must be in ParsePESHeader when reading timestamps. This 33bit counter wraps over every 26 hours. I try to remove those wraps but there must be some error.

[FernetMenta]

I have pushed some fixes: https://github.com/FernetMenta/xbmc-pvr-...922cc4020b

And another one, copy paste error. Instead of adding to dts it incremented pts twice.
https://github.com/FernetMenta/xbmc-pvr-...cb9fd15ceb

[Nachteule]

The problem must be in ParsePESHeader when reading timestamps. This 33bit counter wraps over every 26 hours. I try to remove those wraps but there must be some error.

I looked to my logs and found, time difference between the error at Wed and the error at Thu was 26,5hrs. I calculated a little bit, 90kHz Clock and 33bit counter results in 26,51hrs . So, next wrap will occur ad 20:45 on my channel "Das Erste"

[FernetMenta]

Many thanks to Nachteule for helping me on this!

Having the time shift buffer in RAM seems to work now. Next steps are:

1)
Implementing the file buffer method

2)
Load current recording into buffer. When opening a channel which is recording, the recording will be loaded into the time shift buffer. Once the recording has finished and the user stays on the channel it will continue with live stream.

[Nachteule]

Having the time shift buffer in RAM seems to work now. Next steps are:

Currently i make some more tests, especially what happens after buffer overrun.

Perhaps it would be better removing the oldest data in the timeshift buffer than the newest data.