xpra icon
Bug tracker and wiki

Opened 16 months ago

Closed 8 months ago

#1921 closed defect (fixed)

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 16 months ago.
info by bug report tool
xpra-info.txt (135.0 KB) - added by Thomas Martitz 15 months ago.
xpra-showconfig.txt (9.0 KB) - added by Thomas Martitz 15 months ago.
env.txt (2.5 KB) - added by Thomas Martitz 15 months ago.
:10.log (97.3 KB) - added by Thomas Martitz 15 months ago.
xpra-info-good.txt (138.4 KB) - added by Thomas Martitz 12 months ago.
xpra-info-bad.txt (168.8 KB) - added by Thomas Martitz 12 months ago.
xpra-info-reinit.txt (181.0 KB) - added by Thomas Martitz 12 months ago.
xpra-info-gl-offon.txt (181.0 KB) - added by Thomas Martitz 12 months ago.
xpra-stats.txt.zip (183.2 KB) - added by Thomas Martitz 12 months ago.

Download all attachments as: .zip

Change History (59)

Changed 16 months ago by Thomas Martitz

Attachment: info.txt.zip added

info by bug report tool

comment:1 Changed 16 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 16 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 16 months ago by tc424

Cc: steved424@… added

comment:4 Changed 16 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 15 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 15 months ago by Antoine Martin (previous) (diff)

Changed 15 months ago by Thomas Martitz

Attachment: xpra-info.txt added

Changed 15 months ago by Thomas Martitz

Attachment: xpra-showconfig.txt added

Changed 15 months ago by Thomas Martitz

Attachment: env.txt added

Changed 15 months ago by Thomas Martitz

Attachment: :10.log added

comment:6 Changed 15 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 15 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 15 months ago by Antoine Martin (previous) (diff)

comment:8 Changed 15 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 15 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 14 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 14 months ago by Antoine Martin (previous) (diff)

comment:11 Changed 14 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 14 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 14 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 14 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 14 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 14 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 14 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 14 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 13 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 13 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 13 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 13 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 13 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 13 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 13 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 13 months ago by Antoine Martin

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

Changed 12 months ago by Thomas Martitz

Attachment: xpra-info-good.txt added

Changed 12 months ago by Thomas Martitz

Attachment: xpra-info-bad.txt added

comment:27 Changed 12 months 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 12 months ago by Thomas Martitz

Attachment: xpra-info-reinit.txt added

Changed 12 months ago by Thomas Martitz

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

comment:28 Changed 12 months 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 12 months ago by Antoine Martin

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

comment:30 Changed 12 months 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 12 months 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 12 months ago by Thomas Martitz

Attachment: xpra-stats.txt.zip added

comment:32 Changed 12 months 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 12 months ago by Thomas Martitz (previous) (diff)

comment:33 Changed 12 months 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 12 months 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 12 months 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 12 months 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 12 months 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 12 months ago by Antoine Martin (previous) (diff)

comment:38 Changed 10 months ago by Thomas Martitz

The situation is definitely vastly improved. I wouldn't say that anywhere near non-xpra windows but I can live with it.

I also found that for some reason KDE is setting the terminal application to full screen. I can undo that and maximize normally after starting it, which seems to help a bit also.

comment:39 Changed 10 months ago by Antoine Martin

Should be even better now, assuming no bottleneck or even recovering from network congestion: ticket:2022#comment:76.

comment:40 Changed 10 months ago by Thomas Martitz

I see only batch delay below 10 now. I guess that's a good sign?

The latency graph in the session info doesn't show the blue batch delay line anymore. I'm on 2.5-20190109r21303-1 (xpra beta)

comment:41 Changed 10 months ago by Antoine Martin

I see only batch delay below 10 now. I guess that's a good sign?

Where?

The latency graph in the session info doesn't show the blue batch delay line anymore. I'm on 2.5-20190109r21303-1 (xpra beta)

Thanks for reminding me, this needed fixing, done in r21340.
Note that the value shown is now more "correct" with new servers - it may be lower or higher than before depending on the window size (the old value was normalized to 1 megapixel)

@kugel: can we close this ticket?
If not, please attach your server's -d stats output.

comment:42 Changed 10 months ago by tc424

Is it worth hanging on a week or two for me to do some testing? Away from home at the moment but back in a few days ...

comment:43 Changed 10 months ago by Antoine Martin

Is it worth hanging on a week or two for me to do some testing? Away from home at the moment but back in a few days ...

Ping.

comment:44 Changed 10 months ago by tc424

Well, I've just tried the latest beta (r21480) on my little netbook (cheap SoC based thing) and it seems much the same. The new thing, unfortunately, is the server keeps crashing with nothing in the log file. I'll open other tickets as and when. Will test for local connection latency issues on other machines as well - I wonder whether something is CPU bound on that cheap machine (top doesn't show CPU maxed out, but who knows..)

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

comment:45 Changed 10 months ago by tc424

Interestingly just tested on my "X terminal" - cheap SoC-based settop box / NUC-alike PC and performance is much better there - not quite as good as native, but pretty close. And no crashes that I could trigger, despite what should be identical software config. So I may need to go looking for differences and crash causes.

I have one more box to test on..

comment:46 Changed 10 months ago by Antoine Martin

The new thing, unfortunately, is the server keeps crashing with nothing in the log file.

What distro version are you running?
Check the usual culprits: disable codecs and clipboard, etc.

There are no changes in 2.5 that would be likely to cause crashes like these.

comment:47 Changed 8 months ago by Antoine Martin

Can I close this for 2.5?

comment:48 Changed 8 months ago by tc424

As far as I can tell everything's looking pretty good here.. I'm still mostly testing r21480, I know you had some concern about ethernet performance on more recent revisions. I did upgrade the netbook (client) yesterday and things did seemed fine over ethernet there. Forcing RGB encoding definitely helps with latency...

comment:49 Changed 8 months ago by Antoine Martin

Resolution: fixed
Status: newclosed

Thanks, let's close this, we can re-open or link back here if we hit any regressions.

Note: See TracTickets for help on using tickets.