Saturday, April 20, 2013

Re: Vim freezes with 100% cpu usage on exit

backtrace after tmux attach(triggered by clicking at the vim pane with the mouse, but this will call eventually returns):

--------------------------------------------------------------------------------------------------------------------------------
#0 0xb779d424 in __kernel_vsyscall ()
#1 0xb671e5f0 in poll () from /lib/i386-linux-gnu/libc.so.6
#2 0xb62c9120 in ?? () from /usr/lib/i386-linux-gnu/libxcb.so.1
#3 0xb62caa60 in ?? () from /usr/lib/i386-linux-gnu/libxcb.so.1
#4 0xb62cad17 in xcb_wait_for_reply () from /usr/lib/i386-linux-gnu/libxcb.so.1
#5 0xb6f486f2 in _XReply () from /usr/lib/i386-linux-gnu/libX11.so.6
#6 0xb6f2db1d in XGetWindowProperty () from /usr/lib/i386-linux-gnu/libX11.so.6
#7 0xb6f2e288 in XGetTextProperty () from /usr/lib/i386-linux-gnu/libX11.so.6
#8 0xb6f2e313 in XGetWMName () from /usr/lib/i386-linux-gnu/libX11.so.6
#9 0x08157cf8 in test_x11_window (dpy=0x997baa0) at os_unix.c:1577
#10 0x0815856f in get_x11_windis () at os_unix.c:1677
#11 get_x11_windis () at os_unix.c:1601
#12 0x08158ff7 in mch_settitle (title=0x99ea298 "vim-debug.txt" (~/) - VIM", icon=0x99f9740 "vim-debug.txt") at os_unix.c:2037
#13 0x08079049 in resettitle () at buffer.c:3353
#14 0x0807c510 in maketitle () at buffer.c:3321
#15 0x081c7133 in win_enter_ext (wp=<optimized out>, undo_sync=1, curwin_invalid=0) at window.c:4182
#16 0x081bd8be in jump_to_mouse (flags=0, inclusive=0xbff2b394, which_button=0) at ui.c:2650
#17 0x0813d519 in do_mouse (oap=0xbff2b380, c=-11517, dir=-1, count=1, fixindent=0) at normal.c:2836
#18 0x0813e7cf in nv_mouse (cap=0xbff2b2f8) at normal.c:4689
#19 0x0813c4a1 in normal_cmd (oap=0xbff2b380, toplevel=1) at normal.c:1193
#20 0x081f60f8 in main_loop (cmdwin=0, noexmode=0) at main.c:1266
#21 0x08074b44 in main (argc=7, argv=0xbff2b604) at main.c:967
--------------------------------------------------------------------------------------------------------------------------------


backtrace after quit (freezes forvever with 100% cpu usage)

