Progress bar "lost" after skipping about 3 times

[laz]

I'm not sure whether this is a known bug or not. If I watch a recording and I skip forward several times either 10 s, 1 min, or to a cut mark, after about 3 or 4 skips the recording progress bar loses the yellow progress bar and the length and position numbers disappear.

Usually, I can recover the numbers and progress bar by going back to the main menu and then resuming the recording.

At other times, skipping leaves me with a black screen with no audio and all input is ignored. At this point, I have to use "kill -KILL" to kill vompclient. Using just "kill" gives messages in the debug output that it has received the kill message and is trying to shutdown but it fails to do so.

This is with latest git. I'm reading my way through the code but have yet to get enough of a grasp to know exactly where to look for this yet!

Skipping has always seemed to be a problem with all output plugins I've tried with vdr!



Laz

[JTe]

I have also noticed that fast forwarding of a recording jams the whole client every now and then. The picture freezes on the screen and the whole vomp client is unresponsive. Only way out is to kill the client with -9. Last time the client did not restart after that without rebooting the whole raspi. And sorry, I did not get any logs from that! If this happen again I will try to find why the client will not restart.

[davep]

Yes I have the same problem with skipping; sometimes it works fine, others the picture and sound freeze and only a 'kill -9' will regain control. I've been waiting for a chance to create a good log file showing the problem.

[MartenR]

Well, I am not aware of this problem. There was a similar problem with live tv and on recording, which I thought was solved in the last weekend commits.

I will try to reproduce it here. There is one problem with the video decoder of the raspberry, if they get damaged streams, they stop decoding...
May be still a way to get damaged streams to the decoder.

Marten

p.S: I am not sure if a log file will help....

[laz]

I did have a  look in the debug log when I had this happen a few days back (before enough use told me that it was fairly reproducible) and didn't spot anything obvious.

Interestingly, skipping forwards 1 min was a lot more sluggish when I had the TCP receive buffer set to 65536. When I reduced it to 32768 (to get HD working properly) skipping was near-instant.

I might try reducing it again this evening to see if that helps this issue...

Laz

[MartenR]

@Laz
tcp receive window has nothing to do with this.
It was jsut faster, since your network connection is faster with the right window size.

Marten

[hondansx]

I have the same problem with fast forwarding and freeze on my mvp. This did it for me. Can anybody confirm this?

Code Select Expand


diff -Naur client744/command.cc client744.new/command.cc
--- client744/command.cc        2009-10-17 18:44:02.000000000 +0200
+++ client744.new/command.cc    2011-11-01 16:23:08.000000000 +0100
@@ -637,7 +637,7 @@
   } 
   else
   {
-    logger->netLogOn();
+    logger->netLogOff();
     logger->log("Command", Log::INFO, "Turned off network logging");
   }
   if (config) delete[] config;


[MartenR]

@hondansx
Really net logging? Then it is a deadlock  in logging, can the others confirm this?

@all
My hypothesis would be something different. Does it only happen, if you navigate fast multiple times one fast another. So that it is possible that you hit it while av startup of the other skip?
Then comment

Code Select Expand

if (!ChangeAudioPortConfig(true)) {

                      Log::getInstance()->log("Audio", Log::DEBUG,

                                         "Changing audio port config failed", error);

                 }
in audioomx.cc. and tell me if this helps?

Marteb

[laz]

