Messages

I'd mentioned this in the thread about skipping and it may or may not be connected.

Pressing pause during playback of a recording always seems to take about 2 s to actually stop playback. About half of the time, the video freezes instantly but the audio carries on for a couple of seconds before stopping.

If I then unpause, both video and audio start but the video runs speeded up for a second or so, presumably to catch up with the audio that stopped about 2 s in front when it paused. I thought it was doing this every time but not when I've looked a bit more closely.

Before an earlier update from git, I was seeing things like:
23:18:01.831696 [debug]  2015 Player - Switch state from 1 to 2
23:18:01.833666 [debug]  2015 Video - enter pause
{snip}
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

About a 3 s gap after entering pause before the CommandFinished timeout from the video and also an error from OMX_EmptyThisBuffer from the audio.

Trying this again now (after the git update today to remove some deadlocks) I see the same behaviour but I can't see the same errors in the debug output!

VVideoRec::drawBarClocks seems to be called about 18 times on pausing: is that correct? It just seems to be redrawing the same thing.

Laz

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

(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

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

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

It looks like my main problem was the TCP receive window size. On your suggestion, I reduced it from the default(?) of 65536 to 32768 and so far so good. All 4 of my available HD channels seem happy: both video and audio working well. (Or no problems apart from the drivers for my HD card being a bit dodgy at times!) HD recordings seem to be fine too.

CPU usage varies about 40-50%, depending on the channel (presumably with bit-rate). In comparison, SD stuff seems to be around 25-30%. I'll try to test HD stuff a bit more thoroughly.

One thing I've also spotted is that SD recordings and live TV give me LOTS of "[mp3 @ 0x47127b20] incorrect frame size" messages if I run "vompclient -n". I guess this is because it's an MP2 stream being decoded by CODEC_ID_MP3. No problem with the decoding, though and avcodec.h has "CODEC_ID_MP3, ///< preferred ID for decoding MPEG audio layer 1, 2 or 3"! They could probably be quietened with a call to av_log_set_level()!

Cheers,

Laz

I had a quick test earlier on and I did have sound on live BBC1 HD. However, after a short while (30 s?) sound disappeared and I had to kill vompclient.

Was video ok? So was it running? If not, it was probably the video blocking the audio playback this will be fix within the next hour in git.
It it is something different, please test if you can reproduce it with an recording, so that I can do something to fix it.

Sorry, I wasn't specific enough. Video kept going fine but sound was lost after a few seconds.

I have now pulled in your SIGILL bug fix and a quick test shows that it plays back that recording I uploaded with sound and video. CPU usage hovers around 50%. After a few tens of seconds, the audio cuts out and in every few seconds.

I am not sure what you mean with cuts out and in?
Is it like stopping and continuing playback? I suggest that you play with the TCPwindowsize in settings, it can be a network performance issue.

The video was fine and playing smoothly but the sound would be perfect for a few seconds, disappear for a few seconds, and then be back perfect again.

I have just checked out your latest patches and am recompiling.

I'll do a bit of testing and hopefully post some log files later on.

Cheers,

Laz

Support is now in git. You will need an update of the server side. Patches will appear soon here in the forum and later in git.
There is one problem, the video has two streams, the second stream is a different audio type but also flagged as aac latm, so if you select this one there will be noise and distortion for your speaker, so please do not select him.

Of course only recordings tested.

Marten

The second audio track is, I think, audio description for the partially sighted. It doesn't surprise me in the slightest that it has a format different from the one it claims!

I had a quick test earlier on and I did have sound on live BBC1 HD. However, after a short while (30 s?) sound disappeared and I had to kill vompclient.

I managed to update my sources and test between your bug-fix for the SIGILL bug. I got that the first time I ran it but it started fine the next time (when I did the quick test mentioned).

I have now pulled in your SIGILL bug fix and a quick test shows that it plays back that recording I uploaded with sound and video. CPU usage hovers around 50%. After a few tens of seconds, the audio cuts out and in every few seconds.

Another quick test with live ITV1 HD and I watched several minutes of video and sound that all worked perfectly.

Maybe it's just a signal quality issue (I've never really watched the HD channels before): I'll do some more intensive tests this evening once my daughter has gone to bed so I don't get crawled over as I do it...

Looks good, though.



Laz

LATM is only a special way of packing aac. Since I am always implementing unpacking directly into vomp, this is not much of an issue.
The only issue will be if aac decoding is fast enough.
For me it is important, that I do the implementation soon, before I will forget the detail of the audio implementation.
The reason why it is not implemented yet, is that on SD it was never an issue and I do receive dvb transmission in HD with AAC.

OK. I have just recorded 5 minutes from BBC HD (I'll PM you a link to it once I've copied it to my web server). I will also upload a debug log from vompclient starting up and then showing BBC1 HD live TV for a few seconds.

Bizarrely, when I tried to play back the 5 minute recording with vompclient it doesn't even show the video. The debug log is then full of lots of:

20:29:46.240877 [debug]  2698 VDR - RR unsleep
20:29:46.257776 [debug]  2698 VDR - RR sleep - opcode 7
20:29:46.328412 [debug]  2698 VDR - Rxd a response packet, requestID=178, len=100000
20:29:46.329942 [debug]  2698 VDR - RR unsleep
20:29:46.346665 [debug]  2698 VDR - RR sleep - opcode 7
20:29:46.416953 [debug]  2698 VDR - Rxd a response packet, requestID=179, len=100000
20:29:46.418518 [debug]  2698 VDR - RR unsleep
20:29:46.443122 [debug]  2698 VDR - RR sleep - opcode 7
20:29:46.512892 [debug]  2698 VDR - Rxd a response packet, requestID=180, len=100000

messages (intermixed with other messages earlier on) that continue until I stop playback. After that, vompclient becomes unresponsive, although remote presses are logged. If I try to kill with CTRL-C or kill PID the debug log has messages saying it is stopping but it doesn't; I have to resort to kill -KILL PID to kill it.
-------------------------------------------------------------
I had a go with omxplayer and that seems to play back the file fine, both video and audio and the output from that is:

$ omxplayer -o hdmi 00001.ts
file : 00001.ts result 0 format mpegts audio streams 2 video streams 1 chapters 0 subtitles 1
Video codec omx-h264 width 1920 height 1080 profile 100 fps 50.000000
Audio codec aac_latm channels 2 samplerate 48000 bitspersample 16
Subtitle count : 1 state off : index 1

have a nice day

omxplayer did sit on 100% CPU usage for about 10 s not appearing to do anything before the file began playing and CPU dropped down to a modest 21% or so. I'm not sure whether that is normal or not: it's the first time I've run it! Maybe the very start of the file has errors that confuses it and also vompclient? I can record another few minutes if you wish.

-------------------------------------------------------------
The same recording plays back fine with mplayer from stock Debian testing and it outputs:

MPlayer svn r34540 (Debian), built with gcc-4.7 (C) 2000-2012 MPlayer Team
mplayer: could not connect to socket
mplayer: No such file or directory
Failed to open LIRC support. You will not be able to use your remote control.

Playing 00001.ts.
libavformat version 53.21.0 (external)
Mismatching header version 53.19.0
TS file format detected.
VIDEO H264(pid=101) AUDIO AAC LATM(pid=102) NO SUBS (yet)!  PROGRAM N. 132
FPS seems to be: 25.000000
Load subtitles in ./
Failed to open VDPAU backend libvdpau_r300.so: cannot open shared object file: No such file or directory
[vdpau] Error when calling vdp_device_create_x11: 1
==========================================================================
Opening video decoder: [ffmpeg] FFmpeg's libavcodec codec family
libavcodec version 53.35.0 (external)
Mismatching header version 53.32.2
Selected video codec: [ffh264] vfm: ffmpeg (FFmpeg H.264)
==========================================================================
==========================================================================
Opening audio decoder: [ffmpeg] FFmpeg/libavcodec audio decoders
[aac_latm @ 0x7f40deaa7380]audio config changed
AUDIO: 48000 Hz, 2 ch, s16le, 0.0 kbit/0.00% (ratio: 0->192000)
Selected audio codec: [fflatm] afm: ffmpeg (FFmpeg AAC in LATM)
==========================================================================     
AO: [pulse] 48000Hz 2ch s16le (2 bytes per sample)                             
Starting playback...                                                           
Unsupported PixelFormat 61                                                     
Unsupported PixelFormat 53                                                     
Unsupported PixelFormat 81                                                     
Movie-Aspect is 1.78:1 - prescaling to correct movie aspect.                   
VO: [xv] 1920x1080 => 1920x1080 Planar YV12                                     
A:69872.4 V:69871.9 A-V:  0.414 ct: -0.252 117/117 174% 16%  4.2% 109 0

-----------------------------------------------------------------------------
Here are the lines from my channels.conf:

BBC One HD :634000000:B8C23D23M256Y0:T:0:6601=27:6602=eng@17,6606=eng@17:0;6605=eng:0:17540:9018:16521:0

BBC HD :634000000:B8C23D23M256Y0:T:0:101=27:102=eng@17,106=eng@17:0;105=eng:0:17472:9018:16521:0


