search

Placeholder-Software / Dissonance

Unity Voice Chat Asset
69 stars 5 forks source link

Voice shatters when using Dissonance over a custom network #254

Closed Arngg closed 1 year ago

Arngg commented 2 years ago

Hello!

We use Dissonance for voice chat in our AR remote assist application. Our custom network (computer as dedicated server + other computer as client + AR headset as other client) is based on System.Net with separate udp connection for unreliable messages and tcp connection for reliable messages. We followed "Writing A Custom Network Integration" tutorial for Dissonance setup. The logic works nice, however the sound is "deep" and constantly shutters. Also, there are a lot of warnings such as "large audio heap", "late packets received" and "lost packets in the preprocessor".

We've disabled other data transmission (such as video) and tested our application in different environments (mobile, different WIFI-s) - the issue remains. We've also checked cpu usage and FPS on AR headset (NReal Light) and it's ok (50-60 fps). The example of audio recording + warnings will be attached to the comment in 5 min

Expected behaviour

Decent quality of audio

Actual behaviour

The voice shutters and disappears + various warnings.

Your Environment

audio example + logs on computer client: https://drive.google.com/file/d/1yvAEAm2bapFVzzRhsLpYMOPYsHz1DyRa/view?usp=sharing

Logs on android client:

05-21 16:30:10.784 3271 3289 I Unity : [Dissonance:Recording] (13:30:10.784) BasicMicrophoneCapture: Began mic capture (SampleRate:44100Hz, FrameSize:882, Buffer Limit:2^13, Latency:20ms, Device:'') 05-21 16:30:10.784 3271 3289 I Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:30:10.784 3271 3289 I Unity : 05-21 16:30:10.878 3271 3289 I Unity : [Dissonance:Network] (13:30:10.878) ConnectionNegotiator`1: Received handshake response from server, joined session '1065911250' 05-21 16:30:10.878 3271 3289 I Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:30:10.878 3271 3289 I Unity : 05-21 16:30:10.900 3271 3289 W Unity : [Dissonance:Recording] (13:30:10.899) CapturePipelineManager: Detected a frame skip, forcing capture pipeline reset (Delta Time:0.1825529) 05-21 16:30:10.900 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:30:10.900 3271 3289 W Unity : 05-21 16:30:10.966 3271 3289 I Unity : [Dissonance:Recording] (13:30:10.966) BasicMicrophoneCapture: Began mic capture (SampleRate:44100Hz, FrameSize:882, Buffer Limit:2^13, Latency:20ms, Device:'') 05-21 16:30:10.966 3271 3289 I Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:30:10.966 3271 3289 I Unity : 05-21 16:30:12.595 3271 3289 W Unity : [Dissonance:Recording] (13:30:12.595) BasePreprocessingPipeline: Lost 255 samples in the preprocessor (buffer full), injecting silence to compensate 05-21 16:30:12.595 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:30:12.595 3271 3289 W Unity : 05-21 16:30:15.157 3271 3289 W Unity : [Dissonance:Recording] (13:30:15.157) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 05-21 16:30:15.157 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:30:15.157 3271 3289 W Unity : 05-21 16:30:32.020 3271 3289 W Unity : [Dissonance:Recording] (13:30:32.015) BasePreprocessingPipeline: Preprocessor running slow! Iteration took:87ms for 0 frames 05-21 16:30:32.020 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:30:32.020 3271 3289 W Unity : 05-21 16:30:48.424 3271 3289 W Unity : [Dissonance:Recording] (13:30:48.424) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 05-21 16:30:48.424 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:30:48.424 3271 3289 W Unity : 05-21 16:30:50.332 3271 3289 I Unity : Look rotation viewing vector is zero 05-21 16:30:50.332 3271 3289 I Unity : (Filename: Line: 85) 05-21 16:30:50.332 3271 3289 I Unity : 05-21 16:31:42.190 3271 3289 W Unity : [Dissonance:Recording] (13:31:42.190) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 05-21 16:31:42.190 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:31:42.190 3271 3289 W Unity : 05-21 16:31:42.233 3271 3289 W Unity : [Dissonance:Recording] (13:31:42.226) BasePreprocessingPipeline: Preprocessor running slow! Iteration took:85ms for 0 frames 05-21 16:31:42.233 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:31:42.233 3271 3289 W Unity : 05-21 16:31:53.721 3271 3289 W Unity : [Dissonance:Recording] (13:31:53.721) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 05-21 16:31:53.721 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:31:53.721 3271 3289 W Unity : 05-21 16:32:10.346 3271 3289 W Unity : [Dissonance:Recording] (13:32:10.346) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 05-21 16:32:10.346 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:32:10.346 3271 3289 W Unity : 05-21 16:32:23.145 3271 3289 W Unity : [Dissonance:Recording] (13:32:23.145) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 05-21 16:32:23.145 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:32:23.145 3271 3289 W Unity : 05-21 16:32:26.988 3271 3289 W Unity : [Dissonance:Recording] (13:32:26.988) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 05-21 16:32:26.988 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:32:26.988 3271 3289 W Unity : 05-21 16:32:33.389 3271 3289 W Unity : [Dissonance:Recording] (13:32:33.389) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 05-21 16:32:33.389 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:32:33.389 3271 3289 W Unity : 05-21 16:32:35.971 3271 3289 W Unity : [Dissonance:Recording] (13:32:35.971) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 05-21 16:32:35.971 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:32:35.971 3271 3289 W Unity : 05-21 16:32:38.516 3271 3289 W Unity : [Dissonance:Recording] (13:32:38.516) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 05-21 16:32:38.516 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:32:38.516 3271 3289 W Unity : 05-21 16:32:41.961 3271 3289 W Unity : [Dissonance:Playback] (13:32:41.961) SpeechSession: Detected oversized buffer before playback started. Jitter:0.02848721ms (1) Buffered:360ms Expected:90ms. Discarding 270ms of audio... 05-21 16:32:41.961 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:32:41.961 3271 3289 W Unity : 05-21 16:32:43.629 3271 3289 W Unity : [Dissonance:Recording] (13:32:43.629) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 05-21 16:32:43.629 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:32:43.629 3271 3289 W Unity : 05-21 16:32:50.030 3271 3289 W Unity : [Dissonance:Recording] (13:32:50.030) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 05-21 16:32:50.030 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:32:50.030 3271 3289 W Unity : 05-21 16:32:52.600 3271 3289 W Unity : [Dissonance:Recording] (13:32:52.600) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 05-21 16:32:52.600 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:32:52.600 3271 3289 W Unity : 05-21 16:32:58.990 3271 3289 W Unity : [Dissonance:Recording] (13:32:58.990) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 05-21 16:32:58.990 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:32:58.990 3271 3289 W Unity : 05-21 16:33:00.273 3271 3289 W Unity : [Dissonance:Recording] (13:33:00.273) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 05-21 16:33:00.273 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39) 05-21 16:33:00.273 3271 3289 W Unity : 05-21 16:33:28.438 3271 3289 W Unity : [Dissonance:Recording] (13:33:28.438) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 05-21 16:33:28.438 3271 3289 W Unity : (Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 39)

martindevans commented 2 years ago

Hi, can you edit your post to fill in all of the sections with as much detail as possible and delete the template text please.

Arngg commented 2 years ago

Hi, can you edit your post to fill in all of the sections with as much detail as possible and delete the template text please.

I've accidentally hit "send" button before finishing describing the issue, sorry! Done now

martindevans commented 2 years ago

No problem, I thought that might be the case when I spotted you cut off halfway through a sentence!

Arngg commented 2 years ago

Oh, and it is also worth mentioning, that the voice coming from PC to Android is ok, the main problem is with the audio which goes the opposite way (from AR headset to PC, the recording is attached). The custom network integration scripts are the same for both builds

martindevans commented 2 years ago

Is it possible for you to use any of the other network integrations for testing (it should be fairly simple to simply build the demo scene for any network integration and run that on the devices)? As you'll see from the summary below there are a few things in the log which hint at the network taking too long to send data which is causing other systems to fall behind.

If you can't use another network system could you please add a timer around your sending/receiving code to see how long it's taking.

// Replace this:
protected override void SendReliable(CustomPeer destination, ArraySegment<byte> packet)
{
    Send_Stuff_Here();
}

// With this:
protected override void SendReliable(CustomPeer destination, ArraySegment<byte> packet)
{
    var timer = new StopWatch();
    timer.Start();

    Send_Stuff_Here();

    timer.Stop();
    Debug.Log(timer.Elapsed);
}

Some explanation on the log messages you're seeing:

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

This indicates that one single frame took 0.182 seconds which is obviously far too slow for realtime audio and so Dissonance reset itself to flush out any buffers which may have filled up in that time. This can often happen early on when a scene is first loaded and there are frame rate stutters due to content loading - if it just happens once or twice and isn't constantly happening it's not a problem.

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

The preprocessor runs on a background thread, audio samples from the mic (captured on the main thread) are sent to the preprocessor as often as possible. The preprocessor should keep that buffer empty at all times. This error indicates that the input buffer was full and 441 samples had to be discarded (the system plays back silence for 441 samples instead, to keep in sync). So either a large amount of audio was dumped into the buffer all at once (e.g. a single very long frame time caused audio to back up) or the preprocessor cannot process audio at realtime rates.

The thread which runs the preprocessor does a few tasks:

  1. Emtpty the buffer
  2. Processes the audio
  3. Encodes the audio
  4. Pass data to network system for sending

If your network system can block on sending it's possible that's causing a problem.

Preprocessor running slow! Iteration took:87ms for 0 frames

This indicates that the preprocessor thread took 87ms to process 0 frames of audio. That counter does not include frames of silence injected in, so it implies the system spent all of it's time processing silence in this particular case. This timer does include the time required to encode and send the data, so again this may indicate the network is going slow.

Detected oversized buffer before playback started. Jitter:0.02848721ms (1) Buffered:360ms Expected:90ms. Discarding 270ms of audio...

Dissonance buffers up some audio before starting playback (to handle network jitter), each frame it checks if the buffer is large enough to start playback. This indicates that although it was aiming for a 90ms buffer it ended up with a 360ms buffer. That could indicate very poor frame rates (250ms from one frame to the next, so it overshot by 250ms) or it could indicate the network delivering a huge amount of audio in one frame.

Arngg commented 2 years ago

Is it possible for you to use any of the other network integrations for testing (it should be fairly simple to simply build the demo scene for any network integration and run that on the devices)? As you'll see from the summary below there are a few things in the log which hint at the network taking too long to send data which is causing other systems to fall behind.

If you can't use another network system could you please add a timer around your sending/receiving code to see how long it's taking.

// Replace this:
protected override void SendReliable(CustomPeer destination, ArraySegment<byte> packet)
{
    Send_Stuff_Here();
}

// With this:
protected override void SendReliable(CustomPeer destination, ArraySegment<byte> packet)
{
    var timer = new StopWatch();
    timer.Start();

    Send_Stuff_Here();

    timer.Stop();
    Debug.Log(timer.Elapsed);
}

Some explanation on the log messages you're seeing:

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

This indicates that one single frame took 0.182 seconds which is obviously far too slow for realtime audio and so Dissonance reset itself to flush out any buffers which may have filled up in that time. This can often happen early on when a scene is first loaded and there are frame rate stutters due to content loading - if it just happens once or twice and isn't constantly happening it's not a problem.

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

The preprocessor runs on a background thread, audio samples from the mic (captured on the main thread) are sent to the preprocessor as often as possible. The preprocessor should keep that buffer empty at all times. This error indicates that the input buffer was full and 441 samples had to be discarded (the system plays back silence for 441 samples instead, to keep in sync). So either a large amount of audio was dumped into the buffer all at once (e.g. a single very long frame time caused audio to back up) or the preprocessor cannot process audio at realtime rates.

The thread which runs the preprocessor does a few tasks:

  1. Emtpty the buffer
  2. Processes the audio
  3. Encodes the audio
  4. Pass data to network system for sending

If your network system can block on sending it's possible that's causing a problem.

Preprocessor running slow! Iteration took:87ms for 0 frames

This indicates that the preprocessor thread took 87ms to process 0 frames of audio. That counter does not include frames of silence injected in, so it implies the system spent all of it's time processing silence in this particular case. This timer does include the time required to encode and send the data, so again this may indicate the network is going slow.

Detected oversized buffer before playback started. Jitter:0.02848721ms (1) Buffered:360ms Expected:90ms. Discarding 270ms of audio...

Dissonance buffers up some audio before starting playback (to handle network jitter), each frame it checks if the buffer is large enough to start playback. This indicates that although it was aiming for a 90ms buffer it ended up with a 360ms buffer. That could indicate very poor frame rates (250ms from one frame to the next, so it overshot by 250ms) or it could indicate the network delivering a huge amount of audio in one frame.

Sure, I'll try testing one of the official integrations (probably the Netcode for GameObjects one, because we used it as an example to make our own integration) and will come back to share the results

Arngg commented 2 years ago

Hi! I've added SDK for my AR glasses (https://developer.nreal.ai/download) to NFGO integration demo and tested it over the Internet. When using 2 computers as clients the sound is ok and there are no warnings. But when I try communicating via AR glasses and a computer the issue remains: the speech from the glasses to the PC resolves into pieces and there are numerous warnings of lost samples in the preprocessor while audio from the PC to the glasses conveys nicely. However, when I stop transmitting audio from the PC ( I set "Mute" in Dissonance Comms to true in Unity Editor) the sound from the glasses stops resolving and there are less warnings of lost samples. The FPS on the mobile device fluctuates from 50 to 60 in both cases. At first, I thought that the preprocessing system while trying to get rid of the sounds picked from the speakers cuts out too much causing the distortion. But echo cancellation system is already turned off, voice detection sensitivity is on a highest level and the broadcast trigger is set to be in an open mode.

To sum up, the network traffic is not the cause of this problem (everything works fine with 2 computers), performance of the glasses is also fine judging by FPS rate; one-way communication works good, but something is off when enabling two-way audio transmission. Correct me if I've missed something, but it looks like it's either NRSDK somehow messes up the preprocessor's background thread or the preprocessor somehow cuts out too much audio.

Logs on android client:

06-21 17:55:09.709 22288 22531 I Unity : [Dissonance:Core] (14:55:09.690) DissonanceComms: Starting Dissonance Voice Comms (8.0.4) 06-21 17:55:09.709 22288 22531 I Unity : - Network: [DissonanceSetup (Dissonance.Integrations.Unity_NFGO.NfgoCommsNetwork)] 06-21 17:55:09.709 22288 22531 I Unity : - Quality Settings: [Quality: High, FrameSize: Medium, FEC: True, DenoiseAmount: Disabled, RNN: False (0.65) VoiceDuckLevel: 1 VAD: VeryHighSensitivity] 06-21 17:55:09.709 22288 22531 I Unity : - Codec: [Codec: Opus, FrameSize: 1920, SampleRate: 48kHz] 06-21 17:55:09.815 22288 22531 I Unity : Dis_timer_elapsed:: 00:00:00.0073412 06-21 17:55:09.910 22288 22531 I Unity : [Dissonance:Recording] (14:55:09.910) BasicMicrophoneCapture: Began mic capture (SampleRate:44100Hz, FrameSize:882, Buffer Limit:2^13, Latency:20ms, Device:'') 06-21 17:55:09.954 22288 22531 I Unity : [Dissonance:Network] (14:55:09.954) ConnectionNegotiator`1: Received handshake response from server, joined session '933649449' 06-21 17:55:10.008 22288 22531 I Unity : Dis_timer_elapsed:: 00:00:00.0000376 06-21 17:55:11.390 22288 22531 W Unity : [Dissonance:Recording] (14:55:11.389) BasePreprocessingPipeline: Lost 255 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:55:17.471 22288 22531 W Unity : [Dissonance:Recording] (14:55:17.470) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:55:19.067 22288 22531 W Unity : [Dissonance:Recording] (14:55:19.066) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:55:20.188 22288 22531 W Unity : [Dissonance:Recording] (14:55:20.188) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:55:22.273 22288 22531 W Unity : [Dissonance:Recording] (14:55:22.272) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:55:27.388 22288 22531 W Unity : [Dissonance:Recording] (14:55:27.388) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:55:32.187 22288 22531 W Unity : [Dissonance:Recording] (14:55:32.187) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:55:37.787 22288 22531 W Unity : [Dissonance:Recording] (14:55:37.787) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:55:39.134 22288 22531 W Unity : [Dissonance:Recording] (14:55:39.117) BasePreprocessingPipeline: Preprocessor running slow! Iteration took:86ms for 0 frames 06-21 17:55:43.071 22288 22531 W Unity : [Dissonance:Recording] (14:55:43.071) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:55:45.305 22288 22531 W Unity : [Dissonance:Recording] (14:55:45.305) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:55:47.387 22288 22531 W Unity : [Dissonance:Recording] (14:55:47.387) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:55:47.387 22288 22531 W Unity : [Dissonance:Recording] (14:55:47.387) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:55:47.705 22288 22531 W Unity : [Dissonance:Recording] (14:55:47.705) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:55:48.188 22288 22531 W Unity : [Dissonance:Recording] (14:55:48.188) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:55:53.791 22288 22531 W Unity : [Dissonance:Recording] (14:55:53.790) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:55:54.151 22288 22531 W Unity : [Dissonance:Recording] (14:55:54.150) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:55:56.220 22288 22531 W Unity : [Dissonance:Network] (14:55:56.219) EventQueue: Large number of received packets pending dispatch (14). Possibly due to network congestion (last frame was 14.172ms) 06-21 17:56:09.148 22288 22531 W Unity : [Dissonance:Recording] (14:56:09.148) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:56:09.183 22288 22531 W Unity : [Dissonance:Recording] (14:56:09.178) BasePreprocessingPipeline: Preprocessor running slow! Iteration took:62ms for 0 frames 06-21 17:56:12.989 22288 22531 W Unity : [Dissonance:Recording] (14:56:12.987) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:56:13.788 22288 22531 W Unity : [Dissonance:Recording] (14:56:13.787) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:56:15.556 22288 22531 W Unity : [Dissonance:Recording] (14:56:15.556) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:56:15.556 22288 22531 W Unity : [Dissonance:Recording] (14:56:15.556) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:56:18.589 22288 22531 W Unity : [Dissonance:Recording] (14:56:18.589) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:56:24.249 22288 22531 W Unity : [Dissonance:Recording] (14:56:24.234) BasePreprocessingPipeline: Preprocessor running slow! Iteration took:59ms for 0 frames 06-21 17:56:31.387 22288 22531 W Unity : [Dissonance:Recording] (14:56:31.387) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:56:33.955 22288 22531 W Unity : [Dissonance:Recording] (14:56:33.954) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:56:38.904 22288 22531 W Unity : [Dissonance:Recording] (14:56:38.904) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:56:44.354 22288 22531 W Unity : [Dissonance:Recording] (14:56:44.354) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:56:49.472 22288 22531 W Unity : [Dissonance:Recording] (14:56:49.472) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:56:54.318 22288 22531 W Unity : [Dissonance:Recording] (14:56:54.316) BasePreprocessingPipeline: Preprocessor running slow! Iteration took:87ms for 0 frames 06-21 17:56:56.671 22288 22531 W Unity : [Dissonance:Recording] (14:56:56.671) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:57:04.506 22288 22531 W Unity : [Dissonance:Recording] (14:57:04.506) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:57:17.473 22288 22531 W Unity : [Dissonance:Recording] (14:57:17.473) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:57:17.788 22288 22531 W Unity : [Dissonance:Recording] (14:57:17.788) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:57:24.823 22288 22531 W Unity : [Dissonance:Recording] (14:57:24.823) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:57:38.104 22288 22531 W Unity : [Dissonance:Recording] (14:57:38.104) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:57:38.752 22288 22531 W Unity : [Dissonance:Recording] (14:57:38.752) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:57:42.753 22288 22531 W Unity : [Dissonance:Recording] (14:57:42.752) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:57:48.187 22288 22531 W Unity : [Dissonance:Recording] (14:57:48.187) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:57:51.553 22288 22531 W Unity : [Dissonance:Recording] (14:57:51.552) BasePreprocessingPipeline: Lost 441 samples in the preprocessor (buffer full), injecting silence to compensate 06-21 17:57:53.789 22288 22531 W Unity : [Dissonance:Recording] (14:57:53.788) BasePreprocessingPipeline: Lost 882 samples in the preprocessor (buffer full), injecting silence to compensate

martindevans commented 2 years ago

This looks exactly how I would expect it to look if the CPU were totally overloaded, but if you're getting solid frame rates that doesn't seem quite right. My best guess is that the preprocessor thread is being delayed waiting for something and that's causing it to fall behind (which is responsible for the poor quality audio) but not to consume all your CPU (since it's simply waiting).

Is it possible to attach a profiler to the glasses when they are running? It would be helpful to see exactly where the thread is spending it's time.

If that's not possible, could instead you try adding some extra timing in to the ThreadEntry method in Assets/Plugins/Dissonance/Core/Audio/Capture/BasePreprocessingPipeline.cs. As you'll see there's already one timer using Environment.TickCount for the entire preprocessing method, if you could wrap smaller blocks in similar timers and then add all the data to the existing "Preprocessor Running Slow" method that'll be almost as good as a profiler trace.

martindevans commented 1 year ago

Since it's been over a month I'll close this issue, but if you're still having problems feel free to comment again and I'll reopen it.