从系统层面分析Emacs的启动性能

之前看到 关于load-path增多对emacs运行速度的重大影响 这个帖子里使用了系统监测工具procmon对Emacs性能进行测试,而且得到了有力的结论(我一开始还不信呢)。今天学着用这个思路来分析一下Linux上Emacs的启动性能。配置是我的koishimacs。

运行strace -C -o strace-summary.log emacs -nw,启动emacs后退出,得到syscall summary如下:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 87.67    0.455477           2    159813    155809 openat
  4.49    0.023314        5828         4           wait4
  2.08    0.010793           6      1752           mmap
  1.15    0.005955           1      4394      3306 faccessat2
  1.11    0.005746           2      2346           read
  0.92    0.004758           1      4018           close
  0.59    0.003055           2      1234      1233 readlink
  0.53    0.002743           1      1494           fstat
  0.48    0.002487           4       517           brk
  0.30    0.001561           1      1171      1070 ioctl
  0.28    0.001463           3       379           mprotect
  0.12    0.000604         604         1           execve
  0.10    0.000504           1       320           fcntl
  0.06    0.000324           1       316           lseek
  0.04    0.000205           8        25        21 rt_sigreturn
  0.03    0.000164           6        27           munmap
  0.03    0.000155           4        32           getdents64
  0.01    0.000042          10         4           clone3
  0.01    0.000035           0        88           rt_sigprocmask
  0.01    0.000028           0        43           write
  0.00    0.000023           0        28           prlimit64
  0.00    0.000019           3         6           unlink
  0.00    0.000019           0        21         4 newfstatat
  0.00    0.000017           4         4         3 access
  0.00    0.000016           2         7           pipe2
  0.00    0.000013           1         9           pread64
  0.00    0.000013           0        20        14 readlinkat
  0.00    0.000005           1         4           setpgid
  0.00    0.000004           0        16           getpid
  0.00    0.000002           0        13           uname
  0.00    0.000001           1         1           arch_prctl
  0.00    0.000001           1         1           set_tid_address
  0.00    0.000001           1         1           set_robust_list
  0.00    0.000001           1         1           rseq
  0.00    0.000000           0        40           rt_sigaction
  0.00    0.000000           0         3           dup2
  0.00    0.000000           0        41           alarm
  0.00    0.000000           0         3         3 mkdir
  0.00    0.000000           0         4           symlink
  0.00    0.000000           0         2           umask
  0.00    0.000000           0         4           getuid
  0.00    0.000000           0         1           getgid
  0.00    0.000000           0         3           geteuid
  0.00    0.000000           0         1           getegid
  0.00    0.000000           0         2           getpgrp
  0.00    0.000000           0         2           setfsuid
  0.00    0.000000           0         2           setfsgid
  0.00    0.000000           0         1           sigaltstack
  0.00    0.000000           0         6         4 prctl
  0.00    0.000000           0         1           gettid
  0.00    0.000000           0         8           futex
  0.00    0.000000           0         1           timer_create
  0.00    0.000000           0        21           timer_settime
  0.00    0.000000           0         2           fchmodat
  0.00    0.000000           0         8         1 pselect6
  0.00    0.000000           0        11           ppoll
  0.00    0.000000           0         1           timerfd_create
  0.00    0.000000           0        21           timerfd_settime
  0.00    0.000000           0         1           eventfd2
  0.00    0.000000           0         3           getrandom
  0.00    0.000000           0         1           pidfd_open
------ ----------- ----------- --------- --------- ----------------
100.00    0.519548           2    178304    161468 total

高得离谱的openat调用,失败率达到了惊人的97%。Emacs的load函数使用openat而不是stat判断文件是否可以访问,在注释中有解释:stat可能产生整数宽度错误(它可能返回32位或64位对齐的数据,没有有效的宽度判断方法)。不过对于Linux的实现,它的开销应该不超过stat。问题是,为什么会有这么多的失败?我想这和之前 @junmoxiao 那个帖子里提到的load-path产生的性能问题是一样的。

于是我们对openat调用进行进一步的分析,运行strace -e trace=openat -o strace-openat.log emacs -nw,同样在启动后退出。得到所有的openat调用,分析这份数据:

  1. Emacs 会依次尝试列表 load-suffix 中的后缀。 这会让 load 的开销乘上一个固定倍数(对我来说是 6 倍)。

  2. Emacs 会在 load-path 的每个路径中,以该列表顺序尝试所有可能的子路径来寻找需要加载的文件,来查找由 require 加载的文件。这会带来非常大的额外开销(倍数྾你的 load-path 对应的文件树森林的结点总个数,对我来说,这个倍数达到了10²数量级)。Emacs主线已经有人针对此问题提了补丁。此外,在更早的版本上想要压缩这部分成本,还有两种“软”方式:

    1. 在使用 require 时显式指定路径名(chenbin的做法)。
    2. 尽可能对load-path进行剪枝,因为搜索会按顺序遍历整个 load-path(lazycat的做法)。

    但是在之前的讨论里里,我们分析了,这种优化影响不到内置包,造成卡顿的其实是这些内置包在启动后的一股脑的加载,比如cl-lib。第三方包的惰性加载反而加剧了内置包的require开销。

  3. Emacs 会在每个已安装的软件包中搜索 info.* 文件,这些文件可能包含软件包文档。该变量由Info-directory-list控制,与前两项相比,这部分的影响不大。