--------------------------------------------------------------------------------------------------------------------------------
#0 0xb779d424 in __kernel_vsyscall ()
#1 0xb671e5f0 in poll () from /lib/i386-linux-gnu/libc.so.6
#2 0xb706b583 in _XtWaitForSomething () from /usr/lib/i386-linux-gnu/libXt.so.6
#3 0xb706cf87 in XtAppPending () from /usr/lib/i386-linux-gnu/libXt.so.6
#4 0x08157c45 in xterm_update () at os_unix.c:6771
#5 0x0815ae7d in setup_term_clip () at os_unix.c:6609
#6 0x0809959f in make_connection () at eval.c:14645
#7 make_connection () at eval.c:14636
#8 0x080995cd in f_serverlist (argvars=0xbff28f60, rettv=0xbff29340) at eval.c:15853
#9 0x080a6091 in call_func (funcname=<optimized out>, len=<optimized out>, rettv=0xbff29340, argcount=0, argvars=0xbff28f60, firstline=13, lastline=13,
doesrange=0xbff29108, evaluate=1, selfdict=0x0) at eval.c:8394
#10 0x080a9cec in get_func_tv (name=0x99cf77c "serverlist(), \"\\n\")) > 1 )", len=10, rettv=0xbff29340, arg=0xbff2943c, firstline=13, lastline=13,
doesrange=0xbff29108, evaluate=1, selfdict=0x0) at eval.c:8207
#11 0x080a859e in eval7 (arg=0xbff2943c, rettv=0xbff29340, evaluate=1, want_string=0) at eval.c:5138
#12 0x080a8893 in eval6 (arg=0xbff2943c, rettv=0xbff29340, evaluate=1, want_string=0) at eval.c:4790
#13 0x080a8afa in eval5 (arg=0xbff2943c, rettv=0xbff29340, evaluate=1) at eval.c:4606
#14 0x080a976e in eval4 (evaluate=1, rettv=0xbff29340, arg=0xbff2943c) at eval.c:4299
#15 eval3 (arg=0xbff2943c, rettv=0xbff29340, evaluate=1) at eval.c:4211
#16 0x080a98ec in eval2 (evaluate=1, rettv=0xbff29340, arg=0xbff2943c) at eval.c:4140
#17 eval1 (arg=<optimized out>, rettv=<optimized out>, evaluate=<optimized out>) at eval.c:4065
#18 0x080a9bf4 in get_func_tv (name=0x99cf776 "split(serverlist(), \"\\n\")) > 1 )", len=5, rettv=0xbff29720, arg=0xbff2981c, firstline=13, lastline=13,
doesrange=0xbff294e8, evaluate=1, selfdict=0x0) at eval.c:8192
#19 0x080a859e in eval7 (arg=0xbff2981c, rettv=0xbff29720, evaluate=1, want_string=0) at eval.c:5138
#20 0x080a8893 in eval6 (arg=0xbff2981c, rettv=0xbff29720, evaluate=1, want_string=0) at eval.c:4790
#21 0x080a8afa in eval5 (arg=0xbff2981c, rettv=0xbff29720, evaluate=1) at eval.c:4606
#22 0x080a976e in eval4 (evaluate=1, rettv=0xbff29720, arg=0xbff2981c) at eval.c:4299
#23 eval3 (arg=0xbff2981c, rettv=0xbff29720, evaluate=1) at eval.c:4211
#24 0x080a98ec in eval2 (evaluate=1, rettv=0xbff29720, arg=0xbff2981c) at eval.c:4140
#25 eval1 (arg=<optimized out>, rettv=<optimized out>, evaluate=<optimized out>) at eval.c:4065
#26 0x080a9bf4 in get_func_tv (name=0x99cf772 "len(split(serverlist(), \"\\n\")) > 1 )", len=3, rettv=0xbff29a40, arg=0xbff29d7c, firstline=13, lastline=13,
doesrange=0xbff298c8, evaluate=1, selfdict=0x0) at eval.c:8192
#27 0x080a859e in eval7 (arg=0xbff29d7c, rettv=0xbff29a40, evaluate=1, want_string=0) at eval.c:5138
#28 0x080a8893 in eval6 (arg=0xbff29d7c, rettv=0xbff29a40, evaluate=1, want_string=0) at eval.c:4790
#29 0x080a8afa in eval5 (arg=0xbff29d7c, rettv=0xbff29a40, evaluate=1) at eval.c:4606
#30 0x080a982a in eval4 (evaluate=1, rettv=0xbff29a40, arg=0xbff29d7c) at eval.c:4299
#31 eval3 (arg=0xbff29d7c, rettv=0xbff29cd0, evaluate=1) at eval.c:4235
#32 0x080a98ec in eval2 (evaluate=1, rettv=0xbff29cd0, arg=0xbff29d7c) at eval.c:4140
#33 eval1 (arg=<optimized out>, rettv=<optimized out>, evaluate=<optimized out>) at eval.c:4065
#34 0x080a782c in eval7 (arg=0xbff29d7c, rettv=0xbff29cd0, evaluate=1, want_string=0) at eval.c:5101
#35 0x080a8893 in eval6 (arg=0xbff29d7c, rettv=0xbff29cd0, evaluate=1, want_string=0) at eval.c:4790
#36 0x080a8afa in eval5 (arg=0xbff29d7c, rettv=0xbff29cd0, evaluate=1) at eval.c:4606
#37 0x080a982a in eval4 (evaluate=1, rettv=0xbff29cd0, arg=0xbff29d7c) at eval.c:4299
#38 eval3 (arg=0xbff29d7c, rettv=0xbff29dc4, evaluate=1) at eval.c:4235
#39 0x080a98ec in eval2 (evaluate=1, rettv=0xbff29dc4, arg=0xbff29d7c) at eval.c:4140
#40 eval1 (arg=<optimized out>, rettv=<optimized out>, evaluate=<optimized out>) at eval.c:4065
#41 0x080a9df4 in eval0 (arg=0x99cf734 "!( exists(s:ccex) && !{s:ccex} ) && !( has('clientserver') && len(split(serverlist(), \"\\n\")) > 1 )", rettv=0xbff29dc4,
nextcmd=0xbff29ee0, evaluate=1) at eval.c:4022
#42 0x080aa683 in eval_to_bool (arg=0x99cf734 "!( exists(s:ccex) && !{s:ccex} ) && !( has('clientserver') && len(split(serverlist(), \"\\n\")) > 1 )",
error=0xbff29dfc, nextcmd=0xbff29ee0, skip=0) at eval.c:1273
#43 0x080d47e7 in ex_if (eap=0xbff29edc) at ex_eval.c:886
#44 0x080ce716 in do_one_cmd (cookie=0x9a35168, fgetline=0x80b07f0 <get_func_line>, cstack=0xbff29fb8, sourcing=1, cmdlinep=0xbff29fa0) at ex_docmd.c:2668
#45 do_cmdline (cmdline=0x0, fgetline=0x80b07f0 <get_func_line>, cookie=0x9a35168, flags=7) at ex_docmd.c:1122
#46 0x080a55e1 in call_user_func (fp=0x999dad8, argcount=0, argvars=0xbff2a650, rettv=0xbff2a7bc, firstline=13, lastline=13, selfdict=0x0) at eval.c:22250
#47 0x080a5f64 in call_func (funcname=<optimized out>, len=<optimized out>, rettv=0xbff2a7bc, argcount=0, argvars=0xbff2a650, firstline=13, lastline=13,
doesrange=0xbff2a7dc, evaluate=1, selfdict=0x0) at eval.c:8365
#48 0x080a9cec in get_func_tv (name=0x9a31b30 "\200\375R72_leavepre", len=14, rettv=0xbff2a7bc, arg=0xbff2a7d4, firstline=13, lastline=13, doesrange=0xbff2a7dc,
evaluate=1, selfdict=0x0) at eval.c:8207
#49 0x080ad0cc in ex_call (eap=0xbff2a8cc) at eval.c:3445
#50 0x080ce716 in do_one_cmd (cookie=0xbff2ad20, fgetline=0x80e3b50 <getnextac>, cstack=0xbff2a9a8, sourcing=1, cmdlinep=0xbff2a990) at ex_docmd.c:2668
#51 do_cmdline (cmdline=0x0, fgetline=0x80e3b50 <getnextac>, cookie=0xbff2ad20, flags=7) at ex_docmd.c:1122
#52 0x080e2f07 in apply_autocmds_group (event=EVENT_VIMLEAVEPRE, fname=0x99d79e0 "/home/tarruda/vim-debug.txt", fname_io=<optimized out>,
force=0, group=-3, buf=0x9696b00, eap=0x0) at fileio.c:9383
#53 0x081f59ba in getout (exitval=0) at main.c:1365
#54 0x080cb577 in ex_quit_all (eap=0xbff2ae9c) at ex_docmd.c:6523
#55 ex_quit_all (eap=0xbff2ae9c) at ex_docmd.c:6496
#56 0x080ce716 in do_one_cmd (cookie=0x0, fgetline=0x80defd0 <getexline>, cstack=0xbff2af78, sourcing=0, cmdlinep=0xbff2af60) at ex_docmd.c:2668
#57 do_cmdline (cmdline=0x0, fgetline=0x80defd0 <getexline>, cookie=0x0, flags=0) at ex_docmd.c:1122
#58 0x0813606d in nv_colon (cap=0xbff2b2f8) at normal.c:5396
#59 0x0813c4a1 in normal_cmd (oap=0xbff2b380, toplevel=1) at normal.c:1193
#60 0x081f60f8 in main_loop (cmdwin=0, noexmode=0) at main.c:1266
#61 0x08074b44 in main (argc=7, argv=0xbff2b604) at main.c:967
--------------------------------------------------------------------------------------------------------------------------------
Dominique thanks for your help.

