CPU Spike in DissonanceComms.Update.Capture()?

[AdamKane]

Hello,

I'm seeing a CPU spike within DissonanceComms.Update(), after my app is running for about 10 minutes, and increasing over time:

Dissonance Version: 6.2.5 Unity Version: 2018.2.11f12

I'll review some of the other related posts, but please let me know if anything jumps out at you in terms of advice.

Thanks, Adam

[AdamKane]

Based on some of the earlier comments, I think I'll try enabling just the basic features, and disabling everything else:

[martindevans]

Can you pin down which line to GC.Alloc is coming from? The capture system is setup so it preallocates a large buffer, and then expands the buffer if it needs it later. I suspect that's the cause of the allocations here (in general Dissonance doesn't allocate much).

If you turn up the logging settings (Window > Dissonance > Diagnostic Settings) to Debug are there any relevant entries in the log? I expect you'll see Trying to read X samples, growing read buffer space to Y at the same time as the CPU spike, this indicates that the buffer expansion has kicked in (which cause a fairly large single allocation, if that triggers a GC collection pass it can be quite a large CPU spike).

A potential workaround would be to force Dissonance to allocate more buffer space ahead of time (increasing memory usage by a few KB). To do that open up BasicMicrophoneCapture.cs, find this around line 77 _maxReadBufferPower = (byte)Math.Ceiling(Math.Log(0.1f * _clip.frequency, 2)); and on the next line put:

//Immediately expand the read buffer up to it's maximum size (to avoid allocations later). This consumes about 32KB of memory assuming a 48kHz sample rate.
while (_readBuffer.Pow2 <= _maxReadBufferPower)
{
    _readBuffer.Expand());
}

[AdamKane]

Hi,

Here's the log:

...and the full log and also profiler dump is attached.

Thanks in advance for any ideas, and I'll try the suggestions in your post in the meantime. output_log.txt profiler_dump.zip

I'll report back tomorrow with the results. Thanks.

[martindevans]

That log has some telltale signs of some kind of performance issue.

Insufficient buffer space, requested 29760, clamped to 16383 (dropping samples)

This indicates that the microphone has 29760 samples of audio waiting, that's so much that Dissonance gave up and threw a load of it away (it's over half a second). All waiting audio is read every frame, so this means almost half a second has passed since the last frame.

Detected a frame skip, forcing capture pipeline reset (Delta Time:0.3333334)

This is direct confirmation of that, this measures Time.deltaTime (i.e. how long since the last frame) and logs this message if it was too long. This is probably causing the capture system to fall behind, which is why such a huge buffer is needed.

Lost 960 samples in the preprocessor (buffer full), injecting silence to compensate

This indicates one of two things. Either the preprocessor is running slow or a lot of samples were delivered all at once (more than the input queue could hold). The preprocessor runs on a dedicated thread so it's almost certainly the second one, again this is caused by a large buildup of samples, probably due to long frame times.

These problems seem to get worse later in the log. There's a long period from 01:14:42.354 to 01:26:53.142 (i.e. 12 minutes) with no problems at all. Around 01:30:59.362 (16 minutes) you seem to be losing samples in the preprocessor, but haven't yet overflowed the mic buffer. Around 01:31:25.445 (17 minutes) it's detecting a frame skip every few seconds (it's likely happening more often than this, but Dissonance ignores ones which happen too frequently). At 01:32:51.756 (18 minutes) you finally exceed the max mic buffer size.

TL;DR Something is causing bad performance (long frames) which causes Dissonance to fall behind the demands of realtime audio. Of course it's possible that this is a bug in Dissonance with long sessions, but no one else has reported any such issue and 18 minutes isn't so incredibly long that no one else would have encountered it!

[AdamKane]

Wow, thanks so much for taking such a close look!

What you're inferring matches up exactly with a known performance bug in our application. So... I'll go ahead and get that resolved, which should then clear the road for Dissonance to operate normally.

In case it's useful, I'll post back here to confirm it worked.

Fingers crossed, and thanks again!

[AdamKane]

Martin,

Thanks again for your help. You were right that resolving our other performance issues cleared the road for Dissonance to do its thing without any issues!

Cheers, Adam

[AdamKane]

Marking as closed.