xpra icon
Bug tracker and wiki

Opened 5 months ago

Last modified 3 weeks ago

#1921 new defect

Local xpra is extremely laggy

Reported by: Thomas Martitz Owned by: Thomas Martitz
Priority: major Milestone: 2.5
Component: keyboard Version: 2.3.x
Keywords: Cc: steved424@…

Description

Local xpra is *very* laggy. The most prominent issue is that keyboard input is delayed by about a second, but also scrolling in GTK apps is laggy (might be caused by input lag, though).

As per IRC, I already tried debugging both client and server with -d keyboard,pointer and it does show that the server receives events delayed.

I also ran the server under strace, as I thought it might be blocked in some poll() loop, but that looked fine (all poll() calls return almost immediately.

Attachments (10)

info.txt.zip (46.1 KB) - added by Thomas Martitz 5 months ago.
info by bug report tool
xpra-info.txt (135.0 KB) - added by Thomas Martitz 4 months ago.
xpra-showconfig.txt (9.0 KB) - added by Thomas Martitz 4 months ago.
env.txt (2.5 KB) - added by Thomas Martitz 4 months ago.
:10.log (97.3 KB) - added by Thomas Martitz 4 months ago.
xpra-info-good.txt (138.4 KB) - added by Thomas Martitz 6 weeks ago.
xpra-info-bad.txt (168.8 KB) - added by Thomas Martitz 6 weeks ago.
xpra-info-reinit.txt (181.0 KB) - added by Thomas Martitz 5 weeks ago.
xpra-info-gl-offon.txt (181.0 KB) - added by Thomas Martitz 5 weeks ago.
xpra-stats.txt.zip (183.2 KB) - added by Thomas Martitz 3 weeks ago.

Download all attachments as: .zip

Change History (47)

Changed 5 months ago by Thomas Martitz

Attachment: info.txt.zip added

info by bug report tool

comment:1 Changed 5 months ago by Antoine Martin

Milestone: 2.4
Owner: changed from Antoine Martin to Thomas Martitz

Since it isn't laggy for anyone else (that I know of), please add more details as per wiki/ReportingBugs so we can identify the difference with your setup.

comment:2 Changed 5 months ago by Thomas Martitz

I attached the zip that's created by the built-in bug report took. What else do you need?

comment:3 Changed 5 months ago by tc424

Cc: steved424@… added

comment:4 Changed 5 months ago by Antoine Martin

What else do you need?

There are many questions on the wiki/ReportingBugs page, it is impossible for us to know which ones will be relevant. They key point is what something is different on your setup.

comment:5 Changed 4 months ago by Thomas Martitz

So I made a completely fresh Kubuntu 18.04.1 install and the behavior is pretty much the same. But as part of answering the question I found that disabling AV sync makes a huge difference, basically I cannot say it's laggy anymore.

what operating system is used on both the client and server, including the full version details

$ uname -a
Linux tmartitz-pc 4.15.0-30-generic #32-Ubuntu SMP Thu Jul 26 17:42:43 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
$ glxinfo | grep GL\ renderer
OpenGL renderer string: Mesa DRI Intel(R) HD Graphics 530 (Skylake GT2)

Kubuntu 18.04.1 comes with KDE Frameworks 5.44, Plasma 5.12 LTS and KDE Applications 17.12.3

$ dpkg -s xpra
Package: xpra
Status: install ok installed
Priority: optional
Section: x11
Installed-Size: 15697
Maintainer: Antoine Martin <antoine@devloop.org.uk>
Architecture: amd64
Version: 2.3.2-r19729-1
Replaces: ffmpeg-xpra
Depends: python (<< 2.8), python (>= 2.7~), python:any (<< 2.8), python:any (>= 2.7.5-5~), libavcodec57 (>= 7:3.4.2) | libavcodec-extra57 (>= 7:3.4.2), libavformat57 (>= 7:3.4.2), libavutil55 (>= 7:3.4.2), libc6 (>= 2.14), libglib2.0-0 (>= 2.12.0), libgtk2.0-0 (>= 2.24.0), libpam0g (>= 0.99.7.1), libswscale4 (>= 7:3.4.2), libsystemd0, libturbojpeg, libvpx5 (>= 1.6.0), libwebp6 (>= 0.5.1), libx11-6 (>= 2:1.2.99.901), libx264-152, libxcomposite1 (>= 1:0.3-1), libxdamage1 (>= 1:1.1), libxext6, libxfixes3, libxi6 (>= 2:1.2.99.4), libxkbfile1, libxrandr2 (>= 2:1.2.99.2), libxtst6, python-gtk2, x11-xserver-utils, xserver-xorg-video-dummy, python-gtkglext1, python-opengl, python-numpy, python-pil, python-rencode, python-lz4
Recommends: libavcodec57, libx264-148, dbus-x11, python-dbus, python-setproctitle, python-cryptography, python-kerberos, python-gssapi, gstreamer1.0-pulseaudio, gstreamer1.0-alsa, gstreamer1.0-plugins-base, gstreamer1.0-plugins-good, gstreamer1.0-plugins-ugly, python-gst-1.0, cups-filters, cups-common, cups-pdf, python-cups, python-pyinotify, python-opencv, v4l2loopback-dkms, openssh-client, ssh-askpass, websockify, libjs-jquery, keyboard-configuration, sshpass
Suggests: openssh-server, gnome-shell-extension-top-icons-plus, pulseaudio, pulseaudio-utils, python-avahi, python-netifaces, python-yaml, python-pycuda, libnvidia-encode1, python-lzo, libxvidcore4
Conflicts: ffmpeg-xpra
Conffiles:
 /etc/dbus-1/system.d/xpra.conf d58c2d718e3eaa799ed0223ab21dd2a5
 /etc/default/xpra 691afa8edec7c167de80fcfd407b0b37
 /etc/pam.d/xpra eaf372a294b1e2e1a1c9123cdeb03a41
 /etc/xpra/conf.d/05_features.conf f8bbd7527e86e50d2fe542470a14243e
 /etc/xpra/conf.d/10_network.conf 9549d386ce697a16e6e4edbc425466e3
 /etc/xpra/conf.d/12_ssl.conf 916ae779caa1a9e4ff3eb00cf9881ccc
 /etc/xpra/conf.d/15_file_transfers.conf 3d8e892d0b1b8ced4da21feac3a87e0f
 /etc/xpra/conf.d/16_printing.conf 55ded8177f08ff99629c34ef059ca163
 /etc/xpra/conf.d/20_sound.conf e805d4bd159a849529e3bc199e8958ea
 /etc/xpra/conf.d/30_picture.conf 2568844319ae92e81e3f3d14feb7c16a
 /etc/xpra/conf.d/35_webcam.conf 9f8857105624a48948078906acebf4ee
 /etc/xpra/conf.d/40_client.conf 2756819619b5c97839e680b3d19aaab0
 /etc/xpra/conf.d/42_client_keyboard.conf f1be5c9d8ef62d2677f1351ee4709ac8
 /etc/xpra/conf.d/50_server_network.conf 396e24f643bf3279360e74afa367fe84
 /etc/xpra/conf.d/55_server_x11.conf 82a4f3a74d998512955f2ca749172a76
 /etc/xpra/conf.d/60_server.conf 09fe862cd1ea649ddcbfcc7e04cde92e
 /etc/xpra/conf.d/65_proxy.conf a8d85747e0a2886341493a07977c390b
 /etc/xpra/cuda.conf 903827a1fd15d11fb4460ce2fc15c653
 /etc/xpra/xorg-uinput.conf 2913f509d04b5cf4432d356716874b95
 /etc/xpra/xorg.conf 4b6c318aef446f6585c83caee678880a
Description: tool to detach/reattach running X programs
 Xpra gives you the functionality of GNU Screen for X applications.
 .
 It allows the user to view remote X applications on their local machine, and
 disconnect and reconnect from the remote machine without losing the state of
 the running applications.
 .
 Unlike VNC, these applications are "rootless".  They appear as individual
 windows inside your window manager rather than being contained within a single
 window.
Homepage: http://xpra.org/

changes made to the default configuration, if any. This can be shown with the command: "xpra showconfig"

I have cleared all custom config. xpra showconfig is attached.

the desktop environment, window manager used - if applicable

KDE with kwin (see above)

anything that would make the setup unusual: number of screens, resolution, virtualization software, access via another remote desktop tool (VNC, RDP, ..), etc

I normally use 3 screens, one of them rotated, but the behavior is the same with only one output. No other remote desktop involved.

the network setup, bandwidth constraints (ie: LAN or DSL)

local

the full command lines used both on the server and client

$ ps aux | grep xpra
tmartitz  3075  5.4  1.5 1338604 369492 ?      Sl   10:44   4:19 /usr/bin/python2 /usr/bin/xpra start :10 --start-via-proxy=no
tmartitz  3076  0.0  0.8 880552 205320 ?       Ssl  10:44   0:04 /usr/lib/xorg/Xorg-for-Xpra-:10 -noreset -novtswitch -nolisten tcp +extension GLX +extension RANDR +extension RENDER -auth /home/tmartitz/.Xauthority -logfile /run/user/1000/xpra/Xorg.:10.log -configdir /run/user/1000/xpra/xorg.conf.d/3075 -config /etc/xpra/xorg.conf -depth 24 :10
tmartitz  3122  2.3  0.0 326532  8404 ?        S<l  10:44   1:52 pulseaudio --start -n --daemonize=false --system=false --exit-idle-time=-1 --load=module-suspend-on-idle --load=module-null-sink sink_name="Xpra-Speaker" sink_properties=device.description="Xpra\ Speaker" --load=module-null-sink sink_name="Xpra-Microphone" sink_properties=device.description="Xpra\ Microphone" --load=module-native-protocol-unix socket=/run/user/1000/xpra/pulse-:10/pulse/native --load=module-dbus-protocol --load=module-x11-publish --log-level=2 --log-target=stderr --enable-memfd=no
tmartitz  3604  5.3  1.7 2121604 438064 pts/1  Sl+  10:44   4:10 /usr/bin/python2 /usr/bin/xpra attach :10
tmartitz  3683  6.4  0.1 1215724 40680 pts/1   Sl+  10:45   5:03 /usr/bin/python2 /usr/bin/xpra _sound_play - -   opus  1.0
tmartitz  3722 12.4  0.1 1009540 40980 ?       Sl   10:45   9:44 /usr/bin/python2 /usr/bin/xpra _sound_record - - pulsesrc device=Xpra-Speaker.monitor opus  1.0
tmartitz  3756  0.0  0.0  25840  6768 ?        Ss   10:45   0:00 /usr/bin/python2 /usr/bin/xpra_signal_listener
tmartitz  5512  0.0  0.0  14780  1048 pts/3    S+   12:03   0:00 grep xpra

the server log file (or output if no log file is used)

:10.log is attached

the environment (ie: %PATH% on MS Windows, $PATH and $LD_LIBRARY_PATH on Linux, etc)

env.txt is attached

"xpra info" for the session

xpra-info.txt is attached

how the software was installed and what version (in full)

I installed it through package managers using the repositories on winswitch.org, version see above (latest stable)

is this a new problem or a regression? (if a regression, when did it start?)

I think it wasn't that bad a couple of years ago, but it's like this since a long time by now (I was too lazy to report early and hoped it would be fixed by the new graphics stack in 18.04)

are there other bugs that are similar?
are there other unusual issues / behaviour apart from this particular bug?

Not that I can tell for both questions

is it reproducible reliably? and if so, how?

Always

does this happen with all picture encodings?

Can't change with local xpra

does switching off certain features make a difference (ie: sound, opengl, clipboard)

Actually, this question gave a key hint. I did play with some settings, and disabling audio-video sync makes a huge difference. I would say the laggy behavior does not occur with AV sync disabled!

include relevant parts of the log files - including enough context to investigate (not just the last line showing the error message, but not necessarily the whole log file either)

What log files would be relevant?

does re-connecting help?

No

does it happen with other type of clients (different OS, etc)

I have only Linux clients. I have one at home (for home office) and it's laggy as well but I can't say for sure it's not the slow internet connection.

try to include the output of some of the diagnosis tools we bundle (ie: Network_Info.exe and Encoding_Info.exe on MS Windows, net_util.py and loader.py everywhere else)

Please say if this is still relevant after my AV sync finding.

Last edited 4 months ago by Antoine Martin (previous) (diff)

Changed 4 months ago by Thomas Martitz

Attachment: xpra-info.txt added

Changed 4 months ago by Thomas Martitz

Attachment: xpra-showconfig.txt added

Changed 4 months ago by Thomas Martitz

Attachment: env.txt added

Changed 4 months ago by Thomas Martitz

Attachment: :10.log added

comment:6 Changed 4 months ago by Thomas Martitz

Sorry, I have to take the av-sync finding back. I made an error on my side. Disabling av-sync *does not* do anything.

comment:7 Changed 4 months ago by Thomas Martitz

But perhaps you can tell if it's truly disabled because to me it looks still like being enabled?

$ xpra info | grep av-sync
client.argv=('/usr/bin/xpra', 'attach', '--av-sync=no', ':10')
client.av-sync=True
client.av-sync.client=0
client.av-sync.delta=0
client.av-sync.enabled=False
client.av-sync.total=75
features.av-sync=True
window.1.av-sync.current=75
window.1.av-sync.enabled=True
window.1.av-sync.target=75
window.9.av-sync.current=75
window.9.av-sync.enabled=True
window.9.av-sync.target=75
window.10.av-sync.current=0
window.10.av-sync.enabled=True
window.10.av-sync.target=0
Last edited 4 months ago by Antoine Martin (previous) (diff)

comment:8 Changed 4 months ago by Antoine Martin

KDE with kwin (see above)

I doubt that's the source of the problem, but if nothing else helps then it would be worth trying a different WM as I very rarely test the client under KDE.

Actually, this question gave a key hint. I did play with some settings, and disabling audio-video sync makes a huge difference. I would say the laggy behavior does not occur with AV sync disabled!

Then that's the problem.
What I don't understand is why you would have AV sync with local connections. Those are meant to use mmap, and mmap is not affected by av-sync.
The only encodings that use av-sync are the video encodings (vp8, vp9, h264 and hevc), and those don't usually trigger unless the application you run is refreshing at a high framerate.
What is the application you are forwarding?
Does the problem manifest itself with a simple xterm?

Can you try to turn off audio completely? Start with --speaker=no --microphone=no

Please say if this is still relevant after my AV sync finding.

I think there's enough data in this ticket, thanks!

comment:9 Changed 4 months ago by Thomas Martitz

Actually, this question gave a key hint. I did play with some settings, and disabling audio-video sync makes a huge difference. I would say the laggy behavior does not occur with AV sync disabled!

Then that's the problem.

av-sync is *not* the problem, the previous post was based on an error on my side (the window I tested wasn't running under xpra).

comment:10 Changed 3 months ago by Antoine Martin

Unless you can give me steps to reproduce the laggyness, I will have to close this ticket as "needinfo".

My prime suspect would be the clipboard.

Last edited 3 months ago by Antoine Martin (previous) (diff)

comment:11 Changed 3 months ago by tc424

FWIW, I'm slowly working my way back to looking at this, I need xpra working for the next stage of one or two projects, but "real world" stuff has intervened recently :(

comment:12 Changed 3 months ago by Thomas Martitz

Alright, so I went into a Kubuntu live install in order to repro this on a truly clean system.

I only changed language and input to German, and then installed xpra and did some test.

I tested with kate first and thought it's snappy as expected. Then I checked debug / support files and found no real difference to my system. Only "input-ethod" seems to be at keep for my problematic although I never explicitly changed this back from the default of none (the live system has input-method = none).

But then I thought I should try the apps I use, that's mainly Geany and some gtk based terminals. And here I found the culprit: Geany was laggy. Much more so than kate.

So I think the root issue seems to be on GTK apps, mayble only if running on a KDE platform.

Do you have an idea?

comment:13 Changed 3 months ago by Thomas Martitz

Oh and changing input-method from keep to none or vice versa doesn't make a difference to the GTK apps.

comment:14 Changed 3 months ago by Antoine Martin

So I think the root issue seems to be on GTK apps, mayble only if running on a KDE platform.
Do you have an idea?

You can enable paint debugging to see if the app is repainting too much:

XPRA_OPENGL_PAINT_BOX=1 xpra attach ...

(assuming that you have opengl enabled on the client)

comment:15 Changed 3 months ago by Thomas Martitz

Seems rather calm. In a terminal application only the edited line flashes according to the cursor and if I hit enter (to add a new line) the full widget flashes only very briefly. So far as expected.

Also, I found previously, that the input events reach the server delayed, see description:

As per IRC, I already tried debugging both client and server with -d keyboard,pointer and it does show that the server receives events delayed.

comment:16 Changed 3 months ago by Antoine Martin

As per IRC, I already tried debugging both client and server with -d keyboard,pointer and it does show that the server receives events delayed.

Then I can only recommend that you try to run a packet sniffer between the server and client, enable network logging with "-d network" and see if the delay comes from the network or from xpra processing those packets too slowly.
(running with XPRA_USE_ALIASES=0 xpra -z 0 ... makes the packets more human-readable)

If somehow xpra is abnormally slow, then it's usually something messing up with X11 or xpra's main loop (ie: clipboard sync, which you can try to disable).

comment:17 Changed 3 months ago by Thomas Martitz

Uhm, this is local xpra (mmap'd), what kind of traffic should I expect? On which interface (lo?)

comment:18 Changed 3 months ago by Antoine Martin

Uhm, this is local xpra (mmap'd), what kind of traffic should I expect? On which interface (lo?)

Yes, you can connect to tcp://127.0.0.1:10000 for example after using --bind-tcp=0.0.0.0:10000 on the server.

comment:19 Changed 2 months ago by Antoine Martin

Milestone: 2.42.5

I will have to close this ticket as NEEDINFO unless I can reproduce it.

comment:20 Changed 2 months ago by Thomas Martitz

I provided steps to reproduce. Is that not sufficient?

  • boot a Kubuntu 18.10 live system
  • install xpra and a GTK app (I used geany)
  • run geany inside local xpra, notice input lag of 0.5 to 1 secs
  • run kate inside local xpra, notice no input lag

comment:21 Changed 2 months ago by tc424

Just had a quick look at this .. using latest Kubuntu daily-live (2018-10-14 00:06, MD5: 020460f18bd227886c2fb1a2a21990cf) and latest Xpra beta (presumably 20683, but forgot to actually check, sorry), I can't reproduce any lag with Geany - was lovely and smooth even on my low power box, apart from a brief delay to cache the drop down menus. No problem with keyboard input.

I tried to experiment with input method but I kept getting messages about not being able to connect to fcitx, which I decided I wasn't up for investigating!

comment:22 Changed 2 months ago by Thomas Martitz

You used different versions of kubuntu and xpra (I used stable), so its not really comparable. Now I don't know if it's your system (maybe sound or graphics driver make a difference?) or the SW versions.

Can you post some system details?

comment:23 Changed 2 months ago by tc424

Ah, OK, didn't know what versions you'd used for the live test. You did say you used 18.10 in comment 20 though?

Anyway, it's an Apollo Lake Intel SoC box..

CPU:       Quad core Intel Celeron N3450 (-MCP-) speed/max: 922/2200 MHz
Graphics:  Card: Intel Device 5a85
00:02.0 VGA compatible controller: Intel Corporation Device 5a85 (rev 0b)
00:0e.0 Audio device: Intel Corporation Celeron N3350/Pentium N4200/Atom E3900 Series Audio Cluster (rev 0b)

Can't check what drivers the Live image used just now but I'd imagine it was i915 kernel-side and modeset for X.

For some reason I'd dropped off IRC but joined again now - tc424 there as well. Shout if you want more details..

comment:24 Changed 2 months ago by Antoine Martin

and latest Xpra beta (presumably 20683, but forgot to actually check, sorry)

You used different versions of kubuntu and xpra (I used stable)

r20683 is 2.4 stable.

comment:25 Changed 2 months ago by Thomas Martitz

Today I made an interesting observation:

I upgraded my system, so that xpra 2.4 stable was installed. After a reboot, I thought the problem disappeared, and I imagined that a important change was made to 2.4.

However, after about 20min of using the system onwards, the problem started to reappear. Then I closed two affected apps and restarted them, and I see that the input delay is close to zero again (I wouldn't say it's indistinguishable from KDE apps like kate under xpra, but it's almost acceptable).

After about 20 minutes the problem appears again.

So the conclusion is that the problem doesn't immediately appear after starting the affected programs, but only after some time (I wouldn't say the apps need to be actively used from my observations).

comment:26 Changed 2 months ago by Antoine Martin

Please capture xpra info both before and after the problem appears so we can see what is different.

Changed 6 weeks ago by Thomas Martitz

Attachment: xpra-info-good.txt added

Changed 6 weeks ago by Thomas Martitz

Attachment: xpra-info-bad.txt added

comment:27 Changed 5 weeks ago by Antoine Martin

Then I closed two affected apps and restarted them, and I see that the input delay is close to zero again (I wouldn't say it's indistinguishable from KDE apps like kate under xpra, but it's almost acceptable).

Be aware that some KDE applications are known to have had pathological paint behaviour in the past, this can contribute to make things slower. That said, on a local connection with mmap enabled this should be a non-issue, just a small waste of CPU cycles.

Next time, try the "re-initialize windows" action from the system tray menu. You will probably get the same effect. (or toggle opengl on and off from the same menu)

The only noticeable difference between the good and bad log you provided is the batch delay in the bad one: it's high enough that one would notice (around >100ms).

I already tried debugging both client and server with -d keyboard,pointer and it does show that the server receives events delayed.

Are you certain this is the case?
Can you post a sample server log? If you also run both the client and server with -d keyboard,pointer and remote logging enabled (it is enabled by default) then the server log will have both client and server events, including the original timecodes from the client end.
The batch delay would not affect input events being received and processed by the server, but it would cause the screen updates to be delayed before being sent to the client.

Assuming that the problem does come from the batch delay rather than an "input lag" then we need to figure out why it reaches >100ms - which should never happen on a local connection.
For that please provide the -d stats server log output around the time when the problem occurs.
You may also want to try --bandwidth-detection=no on the client. (there are recent reports that it does cause problems)

Changed 5 weeks ago by Thomas Martitz

Attachment: xpra-info-reinit.txt added

Changed 5 weeks ago by Thomas Martitz

Attachment: xpra-info-gl-offon.txt added

comment:28 Changed 5 weeks ago by Thomas Martitz

I'll collect the requested logs later on. Meanwhile I tried your suggestion to 1) re-initialize the windows and 2) toggle opengl.

1) The former did not make a difference, the delay remained the same.
2) Toggling OpenGL off an on again did make a difference. The delay reduced significantly.

I attached xpra info output after each (so xpra-info-gl-offon.txt is after 1) and 2))

comment:29 Changed 5 weeks ago by Antoine Martin

Some of the slowness could be explained / fixed by #2037

comment:30 Changed 5 weeks ago by Thomas Martitz

Here is the log of a single key press.

It seems that I have misinterpreted the logs earlier. According to the timestamps there seems to be a delay of 100ms? But the actual delay is a lot higher.

I pressed arrow-down in a affected GTK-based terminal and watched the output of "journalctl -f" in another KDE-based terminal (which runs on the original DISPLAY not inside xpra).

What's interesting is that the entire bulk of the log lines that relate to the key press appears at once only after the affected application updates according to the keypress, so after the delay.

Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,661 client @55.787 parse_key_event(<gtk.gdk.Event at 0x7ff7c4d3f7d8: GDK_KEY_PRESS keyval=Down>, True)=<GTKKeyEvent object, contents: {'modifiers': ['mod2'], 'group': 0, 'string': '', 'keyname': 'Down', 'pressed': True, 'keyval': 65364, 'keycode': 116}>
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,663 client @55.787 handle_key_action(GLClientWindow(1 : gtk2.GLWindowBacking(1, (1920, 932), None)), <GTKKeyEvent object, contents: {'modifiers': ['mod2'], 'group': 0, 'string': '', 'keyname': 'Down', 'pressed': True, 'keyval': 65364, 'keycode': 116}>) wid=1
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,663 client @55.789 key_handled_as_shortcut: shortcut(Down)=None
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,664 client @55.789 send_key_action(1, <GTKKeyEvent object, contents: {'modifiers': ['mod2'], 'group': 0, 'string': '', 'keyname': 'Down', 'pressed': True, 'keyval': 65364, 'keycode': 116}>)
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,665 set_keyboard_layout_group(0) config=KeyboardConfig(de /  / None), current keyboard group=0
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,665 get_keycode(116, Down, ('mod2',))=116 (native keymap)
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,665 process_key_action(['key-action', 1, 'Down', True, ('mod2',), 65364, '', 116, 0]) server keycode=116
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,666 filtered_modifiers_set(['mod2'])=set(['mod2'])
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,666 filtered_modifiers_set(('mod2',))=set(['mod2'])
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,666 handle_key(1,True,Down,65364,116,('mod2',)) keyboard_sync=True
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,666 is_modifier(116) not found
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,667 handle keycode pressing   116: key 'Down'
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,667 fake_key(116, True)
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,668 scheduling key repeat timer with delay 600 for Down / 116
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,668 key repeat timeout for Down / '116' - clearing it, now=38615.7958299, scheduled at 38615.795702 with delay=600
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,668 handle_key(1,False,Down,65364,116,('mod2',)) keyboard_sync=True
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,669 is_modifier(116) not found
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,669 handle keycode unpressing 116: key 'Down'
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,669 fake_key(116, False)
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,765 client @55.890 parse_key_event(<gtk.gdk.Event at 0x7ff7c4d3f7d8: GDK_KEY_RELEASE keyval=Down>, False)=<GTKKeyEvent object, contents: {'modifiers': ['mod2'], 'group': 0, 'string': '', 'keyname': 'Down', 'pressed': False, 'keyval': 65364, 'keycode': 116}>
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,766 client @55.891 handle_key_action(GLClientWindow(1 : gtk2.GLWindowBacking(1, (1920, 932), None)), <GTKKeyEvent object, contents: {'modifiers': ['mod2'], 'group': 0, 'string': '', 'keyname': 'Down', 'pressed': False, 'keyval': 65364, 'keycode': 116}>) wid=1
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,767 client @55.891 key_handled_as_shortcut: shortcut(Down)=None
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,767 client @55.892 send_key_action(1, <GTKKeyEvent object, contents: {'modifiers': ['mod2'], 'group': 0, 'string': '', 'keyname': 'Down', 'pressed': False, 'keyval': 65364, 'keycode': 116}>)
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,768 set_keyboard_layout_group(0) config=KeyboardConfig(de /  / None), current keyboard group=0
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,768 process_key_action(['key-action', 1, 'Down', False, ('mod2',), 65364, '', 116, 0]) server keycode=116
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,768 filtered_modifiers_set(['mod2'])=set(['mod2'])
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,769 filtered_modifiers_set(('mod2',))=set(['mod2'])
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,769 handle_key(1,False,Down,65364,116,('mod2',)) keyboard_sync=True
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,769 is_modifier(116) not found
Nov 15 12:57:57 tmartitz-pc xpra[1842]: 2018-11-15 12:57:57,769 handle keycode 116: key Down was already unpressed, ignoring

--bandwidth-detection=no on the client makes no difference.

comment:31 Changed 5 weeks ago by Antoine Martin

Based on the log above, there does not seem to be any input lag.
There are two key events in that log: one GDK_KEY_PRESS and one GDK_KEY_RELEASE 100 ms later.
From the moment the client parses the key event (parse_key_event) until the server simulates pressing the corresponding key (fake_key), only 6ms have passed. (4ms for the release)

So I think the whole premise of this ticket led us on a wild goose chase, there is no input lag and the problem is elsewhere.
My guess is that somehow the batch delay goes way up for the affected windows.
Please attach the -d stats server debug output of a session that goes wrong.

Changed 3 weeks ago by Thomas Martitz

Attachment: xpra-stats.txt.zip added

comment:32 Changed 3 weeks ago by Thomas Martitz

I attached the requested logs. As you can see, only after a few minutes the batch delay ramps up to 260+ ms. I have seen values above 400ms too in previous sessions.

I guess you can interpret the logs better. I only see that starting with the high batch delay the following lines appear start to appear in the log:

Nov 27 09:43:41 tmartitz-pc xpra[1807]: 2018-11-27 09:43:41,703 calculate_batch_delay for wid=1 current batch delay=74, last update 60 seconds ago
Nov 27 09:43:41 tmartitz-pc xpra[1807]: 2018-11-27 09:43:41,703 update_batch_delay: damage-network-delay         : 0.99,0.51  {u'avg': 40, u'recent': 40}
Nov 27 09:43:41 tmartitz-pc xpra[1807]: 2018-11-27 09:43:41,703 update_batch_delay: client-decode-speed          : 0.88,0.04  {u'avg': 90, u'recent': 76}
Nov 27 09:43:41 tmartitz-pc xpra[1807]: 2018-11-27 09:43:41,703 update_batch_delay: damage-rate                  : 1.00,0.00  {'max_latency': 100, 'elapsed': 172}
Nov 27 09:43:41 tmartitz-pc xpra[1807]: 2018-11-27 09:43:41,704 update_batch_delay: client-latency               : 0.49,0.25  {u'target': 5, u'weight_multiplier': 355, u'smoothing': u'sqrt', u'aim': 800, u'aimed_avg': 238, u'div': 1000, u'avg': 2, u'recent': 1}
Nov 27 09:43:41 tmartitz-pc xpra[1807]: 2018-11-27 09:43:41,704 update_batch_delay: client-ping-latency          : 0.48,0.12  {u'target': 5, u'weight_multiplier': 161, u'smoothing': u'sqrt', u'aim': 949, u'aimed_avg': 233, u'div': 1000, u'avg': 1, u'recent': 1}
Nov 27 09:43:41 tmartitz-pc xpra[1807]: 2018-11-27 09:43:41,704 update_batch_delay: server-ping-latency          : 0.62,0.10  {u'target': 6, u'weight_multiplier': 163, u'smoothing': u'sqrt', u'aim': 949, u'aimed_avg': 380, u'div': 1000, u'avg': 2, u'recent': 2}
Nov 27 09:43:41 tmartitz-pc xpra[1807]: 2018-11-27 09:43:41,704 update_batch_delay: packet-queue-size            : 0.00,0.05  {u'target': 1000, u'weight_multiplier': 48, u'smoothing': u'sqrt', u'aim': 250, u'aimed_avg': 0, u'div': 1000, u'avg': 2, u'recent': 0}
Nov 27 09:43:41 tmartitz-pc xpra[1807]: 2018-11-27 09:43:41,704 update_batch_delay: packet-queue-pixels          : 0.00,0.00  {u'target': 1000, u'weight_multiplier': 0, u'smoothing': u'sqrt', u'aim': 250, u'aimed_avg': 0, u'div': 962684000, u'avg': 0, u'recent': 0}
Nov 27 09:43:41 tmartitz-pc xpra[1807]: 2018-11-27 09:43:41,704 update_batch_delay: compression-work-queue       : 0.00,0.04  {u'target': 1000, u'weight_multiplier': 41, u'smoothing': u'logp', u'aim': 250, u'aimed_avg': 0, u'div': 1000, u'avg': 1, u'recent': 0}
Nov 27 09:43:41 tmartitz-pc xpra[1807]: 2018-11-27 09:43:41,704 update_batch_delay: damage-packet-queue-pixels   : 0.00,0.00  {u'target': 1000, u'weight_multiplier': 0, u'smoothing': u'sqrt', u'aim': 250, u'aimed_avg': 0, u'div': 962684000, u'avg': 0, u'recent': 0}
Nov 27 09:43:41 tmartitz-pc xpra[1807]: 2018-11-27 09:43:41,704 update_batch_delay: focus                        : 1.00,0.00  {'has_focus': False}
Nov 27 09:43:41 tmartitz-pc xpra[1807]: 2018-11-27 09:43:41,704 update_batch_delay: override-redirect            : 1.00,0.00  {'is_OR': False}
Nov 27 09:43:41 tmartitz-pc xpra[1807]: 2018-11-27 09:43:41,704 update_batch_delay: fullscreen                   : 4.00,1.00  {'other_is_fullscreen': True}
Nov 27 09:43:41 tmartitz-pc xpra[1807]: 2018-11-27 09:43:41,704 update_batch_delay: maximized                    : 0.00,0.00  {'other_is_maximized': False}
Nov 27 09:43:41 tmartitz-pc xpra[1807]: 2018-11-27 09:43:41,704 update_batch_delay: soft-expired                 : 0.00,0.00  {'count': 0}
Nov 27 09:43:41 tmartitz-pc xpra[1807]: 2018-11-27 09:43:41,704 update_batch_delay: delay=120

The last line "delay=120" seems set the high delay. Following that the delay becomes even larger. Does that makes any sense to you?

What I find also curious is that the logs output recalculations messages every second, but the log lines state "last update 20 seconds ago."

Last edited 3 weeks ago by Thomas Martitz (previous) (diff)

comment:33 Changed 3 weeks ago by Thomas Martitz

BTW: As of now, only one of the windows is affected. This is confirmed by the logs (the delay for wid=2 is small).

I see some more curious thing: For wid=1 (the problematic one) I only find references to the pixel dimensions 74x18. This is nowhere near the actual size of the window which is more like 1200x600 (roughly). On the other hand, for the working window there are multiple pixel dimensions mentioned, one of them (1920x1200) is the actual size of the window.

comment:34 Changed 3 weeks ago by Antoine Martin

As expected, this has nothing to do with input lag.
The batch delay goes up because you are forwarding multiple windows and one of them is fullscreen. When that happens the system decides to slow down the other windows since the fullscreen window takes priority.
r21115 reduces the impact that this factor has on the batch delay. You can try applying it by hand.

comment:35 Changed 3 weeks ago by Thomas Martitz

Okay. That raises two questions:

1) Did anything change in this regard? In the past the full screen window was laggy as well, not any better than the other windows. It doesn't appear to be the case currently but xpra was updated a few times since then (I'm now on 2.4.2).

