1726249 - higher than expected CPU usage in audio code

Status: ASSIGNED

(Core :: Audio/Video: cubeb, defect)

Description

[Jeff Muizelaar [:jrmuizel]]

I've been comparing CPU usage of Firefox and Chrome when running twitch using perfview. This uses the xperf profiling infrastructure which will periodically sample what ever thread is running on each CPU.

One of things that I noticed is that there's a fair amount of CPU time being spent in GetQueuedCompletionStatusEx called from the tokio event loop. Looking at some ETW traces suggests that there are periods where the thread will stop and start a couple of times in quick succession, with a sleep of about ~0.05ms inbetween.

I saw the time being spent in GetQueuedCompletionStatusEx on a couple of different Audio/AudioIPC threads that we're using tokio.

What's the expected behaviour here? How often do we expect a thread to wake up and sleep over a particular period of time? Could it be that the way we're using tokio is causing is to rely on signalling an IO Completion Port more often than we need to?

Comment 1

[Matthew Gregan [:kinetik]]

(In reply to Jeff Muizelaar [:jrmuizel] from comment #0)

What's the expected behaviour here? How often do we expect a thread to wake up and sleep over a particular period of time? Could it be that the way we're using tokio is causing is to rely on signalling an IO Completion Port more often than we need to?

I'd expect thread wake/sleep cycles to be in the region of 10s of ms for a low latency audio stream and higher for regular playback (there may be several wakes due to messaging bouncing between threads, but expected worse case would be ~4). We're not doing anything deliberately to cause sub-ms cycles cycles, so that's unexpected behaviour. It's possible the code is doing something bad, or we're hitting a bug in tokio or mio.

This code will be replaced shortly (bug 1726275/bug 1726279) by a rework of the audioipc IPC code that switches a very old tokio/mio out for a current mio (no tokio), so I'll revisit this once that has landed.

Comment 2

[Emma Malysz]

Hey Paul, can we assign someone to this? It's currently marked as an S1

Comment 3

[Jeff Muizelaar [:jrmuizel]]

FWIW, I don't think this needs to be S1

Comment 4

[Matthew Gregan [:kinetik]]

Jeff, would you mind sharing how you collected the data showing frequent GetQueuedCompletionStatusEx calls please? I'm investigating this now that we're close to shipping the new AudioIPC backend on Windows (bug 1726279).

Comment 5

[Jeff Muizelaar [:jrmuizel]]

I originally used perfview but found it quite hard to use. Instead I'd suggest using https://github.com/jrmuizel/etw-profiler/tree/main/etw-gecko with the --merge-threads flag.

That will give you something like: https://share.firefox.dev/3nlr3HC