[BUG]Movie texture only decoding every 2nd frame

[jean-claude]

Tried exactly the same approach with test_2

(1) at init (with quad not visible by the camera): one junk message then ok
(2) as soon as the quad is in the camera's frustum:
spam, spam, spam...

:movies:ffmpeg(error): MS RLE: ended frame decode with bytes left over (26830 < 26832)
:movies:ffmpeg(error): MS RLE: ended frame decode with bytes left over (27104 < 27106)
:movies:ffmpeg(error): MS RLE: ended frame decode with bytes left over (27100 < 27102)
:movies:ffmpeg(error): MS RLE: ended frame decode with bytes left over (27114 < 27116)
:movies:ffmpeg(error): MS RLE: ended frame decode with bytes left over (27202 < 27204)
:movies:ffmpeg(error): MS RLE: ended frame decode with bytes left over (27126 < 27128)
:movies:ffmpeg(error): MS RLE: ended frame decode with bytes left over (27194 < 27196)
:movies:ffmpeg(error): MS RLE: ended frame decode with bytes left over (27106 < 27108)
:movies:ffmpeg(error): MS RLE: ended frame decode with bytes left over (26924 < 26926)
...

funny enough: apparently there's always an offset of 2 bytes?!?


BUT: in this case, the movie plays!

[drwr]

I'm not able to reproduce this spammage. My copy of your test_2 plays fine with no per-frame error messages. Curious.

David

[jean-claude]

(1) here is test_1.avi
https://rapidshare.com/files/250936288/test_1.avi

please note that this file is insanely heavy!!

(2) again, with pview things are almost ok (apart 1 or 2 warnings)
but the issue pops up whenever the app is started with no view on the video (ie video not visible by the camera) and then while moving the camera as soon as the quad supporting the video display enters in the camera frustum.

please note too: that I have 4 task_chains threaded, but the video is simply loaded as mentionned in my previous post..

[jean-claude]

I'm puzzled, wind back:just with test_2 on pview, aren't you observing a spam with this???
https://rapidshare.com/files/3078077278/pview.exe
https://rapidshare.com/files/1990279957/test_2.avi

[drwr]

Nope, and not with the buildbot Panda3D-1.8.0 neither. It plays happily, quietly. Maybe it's a difference in the codecs we have installed on our machines; maybe it has something to do with CPU performance. Who knows?

David

[jean-claude]

Did you try my pview (it is compiled with SSE2 and aligned Z16)? Maybe this is related (ie byte alignment shift...)

btw. I just noticed you made some changes in the cvs (ffmpeg...). Let me regenerate a build!

[jean-claude]

with the latest cvs I'm now getting this build error:

1>[ 25%] Building Interrogate database built/pandac/input/libmovies.in
1>built/bin/interrogate -srcdir panda/src/movies -Ipanda/src/movies -Dvolatile -Dmutable -DCPPPARSER -D__STDC__=1 -D__cplusplus -D__inline -longlong __int64 -D_X86_ -DWIN32_VC -D_WIN32 -D_MSC_VER=1500 -D"_declspec(param)=" -D_near -D_far -D__near -D__far -D__stdcall -DNDEBUG -oc built/tmp/libmovies_igate.cxx -od built/pandac/input/libmovies.in -fnames -string -refcount -assert -python-native -Sbuilt/include/parser-inc -Ipanda/src/movies -Sbuilt/tmp -Sbuilt/include -Sthirdparty/win-python/include -Sthirdparty/win-libs-vc9/ffmpeg/include -DMAKEPANDA= -DBUILDING_PANDA -module panda -library libmovies config_movies.h ffmpegAudio.h ffmpegAudioCursor.h ffmpegVideo.h ffmpegVideoCursor.h ffmpegVirtualFile.h inkblotVideo.h inkblotVideoCursor.h microphoneAudio.h movieAudio.h movieAudioCursor.h movieVideo.h movieVideoCursor.h movies_composite.cxx userDataAudio.h userDataAudioCursor.h
1> *** Error in ffmpegVideoCursor.h near line 87, column 20:
1> parse error
1>Error parsing file: 'ffmpegVideoCursor.h'
1>'built' n'est pas reconnu en tant que commande interne
1>ou externe, un programme exécutable ou un fichier de commandes.
1>Interrogate failed, retrieving debug output...
1>Storing dependency cache.

