deoplete window doesn't appear for ~5s

[jonahx]

deoplete.log

log_py3_neovim_rpc_server.log

log_py3_deoplete.log Warning: I will close the issue without the minimal init.vim and the reproduce ways.

Problems summary

It takes about 5 seconds for the deoplete window to appear on a minimal .vimrc test on a 16G MacBook pro with vim8 (macvim). Here's a video showing the problem:

Expected

deoplete window appears almost instantly

Environment Information

• deoplete version(SHA1): 6924385c96fe606cf588467d418df3d2f1c364ef plugin/deoplete.vim (I installed it last night so this should be current)

• OS: OSX Sierra 10.12.6

• neovim/Vim version: MacVim version 8.0.1376

• :checkhealth or :CheckHealth result(neovim only):

Provide a minimal init.vim/vimrc with less than 50 lines (Required!)

set pythonthreedll=/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/Python
set rubydll=/usr/local/Cellar/ruby/2.4.2_1/lib/libruby.2.4.dylib
set luadll=/usr/local/Cellar/lua/5.3.4_2/lib/liblua.dylib

set rtp+=~/.vim/bundle/vim-hug-neovim-rpc/
set rtp+=~/.vim/bundle/nvim-yarp/
set rtp+=~/.vim/bundle/deoplete.nvim/
let g:deoplete#enable_at_startup = 1
let g:deoplete#enable_yarp = 1
let g:deoplete#enable_profile = 1
call deoplete#enable_logging('DEBUG', 'deoplete.log')

The reproduce ways from neovim/Vim starting (Required!)

1. mvim
2. :e .vimrc
3. Type rt, wait for deoplete window with rtp suggestions to appear (5 seconds), select one, hit enter, the quit.

Generate a logfile if appropriate

1. export NVIM_PYTHON_LOG_FILE=/tmp/log
2. export NVIM_PYTHON_LOG_LEVEL=DEBUG
3. nvim -u minimal.vimrc
4. some works
5. cat /tmp/log_{PID}

Screen shot (if possible)

See video above

Upload the log file

Log files and both /tmp/log files are attached.

[Shougo]

I will look into the problem.

[Shougo]

I have checked deoplete.log.

2017-12-13 23:05:37,824 DEBUG    (deoplete.core) Profile Start: around
2017-12-13 23:05:37,831 DEBUG    (deoplete.core) Profile End  : around                    time=0.0030720000
...
2017-12-13 23:05:37,892 DEBUG    (deoplete.core) Profile Start: converter_truncate_menu
2017-12-13 23:05:37,892 DEBUG    (deoplete.core) Profile End  : converter_truncate_menu   time=0.0000030000

The time is not so bad.

[Shougo]

Please test neovim instead. It may be nvim-yarp or vim-hug-neovim rpc problem.

[Shougo]

I have checked other log. deoplete works properly.

