View Issue Details
ID | Project | Category | View Status | Date Submitted | Last Update |
---|---|---|---|---|---|
0004518 | The Dark Mod | GUI | public | 01.05.2017 19:29 | 12.06.2017 07:59 |
Reporter | duzenko | Assigned To | stgatilov | ||
Priority | normal | Severity | normal | Reproducibility | have not tried |
Status | resolved | Resolution | fixed | ||
Product Version | SVN | ||||
Target Version | TDM 2.06 | Fixed in Version | TDM 2.06 | ||
Summary | 0004518: Briefing video starts decoding in background | ||||
Description | During 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++ | ||||
Tags | No tags attached. | ||||
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? |
|
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... |
|
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. |
|
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. |
|
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. |
|
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. |
|
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). |
|
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 |