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
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.
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.
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....
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
@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
I have the same problem with fast forwarding and freeze on my mvp. This did it for me. Can anybody confirm this?
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;
@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
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
(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
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
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:
[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.
Quote from: MartenR on November 01, 2012, 07:22:06
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.
@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.
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
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.
Thanks, this helps a bit.
What you can see, that in the last skip attempt, after 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
Here's the instrumented code:
Log::getInstance()->log("Audio", Log::DEBUG, "deallocatecodecsomx mark 5");
video->LockClock();
Log::getInstance()->log("Audio", Log::DEBUG, "**DP0**");
if (!video->ChangeComponentState(omx_aud_rend,OMX_StateIdle)) {
Log::getInstance()->log("Audio", Log::DEBUG, "aud_rend ChangeComponentState");
}
Log::getInstance()->log("Audio", Log::DEBUG, "**DP1**");
// TODO proper deinit sequence
// first flush all buffers
error=OMX_SendCommand(omx_aud_rend,OMX_CommandFlush, omx_rend_input_port, NULL);
Log::getInstance()->log("Audio", Log::DEBUG, "**DP2**");
if (error!=OMX_ErrorNone) {
Log::getInstance()->log("Audio", Log::DEBUG, "OMX_Flush rend in failed %x", error);
}
/* error=OMX_SendCommand(omx_aud_dec,OMX_CommandFlush, omx_codec_input_port, NULL);
if (error!=OMX_ErrorNone){
Log::getInstance()->log("Audio", Log::DEBUG, "OMX_Flush codec out failed %x", error);
}*/
/* if (!video->CommandFinished(omx_aud_dec,OMX_CommandFlush,omx_codec_input_port)) {
Log::getInstance()->log("Audio", Log::DEBUG, "flush cmd codec input failed");
}*/
error=OMX_SendCommand(omx_clock,OMX_CommandFlush, omx_clock_output_port, NULL);
Log::getInstance()->log("Audio", Log::DEBUG, "**DP3**");
if (error!=OMX_ErrorNone){
Log::getInstance()->log("Audio", Log::DEBUG, "OMX_Flush clock out failed %x", error);
}
error=OMX_SendCommand(omx_aud_rend,OMX_CommandFlush, omx_rend_clock_port, NULL);
Log::getInstance()->log("Audio", Log::DEBUG, "**DP4**");
if (error!=OMX_ErrorNone){
Log::getInstance()->log("Audio", Log::DEBUG, "OMX_Flush rend clock failed %x", error);
}
Log::getInstance()->log("Audio", Log::DEBUG, "deallocatecodecsomx mark 6");
and the hang occurs after DP0 but before DP1. The "aud_rend ChangeComponentState" log entry does not appear either.
Thanks, can you nail it down a big further and go into videoomx changecomponentstate method and see where it hangs there.
I suspect the OMX_ call there... (If I am right please try my advise about comment out some code a few posts above).
Marten
The hang is in the line
error=OMX_SendCommand(handle,OMX_CommandStateSet,type,0);
in VideoOMX::ChangeComponentState.
I already commented out the lines in audioomx.cc.
Ok, then the reason is that something breaks the communication to the omx stuff on the videocore.
And it is not the audio change...
Well this will be difficult.
Marten
@Marten
Attached is a debug.log, where the client will hang if I jump from 50% to 20% of the recording, Log says that network logging is disabled.
Using latest git with protocollchanges.
This is reproducable with this recording.
Any Ideas?
@ hondansx
This is something different. Can you please put log messages into " void Player::switchState(UCHAR toState, ULONG jumpFrame)" , maybe also restartatframe() there your deadlock occurs. But we have to investigate.
@davep
Your problem is caused, by an interuption of the audio and video feeding threads inside an omx command, we have to find out, where it occurs.
So can you please put log message in videomx and audioomx inside DeliverMediaPacket( so that we can see where the threads is forcefully exited, when the omx connection is damaged. (So in which command it was)
@both I thought these issues were closed, but it seems that I was wrong.
Marten.
Quote from: MartenR on November 01, 2012, 21:42:50
@ hondansx
This is something different. Can you please put log messages into " void Player::switchState(UCHAR toState, ULONG jumpFrame)" , maybe also restartatframe() there your deadlock occurs. But we have to investigate.
Attached is a new log (play.log), where I can see that it hangs on demuxer->put(threadBuffer + writeLength, thisRead - writeLength)
Is the error in DemuxerTS (dbg.log)?
while(writeLength < thisRead)
{
logger->log("Player", Log::DEBUG, "Put in");
thisWrite = demuxer->put(threadBuffer + writeLength, thisRead - writeLength);
logger->log("Player", Log::DEBUG, "Put out");
writeLength += thisWrite;
if (!thisWrite)
{
// demuxer is full and can't take anymore
threadLock();
threadWaitForSignal();
threadUnlock();
}
threadCheckExit();
}
Quote from: MartenR on November 01, 2012, 21:42:50
Your problem is caused, by an interuption of the audio and video feeding threads inside an omx command, we have to find out, where it occurs.
So can you please put log message in videomx and audioomx inside DeliverMediaPacket( so that we can see where the threads is forcefully exited, when the omx connection is damaged. (So in which command it was)
These are rather large functions and so difficult to instrument. Also it seems that adding more debug code reduces the likelihood of failure. However I do see a consistent signature of the failure in the log:
12:39:26.999358 [debug] 2031 BoxStack - Update called
12:39:27.000129 [debug] 2031 BoxStack - Locked for update
12:39:27.000760 [debug] 2031 BoxStack - Unlocked for update
12:39:27.000918 [debug] 2031 Timers - Starting cancel timer 0x2a9cb4 1, list size = 3
12:39:27.001107 [debug] 2031 Timers - Removed timer for 0x2a9cb4 ref 1
12:39:27.001844 [debug] 2031 Timers - Starting set timer 1
12:39:27.002931 [debug] 2031 Timers - Timer set for 0x2a9cb4 ref 1
12:39:27.003144 [debug] 2031 Timers - Starting set timer 1
12:39:27.004074 [debug] 2031 Boxx - Destruct, now 7
12:39:27.004224 [debug] 2031 Player - LOCKED
12:39:27.004301 [debug] 2031 Player - SKIP FORWARD 60 SECONDS
12:39:27.005327 [debug] 2031 Video - ++++DP0
12:39:27.005496 [debug] 2031 Video - ++++DP1
12:39:27.005573 [debug] 2031 Video - ++++DP2
12:39:27.005649 [debug] 2031 Video - ++++DP2a
12:39:27.006861 [debug] 2031 DemuxerTS - getFrameNumfromPTS pts 3288940265 deleted 21 difference 0
12:39:27.007045 [debug] 2031 Player - Switch state from 1 to 7
12:39:27.007127 [debug] 2031 VFeed - Stop1
12:39:27.008377 [debug] 2031 VFeed - Stop2
12:39:27.008582 [debug] 2031 AFeed - Stop1
12:39:27.010694 [debug] 2031 AFeed - Stop2
This pattern of video calls immediately after the skip does not appear if the skip is successful. Here is the section of code in videoomx.cc:
Log::getInstance()->log("Video", Log::DEBUG, "++++DP2");
if (!cur_input_buf_omx) {
input_bufs_omx_mutex.Lock();
if (input_bufs_omx_free.size()==0) {
input_bufs_omx_mutex.Unlock();
//Log::getInstance()->log("Video", Log::DEBUG, "Deliver MediaPacket no free sample");
Log::getInstance()->log("Video", Log::DEBUG, "++++DP2a");
return 0; // we do not have a free media sample
}
Log::getInstance()->log("Video", Log::DEBUG, "++++DP2b");
cur_input_buf_omx=input_bufs_omx_free.front();
cur_input_buf_omx->nFilledLen=0;
cur_input_buf_omx->nOffset=0;
cur_input_buf_omx->nTimeStamp=intToOMXTicks(0);
input_bufs_omx_free.pop_front();
input_bufs_omx_mutex.Unlock();
}
Log::getInstance()->log("Video", Log::DEBUG, "++++DP3");
so it seems that the function returns successfully?
@davep
Yes, on this run the function returned sucessfully (if it was not entered) again.
Hmm, maybe the audio thread is causing troubles.
Or the point, that there are no free buffers and deallocateomx can not emit a buffer with EOS???
No real clue.
Marten
@ hondansx
it is unlikely that the demuxerts code is making something.
I suspect, that at the endit will hang at putting it to the stream.
I am sorry but I am afraid, that you have to do the same inside demuxerts (I suspect submitpacket and then in the end putting it to the stream).
Marten
@davep
Please also add to audioomx, log message. I do not think that the videoomx thread causes problems, since it exits cleanly.
Quote from: MartenR on November 02, 2012, 21:37:53
@davep
Please also add to audioomx, log message. I do not think that the videoomx thread causes problems, since it exits cleanly.
I did log audioomx but it seemed that the video function was the last to be called. However I've now added logging to the entry and to every exit point and it seems that there may be a problem:
13:29:50.929267 [debug] 2126 Remote - CECLOG: 42622 8 >> 04:44:04
13:29:50.929566 [debug] 2126 Remote - CECLOG: 42622 4 >> TV (0) -> Playback 1 (4): user control pressed (44)
13:29:50.929754 [debug] 2126 Remote - CECLOG: 42622 16 key pressed: right (4)
13:29:50.934198 [debug] 2126 Audio - ++++IN
13:29:50.934417 [debug] 2126 Audio - ----4
13:29:50.937258 [debug] 2126 VDR - RR sleep - opcode 7
13:29:50.939620 [debug] 2126 Audio - ++++IN
13:29:50.939771 [debug] 2126 Audio - ----4
13:29:50.941122 [debug] 2126 Timers - Timer firing for client 0x25a07c ref 2
13:29:50.942435 [debug] 2126 Boxx - Construct, now 8
13:29:50.943731 [debug] 2126 VVideoRec - Draw bar clocks
13:29:50.945727 [debug] 2126 Audio - ++++IN
13:29:50.947276 [debug] 2126 DemuxerTS - getFrameNumfromPTS pts 6878675788 deleted 8 difference 0
13:29:50.948233 [debug] 2126 VVideoRec - 0:09:25 / 1:00:50
13:29:50.948914 [debug] 2126 BoxStack - Update called
13:29:50.949016 [debug] 2126 BoxStack - Locked for update
13:29:50.953240 [debug] 2126 VDR - Rxd a response packet, requestID=609, len=100000
13:29:50.954256 [debug] 2126 VDR - RR unsleep
13:29:50.956589 [debug] 2126 BoxStack - Unlocked for update
13:29:50.957784 [debug] 2126 Timers - Starting cancel timer 0x25a07c 1, list size = 3
13:29:50.957936 [debug] 2126 Timers - Removed timer for 0x25a07c ref 1
13:29:50.958998 [debug] 2126 Timers - Starting set timer 1
13:29:50.959302 [debug] 2126 Timers - Timer set for 0x25a07c ref 1
13:29:50.959408 [debug] 2126 Timers - Second rollover - CHECK FIXME
13:29:50.959483 [debug] 2126 Timers - Starting set timer 1
13:29:50.959566 [debug] 2126 Boxx - Destruct, now 7
13:29:50.959649 [debug] 2126 Player - LOCKED
13:29:50.962920 [debug] 2126 Player - SKIP FORWARD 60 SECONDS
13:29:50.961781 [debug] 2126 Timers - sending timer to 0x25a07c with parameter 2
13:29:50.963544 [debug] 2126 VVideoRec - Draw bar clocks
13:29:50.964785 [debug] 2126 DemuxerTS - getFrameNumfromPTS pts 6878677408 deleted 8 difference 0
13:29:50.964960 [debug] 2126 Player - Switch state from 1 to 7
13:29:50.965044 [debug] 2126 VFeed - Stop1
13:29:50.968532 [debug] 2126 DemuxerTS - getFrameNumfromPTS pts 6878677768 deleted 8 difference 0
13:29:50.968804 [debug] 2126 VVideoRec - 0:09:25 / 1:00:50
13:29:50.969084 [debug] 2126 VFeed - Stop2
13:29:50.969206 [debug] 2126 AFeed - Stop1
13:29:50.969924 [debug] 2126 BoxStack - Update called
13:29:50.970044 [debug] 2126 BoxStack - Locked for update
13:29:50.972577 [debug] 2126 AFeed - Stop2
13:29:50.974870 [debug] 2126 BoxStack - Unlocked for update
13:29:50.975064 [debug] 2126 Timers - Second rollover - CHECK FIXME
13:29:50.975146 [debug] 2126 Timers - Starting set timer 1
13:29:50.975228 [debug] 2126 Timers - timerEventFinished for 0x25a07c
13:29:50.975306 [debug] 2126 Timers - timerEventFinished RESTART for 0x25a07c
The ++++ lines are the function entry and ---- marks the exits. It seems that we do enter just before the skip and never exit.
I will try to narrow down the point of failure, but this is a complex function with many code paths and may take a while...
QuoteThe ++++ lines are the function entry and ---- marks the exits. It seems that we do enter just before the skip and never exit.
That is exactly what I want to know. The audio thread is cancel, so the function can be exited at any command through a cancelation point and if the cancelation point is inside an omx call, the communication with the video hardware is lost. So I need to know through which command the audio thread is exiting so that I can prevent this.
Marten
Not as difficult as I feared 8)
The failing line is
error = vw->ProtOMXEmptyThisBuffer(omx_aud_rend/*dec*/, cur_input_buf_omx);
at the end of the function. I suspect there is a timing issue somewhere as the failure changed depending on how many logging statements were included - in some cases the hang problem disappeared completely. This is the output with one log statement immediately before the above line:
15:54:15.905686 [debug] 2028 Remote - CECLOG: 64502 16 received data: header:00030004 p0:00044404 p1:00000000 p2:0000000
0 p3:00000000 reason:4
15:54:15.906636 [debug] 2028 Remote - CECLOG: 64503 8 >> 04:44:04
15:54:15.906842 [debug] 2028 Remote - CECLOG: 64504 4 >> TV (0) -> Playback 1 (4): user control pressed (44)
15:54:15.906996 [debug] 2028 Remote - CECLOG: 64504 16 key pressed: right (4)
15:54:15.913810 [debug] 2028 Boxx - Construct, now 8
15:54:15.909163 [debug] 2028 VDR - Rxd a response packet, requestID=1318, len=100000
15:54:15.914351 [debug] 2028 VVideoRec - Draw bar clocks
15:54:15.915965 [debug] 2028 DemuxerTS - getFrameNumfromPTS pts 6051208009 deleted 15 difference 0
15:54:15.916198 [debug] 2028 VVideoRec - 0:15:56 / 1:00:28
15:54:15.916888 [debug] 2028 BoxStack - Update called
15:54:15.917002 [debug] 2028 BoxStack - Locked for update
15:54:15.917506 [debug] 2028 BoxStack - Unlocked for update
15:54:15.917635 [debug] 2028 Timers - Starting cancel timer 0xa638ac 1, list size = 3
15:54:15.917737 [debug] 2028 Timers - Removed timer for 0xa638ac ref 1
15:54:15.918042 [debug] 2028 VDR - RR unsleep
15:54:15.904278 [debug] 2028 Timers - sending timer to 0xa638ac with parameter 2
15:54:15.924730 [debug] 2028 VVideoRec - Draw bar clocks
15:54:15.925799 [debug] 2028 Timers - Starting set timer 1
15:54:15.926074 [debug] 2028 Timers - Timer set for 0xa638ac ref 1
15:54:15.926177 [debug] 2028 Timers - Second rollover - CHECK FIXME
15:54:15.926252 [debug] 2028 Timers - Starting set timer 1
15:54:15.926330 [debug] 2028 Boxx - Destruct, now 7
15:54:15.926410 [debug] 2028 Player - LOCKED
15:54:15.926483 [debug] 2028 Player - SKIP FORWARD 60 SECONDS
15:54:15.928447 [debug] 2028 Audio - ****9
15:54:15.929584 [debug] 2028 DemuxerTS - getFrameNumfromPTS pts 6051209179 deleted 15 difference 0
15:54:15.929759 [debug] 2028 Player - Switch state from 1 to 7
15:54:15.929843 [debug] 2028 VFeed - Stop1
15:54:15.930666 [debug] 2028 VFeed - Stop2
I was also on the hunt of deadlocks, I also found this line.
Please try the following changed code in videoomx and please confirm that at least this navigation deadlock issue is gone: (there might be multiple deadlock, so a new one might appear!)
void VideoOMX::DeinterlaceFix()
{
int oldcancelstate;
int oldcanceltype;
Demuxer* demux=Demuxer::getInstance();
pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldcancelstate);
pthread_setcanceltype(PTHREAD_CANCEL_DEFERRED, &oldcanceltype);
clock_mutex.Lock();
OMX_ERRORTYPE error;
OMX_PARAM_PORTDEFINITIONTYPE port_def_type;
memset(&port_def_type,0,sizeof(port_def_type));
port_def_type.nSize=sizeof(port_def_type);
port_def_type.nVersion.nVersion=OMX_VERSION;
port_def_type.nPortIndex=omx_codec_output_port;
error=OMX_GetParameter(omx_vid_dec,OMX_IndexParamPortDefinition, &port_def_type);
if (error != OMX_ErrorNone) {
Log::getInstance()->log("Video", Log::DEBUG,
"OMX_IndexParamPortDefinition fix failed %x", error);
clock_mutex.Unlock();
return;
}
if (port_def_type.format.video.nFrameWidth == demux->getHorizontalSize()
&& port_def_type.format.video.nFrameHeight == demux->getVerticalSize()){
Log::getInstance()->log("Video", Log::DEBUG,
"Deinit first frame fix");
deint_first_frame=false;
WaitForEvent(omx_vid_dec,OMX_EventPortSettingsChanged);
DisablePort(omx_vid_dec,omx_codec_output_port,false);
DisablePort(omx_vid_sched,omx_shed_input_port,false);
DisablePort(omx_vid_deint,omx_deint_output_port,false);
DisablePort(omx_vid_deint,omx_deint_input_port,false);
port_def_type.nPortIndex=omx_deint_input_port;
error = OMX_SetParameter(omx_vid_deint, OMX_IndexParamPortDefinition,
&port_def_type);
if (error != OMX_ErrorNone) {
Log::getInstance()->log("Video", Log::DEBUG,
"Set OMX_IndexParamPortDefinition1 failed %x", error);
clock_mutex.Unlock();
pthread_setcancelstate(oldcancelstate, NULL);
pthread_setcanceltype(oldcanceltype, NULL);
return;
}
port_def_type.nPortIndex=omx_deint_output_port;
error = OMX_SetParameter(omx_vid_deint, OMX_IndexParamPortDefinition,
&port_def_type);
if (error != OMX_ErrorNone) {
Log::getInstance()->log("Video", Log::DEBUG,
"Set OMX_IndexParamPortDefinition2 failed %x", error);
clock_mutex.Unlock();
pthread_setcancelstate(oldcancelstate, NULL);
pthread_setcanceltype(oldcanceltype, NULL);
return;
}
EnablePort(omx_vid_dec,omx_codec_output_port,false);
EnablePort(omx_vid_deint,omx_deint_input_port,false);
EnablePort(omx_vid_deint,omx_deint_output_port,false);
EnablePort(omx_vid_sched,omx_shed_input_port,false);
}
clock_mutex.Unlock();
pthread_setcancelstate(oldcancelstate, NULL);
pthread_setcanceltype(oldcanceltype, NULL);
}
Edit: I have put this and some other fixes to git. Maybe it helps, but other problems might remain. Look if it is fix and if not do the diagnosis as described before. The problem is that these problems highly depend on timing, so it is very difficult to reproduce them on other machines with other network setups.
Quote from: MartenR on November 02, 2012, 13:37:53
@ hondansx
it is unlikely that the demuxerts code is making something.
I suspect, that at the endit will hang at putting it to the stream.
I am sorry but I am afraid, that you have to do the same inside demuxerts (I suspect submitpacket and then in the end putting it to the stream).
Marten
What I can tell is, that in the end it jumps to DemuxerTS::processTS into the payload section (while olders do not) to parseTSPacketDetails and it looks like it will hang in
ULLONG pts_expected = me.pts + 90000*((int)(((double)(frame_num - me.frame)) / tfps));
while (pts_expected > (1LL<<33)) pts_expected -= (1LL<<33);
And no I am stuck and do not know what I can do..
@Marten
Would it be okay for you, to send you this file?
First impression is that the latest git fixes my hanging problem. Maybe there are some other quirks but we can fix those later.
Many thanks, and well done.
Dave
I've not had that much time to do my own debugging on this but I've been following this closely. I've just checked out from git and rebuilt.
My first impressions was that skipping forward and back by a minute was now working all the time. However, I still have some problems with it.
It seems to work properly a lot more of the time than it did before. The sequence I see is:
- press remote button:
a. screen goes black
b. blank progress bar appears with "-:-- -:--" for the position and length
c. video starts
d. yellow progress bar and position and length appear
e. OSD times out and status bar disappears
Normally this happens pretty quickly. A few times (and this has happened as the first time I skip on starting playback or after several skips) "d" never happens and the OSD disappears before the times or yellow progress bar appear. If I press "OK" to show the progress bar, it remains blank with the dashes instead of times.
If I try to skip again after this has happened, only steps "b" and "e" seem to happen, i.e. it displays the blank progress bar (with the >>| icon) which then times out and no skipping occurs. If I pause, the blanks status bar is shown.
If I skip a few more times, it becomes unresponsive and I eventually need to use "kill -KILL" to kill vompclient. If I stop playback after the failed skip and then resume, the resume position is a minute forwards.
This behaviour seems worse with some recordings than others. I had a feeling it might be where I'm skipping from "within programme" to "within advert" or vice versa and there is a change in audio format, bitrate, or something that is tripping up the audio or video decoder. I think I've just disproved that theory, though!
I have found one of my recordings that seems to cause a blank status bar and not skip after skipping 4-5 times. I'll produce some debug output and see if there's anything obvious.
Laz
@hondansx
Quote@Marten
Would it be okay for you, to send you this file?
Depends, how big is it?
Can you please make a log of pts_expected?
I have the feeling, that if I now the number I can fix it.
(Btw. if it really hangs there, the bug should be there also on mvp).
@laz
The -:-- thing is probably related to a bug in obtaining the time from the videoomx object, which empties the database of pts entries. (Anyway it recovers after a while)
For the hang I need to have information where the hang occurs, because it can be really anywhere in the code. (and it does not hang on my machine)
Marten
Quote
Can you please make a log of pts_expected?
I have the feeling, that if I now the number I can fix it.
(Btw. if it really hangs there, the bug should be there also on mvp).
Yes, this happens on my mvp.
This is the output, which runs since 30 min. ;-).
demuxerts.cc:
while (pts_expected > (1LL<<33)) {
Log::getInstance()->log("DemuxerTS", Log::DEBUG, "parseTSPacketDetails pts_expected: %llu 1LL: %llu", pts_expected, (1LL<<33));
pts_expected -= (1LL<<33);
}
10:03:52.898206 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961601221124321 1LL: 8589934592
10:03:52.898461 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961592631189729 1LL: 8589934592
10:03:52.898717 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961584041255137 1LL: 8589934592
10:03:52.898973 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961575451320545 1LL: 8589934592
10:03:52.899229 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961566861385953 1LL: 8589934592
10:03:52.899483 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961558271451361 1LL: 8589934592
10:03:52.899739 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961549681516769 1LL: 8589934592
10:03:52.899994 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961541091582177 1LL: 8589934592
10:03:52.900249 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961532501647585 1LL: 8589934592
10:03:52.900505 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961523911712993 1LL: 8589934592
10:03:52.900761 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961515321778401 1LL: 8589934592
10:03:52.901016 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961506731843809 1LL: 8589934592
10:03:52.901272 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961498141909217 1LL: 8589934592
10:03:52.901527 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961489551974625 1LL: 8589934592
10:03:52.901782 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961480962040033 1LL: 8589934592
10:03:52.902149 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961472372105441 1LL: 8589934592
10:03:52.902425 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961463782170849 1LL: 8589934592
10:03:52.902680 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961455192236257 1LL: 8589934592
10:03:52.902935 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961446602301665 1LL: 8589934592
10:03:52.903190 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961438012367073 1LL: 8589934592
10:03:52.903492 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961429422432481 1LL: 8589934592
10:03:52.903755 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961420832497889 1LL: 8589934592
10:03:52.904011 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961412242563297 1LL: 8589934592
10:03:52.904267 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961403652628705 1LL: 8589934592
10:03:52.904524 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961395062694113 1LL: 8589934592
10:03:52.904779 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961386472759521 1LL: 8589934592
10:03:52.905035 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961377882824929 1LL: 8589934592
10:03:52.905291 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961369292890337 1LL: 8589934592
10:03:52.905547 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961360702955745 1LL: 8589934592
10:03:52.905803 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961352113021153 1LL: 8589934592
10:03:52.906059 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961343523086561 1LL: 8589934592
10:03:52.906315 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961334933151969 1LL: 8589934592
10:03:52.906571 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961326343217377 1LL: 8589934592
10:03:52.906827 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961317753282785 1LL: 8589934592
10:03:52.907084 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961309163348193 1LL: 8589934592
10:03:52.907342 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961300573413601 1LL: 8589934592
10:03:52.907599 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961291983479009 1LL: 8589934592
10:03:52.907855 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961283393544417 1LL: 8589934592
10:03:52.908112 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961274803609825 1LL: 8589934592
10:03:52.908369 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961266213675233 1LL: 8589934592
10:03:52.908625 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961257623740641 1LL: 8589934592
10:03:52.908881 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961249033806049 1LL: 8589934592
10:03:52.909137 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961240443871457 1LL: 8589934592
10:03:52.909394 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961231853936865 1LL: 8589934592
10:03:52.909649 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961223264002273 1LL: 8589934592
10:03:52.909906 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961214674067681 1LL: 8589934592
10:03:52.910163 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961206084133089 1LL: 8589934592
10:03:52.910420 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961197494198497 1LL: 8589934592
10:03:52.910675 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961188904263905 1LL: 8589934592
10:03:52.910932 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961180314329313 1LL: 8589934592
10:03:52.911187 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961171724394721 1LL: 8589934592
10:03:52.911443 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961163134460129 1LL: 8589934592
10:03:52.911700 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961154544525537 1LL: 8589934592
10:03:52.911956 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961145954590945 1LL: 8589934592
10:03:52.912316 [debug] 170 DemuxerTS - parseTSPacketDetails pts_expected: 18435961137364656353 1LL: 8589934592
I need the first line that occurs of parseTSpacketsdetails.
It seems that it is out of bounds.
The question is why...
Marten
Good:
10:14:50.710182 [debug] 241 Demuxer - Entering audio sync: Video PTS = 120954145
10:14:50.710429 [debug] 241 Demuxer - Entering audio sync: Audio PTS = 120887173
10:14:50.713508 [debug] 241 DemuxerTS - parseTSPacketDetails pts_expected: 8710867137 1LL: 8589934592
10:14:50.714225 [debug] 241 Demux - START packet_type à 224
10:14:50.715185 [debug] 241 Demux - END sent: 34852 packet.getSize: 34852
Bad:
10:14:56.801418 [debug] 264 Demuxer - Entering audio sync: Video PTS = 8548456737
10:14:56.801668 [debug] 264 Demuxer - Entering audio sync: Audio PTS = 0
10:14:56.805154 [debug] 264 DemuxerTS - parseTSPacketDetails pts_expected: 18446744073668019761 1LL: 8589934592
10:14:56.805411 [debug] 264 DemuxerTS - parseTSPacketDetails pts_expected: 18446744065078085169 1LL: 8589934592
10:14:56.805664 [debug] 264 DemuxerTS - parseTSPacketDetails pts_expected: 18446744056488150577 1LL: 8589934592
10:14:56.805917 [debug] 264 DemuxerTS - parseTSPacketDetails pts_expected: 18446744047898215985 1LL: 8589934592
10:14:56.806171 [debug] 264 DemuxerTS - parseTSPacketDetails pts_expected: 18446744039308281393 1LL: 8589934592
10:14:56.806426 [debug] 264 DemuxerTS - parseTSPacketDetails pts_expected: 18446744030718346801 1LL: 8589934592
10:14:56.806680 [debug] 264 DemuxerTS - parseTSPacketDetails pts_expected: 18446744022128412209 1LL: 8589934592
10:14:56.806933 [debug] 264 DemuxerTS - parseTSPacketDetails pts_expected: 18446744013538477617 1LL: 8589934592
/code]
Sorry to bother you again, I need the values of all variables in the expression:
me.pts + 90000*((int)(((double)(frame_num - me.frame)) / tfps));
It seems like an signed unsigned mismatch.
Quote from: MartenR on November 04, 2012, 12:21:36
Sorry to bother you again, I need the values of all variables in the expression:
me.pts + 90000*((int)(((double)(frame_num - me.frame)) / tfps));
It seems like an signed unsigned mismatch.
Doesn't matter.
Is this the right thing?
ULLONG pts_expected = me.pts + 90000*((int)(((double)(frame_num - me.frame)) / tfps));
Log::getInstance()->log("DemuxerTS", Log::DEBUG, "parseTSPacketDetails me.pts: %i frame_num: %lu me.frame: %lu tfps: %f", me.pts, frame_num, me.frame, tfps);
Log::getInstance()->log("DemuxerTS", Log::DEBUG, "parseTSPacketDetails pts_expected: %llu tfps: %f", pts_expected, tfps);
while (pts_expected > (1LL<<33)) {
Log::getInstance()->log("DemuxerTS", Log::DEBUG, "parseTSPacketDetails pts_expected: %llu 1LL: %llu", pts_expected, (1LL<<33))
pts_expected -= (1LL<<33);
}
Yes this is the right thing one log line of the first occurence should show me, what is happening.
Marten
P.S: @laz the -:-- issue should be solved by latest git
Next try.
@hondansx
We coming close, the frame number is a problem. It is too big.
Please print before
if (frameCounting && numpicts &&
packet.getPacketType() >= PESTYPE_VID0 &&
packet.getPacketType() <= PESTYPE_VIDMAX)
the content of frameNumber and numpicts.
Either frameNumber or numpicts are making trouble.
Marten
Your recent git update (Fix invalid time) does seem at first sight to have fixed the problem I had with skipping. I've only had a quick test so far, skipping minute-wise (or 10-s wise) back and forth about half an hour into a film and it seems pretty resilient. Even repeatedly pressing skip as fast as I could didn't cause it to hang. This recording is one that always caused a hang after a 4-5 skips before this.
:)
I'll stop being careful with how rapidly I skip and test some more...
Laz
Quote from: MartenR on November 04, 2012, 15:17:18
@hondansx
We coming close, the frame number is a problem. It is too big.
Please print before
if (frameCounting && numpicts &&
packet.getPacketType() >= PESTYPE_VID0 &&
packet.getPacketType() <= PESTYPE_VIDMAX)
the content of frameNumber and numpicts.
Either frameNumber or numpicts are making trouble.
Marten
New log
@hondansx
Thanks for being patient.
I just recognized that part of your debug code is wrong.
Can you please change
Log::getInstance()->log("DemuxerTS", Log::DEBUG, "parseTSPacketDetails me.pts: %i frame_num: %lu me.frame: %lu tfps: %f", me.pts, frame_num, me.frame, tfps);
to
Log::getInstance()->log("DemuxerTS", Log::DEBUG, "parseTSPacketDetails me.pts: %ulld frame_num: %lu me.frame: %lu tfps: %f", me.pts, frame_num, me.frame, tfps);
Note, that frame num is long long.
Sorry, I should have spotted that earlier.
Marten
Marten
new try..
Log::getInstance()->log("DemuxerTS", Log::DEBUG, "TEST parseTSPacketDetails me.pts: %lu frame_num: %lu me.frame: %lu tfps: %f", me.pts, frame_num, me.frame, tfps);
Log::getInstance()->log("DemuxerTS", Log::DEBUG, "TEST pts_expected: %llu tfps: %f", pts_expected, tfps);
Sorry that is stilln ot working me.pts have to be "me.pts: %llu" two l !
If there is no second l it corrupts the output of the other variables.
Marten
Quote from: MartenR on November 04, 2012, 19:05:30
Sorry that is stilln ot working me.pts have to be "me.pts: %llu" two l !
If there is no second l it corrupts the output of the other variables.
Marten
Fine, now looks better.
long long pts_expected = me.pts + 90000LL*((long long)(((double)(frame_num - me.frame)) / tfps));
while (pts_expected < 0) pts_expected += (1LL<<33);
while (pts_expected > (1LL<<33)) pts_expected -= (1LL<<33);
Can you please try this code?
Marten
Yes it works. Many thanks.
Is there any chance to get it into the mvp git too?
QuoteIs there any chance to get it into the mvp git too?
I do not think, that this is necessary, you can try to build it for mvp also from the raspberry git.
(If it does not work, tell me were the problems is....)
Marten