bug#65760: 29.1; eglot performance issue

bug#65760: 29.1; eglot performance issue

[Глеб Смирнов]

[-- Attachment #1: Type: text/plain, Size: 6205 bytes --]

The problem is that running eglot with rust-analyzer on my project
causes major input lag. Profiling shows that the problem is in
synchronous and slow function jsonrpc--log-event that is called on each
server request or response. Disabling this function with (advice-add
'jsonrpc--log-event :override #'ignore) solves the problem.


In GNU Emacs 29.1 (build 1, x86_64-pc-linux-gnu, GTK+ Version 3.24.38,
cairo version 1.16.0)
System Description: Fedora Linux 38 (Workstation Edition)

Configured using:
 'configure
 --prefix=/nix/store/rfn1864b8s7zd1g40zzfdxwi4v7b94k1-emacs-pgtk-29.1
 --disable-build-details --with-modules --with-pgtk
 --with-native-compilation --with-tree-sitter --with-xwidgets'

Configured features:
CAIRO DBUS FREETYPE GIF GLIB GMP GNUTLS GPM GSETTINGS HARFBUZZ JPEG JSON
LIBSELINUX LIBSYSTEMD LIBXML2 MODULES NATIVE_COMP NOTIFY INOTIFY PDUMPER
PGTK PNG RSVG SECCOMP SOUND SQLITE3 THREADS TIFF TOOLKIT_SCROLL_BARS
TREE_SITTER WEBP XIM XWIDGETS GTK3 ZLIB

Important settings:
  value of $LC_MONETARY: en_GB.UTF-8
  value of $LC_NUMERIC: en_GB.UTF-8
  value of $LC_TIME: en_GB.UTF-8
  value of $LANG: en_US.UTF-8
  value of $XMODIFIERS: @im=ibus
  locale-coding-system: utf-8-unix

Major mode: Dashboard

Minor modes in effect:
  delete-selection-mode: t
  global-auto-revert-mode: t
  pixel-scroll-precision-mode: t
  electric-pair-mode: t
  server-mode: t
  gcmh-mode: t
  save-place-mode: t
  savehist-mode: t
  vertico-mouse-mode: t
  vertico-mode: t
  marginalia-mode: t
  corfu-popupinfo-mode: t
  diff-hl-flydiff-mode: t
  global-diff-hl-mode: t
  direnv-mode: t
  shell-dirtrack-mode: t
  global-ligature-mode: t
  ligature-mode: t
  recentf-mode: t
  solaire-global-mode: t
  solaire-mode: t
  mood-line-mode: t
  yas-global-mode: t
  yas-minor-mode: t
  global-corfu-mode: t
  corfu-mode: t
  override-global-mode: t
  straight-use-package-mode: t
  straight-package-neutering-mode: t
  tooltip-mode: t
  global-eldoc-mode: t
  show-paren-mode: t
  electric-indent-mode: t
  mouse-wheel-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  blink-cursor-mode: t
  buffer-read-only: t
  line-number-mode: t
  transient-mark-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t

Load-path shadows:
None found.

Features:
(shadow sort mail-extr emacsbug message mailcap yank-media puny dired
dired-loaddefs rfc822 mml mml-sec epa epg rfc6068 epg-config gnus-util
mm-decode mm-bodies mm-encode mail-parse rfc2231 mailabbrev gmm-utils
mailheader sendmail rfc2047 rfc2045 ietf-drums mm-util mail-prsvr
mail-utils mule-util tramp-cmds cursor-sensor comp comp-cstr
display-line-numbers flymake-proc flymake warnings delsel autorevert
filenotify pixel-scroll cua-base elec-pair server gcmh saveplace
savehist vertico-mouse vertico marginalia corfu-popupinfo
diff-hl-flydiff diff diff-hl log-view pcvs-util vc-dir ewoc vc
vc-dispatcher project time direnv diff-mode dash init cyrillic-colemak
quail direnv-autoloads dash-autoloads typst-mode polymode derived
poly-lock polymode-base polymode-weave polymode-export polymode-compat
advice polymode-methods polymode-core polymode-classes eieio-custom
eieio-base typst-mode-autoloads polymode-autoloads
vterm-toggle-autoloads vterm bookmark pp tramp tramp-loaddefs trampver
tramp-integration files-x tramp-compat parse-time iso8601 compile
text-property-search color term disp-table shell ehelp vterm-module
term/xterm xterm vterm-autoloads org ob ob-tangle ob-ref ob-lob ob-table
ob-exp org-macro org-src ob-comint org-pcomplete pcomplete comint
ansi-osc ansi-color ring org-list org-footnote org-faces org-entities
time-date noutline outline icons ob-emacs-lisp ob-core ob-eval org-cycle
org-table ol org-fold org-fold-core org-keys oc org-loaddefs find-func
cal-menu calendar cal-loaddefs org-version org-compat org-macs
format-spec olivetti-autoloads rx ligature ligature-autoloads dashboard
dashboard-widgets recentf tree-widget wid-edit ffap thingatpt url-parse
auth-source eieio eieio-core password-cache json map url-vars
dashboard-autoloads solaire-mode solaire-mode-autoloads mood-line
mood-line-autoloads doom-themes-ext-org doom-themes-ext-visual-bell
face-remap doom-dracula-theme doom-themes doom-themes-base
doom-themes-autoloads yasnippet-snippets yasnippet
yasnippet-snippets-autoloads yasnippet-autoloads diff-hl-autoloads
corfu-terminal byte-opt popon corfu compat corfu-terminal-autoloads
popon-autoloads corfu-autoloads consult-autoloads marginalia-autoloads
orderless orderless-autoloads vertico-autoloads compat-autoloads
hide-mode-line hide-mode-line-autoloads finder-inf gcmh-autoloads
edmacro kmacro use-package-bind-key bind-key easy-mmode use-package-core
straight-autoloads cl-seq cl-extra help-mode straight subr-x cl-macs gv
cl-loaddefs cl-lib bytecomp byte-compile xdg rmc iso-transl tooltip
cconv eldoc paren electric uniquify ediff-hook vc-hooks lisp-float-type
elisp-mode mwheel term/pgtk-win pgtk-win term/common-win pgtk-dnd
tool-bar dnd fontset image regexp-opt fringe tabulated-list replace
newcomment text-mode lisp-mode prog-mode register page tab-bar menu-bar
rfn-eshadow isearch easymenu timer select scroll-bar mouse jit-lock
font-lock syntax font-core term/tty-colors frame minibuffer nadvice seq
simple cl-generic indonesian philippine cham georgian utf-8-lang
misc-lang vietnamese tibetan thai tai-viet lao korean japanese eucjp-ms
cp51932 hebrew greek romanian slovak czech european ethiopic indian
cyrillic chinese composite emoji-zwj charscript charprop case-table
epa-hook jka-cmpr-hook help abbrev obarray oclosure cl-preloaded button
loaddefs theme-loaddefs faces cus-face macroexp files window
text-properties overlay sha1 md5 base64 format env code-pages mule
custom widget keymap hashtable-print-readable backquote threads
xwidget-internal dbusbind inotify dynamic-setting system-font-setting
font-render-setting cairo gtk pgtk multi-tty make-network-process
native-compile emacs)

Memory information:
((conses 16 368796 66631)
 (symbols 48 25294 3)
 (strings 32 85384 13134)
 (string-bytes 1 3644523)
 (vectors 16 52578)
 (vector-slots 8 1279807 93492)
 (floats 8 524 278)
 (intervals 56 640 425)
 (buffers 984 16))

[-- Attachment #2: Type: text/html, Size: 6771 bytes --]

bug#65760: 29.1; eglot performance issue

[Ivan Sokolov]

[-- Attachment #1: Type: text/plain, Size: 692 bytes --]

Глеб Смирнов <glebsmirnov0708@gmail.com> writes:

> The problem is that running eglot with rust-analyzer on my project
> causes major input lag. Profiling shows that the problem is in
> synchronous and slow function jsonrpc--log-event that is called on each
> server request or response. Disabling this function with (advice-add
> 'jsonrpc--log-event :override #'ignore) solves the problem.

To be more precise the problem is that jsonrpc--log-event is pretty
printing every reply from the server and they can be quite large and
nested.  I am attaching Gleb's profiler report, as a screenshot, but
this should be enough to give a better understanding of the problem.


[-- Attachment #2: profiler report --]
[-- Type: image/jpeg, Size: 70459 bytes --]

bug#65760: 29.1; eglot performance issue

[Eli Zaretskii]

> Cc: 65760@debbugs.gnu.org
> From: Ivan Sokolov <ivan-p-sokolov@ya.ru>
> Date: Tue, 05 Sep 2023 18:55:23 +0300
> 
> Глеб Смирнов <glebsmirnov0708@gmail.com> writes:
> 
> > The problem is that running eglot with rust-analyzer on my project
> > causes major input lag. Profiling shows that the problem is in
> > synchronous and slow function jsonrpc--log-event that is called on each
> > server request or response. Disabling this function with (advice-add
> > 'jsonrpc--log-event :override #'ignore) solves the problem.
> 
> To be more precise the problem is that jsonrpc--log-event is pretty
> printing every reply from the server and they can be quite large and
> nested.  I am attaching Gleb's profiler report, as a screenshot, but
> this should be enough to give a better understanding of the problem.

Yes, the real CPU eater is pp-buffer.

But I also see that jsonrpc-request took a substantial amount of CPU
time, and since jsonrpc-request runs from a timer, it is a good
candidate for explaining a perceived lag.

Can you tell if this profile was in an Emacs build with built-in JSON
support, or was Emacs using the Lisp implementation on json.el?

bug#65760: 29.1; eglot performance issue

[Eli Zaretskii]

Adding João.

> Cc: 65760@debbugs.gnu.org, glebsmirnov0708@gmail.com
> Date: Tue, 05 Sep 2023 19:22:15 +0300
> From: Eli Zaretskii <eliz@gnu.org>
> 
> > Cc: 65760@debbugs.gnu.org
> > From: Ivan Sokolov <ivan-p-sokolov@ya.ru>
> > Date: Tue, 05 Sep 2023 18:55:23 +0300
> > 
> > Глеб Смирнов <glebsmirnov0708@gmail.com> writes:
> > 
> > > The problem is that running eglot with rust-analyzer on my project
> > > causes major input lag. Profiling shows that the problem is in
> > > synchronous and slow function jsonrpc--log-event that is called on each
> > > server request or response. Disabling this function with (advice-add
> > > 'jsonrpc--log-event :override #'ignore) solves the problem.
> > 
> > To be more precise the problem is that jsonrpc--log-event is pretty
> > printing every reply from the server and they can be quite large and
> > nested.  I am attaching Gleb's profiler report, as a screenshot, but
> > this should be enough to give a better understanding of the problem.
> 
> Yes, the real CPU eater is pp-buffer.
> 
> But I also see that jsonrpc-request took a substantial amount of CPU
> time, and since jsonrpc-request runs from a timer, it is a good
> candidate for explaining a perceived lag.
> 
> Can you tell if this profile was in an Emacs build with built-in JSON
> support, or was Emacs using the Lisp implementation on json.el?
> 
> 
> 
> 

bug#65760: 29.1; eglot performance issue

[João Távora]

On Tue, Sep 5, 2023 at 5:25 PM Eli Zaretskii <eliz@gnu.org> wrote:
>
> Adding João.

The troubleshooting section in the manual

   https://joaotavora.github.io/eglot/#Troubleshooting-Eglot

has a heading specifically dedicated to these types of
performance problems:

"A common and easy-to-fix cause of performance problems is the length
of the Eglot events buffer because it represent additional work that Eglot
must do. After verifying Eglot is operating correctly but slowly, try
to customize the variable eglot-events-buffer-size (see Eglot
Variables) to 0. This will disable any debug logging and may speed
things up."

So, keeping a rich log and human-readable log is very useful for
debugging but can kill performance if servers send tons of JSON.

Maybe I could review the default value of eglot-events-buffer-size
or find a more fine-grained solution like some new foo-print-level
or foo-print-length variables, likely for jsonrpc.el.  Suggestions
welcome.  Patches doing this are even more welcome.

João

bug#65760: 29.1; eglot performance issue

[Axel Forsman]

I disagree with the initial decision to log all JSONRPC events
by default to begin with, but irregardless,
should it not be possible to fix the performance issues by
having jsonrpc--log-event push raw events onto a ring,
and introducing a second function that
formats the raw events as strings
and inserts them into a new buffer that gets displayed.
That way the expensive pretty printing would be deferred
to until the events are actually viewed.


/Axel

bug#65760: 29.1; eglot performance issue

[João Távora]

On Tue, Sep 5, 2023 at 5:59 PM Axel Forsman <axel@axelf.se> wrote:
>
> I disagree with the initial decision to log all JSONRPC events
> by default to begin with, but irregardless,

I'll change the default if you volunteer to share half
the work of answering and debugging bug reports that contain
nothing but screenshots and minimal information with me for
the next year.  Deal?

> should it not be possible to fix the performance issues by
> having jsonrpc--log-event push raw events onto a ring,
> and introducing a second function that
> formats the raw events as strings
> and inserts them into a new buffer that gets displayed.
> That way the expensive pretty printing would be deferred
> to until the events are actually viewed.

Fantastic idea if you can make it work.  You might be able
to use window-configuration-change-hook or something like that.
Anyway, await your patches eagerly, but there can't be any
interface changes M-x eglot-events-buffer and switch to buffer
must work as before.

João

bug#65760: 29.1; eglot performance issue

[Ivan Sokolov]

[-- Attachment #1: Type: text/plain, Size: 1915 bytes --]

Eli Zaretskii <eliz@gnu.org> writes:

>> Cc: 65760@debbugs.gnu.org
>> From: Ivan Sokolov <ivan-p-sokolov@ya.ru>
>> Date: Tue, 05 Sep 2023 18:55:23 +0300
>> 
>> Глеб Смирнов <glebsmirnov0708@gmail.com> writes:
>> 
>> > The problem is that running eglot with rust-analyzer on my project
>> > causes major input lag. Profiling shows that the problem is in
>> > synchronous and slow function jsonrpc--log-event that is called on each
>> > server request or response. Disabling this function with (advice-add
>> > 'jsonrpc--log-event :override #'ignore) solves the problem.
>> 
>> To be more precise the problem is that jsonrpc--log-event is pretty
>> printing every reply from the server and they can be quite large and
>> nested.  I am attaching Gleb's profiler report, as a screenshot, but
>> this should be enough to give a better understanding of the problem.
>
> Yes, the real CPU eater is pp-buffer.
>
> But I also see that jsonrpc-request took a substantial amount of CPU
> time, and since jsonrpc-request runs from a timer, it is a good
> candidate for explaining a perceived lag.

Before disabling jsonrpc--log-event, it accounted for most of the
execution time of jsonrpc-request.  After disabling jsonrpc--log-event
jsonrpc-request took much less CPU, on par with command-execute, see the
attachment.

> Can you tell if this profile was in an Emacs build with built-in JSON
> support, or was Emacs using the Lisp implementation on json.el?

I think JSON in the list below signifies built-in JSON support:

Глеб Смирнов <glebsmirnov0708@gmail.com> writes:

> Configured features:
> CAIRO DBUS FREETYPE GIF GLIB GMP GNUTLS GPM GSETTINGS HARFBUZZ JPEG JSON
> LIBSELINUX LIBSYSTEMD LIBXML2 MODULES NATIVE_COMP NOTIFY INOTIFY PDUMPER
> PGTK PNG RSVG SECCOMP SOUND SQLITE3 THREADS TIFF TOOLKIT_SCROLL_BARS
> TREE_SITTER WEBP XIM XWIDGETS GTK3 ZLIB


[-- Attachment #2: profiler report with advice --]
[-- Type: image/jpeg, Size: 70661 bytes --]