xpra icon
Bug tracker and wiki

Opened 6 weeks ago

Last modified 11 days ago

#2517 new defect

Cannot enable av-sync option on server side

Reported by: yvk1 Owned by: yvk1
Priority: major Milestone: 4.0
Component: server Version: 3.0.x
Keywords: Cc:

Description (last modified by Antoine Martin)

I installed and started xpra with the following steps, but the av-sync option of xpra server cannot be enabled on my machine.
What is missing or wrong?

  1. Environment
    Host: Ubuntu Server 16.04 in windows10 VirtualBox
    Client: Windows10 PC in the same LAN
    Both xpra versions: v3.0.3-r24690
  2. I installed Ubuntu server 16.04 on virtualbox and installed PulseAudio and Firefox.
  3. The user was added to the audio group referring to The Perfect Setup of PulseAudio.
  4. After that, I installed Xpra v3.0.3-r24690 with reference to winswitch download page.
  5. The following command was executed on the Ubuntu machine. xpra start: 100 --start = "firefox" --bind-tcp = 0.0.0.0:10000
  6. Executed xpra attach on the client side windows10 machine.
  7. When I played a video on a youtube, I heard sound, but only the sound will be delayed.


When xpra start and xpra attach was executed with the --debug = av-sync option, the following messages were displayed.
Server:

2019-12-17 11:52:44,125 av-sync set to 150ms (from client queue latency=150, encoder latency=0, delta=0)
2019-12-17 11:52:44,125 av-sync: server=True, client=True, total=150

Client:

2019-12-17 11:52:44,765 av-sync: server = False, client = True

Attachments (9)

100.log (86.8 KB) - added by yvk1 5 weeks ago.
client_log_python2.zip (52.9 KB) - added by yvk1 5 weeks ago.
client_log_python3.zip (49.6 KB) - added by yvk1 5 weeks ago.
logs.zip (104.7 KB) - added by yvk1 5 weeks ago.
screenshot.png (270.8 KB) - added by yvk1 5 weeks ago.
server_logs.zip (3.9 MB) - added by yvk1 3 weeks ago.
client_logs.zip (3.0 MB) - added by yvk1 3 weeks ago.
logs.2.zip (283.1 KB) - added by yvk1 2 weeks ago.
fsync.patch (633 bytes) - added by Antoine Martin 2 weeks ago.
force fsync after each write

Change History (33)

comment:1 Changed 6 weeks ago by Antoine Martin

Description: modified (diff)
Owner: changed from Antoine Martin to yvk1

Sorry about that, it broke again.
This server-side bug is fixed in r24730, backported to v3.0.x in r24731.

To get going, you can:

  • apply the r24731 patch to your installation
  • use the beta repository to install 3.0.4-RC1 (fresh Ubuntu Xenial builds uploaded just now)
  • temporarily apply this hack patch to your client instead (patch C:\Program Files\Xpra\lib\xpra\client\mixins\audio.py):
    --- xpra/client/mixins/audio.py
    +++ xpra/client/mixins/audio.py
    @@ -170,7 +170,7 @@
     
         def parse_server_capabilities(self):
             c = self.server_capabilities
    -        self.server_av_sync = c.boolget("av-sync.enabled")
    +        self.server_av_sync = True
             avsynclog("av-sync: server=%s, client=%s", self.server_av_sync, self.av_sync)
             self.server_pulseaudio_id = c.strget("sound.pulseaudio.id")
             self.server_pulseaudio_server = c.strget("sound.pulseaudio.server")
    
  • or wait for the 3.0.4 release.

Let me know if that works for you.

Note that this is only enabled for video content, so the video area of youtube should now be in sync (if it gets detected correctly), whilst the rest of the page won't be in sync (so you can interact with it, without unnecessary delay).

comment:2 in reply to:  1 Changed 6 weeks ago by yvk1

Replying to Antoine Martin:
Thank you for your quick response.

It seems that the av-sync option was enabled when applied to xpra with the r24731 patch installed.
But the sound doesn't seem to sync ...
When starting xpra with --debug = av-sync option and playing video, the following log is output

Is there any library or configuration omission on my machine?

