使用 strace 查找 Emacs 啟動阻塞的原因

之前就覺得我的 Emacs 啟動好慢，查看啟動日誌會發現啟動到一般的時候會有一個比較長時間的卡頓。 之前一直沒有理會它，今天花了點時間探索了一下，發現罪魁禍首居然是 exec-path-from-shell 這個包。

現將探索的過程記錄如下： 由於使用了 spacemacs 的配置，配置上比較複雜，不太想通過實驗縮減配置的方式來摸索出問題的地方。剛好最近在學習使用 strace 工具，因此決定使用 strace 來看看 Emacs 到底卡在哪裡。

strace emacs --fg-daemon

輸出的內容特別多，這裡只截取卡頓前的部分內容

readlinkat(AT_FDCWD, "/home", 0x7ffd1d3abb50, 1024) = -1 EINVAL (無效的參數)
readlinkat(AT_FDCWD, "/home/lujun9972", 0x7ffd1d3abf00, 1024) = -1 EINVAL (無效的參數)
readlinkat(AT_FDCWD, "/home/lujun9972/.emacs.d", 0x7ffd1d3ac2b0, 1024) = -1 EINVAL (無效的參數)
readlinkat(AT_FDCWD, "/home/lujun9972/.emacs.d/elpa", 0x7ffd1d3ac660, 1024) = -1 EINVAL (無效的參數)
readlinkat(AT_FDCWD, "/home/lujun9972/.emacs.d/elpa/exec-path-from-shell-20180323.1904", 0x7ffd1d3aca10, 1024) = -1 EINVAL (無效的參數)
readlinkat(AT_FDCWD, "/home/lujun9972/.emacs.d/elpa/exec-path-from-shell-20180323.1904/exec-path-from-shell.elc", 0x7ffd1d3acdc0, 1024) = -1 EINVAL (無效的參數)
lseek(7, -2655, SEEK_CUR)               = 1441
read(7, "n(defvar exec-path-from-shell-de"..., 4096) = 4096
lseek(7, 5537, SEEK_SET)                = 5537
lseek(7, 5537, SEEK_SET)                = 5537
lseek(7, 5537, SEEK_SET)                = 5537
lseek(7, 5537, SEEK_SET)                = 5537
lseek(7, 5537, SEEK_SET)                = 5537
lseek(7, 5537, SEEK_SET)                = 5537
brk(0x7507000)                          = 0x7507000
lseek(7, 5537, SEEK_SET)                = 5537
lseek(7, 5537, SEEK_SET)                = 5537
lseek(7, 5537, SEEK_SET)                = 5537
read(7, "230\20526t22\307\310t!vC\"\21124\2"..., 4096) = 2430
lseek(7, 7967, SEEK_SET)                = 7967
lseek(7, 7967, SEEK_SET)                = 7967
lseek(7, 7967, SEEK_SET)                = 7967
lseek(7, 7967, SEEK_SET)                = 7967
read(7, "", 4096)                       = 0
close(7)                                = 0
getpid()                                = 10818
faccessat(AT_FDCWD, "/home/lujun9972/bin/printf", X_OK) = -1 ENOENT (沒有那個文件或目錄)
faccessat(AT_FDCWD, "/usr/local/sbin/printf", X_OK) = -1 ENOENT (沒有那個文件或目錄)
faccessat(AT_FDCWD, "/usr/local/bin/printf", X_OK) = -1 ENOENT (沒有那個文件或目錄)
faccessat(AT_FDCWD, "/usr/bin/printf", X_OK) = 0
stat("/usr/bin/printf", {st_mode=S_IFREG|0755, st_size=51176, ...}) = 0
openat(AT_FDCWD, "/dev/null", O_RDONLY|O_CLOEXEC) = 7
faccessat(AT_FDCWD, "/proc/5070/fd/.", F_OK) = 0
faccessat(AT_FDCWD, "/proc/5070/fd/.", F_OK) = 0
faccessat(AT_FDCWD, "/bin/bash", X_OK)  = 0
stat("/bin/bash", {st_mode=S_IFREG|0755, st_size=903440, ...}) = 0
pipe2([8, 9], O_CLOEXEC)                = 0
rt_sigprocmask(SIG_BLOCK, [INT CHLD], [], 8) = 0
vfork()                                 = 10949
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
close(9)                                = 0
close(7)                                = 0
read(8, "bash: 346227240346263225350256276345256232347273210347253257350277233347250213347273"..., 16384) = 74
read(8, "bash: 346255244 shell 344270255346227240344273273345212241346216247345"..., 16310) = 35
read(8, "setterm: 347273210347253257 xterm-256color 344"..., 16275) = 51
read(8, "Couldn't get a file descriptor r"..., 16224) = 56
read(8, "bash: [: 357274232351234200350246201346225264346225260350241250350276276345274"..., 16168) = 34
read(8, "Your display number is 0n", 16134) = 25
read(8, "Test whether fcitx is running co"..., 16109) = 53
read(8, "Fcitx is running correctly.nn==="..., 16056) = 87
read(8, "Launch fbterm...n", 15969)    = 17
read(8, "stdin isn't a tty!n", 15952)  = 19
read(8, "__RESULT/home/lujun9972/bin:/ho"..., 15933) = 298
read(8, 0x7ffd1d39ce9d, 15635)          = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=10949, si_uid=1000, si_status=0, si_utime=10, si_stime=7} rt_sigreturn({mask=[]})                 = -1 EINTR (被中斷的系統調用)
read(8, "", 15635)                      = 0
wait4(10949, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 10949
close(8)                                = 0
getpid()                                = 10818
faccessat(AT_FDCWD, "/home/lujun9972/bin/printf", X_OK) = -1 ENOENT (沒有那個文件或目錄)
faccessat(AT_FDCWD, "/usr/local/sbin/printf", X_OK) = -1 ENOENT (沒有那個文件或目錄)
faccessat(AT_FDCWD, "/usr/local/bin/printf", X_OK) = -1 ENOENT (沒有那個文件或目錄)
faccessat(AT_FDCWD, "/usr/bin/printf", X_OK) = 0
stat("/usr/bin/printf", {st_mode=S_IFREG|0755, st_size=51176, ...}) = 0
openat(AT_FDCWD, "/dev/null", O_RDONLY|O_CLOEXEC) = 7
faccessat(AT_FDCWD, "/proc/5070/fd/.", F_OK) = 0
faccessat(AT_FDCWD, "/proc/5070/fd/.", F_OK) = 0
faccessat(AT_FDCWD, "/bin/bash", X_OK)  = 0
stat("/bin/bash", {st_mode=S_IFREG|0755, st_size=903440, ...}) = 0
pipe2([8, 9], O_CLOEXEC)                = 0
rt_sigprocmask(SIG_BLOCK, [INT CHLD], [], 8) = 0
vfork()                                 = 11679
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
close(9)                                = 0
close(7)                                = 0
read(8, "setterm: 347273210347253257 xterm-256color 344"..., 16384) = 51
read(8, "Couldn't get a file descriptor r"..., 16333) = 56
read(8, "/home/lujun9972/.bash_profile: 347"..., 16277) = 72
read(8, "Your display number is 0nTest wh"..., 16205) = 78
read(8, "Fcitx is running correctly.nn==="..., 16127) = 104
read(8, "stdin isn't a tty!n", 16023)  = 19
read(8, "__RESULTb269cd09e7ec4e8a115188c"..., 16004) = 298
read(8, 0x7ffd1d39cba6, 15706)          = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=11679, si_uid=1000, si_status=0, si_utime=1, si_stime=1} rt_sigreturn({mask=[]})                 = -1 EINTR (被中斷的系統調用)
read(8, 

很容易就可以看出，當 Emacs 卡頓時，它在嘗試從 8 號文件句柄中讀取內容。

那麼 8 號文件句柄在哪裡定義的呢？往前看可以看到：

pipe2([8, 9], O_CLOEXEC)                = 0
rt_sigprocmask(SIG_BLOCK, [INT CHLD], [], 8) = 0
vfork()                                 = 11679
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
close(9)                                = 0

可以推測出，Emacs 主進程 fork 出一個子進程（進程號為 11679），並通過管道讀取子進程的內容。

然而，從

--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=11679, si_uid=1000, si_status=0, si_utime=1, si_stime=1} rt_sigreturn({mask=[]})                 = -1 EINTR (被中斷的系統調用)
read(8, 

可以看出，實際上子進程已經退出了（父進程收到 SIGCHLD 信號），父進程確依然在嘗試從管道中讀取內容，導致的阻塞。

而且從

read(8, "setterm: 347273210347253257 xterm-256color 344"..., 16384) = 51
read(8, "Couldn't get a file descriptor r"..., 16333) = 56
read(8, "/home/lujun9972/.bash_profile: 347"..., 16277) = 72
read(8, "Your display number is 0nTest wh"..., 16205) = 78
read(8, "Fcitx is running correctly.nn==="..., 16127) = 104
read(8, "stdin isn't a tty!n", 16023)  = 19
read(8, "__RESULTb269cd09e7ec4e8a115188c"..., 16004) = 298
read(8, 0x7ffd1d39cba6, 15706)          = ? ERESTARTSYS (To be restarted if SA_RESTART is set)

看到，子進程的輸出似乎是我的互動式登錄 bash 啟動時的輸出（載入了 .bash_profile）

在往前翻發現這麼一段信息：

readlinkat(AT_FDCWD, "/home", 0x7ffd1d3abb50, 1024) = -1 EINVAL (無效的參數)
readlinkat(AT_FDCWD, "/home/lujun9972", 0x7ffd1d3abf00, 1024) = -1 EINVAL (無效的參數)
readlinkat(AT_FDCWD, "/home/lujun9972/.emacs.d", 0x7ffd1d3ac2b0, 1024) = -1 EINVAL (無效的參數)
readlinkat(AT_FDCWD, "/home/lujun9972/.emacs.d/elpa", 0x7ffd1d3ac660, 1024) = -1 EINVAL (無效的參數)
readlinkat(AT_FDCWD, "/home/lujun9972/.emacs.d/elpa/exec-path-from-shell-20180323.1904", 0x7ffd1d3aca10, 1024) = -1 EINVAL (無效的參數)
readlinkat(AT_FDCWD, "/home/lujun9972/.emacs.d/elpa/exec-path-from-shell-20180323.1904/exec-path-from-shell.elc", 0x7ffd1d3acdc0, 1024) = -1 EINVAL (無效的參數)
lseek(7, -2655, SEEK_CUR)               = 1441
read(7, "n(defvar exec-path-from-shell-de"..., 4096) = 4096

這很明顯是跟 exec-path-from-shell 有關啊。

通過查看 exec-path-from-shell 的實現，發現 exec-path-from-shell 的實現原理是通過實際調啟一個 shell，然後輸出 PATH 和 MANPATH 的值的。 而且對於 bash 來說，默認的啟動參數為 -i -l（可以通過exec-path-from-shell-arguments來設置）。也就是說 bash 會作為互動式的登錄shell來啟動的，因此會載入 .bash_profile 和 .bashrc。

既然發現跟 exec-path-from-shell 這個包有關，而且據說這個包對 Linux 其實意義不大，那不如直接禁用掉好了。

dotspacemacs-excluded-packages '(exec-path-from-shell)

再次重啟Emacs，發現這次啟動速度明顯快了許多了。

本文轉載來自 Linux 中國: https://github.com/Linux-CN/archive