mmal: Get component port state debug information

[julianscheel]

Is there a similiar mechanism for mmal to OMX_GetDebugInformation for openmax which enables us to see the state of the active mmal components and their ports?
I am looking for an issue where mmal_port_flush() does not seem to work properly on image_fx component - my internal refcounting says that still one buffer is in use by the input port. It would be quite helpful to have a chance to see the internal port state.

[popcornmix]

Yes, /opt/vc/bin/mmal_vc_diag should do what you want.
Source: https://github.com/raspberrypi/userland/blob/master/interface/mmal/vc/mmal_vc_diag.c

[julianscheel]

Thanks, this looks very helpful :)
While talking about it: Is it required to lock mmal component creation/destruction and port configuration with a mutex when it is possibly done from different threads? In VLC the decoder, filter and vout are running in different threads.

[popcornmix]

I believe mmal and openmax are thread safe, so you don't need additional locking.
Obviously you need to protect your own structures (e.g. when accessed from a mmal callback).

[julianscheel]

Ok, this is what I assumed. I'm currently seeing a deadlock when I do aggressive start/stop loops. See this backtrace:
http://pastie.org/private/1hnlmgt0guk8dqd8t1oklq

Looking at Thread 6, which is teardown of the decoder module, which just called mmal_component_disable and at Thread 4 which just tries to send a picture to the deinterlace input port it looks like mmal_vc_send_message and mmal_vc_sendwait_message might be blocking each other. Could this be? Maybe @6by9 has some thoughts, too?

[julianscheel]

Here is a slight variation of the deadlock:
http://pastie.org/private/glaqerdbule6gg2r3unlq

In this case Thread 5 and 4 seem to block each other - Thread 5 being the deinterlace filter calling mmal_port_send_buffer and Thread 4 the vout calling mmal_port_format_commit. This is due to an aspect ratio change happening right before stopping the playback.

[julianscheel]

And the next hit, this time the flush on image_fx does not seem to finish as expected. My internal refcounting says that 1 buffer is held by the output port still. mmal_vc_diag mmal-stats seems to confirm this:

# mmal_vc_diag mmal-stats
component       port        buffers     fps delay
ril.image_fx            0 [in ]rx   32          27.3    86637
ril.image_fx            0 [in ]tx   32          27.3    86636
ril.image_fx            0 [out]rx   65          54.6    126535
ril.image_fx            0 [out]tx   64          53.9    80008
ril.video_render        0 [in ]rx   135         39.6    507479
ril.video_render        0 [in ]tx   135         39.6    507478

Related stacktrace is here: http://pastie.org/private/vwpmjsqqptmvazvj3jfkdw
This time I can't see any mmal calls which might block each other.

Any thoughts?

[6by9]

Locking around component create/destroy: it should all be internally safe for different threads to be creating and destroying components simultaneously.
If multiple threads are talking to the same component, you can also use mmal_component_acquire and mmal_component_release to take an additional ref count on a component from the other threads, so it only actually destroys when both threads have released. See https://github.com/raspberrypi/userland/blob/master/interface/mmal/mmal_component.h

I thought it was possible to do the same refcounting with pools as well, but can't see it at the moment (may have been on a different dev branch - I'm sure I've used it. You can call mmal_pool_destroy on a pool before the last buffer is released, and it only actually gets destroyed when that buffer is finally released. Perhaps I'm misremembering).

Do remember that port_disable will flush back any buffers owned by the components, so ensure that your callback isn't blocked when you make the call. (Doesn't appear to be an issue from your callstacks)

On the VideoCore side, there is a single thread that brokers all MMAL requests from the ARM. A couple of longer running tasks are offloaded to worker threads, but otherwise most things are run sequentially.
It may be that something has managed to wedge that broker thread, or otherwise bork VCHI. That really needs the ability to see inside the GPU.
@popcornmix did we ever get anywhere with ramdumps and offline analysis for Pi? I know we had it on other platforms but memory says there was some issue with doing it on the Pi.

[julianscheel]

@6by9 Thanks for the feedback. If it would help for analysing things on the GPU I could prepare a SD card image containing the test-case.

[6by9]

Does it need to be a full SD card image, or just a test app? I'd need to rebuild the firmware anyway to use a debug build, so if it can just be an app on top of a known rpi-update release hash then it would be easier.

[popcornmix]

@6by9 I've not tried to get the ramdump stuff going on Pi. Can't think why it wouldn't work.
Did this use vcdbg for analysis or something else?

[6by9]

@popcornmix - switching to email.

[julianscheel]

@6by9 let me try building VLC in recent raspbian and provide it as tarball. Was a bit tricky last time I did... Making up a minimal test case is probably a hard task in this case.

[6by9]

If it needs to be a full SD card image then I can cope, just that it's easier to have an environment I know I can hack around.

[julianscheel]

Build is running on a clean raspbian install - I should be able to provide you with prebuilt binaries +source tomorrow.

[julianscheel]

I was able to finally build things properly for raspbian (using a cross toolchain linking against nfs-exported raspbian root actually).
Actually the firmware from today breaks everything for mmal+vlc, because the codec component won't emit the initial format changed event at all. With mmal_vc_diag you can see that it's fed with buffers but the output port will never send one out. Is it a problem with the new firmware that we do not push any output buffers to the output port before receiving the first format change buffer? So far those status update buffers did not rely on having picture output buffers ready on the port... I can reproduce this issue on my system, btw.

If I downgrade to what I have on my systems currently (firmware from Feb 4) things are better but still odd and different to how it behaves on my system. After the first few frames have been decoded the whole system stalls for several seconds - no mmal events occur in that time and then it resumes spontaneously. It keeps running smooth until a mmal component create/destroy (ie deinterlace plugin reset on aspect ratio change) occurs. Then it stalls again.

In the hope you might see more than I do I create a package though:
http://jusst.de/files/vlc-raspbian.tar.xz

Use it like this:

cd /home/pi
wget http://jusst.de/files/vlc-raspbian.tar.xz
tar -xvf vlc-raspbian.tar.xz

export VLC_PLUGIN_PATH=/home/pi/vlc-raspbian/install/usr/lib/vlc/plugins
export LD_LIBRARY_PATH=/home/pi/vlc-raspbian/install/usr/lib
export PATH=/home/pi/vlc-raspbian/install/usr/bin:$PATH

vlc -vvv somefile.mp4

Additionaly I packaged my aspect-ratio change source - you should ideally run this on another PC which has VLC installed (version shouldn't matter much) - it will stream a continuous mpeg-ts with aspect ratio change every second to 239.2.2.2:10101 (feel free to change the address in the script as you like)

wget http://jusst.de/files/aspect.tar.xz
tar -xvf aspect.tar.xz
cd aspect
./stream-aspect-short.sh

You can then play the stream on the pi using:

with deinterlace: vlc -vvv udp://@239.2.2.2:10101
without deinterlace: vlc -vvv --deinterlace 0 udp://@239.2.2.2:10101

Be aware it is a mpeg2 encoded stream so you need to have the mpeg2 license activated. The case without deinterlace runs smooth after the initial stall is over. The one with deinterlace stalls over and over again because the deinterlace filter is recreated.

And finally some notes for building:
The vlc directory contains my full build in the build-cross subdirectory. There are two scripts (configure.sh and build.sh) to help with configuring and building. In my case /tmp/raspbian-root was just a regular raspberry which exported its rootfs via nfs like this:

172.27.0.0/21(rw,async,no_root_squash,no_subtree_check)

The rootfs needs one fix though: /usr/lib/arm-linux-gnueabihf/libdl.so has to be recreated as relative link in favor of the absolute one it normally is in that rootfs

sudo rm /usr/lib/arm-linux-gnueabihf/libdl.so
cd /usr/lib/arm-linux-gnueabihf/
sudo ln -s ../../../lib/arm-linux-gnueabihf/libdl.so.2 libdl.so

I used the linaro toolchain from the tools repository for building - change configure.sh to use your paths...

And finally just in case you don't experience these odd stalls on start/component creation or find a way to fix it you can use this python script to run the actual loop test which I run to hit the deadlocks I reported last days:

wget http://jusst.de/files/stream-zap-test.tar.xz
tar -xvf stream-zap-test.xz
cd stream-zap-test
./stream-loop-test.py udp://@239.2.2.2:10101

This will just restart the playback every 5 seconds, which stresses the component create/destroy cycle in addition to the permanent recreation of image_fx deinterlace due to the aspect change.

The sources for the mmal modules in vlc reside in modules/hw/mmal/ - just in case you're interested in looking into them.

I hope this is somehow understandable :)

[popcornmix]

If you can identify when the firmware broke things, it would be helpful.
There were vdec3 changes in Hexxeh/rpi-firmware@0c9001b which should be harmless, but could have changed behaviour.

Also there were some memory reductions here:
Hexxeh/rpi-firmware@a8b36a5
which no longer forces at least 7 buffers. Might be worth checking if setting more "extra buffers" on video_decode helps.
(Additionally, setting "extra buffers" to 3 when using deinterlace should no longer be required).

[julianscheel]

@popcornmix Hexxeh/rpi-firmware@0c9001b introduces the regression for me.

[popcornmix]

Do files play with omxplayer with new firmware?
If not can you provide a video file/player that works with older firmware and fails with newer firmware?

[julianscheel]

@popcornmix omxplayer seems to work well. You can use vlc to see the issue - it seems to appear with mpeg2 codec only. You can use the vlc bundle I uploaded along with the aspect ratio stream.
If you need I can try to generate a more simplistic testcase for this, but unfortunately this will be by the end of next week only as I have to leave now and will be out of office until thursday. So only remote access in that time, no real development work...

[deborah-c]

Thanks for the detailed reports; I'll look at this as soon as possible. Unfortunately the change to the video decoder firmware at Hexxeh/rpi-firmware@0c9011b is quite large, and we don't have the same ability to regression test it at Pi Towers that used to be possible at Broadcom (we're working on it...). However, if this only affects MPEG-2, we should be able to get to the bottom of it quickly.

[julianscheel]

@6by9 Thank you. Regarding mpeg2 only: I wouldn't take this as proven so far - but probable. So it probably makes sense to look for mpeg2 related things first regarding the regression.

[popcornmix]

@julianscheel can you try latest rpi-update firmware? Includes a fix from @deborah-c for MPEG-2 decode.

[julianscheel]

I just did a quick remote login and it seems the decoder starts up properly again now. Thanks. So we can get back to the deadlocks.
On the raspbian build I still experience these odd stalls on component startup though. Maybe one of you guys can see something within the GPU which could explain that stall in the first place? I could imagine it's related to the deadlocks I see with my rootfs, just slightly different symptomatics.

[deborah-c]

I found that MPEG-2 decode worked poorly using that build: it complains that the TS demuxer is an invalid module, and playing from a .VOB file had very slow (~10s) startup, and then played jerkily. I'm not sure how VLC works internally -- does it use our A/V sync, or is that done on the ARM side of the world?

The regression wasn't MPEG-2 specific, but applied to all non-H.264 streams, and failed to produce images after a resolution change. VLC appears to create the initial image pool differently from omxplayer -- the latter generated a pool the same dimension that the decoder wanted, whereas VLC asked for larger images, causing an immediate resolution change.

[julianscheel]

@deborah-c Ah sorry, I forgot to post the note about the dependencies. This is what I installed for doing the raspbian build:

sudo apt-get install libavcodec54 libavformat54 libdvbpsi-dev libavcodec-dev libavutil-dev libasound2-dev libtool automake libswscale-dev

libdvbpsi is what you need for the ts demux to work.

These ~10s on statup are what I see on the raspbian build as well. At a first glance it did not look like some a/v sync issue - the a/v sync is handled on the ARM side with VLC, it's using alsa for audio output.
I actually overclock the Pi to 950/500/500 usually, but streams with not-so-high bandwidth should work well with lower frequencies. When playing a VOB file it might be that some module in the input chain did not work very well for you. TS files/streams are what I test with usually. So after installing the dependencies you should be able to play that aspect changing stream.

Thanks for the init analysis and fix. I wonder a bit why we create a pool with a different size initially, I will take a look into it. Maybe we can avoid it.

[julianscheel]

@deborah-c, @6by9 I've prepared a new build of vlc for raspbian which fixes that startup stall.
The old one was missing an initialisation which was not exhibited when compiling with my buildroot toolchain and caused an arbitrary offset being applied to the timestamps. I have rebased the code against latest vlc git HEAD, which unfortunately dropped support for libdvbpsi 0.7 series, so I had to update to libdvbpsi from jessie:

sudo apt-get install -t jessie libdvbpsi9 libdvbpsi-dev

I also use gdb from jessie, because the wheezy gdb does not properly support the dwarf4 debug symbols generated by the toolchain.

Once you have updated the dependencies and VLC you should be able to use the aspect streaming script on another machine and start the testcase with

./stream-loop-test.py udp://@239.2.2.2:10101

as described in my older post. Just let this one run for a while (sometimes it runs quite some hours without failing). It will change aspect ratio frequently and restart the stream every 5 seconds. At some point it will just stop. Now you can attach the debugger and should be able to see that one of the mmal components is either waiting for a mmal_port_* call to finish or is waiting for buffers to be returned. The last case I had where it failed I couldn't even check the mmal internal state because mmal_vc_diag mmal-stats did stall immediately as well.

[julianscheel]

Is the testcase working for you?

[6by9]

Sorry, not had any time to look at anything Pi related. Hopefully will over the weekend.

[julianscheel]

Ok, this gave me the "oh crap" moment :)
We did have a guard in front of video_render component to ensure an opaque picture is not sent twice to the input port. But not in front of the image_fx component. I guess this is also what's causing the assertion when not using zero_copy. It just was not as visible as it is now because we used the local buffer pools. Instead of sending the same buffer header twice, the opaque buffer data was attached to a new buffer_header for both transmits and thus we could not see it's been the actually the same image twice.

@deborah-c Could this match the exception you see in the VC?

I've started a testrun with zero_copy and guard in front of input now and a second one using the old approach without zero_copy and local buffers but with the guard included. Let's see how they go.

[deborah-c]

My guess would be that what I saw was a use-after-free, in effect; that could be the symptom of passing something twice, but I'm more inclined to suspect either errant shutdown code or accidental parallelism. Annoyingly, I had a run stopped at an assert when I came in today, but the (rather static and motion sensitive) debugger had disconnected; I've had another that did the same, one that just stalled completely with no immediately obvious reason, and my current run has been running for a long, long while...

[julianscheel]

From time to time the error hides for a while, I've had that as well...
I will setup a verification test to figure out if in the non-zero_copy case the double-send to image_fx is indeed happening when the crash occurs in the meantime. Actually in the tons of stashed testing code I created over the last weeks I had already added a guard in front of image_fx once, but obviously stashed it away later. But this might likely have been because of some other issue covering the real one at that point... So let's see how test goes and if you happen to get a usable debug run.

[julianscheel]

My test runs survived the night - I think the double send into image_fx really seems to be the problems root cause...

[julianscheel]

@deborah-c Happened to hit a debuggable assert in the meantime?
My testruns are still alive, so I'm confident that the issue is not triggered anymore now. I assume that sending the same buffer (or even worse the same data attached to two different buffer headers) twice into image_fx when running in opaque mode is really to be accounted as userspace fault, right? So in that case I'd say no further action on the firmware would be required. What do you think, @deborah-c, @6by9?

[6by9]

I guess we can add a sanity check to ensure the queue linked list remains valid, but yes it sounds like is really a userspace error. Ensuring the pools keep a sane allocated count would also be useful - just had a related thought on how it may have got into that state :-)

(Not sure how we detect the double submit as I don't think the component has a listed of already submitted buffers. It'll take some investigation)

[julianscheel]

@6by9 I also thought about ways for sanity checks, but doing that efficiently seems not really like a simple task. Actually for the case where the same buffer_header is submitted twice it can be detected by scanning the queue for duplicates on each _put. This is in fact how I nailed the issue down on my side. But this requires a loop over the queue each time which might hurt depending on the queue size. And secondly this wouldn't have helped in the initial error case at all, because there I did that magic data reuse with different buffer headers, so the queue looked just fine. So to detect that, one would have to actually check the data pointer and I really don't know how feasible that is.

Maybe adding some comment/documentation stating the opaque buffers must not be send to input ports twice would be a good idea though...

[6by9]

Unless I'm missing something, the mmal_queue_put calls can trap it when the buffer is returned and released, but ideally we want to do it when the mmal_port_send_buffer call is made. I can't see a useful queue there to check as most stuff just passes through down to the component.
A quick scan of the queue shouldn't take too long - typically we're looking at a max of 20 items, so not masses of processing required.
Those who play with buffer->data need to be brave :-) though adding a check of buffer->data is only one extra comparison per queue entry. It still won't pick up the case where the duplicate buffer has already been dequeued again for reuse.

No buffer, opaque or otherwise, should be sent to a port twice. As you say, munging buffer->data pointers masked things further.

[popcornmix]

This was my sanity check:
http://pastebin.com/7PXaHdcX

It only helps if the duplicates are in the same queue at the same time. If the queues are drained quickly, then you may never spot the issue. However this did detect a bug in my kodi/mmal code.

I wonder if the MMAL_BUFFER_HEADER_T itself could contain a flag that indicates arm/vc ownership. If you try to submit a buffer that you don't have ownership of (e.g. submitting buffer a second time to video_render) then it fails.

@6by9 @luked99 does that sound possible?