2) Why are the other windows slowed down at all? Is there some contention that requires a resultion like this? Since this is a local connection there ought to be enough room for many windows.
Is this decision made regardless of bandwidth, cpu usage or other factors?

In my eyes slowing things down should only happen if there is a bottleneck.

comment:36 Changed 3 weeks ago by Thomas Martitz

Also: the fullscreen window is a terminal (terminator) which I'd like to use without window decorations, not a demanding game or anything like that. It doesn't seem appropriate to slow other windows down in favor of that even if there was a bottleneck.

comment:37 Changed 3 weeks ago by Antoine Martin

Did anything change in this regard? In the past the full screen window was laggy as well, not any better than the other windows. It doesn't appear to be the case currently but xpra was updated a few times since then (I'm now on 2.4.2).

Impossible to say: there were likely many bugfixes between whatever version you had and 2.4.2

Since this is a local connection there ought to be enough room for many windows.

Even on a local connection, it is possible for screen updates to accumulate to the point where we need to slow things down a little.
The newer rate control mechanisms (#2061 and earlier fixes) ought to be able to handle those sorts of problems a lot better, so this old code may be removed or at least moderated: more improvements recorded in ticket:2061#comment:4.

Why are the other windows slowed down at all?
It doesn't seem appropriate to slow other windows down in favor of that even if there was a bottleneck.

The idea is to favour the window that is likely to be the one that is in use / seen. (ie: focused)

Please try latest trunk and let me know if I can close this ticket.

Last edited 3 weeks ago by Antoine Martin (previous) (diff)
Note: See TracTickets for help on using tickets.