I think it's time for me to go to bed!
Tomorrow is another day...

[drwr]

I can't run your pview.exe without also having your libpanda.dll, libp3dtool.dll, and so on, as well as any thirdparty dll's your build is made against (including ffmpeg if required).

Sorry about the build error; I just committed a fix that might address it. Not entirely sure why this latest version presents this build error that wasn't a problem in earlier versions. But my latest fixes don't do anything about your ffmpeg errors, so I don't think it will help this particular problem much.

David

[drwr]

jean-claude, another thought occurred to me: does setting "ffmpeg-max-readahead-frames 0" in your Config.prc file improve the error situation in your case? This disables the use of threads in ffmpeg playback; I'm wondering if the problem might be a subtle race condition somewhere.

David

[jean-claude]

Hi David,
Just tried to run test_1.avi with:

Code: Select all

load_prc_file_data("", "support-threads 0");
load_prc_file_data("", "ffmpeg-max-readahead-frames 0");
load_prc_file_data("", "sync_video 1");

Same effect, apart that the fps is now divided by 12!
This occurs as soon as the camera is 'looking at' the video quad

Just for the record the same file used to work ok in the app a few weeks ago... Weird!

[jean-claude]

Ok,
Just tried with:

Code: Select all

load_prc_file_data("", "support-threads 1");
load_prc_file_data("", "notify-level-ffmpeg fatal");
load_prc_file_data("", "sync_video 1");

It does work this way, as well as it used to do last fortnight.
Apparently ffmpeg error reporting is screwing up something...

btw. don't know if this may be related, I recently noticed some cracklings in sounds unrelated to the video (the sounds play in a different task_chain...)

[jean-claude]

Just to mention, after a few hours working ok, here is a crash that was (sporadically) generated.

Call stack:

