Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Load audio asychronously (fix #4880) #2928

Closed
wants to merge 9 commits into from
Closed

Conversation

elsid
Copy link
Collaborator

@elsid elsid commented Jun 24, 2020

The idea is to use background thread to open voice files. The problem first was discovered in https://gitlab.com/OpenMW/openmw/-/issues/4880 . My research shows this as the only thing that may have significant impact on a single frame time in mechanics manager. This graph shows frame time for each frame before this change:
before_osg_stats

There are multiple one frame duration spikes. This happens on SSD. Digging into the problem shows the same reason as bug 4880.

After the change for the same test graph doesn't have this kind of spikes:
after_osg_stats

@kcat
Copy link
Contributor

kcat commented Jun 24, 2020

I don't know about this. This makes it so the game will keep playing while the voice file is being opened, which means in degenerate cases the character might not speak for a while despite needing to. Skyrim had an annoying bug just like this; a character's supposed to say something, and sometimes they'd just stare blankly for an extra long moment before giving their line, as if an asynchronous load was being stalled.

Additionally, this seems like it could cause problems with scripts, where they can call say on a character and then check saydone before the voice clip gets a chance to play.

FWIW, the voice is already being streamed, which means it's not being decoded all at once (in fact, a fair bit of work went into being able to stream voices and build up the 'lip' data in small bits with each update). If the issue is specifically with the open call, it may be worth looking into what exactly is making it slow and see if that can be fixed or improved. FFmpeg is a pretty large library, so it's possible there's more efficient ways to prepare sound files for our audio decoding needs.

@wareya
Copy link
Contributor

wareya commented Jun 24, 2020 via email

@elsid
Copy link
Collaborator Author

elsid commented Jun 24, 2020

This makes it so the game will keep playing while the voice file is being opened, which means in degenerate cases the character might not speak for a while despite needing

I can add a deadline in frame numbers like if file isn't opened in 1 to n frames, wait until it is.

Additionally, this seems like it could cause problems with scripts, where they can call say on a character and then check saydone before the voice clip gets a chance to play.

I missed this but current logic is not clear. It was introduced by 4c2b694. SoundManager::sayDone checks only mActiveSaySounds. But here ptr is added to mSaySoundsQueue. Is it intended? The only case ptr is added to mActiveSaySounds here with empty Ptr. So this call always returns true. I think I should fix this. sayDone should check both queues. Then sayActive will become a negation of sayDone.

If the issue is specifically with the open call, it may be worth looking into what exactly is making it slow and see if that can be fixed or improved

If it's a disk, then there is nothing to improve.

@Capostrophic
Copy link
Collaborator

Capostrophic commented Jun 24, 2020

sayActive is not supposed to be a negation of sayDone. sayDone is supposed to be a vanilla-compatible implementation of SayDone, which returns 1 during the frame a speech sound is started (i.e. no current say sound) and it's only used for that scripting function. sayActive returns the actual status of a speech sound (1 if there's a sound) used for our game mechanics.

So sayDone shouldn't care if there's something in the queue. Don't "fix" it, it'll break mods.

@elsid
Copy link
Collaborator Author

elsid commented Jun 24, 2020

So sayDone shouldn't care if there's something in the queue. Don't "fix" it, it'll break mods.

Checked the script in the game and found that it actually works, so I will not change it. I need to make appropriate changes to this pr now.

@kcat
Copy link
Contributor

kcat commented Jun 24, 2020

You're going to get random multi-second stalls on file/filesystem operations sometimes no matter what you're doing, even if you're just setting up buffers for streaming.

Only if disk access is temporarily blocked due to other processes hammering the disk. The kernel should be expected to balance the needs of various apps to avoid resource starvation, and disk access is no exception. However, with this it's not just dependent on disk access, but also on thread scheduling and the work queue to not cause stalls.

There's no problem with, for example, having the game go on for a second while an audio asset loads into cache the first time it's used, as long as it's somehow made invisible to game logic.

I disagree. Having an audio cue delayed from the corresponding visual cue is quite jarring. If you move the mouse, you wouldn't want to see the game continue rendering new frames but not actually turn the camera for an extra 30+ frames afterward when a needed model gets loaded. Similarly, if you hit someone with a sword, you wouldn't want the game to continue on only to hear the hit/grunt sound a half second later after the particulars and stagger animation are finished. Sound feedback is important, and you don't want to let it lag behind the game simulation too far or go too out of sync with the visuals.

Or do you want to preload every voice asset in the game?

Loading sounds as needed shouldn't be a significant stall. Games were loading sounds synchronously on mechanical drives decades ago and had no problems holding 60fps. Longer sounds, like voice lines, would be streamed to avoid loading too much at once. That some people are experiencing stalls on modern SSDs from just opening a file (not even fully decoding/loading it) points to an issue being elsewhere. Throwing it onto another thread is just hiding the problem and exchanging it for others.

@kcat
Copy link
Contributor

kcat commented Jun 24, 2020

I can add a deadline in frame numbers like if file isn't opened in 1 to n frames, wait until it is.

A deadline would be preferable to no deadline. However, you're potentially making the problem worse since the overhead of asynchronous workloads is being added.

If it's a disk, then there is nothing to improve.

It depends on what the problem is. Like I mentioned, FFmpeg is a big library. It's designed to automagically handle tons of formats for many different purposes. However, what we need when opening a regular wav/mp3/ogg/etc audio file to get decoded PCM samples from is different than what we'd need for opening random video file 53 that can have multiple video and audio streams we may want to dynamically jump between during playback. When naively opening a file, ffmpeg has to be prepared for us wanting the latter, even though we really only need the former. As shots in the dark, we might be able to improve it by pre-preparing codecs and coverters that can be shared between instances, without having to search/detect and recreate them for each file.

@AnyOldName3
Copy link
Member

Is it too much overhead to pre-emptively get a handle to each audio file and maybe read the header so we've not got any of the actual file in memory, but don't need to do any setup for streaming either and can start immediately once it's time to actually play something?

@wareya
Copy link
Contributor

wareya commented Jun 25, 2020

Only if disk access is temporarily blocked due to other processes hammering the disk. The kernel should be expected to balance the needs of various apps to avoid resource starvation, and disk access is no exception.

