sound comes out delayed - by a lot!

[Francesco Potortì]

Running Xpra 4.0.3 on Debian testing on both sides. I use --env=XPRA_CUTTER_THRESHOLD=0 because of #2855

I was observing a delay of 27s on sound from a server started about 9h ago. So I killed everything and started a fresh Xpra from the client like this:

xpra start $remote --attach=auto --use-display=auto --speaker=on --border=\#CCCC00 --env=XPRA_CUTTER_THRESHOLD=0 --start=editor

As soon as started, the sound is delayed by about one second. After 15m the delay is about 2s. After 40m is about 3s. After 2h about 7s. After 2h15m about 9s.

The sound I am playing is a single beep 50ms long: date; DISPLAY=:7 play -qn synth 0.05 pluck 1000 2>/dev/null. I measure the delay by issuing a further date command and pressing RET when I hear the beep. As expected, when I issue the play command locally the beep is immediate (no delay).

I am leaving for a vacation far from the client system exhibiting the problem, so I will not be able to make new tests until end of August.

[Antoine Martin]

Have you tried different codecs?
Please post the server and client log when running with -d sound,gstreamer.

I could be wrong, but I suspect that the buffering happens client side.
We use the ​gstreamer appsrc element to feed the audio buffers, with the following settings:

• do-timestamp unset (you can try changing this setting in sink.py)
• emit-signals=0
• block=0
• is-live=0
• stream-type=stream
• format=buffers

The buffers we push do not have a timestamp, the code is commented out and says: having a timestamp causes problems with the queue and overruns. (probably because the timestamp value would come from the server, which does not necessarily have the same clock as the client)

Then there are a bunch of elements, including a buffer - but this one is bounded and we drop buffers if too many of them accumulate. (you can see how full it is on the session info window graphs pane)

At the end of the pipeline is usually ​pulsesink without any specific attributes.

You can see the full pipeline used by running with -d sound.
It is possible that we need to tweak some settings somewhere... It is also quite possible that the problem is not reproducible on other hardware (we've seen this before), so very hard for me to fix.

See ​Clocks and synchronization in GStreamer.

[Francesco Potortì]

Ok, came back from vacations. By the way, on a server up for 7 days, the sound gets delayed by almost 7 minutes!

I attach a log from the server started with -d sound,gstreamer (which grows costantly). More info later.

[Francesco Potortì]

The above problem is with opus. Using vorbis the sound does not come out at all. mp3 seems to have no problems: the delay is noticeable but below one second still after 30 minutes from server start.

However, I have the impression thta the ddelay is increasing, so I'll report later again.

[Francesco Potortì]

Updates. both mp3 and wav exhibit the same problem, albeit slower.

In comparison, opus gets a 3s delay after 40 minutes, wav and mp3 after 100m, vorbis does not work at all.

The sound buffer is always under 250ms

If I can do anything else do diagnose or even work around the problem please let me know. I use sound for alarms, but if they come several minutes later they are not so useful :)

[Antoine Martin]

The sound buffer is always under 250ms

Then there's not much we can do.

If I can do anything else do diagnose or even work around the problem please let me know.

See comment:2.

[Francesco Potortì]

Replying to Antoine Martin:

• do-timestamp unset (you can try changing this setting in sink.py)

I want to try this. I uncommented the line in the .py file and changed the name of __pycache__/sink.cpython-38.pyc to sink.cpython-38.pyc.orig

I am around the beginner level with Python, but I suppose this should be enough, please let me know if it isn't.

Apparently nothing changed. Now I see a 43s delay for a server launched 25h ago

[Antoine Martin]

do-timestamp unset
Apparently nothing changed

You can try to also change is-live=.
Maybe a specific combination will work, hard to tell.

and changed the name of __pycache__/sink.cpython-38.pyc to ...

You can just delete that file or even the whole __pycache__.

[Francesco Potortì]

Tried the four combinations of do-timestamp and is-live, with no changes.

[Antoine Martin]

Maybe I was wrong and the delay is server-side?
You should be able to see the memory growing wherever the buffering is occurring.

See also #2517

[Francesco Potortì]

I just noticed that the delay is reset if I disconnect from the server
and then reconnect (the server is remote).

Update:
The data and resident memory of client end server do not change appreciably, yet the delay increases

[Antoine Martin]

I just noticed that the delay is reset if I disconnect from the server and then reconnect (the server is remote).

Every new client gets its own audio connection, so this is expected.

The data and resident memory of client end server do not change appreciably, yet the delay increases