[Frames below may be incorrect and/or missing, no symbols loaded for msvcrt.dll]
avformat-50-panda.dll!7078269a()
avcodec-51-panda.dll!641c2fd2()
libpanda.dll!FfmpegVideoCursor::fetch_packet(double default_time=-1.#QNAN00000000000) Line 717 + 0x13 bytes C++
libpanda.dll!FfmpegVideoCursor::fetch_frame(double time=4.2958338861434704e-285) Line 818 + 0x1f bytes C++

time=-1.#QNAN00000000000 ??? !!!

[drwr]

Hmm, I'm still trying to track down a mysterious crash that another user has been reporting to me, and it might be related to yours as well.

Unfortunately, the suspicious non-number in the stack trace doesn't mean very much, because it's common for the stack data to become meaningless after a crash. Still, it's useful to see that the last Panda function before the crash was fetch_packet(). Is this in the child thread, and not in the main thread? Do you have more than one ffmpeg video texture in your game? Did the crash appear immediately after creating the texture, or some time later, after rendering a few frames?

There are a few more possible fixes I've recently committed, so if you get a chance to try the latest and see if it helps, I'd appreciate it. In particular, I did find a definite problem with the log message callbacks, so you should be able to turn those back on now and not crash (though you might want them off anyway to avoid the spammage).

David

[jean-claude]

Is this in the child thread, and not in the main thread?

main thread

Do you have more than one ffmpeg video texture in your game?

two

Did the crash appear immediately after creating the texture, or some time later, after rendering a few frames?

It appeared a long time (ie 15mn) after creating the texture. But for all the time no video was within the camera frustum... (ie the video are textured on a different region of the scene)

[drwr]

Hmm, that's very strange--are you absolutely sure about the thread of the crash? Because, other than during initial texture creation, the main thread shouldn't call into fetch_frame() again--that should only be the child thread. If the main thread really *is* calling into fetch_frame() 15 minutes after texture creation, that would indeed be a serious error.

Is there more to the stack trace, showing where fetch_frame() had been called from?

David

[drwr]

Just checked in a few more possible fixes, though I admit I'm casting about in the dark here.

David

[jean-claude]

Sorry, I understood that you were talking about a different thread_chain and since my texture is loaded in the core program actually I don't know which thread was calling the fetch_frame.

I have no more info than the call stack dump, and for the time being I haven't been able to reproduce the bug.

BTW. Some pb with the new build

1>[ 32%] Building C++ object built/tmp/vision_composite1.obj
1>cl /wd4996 /wd4275 /wd4267 /wd4101 /wd4273 /DPANDA_WIN7 /DWINVER=0x601 /Fobuilt/tmp/vision_composite1.obj /nologo /c /Ipanda/src/vision /Ibuilt/tmp /Ibuilt/include /Ithirdparty/win-python/include /I"C:/Program Files (x86)/Microsoft DirectX SDK (June 2010)/include" /Ithirdparty/win-libs-vc9/jpeg/include /Ithirdparty/win-libs-vc9/artoolkit/include /Ithirdparty/win-libs-vc9/opencv/include /Ithirdparty/win-libs-vc9/directcam/include /DMAKEPANDA= /MD /Zi /Ox /Ob2 /Oi /Ot /arch:SSE2 /fp:fast /DFORCE_INLINING /DNDEBUG /GL /Oy /Zp16 /Fdbuilt/tmp/vision_composite1.pdb /DBUILDING_VISION /EHa /Zm300 /DWIN32_VC /DWIN32 /W3 panda/src/vision/vision_composite1.cxx
1>vision_composite1.cxx
1>c:\users\jc\desktop\panda_build_bot\source maj\panda3d\panda\src\vision\webcamVideoDS.cxx(598) : error C2065: '_last_start' : undeclared identifier
1>c:\users\jc\desktop\panda_build_bot\source maj\panda3d\panda\src\vision\webcamVideoDS.cxx(599) : error C2065: '_next_start' : undeclared identifier

[drwr]

Sorry, I understood that you were talking about a different thread_chain and since my texture is loaded in the core program actually I don't know which thread was calling the fetch_frame.

Ah, I understand. OK. In the debugger, there's a different call stack for each active thread; you can usually tell whether you're looking at the main thread stack, or some other thread's stack.

Some pb with the new build

Oops, fixed! Sorry about that.

David

[jean-claude]

maybe it's not relevant anymore (simply because a lot of code has changed since then) but just for remembrance could it be something related to post 1 of http://www.panda3d.org/forums/viewtopic.php?t=12244 ?

libpanda.dll!FfmpegVideoCursor::export_frame(unsigned char * data=0x2fcad218, bool bgra=false, int bufx=512) Line 249 + 0x24 bytes C++
libpanda.dll!FfmpegVideoCursor::fetch_into_texture(double time=13.078053811331131, Texture * t=0x04ac8340, int page=0) Line 482 C++
libpanda.dll!MovieTexture::cull_callback(CullTraverser * __formal=, CullTraverser * __formal=) Line 389 + 0x19 bytes C++
libpanda.dll!TextureAttrib::cull_callback(CullTraverser * trav=0x3891f3e0, const CullTraverserData & data={...}) Line 459 + 0x12 bytes C++

[ThomasEgi]

one more thing that i noticed that made me go "huh?" at first.

i happened to run across a video which usually plays just fine. but sometimes it "freezes" the picture.

upon investigation with pstats i found that ffmpeg is still decoding all frames + it starts to "seek".

it some point it simply continues to display the video frames again. and the seek time disappears in pstats.

the beginning or cuts in the movie are common points. i investigated the video bit rates and it seems to occur on I-frames mostly, where the bitrate peaks far beyond the average.

so my conclusion whats going on would be:
panda tells ffmpeg to decode a frame. ffmpeg doesnt finish within the frame's time. panda tells ffmpeg to display the next frame, ffmpeg seeks forward and is still in a hurry to catch up effectively missing the next frames,too.

skipping a few frames aint that bad. but when a big I-frame is at the beginning of the movie, it sometimes happens to freeze the first video frame for 5 to 10 seconds.

vlc player just skipps one or 2 frames and continues.

any way to improve this behaviour? (i know i shouldnt cut it quite that close with the cpu performance but one keyframe can freeze the entire vid in worst case)

[drwr]

Hmm, that does sound like a bad situation. Not entirely sure how to solve it--one of the problems is that there's not really a way to seek quickly through a video stream. The fastest way to move from frame 0 to frame 3 is to decode frame 1 and frame 2. (You can get a little bit faster by minimizing the decoding effort of 1 and 2 if you know you won't be displaying these frames anyway, but this is a challenge to determine in the new dual-threaded implementation.)