This is not actually true in practice. File access can freeze up for just about any reason, like the disk scheduler randomly deciding to go on a picnic, or the filesystem driver deciding to do an expensive journaling operation (depending on how it's designed).

However, with this it's not just dependent on disk access, but also on thread scheduling and the work queue to not cause stalls.

A thread that's not being waited on getting stuck for a few seconds won't cause stalls, and describing it as such is misleading.

If you move the mouse, you wouldn't want to see the game continue rendering new frames but not actually turn the camera for an extra 30+ frames afterward when a needed model gets loaded.

Yes, actually, I would. If the game locks while I'm turning the camera real fast because it wants to load in a model, I might get physically sick. Really, models should be loaded the moment they come into the game world, but that's not appropriate for the vast number of voice files in an RPG, and voice files don't have a physical presence in the game world, so they're not really comparable either way.

Sound feedback is important, and you don't want to let it lag behind the game simulation too far or go too out of sync with the visuals.

This is true for normal sound effects or for dialogue in cutscenes, but in Morrowind the typical voice line is someone making combat grunts or making a greeting, and a little delay is acceptable for both of them.

Games were loading sounds synchronously on mechanical drives decades ago and had no problems holding 60fps. Longer sounds, like voice lines, would be streamed to avoid loading too much at once.

Synchronous file access has, actually, in fact, been a problematic source of hitches and stuttering in mainstream games for a long time, including in major games like Team Fortress 2. Though these days the problem with hitches is coming from shader compilation instead...

That some people are experiencing stalls on modern SSDs from just opening a file (not even fully decoding/loading it) points to an issue being elsewhere.

Yes. It does. But historically speaking, problems with file access randomly locking up for a few seconds even if you're just grabbing a file handle or reading a header are generally caused by the OS. Which we're not exactly going to fix.

@wareya
Copy link
Contributor

wareya commented Jun 25, 2020

Is it too much overhead to pre-emptively get a handle to each audio file and maybe read the header so we've not got any of the actual file in memory, but don't need to do any setup for streaming either and can start immediately once it's time to actually play something?

There only seem to be around 200MB of (non-music) audio assets in Morrowind, so this actually shouldn't be too bad. In fact, if you have a computer with enough RAM to run a modern web browser, you actually could just preload all the voice assets in the entire game, at least in their compressed form, despite me suggesting such as a joke earlier.

EDIT: Just opening them as handles would be fine, but there's like 6000 of them, and OSs generally have a limit to how many file handles a process can have open at once. It looks like normal values for this limit range from around 500 to several thousand, and it depends on the particular OS etc.

@kcat
Copy link
Contributor

kcat commented Jun 25, 2020

Is it too much overhead to pre-emptively get a handle to each audio file and maybe read the header so we've not got any of the actual file in memory, but don't need to do any setup for streaming either and can start immediately once it's time to actually play something?

We wouldn't be able to hold open a handle to each audio file, as the OS provides only a limited number of file handles (my system only allows 1024 file descriptors, and there's over 7000 loose wav/mp3 files in a vanilla install). Though we might be able to pre-scan each one to get the codec it needs and precalculate its length, to help reduce the work ffmpeg needs to do when loading the file during play. We might also be able to limit the allowed codecs so it doesn't try to match files to dozens of completely esoteric formats nobody really uses (or at least give higher priority to ones we more expect to be used).

A thread that's not being waited on getting stuck for a few seconds won't cause stalls, and describing it as such is misleading.

It would stall a sound event since it can't play until the work queue finishes the task (which in turn depends on the worker thread getting scheduled, potentially vying for a timeslice on some core that the main thread or rendering thread also wants, and not having any other tasks already in the queue it needs to wait for). And since voices aren't and can't realistically be cached, this can potentially happen every time someone speaks.

Yes, actually, I would. If the game locks while I'm turning the camera real fast because it wants to load in a model, I might get physically sick.

I guess we have different standards, then. If I see the game continue without doing something it should do (turn the camera, play a sound), that makes me think it's bugging out because of an error it's not reporting. If there's resource contention and the game has to pause for a quick moment to load something, I can tell it's an issue outside of the app's direct control. Neither is good, but silently delaying feedback is worse to me than an occasional very slight hitch from loading/preparing an uncached resource.

@wareya
Copy link
Contributor

wareya commented Jun 25, 2020

And since voices aren't and can't realistically be cached, this can potentially happen every time someone speaks.

This exact same argument can be used for the game hitching, not just voice files being delayed. I don't know about you, but I don't want to walk into a new building and get a series of seconds-long stutters because every NPC decides to greet me at the same time (actual experience, minus the stutters).

@kcat
Copy link
Contributor

kcat commented Jun 25, 2020

I don't know about you, but I don't want to walk into a new building and get a series of seconds-long stutters because every NPC decides to greet me at the same time (actual experience, minus the stutters).

My system is a good 10+ years old; ancient dual-core processor, mechanical HD, low memory, the whole nine yards, and the only times I'd notice a hitch with voices is if I attacked a room with several NPCs causing them all to shout in alarm at the same exact time. During normal play where only a single character would start speaking on a given frame, it was completely seamless. However, I'd not be surprised if this causes problems for my system since there's only so much processor time to go around, meaning the work queue is inherently more flaky when it comes to completing what would be very quick work in a reasonable amount of time; freeing up memory to avoid swap or stopping background processes that want to use the disk won't be able to help since the problem won't be the disk.

@elsid
Copy link
Collaborator Author

elsid commented Jun 26, 2020

I gathered some profile for openmw + ffmpeg 4.2.3 using systemtap with script. There are 2 kinds of issues:

  1. Slow avio_read.

Top calls by sum duration:

function duration calls number duration, % (frame)
update@/home/elsid/dev/openmw/apps/openmw/mwmechanics/mechanicsmanagerimp.cpp:312 43511 1 100.0
update@/home/elsid/dev/openmw/apps/openmw/mwmechanics/actors.cpp:1662 43201 1 99.28753648502678
open@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:178 41236 1 94.77143710785778
avformat_open_input@src/libavformat/utils.c:537 31367 1 72.08981636827468
avio_read@src/libavformat/aviobuf.c:647 30946 15 71.12224494955298
av_probe_input_buffer2@src/libavformat/format.c:222 30786 1 70.75452184505068
avformat_find_stream_info@src/libavformat/utils.c:3584 9681 1 22.24954609179288
av_probe_input_format3@src/libavformat/format.c:128 9558 6 21.96685895520673
av_reallocp@src/libavutil/mem.c:163 8 1 0.01838615522511549

Stack:

1 update@/home/elsid/dev/openmw/apps/openmw/mwmechanics/mechanicsmanagerimp.cpp:312 43511 43201 99.28753648502678% 100.0% 100.0%
  2 update@/home/elsid/dev/openmw/apps/openmw/mwmechanics/actors.cpp:1662 43201 41236 95.4514941783755% 99.28753648502678% 99.28753648502678%
    3 open@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:178 41236 41048 99.54408769036765% 95.4514941783755% 94.77143710785778%
      4 avformat_find_stream_info@src/libavformat/utils.c:3584 9681 9382 96.91147608718109% 23.477058880589777% 22.24954609179288%
        5 av_probe_input_format3@src/libavformat/format.c:128 3863 0 0.0% 39.90290259270736% 8.878214704327641%
        6 avio_read@src/libavformat/aviobuf.c:647 4 0 0.0% 0.041318045656440455% 0.009193077612557745%
        7 avio_read@src/libavformat/aviobuf.c:647 11 0 0.0% 0.11362462555521123% 0.025280963434533798%
        8 avio_read@src/libavformat/aviobuf.c:647 6 0 0.0% 0.061977068484660676% 0.013789616418836617%
        9 avio_read@src/libavformat/aviobuf.c:647 17 0 0.0% 0.17560169403987191% 0.03907057985337042%
        10 av_probe_input_format3@src/libavformat/format.c:128 3031 0 0.0% 31.308749096167755% 6.96605456091563%
        11 avio_read@src/libavformat/aviobuf.c:647 5 0 0.0% 0.05164755707055056% 0.01149134701569718%
        12 avio_read@src/libavformat/aviobuf.c:647 12 0 0.0% 0.12395413696932135% 0.027579232837673235%
        13 avio_read@src/libavformat/aviobuf.c:647 5 0 0.0% 0.05164755707055056% 0.01149134701569718%
        14 avio_read@src/libavformat/aviobuf.c:647 15 0 0.0% 0.15494267121165167% 0.03447404104709154%
        15 av_probe_input_format3@src/libavformat/format.c:128 1352 0 0.0% 13.965499431876871% 3.1072602330445176%
        16 avio_read@src/libavformat/aviobuf.c:647 5 0 0.0% 0.05164755707055056% 0.01149134701569718%
        17 avio_read@src/libavformat/aviobuf.c:647 14 0 0.0% 0.14461315979754158% 0.032175771643952106%
        18 av_probe_input_format3@src/libavformat/format.c:128 642 0 0.0% 6.631546327858692% 1.4754889568155178%
        19 avio_read@src/libavformat/aviobuf.c:647 6 0 0.0% 0.061977068484660676% 0.013789616418836617%
        20 av_probe_input_format3@src/libavformat/format.c:128 377 0 0.0% 3.8942258031195123% 0.8664475649835675%
        21 avio_read@src/libavformat/aviobuf.c:647 17 0 0.0% 0.17560169403987191% 0.03907057985337042%
      22 avformat_open_input@src/libavformat/utils.c:537 31367 31163 99.34963496668473% 76.06702880977785% 72.08981636827468%
        23 avio_read@src/libavformat/aviobuf.c:647 371 0 0.0% 1.182771702744923% 0.8526579485647309%
        24 avio_read@src/libavformat/aviobuf.c:647 6 0 0.0% 0.01912838333280199% 0.013789616418836617%
        25 av_probe_input_buffer2@src/libavformat/format.c:222 30786 30753 99.89280841941141% 98.147734880607% 70.75452184505068%
          26 av_probe_input_format3@src/libavformat/format.c:128 293 0 0.0% 0.9517313064379912% 0.6733929351198548%
          27 avio_read@src/libavformat/aviobuf.c:647 30452 0 0.0% 98.91509127525498% 69.9868998644021%
          28 av_reallocp@src/libavutil/mem.c:163 8 0 0.0% 0.02598583771844345% 0.01838615522511549%
  1. Less slow av_probe_input_format3:

Top calls by sum duration:

function duration calls number duration, % (frame)
update@/home/elsid/dev/openmw/apps/openmw/mwmechanics/mechanicsmanagerimp.cpp:312 11327 1 100.0
update@/home/elsid/dev/openmw/apps/openmw/mwmechanics/actors.cpp:1662 11038 1 97.44857420323122
open@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:178 8704 1 76.8429416438598
avformat_find_stream_info@src/libavformat/utils.c:3584 8045 1 71.02498455018981
av_probe_input_format3@src/libavformat/format.c:128 7953 6 70.2127659574468
avformat_open_input@src/libavformat/utils.c:537 515 1 4.546658426767899
av_probe_input_buffer2@src/libavformat/format.c:222 290 1 2.56025425973338
avio_read@src/libavformat/aviobuf.c:647 143 12 1.2624702039374944
av_reallocp@src/libavutil/mem.c:163 6 1 0.05297077778758718

Stack:

1 update@/home/elsid/dev/openmw/apps/openmw/mwmechanics/mechanicsmanagerimp.cpp:312 11327 11038 97.44857420323122% 100.0% 100.0%
  2 update@/home/elsid/dev/openmw/apps/openmw/mwmechanics/actors.cpp:1662 11038 8704 78.85486501177749% 97.44857420323122% 97.44857420323122%
    3 open@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:178 8704 8560 98.34558823529412% 78.85486501177749% 76.8429416438598%
      4 avformat_find_stream_info@src/libavformat/utils.c:3584 8045 7790 96.83032939714109% 92.42876838235294% 71.02498455018981%
        5 av_probe_input_format3@src/libavformat/format.c:128 2935 0 0.0% 36.482287134866375% 25.91153880109473%
        6 avio_read@src/libavformat/aviobuf.c:647 12 0 0.0% 0.14916096954630206% 0.10594155557517436%
        7 av_probe_input_format3@src/libavformat/format.c:128 2554 0 0.0% 31.746426351771284% 22.547894411582945%
        8 avio_read@src/libavformat/aviobuf.c:647 5 0 0.0% 0.06215040397762585% 0.04414231482298932%
        9 avio_read@src/libavformat/aviobuf.c:647 10 0 0.0% 0.1243008079552517% 0.08828462964597864%
        10 avio_read@src/libavformat/aviobuf.c:647 6 0 0.0% 0.07458048477315103% 0.05297077778758718%
        11 avio_read@src/libavformat/aviobuf.c:647 13 0 0.0% 0.16159105034182722% 0.11477001853977223%
        12 av_probe_input_format3@src/libavformat/format.c:128 1267 0 0.0% 15.748912367930393% 11.185662576145493%
        13 avio_read@src/libavformat/aviobuf.c:647 5 0 0.0% 0.06215040397762585% 0.04414231482298932%
        14 avio_read@src/libavformat/aviobuf.c:647 13 0 0.0% 0.16159105034182722% 0.11477001853977223%
        15 av_probe_input_format3@src/libavformat/format.c:128 634 0 0.0% 7.880671224362959% 5.597245519555045%
        16 avio_read@src/libavformat/aviobuf.c:647 6 0 0.0% 0.07458048477315103% 0.05297077778758718%
        17 av_probe_input_format3@src/libavformat/format.c:128 318 0 0.0% 3.9527656929770045% 2.8074512227421207%
        18 avio_read@src/libavformat/aviobuf.c:647 12 0 0.0% 0.14916096954630206% 0.10594155557517436%
      19 avformat_open_input@src/libavformat/utils.c:537 515 337 65.4368932038835% 5.916819852941177% 4.546658426767899%
        20 avio_read@src/libavformat/aviobuf.c:647 42 0 0.0% 8.155339805825243% 0.3707954445131103%
        21 avio_read@src/libavformat/aviobuf.c:647 5 0 0.0% 0.9708737864077669% 0.04414231482298932%
        22 av_probe_input_buffer2@src/libavformat/format.c:222 290 265 91.37931034482759% 56.310679611650485% 2.56025425973338%
          23 av_probe_input_format3@src/libavformat/format.c:128 245 0 0.0% 84.48275862068965% 2.1629734263264764%
          24 avio_read@src/libavformat/aviobuf.c:647 14 0 0.0% 4.827586206896552% 0.12359848150437008%
          25 av_reallocp@src/libavutil/mem.c:163 6 0 0.0% 2.0689655172413794% 0.05297077778758718%

Frame time graph for this test:
timeseries

