Subject: bug#41200: Displaying a tooltip with x-show-tip gets very slow as more faces are defined

From: Clément Pit-Claudel <[email-masked]>
Date: Tue, 12 May 2020 00:30:23 -0400

Hi all,

I've recently noticed that opening a tooltip on my machine takes about 0.5s when x-gtk-use-system-tooltips is set to nil.
I bisected my config, and… nothing.  It's not one package: instead, it's an accumulation of small slowdowns.
Is seems that defining a face makes x-show-tip a tiny bit slower, but these effects stack.

Here is a repro:

  (defun my-def-many-faces (nfaces)
    (dotimes (i nfaces)
      (custom-declare-face
       (intern (format "my-face-%d" i))
       '((t)) "A face."
       :group 'basic-faces)))

  (defun my-bench-x-tip (nfaces)
    (setq x-gtk-use-system-tooltips nil)
    (my-def-many-faces nfaces)
    (benchmark-run 1 (x-show-tip "Test" (selected-frame) nil 5 nil nil)))

  (my-bench-x-tip 100) ;; ⇒ (0.035934318 1 0.015908304000000012)
  (my-bench-x-tip 200) ;; ⇒ (0.049593474 1 0.01508625500000002)
  (my-bench-x-tip 300) ;; ⇒ (0.094929297 2 0.03376510099999999)
  (my-bench-x-tip 400) ;; ⇒ (0.094900665 2 0.03254889999999999)
  (my-bench-x-tip 500) ;; ⇒ (0.118183442 2 0.03218763600000002)
  (my-bench-x-tip 600) ;; ⇒ (0.154759438 3 0.04923829399999996)
  (my-bench-x-tip 700) ;; ⇒ (0.183241646 3 0.04901039700000004)
  (my-bench-x-tip 800) ;; ⇒ (0.212218872 3 0.050182316999999976)
  (my-bench-x-tip 900) ;; ⇒ (0.248743542 3 0.04915146899999995)
  (my-bench-x-tip 1000) ;; ⇒ (0.29221963 3 0.04943874300000006)
  (my-bench-x-tip 1100) ;; ⇒ (0.334084605 3 0.05403986499999991)
  (my-bench-x-tip 1200) ;; ⇒ (0.397292289 4 0.06869684599999992)
  (my-bench-x-tip 1300) ;; ⇒ (0.442873256 4 0.06865671799999995)
  (my-bench-x-tip 1400) ;; ⇒ (0.492474982 4 0.06888139900000001)
  (my-bench-x-tip 1500) ;; ⇒ (0.579180262 5 0.08583425400000011)
  (my-bench-x-tip 1600) ;; ⇒ (0.63504114 5 0.08973981699999989)
  (my-bench-x-tip 1700) ;; ⇒ (0.723722857 5 0.09094433899999999)
  (my-bench-x-tip 1800) ;; ⇒ (0.791952279 5 0.08777533800000015)
  (my-bench-x-tip 1900) ;; ⇒ (0.902377982 6 0.10768666300000018)
  (my-bench-x-tip 2000) ;; ⇒ (0.998815784 6 0.11384837999999986)

Be sure to run it in emacs -q, not emacs -Q, because emacs -Q ignores X resources and hence skips the body of make-face-x-resource-internal, which contributes greatly to the issue.
For some reasons the effects are a bit worse in my config — roughly a factor 3 to 5 (I have 600 faces defined, and each tooltip takes .5s to display).  The profiles below suggest that face-spec-set-2 is called in my config, but not in my repro, which could explain part of the difference.

This is what the profile in emacs -q looks like:

- command-execute                                                1742  97%
 - call-interactively                                            1742  97%
  - funcall-interactively                                        1720  96%
   - eval-defun                                                  1711  95%
    - elisp--eval-defun                                          1711  95%
     - eval-region                                               1711  95%
      - let                                                      1711  95%
       - list                                                    1711  95%
        - let                                                    1711  95%
         - x-show-tip                                            1708  95%
          - face-set-after-frame-default                         1708  95%
           - face-spec-recalc                                    1654  92%
            - make-face-x-resource-internal                      1414  78%
             - set-face-attributes-from-resources                1413  78%
              - set-face-attribute-from-resource                 1394  77%
               - face-name                                       1353  75%
                - check-face                                     1348  75%
                   facep                                         1344  75%
            - face-spec-reset-face                                239  13%
             - apply                                              239  13%
                set-face-attribute                                234  13%

And this is what it looks like in my config:

- command-execute                                                1423  87%
 - call-interactively                                            1423  87%
  - apply                                                        1423  87%
   - call-interactively@ido-cr+-record-current-command               1423  87%
    - apply                                                      1423  87%
     - #<subr call-interactively>                                1423  87%
      - funcall-interactively                                    1423  87%
       - eval-defun                                              1345  83%
        - apply                                                  1345  83%
         - #<compiled 0x1fa5d1dc39debc9e>                        1345  83%
          - elisp--eval-defun                                    1345  83%
           - eval-region                                         1344  83%
            - apply                                              1344  83%
             - #<lambda -0x120930d847119138>                     1344  83%
              - endless/eval-overlay                             1344  83%
               - apply                                           1343  83%
                - #<subr eval-region>                            1343  83%
                 - my-bench-x-tip                                1343  83%
                  - let                                          1280  79%
                   - list                                        1280  79%
                    - let                                        1280  79%
                     - x-show-tip                                1277  78%
                      - face-set-after-frame-default               1277  78%
                       - face-spec-recalc                        1218  75%
                        - face-spec-set-2                         673  41%
                         - apply                                  672  41%
                          - set-face-attribute                    671  41%
                           - internal-set-lisp-face-attribute                669  41%
                            - frame-set-background-mode                651  40%
                             - face-spec-recalc                   411  25%
                              - make-face-x-resource-internal                352  21%
                               - set-face-attributes-from-resources                350  21%
                                - set-face-attribute-from-resource                343  21%
                                 - face-name                      312  19%
                                  - check-face                    309  19%
                                     facep                        308  19%
                              + face-spec-reset-face                 56   3%
                                face-spec-choose                    1   0%
                              + face-spec-set-2                     1   0%
                             - face-attr-match-p                  235  14%
                                face-attribute                    235  14%
                        - make-face-x-resource-internal                321  19%
                         - set-face-attributes-from-resources                320  19%
                          - set-face-attribute-from-resource                316  19%
                           - face-name                            296  18%
                            - check-face                          294  18%
                               facep                              293  18%
                        - face-spec-reset-face                    223  13%
                         - apply                                  223  13%
                            set-face-attribute                    219  13%
                  + my-def-many-faces                              63   3%
               + cider--make-result-overlay                         1   0%
           + end-of-defun                                           1   0%
       + smex                                                      78   4%
+ ...                                                             188  11%
+ timer-event-handler                                               4   0%
+ redisplay_internal (C function)                                   2   0%
+ flyspell-post-command-hook                                        1   0%

I've attached both profiles.

Clément.

Configured using:
 'configure -C'

Configured features:
XPM JPEG TIFF GIF PNG RSVG CAIRO SOUND GPM DBUS GSETTINGS GLIB NOTIFY
INOTIFY ACL LIBSELINUX GNUTLS LIBXML2 FREETYPE HARFBUZZ M17N_FLT LIBOTF
ZLIB TOOLKIT_SCROLL_BARS GTK3 X11 XDBE XIM MODULES THREADS LIBSYSTEMD
JSON PDUMPER LCMS2 GMP

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

Major mode: Fundamental

Minor modes in effect:
  tooltip-mode: t
  global-eldoc-mode: t
  electric-indent-mode: t
  mouse-wheel-mode: t
  tool-bar-mode: t
  menu-bar-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  blink-cursor-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  buffer-read-only: t
  line-number-mode: t
  transient-mark-mode: t

Load-path shadows:
None found.

Features:
(shadow sort mail-extr emacsbug message rmc puny dired dired-loaddefs
format-spec rfc822 mml easymenu mml-sec password-cache epa derived epg
epg-config gnus-util rmail rmail-loaddefs text-property-search time-date
subr-x seq byte-opt gv bytecomp byte-compile cconv mm-decode mm-bodies
mm-encode mail-parse rfc2231 mailabbrev gmm-utils mailheader cl-loaddefs
cl-lib sendmail rfc2047 rfc2045 ietf-drums mm-util mail-prsvr mail-utils
tooltip eldoc electric uniquify ediff-hook vc-hooks lisp-float-type
mwheel term/x-win x-win term/common-win x-dnd tool-bar dnd fontset image
regexp-opt fringe tabulated-list replace newcomment text-mode elisp-mode
lisp-mode prog-mode register page tab-bar menu-bar rfn-eshadow isearch
timer select scroll-bar mouse jit-lock font-lock syntax facemenu
font-core term/tty-colors frame minibuffer cl-generic 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 charscript charprop
case-table epa-hook jka-cmpr-hook help simple abbrev obarray
cl-preloaded nadvice loaddefs button faces cus-face macroexp files
text-properties overlay sha1 md5 base64 format env code-pages mule
custom widget hashtable-print-readable backquote threads dbusbind
inotify lcms2 dynamic-setting system-font-setting font-render-setting
cairo move-toolbar gtk x-toolkit x multi-tty make-network-process emacs)

Memory information:
((conses 16 48162 5363)
 (symbols 48 6344 1)
 (strings 32 15896 1092)
 (string-bytes 1 517314)
 (vectors 16 10213)
 (vector-slots 8 140571 9444)
 (floats 8 19 41)
 (intervals 56 230 7)
 (buffers 992 11))