2019-12-18 11:30:35,218 created tcp socket '0.0.0.0:10000'[0m
2019-12-18 11:30:35,219 cannot access python uinput module:[0m
2019-12-18 11:30:35,219  No module named uinput[0m
2019-12-18 11:30:35,626 created unix domain socket '/run/user/1000/xpra/ubuntu-100'[0m
2019-12-18 11:30:35,627 created unix domain socket '/run/xpra/ubuntu-100'[0m
2019-12-18 11:30:35,674 pointer device emulation using XTest[0m
2019-12-18 11:30:35,684 serving html content from '/usr/share/xpra/www'[0m
[33m2019-12-18 11:30:35,726 Warning: skipped OpenGL probing,[0m
[33m2019-12-18 11:30:35,726  found 1 blacklisted kernel module:[0m
[33m2019-12-18 11:30:35,726  vboxguest[0m
2019-12-18 11:30:35,761 D-Bus notification forwarding is available[0m
2019-12-18 11:30:35,781 pulseaudio server started with pid 3300[0m
2019-12-18 11:30:35,781  private server socket path:[0m
2019-12-18 11:30:35,781  '/run/user/1000/xpra/pulse-100/pulse/native'[0m
2019-12-18 11:30:36,179 GStreamer version 1.8.3 for Python 2.7.12 64-bit[0m
2019-12-18 11:30:36,258 xpra is ready.[0m
2019-12-18 11:30:36,258 xpra GTK2 X11 version 3.0.3-r24690 64-bit[0m
[33m2019-12-18 11:30:36,262 Warning: webcam forwarding is disabled[0m
[33m2019-12-18 11:30:36,262  the virtual video directory '/sys/devices/virtual/video4linux' was not found[0m
[33m2019-12-18 11:30:36,262  make sure that the 'v4l2loopback' kernel module is installed and loaded[0m
2019-12-18 11:30:36,262 found 0 virtual video devices for webcam forwarding[0m
2019-12-18 11:30:36,275 printer forwarding enabled using postscript and pdf[0m
2019-12-18 11:30:36,307 watching for applications menu changes in:[0m
2019-12-18 11:30:36,307  '/usr/share/applications'[0m
2019-12-18 11:30:36,513  uid=1000 (yvk1), gid=1000 (yvk1)[0m
2019-12-18 11:30:36,513  running with pid 3277 on Linux Ubuntu 16.04 xenial[0m
2019-12-18 11:30:36,513  connected to X11 display :100 with 24 bit colors[0m
2019-12-18 11:30:37,453 7.8GB of system memory[0m
[ERROR audio_thread_priority::rt_linux] setrlimit64: 1
[33m2019-12-18 11:30:38,931 Warning: remote clipboard request timed out[0m
[33m2019-12-18 11:30:38,931  request id 0, selection=CLIPBOARD, target=TARGETS[0m
2019-12-18 11:30:39,075 New unix-domain connection received[0m
2019-12-18 11:30:39,075  on '/run/user/1000/xpra/ubuntu-100'[0m
2019-12-18 11:30:39,152 processed structured info request from unix-domain socket:/run/user/1000/xpra/ubuntu-100 in 62ms[0m
2019-12-18 11:30:40,069 New unix-domain connection received[0m
2019-12-18 11:30:40,069  on '/run/user/1000/xpra/ubuntu-100'[0m
2019-12-18 11:30:40,071 New unix-domain connection received[0m
2019-12-18 11:30:40,071  on '/run/xpra/ubuntu-100'[0m
2019-12-18 11:30:45,018 New tcp connection received[0m
2019-12-18 11:30:45,018  from '10.3.239.52:62630'[0m
2019-12-18 11:30:45,019  on '0.0.0.0:10000'[0m
2019-12-18 11:30:45,023 Handshake complete; enabling connection[0m
[36m2019-12-18 11:30:45,102 set_screen_sizes([('4\\WinSta0\\Default', 1366, 768, 361, 203, (('(\xe6\xa8\x99\xe6\xba\x96\xe3\x83\xa2\xe3\x83\x8b\xe3\x82\xbf\xe3\x83\xbc\xe3\x81\xae\xe7\xa8\xae\xe9\xa1\x9e) \xe6\xb1\x8e\xe7\x94\xa8 PnP \xe3\x83\xa2\xe3\x83\x8b\xe3\x82\xbf\xe3\x83\xbc', 0, 0, 1366, 768, 276, 155, 0, 0, 1366, 728),), 0, 0, 1366, 728)])[0m
[36m2019-12-18 11:30:45,102 client validated screen sizes: [('4\\WinSta0\\Default', 1366, 768, 361, 203, (('(\xe6\xa8\x99\xe6\xba\x96\xe3\x83\xa2\xe3\x83\x8b\xe3\x82\xbf\xe3\x83\xbc\xe3\x81\xae\xe7\xa8\xae\xe9\xa1\x9e) \xe6\xb1\x8e\xe7\x94\xa8 PnP \xe3\x83\xa2\xe3\x83\x8b\xe3\x82\xbf\xe3\x83\xbc', 0, 0, 1366, 768, 276, 155, 0, 0, 1366, 728),), 0, 0, 1366, 728)][0m
2019-12-18 11:30:45,111  automatic picture encoding enabled, also available:[0m
2019-12-18 11:30:45,111   h264, vp9, vp8, png, png/P, png/L, rgb24, rgb32, jpeg[0m
[36m2019-12-18 11:30:45,111 av-sync set to 150ms (from client queue latency=150, encoder latency=0, delta=0)[0m
[36m2019-12-18 11:30:45,111 av-sync: server=True, client=True, total=150[0m
[36m2019-12-18 11:30:45,111 av-sync: server=True, client=True, enabled=True ,total=150[0m
2019-12-18 11:30:45,112 Python/GTK3 Microsoft Windows 10 aero client version 3.0.3-r24690 64-bit[0m
2019-12-18 11:30:45,112  connected from 'NTLP-19008' as 'yogata'[0m
2019-12-18 11:30:45,200 setting key repeat rate from client: 500ms delay / 33ms interval[0m
2019-12-18 11:30:45,202 setting keyboard layout to 'jp'[0m
2019-12-18 11:30:45,256  client root window size is 1366x768 with 1 display:[0m
2019-12-18 11:30:45,256   Default (361x203 mm - DPI: 96x96) workarea: 1366x728[0m
2019-12-18 11:30:45,256     (標準モニターの種類) 汎用 PnP モニター (276x155 mm - DPI: 125x125)[0m
2019-12-18 11:30:45,779 server virtual display now set to 1368x768 (best match for 1366x768)[0m
2019-12-18 11:30:45,807 DPI set to 96 x 96[0m
[36m2019-12-18 11:30:45,807 updated_desktop_size(1368, 768, 5760, 2560) randr_notify=True, desktop_size=(1366, 768)[0m
[36m2019-12-18 11:30:45,807 updated_desktop_size(1368, 768, 5760, 2560) randr_notify=True, desktop_size=(1366, 768)[0m
2019-12-18 11:30:45,833 client   1 @03.558 Xpra GTK2 X11 server version 3.0.3-r24690 64-bit[0m
2019-12-18 11:30:45,834 client   1 @03.559  running on Linux Ubuntu 16.04 xenial[0m
2019-12-18 11:30:45,843 client   1 @03.566 Attached to tcp://10.3.239.90:10000/[0m
2019-12-18 11:30:45,843 client   1 @03.567  (press Control-C to detach)[0m
[36m2019-12-18 11:30:46,016 cancel_encode_from_queue() timer=None for wid=1[0m
[36m2019-12-18 11:30:46,118 encode_from_queue: 2 items for wid=1[0m
[36m2019-12-18 11:30:46,119 encode_from_queue: first due in 47ms, due list=[47, 112] (av-sync delay=150, actual=0, for wid=1)[0m
[36m2019-12-18 11:30:46,119 cancel_encode_from_queue() timer=None for wid=1[0m
[36m2019-12-18 11:30:46,167 encode_from_queue: 2 items for wid=1[0m
[36m2019-12-18 11:30:46,167 encode_from_queue: processing item 1/2 (overdue by 0ms)[0m
[36m2019-12-18 11:30:46,199 encode_from_queue: first due in 64ms, due list=[64] (av-sync delay=150, actual=0, for wid=1)[0m
[36m2019-12-18 11:30:46,199 cancel_encode_from_queue() timer=None for wid=1[0m
[36m2019-12-18 11:30:46,215 schedule_av_sync_update(0) wid=1, delay=150, target=0, timer=None[0m
[36m2019-12-18 11:30:46,215 update_av_sync_delay() wid=1, current=150, target=0, adding -20 (capped to +-20 from -150)[0m
[36m2019-12-18 11:30:46,215 schedule_av_sync_update(500) wid=1, delay=130, target=0, timer=None[0m
[36m2019-12-18 11:30:46,265 encode_from_queue: 3 items for wid=1[0m
[36m2019-12-18 11:30:46,265 update_av_sync_delay() wid=1, current=130, target=0, adding -20 (capped to +-20 from -130)[0m
[36m2019-12-18 11:30:46,265 schedule_av_sync_update(500) wid=1, delay=110, target=0, timer=None[0m
[36m2019-12-18 11:30:46,265 encode_from_queue: processing item 1/3 (overdue by 73ms)[0m
[36m2019-12-18 11:30:46,267 encode_from_queue: first due in 54ms, due list=[54, 93] (av-sync delay=110, actual=0, for wid=1)[0m
[36m2019-12-18 11:30:46,267 cancel_encode_from_queue() timer=None for wid=1[0m
[36m2019-12-18 11:30:46,324 encode_from_queue: 2 items for wid=1[0m
[36m2019-12-18 11:30:46,324 update_av_sync_delay() wid=1, current=110, target=0, adding -20 (capped to +-20 from -110)[0m
[36m2019-12-18 11:30:46,324 schedule_av_sync_update(500) wid=1, delay=90, target=0, timer=None[0m
[36m2019-12-18 11:30:46,325 encode_from_queue: processing item 1/2 (overdue by 25ms)[0m
[36m2019-12-18 11:30:46,337 encode_from_queue: first due in 13ms, due list=[13] (av-sync delay=90, actual=0, for wid=1)[0m
[36m2019-12-18 11:30:46,337 cancel_encode_from_queue() timer=None for wid=1[0m
[36m2019-12-18 11:30:46,352 encode_from_queue: 1 items for wid=1[0m
[36m2019-12-18 11:30:46,352 update_av_sync_delay() wid=1, current=90, target=0, adding -20 (capped to +-20 from -90)[0m
[36m2019-12-18 11:30:46,353 schedule_av_sync_update(500) wid=1, delay=70, target=0, timer=None[0m
[36m2019-12-18 11:30:46,353 encode_from_queue: processing item 1/1 (overdue by 34ms)[0m
[36m2019-12-18 11:30:46,353 encode_from_queue: nothing due[0m
[36m2019-12-18 11:30:46,490 cancel_encode_from_queue() timer=None for wid=1[0m
[36m2019-12-18 11:30:46,512 encode_from_queue: 1 items for wid=1[0m
[36m2019-12-18 11:30:46,512 update_av_sync_delay() wid=1, current=70, target=0, adding -20 (capped to +-20 from -70)[0m
[36m2019-12-18 11:30:46,512 schedule_av_sync_update(500) wid=1, delay=50, target=0, timer=None[0m
[36m2019-12-18 11:30:46,512 encode_from_queue: first due in 28ms, due list=[28] (av-sync delay=50, actual=0, for wid=1)[0m
[36m2019-12-18 11:30:46,512 cancel_encode_from_queue() timer=None for wid=1[0m
2019-12-18 11:30:46,554 using pulseaudio device:[0m
2019-12-18 11:30:46,554  'Monitor of Xpra Speaker'[0m
[36m2019-12-18 11:30:46,582 encode_from_queue: 1 items for wid=1[0m
[36m2019-12-18 11:30:46,582 update_av_sync_delay() wid=1, current=50, target=0, adding -20 (capped to +-20 from -50)[0m
[36m2019-12-18 11:30:46,583 schedule_av_sync_update(500) wid=1, delay=30, target=0, timer=None[0m
[36m2019-12-18 11:30:46,583 encode_from_queue: processing item 1/1 (overdue by 62ms)[0m
[36m2019-12-18 11:30:46,602 encode_from_queue: nothing due[0m
[36m2019-12-18 11:30:46,716 update_av_sync_delay() wid=1, current=30, target=0, adding -20 (capped to +-20 from -30)[0m
[36m2019-12-18 11:30:46,717 schedule_av_sync_update(500) wid=1, delay=10, target=0, timer=None[0m
[36m2019-12-18 11:30:46,766 update_av_sync_delay() wid=1, current=10, target=0, adding -10 (capped to +-20 from -10)[0m
[33m2019-12-18 11:30:46,812 Warning: not adding duplicate printer '\\alice\RICOH MP C5504 JPN RPCS -東京8F右側'[0m
[33m2019-12-18 11:30:46,815 Warning: not adding duplicate printer '\\alice\RICOH MP C5504 JPN RPCS -東京8F左側'[0m
[33m2019-12-18 11:30:46,817 Warning: not adding duplicate printer 'Microsoft Print to PDF'[0m
[33m2019-12-18 11:30:46,818 Warning: not adding duplicate printer 'RICOH MP C4504 JPN'[0m
[33m2019-12-18 11:30:46,819 Warning: not adding duplicate printer 'OneNote'[0m
2019-12-18 11:30:47,568 sound source using 'opus' audio codec
[36m2019-12-18 11:30:52,233 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 1366x704), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:30:52,233 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:30:53,237 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 1352x630), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:30:53,237 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:30:54,235 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 294x696), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:30:54,235 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:30:55,240 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:30:56,241 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 1366x630), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:30:56,241 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:30:58,245 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 294x696), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:30:58,245 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:30:59,241 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 1030x346), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:30:59,241 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:00,242 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 424x238), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:00,242 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:01,242 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 278x188), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:01,242 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:02,245 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 424x238), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:02,245 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:03,249 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 424x238), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:03,249 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:04,250 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 424x238), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:04,250 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:05,252 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 424x238), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:05,252 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:06,257 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 424x238), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:06,257 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:07,253 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 424x238), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:07,253 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:08,253 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 424x290), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:08,253 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:09,256 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 1366x632), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:09,257 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:10,258 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 1366x632), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:10,258 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:11,254 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 1366x632), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:11,254 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:12,256 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 1366x632), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:12,256 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:13,257 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 1366x632), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:13,257 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:14,256 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 1328x632), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:14,257 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:15,257 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 852x480), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:15,258 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:16,259 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 852x480), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:16,259 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:18,267 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 852x480), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:18,267 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:20,270 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 852x480), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:20,270 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:21,268 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 852x480), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:21,268 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:22,273 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 852x480), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:22,273 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:23,270 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 852x480), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:23,272 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:24,269 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 852x480), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:24,269 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:25,274 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 852x480), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:25,274 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:26,277 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 852x480), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:26,290 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m
[36m2019-12-18 11:31:27,272 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 852x480), delayed frames=0, frame delay=0[0m
[36m2019-12-18 11:31:27,273 schedule_av_sync_update(0) wid=1, delay=0, target=0, timer=None[0m

comment:3 Changed 6 weeks ago by Antoine Martin

Found lots of little bugs in av-sync, mostly server-side:

  • r24744 the target delay was not getting updated
  • r24745 python3 compatibility (minor)
  • r24746 need a delay to ensure the audio source info dictionary is populated
  • r24752 av-sync delay was not set for new windows
  • r24760 python3 compatibility - could cause drift if the client audio buffer grows (this one is client side)

and also made some improvements:

  • r24756 improve accuracy of video encoder frame delay calculations
  • r24761 make finer delta adjustements and make the threshold configurable
  • r24762 tune default audio latency guess (increase slightly - especially for 'latency' mode: #1370)

Some of these bugs were fairly minor, but combined they caused the av-sync delay to stick to zero..

There are 3.0.4-RC builds in the beta area with these fixes (not the improvements as those are in the development branch only): https://xpra.org/beta.

Those work well enough for me.
I have tested using youtube: audio video sync test with Firefox.

@yvk1: please close if this works for you.

comment:4 Changed 6 weeks ago by yvk1

Thank you for the detailed explanation.

In order to try out 3.0.4-RC builds, I added the Xpra beta repository to the apt list by following the steps below,
but it seems that it can't be loaded normally ...

sudo su -
curl  http://www.xpra.org/gpg.asc | apt-key add -  
echo deb https://www.xpra.org/beta/ xenial main" > /etc/apt/sources.list.d/xpra.list
echo deb https://www.xpra.org/ xenial main" > /etc/apt/sources.list.d/xpra.list
apt-get update
Ign:1 http://dl.google.com/linux/chrome/deb stable InRelease
Hit:2 http://dl.google.com/linux/chrome/deb stable Release
Get:4 http://security.ubuntu.com/ubuntu xenial-security InRelease [109 kB]
Hit:5 http://ppa.launchpad.net/deadsnakes/ppa/ubuntu xenial InRelease
Hit:6 http://us.archive.ubuntu.com/ubuntu xenial InRelease
Get:8 http://us.archive.ubuntu.com/ubuntu xenial-updates InRelease [109 kB]
Hit:9 http://winswitch.org xenial InRelease
Get:10 https://www.xpra.org xenial InRelease [4086 B]
Get:11 http://us.archive.ubuntu.com/ubuntu xenial-backports InRelease [107 kB]
Get:12 https://www.xpra.org/beta xenial InRelease [4197 B]
Get:7 http://winswitch.org/beta xenial InRelease [4197 B]
Get:13 https://www.xpra.org xenial/main amd64 Packages [18.4 kB]
Get:14 https://www.xpra.org xenial/main i386 Packages [18.4 kB]
Reading package lists... Done
E: Unable to parse package file  (1)
E: Unable to parse package file  (1)

comment:5 Changed 6 weeks ago by Antoine Martin

E: Unable to parse package file (1)

Sorry about that, and thanks for pointing that out.
The Debian repository tools aren't python3 clean, so I've switched back to python2 for now.

BTW, you have duplicate repositories in there: xpra.org is the same as winswitch.org.
So you can remove one of them.

comment:6 Changed 6 weeks ago by yvk1

Thank you for the successful update.

Server: v3.0.3-r24731 -> v3.0.4-r24762
Client: v3.0.3-r24690 -> v3.0.4-r24762
The client used Xpra-Python3-x86_64_Setup_3.0.4-r24762

I tried it now and it seems that the sound is still out of alignment ...
Although it is synchronized immediately after server startup, the sound delay seems to increase in proportion to the startup time.

The following is a part of the server log.

^[[36m2019-12-19 19:35:47,930 encode_from_queue: processing item 1/6 (overdue by 2ms)^[[0m
^[[36m2019-12-19 19:35:47,931 encode_from_queue: first due in 34ms, due list=[34, 85, 113, 157, 204] (av-sync delay=225, actual=0, for wid=1)^[[0m
^[[36m2019-12-19 19:35:47,932 cancel_encode_from_queue() timer=None for wid=1^[[0m
^[[36m2019-12-19 19:35:47,967 encode_from_queue: 6 items for wid=1^[[0m
^[[36m2019-12-19 19:35:47,967 encode_from_queue: processing item 1/6 (overdue by 3ms)^[[0m
^[[36m2019-12-19 19:35:47,969 encode_from_queue: first due in 48ms, due list=[48, 75, 119, 167, 213] (av-sync delay=225, actual=0, for wid=1)^[[0m
^[[36m2019-12-19 19:35:47,969 cancel_encode_from_queue() timer=None for wid=1^[[0m
^[[36m2019-12-19 19:35:47,984 update_av_sync_frame_delay() video encoder=x264_encoder(BGRX - 680x622), delayed frames=0, frame delay=0^[[0m
^[[36m2019-12-19 19:35:47,984 schedule_av_sync_update(0) wid=1, delay=225, target=225, timer=None^[[0m
^[[36m2019-12-19 19:35:48,018 encode_from_queue: 6 items for wid=1^[[0m
^[[36m2019-12-19 19:35:48,018 encode_from_queue: processing item 1/6 (overdue by 2ms)^[[0m
^[[36m2019-12-19 19:35:48,022 cancel_encode_from_queue() timer=None for wid=1^[[0m
^[[36m2019-12-19 19:35:48,023 encode_from_queue: first due in 24ms, due list=[24, 68, 116, 162, 194, 228] (av-sync delay=225, actual=0, for wid=1)^[[0m
^[[36m2019-12-19 19:35:48,023 cancel_encode_from_queue() timer=67762 for wid=1^[[0m
^[[36m2019-12-19 19:35:48,049 encode_from_queue: 6 items for wid=1^[[0m
^[[36m2019-12-19 19:35:48,049 encode_from_queue: processing item 1/6 (overdue by 5ms)^[[0m
^[[36m2019-12-19 19:35:48,053 encode_from_queue: first due in 38ms, due list=[38, 85, 132, 164, 198] (av-sync delay=225, actual=0, for wid=1)^[[0m
^[[36m2019-12-19 19:35:48,053 cancel_encode_from_queue() timer=None for wid=1^[[0m
^[[36m2019-12-19 19:35:48,092 encode_from_queue: 6 items for wid=1^[[0m
^[[36m2019-12-19 19:35:48,092 encode_from_queue: processing item 1/6 (overdue by 5ms)^[[0m
^[[36m2019-12-19 19:35:48,094 encode_from_queue: first due in 42ms, due list=[42, 88, 120, 155, 201] (av-sync delay=225, actual=0, for wid=1)^[[0m
^[[36m2019-12-19 19:35:48,095 cancel_encode_from_queue() timer=None for wid=1^[[0m
^[[36m2019-12-19 19:35:48,138 encode_from_queue: 6 items for wid=1^[[0m
^[[36m2019-12-19 19:35:48,138 encode_from_queue: processing item 1/6 (overdue by 3ms)^[[0m
^[[36m2019-12-19 19:35:48,140 encode_from_queue: first due in 42ms, due list=[42, 74, 109, 155, 206] (av-sync delay=225, actual=0, for wid=1)^[[0m
^[[36m2019-12-19 19:35:48,141 cancel_encode_from_queue() timer=None for wid=1^[[0m
^[[36m2019-12-19 19:35:48,186 encode_from_queue: 6 items for wid=1^[[0m
^[[36m2019-12-19 19:35:48,186 encode_from_queue: processing item 1/6 (overdue by 5ms)^[[0m
^[[36m2019-12-19 19:35:48,188 encode_from_queue: first due in 26ms, due list=[26, 61, 107, 158, 190] (av-sync delay=225, actual=0, for wid=1)^[[0m
^[[36m2019-12-19 19:35:48,188 cancel_encode_from_queue() timer=None for wid=1^[[0m
^[[36m2019-12-19 19:35:48,215 encode_from_queue: 6 items for wid=1^[[0m
^[[36m2019-12-19 19:35:48,215 encode_from_queue: processing item 1/6 (overdue by 2ms)^[[0m
^[[36m2019-12-19 19:35:48,227 encode_from_queue: first due in 32ms, due list=[32, 78, 129, 161, 213] (av-sync delay=225, actual=0, for wid=1)^[[0m
^[[36m2019-12-19 19:35:48,227 cancel_encode_from_queue() timer=None for wid=1^[[0m
^[[36m2019-12-19 19:35:48,260 encode_from_queue: 6 items for wid=1^[[0m
^[[36m2019-12-19 19:35:48,260 encode_from_queue: processing item 1/6 (overdue by 12ms)^[[0m
^[[36m2019-12-19 19:35:48,273 encode_from_queue: first due in 33ms, due list=[33, 84, 116, 168, 208] (av-sync delay=225, actual=0, for wid=1)^[[0m
^[[36m2019-12-19 19:35:48,273 cancel_encode_from_queue() timer=None for wid=1^[[0m
^[[36m2019-12-19 19:35:48,308 encode_from_queue: 5 items for wid=1^[[0m
^[[36m2019-12-19 19:35:48,308 encode_from_queue: processing item 1/5 (overdue by 14ms)^[[0m
^[[36m2019-12-19 19:35:48,318 encode_from_queue: first due in 35ms, due list=[35, 68, 120, 160] (av-sync delay=225, actual=0, for wid=1)^[[0m
^[[36m2019-12-19 19:35:48,318 cancel_encode_from_queue() timer=None for wid=1^[[0m
^[[36m2019-12-19 19:35:48,354 encode_from_queue: 4 items for wid=1^[[0m
^[[36m2019-12-19 19:35:48,354 encode_from_queue: processing item 1/4 (overdue by 9ms)^[[0m
^[[36m2019-12-19 19:35:48,364 encode_from_queue: first due in 22ms, due list=[22, 74, 114] (av-sync delay=225, actual=0, for wid=1)^[[0m
^[[36m2019-12-19 19:35:48,365 cancel_encode_from_queue() timer=None for wid=1^[[0m
^[[36m2019-12-19 19:35:48,387 encode_from_queue: 3 items for wid=1^[[0m
^[[36m2019-12-19 19:35:48,387 encode_from_queue: processing item 1/3 (overdue by 10ms)^[[0m
^[[36m2019-12-19 19:35:48,398 encode_from_queue: first due in 41ms, due list=[41, 81] (av-sync delay=225, actual=0, for wid=1)^[[0m
^[[36m2019-12-19 19:35:48,398 cancel_encode_from_queue() timer=None for wid=1^[[0m
^[[36m2019-12-19 19:35:48,441 encode_from_queue: 3 items for wid=1^[[0m
^[[36m2019-12-19 19:35:48,441 encode_from_queue: processing item 1/3 (overdue by 12ms)^[[0m
^[[36m2019-12-19 19:35:48,452 encode_from_queue: first due in 27ms, due list=[27, 203] (av-sync delay=225, actual=0, for wid=1)^[[0m
^[[36m2019-12-19 19:35:48,452 cancel_encode_from_queue() timer=None for wid=1^[[0m
^[[36m2019-12-19 19:35:48,479 encode_from_queue: 2 items for wid=1^[[0m
^[[36m2019-12-19 19:35:48,480 encode_from_queue: processing item 1/2 (overdue by 10ms)^[[0m
^[[36m2019-12-19 19:35:48,489 encode_from_queue: first due in 165ms, due list=[165] (av-sync delay=225, actual=0, for wid=1)^[[0m
^[[36m2019-12-19 19:35:48,489 cancel_encode_from_queue() timer=None for wid=1^[[0m
^[[36m2019-12-19 19:35:48,656 encode_from_queue: 2 items for wid=1^[[0m
^[[36m2019-12-19 19:35:48,657 encode_from_queue: processing item 1/2 (overdue by 11ms)^[[0m
^[[36m2019-12-19 19:35:48,666 encode_from_queue: first due in 154ms, due list=[154] (av-sync delay=225, actual=0, for wid=1)^[[0m
^[[36m2019-12-19 19:35:48,666 cancel_encode_from_queue() timer=None for wid=1^[[0m
^[[36m2019-12-19 19:35:48,822 encode_from_queue: 2 items for wid=1^[[0m
^[[36m2019-12-19 19:35:48,822 encode_from_queue: processing item 1/2 (overdue by 11ms)^[[0m
^[[36m2019-12-19 19:35:48,833 encode_from_queue: first due in 155ms, due list=[155] (av-sync delay=225, actual=0, for wid=1)^[[0m

Looking at the Codecs tab of my client's Session info, the server's Packet Encoders and Packet Compressors items are blank.
Is this also related to this phenomenon?

comment:7 Changed 6 weeks ago by Antoine Martin

Although it is synchronized immediately after server startup, the sound delay seems to increase in proportion to the startup time.

That's because I had missed a part: r24778 fixes that.

FYI: what's happening is that some systems are known to gradually drift, either causing the client audio buffer to drain (which causes the audio to stop briefly as we fill up the buffer again) or overflow (which triggers some stuttering as we drop some buffers).
You can see this on the "Graphs" tab of the session info dialog, found in the system tray menu.
Normally, the size of the client audio buffer is sent to the server, which then adjusts the video frame delay by the same amount.

You can find updated 3.0.4-r24778 builds in the beta area: https://xpra.org/beta/windows.
Alternatively, you can use a 4.0 beta build, or a python2 build as those were not affected.

Bear in mind that perfect synchronization is extremely hard to do in real time.

Looking at the Codecs tab of my client's Session info, the server's Packet Encoders and Packet Compressors items are blank.

That's fixed in r24773.

Is this also related to this phenomenon?

No, but thanks for reporting it.

comment:8 Changed 5 weeks ago by yvk1

Sorry for my late reply.
Thanks for commenting on the delay.
I understand that a little delay is inevitable.

I tried 3.0.4-r24778 which was released the other day.
Server: 3.0.4-r24762-> 3.0.4-r24778
Client: 3.0.4-r24762-> 3.0.4-r24778
The client used Xpra-x86_64_Setup.exe.

As a result, in my environment, it seems that the sound is delayed by one second about every 20 seconds.
So, to confirm Sound/Debugging and execute gst-launch, there was a delay of about 1 second at the time of execution.

Next, the xpra server was started with the following command.
xpra start: 100 --start = "firefox" --bind-tcp = 0.0.0.0:10000 --debug = gstreamer
The log looks like the following 100.log.

Also, when I switched the client to python2 version using Xpra-Python2-x86_64_Setup_3.0.4-r24778, the speaker became unavailable.
In the case of 4.0-r24778, it behaved the same as 3.0.4-r24778.

From the results of running gst-launch, etc., my settings seem to be bad. Is there any solution to reduce the delay based on this information?

Changed 5 weeks ago by yvk1

Attachment: 100.log added

comment:9 Changed 5 weeks ago by Antoine Martin

Thanks for the log, in it I found that the av-sync backport was incomplete and would not work with python2 servers, that's fixed in r24783. You can apply it by hand to your installation, as 3.0.5 is unlikely to be released before mid-January at the earliest. Or you could also use a python3 server.

Most of your log output is taken up by "cutter" messages (#1617). This silence detection may affect latency.
If you want, you can turn it off by starting your server with:

XPRA_CUTTER_THRESHOLD=0 xpra start ...

You may also want to switch to a different audio codec to see if that helps (ie: #1638, "mp3", "vorbis" are worth a try)

comment:10 Changed 5 weeks ago by yvk1

Thank you for your response and suggesting a solution.
The change of r24783 was applied to audio_mixin.py of python2 immediately.

After trying it, it seems that the sound is delayed as before the change was applied ...
The executed command is as follows.

XPRA_CUTTER_THRESHOLD=0 xpra start :100 --start="firefox" --bind-tcp=0.0.0.0:10000

Also, I don't know if the usage is correct, but I ran the following command and started the python3 version of the server,
but this was the same situation.

XPRA_CUTTER_THRESHOLD=0 python3 /usr/bin/xpra start :100 --start="firefox" --bind-tcp=0.0.0.0:10000

The logs of the client when executed with python2 version and python3 version are as follows.
Please let me know if you need any other logs to take.

Changed 5 weeks ago by yvk1

Attachment: client_log_python2.zip added

Changed 5 weeks ago by yvk1

Attachment: client_log_python3.zip added

comment:11 Changed 5 weeks ago by Antoine Martin

Also, I don't know if the usage is correct..
XPRA_CUTTER_THRESHOLD=0 python3 /usr/bin/xpra start :100 --start="firefox" --bind-tcp=0.0.0.0:10000

That's correct.

The logs of the client when executed with python2 version and python3 version are as follows.

Those are not logs, they're bug report tool snapshots.
The most useful log data you can capture is to run both the client and server with --debug=av-sync and attach the server log (which will automatically include the client debug output)

comment:12 Changed 5 weeks ago by yvk1

I'm sorry, I misunderstood

I got the log when the client's speaker codec was set to opus and mp3, and then the python2 version and python3 version xpra server logs.

Changed 5 weeks ago by yvk1

Attachment: logs.zip added

comment:13 Changed 5 weeks ago by Antoine Martin

Thanks for the logs.

First, the easy part: the client logs always show the same pattern, both with python2 and python3 servers, and both with "mp3" and "opus": the client buffer level initially goes up, reaches as high as ~360ms, it goes back down to zero and then it oscillates between 0 and ~140. (ie: server sound sync: sending updated queue.used=0 (was 130))
That's all normal.

During that time server side, update_av_sync_delay tries to prevent this oscillation and smooths the delay value.
The resulting server-side av-sync delay usually ends up being in the range 75 to 250ms. (ie: update_av_sync_delay() wid=1, current=135, target=75, adding -20 (capped to +-20 from -60))

Except in one case, where it goes much higher, ie:

python2_server/mp3/server.log:
2019-12-26 09:33:02,879 av-sync set to 664ms (from client queue latency=339, encoder latency=325, delta=0)

That's because the python2 server with mp3 doesn't detect the encoder pipeline latency (not sure why), and so it uses the default value, which is 325ms for mp3. (and seemingly too high?)


Server side there are strange events: sometimes completely out of the blue, we end up with many items in the encode queue:

2019-12-26 09:21:46,815 encode_from_queue: processing item 1/16 (overdue by 0ms)
2019-12-26 09:21:46,815 encode_from_queue: first due in 0ms, due list=[0, 56, 56, 57, 57, 57, 58, 58, 58, 58, 59, 59, 59, 60, 64] (av-sync delay=75, actual=0, for wid=1)
2019-12-26 09:21:46,817 cancel_encode_from_queue() timer=None for wid=1

This looks like a bug: we should never have so many frames so close together.
And this happens repeatedly:

2019-12-26 09:21:47,820 encode_from_queue: processing item 1/30 (overdue by 116ms)
2019-12-26 09:22:48,334 encode_from_queue: first due in 47ms, due list=[47, 50, 50, 50, 51, 51, 51, 51] (av-sync delay=75, actual=0, for wid=1)

In all cases, the frames due times are very close together.

Things get pretty bad in one case:

2019-12-26 09:22:54,314 encode_from_queue: first due in 0ms, due list=[-1600, -1402, -1334, -1102, -402, -301] (av-sync delay=75, actual=0, for wid=1)

That's 1.5 seconds overdue!?


@yvk1: what do you run in Firefox? Just a youtube video? Is it easy to reproduce with any video? Can you reproduce the problem with audio video sync test?

comment:14 Changed 5 weeks ago by yvk1

Thank you for the detailed explanation.
What I played to take this log was that audio video sync test ...
The other thing I played was the Audio Video Sync Test 60 FPS, which happened to play on YouTube autoplay.
And this sound delay happens with any video ...

As the delay gets worse, the following occurs:

  • Even if you stop playing a movie, the sound of that movie will still play.
  • When another video is played, the audio of the delayed part of the previously played video is played.

I am testing in an environment like the image below.

Changed 5 weeks ago by yvk1

Attachment: screenshot.png added

comment:15 Changed 5 weeks ago by Antoine Martin

Owner: changed from yvk1 to Antoine Martin
Status: newassigned

Even if you stop playing a movie, the sound of that movie will still play.

OK, so the client side audio buffer is growing out of control..
The client's audio system is probably not processing buffers fast enough because if the buffering was happening inside the gstreamer code, we would get notified and we would take countermeasures.
You would also be able to see it in the "Graphs" section of the "Session Info" dialog you can find in the system tray menu.
This is a problem we encounter a lot when using the html5 client: #1775 and ticket:2369#comment:3.
Is there anything unusual about this system? Is it a virtual machine perhaps? Or using an unusual audio setup? Unusual sound card?
That's going to be very difficult to fix unless I can reproduce the problem myself.
I'll try again when I am back in the office.

In the meantime, you can have a look at the code in sink.py and you can try to play with the settings in that file, in particular:

You can also run your client with either --debug=gstreamer, --debug=sound or even both.
The log output will be very verbose and difficult to understand...
It gets even worse if you set the environment variable GST_DEBUG=4 (or higher, as per gstreamer debugging tools)

comment:16 Changed 3 weeks ago by yvk1

Sorry for the late reply.

Describe in detail the environment I am trying.
The host PC has the following configuration.
I installed VirtualBox on this PC, set up a Ubuntu virtual machine, and started xpra server.

System model: MB-K690
CPU: Intel i7-8750H 2.20GHz
OS: Windows 10 Pro (version 1903)
Memory: 32GB
VirtualBox: version 6.1.0
Virtual machine memory: 8192MB

The client PC is not a virtual machine, but a machine with regular Windows 10 Pro.
The client PC has the following configuration.

System model: Latitude 7290
CPU: i3-8130U 2.20GHz
OS: Windows 10 Pro (version: 1809)
Memory: 8GB
Sound driver: Realtek Audio

I don't remember changing anything ...

Both PCs are in the same LAN.

The changes in sink.py were reflected in the code of both python2 and python3, and xpra start and xpra attach were executed under the following conditions.

  • run with --debug = gstreamer
  • run with --debug = sound
  • run with GST_DEBUG = 4
  • run with --debug = gstreamer, sound
  • run with --debug = gstreamer, sound GST_DEBUG = 4

I attach the result of each execution and the image of the graph of session info though I do not know whether it will help.
Sorry for the very large log ...

Changed 3 weeks ago by yvk1

Attachment: server_logs.zip added

Changed 3 weeks ago by yvk1

Attachment: client_logs.zip added

comment:17 Changed 3 weeks ago by Antoine Martin

Owner: changed from Antoine Martin to yvk1
Status: assignednew

Thanks for the very detailed logs.
I don't think we need to bother having both python2 and python3 logs since the problem occurs with both.


First thing I have noticed in your logs is that there does not seem to be any audio playing, as every single buffer emitted by the server is exactly 160 bytes (the size of an empty buffer with metadata):

$ grep emit_buffer debug-both/server.log | wc -l
10150
$ grep emit_buffer debug-both/server.log | grep -v "len=160" | wc -l
0

That should not be the case: #1617.


Next, the latency graphs screenshot match the client debug output: the client output buffer varies between 0 and ~300ms, which is fine.
What is odd is that your client debug output shows an ever increasing value for "underruns" (thousands!) with a relatively small number of "overruns".

Here's a status update we get from the client's audio subprocess:

info_update: {b'buffer_count': 9824, b'bytes': 1571840, \
    b'queue': {b'min': 0, b'max': 179, b'cur': 0, b'pct': 0, b'overruns': 19, b'underruns': 8703, b'state': b'underrun'}}

That's 90% underruns!

The underrun events happen when gstreamer is telling us we need to send audio buffers faster - we then pause and buffer more to try to prevent further underruns.
Your audio is constantly in an 'underrun' state, it briefly recovers every second or so, only to go back into 'underrun' immediately after.

At this point I strongly suspect that that the problem lies within the OS / driver or gstreamer and that there's not much we can do in xpra: the extra buffering is not in xpra, nor is it controlled by xpra.

You could try:

set XPRA_QUEUE_SILENT=1
set XPRA_SOUND_GRACE_PERIOD=100000000
set XPRA_SOUND_MARGIN=500
xpra_cmd attach ...

This will turn off some of the buffering management logic.

You could also try older Xpra MS Windows installers (ie: 1.0.x or 2.x https://xpra.org/dists/windows/), as those will be using older versions of GStreamer and different versions of the python bindings, maybe that will help or make a difference.

Beyond that, I think I would need to be able to reproduce the problem to be able to fix it.

comment:18 Changed 3 weeks ago by Antoine Martin

Just one more thing I have noticed, there are pairs of UI thread is now blocked / UI thread is running again, resuming. This usually happens when the OS is not letting us run (usually on macos) or when the system is overloaded.
You may want to try on a different, more powerful system.
You could also try using an uncompressed codec: wav / wavpack / wav+lz4.

comment:19 Changed 3 weeks ago by yvk1

Thank you for explaining what is happening.

I tried to set xpra environment variables and codec to wav, but the status did not change.
I also tried the 3.0.5-r24928 released the other day, but it still didn't change ...

I also tried the old Xpra MS Windows installer on the client and it looks like this:

1.0.14-r24089 -> sound is delayed
2.1.3-r17250 -> no sound
2.2.6-r18959 -> very unstable
2.3.4-r20511 -> sound is delayed
2.4.3-r21365 -> cannot attach
2.5.3-r23270 -> sound is delayed, sound buffer graph remains at 0

By the way, I changed the server and client versions to LTS v1.0.x as follows, and the sound synchronization was perfectly successful ...

server: 3.0.5-r24928 -> 1.0.14-r24088
client: 3.0.5-r24928 -> 1.0.14-r24089

Is there anything I should print about these things, logs, environment variables to try, etc?
Can I ask what kind of environment is being tested?

comment:20 Changed 3 weeks ago by Antoine Martin

By the way, I changed the server and client versions to LTS v1.0.x as follows, and the sound synchronization was perfectly successful ...

Interesting.
Downgrading the client does not help, but downgrading the server does?
Did you try a 1.0.x server with a 3.0.x client? Is that still delayed?

Can I ask what kind of environment is being tested?

Do you mean what I use for testing?
Today I only have access to a win7 virtualbox VM, so testing is fairly limited. Normally, I have access to much more.

comment:21 Changed 2 weeks ago by yvk1

When I tried the combination of 3.0.5-r24928 client and 1.0.14-r24088 server,
the video flickers a little but the sound seems to be almost perfectly synchronized.
Attach the server, client --debug=gstreamer, sound log at this time.

I also tried a combination of a 3.0.5-r24928 client and the following version of the server, but the sound is delayed as in the case of server 3.0.x.

2.5.3-r23270-1
2.4.3-r21365-1
2.3.4-r20525-1
2.2.6-r18969-1
2.1.7-r17247-1

Changed 2 weeks ago by yvk1

Attachment: logs.2.zip added

Changed 2 weeks ago by Antoine Martin

Attachment: fsync.patch added

force fsync after each write

comment:22 Changed 2 weeks ago by Antoine Martin

From your latest log: v1.0.14 uses Python GStreamer version 1.8.3 for Python 2.7 and starts the audio capture using this pipeline:

pulsesrc device="Xpra-Speaker.monitor" name="src" ! \
    queue name=queue min-threshold-time=0 max-size-buffers=0 max-size-bytes=0 max-size-time=50000000000000 leaky=2 ! \
    volume name=volume volume=1.0 ! \
    opusenc complexity=0 ! \
    appsink name=sink emit-signals=true max-buffers=10 drop=true sync=false async=false qos=false

From one of your earlier logs: v3 uses GStreamer version 1.8.3 for Python 3.5.2 64-bit and the pipeline:

pulsesrc name="src" device="Xpra-Speaker.monitor" ! \
    queue name=queue min-threshold-time=0 max-size-buffers=0 max-size-bytes=0 max-size-time=50000000000000 leaky=2 ! \
    volume name=volume volume=1.0 ! \
    opusenc complexity=0 ! \
    appsink name=sink emit-signals=true max-buffers=10 drop=true sync=false async=false qos=false

So the pipelines are identical and from your previous logs it looks like you had tried with a python2 server running xpra version>=2.
The only important difference between xpra v1 and v2 is that v2 uses the gi bindings to connect to gstreamer whereas v1 uses pygst.
But I've skimmed the code and I don't see anything different between the two code paths..

The fsync patch attached is unlikely to help, but since I'm out of ideas...

comment:23 Changed 12 days ago by alas

Just as an addition - I'm able to induce as much as 1 full second, sometimes as much as maybe 1200 ms (give or take, just judging by eye/ear)... though usually it seems to be closer to something like a long 750 ms.

Using Xpra-Python 3.0.5-r24942 64-bit Windows client, or the Xpra-Python 3.0.5-r24930 64-bit OSX client against a 3.0.5-r24939 Fedora 30 server, with two xterm start-children.

Using the BBC HD sync video it is hard to tell, and if I use solely that video (with either Firefox or Chromium-Browser launched from an xterm) the sync looks nearly perfect. If I use any other video (with some moving lips and sound to try to sync - I often just use music videos which I watch a few times in a local browser to watch for points where I can tie lyrics to well articulated lip movements, then watch them over and over via Xpra), then it looks like the delay stays around 750 ms to a full second, or sometimes more.

I've also tried using the manual delta syncing from #835 (xpra control :13 sound-output av-sync-delta "750", for example) to see if I can compensate, but it looks like the heuristics "very accurately counter-compensate" and keep the video the same 750-ish ms delayed from sound.

I'll let a youtube channel run for a while to see if the delay seems to continue to grow (it did with the 3.0.4-r24778).

In the meantime, a possible set of repro steps for you, which made the effect rather clear.

  • Launch a browser & navigate to a video that has elements to gauge sync.
  • Watch for a minute or two, noting how much the sound is delayed behind the video.
  • At some arbitrary point close the browser entirely (control-c on xterm or even just the red-X for the browser).
  • Launch a new browser (I move from firefox to chromium-browser) & navigate to a video that also has elements to gauge sync (I often use the same video).

In my testing, the moment the new video starts playing in the new browser, content that is apparently still "in the pipeline" plays, which the video for the new browser rolls. It is usually about that same 750-ish ms that plays out, but then whatever is "delaying" the initiation of the pipeline from the initial sound channel seems to "happen again"?, and so the delay effect is magnified and often pushes up to something in the 1000 to 1200 ms range (again, a bit of a guess... haven't tried to sort through -d sound logs, because they're awfully loquacious).

(Sure enough, the time that it took to type this was enough that starting the video used thousands of times testing #835 showed nearly a 3000 ms delay... so it is definitely still growing.)

I'll also try more testing with -d av-sync and see if I can isolate anything interesting.

comment:24 Changed 11 days ago by Antoine Martin

I'll try to reproduce using those steps.
In the meantime, some things worth trying:

  • XPRA_OPENGL_PAINT_BOX=1 xpra attach to make sure that the screen is actually being painted using a video codec since we only sync video - the mapping from encoding to colors can be found here: browser/xpra/trunk/src/xpra/client/paint_colors.py (ie: h264 is blue)
  • @afarr: disable cutter (as per comment:10) and see if it makes any difference
Note: See TracTickets for help on using tickets.