Severe Delays in WriteBinary and Connect Calls in Deepgram Go SDK

ToxicityMax commented 1 month ago

What is the current behavior?

The Deepgram Go SDK is experiencing significant delays when sending audio packets over a websocket. Specifically, the WriteBinary calls often take much longer than expected, 2-5 seconds and sometimes up to 15 seconds. Additionally, the Connect call can also take an unusually long time, up to 2-3 seconds. These delays cause severe audio packet loss, affecting the overall performance of the audio processing pipeline.

Steps to reproduce

Implement the Deepgram Go SDK (version 1.4.0) in a Go application.
Send a high volume of audio packets over a websocket.
Log the time taken for each WriteBinary and Connect call.
Observe the delays, particularly after sending a batch of packets.

Expected behavior

The WriteBinary calls should consistently complete within 100µs to less than 100-200ms.

Please tell us about your environment

Operating System/Version: Ubuntu 20.04
Go Version: v1.22
Deepgram SDK versions: v1.4.0, v1.36.0, v1.35.0, v.1.2.1

Other information

The delays are suspected to stem from an internal keep-alive periodic loop within the Deepgram SDK. This loop holds a lock for longer than anticipated, which impacts the performance of WriteBinary and Connect calls.
The WriteBinary method locks c.muConn to ensure exclusive access to the WebSocket connection. This mutex lock prevents concurrent write operations but may introduce delays if multiple goroutines are trying to write simultaneously. This lock contention could lead to increased wait times for acquiring the lock.
The internalConnect method is called for every write operation including KeepAlive, WriteBinary, WriteJson. It may involve re-establishing the connection if it is invalid. This can add latency, especially if the connection is not immediately available or if internalConnect frequently reestablishes connections.
Despite batching packets to reduce the number of WriteBinary calls, the issue persists.
The delays caused the pipeline for reading audio packets to choke, resulting in severe audio packet loss. Despite optimizations, transcription times remain excessively long.
Even with optimizations above, it sometimes takes up to 15 seconds

Example logs:

Write Binary took: 2.620393163s
Write Binary took: 3.215650843s
Write Binary took: 4.830298621s
Write Binary took: 2.358158705s
Write Binary took: 15.915874898s

Connect taking >2s

I0721 13:43:43.949184      1 client.go:153] live.internalConnectWithCancel() ENTER
I0721 13:43:43.949198      1 client.go:169] Locking connection mutex
I0721 13:43:43.949207      1 client.go:193] Context is still valid. Retry...
I0721 13:43:43.949277      1 version.go:45] host decompose... match: false
I0721 13:43:43.949288      1 version.go:58] protocol: wss
I0721 13:43:43.949294      1 version.go:59] host: api.deepgram.com
I0721 13:43:43.949319      1 version.go:69] path decompose - match: false
I0721 13:43:43.949363      1 client.go:247] Connecting to wss://api.deepgram.com/v1/listen?{query_params}
I0721 13:43:45.003816      1 client.go:775] Starting ping...
I0721 13:43:45.003835      1 client.go:778] Sending Deepgram KeepAlive message...
I0721 13:43:45.003845      1 client.go:597] live.KeepAlive() ENTER
I0721 13:43:45.003853      1 client.go:534] live.WriteJSON() ENTER
I0721 13:43:46.117175      1 client.go:252] HTTP Response: 101 Switching Protocols
Received open callback from deepgram
I0721 13:43:46.117230      1 client.go:297] live.listen() ENTER
I0721 13:43:46.117232      1 client.go:282] WebSocket Connection Successful!
I0721 13:43:46.117242      1 client.go:741] live.ping() ENTER
I0721 13:43:46.117250      1 client.go:283] live.internalConnectWithCancel() LEAVE
[DEEPGRAM] Connect:  2.168079244s

Write taking >3s

