3

The gvim program is stuck for 3 seconds before opening any file. This issue is isolated to gvim, vim opens just fine. Therefore, the cause must be somewhere in X or some related service and not vim.

I have tried disabling all my vim plugins and the vimrc file.

Here is the symptom:

$ time strace -o strace.gvim -f -yy -T gvim -c q 
time: Real 0m3.5s  User 0m0.0s  System 0m0.1s

While vim runs fine:

$ time strace -o strace.vim -f -yy -T vim -c q 
time: Real 0m0.2s  User 0m0.0s  System 0m0.0s

To get to the bottom of this, I am looking for what is taking such a long time:

...It looks like it is related to the dbus service somehow.

$ grep '<3\.[0-9]' -C 2 strace.gvim

-

4907  exit_group(0)                     = ?
4907  +++ exited with 0 +++
4848  <... nanosleep resumed> 0x7ffcaa8f8670) = 0 <3.000198>
4848  kill(4907, SIGKILL)               = -1 ESRCH (No such process) <0.000061>
4848  write(1<pipe:[29773]>, "unix:abstract=/tmp/dbus-8t4OQuvB"..., 73) = 73 <0.000071>
@@@@@@@@ 4586  <... read resumed> "unix:abstract=/tmp/dbus-8t4OQuvB"..., 1024) = 73 <3.038342>
4848  write(1<pipe:[29773]>, "+\23\0\0", 4 <unfinished ...>
4586  read(7<pipe:[29773]>,  <unfinished ...>
--
4586  <... read resumed> "", 1024)      = 0 <0.000038>
4586  wait4(4848,  <unfinished ...>
@@@@@@@@ 4900  <... read resumed> "", 4)         = 0 <3.017352>
4848  +++ exited with 0 +++
4900  write(2</dev/null<char 1:3>>, "EOF in dbus-launch reading PID f"..., 47) = 47 <0.000003>
--
4586  close(4<pipe:[30791]>)            = 0 <0.000003>
4586  poll([{fd=5<UNIX:[29772]>, events=POLLIN}, {fd=6<anon_inode:[eventfd]>, events=POLLIN}], 2, 0 <unfinished ...>
@@@@@@@@ 4579  <... read resumed> "ok\0", 9)     = 3 <3.368490>
4586  <... poll resumed> )              = 0 (Timeout) <0.000006>
4586  poll([{fd=5<UNIX:[29772]>, events=POLLIN}, {fd=6<anon_inode:[eventfd]>, events=POLLIN}], 2, 0 <unfinished ...>

Looking further up, I discover that the ~/.dbus folder is owned by root:

4848  mkdir("/home/jaroslav/.dbus", 0700) = -1 EEXIST (File exists) <0.000005>
4848  mkdir("/home/jaroslav/.dbus/session-bus", 0700) = -1 EACCES (Permission denied) <0.000003>
4848  write(2<pipe:[29774]>, "Unable to create /home/jaroslav/"..., 50) = 50 <0.000004>

-

$ ls -ld ~/.dbus 
drwx------ 1 root root 1 191206 18:50 /home/jaroslav/.dbus

Changing the owner solves the issue and gvim starts instantaneously.

strace is fine, but

Is it possible to somewhow trace all kernel calls that take more than 3 seconds and print their stacks (Linux 4.19.72)?

Ярослав Рахматуллин
  • 1,294
  • 9
  • 20
  • What's the name and args of pid 4848? It looks like the nanosleep there is the first thing that takes almost exactly 3 seconds. Maybe it's a `timeout` command? – Mark Plotnick Dec 08 '19 at 00:40
  • no, coreutils/timeout is not involved here. that 4848 pid a listener from -i-dont-know-, reporting that it is done waiting. it looks like thread because of "<... .resumed" - which is strace saying: I have awoken/resumed a thread - because "..." is not a syscall. – Ярослав Рахматуллин Dec 11 '19 at 06:52
  • The issue is solved, @MarkPlotnick, my real interest here is to entice someone to debug this scenario with eBPF / ply kernel features from linux 4.9+. I just have other pressing issues right now... – Ярослав Рахматуллин Dec 11 '19 at 06:57
  • @ЯрославРахматуллин strace can print timestamps (`-t`, `-tt`, `-ttt`), so it might possible to use those with awk, etc. to get calls that took more than x seconds. – muru Dec 11 '19 at 07:10
  • @muru thank you, I was not aware, however the -T option was enough to isolate the hung calls. – Ярослав Рахматуллин Dec 11 '19 at 07:21

0 Answers0