使用 strace 查找 Emacs 启动阻塞的原因 | Linux 中国

Posted Linux中国

tags:

篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了使用 strace 查找 Emacs 启动阻塞的原因 | Linux 中国相关的知识，希望对你有一定的参考价值。

刚好最近在学习使用 strace 工具，因此决定使用 strace 来看看 Emacs 到底卡在哪里。
-- Darksun

作者：Darksun

之前就觉得我的 Emacs 启动好慢，查看启动日志会发现启动到一般的时候会有一个比较长时间的卡顿。之前一直没有理会它，今天花了点时间探索了一下，发现罪魁祸首居然是 exec-path-from-shell 这个包。

现将探索的过程记录如下：由于使用了 spacemacs 的配置，配置上比较复杂，不太想通过实验缩减配置的方式来摸索出问题的地方。刚好最近在学习使用  工具，因此决定使用  来看看 Emacs 到底卡在哪里。

  
    
    
  

   
     
     
   strace emacs --fg-daemon

输出的内容特别多，这里只截取卡顿前的部分内容

  
    
    
  
    
   
     
     
   
  1.  
    
     
     readlinkat(AT_FDCWD, "/home", 0x7ffd1d3abb50, 1024) = -1 EINVAL (无效的参数) 
    
    2. 
   
     
     
   
  2.  
    
     
     readlinkat(AT_FDCWD, "/home/lujun9972", 0x7ffd1d3abf00, 1024) = -1 EINVAL (无效的参数) 
    
    3. 
   
     
     
   
  3.  
    
     
     readlinkat(AT_FDCWD, "/home/lujun9972/.emacs.d", 0x7ffd1d3ac2b0, 1024) = -1 EINVAL (无效的参数) 
    
    4. 
   
     
     
   
  4.  
    
     
     readlinkat(AT_FDCWD, "/home/lujun9972/.emacs.d/elpa", 0x7ffd1d3ac660, 1024) = -1 EINVAL (无效的参数) 
    
    5. 
   
     
     
   
  5.  
    
     
     readlinkat(AT_FDCWD, "/home/lujun9972/.emacs.d/elpa/exec-path-from-shell-20180323.1904", 0x7ffd1d3aca10, 1024) = -1 EINVAL (无效的参数) 
    
    6. 
   
     
     
   
  6.  
    
     
     readlinkat(AT_FDCWD, "/home/lujun9972/.emacs.d/elpa/exec-path-from-shell-20180323.1904/exec-path-from-shell.elc", 0x7ffd1d3acdc0, 1024) = -1 EINVAL (无效的参数) 
    
    7. 
   
     
     
   
  7.  
    
     
     lseek(7, -2655, SEEK_CUR) = 1441 
    
    8. 
   
     
     
   
  8.  
    
     
     read(7, "\n(defvar exec-path-from-shell-de"..., 4096) = 4096 
    
    9. 
   
     
     
   
  9.  
    
     
     lseek(7, 5537, SEEK_SET) = 5537 
    
    10. 
   
     
     
   
  10.  
    
     
     lseek(7, 5537, SEEK_SET) = 5537 
    
    11. 
   
     
     
   
  11.  
    
     
     lseek(7, 5537, SEEK_SET) = 5537 
    
    12. 
   
     
     
   
  12.  
    
     
     lseek(7, 5537, SEEK_SET) = 5537 
    
    13. 
   
     
     
   
  13.  
    
     
     lseek(7, 5537, SEEK_SET) = 5537 
    
    14. 
   
     
     
   
  14.  
    
     
     lseek(7, 5537, SEEK_SET) = 5537 
    
    15. 
   
     
     
   
  15.  
    
     
     brk(0x7507000) = 0x7507000 
    
    16. 
   
     
     
   
  16.  
    
     
     lseek(7, 5537, SEEK_SET) = 5537 
    
    17. 
   
     
     
   
  17.  
    
     
     lseek(7, 5537, SEEK_SET) = 5537 
    
    18. 
   
     
     
   
  18.  
    
     
     lseek(7, 5537, SEEK_SET) = 5537 
    
    19. 
   
     
     
   
  19.  
    
     
     read(7, "230\\205\26\0\t\22\\307\\310\t!\vC\\\"\\211\24\\2"..., 4096) = 2430 
    
    20. 
   
     
     
   
  20.  
    
     
     lseek(7, 7967, SEEK_SET) = 7967 
    
    21. 
   
     
     
   
  21.  
    
     
     lseek(7, 7967, SEEK_SET) = 7967 
    
    22. 
   
     
     
   
  22.  
    
     
     lseek(7, 7967, SEEK_SET) = 7967 
    
    23. 
   
     
     
   
  23.  
    
     
     lseek(7, 7967, SEEK_SET) = 7967 
    
    24. 
   
     
     
   
  24.  
    
     
     read(7, "", 4096) = 0 
    
    25. 
   
     
     
   
  25.  
    
     
     close(7) = 0 
    
    26. 
   
     
     
   
  26.  
    
     
     getpid() = 10818 
    
    27. 
   
     
     
   
  27.  
    
     
     faccessat(AT_FDCWD, "/home/lujun9972/bin/printf", X_OK) = -1 ENOENT (没有那个文件或目录) 
    
    28. 
   
     
     
   
  28.  
    
     
     faccessat(AT_FDCWD, "/usr/local/sbin/printf", X_OK) = -1 ENOENT (没有那个文件或目录) 
    
    29. 
   
     
     
   
  29.  
    
     
     faccessat(AT_FDCWD, "/usr/local/bin/printf", X_OK) = -1 ENOENT (没有那个文件或目录) 
    
    30. 
   
     
     
   
  30.  
    
     
     faccessat(AT_FDCWD, "/usr/bin/printf", X_OK) = 0 
    
    31. 
   
     
     
   
  31.  
    
     
     stat("/usr/bin/printf", {st_mode=S_IFREG|0755, st_size=51176, ...}) = 0 
    
    32. 
   
     
     
   
  32.  
    
     
     openat(AT_FDCWD, "/dev/null", O_RDONLY|O_CLOEXEC) = 7 
    
    33. 
   
     
     
   
  33.  
    
     
     faccessat(AT_FDCWD, "/proc/5070/fd/.", F_OK) = 0 
    
    34. 
   
     
     
   
  34.  
    
     
     faccessat(AT_FDCWD, "/proc/5070/fd/.", F_OK) = 0 
    
    35. 
   
     
     
   
  35.  
    
     
     faccessat(AT_FDCWD, "/bin/bash", X_OK) = 0 
    
    36. 
   
     
     
   
  36.  
    
     
     stat("/bin/bash", {st_mode=S_IFREG|0755, st_size=903440, ...}) = 0 
    
    37. 
   
     
     
   
  37.  
    
     
     pipe2([8, 9], O_CLOEXEC) = 0 
    
    38. 
   
     
     
   
  38.  
    
     
     rt_sigprocmask(SIG_BLOCK, [INT CHLD], [], 8) = 0 
    
    39. 
   
     
     
   
  39.  
    
     
     vfork() = 10949 
    
    40. 
   
     
     
   
  40.  
    
     
     rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 
    
    41. 
   
     
     
   
  41.  
    
     
     close(9) = 0 
    
    42. 
   
     
     
   
  42.  
    
     
     close(7) = 0 
    
    43. 
   
     
     
   
  43.  
    
     
     read(8, "bash: \346\227\240\346\263\225\350\256\276\345\256\232\347\273\210\347\253\257\350\277\233\347\250\213\347\273"..., 16384) = 74 
    
    44. 
   
     
     
   
  44.  
    
     
     read(8, "bash: \346\255\244 shell \344\270\255\346\227\240\344\273\273\345\212\241\346\216\247\345"..., 16310) = 35 
    
    45. 
   
     
     
   
  45.  
    
     
     read(8, "setterm: \347\273\210\347\253\257 xterm-256color \344"..., 16275) = 51 
    
    46. 
   
     
     
   
  46.  
    
     
     read(8, "Couldn't get a file descriptor r"..., 16224) = 56 
    
    47. 
   
     
     
   
  47.  
    
     
     read(8, "bash: [: \357\274\232\351\234\200\350\246\201\346\225\264\346\225\260\350\241\250\350\276\276\345\274"..., 16168) = 34 
    
    48. 
   
     
     
   
  48.  
    
     
     read(8, "Your display number is 0\n", 16134) = 25 
    
    49. 
   
     
     
   
  49.  
    
     
     read(8, "Test whether fcitx is running co"..., 16109) = 53 
    
    50. 
   
     
     
   
  50.  
    
     
     read(8, "Fcitx is running correctly.\n\n==="..., 16056) = 87 
    
    51. 
   
     
     
   
  51.  
    
     
     read(8, "Launch fbterm...\n", 15969) = 17 
    
    52. 
   
     
     
   
  52.  
    
     
     read(8, "stdin isn't a tty!\n", 15952) = 19 
    
    53. 
   
     
     
   
  53.  
    
     
     read(8, "__RESULT\0/home/lujun9972/bin:/ho"..., 15933) = 298 
    
    54. 
   
     
     
   
  54.  
    
     
     read(8, 0x7ffd1d39ce9d, 15635) = ? ERESTARTSYS (To be restarted if SA_RESTART is set) 
    
    55. 
   
     
     
   
  55.  
    
     
     --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=10949, si_uid=1000, si_status=0, si_utime=10, si_stime=7} --- 
    
    56. 
   
     
     
   
  56.  
    
     
     rt_sigreturn({mask=[]}) = -1 EINTR (被中断的系统调用) 
    
    57. 
   
     
     
   
  57.  
    
     
     read(8, "", 15635) = 0 
    
    58. 
   
     
     
   
  58.  
    
     
     wait4(10949, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 10949 
    
    59. 
   
     
     
   
  59.  
    
     
     close(8) = 0 
    
    60. 
   
     
     
   
  60.  
    
     
     getpid() = 10818 
    
    61. 
   
     
     
   
  61.  
    
     
     faccessat(AT_FDCWD, "/home/lujun9972/bin/printf", X_OK) = -1 ENOENT (没有那个文件或目录) 
    
    62. 
   
     
     
   
  62.  
    
     
     faccessat(AT_FDCWD, "/usr/local/sbin/printf", X_OK) = -1 ENOENT (没有那个文件或目录) 
    
    63. 
   
     
     
   
  63.  
    
     
     faccessat(AT_FDCWD, "/usr/local/bin/printf", X_OK) = -1 ENOENT (没有那个文件或目录) 
    
    64. 
   
     
     
   
  64.  
    
     
     faccessat(AT_FDCWD, "/usr/bin/printf", X_OK) = 0 
    
    65. 
   
     
     
   
  65.  
    
     
     stat("/usr/bin/printf", {st_mode=S_IFREG|0755, st_size=51176, ...}) = 0 
    
    66. 
   
     
     
   
  66.  
    
     
     openat(AT_FDCWD, "/dev/null", O_RDONLY|O_CLOEXEC) = 7 
    
    67. 
   
     
     
   
  67.  
    
     
     faccessat(AT_FDCWD, "/proc/5070/fd/.", F_OK) = 0 
    
    68. 
   
     
     
   
  68.  
    
     
     faccessat(AT_FDCWD, "/proc/5070/fd/.", F_OK) = 0 
    
    69. 
   
     
     
   
  69.  
    
     
     faccessat(AT_FDCWD, "/bin/bash", X_OK) = 0 
    
    70. 
   
     
     
   
  70.  
    
     
     stat("/bin/bash", {st_mode=S_IFREG|0755, st_size=903440, ...}) = 0 
    
    71. 
   
     
     
   
  71.  
    
     
     pipe2([8, 9], O_CLOEXEC) = 0 
    
    72. 
   
     
     
   
  72.  
    
     
     rt_sigprocmask(SIG_BLOCK, [INT CHLD], [], 8) = 0 
    
    73. 
   
     
     
   
  73.  
    
     
     vfork() = 11679 
    
    74. 
   
     
     
   
  74.  
    
     
     rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 
    
    75. 
   
     
     
   
  75.  
    
     
     close(9) = 0 
    
    76. 
   
     
     
   
  76.  
    
     
     close(7) = 0 
    
    77. 
   
     
     
   
  77.  
    
     
     read(8, "setterm: \347\273\210\347\253\257 xterm-256color \344"..., 16384) = 51 
    
    78. 
   
     
     
   
  78.  
    
     
     read(8, "Couldn't get a file descriptor r"..., 16333) = 56 
    
    79. 
   
     
     
   
  79.  
    
     
     read(8, "/home/lujun9972/.bash_profile: \347"..., 16277) = 72 
    
    80. 
   
     
     
   
  80.  
    
     
     read(8, "Your display number is 0\nTest wh"..., 16205) = 78 
    
    81. 
   
     
     
   
  81.  
    
     
     read(8, "Fcitx is running correctly.\n\n==="..., 16127) = 104 
    
    82. 
   
     
     
   
  82.  
    
     
     read(8, "stdin isn't a tty!\n", 16023) = 19 
    
    83. 
   
     
     
   
  83.  
    
     
     read(8, "__RESULT\0b269cd09e7ec4e8a115188c"..., 16004) = 298 
    
    84. 
   
     
     
   
  84.  
    
     
     read(8, 0x7ffd1d39cba6, 15706) = ? ERESTARTSYS (To be restarted if SA_RESTART is set) 
    
    85. 
   
     
     
   
  85.  
    
     
     --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=11679, si_uid=1000, si_status=0, si_utime=1, si_stime=1} --- 
    
    86. 
   
     
     
   
  86.  
    
     
     rt_sigreturn({mask=[]}) = -1 EINTR (被中断的系统调用) 
    
    87. 
   
     
     
   
  87.  
    
     
     read(8,  
    
    88.

很容易就可以看出，当 Emacs 卡顿时，它在尝试从 8 号文件句柄中读取内容。

那么 8 号文件句柄在哪里定义的呢？往前看可以看到：

  
    
    
  
    
   
     
     
   
  1.  
    
     
     pipe2([8, 9], O_CLOEXEC) = 0 
    
    2. 
   
     
     
   
  2.  
    
     
     rt_sigprocmask(SIG_BLOCK, [INT CHLD], [], 8) = 0 
    
    3. 
   
     
     
   
  3.  
    
     
     vfork() = 11679 
    
    4. 
   
     
     
   
  4.  
    
     
     rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 
    
    5. 
   
     
     
   
  5.  
    
     
     close(9) = 0 
    
    6.

可以推测出，Emacs 主进程 fork 出一个子进程（进程号为 11679），并通过管道读取子进程的内容。

然而，从

  
    
    
  
    
   
     
     
   
  1.  
    
     
     --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=11679, si_uid=1000, si_status=0, si_utime=1, si_stime=1} --- 
    
    2. 
   
     
     
   
  2.  
    
     
     rt_sigreturn({mask=[]}) = -1 EINTR (被中断的系统调用) 
    
    3. 
   
     
     
   
  3.  
    
     
     read(8,  
    
    4.

可以看出，实际上子进程已经退出了（父进程收到 SIGCHLD 信号），父进程确依然在尝试从管道中读取内容，导致的阻塞。

而且从

  
    
    
  
    
   
     
     
   
  1.  
    
     
     read(8, "setterm: \347\273\210\347\253\257 xterm-256color \344"..., 16384) = 51 
    
    2. 
   
     
     
   
  2.  
    
     
     read(8, "Couldn't get a file descriptor r"..., 16333) = 56 
    
    3. 
   
     
     
   
  3.  
    
     
     read(8, "/home/lujun9972/.bash_profile: \347"..., 16277) = 72 
    
    4. 
   
     
     
   
  4.  
    
     
     read(8, "Your display number is 0\nTest wh"..., 16205) = 78 
    
    5. 
   
     
     
   
  5.  
    
     
     read(8, "Fcitx is running correctly.\n\n==="..., 16127) = 104 
    
    6. 
   
     
     
   
  6.  
    
     
     read(8, "stdin isn't a tty!\n", 16023) = 19 
    
    7. 
   
     
     
   
  7.  
    
     
     read(8, "__RESULT\0b269cd09e7ec4e8a115188c"..., 16004) = 298 
    
    8. 
   
     
     
   
  8.  
    
     
     read(8, 0x7ffd1d39cba6, 15706) = ? ERESTARTSYS (To be restarted if SA_RESTART is set) 
    
    9.

看到，子进程的输出似乎是我的交互式登录 bash 启动时的输出（加载了 .bash_profile）

在往前翻发现这么一段信息：

  
    
    
  
    
   
     
     
   
  1.  
    
     
     readlinkat(AT_FDCWD, "/home", 0x7ffd1d3abb50, 1024) = -1 EINVAL (无效的参数) 
    
    2. 
   
     
     
   
  2.  
    
     
     readlinkat(AT_FDCWD, "/home/lujun9972", 0x7ffd1d3abf00, 1024) = -1 EINVAL (无效的参数) 
    
    3. 
   
     
     
   
  3.  
    
     
     readlinkat(AT_FDCWD, "/home/lujun9972/.emacs.d", 0x7ffd1d3ac2b0, 1024) = -1 EINVAL (无效的参数) 
    
    4. 
   
     
     
   
  4.  
    
     
     readlinkat(AT_FDCWD, "/home/lujun9972/.emacs.d/elpa", 0x7ffd1d3ac660, 1024) = -1 EINVAL (无效的参数) 
    
    5. 
   
     
     
   
  5.  
    
     
     readlinkat(AT_FDCWD, "/home/lujun9972/.emacs.d/elpa/exec-path-from-shell-20180323.1904", 0x7ffd1d3aca10, 1024) = -1 EINVAL (无效的参数) 
    
    6. 
   
     
     
   
  6.  
    
     
     readlinkat(AT_FDCWD, "/home/lujun9972/.emacs.d/elpa/exec-path-from-shell-20180323.1904/exec-path-from-shell.elc", 0x7ffd1d3acdc0, 1024) = -1 EINVAL (无效的参数) 
    
    7. 
   
     
     
   
  7.  
    
     
     lseek(7, -2655, SEEK_CUR) = 1441 
    
    8. 
   
     
     
   
  8.  
    
     
     read(7, "\n(defvar exec-path-from-shell-de"..., 4096) = 4096 
    
    9.

这很明显是跟 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，发现这次启动速度明显快了许多了。

以上是关于使用 strace 查找 Emacs 启动阻塞的原因 | Linux 中国的主要内容，如果未能解决你的问题，请参考以下文章

Linux上进程追踪与调试（strace和gdb）

Linux上进程追踪与调试（strace和gdb）

启动make并通过Emacs中的快捷方式转到错误位置

如何从 OSX 的命令行启动 GUI Emacs？

strace 命令分析mysql的相关的问题

strace分析启动流程