search

ycm-core / YouCompleteMe

A code-completion engine for Vim
http://ycm-core.github.io/YouCompleteMe/
GNU General Public License v3.0
25.35k stars 2.8k forks source link

VIM high CPU usage after using completion #3549

Closed xenos1984 closed 4 years ago

xenos1984 commented 4 years ago

Issue Prelude

Please complete these steps and check these boxes (by putting an x inside the brackets) before filing your issue:

Thank you for adhering to this process! It ensures your issue is resolved quickly and that neither your nor our time is needlessly wasted.

Issue Details

After entering insert mode, starting typing and doing completion in a document which uses completion via YouCompleteMe, VIM CPU usage rises to around 30-50% and stays there. Even after leaving insert mode, changing to a different buffer etc. CPU usage does not drop, but stays at 30-50%, occasionally even higher, up to 100%.

I suspect it to be related to YCM, since 1. CPU usage does not rise if I disable YCM, 2. even with all other plugins except YCM disabled, CPU usage still rises.

Start VIM, open a document with completion enabled, enter insert mode, start typing.

Minimal test case:

CPU usage stays low / returns to low when leaving insert mode.

See report; VIM CPU usage rises and does not return to normal.

Diagnostic data

https://gist.github.com/xenos1984/2353bbdb48fd6ef63b1ece72760567ac

OS version, distribution, etc.

Ubuntu 18.04 VIM installed from https://launchpad.net/~jonathonf/+archive/ubuntu/vim

puremourning commented 4 years ago

Thanks. Can you paste all of your g:ycm_ settings?

puremourning commented 4 years ago

Also can you attach gdb to vim and get a back trace? Or use pstack on the pid?

xenos1984 commented 4 years ago

Sure. First, my settings:

let g:ycm_warning_symbol = '▶'
let g:ycm_error_symbol = '▶'
let g:ycm_collect_identifiers_from_comments_and_strings = 1
let g:ycm_collect_identifiers_from_tags_files = 1
let g:ycm_seed_identifiers_with_syntax = 1
let g:ycm_complete_in_comments = 1
let g:ycm_complete_in_strings = 1
let g:ycm_semantic_triggers = {'tex' : ['\ref{','\vref{','\eqref{','\pageref{','\cite{'], }
let g:ycm_server_python_interpreter = '/usr/bin/python3'
let g:ycm_disable_for_files_larger_than_kb = 0
"let g:ycm_log_level = 'debug'

Backtrace:

(gdb) bt
#0  0x00007fc4fd672bf9 in __GI___poll (fds=0x7ffea75f91a0, nfds=1, timeout=7) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007fc500a57e7a in _XtWaitForSomething () from /usr/lib/x86_64-linux-gnu/libXt.so.6
#2  0x00007fc500a59632 in XtAppProcessEvent () from /usr/lib/x86_64-linux-gnu/libXt.so.6
#3  0x0000564301b487b5 in gui_mch_wait_for_chars ()
#4  0x0000564301b15786 in ui_wait_for_chars_or_timer ()
#5  0x0000564301b17e52 in inchar_loop ()
#6  0x0000564301b3c695 in ?? ()
#7  0x0000564301b17905 in ui_inchar ()
#8  0x0000564301a02412 in ?? ()
#9  0x0000564301a02da6 in ?? ()
#10 0x0000564301a044ff in vgetc ()
#11 0x0000564301a04a19 in safe_vgetc ()
#12 0x0000564301a572d4 in normal_cmd ()
#13 0x0000564301b8d2f7 in main_loop ()
#14 0x0000564301b8e67f in vim_main2 ()
#15 0x0000564301969a27 in main ()
xenos1984 commented 4 years ago

Another comment and clarification of the test results above: These are actually taken from gvim with the Athena GUI.

I forgot to mention, since I had the problem with plain command line vim a few days ago as well. I'm currently trying to reproduce the issue (I'm on a different computer at the moment), but now command line vim does not cause issues, CPU usage stays low.

xenos1984 commented 4 years ago

Backtrace from command line vim (in urxvt terminal) after CPU usage rising:

(gdb) bt
#0  0x00007fa4dc2d303f in __GI___select (nfds=5, readfds=0x5641c26f18e0, writefds=0x5641c26f1860, exceptfds=0x5641c26f17e0, timeout=0x7fff1d7caef0)
    at ../sysdeps/unix/sysv/linux/select.c:41
#1  0x00005641c23220a0 in  ()
#2  0x00005641c232254b in  ()
#3  0x00005641c23be656 in ui_wait_for_chars_or_timer ()
#4  0x00005641c231b545 in  ()
#5  0x00005641c23c0d62 in inchar_loop ()
#6  0x00005641c23c07da in ui_inchar ()
#7  0x00005641c22aac52 in  ()
#8  0x00005641c22ab5e6 in  ()
#9  0x00005641c22ace24 in vgetc ()
#10 0x00005641c22ad289 in safe_vgetc ()
#11 0x00005641c22fff8e in normal_cmd ()
#12 0x00005641c24377cf in main_loop ()
#13 0x00005641c2438b0f in vim_main2 ()
#14 0x00005641c221179f in main ()
bstaletic commented 4 years ago

Which process is hogging the CPU? Is it vim or python?

xenos1984 commented 4 years ago

It's vim, so not Python.

puremourning commented 4 years ago

Does it only happen for html files?

xenos1984 commented 4 years ago

As far as I can say, it happens for all file types for which syntax completion is enabled - at least for all which I have tested. So far I have observed it for tex, remind, php and html - the latter was just convenient to hack up a quick minimal working example.

puremourning commented 4 years ago

Does it happen for any filetypes with native YCM support, like python?

In any case, would you be able to capture a profile, using these instructions :

:profile start profile.log
:profile func *
:profile file *
" At this point do slow actions
:profile pause
:noautocmd qall!

profile.log will contain the relevant info.

xenos1984 commented 4 years ago

It seems that Python is not affected. I typed for quite a while, including both identifier and semantic completion, but CPU usage stayed low.

In the meantime I also tried C++. There CPU usage rises again.

Here's the requested profile:

https://gist.github.com/xenos1984/c79836e6677bac9fdb7ab9ef4b72d7b5

Could it be related to signature help? That seems to be called quite often, and as far as I could see from the commit history, there were some recent changes.

bstaletic commented 4 years ago

So, python does support signature help, but PHP and html don't (by default). What's the output of :YcmDebugInfo in a c++ file?

xenos1984 commented 4 years ago

Here I picked a file for which semantic completion is enabled by passing compile flags via .ycm_extra_conf.py:

Printing YouCompleteMe debug information...
-- Client logfile: /tmp/ycm_0ajfctk2.log
-- Server Python interpreter: /usr/bin/python3
-- Server Python version: 3.6.9
-- Server has Clang support compiled in: True
-- Clang version: clang version 7.0.0-3~ubuntu0.18.04.1 (tags/RELEASE_700/final)
-- Extra configuration file found and loaded
-- Extra configuration path: /data/epi/C/osdev/nos/.ycm_extra_conf.py
-- C-family completer debug information:
--   Compilation database path: None
--   Flags: ['-target', 'i686-pc-elf', '-nostdinc', '-nostdlib', '-fdiagnostics-color=always', '-mgeneral-regs-only', '-O3', '-ffreestanding', '-fno-leading-underscore', '-Wall', '-Wextra', '-Wpedantic', '-fno-rtti', '-fno-exceptions', '-std=c++17', '-isystem', '/opt/cross/i686-elf/lib/gcc/i686-elf/9.2.0/../../../../i
686-elf/include/c++/9.2.0', '-isystem', '/opt/cross/i686-elf/lib/gcc/i686-elf/9.2.0/../../../../i686-elf/include/c++/9.2.0/i686-elf', '-isystem', '/opt/cross/i686-elf/lib/gcc/i686-elf/9.2.0/../../../../i686-elf/include/c++/9.2.0/backward', '-isystem', '/opt/cross/i686-elf/lib/gcc/i686-elf/9.2.0/include', '-isystem', '
/opt/cross/i686-elf/lib/gcc/i686-elf/9.2.0/include-fixed', '-isystem', '/opt/cross/i686-elf/lib/gcc/i686-elf/9.2.0/../../../../i686-elf/include', '-DHAVE_CONFIG_H', '-imacros', '/data/epi/C/osdev/nos/./build/system/config.h', '-I', '/data/epi/C/osdev/nos/./source/system/include', '-I', '/data/epi/C/osdev/nos/./source/
system/kernel', '-resource-dir=/home/mhohmann/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/clang/lib/clang/9.0.0', '-fspell-checking']
--   Translation unit: /data/epi/C/osdev/nos/source/system/kernel/Process.cpp
-- Server running at: http://127.0.0.1:36615
-- Server process ID: 29793
-- Server logfiles:
--   /tmp/ycmd_36615_stdout_3btfa3du.log
--   /tmp/ycmd_36615_stderr_i81ek7bm.log
bstaletic commented 4 years ago

That's what I expected. It's the libclang based completer which doesn't support signature help, just like PHP, but unlike Python.

-- Clang version: clang version 7.0.0-3~ubuntu0.18.04.1 (tags/RELEASE_700/final)

For the record, you should be on version 9. Also make sure you are on the latest YCM commit and have updated submodules (git submodule update --init --recursive).

 

Open a python file and execute :py3 print(ycm_state._signature_help_available_requests['python'].Done()). Then reproduce the issue in another filetype and do the same, but change the 'python' part.

Expected output for a filetype that supports sig help is True and for a filetype that doesn't is False.

bstaletic commented 4 years ago

You can also try setting g:ycm_disable_signature_help to 1 in your vimrc, to confirm if signature help is the problem.

xenos1984 commented 4 years ago

Oh, indeed, it seems that I haven't properly updated in a while. So now I did and indeed I have clang version 9. But results are still not quite as expected:

bstaletic commented 4 years ago

The python command you asked for returns True on python, tex, php... I would have expected that it is false on at least one of them.

That's because it should have been .Response(), not .Done() at the end. The expected values are YES and NO. .Done() only checks if the /signature_help_available request completed.

bstaletic commented 4 years ago

Oh, did you remember to restart vim after setting ycm_disable_signature_help?

xenos1984 commented 4 years ago

Yes, I did restart. Still no luck.

Now indeed I get NO for tex, php, html... And for python I get YES if signature help is enabled and None if it is disabled.

puremourning commented 4 years ago

Thanks for the investigation. It does look like a performance issue with the new signature help feature particularly where not available for a filetype. Will have to look into it.

xenos1984 commented 4 years ago

Thanks for looking into this issue!

This might be a stupid question, since I'm not familiar with the YCM code, but where is the value of ycm_disable_signature_help actually used / taken into account? I ran grep -rn ycm_disable_signature_help * on the YCM directory and it only showed me the files where it is initially set and where it is documented, but no other occurrence in the code. The same for a search on GitHub. So I wonder how setting this will have an effect.

Also I looked up the code for those functions which are called a few thousand times during my test, according to the profile. This made me wonder:

https://github.com/ycm-core/YouCompleteMe/blob/master/autoload/youcompleteme.vim#L933

function! s:ShouldUseSignatureHelp()
  return s:Pyeval( 'vimsupport.VimSupportsPopupWindows()' )
endfunction

function! s:RequestSignatureHelp()
  if !s:ShouldUseSignatureHelp()
    return
  endif

  exec s:python_command "ycm_state.SendSignatureHelpRequest()"
  call s:PollSignatureHelp()
endfunction

function! s:PollSignatureHelp( ... )
  if !s:ShouldUseSignatureHelp()
    return
  endif

  if !s:Pyeval( 'ycm_state.SignatureHelpRequestReady()' )
    let s:pollers.signature_help.id = timer_start(
          \ s:pollers.signature_help.wait_milliseconds,
          \ function( 's:PollSignatureHelp' ) )
    return
  endif

  let s:signature_help = s:Pyeval( 'ycm_state.GetSignatureHelpResponse()' )
  call s:UpdateSignatureHelp()
endfunction

So do I understand correctly that the first one only checks whether vim supports popup windows, and then the last one starts polling? The same here:

https://github.com/ycm-core/YouCompleteMe/blob/master/python/ycm/signature_help.py#L87

def ShouldUseSignatureHelp():
  return ( vimsupport.VimHasFunctions( 'screenpos', 'pum_getpos' ) and
vimsupport.VimSupportsPopupWindows() )

Only here I found more checks:

https://github.com/ycm-core/YouCompleteMe/blob/master/python/ycm/youcompleteme.py#L324

But again, this might be an irrelevant observation, since I'm not familiar with the code.

bstaletic commented 4 years ago

where is the value of ycm_disable_signature_help actually used / taken into account?

The ycm_ prefix is just that, a prefix. What you should have looked for is disable_signature_help, which is used on the server side:

ycmd/completers/completer.py:199:29:      if not user_options[ 'disable_signature_help' ] else None )
ycmd/completers/completer.py:242:28:    if self.user_options[ 'disable_signature_help' ]:
ycmd/completers/language_server/language_server_completer.py:789:52:    self._signature_help_disabled = user_options[ 'disable_signature_help' ]

