DissonanceComms.Update() Taking 25ms on a Single Frame

GabeBigBoxVR commented 6 years ago

Context

We're profiling cases where DissonanceComms.Update() is taking upwards of 25ms to complete a single frame. We're working in VR where we have a max of 11ms per frame and this is putting us way above our budget. :(

Workaround

Unknown

Fix

Unknown, still trying to find the issue

Steps to Reproduce

Unknown

Your Environment

Dissonance version used: v3.0.3 with Unity HLAPI
Unity version: 2017.3.0p3
Editor Operating System and version: Windows 10
Build Settings: Windows, x86_64, Development Build + Release

martindevans commented 6 years ago

Wow that's definitely not right! Is it possible for you to upgrade to the latest version of Dissonance to see if this issue has already been resolved?

If not (or if the issue persists in a newer version):

Could you run the profiler on the application and drill down in what's taking the time? Or just send me a profile dump and I'll take a look for you :)
Can you send me a log from a time this happened (if possible with Core turned up to Debug in the diagnostic settings)
Is this one or two frames at startup, one or two frames randomly through playback, or frequent frame during playback?

GabeBigBoxVR commented 6 years ago

I'll try upgrading to latest to see if it repros. This is one/two frames randomly through playback.

GabeBigBoxVR commented 6 years ago

I reproduced this on 6.2.0. Will try and get more information, but it's odd that it's allocating 270KB in a single frame.

capture

martindevans commented 6 years ago

270KB allocated in a single frame!? That's obviously not right.

If this is the first frame that the network system is setting itself up (is it?) it should allocate a few buffers up front (by default 32x1KB buffers) and also it'll create a load of C# objects which maybe make up another few KB at most. After that it should only allocate if it needs more than the 8 available buffers (e.g. a lot of incoming/outgoing packets all at once). HLAPI itself may also allocate (which we call out to inside Update) but I doubt it'd be allocating that much.

Is it possible to drill down any further to discover what is being allocated?

GabeBigBoxVR commented 6 years ago

This is not the first frame, it happens randomly while the game is running. I can try and drill down with deep profiling, but it slows everything down to the point where it's nearly impossible to find this.

martindevans commented 6 years ago

You could try slotting https://docs.unity3d.com/ScriptReference/Profiling.Profiler.GetMonoUsedSizeLong.html into a few places in the Update method to see if you can narrow it down. I'll try to reproduce this myself too.

martindevans commented 6 years ago

I've tried to reproduce this. Using the Dissonance HLAPI demo scene I get no allocations at all beyond the initial setup and some bytes used in the speaking indicator.

GabeBigBoxVR commented 6 years ago

This happens when we have about 5 people online in the same room at once. I'm guessing that it's related to that somehow?

martindevans commented 6 years ago

Nothing should trigger this kind of behaviour unless an incredible amount of packets are flowing, enough that the pool of buffers is exhausted and it starts allocating new buffers to hold packets. As far as I can see it'd have to be ~250 packets arriving in this single frame to trigger this much allocation which obviously isn't something that should happen in normal circumstances!

The things I'm trying to narrow it down to at the moment:

HLAPI is doing something crazy when Dissonance calls send/receive
Dissonance is doing something crazy with a reasonable number of packets (a client bug no one else has encountered)
Dissonance is doing something reasonable with a crazy number of packets (client or server side bug no one else has encountered)
Your logging levels are set too high and Dissonance is logging a vast amount of data (this would most likely affect every frame)

None of these seem particularly likely though...

Would it be possible to get a log with Networking set to Trace and every other category set to Debug? This should show me if silly numbers of packets are flying around or a huge number of other log messages are being written.

GabeBigBoxVR commented 6 years ago

I'll do that. Our logging levels are always set to Error only, so I double it's that.

Just FYI, I was experiencing issues with players voices being cut off and cutting out during speaking on 6.2 and rolled back to UNet_HLAPI 6.0.0 and it stopped. Using v6.1.0 of Dissonance. (not as old as I thought)

martindevans commented 6 years ago

Just FYI...

That's very concerning, I will have to investigate that tomorrow. Were there any Dissonance error messages in the log when this happened?

The HLAPI 6.2.0 integration changed nothing important (we attached HelpURL attributes to components) so it can't possibly be that causing the issues.

Dissonance 6.2.0 only really changed 4 potentially relevant things:

Added in a check for excessively sized jitter buffer (caused by the application being suspended or really terrible performance e.g. 90ms+ frame times)
- This prints a Warn level message when it occurs, so it should be obvious
Added support for forward error correction (improves voice quality on a lossy network)
- This can be turned off
Fixed packet loss counter measuring incorrect rate (used for a variety of quality control systems)
- This is was a trivial change (inverted boolean logic)
Fixed server relaying unreliable packets over reliable connection
- Also a trivial change

