View Issue Details

IDProjectCategoryView StatusLast Update
0004518The Dark ModGUIpublic12.06.2017 07:59
Reporterduzenko Assigned Tostgatilov  
PrioritynormalSeveritynormalReproducibilityhave not tried
Status resolvedResolutionfixed 
Product VersionSVN 
Target VersionTDM 2.06Fixed in VersionTDM 2.06 
Summary0004518: Briefing video starts decoding in background
DescriptionDuring work on 4507 I noticed that the video starts decoding automatically on TDM start.
I believe this is unnecessary and wasteful of resources.
I don't know how to do that yet but OpenAVDecoder should only run when the video actually shows.
Stack trace:
> TheDarkMod.exe!idCinematicFFMpeg::OpenAVDecoder() Line 135 C++
     TheDarkMod.exe!idCinematicFFMpeg::ResetTime(time=5692) Line 606 C++
     TheDarkMod.exe!idMaterial::ResetCinematicTime(time=5692) Line 2605 C++
     TheDarkMod.exe!idWindow::ResetCinematics() Line 2595 C++
     TheDarkMod.exe!Script_ResetCinematics(window=0x203866c0, src=0x20387034) Line 169 C++
     TheDarkMod.exe!idGuiScriptList::Execute(win=0x203866c0) Line 419 C++
     TheDarkMod.exe!idWindow::RunScriptList(src=0x20386df8) Line 2638 C++
     TheDarkMod.exe!idWindow::Time() Line 1056 C++
     TheDarkMod.exe!idWindow::RunTimeEvents(time=5692) Line 607 C++
     TheDarkMod.exe!idWindow::RunTimeEvents(time=5692) Line 612 C++
     TheDarkMod.exe!idWindow::RunTimeEvents(time=5692) Line 612 C++
     TheDarkMod.exe!idWindow::HandleEvent(event=0x0763f8d8, updateVisuals=0x00000000) Line 711 C++
     TheDarkMod.exe!idUserInterfaceLocal::HandleEvent(event=0x0763f8d8, _time=5692, updateVisuals=0x00000000) Line 350 C++
     TheDarkMod.exe!idSessionLocal::GuiFrameEvents() Line 1114 C++
     TheDarkMod.exe!idSessionLocal::Frame() Line 2689 C++
     TheDarkMod.exe!idCommonLocal::Frame() Line 2452 C++
     TheDarkMod.exe!WinMain(hInstance=0x00f60000, hPrevInstance=0x00000000, lpCmdLine=0x07754e3a, nCmdShow=10) Line 1360 C++

TagsNo tags attached.

Relationships

related to 0004519 resolvedstgatilov Investigate using videos of common formats (avi, mp4) 
related to 0004541 new Glimpse of old frames when cinematic is restarted 

Activities

stgatilov

stgatilov

02.05.2017 19:08

administrator   ~0008827

What video is it exactly?
What do you mean by "starts decoding"? Does it open the file ans allocates some buffer?
Which resources are wasted?
stgatilov

stgatilov

03.05.2017 03:59

administrator   ~0008828

Ok, as I see, all the contexts are created and all the buffers are allocated. It is quite likely that they sit without need for the whole time.

Only the videos from \video\credits\ are loaded on start. Since other videos (including ones from FM) are not loaded immediately, I suppose the issue must be fixed somewhere in GUI scripts...
duzenko

duzenko

03.05.2017 09:17

developer   ~0008829

I tested this with Accountant2.
It was specifically the briefing video that loaded on TDM startup.
Just set a breakpoint on OpenAVDecoder and see the file path in debugger.
stgatilov

stgatilov

16.05.2017 12:04

administrator   ~0008862

Last edited: 16.05.2017 12:05

This is not fully about this issue, but still important.

I have fixed noticeable slowdown at the moment video starts (which also causes starting frames to be skipped) in rev 6879.

The typical sequence of ResetTime and FrameForTime calls is:
  (when TDM starts)
    ResetTime with backend time = -1 //sets startTime to -1
  (when briefing starts)
    ImageForTime with time = 8766 //someone wants image for 8.7s after start ?!
    ResetTime with backend time = 8766 //sets startTime to 8766 ms
    ImageForTime with time = 8916 //OK, now this is 150 ms after start
    ImageForTime with time = 8958
    ... (etc)

The first ResetTime call happens in mainmenu_briefing_video.gui in window BriefingVid::Video in event onTime 0, which triggers immediately on startup because noTime is not set in the class. This call can probably be removed by changing GUI scripts, although AC2 mission uses its local version, meaning that no updates would affect it.