I have attached gdb to vim in both cases: when I re-attach to tmux after a reboot(which hangs without cpu activity for a while) and soon after that, when I send the quit command(which hangs vim with 100% cpu).

In both cases it seems the issue is related with x11 libraries and the fact that my x11 session(provided by cygwin-x) has a different lifecycle than the vim session. The function that causes vim to freeze with 100% cpu is '_XtWaitForSomething' from libXt. As the name says this function waits for something that never happens with a busy poll which causes the freeze.

The issue was fixed for me by replacing ubuntu's 'vim-gtk' for 'vim-nox' package. The x11 clipboard integration I replaced by creating mappings that invoke the xclip commandline utility(which doesn't keep a connection with x11 open).

In any case I attached gdb backtraces for anyone interested in doing further investigations. It may be possible to reproduce these issues by starting vim with x11 support in a tmux/screen session, restarting x11 and then reattaching to it. To debug in debian/ubuntu just install the vim-gtk/vim-dbg packages


On Fri, Apr 19, 2013 at 4:05 PM, Dominique Pellé <dominique.pelle@gmail.com> wrote:
Thiago Padilha <tpadilha84@gmail.com> wrote:

> Sometimes when I reattach to the tmux session after the virtual machine
> has been frozen for a long time vim freezes right away without consuming 100% cpu,
...
> This is really annoying me, I was hoping someone could give me hints on how to debug this issue.


You could build vim with debug information (-g -O0). Then, when bug
happens & Vim uses 100% of the CPU, you can attach with gdb to the
Vim process that hogs the CPU, and look at the stack trace. That may
give useful information to debug it.

$ gdb
(gdb) attach pid
(gdb) bt

(where pid is he process ID of the Vim process using 100% of the CPU)

You can then continue with...

(gdb) c

... and press CTRL-C in gdb to stop vim and run bt again to see if you
get similar stack trace.  You can repeat that a few times to get a feeling
of what Vim is doing.

Dominique

--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php

---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to vim_use+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.



--
--
You received this message from the "vim_use" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php
 
---
You received this message because you are subscribed to the Google Groups "vim_use" group.
To unsubscribe from this group and stop receiving emails from it, send an email to vim_use+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

No comments: