encoded audio heap is getting very large (46 items) SCP Secret lab

[Smokedalmon]

Hello i've been having trouble with scpsl lately. I would very much appreciate if someone could help me Context everytime i enter a server i eventually lose connection due to a time out and i have this error in the output log encoded audio heap is getting very large (46 items)! This is probably a bug in Dissonance, we're sorry! Please report the bug on the issue tracker "https://github.com/Placeholder-Software/Dissonance/issues". You could also seek help on the community at "http://placeholdersoftware.co.uk/dissonance/community" to get help for a temporary workaround. Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C I've tried the usual stuff to do but nothing worked and the discord server tech support pointed me to ask here

Expected Behavior Normally it would let me connect and everything would be fine

Actual Behavior I get disconnected after a few min of being connected

Steps to Reproduce

I have no idea how this started, there was a previous issue but there wasn't any info on how to fix it

output_log.txt

[martindevans]

The log you've posted doesn't actually show the error you mention. What it does show is a number of other errors which are related to poor performance on the capture side, this can also cause the error you mentioned (playback heap getting large) on the playback side.

Are you getting poor frame rates or anything else indicative of bad performance? It doesn't need to be sustained bad performance, 5 seconds of bad framerates will cause realtime audio to fall behind quite badly.

[MichalPetryka]

I've wanted to report this as one of game's devs, but i see that one of our players reported it, here you have log with it https://pastebin.com/aZeA7um7 Some of our players have this in their log, its always 59EE0102-FF75-467A-A50D-00BF670E9B8C

[martindevans]

This is showing something very wrong with the rate at which packets are arriving. For example:

Line 2326: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (50 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2330: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (51 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2334: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (52 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2338: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (53 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2342: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (54 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2346: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (55 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2350: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (56 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2354: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (57 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2358: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (58 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2362: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (59 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2366: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (60 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2370: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (61 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2374: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (62 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2378: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (63 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2382: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (64 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2386: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (65 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2390: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (41 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2394: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (42 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2398: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (66 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2402: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (43 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C
Line 2406: [Dissonance:Playback] (17:40:14.301) EncodedAudioBuffer: Error: Encoded audio heap is getting very large (67 items)!  Error ID: 59EE0102-FF75-467A-A50D-00BF670E9B8C

That's 17 packets (about 700ms of audio) all arriving from the network at exactly the same time (they're delivered the frame after they arrive, so that imples that 700ms passed between frames).

On the capture side of things there are frequent messages like this:

[Dissonance:Recording] (17:40:17.022) BasicMicrophoneCapture: Insufficient buffer space, requested 111894, clamped to 16383 (dropping samples)

This means that 111,894 samples (about 2.33 seconds) passed without the microphone system being updated (which happens once a frame)!

Both of these things point to massive performance problem which is causing Dissonance to fall behind realtime.

[Smokedalmon]

The first time i checked the log it was audio heap error, i played a game to time how long i lasted, it must have changed, i lasted 2 min and 37 sec before getting disconnected. i dont get poor frame rate or performance and ive been able to play before. Strangly there was a period where it disconnected and then i could play fine and after around 3-4 days it reverted to disconnecting me. i have the original one that had the audio issue. output_log.txt

[martindevans]

The three possibilities to cause an oversized playback buffer are:

1. Packets are delivered all at once (because of a network issue delaying packets).
2. Packets are delivered all at once (because frame rate is low, so they get stuck in a buffer waiting for a frame tick).
3. Playback system isn't draining the packets fast enough.

Tackling those in reverse...

---

I don't think it's (3) because we also have this error:

> SpeechSession: Detected oversized buffer before playback started. Buffered:3440ms Expected:750ms. Discarding 2690ms of audio...

That means the buffer was inflated _before_ playback even started, so clearly playback isn't the cause.

---

If you're saying you're not encountering bad performance then it can't be (2).

---

So it must be (1), something in the network system is causing packets to be incredibly delayed and then delivering them all at once. This is actually somewhat corroborated by this other error:

Error: Received a very late packet (45 packets late)!

Which means that a packet was delivered out of order (that's fine) but it was delivered very out of order - 45 packets late means it arrived about 1.8 seconds late! Something very bad seems to be going on with networking here. @MichalPetryka any ideas what could cause that in your network system?

[Smokedalmon]

Do you have any suggestions on how to solve it, like reinstall unity, dissonance or something like that?

[martindevans]

The fix is unlikely to be anything like that, it's going to be something in the network system of the game or the network system of Dissonance interacting badly with the game. We'll have to see what @MichalPetryka says.

[MichalPetryka]

We're using UNET with Dissonance's integration, I don't know what could cause packet delays, everything is ok for most players

[Smokedalmon]

output_log.txt another same result as before

[martindevans]

This shows a similar set of errors to before:

• A single very long frame (Detected a frame skip, forcing capture pipeline reset (Delta Time:0.3333333)), this is right at the start so is probably caused by some kind of loading slowing things down - it's probably ok since it just happens once
• Increasingly bad packet delays, at one point 58 packets are delivered at exactly the same time (search for 20:50:11.388), that's 2.3 seconds of audio!

One other thing which I noticed, after the buffer oversize warnings is this error:

Log: connection {1} has been disconnected by timeout; address {::ffff:75.179.138.195:7778} time {151149}, last rec time {148069} rtt {384} timeout {3000}

That's the network system timing out. So I still think that something at a lower level than Dissonance is causing very bad network conditions and eventually causes a timeout of the entire game networking. @Smokedalmon did you gracefully quit from this match or did you crash/timeout/get kicked etc?

[Smokedalmon]

i got timed out. my internet is really bad and i cant upgrade it

[Smokedalmon]

i think its my internet bc i connected to my phone hotspot and it worked fine

[Smokedalmon]

It started to time out on the hotspot

[martindevans]

Thanks for testing that on a different connection, that's very helpful. Unfortunately if this is a network problem there's obviously nothing we can do to fully solve the problem.

I'm going to have a look through some of the involved systems today to see if I can at least improve the error logging messages in this kind of situation, e.g. log out the latency/jitter when it happens so we can pin it down to a network problem more easily next time. I will also consider if there's anything we can do to make this kind of thing less bad (e.g. discard more audio to bring you back to speech sync), that kind of thing is extremely complex though and has a chance of breaking the pipeline in other situations so no promises I'll manage anything there.

[MichalPetryka]

I think that it only occures for people with bad internet connection, it might be caused by our really bad walking sound syncing which sends lots of packets, that may cause network overload (we are going to remake it in future)

[martindevans]

That sounds like a good guess - something sending out lots of packets over a bad connection can easily cause intermediate buffers to bloat and therefore massive delays. That in turn would obviously cause Dissonance packets to arrive late (and potentially all at once) which causes all the errors we're seeing.

[Smokedalmon]

So case closed, its my internet

[martindevans]

That does seem likely to be the root cause. However I do plan to do a review of the network and playback systems to see if we can handle bad network conditions better. From what I see in your logs it looks like the worst network conditions I've ever seen (perhaps made worse by the walking sound syncing Michal mentioned congesting the network even more). I doubt we can salvage your situation but maybe we can improve things a little bit :)

[Smokedalmon]

Thank you for all the help

[martindevans]

I've just submitted Dissonance 6.2.6 to the asset store with some extra sanity checking and logging that would help diagnose this kind of problem in the future. For example once this makes its way into SCP I imagine you should see a message like this in the log:

Large number of received packets pending dispatch (NNN). Possibly due to network congension (last frame was 16ms)

Where NNN indicates that that many packets were delivered all at once (due to network congestion).

[MichalPetryka]

@martindevans We've updated to dissonance 6.2.6, but logs like that don't appear

[martindevans]

To clarify, those errors should only appear for users suffering from bad voice quality due to network congestion. Are you not seeing these log messages for users suffering from this problem?

[MichalPetryka]

I haven't seen them at all, while i've seen other warnings.

[MichalPetryka]

Also, i'm getting this even with host (client is a server)

[Dissonance:Recording] (16:51:47.321) BasicMicrophoneCapture: Insufficient buffer space, requested 33516, clamped to 16383 (dropping samples)

(Filename: C:\buildslave\unity\build\Runtime/Export/Debug.bindings.h Line: 43)

[Dissonance:Recording] (16:51:47.322) BasePreprocessingPipeline: Lost 255 samples in the preprocessor (buffer full), injecting silence to compensate

(Filename: C:\buildslave\unity\build\Runtime/Export/Debug.bindings.h Line: 43)

[Dissonance:Recording] (16:51:47.322) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate

(Filename: C:\buildslave\unity\build\Runtime/Export/Debug.bindings.h Line: 43)

[Dissonance:Recording] (16:51:47.322) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate

(Filename: C:\buildslave\unity\build\Runtime/Export/Debug.bindings.h Line: 43)

[Dissonance:Recording] (16:51:47.322) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate

(Filename: C:\buildslave\unity\build\Runtime/Export/Debug.bindings.h Line: 43)

[Dissonance:Recording] (16:51:47.322) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate

(Filename: C:\buildslave\unity\build\Runtime/Export/Debug.bindings.h Line: 43)

[Dissonance:Recording] (16:51:47.322) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate

(Filename: C:\buildslave\unity\build\Runtime/Export/Debug.bindings.h Line: 43)

[Dissonance:Recording] (16:51:47.322) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate

(Filename: C:\buildslave\unity\build\Runtime/Export/Debug.bindings.h Line: 43)

[Dissonance:Recording] (16:51:47.322) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate

(Filename: C:\buildslave\unity\build\Runtime/Export/Debug.bindings.h Line: 43)

[Dissonance:Recording] (16:51:47.322) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate

(Filename: C:\buildslave\unity\build\Runtime/Export/Debug.bindings.h Line: 43)

[Dissonance:Recording] (16:51:47.322) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate

(Filename: C:\buildslave\unity\build\Runtime/Export/Debug.bindings.h Line: 43)

[Dissonance:Recording] (16:51:47.322) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate

(Filename: C:\buildslave\unity\build\Runtime/Export/Debug.bindings.h Line: 43)

[Dissonance:Recording] (16:51:47.323) CapturePipelineManager: Detected a frame skip, forcing capture pipeline reset (Delta Time:0,3333333)

(Filename: C:\buildslave\unity\build\Runtime/Export/Debug.bindings.h Line: 43)

My teammates aren't getting it, it's only appearning for me.

[MichalPetryka]

Actually, i've searched our tech support for logs and they have that message

[martindevans]

This looks like a different problem to before. Previously the problem was playback delay caused by terrible network conditions, which is what the extra messages I added should detect.

However these messages are from the capture side and look like a more general performance problem:

BasePreprocessingPipeline: Lost [...] samples in the preprocessor (buffer full), injecting silence to compensate

Indicates that the preprocessor is falling behind or the mic is providing too much audio.

This thread does preprocessing, encoding and network sending, so it can only fall behind if the CPU is too busy to do the work, or if something in the network layer is delaying it. If the the mic is supplying too much data that would be an audio driver problem, which we can rule out since several people have the problem.

Is your network layer using background threads for sending? I guess it's possible there's some kind of locking problem delaying things.

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

This is a more direct indication of a performance problem - a single frame took 0.3 seconds. If that only happens once or twice it's not a huge problem, as long as frame times are usually ok.

[MichalPetryka]

I've noticed that it only occures for users with Realtek audio cards (at least all users with issues like this say that they have Realtek drivers)

[MichalPetryka]

No idea about background threads, haven't really looked into uNet (that's what we currently use)

[martindevans]

background threads … [we use uNet]

I knew you had been considering moving to something else (e.g. Mirror+Ignorance) - I wasn't sure if you'd made that move yet. A lot of people use uNet with Dissonance so it's probably not a problem in the network layer.

Realtek

It could be possible that Realtek cards have a bad input system which causes them to over buffer and supply too much audio all at once, this could theoretically overflow the buffers and cause the "Lost pre-processor samples" error.

Unfortunately if it is a hardware/driver problem it's very much out of our control! The only potential fix would be to use a different Windows Audio API to capture mic input (using a custom mic component) and hope that the Realtek cards don't produce the same behaviour with that API.

Warnings & Errors

When you see the lost "pre-processor samples" error do you also see these messages (earlier in the log):

DEBUG Trying to read XXX samples, growing read buffer space to YYY

WARN Insufficient buffer space, requested XXX, clamped to YYY (dropping samples)

[Bloomsi]

Hi, I had a similar issue. My mic "Default Format" was set at 48000Hz in windows device properties. I resolved it by changing it to 41000hz. The problem is gone. Check your mic device properties in Windows.