2017-12-13 23:05:37,895 [DEBUG @ session.py:response_cb:148] 22986 - response is available for greenlet <greenlet.greenlet object at 0x110647af8>, switching back
2017-12-13 23:05:37,896 [DEBUG @ msgpack_stream.py:send:33] 22986 - sent [0, 82, 'nvim_call_function', ('deoplete#handler#_completion_timer_start', [])]
2017-12-13 23:05:37,896 [DEBUG @ base.py:send:113] 22986 - Sending 'b'\x94\x00R\xb2nvim_call_function\x92\xda\x00(deoplete#handler#_completion_timer_start\x90''
2017-12-13 23:05:37,896 [DEBUG @ session.py:_yielding_request:152] 22986 - yielding from greenlet <greenlet.greenlet object at 0x110647af8> to wait for response
2017-12-13 23:05:37,896 [DEBUG @ msgpack_stream.py:_on_data:54] 22986 - waiting for message...
2017-12-13 23:05:37,896 [DEBUG @ msgpack_stream.py:_on_data:59] 22986 - unpacker needs more data...
2017-12-13 23:05:37,897 [DEBUG @ msgpack_stream.py:_on_data:54] 22986 - waiting for message...
2017-12-13 23:05:37,898 [DEBUG @ msgpack_stream.py:_on_data:56] 22986 - received message: [1, 82, None, 0]
2017-12-13 23:05:37,898 [DEBUG @ async_session.py:_on_response:95] 22986 - received response: None, 0
2017-12-13 23:05:37,898 [DEBUG @ session.py:response_cb:148] 22986 - response is available for greenlet <greenlet.greenlet object at 0x110647af8>, switching back
2017-12-13 23:05:37,898 [DEBUG @ session.py:handler:207] 22986 - greenlet <greenlet.greenlet object at 0x110647af8> finished executing
2017-12-13 23:05:37,898 [DEBUG @ session.py:handler:212] 22986 - greenlet <greenlet.greenlet object at 0x110647af8> is now dying...
2017-12-13 23:05:37,898 [DEBUG @ msgpack_stream.py:_on_data:54] 22986 - waiting for message...
2017-12-13 23:05:37,898 [DEBUG @ msgpack_stream.py:_on_data:59] 22986 - unpacker needs more data...

deoplete#handler#_completion_timer_start() is called.

[Shougo]

Please check your g:deoplete#auto_complete_delay value.

[Shougo]

I cannot reproduce it on Vim8 using below vimrc.

set rtp+=~/.cache/dein/repos/github.com/Shougo/deoplete.nvim/
set rtp+=~/.cache/dein/repos/github.com/roxma/nvim-yarp/
set rtp+=~/.cache/dein/repos/github.com/roxma/vim-hug-neovim-rpc/

let g:deoplete#enable_at_startup = 1

filetype plugin indent on
syntax enable

Please test the minimal vimrc.

[Shougo]

My Vim version is 8.0.1386.

[Shougo]

Have you read your log_py3_neovim_rpc_server.log?

It seems broken.

2017-12-13 23:05:37,873 [INFO @ neovim_rpc_server.py:process_pending_requests:340] 22981 - get msg from channel [1]: [0, 66, 'nvim_err_write', ["[deoplete]     m = re.match('\\S+', context['next_input'])\n"]]
2017-12-13 23:05:37,873 [INFO @ neovim_rpc_server.py:process_pending_requests:368] 22981 - sending result: [1, 66, None, None]
2017-12-13 23:05:37,873 [INFO @ neovim_rpc_server.py:process_pending_requests:371] 22981 - sended
2017-12-13 23:05:37,874 [INFO @ neovim_rpc_server.py:handle:173] 22981 - unpacked: [0, 67, b'nvim_err_write', [b'[deoplete]   File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/re.py", line 172, in match\n']]
2017-12-13 23:05:37,874 [INFO @ neovim_rpc_server.py:notify:73] 22981 - sending notification: ["ex", "call neovim_rpc#_callback()"]
2017-12-13 23:05:37,874 [INFO @ neovim_rpc_server.py:process_pending_requests:328] 22981 - process_pending_requests
2017-12-13 23:05:37,874 [INFO @ neovim_rpc_server.py:process_pending_requests:340] 22981 - get msg from channel [1]: [0, 67, 'nvim_err_write', ['[deoplete]   File "/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/re.py", line 172, in match\n']]
2017-12-13 23:05:37,874 [INFO @ neovim_rpc_server.py:process_pending_requests:368] 22981 - sending result: [1, 67, None, None]
2017-12-13 23:05:37,874 [INFO @ neovim_rpc_server.py:process_pending_requests:371] 22981 - sended
2017-12-13 23:05:37,875 [INFO @ neovim_rpc_server.py:handle:173] 22981 - unpacked: [0, 68, b'nvim_err_write', [b'[deoplete]     return _compile(pattern, flags).match(string)\n']]
2017-12-13 23:05:37,875 [INFO @ neovim_rpc_server.py:notify:73] 22981 - sending notification: ["ex", "call neovim_rpc#_callback()"]
2017-12-13 23:05:37,875 [INFO @ neovim_rpc_server.py:process_pending_requests:328] 22981 - process_pending_requests
2017-12-13 23:05:37,875 [INFO @ neovim_rpc_server.py:process_pending_requests:340] 22981 - get msg from channel [1]: [0, 68, 'nvim_err_write', ['[deoplete]     return _compile(pattern, flags).match(string)\n']]
2017-12-13 23:05:37,875 [INFO @ neovim_rpc_server.py:process_pending_requests:368] 22981 - sending result: [1, 68, None, None]
2017-12-13 23:05:37,876 [INFO @ neovim_rpc_server.py:process_pending_requests:371] 22981 - sended
2017-12-13 23:05:37,876 [INFO @ neovim_rpc_server.py:handle:173] 22981 - unpacked: [0, 69, b'nvim_err_write', [b'[deoplete] TypeError: expected string or bytes-like object\n']]

The many error messages are saved. Please check your :messages result.

It seems not deoplete problem.

And why you have set this?

set pythonthreedll=/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/Python

[jonahx]

Thanks for looking into this.

And why you have set this?....

See https://github.com/macvim-dev/macvim/wiki/FAQ#how-to-use-pythonrubylua-interface-in-macvim. I believe I put it in because has('python3') wasn't working without that...

Have you read your log_py3_neovim_rpc_server.log? It seems broken.

So does that mean I should stick with your advice to try neovim instead? Do you use neovim in the terminal only or do you use neovim dot app or another GUI version?

Thanks again.

[jonahx]

I tried removing the line:

set pythonthreedll=/usr/local/Cellar/python3/3.6.3/Frameworks/Python.framework/Versions/3.6/Python

and it still worked ok, but it didn't fix the issue (still had the 5s delay)

[Shougo]

See https://github.com/macvim-dev/macvim/wiki/FAQ#how-to-use-pythonrubylua-interface-in-macvim. I believe I put it in because has('python3') wasn't working without that...

Hm.... I don't know why. But I recommend for you to build Vim manually.

[Shougo]

Please check your :messages result.

Please do this.

[Shougo]

So does that mean I should stick with your advice to try neovim instead? Do you use neovim in the terminal only or do you use neovim dot app or another GUI version?

I use neovim in the terminal only.

[jonahx]

Please do this.

It showed only the "Logging to deoplete.log" message.

[Shougo]

It showed only the "Logging to deoplete.log" message.

Really? It is the after of the completion?

[jonahx]

Really? It is the after of the completion?

Correct. I redid the same steps as I outlined, made one completion, then executed :messages.

[Shougo]

I cannot reproduce the problem on Vim8 Linux.... The handler is called properly.

I don't have the magic. You can investigate it though.

https://github.com/Shougo/deoplete.nvim/blob/master/autoload/deoplete/handler.vim#L74

Here is the callback.

[jonahx]

I will take your advice and try rebuilding macvim from scratch. I will report back what happens. If it continues to fail, I will probably just switch to neovim. I mainly like the gui because the fonts look nicer.

[Shougo]

I also like GUI. But the performance is very important for me.

[roxma]

Hi, there used to be a wired issue on NCM on vim8. https://github.com/roxma/nvim-completion-manager/issues/47#issuecomment-285705014

The complete() function is called by the async completion engine, but the popup menu is not displayed.

It is fixed by adding arbitrary timer.

I'm not sure it's relevant. Just post here in case it's useful.

[roxma]

Have you read your log_py3_neovim_rpc_server.log?

It seems broken.

2017-12-13 23:05:37,822 [INFO @ neovim_rpc_server.py:notify:229] 22981 - notify channel[1]: [2, 'deoplete_auto_completion_begin', [{'max_menu_width': 117, 'cwd': '/Users/jgoldstein', 'vars': {'deoplete#complete_method': 'complete', 'deoplete#omni#functions': {}, 'deoplete#_initialized': 1, 'deoplete#auto_complete_delay': 50, 'deoplete#max_abbr_width': 80, 'deoplete#enable_yarp': 1, 'deoplete#_rank': {}, 'deoplete#enable_on_insert_enter': 1, 'deoplete#omni#input_patterns': {}, 'deoplete#sources': {}, 'deoplete#auto_refresh_delay': 500, 'deoplete#_channel_id': 1, 'deoplete#ignore_sources': {}, 'deoplete#max_list': 100, 'deoplete#member#prefix_patterns': {}, 'deoplete#delimiters': ['/'], 'deoplete#omni_patterns': {}, 'deoplete#enable_refresh_always': 0, 'deoplete#enable_camel_case': 0, 'deoplete#enable_smart_case': 0, 'deoplete#_logging': {'level': 'DEBUG', 'logfile': 'deoplete.log'}, 'deoplete#auto_complete_start_length': 2, 'deoplete#disable_auto_complete': 0, 'deoplete#_keyword_patterns': {'_': '[a-zA-Z_]\\k*'}, 'deoplete#enable_at_startup': 1, 'deoplete#enable_profile': 1, 'deoplete#_context': {'complete_position': -1, 'candidates': [], 'event': 'TextChangedI', 'input': 'r'}, 'deoplete#max_menu_width': 40, 'deoplete#keyword_patterns': {}, 'deoplete#_omni_patterns': {'xhtml': ['<', '</', '<[^>]*\\s[[:alnum:]-]*'], 'xml': ['<', '</', '<[^>]*\\s[[:alnum:]-]*'], 'html': ['<', '</', '<[^>]*\\s[[:alnum:]-]*']}, 'deoplete#skip_chars': [], 'deoplete#enable_ignore_case': 0}, 'same_filetypes': [], 'smartcase': 0, 'runtimepath': '/Users/jgoldstein/.vim,/Applications/MacVim.app/Contents/Resources/vim/vimfiles,/Applications/MacVim.app/Contents/Resources/vim/runtime,/Applications/MacVim.app/Contents/Resources/vim/vimfiles/after,/Users/jgoldstein/.vim/after,/Users/jgoldstein/.vim/bundle/vim-hug-neovim-rpc/,/Users/jgoldstein/.vim/bundle/nvim-yarp/,/Users/jgoldstein/.vim/bundle/deoplete.nvim/', 'bufvars': {}, 'bufnr': 1, 'changedtick': 7, 'custom': {'source': {'_': {}}}, 'omni__omnifunc': '', 'filetype': 'vim', 'input': 'rt', 'is_windows': False, 'delay': 50, 'bufsize': 497, 'max_kind_width': 117, 'rpc': 'deoplete_auto_completion_begin', 'bufpath': '/Users/jgoldstein/.vimrc', 'bufname': '.vimrc', 'event': 'TextChangedI', 'max_abbr_width': 117, 'sources': [], 'complete_str': '', 'camelcase': 0, 'ignorecase': 0, 'filetypes': ['vim'], 'keyword_patterns': '[a-zA-Z_][a-zA-Z@0-9_À-ÿ]*', 'dict__dictionary': '', 'position': [0, 12, 3, 0], 'next_input': None, 'encoding': 'utf-8'}]]

highlight:

'next_input': None

Wired that \ 'next_input': deoplete#util#get_next_input(a:event), at autoload/deoplete/init.vim:219 gets a None in python.

[roxma]

hmm... This vimscript gets {"a":null} on my vim8. (simulating in the way vim-hug-neovim-rpc works)

enew
python import vim
python print vim.eval('json_encode({"a":getline(".")[100:]})')

This version works on my side: {'a': ''}

enew
python import vim
python print vim.eval('{"a":getline(".")[100:]}')

[Shougo]

It is fixed by adding arbitrary timer.

OK. I get it. Vim8 is buggy. Huh...

[roxma]

I have ditched the json_encode implementation, could you update vim-hug-neovim-rpc and try again?

If the issue is still there, log files are needed.

// cc @jsfaint

[Shougo]

OH, thank you!

[jsfaint]

@roxma Works for me, this fix reduce the time from 3s to 1s on windows. although it is still slower than neovim, but can be acceptable Thanks

[Shougo]

@jonahx Please test the latest vim-hug-neovim-rpc.

[jonahx]

I will test tomorrow and let you know. Thanks.

[Shougo]

@jonahx Ping.

[jonahx]

@Shougo I updated vim-hug-neovim-rpc, but that did not resolve the problem.

[Shougo]

Please test below steps. I need more information.

1. Please test CUI version of Vim

2. Please test the latest Vim

3. Please test neovim

4. Please add call deoplete#handler#_async_timer_start() in autoload/deoplete/handler.vim L33.

[jonahx]

Please test CUI version of Vim

What is this?

Please test the latest Vim

I've tested: VIM - Vi IMproved 8.0 (2016 Sep 12, compiled Dec 7 2017 16:07:42). Is that not the correct version?

Please test neovim

Everything works fine in neovim. I made the .vimrc adjustments per the deoplete install instructions before testing in neovim.

Please add call deoplete#handler#_async_timer_start() in autoload/deoplete/handler.vim L33.

I got a "Command too recursive" error. But I'm not sure I did what you wanted. Here is how my handler looks...

 28   if g:deoplete#enable_refresh_always
 29     autocmd deoplete InsertCharPre *
 30           \ call s:completion_begin('InsertCharPre')
 31   endif
 32 endfunction
 33 call deoplete#handler#_async_timer_start()  "<---I added it here....
 34 function! s:do_complete(timer) abort
 35   let context = g:deoplete#_context

[Shougo]

I got a "Command too recursive" error. But I'm not sure I did what you wanted. Here is how my handler looks...

Please add it in L32 after endif.

[Shougo]

What is this?

MacVim is GUI version of Vim. Please test CUI version instead.

I've tested: VIM - Vi IMproved 8.0 (2016 Sep 12, compiled Dec 7 2017 16:07:42). Is that not the correct version?

It is old. Please build the latest version manually.

[jonahx]

It is old. Please build the latest version manually.

I will attempt this later tonight.

[jonahx]

I successfully compiled macvim following the instructions here: https://github.com/macvim-dev/macvim/wiki/Building-%28not-recommended-way%29

However, it did not solve the problem.

Note that after cloning from github and building, the version still lists an old date, I'm not sure why...

VIM - Vi IMproved 8.0 (2016 Sep 12, compiled Dec 19 2017 22:10:03)
macOS version
Included patches: 1-1397

[Shougo]

OK.

Please add it in L32 after endif.

I cannot change it until you have tried.

And

Please test CUI version of Vim

[kiryph]

I have the same issue that I have to wait a long time until the deoplete window appears. It seems related to the MacVIM Gui. The vim binary contained in Macvim.app can be used on the command line (CUI) and works fine:

❯ which vim
vim: aliased to /Applications/MacVim.app/Contents/MacOS/Vim
❯ vim --version
VIM - Vi IMproved 8.0 (2016 Sep 12, compiled Dec  7 2017 16:07:42)
macOS version
Included patches: 1-1376
Compiled by travis@Traviss-Mac-1055.local
Huge version with MacVim GUI.

I didn't have this issue with neocomplete which I had used the last several years with Macvim GUI.

[kiryph]

@Shougo Thanks for the update. I can confirm that the delay is gone.

[jonahx]

@Shougo @kiryph Is this supposed to fix the delay on macvim? I've updated deoplete but still see the delay in macvim GUI. Thanks.

[Shougo]

@Shougo @kiryph Is this supposed to fix the delay on macvim? I've updated deoplete but still see the delay in macvim GUI. Thanks.

I gave up. It is just tricky hack. I don't want to support the problem anymore. It should be reported in MacVim issues. I cannot reproduce the problem in GVim. So it is not Vim issue.

[markonm]

Delay is also present in gVim (v8.0.1417) on Windows 10. If blank timer is used, as @roxma suggests, problem goes away. I would like to report the problem to Vim but I'm struggling with providing minimal reproducible steps.

[Shougo]

I have added the timer in the latest version.

[Shougo]

I don't want to add the blank timer because https://github.com/Shougo/deoplete.nvim/issues/543

[markonm]

I tested the latest version and delay is still present. I understand why you don't want to add unnecessary timer. The best solution would be to report problem to Vim directly.

[Shougo]

I can add the timer, but when it is removed?

[Shougo]

@jonahx @xtal8 Please test the latest version. I have tired.

[markonm]

It does not work. Delay is still present. But if I add the following snippet to my vimrc than the delay is gone.

func! g:Foo(...)
" do nothing
endfunc
call timer_start(30,function('g:Foo'),{'repeat':-1})

I didn't mention but on Windows's gVim, delay is only very noticeable when I turn off cursor blinking. If blinking is on than the delay is dependent on blinking refresh rate.

[Shougo]

Please test the latest version again.

[Shougo]

I have understood the problem. The ugly timer is needed.