@elsid elsid force-pushed the async_decode branch 2 times, most recently from 7a1d265 to 5777737 Compare June 26, 2020 21:25
@elsid
Copy link
Collaborator Author

elsid commented Jun 26, 2020

  1. Fixed sayDone/sayActive.
  2. Added 200ms deadline for decoding. If deadline is reached then wait until async task is done.

Want to make music decoding async too.

@kcat
Copy link
Contributor

kcat commented Jun 26, 2020

To clarify, this PR doesn't make voices decode asynchronously. They're already streamed with a background thread. All this PR does is open the file asynchronously, then start a streaming sound.

Want to make music decoding async too.

It already is.

@elsid elsid changed the title Decode voice asychronously (fix #4880) Create audio decoder asychronously (fix #4880) Jun 26, 2020
@elsid elsid force-pushed the async_decode branch 2 times, most recently from 3337f4e to 45b5422 Compare June 26, 2020 22:35
@elsid
Copy link
Collaborator Author

elsid commented Jun 26, 2020

It already is.

Ok, you're right. I mean create a decoder and open file. It's not full decoding but it's a part of a decoding process. Changed all the naming in the pr to reflect this.

Sounds are left now.

@elsid elsid force-pushed the async_decode branch 2 times, most recently from cd6187c to ce7a915 Compare June 26, 2020 22:48
@kcat
Copy link
Contributor

kcat commented Jun 26, 2020

Honestly, if the performance of opening audio files is a real problem, it would be best to have a generic solution. As it is, sound effects are going to be loaded about as often as voices (any time a sound is first used, or if it's been purged from cache due to lack of use), which are opened and decoded synchronously.

av_probe_input_buffer2 and av_probe_input_format3 seem to be the biggest culprits, which would align with what I suggested above that the issue could be with ffmpeg needing to detect the codec out of all possible codecs, then find other info the stream has (that we may not need). If there's a way to avoid the overhead from them, that would likely solve the issue.

It you really need to, though, a more general solution may be to handle audio similar to graphics. Put all the stuff with openal and ffmpeg on a separate thread, separate from the main simulation, and have the main thread just supply the updates for a given frame. A fence of some sort can be used to ensure a frame has been processed before handling the next frame, preventing it from lagging too far behind.

@psi29a
Copy link
Member

psi29a commented Jun 26, 2020

Essentially preloading (priming) assets before need them in other words? We do this already with meshes/textures (preload in settings).

@kcat
Copy link
Contributor

kcat commented Jun 27, 2020

Sort of. My original thought was to go through the audio files at load time and have ffmpeg detect what codec it would use, and store that information with the sound definition. Then when it needs to be loaded, we could tell ffmpeg to use that codec (or prioritize that codec) so it doesn't have to probe the file during runtime.

We could also look into seeing if calling avformat_find_stream_info is strictly needed. The comments in avformat.h actually mention:

todo Let the user decide somehow what information is needed so that we do not waste time getting stuff the user does not need.

indicating they know it's a time-consuming call.

@elsid
Copy link
Collaborator Author

elsid commented Jun 28, 2020

Put all the stuff with openal and ffmpeg on a separate thread, separate from the main simulation

Looking at this sample, I agree.

Top calls by duration:

id function duration callee duration callee duration, % duration, % (caller) duration, % (frame)
1 frame@/home/elsid/dev/openmw/apps/openmw/engine.cpp:88 22924 20225 88.22631303437446 100.0 100.0
5 updateRegionSound@/home/elsid/dev/openmw/apps/openmw/mwsound/soundmanagerimp.cpp:931 19274 19251 99.88066825775657 84.077822369569 84.077822369569
7 loadSound@/home/elsid/dev/openmw/apps/openmw/mwsound/openal_output.cpp:945 19237 18939 98.45090190778187 99.80803154508665 83.91641947304136
10 open@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:178 18545 18474 99.61714747910489 96.40276550397671 80.89774908392951
11 avformat_find_stream_info@src/libavformat/utils.c:3584 17954 17080 95.13200401024842 96.81315718522512 78.31966497993369
47 av_probe_input_format3@src/libavformat/format.c:128 8007 0 0.0 44.597304221900416 34.92845925667423
80 av_probe_input_format3@src/libavformat/format.c:128 3996 0 0.0 22.25687868998552 17.431512824986914
97 av_probe_input_format3@src/libavformat/format.c:128 2088 0 0.0 11.62972039656901 9.108358052695865
106 av_probe_input_format3@src/libavformat/format.c:128 1054 0 0.0 5.870558092904088 4.597801430814866
111 av_probe_input_format3@src/libavformat/format.c:128 934 0 0.0 5.202183357469088 4.074332577211656
2 update@/home/elsid/dev/openmw/apps/openmw/mwmechanics/mechanicsmanagerimp.cpp:312 771 540 70.03891050583657 3.3632873844006284 3.3632873844006284
3 update@/home/elsid/dev/openmw/apps/openmw/mwmechanics/actors.cpp:1662 540 0 0.0 70.03891050583657 2.3556098412144477
117 avformat_open_input@src/libavformat/utils.c:537 520 401 77.11538461538461 2.8039902938797523 2.2683650322805793
8 readAll@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:407 394 9 2.284263959390863 2.048136403805167 1.7187227359972084
114 av_probe_input_format3@src/libavformat/format.c:128 308 0 0.0 1.715495154283168 1.3435700575815739

Top calls by sum duration:

function duration calls number duration, % (frame)
frame@/home/elsid/dev/openmw/apps/openmw/engine.cpp:88 22924 1 100.0
updateRegionSound@/home/elsid/dev/openmw/apps/openmw/mwsound/soundmanagerimp.cpp:931 19274 1 84.077822369569
loadSound@/home/elsid/dev/openmw/apps/openmw/mwsound/openal_output.cpp:945 19237 1 83.91641947304136
open@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:178 18545 1 80.89774908392951
avformat_find_stream_info@src/libavformat/utils.c:3584 17954 1 78.31966497993369
av_probe_input_format3@src/libavformat/format.c:128 16622 7 72.50916070493805
update@/home/elsid/dev/openmw/apps/openmw/mwmechanics/mechanicsmanagerimp.cpp:312 771 1 3.3632873844006284
avio_read@src/libavformat/aviobuf.c:647 723 50 3.1538998429593437
update@/home/elsid/dev/openmw/apps/openmw/mwmechanics/actors.cpp:1662 540 1 2.3556098412144477
avformat_open_input@src/libavformat/utils.c:537 520 1 2.2683650322805793
readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 399 52 1.740533938230675
readAll@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:407 394 1 1.7187227359972084
av_probe_input_buffer2@src/libavformat/format.c:222 275 1 1.199616122840691
updateSounds@/home/elsid/dev/openmw/apps/openmw/mwsound/soundmanagerimp.cpp:1080 149 1 0.6499738265573198
seek@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:35 108 9 0.47112196824288954

Stack:

1 frame@/home/elsid/dev/openmw/apps/openmw/engine.cpp:88 22924 20225 88.22631303437446% 100.0% 100.0%
  2 update@/home/elsid/dev/openmw/apps/openmw/mwmechanics/mechanicsmanagerimp.cpp:312 771 540 70.03891050583657% 3.3632873844006284% 3.3632873844006284%
    3 update@/home/elsid/dev/openmw/apps/openmw/mwmechanics/actors.cpp:1662 540 0 0.0% 70.03891050583657% 2.3556098412144477%
  4 updateWaterSound@/home/elsid/dev/openmw/apps/openmw/mwsound/soundmanagerimp.cpp:983 20 0 0.0% 0.08724480893386843% 0.08724480893386843%
  5 updateRegionSound@/home/elsid/dev/openmw/apps/openmw/mwsound/soundmanagerimp.cpp:931 19274 19251 99.88066825775657% 84.077822369569% 84.077822369569%
    6 playSound@/home/elsid/dev/openmw/apps/openmw/mwsound/openal_output.cpp:1132 14 0 0.0% 0.07263671266991803% 0.061071366253707904%
    7 loadSound@/home/elsid/dev/openmw/apps/openmw/mwsound/openal_output.cpp:945 19237 18939 98.45090190778187% 99.80803154508665% 83.91641947304136%
      8 readAll@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:407 394 9 2.284263959390863% 2.048136403805167% 1.7187227359972084%
        9 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 9 0 0.0% 2.284263959390863% 0.039260164020240795%
      10 open@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:178 18545 18474 99.61714747910489% 96.40276550397671% 80.89774908392951%
        11 avformat_find_stream_info@src/libavformat/utils.c:3584 17954 17080 95.13200401024842% 96.81315718522512% 78.31966497993369%
          12 seek@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:35 12 0 0.0% 0.06683747354350006% 0.05234688536032106%
          13 seek@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:35 12 0 0.0% 0.06683747354350006% 0.05234688536032106%
          14 seek@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:35 13 0 0.0% 0.07240726300545838% 0.05670912580701448%
          15 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 6 0 0.0% 0.03341873677175003% 0.02617344268016053%
          16 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 7 0 0.0% 0.03898852623370837% 0.030535683126853952%
          17 avio_read@src/libavformat/aviobuf.c:647 18 10 55.55555555555556% 0.10025621031525009% 0.07852032804048159%
            18 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 10 0 0.0% 55.55555555555556% 0.04362240446693422%
          19 avio_read@src/libavformat/aviobuf.c:647 10 4 40.0% 0.055697894619583375% 0.04362240446693422%
            20 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 40.0% 0.017448961786773687%
          21 avio_read@src/libavformat/aviobuf.c:647 16 9 56.25% 0.08911663139133341% 0.06979584714709475%
            22 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 9 0 0.0% 56.25% 0.039260164020240795%
          23 avio_read@src/libavformat/aviobuf.c:647 10 4 40.0% 0.055697894619583375% 0.04362240446693422%
            24 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 40.0% 0.017448961786773687%
          25 avio_read@src/libavformat/aviobuf.c:647 15 9 60.0% 0.08354684192937507% 0.06543360670040133%
            26 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 9 0 0.0% 60.0% 0.039260164020240795%
          27 avio_read@src/libavformat/aviobuf.c:647 10 4 40.0% 0.055697894619583375% 0.04362240446693422%
            28 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 40.0% 0.017448961786773687%
          29 avio_read@src/libavformat/aviobuf.c:647 16 9 56.25% 0.08911663139133341% 0.06979584714709475%
            30 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 9 0 0.0% 56.25% 0.039260164020240795%
          31 avio_read@src/libavformat/aviobuf.c:647 10 4 40.0% 0.055697894619583375% 0.04362240446693422%
            32 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 40.0% 0.017448961786773687%
          33 avio_read@src/libavformat/aviobuf.c:647 15 9 60.0% 0.08354684192937507% 0.06543360670040133%
            34 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 9 0 0.0% 60.0% 0.039260164020240795%
          35 avio_read@src/libavformat/aviobuf.c:647 11 4 36.36363636363637% 0.06126768408154172% 0.04798464491362764%
            36 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 36.36363636363637% 0.017448961786773687%
          37 avio_read@src/libavformat/aviobuf.c:647 16 9 56.25% 0.08911663139133341% 0.06979584714709475%
            38 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 9 0 0.0% 56.25% 0.039260164020240795%
          39 avio_read@src/libavformat/aviobuf.c:647 11 3 27.27272727272727% 0.06126768408154172% 0.04798464491362764%
            40 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 3 0 0.0% 27.27272727272727% 0.013086721340080265%
          41 avio_read@src/libavformat/aviobuf.c:647 16 9 56.25% 0.08911663139133341% 0.06979584714709475%
            42 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 9 0 0.0% 56.25% 0.039260164020240795%
          43 avio_read@src/libavformat/aviobuf.c:647 11 4 36.36363636363637% 0.06126768408154172% 0.04798464491362764%
            44 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 36.36363636363637% 0.017448961786773687%
          45 avio_read@src/libavformat/aviobuf.c:647 24 14 58.333333333333336% 0.13367494708700012% 0.10469377072064212%
            46 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 14 0 0.0% 58.333333333333336% 0.061071366253707904%
          47 av_probe_input_format3@src/libavformat/format.c:128 8007 0 0.0% 44.597304221900416% 34.92845925667423%
          48 avio_read@src/libavformat/aviobuf.c:647 11 4 36.36363636363637% 0.06126768408154172% 0.04798464491362764%
            49 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 36.36363636363637% 0.017448961786773687%
          50 avio_read@src/libavformat/aviobuf.c:647 17 9 52.94117647058824% 0.09468642085329175% 0.07415808759378817%
            51 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 9 0 0.0% 52.94117647058824% 0.039260164020240795%
          52 avio_read@src/libavformat/aviobuf.c:647 10 4 40.0% 0.055697894619583375% 0.04362240446693422%
            53 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 40.0% 0.017448961786773687%
          54 avio_read@src/libavformat/aviobuf.c:647 15 8 53.333333333333336% 0.08354684192937507% 0.06543360670040133%
            55 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 8 0 0.0% 53.333333333333336% 0.034897923573547374%
          56 avio_read@src/libavformat/aviobuf.c:647 11 4 36.36363636363637% 0.06126768408154172% 0.04798464491362764%
            57 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 36.36363636363637% 0.017448961786773687%
          58 avio_read@src/libavformat/aviobuf.c:647 15 9 60.0% 0.08354684192937507% 0.06543360670040133%
            59 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 9 0 0.0% 60.0% 0.039260164020240795%
          60 avio_read@src/libavformat/aviobuf.c:647 10 4 40.0% 0.055697894619583375% 0.04362240446693422%
            61 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 40.0% 0.017448961786773687%
          62 avio_read@src/libavformat/aviobuf.c:647 17 9 52.94117647058824% 0.09468642085329175% 0.07415808759378817%
            63 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 9 0 0.0% 52.94117647058824% 0.039260164020240795%
          64 avio_read@src/libavformat/aviobuf.c:647 10 4 40.0% 0.055697894619583375% 0.04362240446693422%
            65 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 40.0% 0.017448961786773687%
          66 avio_read@src/libavformat/aviobuf.c:647 16 9 56.25% 0.08911663139133341% 0.06979584714709475%
            67 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 9 0 0.0% 56.25% 0.039260164020240795%
          68 avio_read@src/libavformat/aviobuf.c:647 10 4 40.0% 0.055697894619583375% 0.04362240446693422%
            69 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 40.0% 0.017448961786773687%
          70 avio_read@src/libavformat/aviobuf.c:647 15 9 60.0% 0.08354684192937507% 0.06543360670040133%
            71 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 9 0 0.0% 60.0% 0.039260164020240795%
          72 avio_read@src/libavformat/aviobuf.c:647 11 4 36.36363636363637% 0.06126768408154172% 0.04798464491362764%
            73 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 36.36363636363637% 0.017448961786773687%
          74 avio_read@src/libavformat/aviobuf.c:647 16 9 56.25% 0.08911663139133341% 0.06979584714709475%
            75 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 9 0 0.0% 56.25% 0.039260164020240795%
          76 avio_read@src/libavformat/aviobuf.c:647 11 3 27.27272727272727% 0.06126768408154172% 0.04798464491362764%
            77 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 3 0 0.0% 27.27272727272727% 0.013086721340080265%
          78 avio_read@src/libavformat/aviobuf.c:647 19 11 57.89473684210527% 0.10582599977720841% 0.08288256848717501%
            79 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 11 0 0.0% 57.89473684210527% 0.04798464491362764%
          80 av_probe_input_format3@src/libavformat/format.c:128 3996 0 0.0% 22.25687868998552% 17.431512824986914%
          81 avio_read@src/libavformat/aviobuf.c:647 10 4 40.0% 0.055697894619583375% 0.04362240446693422%
            82 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 40.0% 0.017448961786773687%
          83 avio_read@src/libavformat/aviobuf.c:647 15 9 60.0% 0.08354684192937507% 0.06543360670040133%
            84 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 9 0 0.0% 60.0% 0.039260164020240795%
          85 avio_read@src/libavformat/aviobuf.c:647 10 4 40.0% 0.055697894619583375% 0.04362240446693422%
            86 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 40.0% 0.017448961786773687%
          87 avio_read@src/libavformat/aviobuf.c:647 15 8 53.333333333333336% 0.08354684192937507% 0.06543360670040133%
            88 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 8 0 0.0% 53.333333333333336% 0.034897923573547374%
          89 avio_read@src/libavformat/aviobuf.c:647 10 4 40.0% 0.055697894619583375% 0.04362240446693422%
            90 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 40.0% 0.017448961786773687%
          91 avio_read@src/libavformat/aviobuf.c:647 15 9 60.0% 0.08354684192937507% 0.06543360670040133%
            92 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 9 0 0.0% 60.0% 0.039260164020240795%
          93 avio_read@src/libavformat/aviobuf.c:647 11 4 36.36363636363637% 0.06126768408154172% 0.04798464491362764%
            94 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 36.36363636363637% 0.017448961786773687%
          95 avio_read@src/libavformat/aviobuf.c:647 20 11 55.00000000000001% 0.11139578923916675% 0.08724480893386843%
            96 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 11 0 0.0% 55.00000000000001% 0.04798464491362764%
          97 av_probe_input_format3@src/libavformat/format.c:128 2088 0 0.0% 11.62972039656901% 9.108358052695865%
          98 avio_read@src/libavformat/aviobuf.c:647 11 3 27.27272727272727% 0.06126768408154172% 0.04798464491362764%
            99 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 3 0 0.0% 27.27272727272727% 0.013086721340080265%
          100 avio_read@src/libavformat/aviobuf.c:647 15 9 60.0% 0.08354684192937507% 0.06543360670040133%
            101 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 9 0 0.0% 60.0% 0.039260164020240795%
          102 avio_read@src/libavformat/aviobuf.c:647 11 4 36.36363636363637% 0.06126768408154172% 0.04798464491362764%
            103 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 36.36363636363637% 0.017448961786773687%
          104 avio_read@src/libavformat/aviobuf.c:647 17 10 58.82352941176471% 0.09468642085329175% 0.07415808759378817%
            105 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 10 0 0.0% 58.82352941176471% 0.04362240446693422%
          106 av_probe_input_format3@src/libavformat/format.c:128 1054 0 0.0% 5.870558092904088% 4.597801430814866%
          107 avio_read@src/libavformat/aviobuf.c:647 11 4 36.36363636363637% 0.06126768408154172% 0.04798464491362764%
            108 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 36.36363636363637% 0.017448961786773687%
          109 avio_read@src/libavformat/aviobuf.c:647 20 12 60.0% 0.11139578923916675% 0.08724480893386843%
            110 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 12 0 0.0% 60.0% 0.05234688536032106%
          111 av_probe_input_format3@src/libavformat/format.c:128 934 0 0.0% 5.202183357469088% 4.074332577211656%
          112 avio_read@src/libavformat/aviobuf.c:647 12 4 33.33333333333333% 0.06683747354350006% 0.05234688536032106%
            113 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 4 0 0.0% 33.33333333333333% 0.017448961786773687%
          114 av_probe_input_format3@src/libavformat/format.c:128 308 0 0.0% 1.715495154283168% 1.3435700575815739%
          115 avio_read@src/libavformat/aviobuf.c:647 17 9 52.94117647058824% 0.09468642085329175% 0.07415808759378817%
            116 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 9 0 0.0% 52.94117647058824% 0.039260164020240795%
        117 avformat_open_input@src/libavformat/utils.c:537 520 401 77.11538461538461% 2.8039902938797523% 2.2683650322805793%
          118 seek@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:35 8 0 0.0% 1.5384615384615385% 0.034897923573547374%
          119 avio_read@src/libavformat/aviobuf.c:647 51 44 86.27450980392157% 9.807692307692308% 0.22247426278136453%
            120 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 44 0 0.0% 86.27450980392157% 0.19193857965451055%
          121 seek@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:35 12 0 0.0% 2.307692307692308% 0.05234688536032106%
          122 seek@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:35 12 0 0.0% 2.307692307692308% 0.05234688536032106%
          123 seek@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:35 12 0 0.0% 2.307692307692308% 0.05234688536032106%
          124 seek@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:35 12 0 0.0% 2.307692307692308% 0.05234688536032106%
          125 seek@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:35 15 0 0.0% 2.8846153846153846% 0.06543360670040133%
          126 avio_read@src/libavformat/aviobuf.c:647 4 0 0.0% 0.7692307692307693% 0.017448961786773687%
          127 av_probe_input_buffer2@src/libavformat/format.c:222 275 260 94.54545454545455% 52.88461538461539% 1.199616122840691%
            128 av_probe_input_format3@src/libavformat/format.c:128 235 0 0.0% 85.45454545454545% 1.025126504972954%
            129 avio_read@src/libavformat/aviobuf.c:647 25 16 64.0% 9.090909090909092% 0.10905601116733554%
              130 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 16 0 0.0% 64.0% 0.06979584714709475%
  131 updateSounds@/home/elsid/dev/openmw/apps/openmw/mwsound/soundmanagerimp.cpp:1080 149 85 57.04697986577181% 0.6499738265573198% 0.6499738265573198%
    132 updateSound@/home/elsid/dev/openmw/apps/openmw/mwsound/openal_output.cpp:1239 4 0 0.0% 2.684563758389262% 0.017448961786773687%
    133 updateSound@/home/elsid/dev/openmw/apps/openmw/mwsound/openal_output.cpp:1239 4 0 0.0% 2.684563758389262% 0.017448961786773687%
    134 updateSound@/home/elsid/dev/openmw/apps/openmw/mwsound/openal_output.cpp:1239 4 0 0.0% 2.684563758389262% 0.017448961786773687%
    135 updateSound@/home/elsid/dev/openmw/apps/openmw/mwsound/openal_output.cpp:1239 4 0 0.0% 2.684563758389262% 0.017448961786773687%
    136 updateSound@/home/elsid/dev/openmw/apps/openmw/mwsound/openal_output.cpp:1239 4 0 0.0% 2.684563758389262% 0.017448961786773687%
    137 updateSound@/home/elsid/dev/openmw/apps/openmw/mwsound/openal_output.cpp:1239 5 0 0.0% 3.3557046979865772% 0.02181120223346711%
    138 updateSound@/home/elsid/dev/openmw/apps/openmw/mwsound/openal_output.cpp:1239 5 0 0.0% 3.3557046979865772% 0.02181120223346711%
    139 updateSound@/home/elsid/dev/openmw/apps/openmw/mwsound/openal_output.cpp:1239 44 0 0.0% 29.53020134228188% 0.19193857965451055%
    140 updateSound@/home/elsid/dev/openmw/apps/openmw/mwsound/openal_output.cpp:1239 4 0 0.0% 2.684563758389262% 0.017448961786773687%
    141 updateSound@/home/elsid/dev/openmw/apps/openmw/mwsound/openal_output.cpp:1239 7 0 0.0% 4.697986577181208% 0.030535683126853952%
  142 playMusicFromCreatedDecoder@/home/elsid/dev/openmw/apps/openmw/mwsound/soundmanagerimp.cpp:1540 4 0 0.0% 0.017448961786773687% 0.017448961786773687%
  143 playAllVoicesFromCreatedDecoders@/home/elsid/dev/openmw/apps/openmw/mwsound/soundmanagerimp.cpp:1491 7 0 0.0% 0.030535683126853952% 0.030535683126853952%

@AnyOldName3
Copy link
Member

Has anyone tried building FFMPEG with the necessary options to make it profilable and then working out what it's actually spending time on?

@elsid
Copy link
Collaborator Author

elsid commented Jul 9, 2020

Has anyone tried building FFMPEG with the necessary options to make it profilable and then working out what it's actually spending time on?

I have. This comment contains some info.

I've tried to profile with read syscall. Here is one slow frame sample: https://gist.github.com/elsid/326cae87b36b59e03098897600ce3b14 . The interesting part is this subtree:

1 frame@/home/elsid/dev/openmw/apps/openmw/engine.cpp:222 60612 57154 94.29485910380782% 100.0% 100.0%
  5 updateRegionSound@/home/elsid/dev/openmw/apps/openmw/mwsound/soundmanagerimp.cpp:837 56297 56272 99.95559266035491% 92.88094766712862% 92.88094766712862%
    7 loadSound@/home/elsid/dev/openmw/apps/openmw/mwsound/openal_output.cpp:946 56221 55982 99.57489194429128% 99.86500168747891% 92.7555599551244%
      11 open@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:178 55780 55722 99.89602007888132% 99.21559559595168% 92.02798125783673%
        147 avformat_open_input@src/libavformat/utils.c:537 31298 31133 99.47280976420218% 56.10971674435281% 51.636639609318294%
          165 av_probe_input_buffer2@src/libavformat/format.c:222 30586 30568 99.94114954554372% 97.72509425522398% 50.46195472843661%
            167 avio_read@src/libavformat/aviobuf.c:647 30248 30237 99.96363395927004% 98.89491924409862% 49.90430937768099%
              168 readPacket@/home/elsid/dev/openmw/apps/openmw/mwsound/ffmpeg_decoder.cpp:14 30237 30212 99.91731983993121% 99.96363395927004% 49.88616115620669%
                169 syscall.read 30212 0 0.0% 99.91731983993121% 49.84491519831057%

And some samples of slow file reads:

readPacket sound/vo/i/m/atk_im011.mp3 size=2048 duration_ns=30329765
readPacket music/battle/mw battle 8.mp3 size=2048 duration_ns=30615280
readPacket sound/vo/i/m/atk_im013.mp3 size=2048 duration_ns=30387108
readPacket sound/vo/w/m/idl_wm007.mp3 size=2048 duration_ns=30477197
readPacket sound/vo/i/m/cratk_im003.mp3 size=2048 duration_ns=30294116

@akortunov
Copy link
Collaborator

Are there plans to continue development, or this PR can be closed?

@elsid
Copy link
Collaborator Author

elsid commented Jan 9, 2021

If https://gitlab.com/OpenMW/openmw/-/merge_requests/520 will be merged I can continue to work on this.

@akortunov
Copy link
Collaborator

Mentioned MR was merged to master.

Volume factor is passed as an argument when engine logic requires to play
sound. SFX volume is loaded from ESM file. These values are not available
at the same time and can change independently. With asynchronous sound loading
SFX volume becomes available when access to the volume factor argument is lost
therefore need to keep it as a separate field.
To avoid initial file read from disk in the main thread. Use deadline to avoid
noticable delay in actors speech start. This changed affects only voices and
music. Sounds are not affected by this change.

Decoder initialization requires to open file to read headers that leads to
read from disk. This operation is performed by a separated thread via
SceneUtil::WorkQueue. Created and initialized decoders are stored into
a map file name -> decoder. Other data required to play voice stored into
SoundManager state and used each update from the main thread to try to start
playing voices and music when corresponding decoder is available. If it's
not available play is delayed until next frame. When deadline to create
decoder is reached main thread stops and waits until that decoder is created.
To avoid initial file read from disk in the main thread. Use deadline to avoid
noticable delay in actors speech start. This changed affects only sounds.

Sounds are played more often than voices and music. There is a pool of created
and initialized sound buffers that allows to play it from memory. When sound
buffer initially requested openwm has to created decoder, read headers and
potentially read all data. Initial request for sound buffer is performed in
a separate thread via SceneUtil::WorkQueue. Created buffers are stored into
a pool. If required sound buffer is present in the pool separate thread is
not used. Other data required to play sound is stored SoundManager state and
used each update from the main thread to try to start playing sounds when
corresponding sound buffer is available. If it's not available play is delayed
until the next frame. When deadline to load sound is reached main thread stops
and waits until sound is loaded and added into the pool.
@elsid
Copy link
Collaborator Author

elsid commented Jan 27, 2021

Rebased on master and includes https://gitlab.com/OpenMW/openmw/-/merge_requests/567 . Two functiional changes from the previous state:

  • Try lookup sound buffer first from the main thread and if it's not present load it in a separate thread.
  • Synchronize operations on SoundBufferPool via mutex because it's accessed from the main and background thread.

I think current state is good enough to be merged. Still I expect review and testing. If you want to get an overview what this changed does please read commit messages. I've tried to explain in some details the context and what change is about.

@elsid elsid removed the Incomplete label Jan 27, 2021
@psi29a psi29a requested a review from kcat January 27, 2021 15:51
class Sound;
class Stream;

class OpenAL_Output : public Sound_Output
{
const DecoderProvider* mDecoderProvider;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

More a stylistic thing that doesn't really matter too much, but this can be a reference instead of a pointer. It would avoid accidental changes, and make it clear that it's set once on initialization and never changed.

@@ -20,6 +25,7 @@ namespace MWSound
class OpenAL_Output : public Sound_Output
{
const DecoderProvider* mDecoderProvider;
const VFS::Manager* mVFS;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is redundant since the decoder also has it. It also creates an implicit dependency of sorts between the output and the decoder... the output checks its VFS to see if the file exists, then passes that filename to the decoder expecting it to open with its VFS. Not that they're expected to be different, but it's something that can trip up someone casually looking through the code.

@@ -109,7 +109,7 @@ namespace MWSound

SoundManager::~SoundManager()
{
clear();
SoundManager::clear();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Marking the SoundManager class as final would also avoid a virtual dispatch, both here and elsewhere that it calls its own virtual methods.

Copy link
Contributor

@kcat kcat left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I still don't like this. It makes the code a lot more complicated and harder to follow, making it do more work overall, and introduces potential undesirable latency issues (which can only be avoided by making the code more complicated, causing potentially worse stalls than it was trying to avoid in the first place). On top of the increased potential for bugs to seep in. Weren't there concerns that it wasn't safe to use the work queue from here like this?

I would much rather explore other options for making opening audio files more efficient, including trying to make ffmpeg not aggressively scan files for stream information, better hint at it the necessary codecs, using a more lightweight library like libsndfile, or even putting all audio work onto its own dedicated worker thread, like OSG does for OpenGL.

@elsid
Copy link
Collaborator Author

elsid commented Jan 27, 2021

I still don't like this.

It's just an opinion.

It makes the code a lot more complicated and harder to follow, making it do more work overall, and introduces potential undesirable latency issues (which can only be avoided by making the code more complicated, causing potentially worse stalls than it was trying to avoid in the first place).

It does make code more complicated. Like with asynchronous physics in this project or anywhere where you introduce asynchronicity. There are no any additional latency issues to what we have now.

Weren't there concerns that it wasn't safe to use the work queue from here like this?

There are no concerns. Work queue is just a thread with a queue. Please stop repeating this groundless idea.

I would much rather explore other options for making opening audio files more efficient, including trying to make ffmpeg not aggressively scan files for stream information, better hint at it the necessary codecs, using a more lightweight library like libsndfile, or even putting all audio work onto its own dedicated worker thread, like OSG does for OpenGL.

Only putting every audio file into a memory on the game start will allow to avoid IO related latency during game session. Who will do it doesn't matter: OS, openmw, or some library. Putting all audio work into it's own thread will require a lot more code and architecture changes. And all operations with sound will become asynchronous because caller will post a request to play sound, to stop sound, etc. This will create much more complicated client code. OSG is a bad example here, because it prepares a frame in a separate thread but engine doesn't start a new one util work with previous is done. With audio you can only expect that IO will finish in some amount of frames. You must not synchronize on it.

@kcat
Copy link
Contributor

kcat commented Jan 27, 2021

There are no any additional latency issues to what we have now.

Yes there are. As it is now, the sound manager calls to the decoder to load a sound. The decoder opens the file and loads it into a buffer, waiting only the amount of time it needs to for those operations to complete, before it can start playing. With it being asynchronous, the sound manager sends off a work queue item to have the decoder open and load the file. That work queue item then has to wait until the work queue wakes up and gets to that task, doing it and then marks it complete. Then the next time the sound manager updates, it checks to see that the load is complete and can play. So rather than it decoding and start playing ASAP, the decoding is going to be delayed by however long it takes the work queue to deal with it, and it will wait to start playing until the next time the sound manager updates after it completed loading.

You'd be better off saying there'd be no appreciable latency issues, since these added delays would ideally be very short. However, I'm not sure that's a safe guarantee. And given a cap on the time the main simulation will wait, any significant delays caused by the work queue would make loading stutters worse.

Only putting every audio file into a memory on the game start will allow to avoid IO related latency during game session. Who will do it doesn't matter: OS, openmw, or some library.

But as your previous posts show, that's not the actual problem here. The majority of the stall comes from avformat_find_stream_info and av_probe_input_format3, which are undoubtedly taking so much time because there's a lot of formats ffmpeg has to consider and it doesn't early-out on probing the file once it gets the bare minimum of information necessary to start loading it. The problem isn't IO latency, it's excessive IO in general. This is indicative of ffmpeg not being a great fit for immediate audio loading (something that ffmpeg's send_packet/receive_frame API design also suggests, as the docs mention its done that way to potentially take advantage of asynchronous processing; good for a video player/encoder, not so much for immediate sound loading).

Putting all audio work into it's own thread will require a lot more code and architecture changes.

Maybe, but it would be more straightforward and logical. There's less back-and-forth between the frontend and backend as the frontend merely tells the backend what to do, like play a sound or move the sound position, and the backend handles it all from there. The frontend doesn't need to hear back that the backend has done anything. At most it will query the backend for the state of active objects, e.g. whether a sound is still playing or the current playback offset of a sound. It puts more work in the backend to be able to stage changes and have a background thread to process them, but to the frontend, the behavior is the same since there's little feedback necessary.

I'm not saying I'm terribly keen on the idea, but the conceptual design is easier to understand and work with, and less invasive. Yes, it would take a fair amount of work, and is part of why I'd check other simpler options first, like trying to find ways to make ffmpeg more efficient with open files (by more strongly indicating the format, or making it not probe the whole file for every bit of information) or using a different more lightweight decoder.

@elsid
Copy link
Collaborator Author

elsid commented Jan 27, 2021

So rather than it decoding and start playing ASAP, the decoding is going to be delayed by however long it takes the work queue to deal with it, and it will wait to start playing until the next time the sound manager updates after it completed loading.

In the best case scenario playback starts on a next frame. That is ok because on that frame picture changes to represent what's happened in the game logic. For example when actor has to speak on the same frame voice is requested to be played and actor animation starts. On the next frame player sees changed image with started animation. Or maybe even one frame after if there is some kind of buffer.

There is a case when it's not a deadline but more than one frame passed since playback requested. Some additional latency may happen but it is less than a frame duration that is not noticable by human at 60 FPS.

The worst case is when deadline happens. There is no additional latency because SoundManager waits until task is complete and right after starts playback.

It's unlikely for this pr to be merged in the current state or in any state that will use the same approach. And another one requires a fresh start so I don't see a point to keep this open.

@elsid elsid closed this Jan 27, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

7 participants