So, it all looks as if it might just work.

Laz

Well vomp does only support mpeg1 audio layer 1 and 2 and ac3.
So your audio format is not supported.
Anyway adding software decoding of another format should not be a big deal, if the cpu is fast enough. (I will only support stereo output, if you need more, someelse have to implement PCM multichannel support, some of the UK vomp developers interested?? ).

But I am not in the UK, so in order to implement this, I need the following:

• Please test if a vdr recording can be played back with omxplayer to ensure, that the performance of the raspberry is fast enough.
• I need a copy of your log file, and the line of the channel from your channel conf, it is likely, that I need to change the server side.
• I need a sample recording file 1-2 minutes, not to annoying content (I will probably watch the clip a hundred times).
  

The other thing I need, that it is supported by libav on raspbian.

Marten

I thought that "currently unsupported" was probably the case! Not that much of an issue for me, to be honest, because I can never tell the difference between SD and HD!

As I say, I've only had a quick play with this so far but I'll try to look into it a bit more deeply in the next few days and get back to you with what you need if it is worth it.

Assuming that libavformat and libavcodec are the same ones in the standard Debian distributions,  I doubt AAC-LATM is supported: I always had to get ffmpeg from git to get it to work with xineliboutput! If it isn't supported, I don't think it's really worth the effort at the moment (for me at least!).

Laz

Sorry if this is a known problem but I'm only just getting to speed with this!



After an evening's testing, SD recordings and live TV all work well for me. HD recordings and live TV give me video but no audio. The log shows lots of:


22:48:12.264200 [debug]  3427 Audio - We can not decompress 323 save for later 1 42f03024 0
22:48:12.277927 [debug]  3427 Audio - We can not decompress 322 save for later 1 42f03024 0
22:48:12.291955 [debug]  3427 Audio - We can not decompress 323 save for later 1 42f03182 15e
22:48:12.322358 [debug]  3427 Audio - We can not decompress 315 save for later 1 42f03024 0

and the occasional
[mp3 @ 0x1da8f00] incomplete frame
or
[mp3 @ 0x1da8f00] Header missing

This is all with DVT-T in the UK (Freeview). From my experiences with softdevice and xineliboutput, I seem to remember that the audio of these channels is in a fairly obscure format (AAC in LATM) and I think it needed a fairly recent ffmpeg from git to decode it properly. It used to need a fairly recent git checkout to decode it properly: is libavcodec + libavformat in raspian up-to-date enough to decode this audio?

Or maybe I'm missing something somewhere?!

Laz

I've been using vomp with a couple of Media MVPs on and off for a few years now (usually when my main xineliboutput client is borked!). When I happened upon this port for the Raspberry pi, I finally had a reason to buy one!

I've only really started testing it as a vomp client in the last day or so but I've been really impressed so far and can see it taking over from my xineliboutput client that seems to need restarting more and more every day!

I finally have CEC working on the third HDMI cable I'd tried but I'm seriously missing a few buttons on my Sony Bravia remote, including the ability to skip a minute, etc.

I have a wireless keyboard attached which gives me more buttons but is not a very elegant solution!

Is there a USB remote that anyone can recommend for using with vomp? I've been using one of the grey Hauppauge remotes both with my Media MVPs and also with LIRC on my other vdr boxes over the years. If I could continue to use one of those, that'd be ideal but I very much doubt that's possible!

Laz

Aha! Sounds extremely plausible, especially with the expanded OSD I'm seeing...

I am in the UK and my working D3A was bought here. The (currently,,,) non-working one could have been bought anywhere in the world.

I will try forcing PAL later on this evening...

---------------------------------------------------------------------------

Yep! Jobs a good'un!

Works fine with that added to the vomp-{MAC}.conf file. Nice to see the feature included!



Keep up the good work!

Right...I've just created a couple of log files form the output of vompclient in debug mode:

From the working D3A (currently watching stuff with it as I type this!):
http://www.club-burniston.co.uk/vdr/d3a_debug_working.log

From the non-working D3A (SCART, network, and mains swapped from the working one):
http://www.club-burniston.co.uk/vdr/d3a_debug_novideo.log

I tried to do pretty much the same keypresses on each. I've also added a few comments in the files where I pressed play, stop, etc.

All of this is with vomp 0.3.0, although I have a build environment set up so I am happy to test vompclient patches if you can come up with anything form my logs!

I won't have a chance to do any more testing until the weekend but I will post as much as I can then (well, links to logs, etc.!).

Anything else that you can think I should try? I had my suspicions that they were subtly different internally (chip revisions, etc.?) but nothing different from dmesg on the two boxes. Will take both apart and compare chip numbers!