The buffering has to happen somewhere... and if it is not in the xpra process then maybe it's not xpra's fault. Find the where the buffering occurs and you should be able to fix it.

[Francesco Potortì]

Client connected for 18h, sound delay is 93s (increasing linearly with time).

Memory occupancy on server 3h and after 18h (I don't see any difference)

Thu Oct 29 22:38:59 CET 2020
    PID TTY      STAT   TIME  MAJFL   TRS   DRS   RSS %MEM COMMAND
1648801 ?        Ssl    1:18      1  2384 194175 25256  0.2 /usr/bin/python3 /usr/bin/xpra _proxy_start :7 --b
1648827 ?        Ssl   19:51      1  2384 817079 55408  0.4 python3.8 /usr/bin/xpra --windows=no --video-encod
2343462 ?        Rl   985:20   1183  2384 1504355 321604  2.6 /usr/bin/python3 /usr/bin/xpra start :7 --border
2343480 ?        Ssl   20:51     54  1356 861243 114828  0.9 Xvfb-for-Xpra-:7 +extension GLX +extension Compos
2343521 ?        S<l  390:24     59    36 247339 6140  0.0 pulseaudio --start -n --daemonize=false --system=fa

Fri Oct 30 13:00:52 CET 2020
    PID TTY      STAT   TIME  MAJFL   TRS   DRS   RSS %MEM COMMAND
1648801 ?        Ssl    9:04      1  2384 194175 21956  0.1 /usr/bin/python3 /usr/bin/xpra _proxy_start :7 --b
1648827 ?        Ssl  138:02    101  2384 902659 58096  0.4 python3.8 /usr/bin/xpra --windows=no --video-encod
2343462 ?        Sl   1046:31  1230  2384 1513063 316080  2.6 /usr/bin/python3 /usr/bin/xpra start :7 --border
2343480 ?        Ssl   21:14     57  1356 861243 114412  0.9 Xvfb-for-Xpra-:7 +extension GLX +extension Compos
2343521 ?        S<l  414:37     70    36 247339 6060  0.0 pulseaudio --start -n --daemonize=false --system=fa

Same on client:

Thu Oct 29 22:39:06 CET 2020
    PID TTY      STAT   TIME  MAJFL   TRS   DRS   RSS %MEM COMMAND
1789749 pts/1    Sl+   20:55      1  2384 2095159 206796  1.0 /usr/bin/python3 /
1789862 ?        Ssl   17:49      0  2384 1096299 60672  0.2 python3.8 /usr/bin/
1789866 ?        Ss     0:00      0  2384 13047  8312  0.0 /usr/bin/python3 /usr

Fri Oct 30 13:12:43 CET 2020
    PID TTY      STAT   TIME  MAJFL   TRS   DRS   RSS %MEM COMMAND
1789749 pts/1    Sl+  144:05      2  2384 2348183 215484  1.0 /usr/bin/python3 /usr/bin/xpra start ssh://fly.i
1789862 ?        Ssl  130:40      0  2384 1102511 67348  0.3 python3.8 /usr/bin/xpra --windows=no --video-enco
1789866 ?        Ss     0:00      0  2384 13047  8312  0.0 /usr/bin/python3 /usr/bin/xpra_signal_listener

Xpra invoked from client like this:

$ xpra start $remote --attach=auto --use-display=auto --dpi=86 --speaker=on --env=XPRA_CUTTER_THRESHOLD=0 --border=\#CCCC00 --start=editor

[Antoine Martin]

Why is the client pid different? Did you re-connect?

The only other thing I can think of is to add a save-to-file option, then we'll be able to play the last second of each file and see where we're at, at least this should tell us which side has the leak.

[Francesco Potortì]

Replying to Antoine Martin:

Why is the client pid different? Did you re-connect?

Sorry, bad paste. I edited my previous comment with correct data.

The only other thing I can think of is to add a save-to-file option, then we'll be able to play the last second of each file and see where we're at, at least this should tell us which side has the leak.

Ok, just let me know what I should try next.

[Antoine Martin]

The code for saving audio streams to file already existed for the capture side (which is the server side for speaker forwarding), r27815 refactors it so that the playback can also use it (ie: client side for speaker forwarding).
Just because it doesn't really cost anything to add (defaults to off), r27816 also adds a pipe flushing option via the XPRA_SUBPROCESS_FLUSH=1 environment variable. I don't see why the subprocess module would add any buffering to the audio pipes, but worth a try anyway since I'm out of ideas.

Running with:

XPRA_SUBPROCESS_FLUSH=1 XPRA_SAVE_AUDIO=server xpra start --start=xterm :20
XPRA_SUBPROCESS_FLUSH=1 XPRA_SAVE_AUDIO=client xpra attach :20 --speaker-codec=mp3

Should create two files: server1.mp3 and client1.mp3.
(more if the audio is re-started)

Note: not all codecs can be used as files without a container format, mp3 can. All codecs that use a container should also work (anything with ogg or mka)

The files are synced to the filesystem after each write, so if you take a snapshot of both files at the same time then you should be able to see if they're roughly at the same point.

The problem is that this stream capture happens at the packet level so that we can construct a valid stream file, but since there should not be any buffering happening between the xpra packets and the audio subprocesses that handle them... I don't expect that you will see any difference here.
But worth a try anyway.

---

Finally, one thing I didn't think of asking you to try is changing the sink plugin (defaults to pulsesink if pulseaudio is installed):

XPRA_SOUND_SINK=alsasink xpra attach ...

You can also try: pulsesink, osssink, oss4sink, jackaudiosink, autoaudiosink.
Who knows, maybe one of those will work better. (many probably won't work at all)
See ​alsasink and ​pulsesink - there are quite a few options related to clock and synchronization.
Or maybe we're meant to use a ​clocksync element? (not available on my current version of gstreamer it seems)

It's really not clear to me what each of these options do, but I guess you could experiment by:

• adding a clocksync element to the playback pipeline - try applying r27818 and adding XPRA_CLOCK_SYNC=1
• modifying sink_str to tune the options for the sink you're using (usually pulsesink)

There's also the XPRA_SOUND_SRC environment variable, but I don't think that any of the other sources actually work.

---

PS: r27821 also adds more details on the source and sink elements (where we get audio from the OS / hand audio over to the OS), including lots of attributes that may or may not be relevant.
Server side, these can be seen with `xpra info :20 | grep "speaker.src".
Client side, you need r27822. And then you can use xpra info to query the client (#2743):

xpra info /run/user/1000/xpra/clients/$HOSTNAME-$CLIENT_PID  | grep sink

---

There are beta builds with these changes here: https://xpra.org/beta/
Let me know how you get on!

[Francesco Potortì]

I tried all the sinks. For the few which were working, I observed no change. Yes, I use pulseaudio. Somehow I think the problem is there but I have next to no idea how pulseaudio and gstreamer or sinks work. Moreover, I can check these things only when I have some free time, which of lately has not been frequent.

I'll try the patched versions ox Xpra.

The delay is easy to observe and reproduce, only it takes time. I observe a delay which increases linearly with time, by 1s every 15m, so if I can get the logs on disk it should be easy to see if the delay is there. Back when I have made some tests.

[Francesco Potortì]

output from the client

[Francesco Potortì]

I installed the beta version xpra_4.1-20201201r28072-1_amd64

I run xpra like

    XPRA_SUBPROCESS_FLUSH=1 XPRA_SAVE_AUDIO=server xpra start $remote \
			 --speaker=on --speaker-codec=mp3 --env=XPRA_CUTTER_THRESHOLD=0 \
			 --border=\#CCCC00 --start=editor
    XPRA_SUBPROCESS_FLUSH=1 XPRA_SAVE_AUDIO=client xpra attach $remote \
			 --speaker=on --speaker-codec=mp3 --env=XPRA_CUTTER_THRESHOLD=0

On the server, I got:

$ xpra info | grep speaker.src
client.sound.speaker.src.actual-buffer-time=200000
client.sound.speaker.src.actual-latency-time=10000
client.sound.speaker.src.buffer-time=200000
client.sound.speaker.src.latency-time=10000
client.sound.speaker.src.provide-clock=True

On the client I got the outout in the attached file info-client.

I see that the server1.mp3 file, but no client1.mp3 file.

The sound comes out distorted, and after the first beep it does not sound at all any more.

[Antoine Martin]

With XPRA_SAVE_AUDIO=client and --speaker-codec=mp3, your client output should show:

2020-12-07 22:02:51,181 audio playback using default pulseaudio device
2020-12-07 22:02:51,190 audio playback saving mp3 stream to client1.mp3
2020-12-07 22:02:51,695 audio playback using 'mp3' audio codec

The resulting file can be played with any decent media player.
As of r28093 (new beta builds have been posted), -d sound should be showing a message like this one when the audio output subprocess starts:

audio playback init_file(mp3) generation=1, SAVE_AUDIO=client

Perhaps it will help you figure out which setting is incorrect / unset?

[migration script]

this ticket has been moved to: ​https://github.com/Xpra-org/xpra/issues/2861