So do I understand correctly that the first one only checks whether vim supports popup windows, and then the last one starts polling?

Yes, s:ShouldUseSignatureHelp() only checks if vim supports a list of necessary functions. The SendSignatureHelpRequest() is supposed to return early if there's no signature help supported. Try reverting https://github.com/ycm-core/YouCompleteMe/pull/3541 locally and see if that helps. Also, for some filetype that has a problem, check the output of echo &ft.

xenos1984 commented 4 years ago

Ah, I see, thanks for the clarification.

I locally reverted #3541, but again it had no effect, CPU usage stays high. Also I ran echo &ft on two of my test cases (both have the issue), and I got html and tex (as I expected).

xenos1984 commented 4 years ago

As a test and temporary workaround, I disabled s:ShouldUseSignatureHelp() by changing it such that it always returns 0, and indeed, CPU usage keeps low while typing in insert mode with completion enabled, and drops back to near 0 when not typing / leaving insert mode. That apparently kills signature help already at the earliest stage.

bstaletic commented 4 years ago

Thanks for confirming. Unfortunately, I can't repro, but I've compiled a list of functions that are called to make signature help work. Feel free to poke around and/or ask questions.

puremourning commented 4 years ago

I think the exists calls are expensive. And we should cache the result.

bstaletic commented 4 years ago

Here's a gist with the patch that caches that: https://gist.github.com/bstaletic/2ff17d054041b0da8816501112835e7f

@xenos1984 Can you test the patch?

xenos1984 commented 4 years ago

@bstaletic I tried the patch, but it does not make a notable difference - vim is still at around 30% CPU usage. It seems that caching on the python side is not enough. Maybe one should cache inside the vim script part already?

Also thanks for the suggestions, I'll play around with these functions and see whether I can figure something out. Also I'm wondering what might be different in my setup which makes me run into this issue, and which you cannot reproduce. I'll try a fresh install of YCM (even though I did this already, but apparently with a stale libclang - now I tried also clangd) and check whether that fixes the issue.

Would you mind capturing a profile as well, just for comparison? I wonder whether these functions are called just as often and take the same amount of time as in my case. What I did in the profile was enter insert mode in an empty html file and typing something like <html><head><title> - that was enough to trigger it.

bstaletic commented 4 years ago

Maybe one should cache inside the vim script part already?

Maybe. You can add something in autoload/youcompleteme.vim along the lines of what my patch does.

Would you mind capturing a profile as well, just for comparison?

https://gist.github.com/bstaletic/d18eb1dba8ee28def401874d5184cc3a

I opened YouCompleteMe/plugin/youcompleteme.vim wrote an empty function and deleted it.

xenos1984 commented 4 years ago

I'm not an expert in vim scripting, but I can give it a try.

Thanks also for the profile log. That looks indeed very similar to mine. Some questions come to my mind looking at these numbers:

As another test / workaround, I increased the poll timer interval to 100ms. CPU usage still increases notably, but significantly less (a few % instead of 30-50%; without signature help, it's less than 1%).

bstaletic commented 4 years ago

Is it really necessary / useful to poll the signature help functions that often, i.e., every 10ms, or could / should one increase the interval?

It should be fast enough to not notice the delay while typing. Completion also uses such a fast timer. Though that doesn't mean 10ms is right, just that it's 10ms because completion is 10ms and the use case is similar.

Does it make sense to poll these functions at all in a buffer / for a file type which does not support signature help? Or should one rather disable the timer completely in that case?

It was just easier to implement that logic in python.

Shouldn't signature help / the poll timer be switched off when leaving insert mode?

It is, or should be, stopped whenever s:ClearSignatureHelp() is called. See here. You can put the following function in the autoload/youcompleteme.vim:

function! youcompleteme#PollTest()
    return s:pollers.signature_help.id
endfunction

Then do :echo youcompleteme#PollTest() and see what's the ID returned. If the timer is stopped, it should be -1.

As another test / workaround, I increased the poll timer interval to 100ms. CPU usage still increases notably, but significantly less (a few % instead of 30-50%; without signature help, it's less than 1%).

For me the CPU usage is around 3% to 5% in insert mode. I'm on a i7-2620M. Somehow I doubt that CPU is 10x faster than whatever you have.

xenos1984 commented 4 years ago

It should be fast enough to not notice the delay while typing. Completion also uses such a fast timer.

That does make sense. Still I wonder why the signature help functions are called more than 100 times more often than the completion ones (according to the profile, s:RequestCompletion() was called 25 times, while the two functions from above were called nearly 4000 times).

It was just easier to implement that logic in python.

I see, that also sounds reasonable to me

It is, or should be, stopped whenever s:ClearSignatureHelp() is called.

Indeed, that's what I was thinking, but...

Then do :echo youcompleteme#PollTest() and see what's the ID returned. If the timer is stopped, it should be -1.

...that gives me some positive number (23082) instead, so it seems that the timer keeps running after leaving insert mode.

For me the CPU usage is around 3% to 5% in insert mode. I'm on a i7-2620M. Somehow I doubt that CPU is 10x faster than whatever you have.

That's what's bugging me about this issue. I don't see a reason how my setup differs to make my CPU usage that much higher. Certainly not the CPU (i7-8550U here). Maybe a different vim version, so that mine could actually be buggy and the bug is triggered by the poll timer?

bstaletic commented 4 years ago

Then do :echo youcompleteme#PollTest() and see what's the ID returned. If the timer is stopped, it should be -1.

...that gives me some positive number (23082) instead, so it seems that the timer keeps running after leaving insert mode.

My bad. I also get a positive number. timer_stop() indeed doesn't reset the ID. However, there's :call timer_stopall() that you can try and see if it brings down the CPU usage.

As for thte vim version, I'm on 8.1.2268.

xenos1984 commented 4 years ago

However, there's :call timer_stopall() that you can try and see if it brings down the CPU usage.

Indeed, that brings down CPU usage immediately. Typing in insert mode raises it again as before, and :call timer_stopall() brings it down again. So I guess there remains a stale poll timer...

bstaletic commented 4 years ago

Try sprinkling echom 'whatever' throughout s:OnInsertLeave() and s:ClearSignatureHelp() and see if the call to the relevant timer_stop is even executed. Also helpful would be :echo timer_info().

EDIT: Use :messages to see what the echom printed.

xenos1984 commented 4 years ago

Now that is interesting. First, my changes:

function! s:OnInsertLeave()
  echom "OnInsertLeave begin"
  if !s:AllowedToCompleteInCurrentBuffer()
    return
  endif

  call timer_stop( s:pollers.completion.id )
  let s:force_semantic = 0
  let s:completion = s:default_completion

  call s:OnFileReadyToParse()
  exec s:python_command "ycm_state.OnInsertLeave()"
  if g:ycm_autoclose_preview_window_after_completion ||
        \ g:ycm_autoclose_preview_window_after_insertion
    call s:ClosePreviewWindowIfNeeded()
  endif

  echom "OnInsertLeave near end"
  call s:ClearSignatureHelp()
  echom "OnInsertLeave end"
endfunction

function! s:ClearSignatureHelp()
  echom "ClearSignatureHelp begin"
  if !s:ShouldUseSignatureHelp()
    return
  endif

  echom "ClearSignatureHelp call timer stop"
  call timer_stop( s:pollers.signature_help.id )
  echom "ClearSignatureHelp timer stop done"
  let s:signature_help = s:default_signature_help
  call s:Pyeval( 'ycm_state.ClearSignatureHelp()' )
  echom "ClearSignatureHelp end"
endfunction

And this is the output:

ClearSignatureHelp begin
ClearSignatureHelp call timer stop
ClearSignatureHelp timer stop done
ClearSignatureHelp end
OnInsertLeave begin
ClearSignatureHelp begin
ClearSignatureHelp call timer stop
ClearSignatureHelp timer stop done
ClearSignatureHelp end
OnInsertLeave near end
ClearSignatureHelp begin
ClearSignatureHelp call timer stop
ClearSignatureHelp timer stop done
ClearSignatureHelp end
OnInsertLeave end

So apparently the timer_stop() does get executed. But timer_info() tells me:

[{'id': 19233, 'repeat': 1, 'remaining': 9, 'time': 10, 'paused': 0, 'callback': function('<SNR>73_PollSignatureHelp')}]

If I call the same function repeatedly, the timer id changes every time. Looks like the timer keeps on restarting.

xenos1984 commented 4 years ago

Huh, now that's even worse. If I just keep working and typing for a while, vim CPU usage rises to 100%. timer_info() shows some 20-30 timers, all of them calling <SNR>73_PollSignatureHelp.

bstaletic commented 4 years ago 
function! s:PollSignatureHelp( ... )
  if !s:ShouldUseSignatureHelp()
    return
  endif

  if !py3eval( 'ycm_state.SignatureHelpRequestReady()' )
    let s:pollers.signature_help.id = timer_start(
          \ s:pollers.signature_help.wait_milliseconds,
          \ function( 's:PollSignatureHelp' ) )
    return
  endif

  let s:signature_help = py3eval( 'ycm_state.GetSignatureHelpResponse()' )
  call s:UpdateSignatureHelp()
endfunction

The idea is that the timer should self-restart until ycm_state.SignatureHelpRequestReady() becomes true. Each timer_start() call does change the ID. However, s:ClearSignatureHelp() should stop that loop by calling timer_stop.

xenos1984 commented 4 years ago

Indeed, so then I understood correctly. I'm puzzled about the 'repeat': 1 in the timer info. Looking at the YCM and vim sources, I would have expected that this should be 0 instead...

xenos1984 commented 4 years ago

Ah, never mind about the repeat. The timer_info adds 1 to the actual value, so that's correct.

Anyway, I analysed the profile I captured and I have kind of a suspicion what might be going on, comparing completion and signature help. So that is what happens on completion:

Now for signature help this happens:

That's just a suspicion, as much as I understand the code by now. Maybe there is some function I have not yet found that prevents timers from piling up.

bstaletic commented 4 years ago

In the meantime, s:RequestSignatureHelp() may be called again (25 times in my profile log) and pile up another timer instance.

Remember, s:RequestSignatureHelp() happens only on TextChangedI event, i.e. when you type in insert mode without the completion menu open. There's another event, called InsertCharPre that is triggered before TextChangedI. The relelvant functions are:

As you can see, those functions treat the completion and signature help timer identically.

 

EDIT: But you are right that if there's no signature help support, at least in insert mode, the timer will keep looping, as these lines never get executed, so self._latest_signature_help_response remains None and these lines never return True.

puremourning commented 4 years ago

yeah I think we should have SendSignatureHelpRequest return False if no request was generated, in which case, we should not call s:PollSignatureHelp.

So we need at least these changes:

I'll look at these changes today.

Thanks again for helping look into this, @bstaletic and @xenos1984

puremourning commented 4 years ago

Guys, can you try this patch ?

https://github.com/puremourning/YouCompleteMe/tree/sig-help-perf

https://github.com/puremourning/YouCompleteMe/commit/feb00b0cf10cae537a600f476f1dab4ca0049622