What causes the very first ImageForTime call --- I have no idea. I'm afraid we simply have to work with it more or less gracefully.
Before the mentioned changes, this call caused FFmpeg to decode 9 seconds of video immediately, getting out of sync with backend timer, and as a result skipping many of the initial frames. Also, the resulting (unwanted) image was briefly visible at the very beginning of the video playback.
After the mentioned change, only two first frames are really decoded because of this weird call. This takes 10 ms or less, so this is tolerable.

stgatilov

stgatilov

17.05.2017 04:22

administrator   ~0008867

Right now the idea to fix the issue is to open the file "on demand":

* InitFromFile: check that file exists + maybe check if video container is recognizable;
* ResetTime: should freshly reopen the video only if the very first frames of the video were already decoded and destroyed;

Also, both ImageFromTime and ResetTime must open FFmpeg contexts if they are not yet present. ResetTime must set startTime, ImageFromTime sets startTime only if it is not set yet.


However, I'll probably postpone this refactoring until new features related to videos are done.
stgatilov

stgatilov

12.06.2017 06:40

administrator   ~0008897

Last edited: 12.06.2017 06:48

Ok, I have some understanding now about the first call of ImageForTime.

I suppose that previously GUI events (idSessionLocal::GuiFrameEvents) were handled before backend had chance to look at its cinematics. As a result, "resetCinematics" command in GUI script (in "onTime 0" handler) took effect before backend tried to obtain its very first frame. At least, this is how it should work in my opinion =)

Now the order have changed: GUI event is fired after backend updates material. That's why we have a single ImageForTime call before ResetTime is called. Perhaps this is result of some multithreading optimizations =)


EDIT: Perfect solution would be to simply ignore ImageForTime calls which happen before ResetTime was called. However, this breaks "Score to settle" briefing (sykes.roq + brief1.roq), because its custom GUI script does not call resetCinematics at all.

stgatilov

stgatilov

12.06.2017 07:02

administrator   ~0008898

Last edited: 12.06.2017 07:03

The issue is completely fixed in svn rev 6931.

The initialization works like this:
1. InitFromFile does NOT open decoder. It only tries to open the file in order to check that it is physically present, which takes no time.
If you set "r_cinematic_checkImmediately" cvar, then it would also fully open decoder and close it immediately afterwards. This allows you to check very early that referenced video is supported, but it takes a bit of time (but not memory) during initialization.
2. ImageForTime opens decoder if it is not opened yet. Also video clock is reset to zero in this case. This is necessary to support cases like the abovementioned sykes.roq and brief1.roq, where ResetTime is not called at all.
3. ResetTime reopens decoder and resets video clock to zero. As a special optimization, decoder is not reopened if the very first frame of the video is still in the queue of decoded frames. This avoids unnecessary reopening in the usual calls sequence: ImageForTime, ResetTime, [ImageForTime, ]

Decoder is also reopened in looped video, when video clock goes to the next lap.

As for the sound decoding, it does not have any control over opening and closing decoder. If SoundForTimeInterval is called when decoder is closed, then it returns false, most likely removing sound sample from sound system (i.e. no sound afterwards). I hope it won't cause problems in future.

When video ends, it usually stays as it is: no other calls to cinematic's methods are performed. Unfortunately, it still consumes memory. The only exception is when a cinematic used as background of GUI window plays up to the end: then GUI window calls Close method (see issue 4535).

Issue History

Date Modified Username Field Change
01.05.2017 19:29 duzenko New Issue
02.05.2017 19:08 stgatilov Note Added: 0008827
03.05.2017 03:59 stgatilov Note Added: 0008828
03.05.2017 09:17 duzenko Note Added: 0008829
16.05.2017 05:33 stgatilov Assigned To => stgatilov
16.05.2017 05:33 stgatilov Status new => assigned
16.05.2017 05:33 stgatilov Relationship added related to 0004519
16.05.2017 12:04 stgatilov Note Added: 0008862
16.05.2017 12:05 stgatilov Note Edited: 0008862
17.05.2017 04:22 stgatilov Note Added: 0008867
12.06.2017 06:40 stgatilov Note Added: 0008897
12.06.2017 06:41 stgatilov Note Edited: 0008897
12.06.2017 06:48 stgatilov Note Edited: 0008897
12.06.2017 07:02 stgatilov Note Added: 0008898
12.06.2017 07:03 stgatilov Note Edited: 0008898
12.06.2017 07:15 stgatilov Status assigned => resolved
12.06.2017 07:15 stgatilov Fixed in Version => TDM 2.06
12.06.2017 07:15 stgatilov Resolution open => fixed
12.06.2017 07:59 stgatilov Relationship added related to 0004541