[6by9]

@popcornmix Your sanity check still adds the duplicate buffer to the queue, so we're then still doomed and potentially stuck within the for (q = queue->first; q; q = q->next) loop of your sanity check. Better than nothing, but we can possibly do better.

ARM/VC ownership also has a niggle. There was the intent that you can do mmal_buffer_header_acquire to increment the refcount on a buffer header as a very cheap splitter. The buffer only gets released back to the pool (and then returned to the source component) when refcount hits 0. That means that you should be able to submit the same buffer header to different components simultaneously. I don't think we've ever used that in anger, but it is there. It really needs zero copy to work properly with opaque buffers though (needs to get the correct refcounting/lifetime on the reloc heap object of the source port buffer payload).

As I commented earlier, tracking which buffers are submitted to a component isn't easy at the moment. But we could have a MMAL_QUEUE in the core of submitted buffers that can be checked on a send to avoid duplicates.

My thought from earlier for image pools and the allocated field is that

• alloc
• release (refcount now 0 - free and decrement allocated)
• acquire (asserts, but increments the refcount)
• release (refcount now 0 - free and decrement allocated again)

= badness.
It is a very dubious thing to do as the image has technically been released back to the image pool, but it appears to not be blocked, and will leave allocated in the sort of bad state Julian was seeing. I don't think there is a way of failing an acquire, so I think it is scream and shout in the logs and increment allocated again.

[popcornmix]

Any patches for additional asserts on the gpu side would be welcome.

[luked99]

Can you use a counter on each buffer header to check for double submission?

The port would store the most recently received counter value and complain
if buffers are received with a value equal or lower.

You would need to do something when it wraps obviously, or just have a 64
bit counter.

It ought to be possible to do entirely in the mmal core code.
On 1 Apr 2015 14:20, "popcornmix" notifications@github.com wrote:

Any patches for additional asserts on the gpu side would be welcome.

—
Reply to this email directly or view it on GitHub
#377 (comment)
.

[6by9]

Can you use a counter on each buffer header to check for double submission?

There's no obligation to submit buffers in the same order they are produced. And what if the client generates buffers to be submitted to say the video encoder? Those won't have been tagged at all.

@popcornmix I have an untested patch for vc_pool. I'll ping it to you by email. Addressing the MMAL core/vc_api to do sanity checking needs some more thought. Your patch would be a safety net, but still leaves things in a bad place.

[luked99]

There's no obligation to submit buffers in the same order they are produced

Perhaps not, but you'll get some very weird effects. It's a pretty niche scenario. I guess you could use this to generate videos where alternate frames are swapped or something, for making peoples' brains explode.

And what if the client generates buffers to be submitted to say the video encoder? Those won't
have been tagged at all.

They won't be opaque.

[6by9]

Slideshow with 2 Image decodes and alternating between the output of the two being fed into video render? If we're failing things on this "error", then a false positive even on a niche use case would be a pain.

I don't think there is a need for them to be opaque images to cause issues. As in Julian's case, submit the same buffer twice to VC and you will get two callbacks when they are returned. If you call mmal_buffer_header_release on each instance then he managed to screw over as the linked list in MMAL_QUEUE (duplicate buffer gets stuffed on the end, so buffers from old->next to the end get lost).
At least I think that's what happens - the number of function pointers that can be set to numerous different things is not fun.
I think it could be prevented by not setting "header->priv->refcount = 1" from mmal_pool_buffer_header_release(), so on a subsequent release refcount won't be decremented to 0 (it'll actually do the decrement to get to -1 - eek!). However that would then require the client to do more than just a mmal_queue_get(pool->queue) when it wanted a new buffer, and an API change is bad news this far in.

[popcornmix]

Latest firmware has a couple of sanity checks from 6by9 so repeated submission of a buffer should produce an complaint in the assert log and may be less likely to wedge things (although I suspect bad stuff may still happen).

[6by9]

Yes, it cleans up the image pool handling, but I haven't looked at the MMAL queue linking doing silly things on double buffer release yet.

[Ruffio]

@julianscheel has this issue been resolved?

[julianscheel]

@Ruffio The actual issue was on the application side and has been resolved. Discussion was ongoing whether it would be wise to add some sanity check at mmal level to detect this kind of bad usage. Maybe @popcornmix, @6by9 or @deborah-c want to add some thoughts? If it appears to be not worth adding a check, let's close the issue.

[6by9]

Created #707 to cover the sanity checking at the MMAL level, so this can be closed.