I0721 14:06:26.385218      1 client.go:497] live.WriteBinary() ENTER
I0721 14:06:26.385223      1 client.go:153] live.internalConnectWithCancel() ENTER
I0721 14:06:26.385228      1 client.go:182] Connection is good. Return object.
I0721 14:06:26.385232      1 client.go:183] live.internalConnectWithCancel() LEAVE
I0721 14:06:28.220183      1 client.go:775] Starting ping...
I0721 14:06:28.220199      1 client.go:778] Sending Deepgram KeepAlive message...
I0721 14:06:28.220204      1 client.go:597] live.KeepAlive() ENTER
I0721 14:06:28.220208      1 client.go:534] live.WriteJSON() ENTER
I0721 14:06:29.600169      1 client.go:522] WriteBinary Successful
I0721 14:06:29.600190      1 client.go:523] payload: 
I0721 14:06:29.600790      1 client.go:524] live.WriteBinary() LEAVE
Batch in transcription (time: 1721570786385) (length: 96000)
Write Binary took: 3.215650843s
I0721 14:06:29.600829      1 client.go:153] live.internalConnectWithCancel() ENTER
I0721 14:06:29.600869      1 client.go:182] Connection is good. Return object.
I0721 14:06:29.600878      1 client.go:183] live.internalConnectWithCancel() LEAVE

dvonthenen commented 1 month ago

hi @ToxicityMax

thanks for the bug report. Will take a look.

dvonthenen commented 1 month ago

hi @ToxicityMax

To try this out, I took an web stream which is very chatty and captured some times along with sending keepalives. This is what I ended up capturing. The output was pretty consistent.

I0723 11:47:05.023154   20797 options.go:19] DEEPGRAM_API_KEY found
I0723 11:47:05.023416   20797 client.go:97] Using DefaultCallbackHandler.
I0723 11:47:05.023420   20797 client.go:113] NewDeepGramWSClient Succeeded
Stream is up and running *http.Response
I0723 11:47:08.470015   20797 client.go:169] Locking connection mutex
I0723 11:47:08.470062   20797 client.go:193] Context is still valid. Retry...
I0723 11:47:08.470351   20797 version.go:45] host decompose... match: false
I0723 11:47:08.470374   20797 version.go:58] protocol: wss
I0723 11:47:08.470386   20797 version.go:59] host: api.deepgram.com
I0723 11:47:08.470446   20797 version.go:69] path decompose - match: false
I0723 11:47:08.620748   20797 client.go:252] HTTP Response: 101 Switching Protocols

[OpenResponse]

I0723 11:47:08.620837   20797 client.go:282] WebSocket Connection Successful!
I0723 11:47:08.972348   20797 client.go:487] live.Stream.Write() took 190.083µs
I0723 11:47:08.972493   20797 client.go:487] live.Stream.Write() took 68.833µs
I0723 11:47:08.972587   20797 client.go:487] live.Stream.Write() took 59.417µs
I0723 11:47:08.972657   20797 client.go:487] live.Stream.Write() took 54.083µs
I0723 11:47:08.972752   20797 client.go:487] live.Stream.Write() took 51.208µs
I0723 11:47:08.972815   20797 client.go:487] live.Stream.Write() took 48.333µs
I0723 11:47:09.131887   20797 client.go:487] live.Stream.Write() took 233.5µs
I0723 11:47:09.132050   20797 client.go:487] live.Stream.Write() took 92.333µs
I0723 11:47:09.132255   20797 client.go:487] live.Stream.Write() took 81.291µs
I0723 11:47:09.132428   20797 client.go:487] live.Stream.Write() took 151.416µs
I0723 11:47:09.132518   20797 client.go:487] live.Stream.Write() took 60.5µs
I0723 11:47:09.132585   20797 client.go:487] live.Stream.Write() took 53.041µs
I0723 11:47:09.132658   20797 client.go:487] live.Stream.Write() took 47.541µs
I0723 11:47:09.132769   20797 client.go:487] live.Stream.Write() took 96.917µs
I0723 11:47:09.132848   20797 client.go:487] live.Stream.Write() took 56.875µs
I0723 11:47:09.132916   20797 client.go:487] live.Stream.Write() took 54.708µs
I0723 11:47:09.132989   20797 client.go:487] live.Stream.Write() took 52.125µs
I0723 11:47:09.133054   20797 client.go:487] live.Stream.Write() took 51µs
I0723 11:47:09.133180   20797 client.go:487] live.Stream.Write() took 50.083µs
I0723 11:47:09.133231   20797 client.go:487] live.Stream.Write() took 26.959µs
I0723 11:47:09.174068   20797 client.go:487] live.Stream.Write() took 113.542µs
I0723 11:47:09.174156   20797 client.go:487] live.Stream.Write() took 39.625µs
I0723 11:47:09.289775   20797 client.go:487] live.Stream.Write() took 138.583µs
I0723 11:47:09.289895   20797 client.go:487] live.Stream.Write() took 56.291µs
I0723 11:47:09.289950   20797 client.go:487] live.Stream.Write() took 34.25µs
I0723 11:47:09.289999   20797 client.go:487] live.Stream.Write() took 39.166µs
I0723 11:47:09.290042   20797 client.go:487] live.Stream.Write() took 29.208µs
I0723 11:47:09.290076   20797 client.go:487] live.Stream.Write() took 26.916µs
I0723 11:47:09.290114   20797 client.go:487] live.Stream.Write() took 26.208µs
I0723 11:47:09.290145   20797 client.go:487] live.Stream.Write() took 24.625µs
I0723 11:47:09.290185   20797 client.go:487] live.Stream.Write() took 29.042µs
I0723 11:47:09.290221   20797 client.go:487] live.Stream.Write() took 28.667µs
I0723 11:47:09.290273   20797 client.go:487] live.Stream.Write() took 29.5µs
I0723 11:47:09.290311   20797 client.go:487] live.Stream.Write() took 30.667µs
I0723 11:47:09.290348   20797 client.go:487] live.Stream.Write() took 29.459µs
I0723 11:47:09.299827   20797 client.go:487] live.Stream.Write() took 44.416µs
I0723 11:47:09.364289   20797 client.go:487] live.Stream.Write() took 165.583µs
I0723 11:47:09.427427   20797 client.go:487] live.Stream.Write() took 123.583µs
I0723 11:47:09.485353   20797 client.go:487] live.Stream.Write() took 126.125µs
I0723 11:47:09.555056   20797 client.go:487] live.Stream.Write() took 132.167µs
I0723 11:47:11.473136   20797 client.go:487] live.Stream.Write() took 161.875µs