对于之前讨论的问题,看起来include-yy已经在他的blog里整理了一份纪要。总之,看起来我只要坐等emacs31发布就行了,windows用户要考虑的就很多了 :laughing:

11 个赞

Windows User 吃的苦你不懂 :smiling_face_with_sunglasses:

这个的具体位置是?我好像没有注意到.

1 个赞

:grin: 不只是启动, 还有其他场景一样会有这个问题, 只是其他场景不像启动的时候要一次性加载这么多.

感觉pdump才是这个问题最好的解决方式, 之前也谈过, 我们用的emacs只是elisp解释器执行了初始化代码后的产物, 本身在emacs构建的过程中, 在编译出elisp解释器后就会执行elisp代码, 最后把执行状态dump成最终的dump文件.

我们的配置如果不改动, 完全可以去掉延迟加载, 把初始化代码都执行一遍, 再dump下来, 下次打开emacs就直接处于这个状态. 只是pdump配置起来有点麻烦

上次有个老哥发的链接挺好的, 有空配置下试试

https://github.com/Master-Hash/.emacs.d/blob/master/dump.el
https://archive.casouri.cc/note/2020/painless-transition-to-portable-dumper/
1 个赞

普通用户减少不必要的包+合理配置延迟启动+native-comp可以将启动速度缩减到完全可以接受的程度,比如这是我的:

Emacs is ready with 60 installed packages, called 1 garbage collection and took 0.99s.

但我现在还是习惯用 Emacs client,倒不是因为 client 拉起 daemon 更快,主要是同一个 Emacs daemon 的话就可以在最近 buffer 列表里看到打开的其他项目的 buffer,而直接用 Emacs 的话进程退出 buffer 就都关掉了,再打开新的进程就没有 buffer。

不过能从 Emacs 本身提高加载速度还是很让人期待的。

现在emacs-31分支已经进入了freezing阶段,除了重大bug修复,新的改动不会再添加到emacs-31分支中。于是,最近我把我的emacs构建更新到了emacs-31分支上。

我实现了一个简单的load-path-filter-function,发现整体启动速度提升了约0.1s(提升并没有期待的那么高,但比较符合strace测出来的数据),openat的命中率提高到了1/3(主要是suffixes不支持过滤造成的),调用次数也下降了20多倍(这次我起的是GUI,会加载比TUI启动更多的包)。

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- -------------------
 23.84    0.020608           0     23350           rt_sigprocmask
 12.80    0.011070           0     11248           timerfd_settime
 12.47    0.010783           0     11248           timer_settime
 11.19    0.009674           5      1865           mmap
  9.59    0.008289           0     22616     21688 faccessat2
  8.08    0.006987          99        70           munmap
  6.61    0.005712           0      6211      4696 openat
  3.44    0.002973           0      3326         1 read
  2.60    0.002246         449         5           wait4
  1.66    0.001431           0      1564           close
  1.56    0.001353           0      1598           fstat
  0.98    0.000846           5       166           ppoll
  0.53    0.000457           0       904           lseek
  0.49    0.000421           2       200           write
  0.47    0.000410           0       504           rt_sigaction
  0.47    0.000403           0       756        73 futex
  0.37    0.000320          35         9           fallocate
  0.36    0.000314           0       391           mprotect
  0.35    0.000303           0      1013      1010 readlink
  0.33    0.000287          14        20           pselect6
  0.29    0.000247           0       405           brk
  0.19    0.000162           2        59           sendmsg
  0.18    0.000155           8        19           memfd_create
  0.16    0.000141           0       328           fcntl
  0.15    0.000128           1        78           alarm
  0.15    0.000128           3        36           getdents64
  0.15    0.000127           2        45         2 rt_sigreturn
  0.14    0.000117           1        74        37 recvmsg
  0.07    0.000062           3        18           ftruncate
  0.06    0.000049           0        81        10 newfstatat
  0.05    0.000041           3        11           pread64
  0.04    0.000034           0       226       185 access
  0.03    0.000027           9         3           symlink
  0.03    0.000027           3         7           tgkill
  0.02    0.000020           0        21           getpid
  0.02    0.000019           4         4           unlink
  0.02    0.000017           1         9           clone3
  0.01    0.000012           1        10           gettid
  0.01    0.000009           0        13           uname
  0.01    0.000005           2         2           fchmodat
  0.00    0.000004           0        15           poll
  0.00    0.000004           0         5         1 readlinkat
  0.00    0.000003           0         8           sendto
  0.00    0.000003           3         1           arch_prctl
  0.00    0.000003           1         3           getrandom
  0.00    0.000003           3         1           rseq
  0.00    0.000002           0         3           socket
  0.00    0.000002           0         3           connect
  0.00    0.000002           2         1           statfs
  0.00    0.000002           2         1           set_tid_address
  0.00    0.000002           2         1           set_robust_list
  0.00    0.000002           0        34           prlimit64
  0.00    0.000001           1         1           ioctl
  0.00    0.000001           1         1           pwrite64
  0.00    0.000001           0         4           madvise
  0.00    0.000001           0         2         2 mkdir
  0.00    0.000001           0         3           geteuid
  0.00    0.000001           1         1           sched_getaffinity
  0.00    0.000001           1         1           inotify_add_watch
  0.00    0.000001           0         4           eventfd2
  0.00    0.000001           1         1           inotify_init1
  0.00    0.000001           0         9           statx
  0.00    0.000000           0         3           dup2
  0.00    0.000000           0         2           getsockname
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         2           umask
  0.00    0.000000           0         3           getuid
  0.00    0.000000           0         1           getgid
  0.00    0.000000           0         1           getegid
  0.00    0.000000           0         1           getpgrp
  0.00    0.000000           0         2           getresuid
  0.00    0.000000           0         2           getresgid
  0.00    0.000000           0         1           sigaltstack
  0.00    0.000000           0         1           sched_getscheduler
  0.00    0.000000           0         1           timer_create
  0.00    0.000000           0         1           timerfd_create
  0.00    0.000000           0         5           pipe2
  0.00    0.000000           0         1           pidfd_open
------ ----------- ----------- --------- --------- -------------------
100.00    0.086456           0     88644     27705 total

让我觉得不舒服的地方是load-path-filter这个功能无法根据load的结果进行动态训练更新cache。目前我的策略是在load-path-filter-function里面提前查找文件的方式训练cache,validation会产生overhead。动态训练和静态生成cache相比不需要反复生成cache,你用的越多它就越聪明。如果你的cache文件因为意外(比如写回时发生故障)损坏了,手动把它删掉就可以了,下次启动时,只要保持my/lpf--cache-training开启,它就会开始从头重练。

以下是我的简易lpf实现,该实现没有使用任何库函数,因此你可以把它放在early-init.el中。startup.el中实现的load-path-filter-cache-directory-files要等到它加载之后才开始起作用,这会错过前面的很多优化点,毕竟load从一开始就在被调用了。

;; setup load-path filter
(defvar my/lpf--cache-file
  (file-name-concat user-emacs-directory "load-path-filter-cache.el"))

(defvar my/lpf--cache
  (if (file-readable-p my/lpf--cache-file)
      (with-temp-buffer
        (insert-file-contents my/lpf--cache-file)
        (goto-char 0)
        (condition-case nil
            (read (current-buffer))
          (error (make-hash-table :test #'equal))))
    (make-hash-table :test #'equal))
  "A cache used by function `my:lpf', which is a hash table whose each entry
is a FILE name, and value is filtered PATH.")

;; save cache when exit emacs
(add-hook 'kill-emacs-hook
          #'(lambda ()
              (with-temp-file my/lpf--cache-file
                (insert (prin1-to-string my/lpf--cache)))))

(defvar my/lpf--cache-training t
  "If this is non-nil, start training when my/lpf--cache missed.")

(defvar my/lpf--cache-validate t
  "If this is non-nil, validate each entry found in cache before load.
If invalid, erase it from the cache.")

(defun my:lpf-match (path file suffixes)
  (catch 'found
    (dolist (x (mapcar #'(lambda (suf) (concat file suf)) suffixes))
      (if-let* ((res (mapcan #'(lambda (p)
                                 (when (file-readable-p (file-name-concat p x))
                                   (list p)))
                             path)))
          (throw 'found res)))))

(defun my:lpf-train (path file suffixes)
  (if (or (file-directory-p file)
          (not my/lpf--cache-training))
      path
    (when-let*
        ((val (my:lpf-match path file suffixes)))
      (puthash file val my/lpf--cache))))

(defun my:lpf (path file suffixes)
  (if-let* ((val (gethash file my/lpf--cache)))
      ;; cache hitted
      (progn
        (when (and my/lpf--cache-validate
                   (null (my:lpf-match val file suffixes)))
          (setq val (my:lpf-train path file suffixes)))
        ;; append val to the beginning of path, this ensures it works correctly
        ;; when there are dirty values that are not validated
        (append val path))
    ;; otherwise, start training, this may be painful when hit rate is low.
    (or (my:lpf-train path file suffixes)
        path)))

(setq load-path-filter-function #'my:lpf)

此外,我观察到strace日志中,仍然有一些无法过滤掉的load-path搜索情况,它们可能来自其它的函数调用。

7 个赞