If you would be interested I can tell you precisely what was changed for the last two. Then you can install 6.2.0, watch for the oversize warning and disable the last three changes and maybe phase them in one by one.

GabeBigBoxVR commented 6 years ago

Once I finish my current work i'll switch to checking this out and see what I can repro.

On Mon, May 14, 2018 at 5:57 PM Martin Evans notifications@github.com wrote:

Just FYI...

That's very concerning, I will have to investigate that tomorrow. Were there any Dissonance error messages in the log when this happened?

The HLAPI 6.2.0 integration changed nothing important (we attached HelpURL attributes to components) so it can't possibly be that causing the issues.

Dissonance 6.2.0 only really changed 4 potentially relevant things:

Added in a check for excessively sized jitter buffer (caused by the application being suspended or really terrible performance e.g. 90ms+ frame times)

This prints a Warn level message when it occurs, so it should be obvious

Added support for forward error correction (improves voice quality on a lossy network)

This can be turned off

Fixed packet loss counter measuring incorrect rate (used for a variety of quality control systems)

This is was a trivial change (inverted boolean logic)

Fixed server relaying unreliable packets over reliable connection

Also a trivial change

If you would be interested I can tell you precisely what was changed for the last two. Then you can install 6.2.0, watch for the oversize warning and disable the last three changes and maybe phase them in one by one.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/Placeholder-Software/Dissonance/issues/92#issuecomment-389008531, or mute the thread https://github.com/notifications/unsubscribe-auth/AVWK_iR2Dsry1cbG15LC3yht69QupaH0ks5tyigMgaJpZM4T8JHs .

maburkitt commented 6 years ago

Is there any update to this issue? I have encountered a similar issue using Photon, with DissonanceComms.Update() taking a long time, and generating lots of GC. IT appears to coincide with a "detected oversized buffer before playback started" message. Again, using VR, but using unity 2018.1 and Latest release of dissonance. The issue is manifesting itself as broken audio. The framerate is generally 90FPS. We are making use of the new Unity Jobs system for some non-main thread processing, so I don't know if dissonance uses another thread for some of it's processing? Even when we turn off all other rendering and processing the issue still occurs. Seems to happen with anything from 2 to 7 or 8 people in a room.

This doesn't happen consistently, but based on the description above, I am assuming a similar think is happening, that the messages are being dumped all at once by photon. From our perspective, we would prefer the audio to be complete and delayed, rather than in-sync and inaudible. My first thought was to up the Delay multiplier in the code that culls excessive audio, or could this have some unforeseen side effects. Can provide more details if needed.

Mark

martindevans commented 6 years ago

I haven't been able to reproduce it yet, so it's at a bit of a standstill :(

I don't know if dissonance uses another thread for some of it's processing?

Dissonance makes use of two threads. The audio capture is preprocessed and encoded on a separate thread, it's possible that this could clash with the job system but that wouldn't cause these kinds of issues. The audio decode/playback is entirely driven from within the Unity audio thread, obviously that shouldn't conflict with the job system since it's a core part of Unity!

detected oversized buffer before playback started

That is interesting, Dissonance does allocate a chunk of memory to handle this. It's an error case which shouldn't happen often/ever so we weren't so careful about not allocating memory. I'll see if I can clean that up a bit (e.g. preallocate the error handling memory and recycle it).

assuming ... the messages are being dumped all at once by photon

That would cause this issue, but why would photon be doing that? The only place we've seen it is when the application is suspended (e.g. paused in editor or suspended by the hololens runtime).

we would prefer the audio to be complete and delayed, rather than in-sync and inaudible

In what way is the audio broken for you? When this warning happens Dissonance should discard enough audio to bring things back in sync and playing at the usual quality level - so you should only have a single chunk of lost speech at the start of a speech session. It's possible that a speech session stops and starts in a long pause between words which may make it slightly worse if, for some reason, we're consistently receiving too many packets.

up the Delay multiplier

I think we've already made the delays as large as they can sensibly go. It's a careful balancing act to have large delays to tolerate bad network conditions and not exceed the size of fixed size buffers, or generate too much memory usage in dynamically sized buffers.

maburkitt commented 6 years ago

Hi Martin,

We are getting this message a lot, so something is not right - below is a snapshot of 30 seconds from the output log to give you an idea of frequency. The app is in general running at around 90FPS. The audio is sometimes fine, then sometimes sounds robotic, other times cuts out completely. For example, for a sentence, some people hear it correctly, whereas others hear only a fraction of each word.

I Tried disabling all other synchronisations and background jobs, but it does appear to still be an issue.

I will do a test using the same setup, but with a scene that doesn't have anything else in it, see if the problem persists, and try to do a recording of the audio to send to you. Let me know if you would like me to raise this as a new issue.

[Dissonance:Playback] (16:17:54.853) SpeechSession: Detected oversized buffer before playback started. Buffered:120ms Expected:57ms. Discarding 63ms of audio...