But if you're seeing "seeking" happen in the sub-thread, that's exactly what's happening: the sub-thread has determined that it's fallen behind, and is trying to decode frames quickly to catch up.

Still, there are a few weaknesses in the current implementation. Are you running a looping video? The current implementation doesn't communicate the loop ahead of time to the sub-thread, so it's always surprised when it finds it has to decode the first frame again after having finished decoding the last frame. If it knew that ahead of time, it could have frame 0 ready and waiting by the time the main thread asked for it. I could fix that little design weakness without too much trouble, but that won't help if you're explicitly seeking the video yourself.

I could also add an option where, instead of discarding the too-old frames, it displayed them anyway. This would mean that instead of a long freeze, you might get a relatively short freeze, then the video would start to play (but it would be a little bit behind). Then it would play a bit faster than normal as it caught up to itself. Would that be an improvement, do you think? The audio would still play at its natural speed.

One easy thing to do right now would be to try to increase the priority of the decoding thread, with the config setting "ffmpeg-thread-priority high".

Also, you should make sure that you have the latest code (as of last Friday or so). I've been making ongoing changes in this system.

David

[ThomasEgi]

code is from tuesday. not running looping.

it is not that i require a fix for that.
was just one of the vids and we reencoded it to mpeg2 for better performance on that cpu already.
i was just wondering if that worst-case can be somehow improved in general.

what surprises me is that seeking adds up on top of the regular decoding.
wont the seeking eat into the regular decoding tasks cpu share? like, 2 decoding threads and still no frames displayed?

[drwr]

what surprises me is that seeking adds up on top of the regular decoding.

This impression is due to a bit of a misleading presentation from PStats, I think. In the sub-frame, there's not a clear definition of what constitutes a "frame", so it arbitrarily defines that one PStats frame has passed when a single frame from the video stream has been decoded.

This means that you get a fairly constant bar graph for decoding video frames in PStats, and any other work that the thread does (like seeking) appears as additional work on top of that. So when the sub-thread needs to seek a bit, then decode an additional frame, the only visible change in PStats is that there is more additional work in "seek".

It *is* a problem if you see many frames go by with lots of seek time. That means the seeks aren't enough to catch up.

"seek", by the way, for the most part just means decoding the next frame(s) in a less-precise way so we can catch up to the frame we actually want to display. The video codec doesn't provide a way to actually seek from one frame to the next without decoding the intervening frames.

David

[ThomasEgi]

another very curious "bug" i ran into.

setting
texture-minfilter linear_mipmap_linear
in the config file, and playing videos hammered performance into the ground. i know it is not a bug because panda is just doing as told and creating mipmaps. but it is very hard to track down that issue should you ever encounter it. might be worth a warning/hint message when you use mipmaps and videos

[drwr]

Hmm, it's a good point. Maybe movie textures shouldn't automatically respect texture-minfilter, but rather a different variable like movie-minfilter.

David