[MessageResponse] (Final) Because, you know, she vietnamese daughter. She has to be
I0723 11:47:11.535954   20797 client.go:487] live.Stream.Write() took 108.458µs
I0723 11:47:11.597601   20797 client.go:487] live.Stream.Write() took 118.584µs
I0723 11:47:11.661139   20797 client.go:487] live.Stream.Write() took 138.166µs
I0723 11:47:11.721552   20797 client.go:487] live.Stream.Write() took 125.166µs
I0723 11:47:11.781476   20797 client.go:487] live.Stream.Write() took 109.542µs
I0723 11:47:11.854182   20797 client.go:487] live.Stream.Write() took 140µs
I0723 11:47:11.920868   20797 client.go:487] live.Stream.Write() took 137.833µs
I0723 11:47:11.992807   20797 client.go:487] live.Stream.Write() took 113.792µs
I0723 11:47:12.054853   20797 client.go:487] live.Stream.Write() took 124.584µs
I0723 11:47:13.622600   20797 client.go:788] KeepAlive took 484µs
I0723 11:47:13.622662   20797 client.go:797] KeepAlive total 562.75µs
I0723 11:47:13.957911   20797 client.go:487] live.Stream.Write() took 162.542µs
I0723 11:47:14.026284   20797 client.go:487] live.Stream.Write() took 170.5µs
I0723 11:47:14.084280   20797 client.go:487] live.Stream.Write() took 115.416µs
I0723 11:47:14.144113   20797 client.go:487] live.Stream.Write() took 90.042µs