(I can't see net logging in the options on my build.)

I initially thought it was a case of "multiple skipping in rapid succession" and started waiting a few seconds between skips (I always had to do that with xineliboutput). That didn't sort it out, though.

If I watch something with cut marks in it (e.g. adverts marked with markad) and skip between them I'm only skipping once every 15-20 minutes or so for each advert break. I still lose the yellow progress bar and numbers after a few of these skips. One thing I have spotted since initially reporting is that the yellow status bar does sometimes reappear after a few seconds, i.e. it might have reappeared at other times but the OSD has timed out and gone before it has a chance to do so.

I can't remember whether vomp on MediaMVP had the same issue. I have a feeling that skipping in recordings could be troublesome at times: I will dig one out when I get the chance. That might help track it down to OMX specific or shared code.

Looking through the source code, it looks fairly straightforward, apart from the multithreading. Perhaps there's a race condition, or something, that only happens when a buffer is only so full / empty? Could the fact that I need to use kill -KILL to kill it at times suggest a lock that isn't released? I'm only guessing here!

Another thing I've noticed is that pausing and unpausing are quite sluggish and take a couple of seconds to kick in. A quick look in my log shows:
23:18:01.813067 [debug]  2015 Remote - CECLOG: 3562508 16 received data: header:00030004 p0:00024401 p1:00000000 p2:00000000 p3:00000000 reason:4
23:18:01.814712 [debug]  2015 Remote - CECLOG: 3562510 8 >> 01:44:02
23:18:01.819226 [debug]  2015 Remote - CECLOG: 3562514 4 >> TV (0) -> Recorder 1 (1): user control pressed (44)
23:18:01.821454 [debug]  2015 Remote - CECLOG: 3562516 16 key pressed: down (2)
23:18:01.830362 [debug]  2015 Player - LOCKED
23:18:01.831696 [debug]  2015 Player - Switch state from 1 to 2
23:18:01.833666 [debug]  2015 Video - enter pause
23:18:01.833367 [debug]  2015 VDR - Rxd a response packet, requestID=11029, len=100000
23:18:01.836137 [notice] 2015 Video - eventHandler 31dc40 0 1 64 0
23:18:01.839259 [debug]  2015 VDR - RR unsleep
23:18:01.865390 [debug]  2015 VDR - RR sleep - opcode 7
23:18:01.876736 [debug]  2015 VDR - Rxd a response packet, requestID=11030, len=100000
23:18:01.878519 [debug]  2015 VDR - RR unsleep
23:18:01.898633 [debug]  2015 VDR - RR sleep - opcode 7
23:18:01.910328 [debug]  2015 VDR - Rxd a response packet, requestID=11031, len=100000
23:18:01.911962 [debug]  2015 VDR - RR unsleep
23:18:01.936080 [debug]  2015 VDR - RR sleep - opcode 7
23:18:01.949363 [debug]  2015 VDR - Rxd a response packet, requestID=11032, len=100000
23:18:01.950980 [debug]  2015 VDR - RR unsleep
23:18:01.959061 [debug]  2015 Remote - CECLOG: 3562654 16 received data: header:00030008 p0:00024501 p1:00000000 p2:00000000 p3:00000000 reason:8
23:18:01.960859 [debug]  2015 Remote - CECLOG: 3562656 8 >> 01:45:02
23:18:01.962533 [debug]  2015 Remote - CECLOG: 3562657 4 >> TV (0) -> Recorder 1 (1): user control release (45)
23:18:01.964516 [debug]  2015 Remote - CECLOG: 3562659 16 key released: down (2)

23:18:01.979846 [debug]  2015 VDR - RR sleep - opcode 7
23:18:01.992204 [debug]  2015 VDR - Rxd a response packet, requestID=11033, len=100000
23:18:01.993804 [debug]  2015 VDR - RR unsleep
   [lots of these...then]
23:18:02.694085 [debug]  2015 VDR - RR sleep - opcode 7
23:18:02.707184 [debug]  2015 VDR - Rxd a response packet, requestID=11053, len=100000
23:18:02.709114 [debug]  2015 VDR - RR unsleep
23:18:04.007473 [debug]  2015 Video - CommandFinished waited too long 31dc40 0 2
23:18:04.008880 [debug]  2015 Audio -  pause aud_rend idle ChangeComponentState
23:18:04.010742 [notice] 2015 Video - eventHandler 31dc40 0 0 2 0
23:18:04.012784 [debug]  2015 Player - UNLOCKING
23:18:04.013961 [debug]  2015 Audio - OMX_EmptyThisBuffer 5 failed 80001018
2

I'm guessing the "CommandFinished waited too long" is complaining about the 2 s delay (not looked in detail at this bit of code yet!)

It then appears to draw the progress bar, marks, and display position with the following chunk (or very similar chunks) repeated about 18 times!

23:18:04.274103 [debug]  2015 VVideoRec - Draw bar clocks
23:18:04.276762 [debug]  2015 DemuxerTS - getFrameNumfromPTS pts 2127438018 deleted 13 difference 0
23:18:04.278485 [debug]  2015 VVideoRec - 0:00:03 / 1:16:54
23:18:04.280489 [debug]  2015 VVideoRec - Drawing mark at frame 2949
23:18:04.282254 [debug]  2015 VVideoRec - Drawing mark at frame 92970
23:18:04.284209 [debug]  2015 BoxStack - Update called
23:18:04.286148 [debug]  2015 BoxStack - Locked for update
23:18:04.288072 [debug]  2015 BoxStack - Unlocked for update
23:18:04.289825 [debug]  2015 Timers - Starting set timer 1
23:18:04.291597 [debug]  2015 Timers - timerEventFinished for 0x31dce4
23:18:04.292913 [debug]  2015 Timers - timerEventFinished RESTART for 0x31dce4
23:18:04.489900 [debug]  2015 Timers - Timer firing for client 0x31dce4 ref 2
23:18:04.491395 [debug]  2015 Timers - sending timer to 0x31dce4 with parameter 2

Is it really meant to repeat drawing so many times, or am I being dense here?! I'm guessing the Timers messages are just happening to be going on too.

Then it removes it when the OSD times out:

23:18:08.075234 [debug]  2015 OSD - Draw Paint -2147482971 0 0
23:18:08.077109 [debug]  2015 BoxStack - Update called
23:18:08.079359 [debug]  2015 BoxStack - Locked for update
23:18:08.081152 [debug]  2015 OSD - Draw Paint Destroy -2147482865
23:18:08.082586 [debug]  2015 OSD - Draw Paint Destroy -2147482891
23:18:08.084799 [debug]  2015 OSD - Draw Paint Destroy -2147482909
23:18:08.086175 [debug]  2015 BoxStack - Unlocked for update

I hope some of the above is useful in some way.

Laz

[MartenR]

So one comment, the problem with loosing the progress bar is probably a second issue (related to the vector osd) than the black screen.
I think all other then laz are reporting the second issue?

Marten

[JTe]

If it helps, I remember having the black screen issue and freezing of client also with mvp client every now and then, but now with raspi client it happens very often. So it could be a very old thread locking problem.

Other thing I have noticed lately is that there is a new problem with audio on some channels making every now and then very loud cracking sounds (similar you get with DVB reception when signal quality is bad). So I guess some audio packets are missing? I tried to set different (smaller) TCP window size, but id did not help (in fact it made the first problem more frequent and caused more jamming). The audio problems seem to be only on channels that report all the time the following:

Code Select Expand

[mp3 @ 0x22e1980] incorrect frame size
[mp3 @ 0x22e1980] incomplete frame

I know this was discussed in another thread and should not have effect to functionality, but there are sound problems only on these channels.

[davep]

So one comment, the problem with loosing the progress bar is probably a second issue (related to the vector osd) than the black screen.
I think all other then laz are reporting the second issue?

The client freezing/hanging on skip issue has been happening since the first RasPi version. The progress bar issue is more recent and is likely related to the vector ISD.

@JTe: Yes I recall the MVP occasionally freezing on skip; maybe 5% of the time and only when repeatedly pressing the skip buttons. RasPi freezes about 25% of the time.

[MartenR]

@JTe
with the incomplete header, this is clearly a bug.
If you can reproduce it with a recording, then I would like to have a sample.

Code Select Expand

The client freezing/hanging on skip issue has been happening since the first RasPi version.
Yes, it was there from the beginning, but it had multiple reasons, most of them should be fixed now. (Please also try my suggestion with the comment in audioomx.)

So I need a log file, and probably a way to reproduce it.

Marten

[davep]

I've attached a log file showing the problem. Vompclient is up-to-date and with the patch from reply 7 applied. Raspbian is also up-to-date.

To create the log, I navigated using the TV remote to a recording and started it playing. I pressed the 'skip 60s' button on the remote 5 times, each time waiting until the progress bar OSD had disappeared before the next press. So far so good. Then I pressed the 'skip 60s' again, and once more about 2s later while the progress bar was still shown. The client then froze.

In a separate experiment I was able to skip at least 25 times without a problem, provided the progress bar had disappeared before pressing again. With a shorter wait (so the bar was still displayed) the client froze on the 4th attempt.

[MartenR]

Thanks, this helps a bit.
What you can see, that in the last skip attempt, after

Code Select Expand

Audio - deallocatecodecsomx mark 5 no mark 6 follows.
If you look into audioomx.cc, we see that the deadlock is occuring some where inbetween.
Can you please add some additional log messages between mark 5 and 6, so that we can nail it a bit more down, where the dealock is happening?

Marten