[MessageResponse] (Final) like her mom and everything. So now she's like,
I0723 11:47:14.214681   20797 client.go:487] live.Stream.Write() took 173.625µs
I0723 11:47:14.280933   20797 client.go:487] live.Stream.Write() took 149.542µs
I0723 11:47:14.348692   20797 client.go:487] live.Stream.Write() took 163.166µs
I0723 11:47:14.418492   20797 client.go:487] live.Stream.Write() took 171.916µs
I0723 11:47:14.483041   20797 client.go:487] live.Stream.Write() took 112.417µs
I0723 11:47:14.547900   20797 client.go:487] live.Stream.Write() took 146.542µs
I0723 11:47:14.620780   20797 client.go:487] live.Stream.Write() took 168.792µs
I0723 11:47:14.672964   20797 client.go:487] live.Stream.Write() took 103.625µs
I0723 11:47:14.740687   20797 client.go:487] live.Stream.Write() took 203.666µs
I0723 11:47:14.804617   20797 client.go:487] live.Stream.Write() took 126.833µs
I0723 11:47:14.863261   20797 client.go:487] live.Stream.Write() took 156.75µs
I0723 11:47:14.930339   20797 client.go:487] live.Stream.Write() took 118.042µs
I0723 11:47:14.999019   20797 client.go:487] live.Stream.Write() took 175.917µs
I0723 11:47:15.064329   20797 client.go:487] live.Stream.Write() took 156.625µs
I0723 11:47:15.117409   20797 client.go:487] live.Stream.Write() took 144.5µs
I0723 11:47:15.168892   20797 client.go:487] live.Stream.Write() took 153.834µs
I0723 11:47:16.942861   20797 client.go:487] live.Stream.Write() took 252.292µs
I0723 11:47:17.006782   20797 client.go:487] live.Stream.Write() took 133.291µs
I0723 11:47:17.075311   20797 client.go:487] live.Stream.Write() took 188.041µs
I0723 11:47:17.134850   20797 client.go:487] live.Stream.Write() took 134.875µs
I0723 11:47:17.198178   20797 client.go:487] live.Stream.Write() took 153.166µs
I0723 11:47:17.261212   20797 client.go:487] live.Stream.Write() took 140µs
I0723 11:47:17.320880   20797 client.go:487] live.Stream.Write() took 143.041µs
I0723 11:47:17.382806   20797 client.go:487] live.Stream.Write() took 111.75µs
I0723 11:47:17.453135   20797 client.go:487] live.Stream.Write() took 135.958µs
I0723 11:47:17.521284   20797 client.go:487] live.Stream.Write() took 108.042µs

[MessageResponse] (Final) my mentor because I always look up to her when, you know, before a major champ or when
I0723 11:47:18.622542   20797 client.go:788] KeepAlive took 308.667µs
I0723 11:47:18.622608   20797 client.go:797] KeepAlive total 459.584µs
I0723 11:47:19.435949   20797 client.go:487] live.Stream.Write() took 163.041µs
I0723 11:47:19.495652   20797 client.go:487] live.Stream.Write() took 98.375µs
I0723 11:47:19.556968   20797 client.go:487] live.Stream.Write() took 151.792µs
I0723 11:47:19.617314   20797 client.go:487] live.Stream.Write() took 133.791µs
I0723 11:47:19.690947   20797 client.go:487] live.Stream.Write() took 153µs
I0723 11:47:19.749924   20797 client.go:487] live.Stream.Write() took 137.042µs
I0723 11:47:19.816203   20797 client.go:487] live.Stream.Write() took 150.958µs
I0723 11:47:19.887813   20797 client.go:487] live.Stream.Write() took 125.042µs
I0723 11:47:19.947351   20797 client.go:487] live.Stream.Write() took 119.792µs
I0723 11:47:20.003942   20797 client.go:487] live.Stream.Write() took 136.708µs
I0723 11:47:20.081286   20797 client.go:487] live.Stream.Write() took 127.041µs
I0723 11:47:20.148877   20797 client.go:487] live.Stream.Write() took 155.791µs
I0723 11:47:20.207423   20797 client.go:487] live.Stream.Write() took 145µs
I0723 11:47:20.286608   20797 client.go:487] live.Stream.Write() took 128.166µs
I0723 11:47:20.352653   20797 client.go:487] live.Stream.Write() took 149.542µs
I0723 11:47:20.423400   20797 client.go:487] live.Stream.Write() took 128.917µs
I0723 11:47:20.510859   20797 client.go:487] live.Stream.Write() took 121.666µs
I0723 11:47:20.569095   20797 client.go:487] live.Stream.Write() took 131.083µs
I0723 11:47:20.631816   20797 client.go:487] live.Stream.Write() took 157.125µs
I0723 11:47:20.694623   20797 client.go:487] live.Stream.Write() took 120.708µs

What region are you in? Is it ap-south-1 by any chance?

ToxicityMax commented 1 month ago

Hey! Yes I am located in the ap-south-1 region. Historically, this hasn't impacted our performance ever, and we've consistently experienced good-quality transcriptions with minimal latency. However, starting around last 18 july, we've encountered significant performance degradation and severe delays.

>> ping api.deepgram.com
64 bytes from 38.142.135.243: icmp_seq=8 ttl=39 time=254.525 ms

dvonthenen commented 1 month ago

This, unfortunately, is a known issue that started several weeks (4+) ago. Here is some additional info on how to mitigate this issue: https://discord.com/channels/1108042150941294664/1264193396726304868/1264349196182618182

Closing the issue since this isn't SDK related.

deepgram / deepgram-go-sdk