Completion menu show up time is long if a source is slow

[jsfaint]

Warning: I will close the issue without the minimal init.vim and the reproduction instructions.

Problems summary

I compared deoplete with ncm.
In ncm, if a source is slow, it will not impact the completion menu show up time.
But in ncm, if a source is slow, it will impact the completion menu show up time.

Expected

If some source is slow, the faster source should show in completion menu first.

Environment Information

• deoplete version(SHA1):
  c145a7f

• OS:
  windows 10

• neovim/Vim version:
  NVIM 0.2.2

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

health#deoplete#check
========================================================================
## deoplete.nvim
  - OK: has("nvim") was successful
  - OK: has("python3") was successful
  - INFO: If you're still having problems, try the following commands:
    $ export NVIM_PYTHON_LOG_FILE=/tmp/log
    $ export NVIM_PYTHON_LOG_LEVEL=DEBUG
    $ nvim
    $ cat /tmp/log_{PID}
    and then create an issue on github

health#nvim#check
========================================================================
## Configuration
  - OK: no issues found

## Performance
  - OK: Build type: RelWithDebInfo

## Remote Plugins
  - OK: Up to date

health#provider#check
========================================================================
## Clipboard (optional)
  - OK: Clipboard tool found: win32yank

## Python 2 provider (optional)
  - WARNING: No Python interpreter was found with the neovim module.  Using the first available for diagnostics.
  - WARNING: provider/pythonx: Could not load Python 2:
    python2 not found in search path or not executable.
    python2.7 not found in search path or not executable.
    python2.6 not found in search path or not executable.
    C:\Users\jia.sui\AppData\Local\Programs\Python\Python36\python is Python 3.6 and cannot provide Python 2.
  - ERROR: Python provider error
    - ADVICE:
      - provider/pythonx: Could not load Python 2:
          python2 not found in search path or not executable.
          python2.7 not found in search path or not executable.
          python2.6 not found in search path or not executable.
          C:\Users\jia.sui\AppData\Local\Programs\Python\Python36\python is Python 3.6 and cannot provide Python 2.
  - INFO: Executable: Not found

## Python 3 provider (optional)
  - INFO: Using: g:python3_host_prog = "C:/Users/jia.sui/AppData/Local/Programs/Python/Python36/python.exe"
  - INFO: Executable: C:/Users/jia.sui/AppData/Local/Programs/Python/Python36/python.exe
  - INFO: Python3 version: 3.6.4
  - INFO: python.exe-neovim version: 0.2.1
  - OK: Latest python.exe-neovim is installed: 0.2.1

## Ruby provider (optional)
  - WARNING: `ruby` and `gem` must be in $PATH.
    - ADVICE:
      - Install Ruby and verify that `ruby` and `gem` commands work.

## Node provider (optional)
  - INFO: Node: v8.9.0
  - WARNING: Missing "neovim" npm package.
    - ADVICE:
      - Run in shell: npm install -g neovim
      - Is the npm bin directory in $PATH?

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

let s:rc_path = fnamemodify(expand('<sfile>'), ':h')

let s:vimplug = expand(s:rc_path . '/autoload')

if empty(glob(s:vimplug . '/plug.vim'))
  execute '!git clone --depth=1 https://github.com/junegunn/vim-plug' s:vimplug
  augroup vimrc
    autocmd VimEnter * PlugInstall
  augroup END
endif

call plug#begin(s:rc_path . '/plugged')

"Completion
Plug 'Shougo/deoplete.nvim', { 'do': ':UpdateRemotePlugins' }

call plug#end()

"deoplete.nvim
if (has('nvim') || v:version >= 800) && has('python3')
  let g:deoplete#enable_at_startup = 1
  let g:deoplete#num_processes = 20
endif

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

1. Add a time.sleep(10) in gather_candidates() tag.py

diff --git a/rplugin/python3/deoplete/source/tag.py b/rplugin/python3/deoplete/source/tag.py
index 1dcec7f..7a32695 100644
--- a/rplugin/python3/deoplete/source/tag.py
+++ b/rplugin/python3/deoplete/source/tag.py
@@ -33,6 +33,8 @@ class Source(Base):
       self._make_cache(context)

   def gather_candidates(self, context):
+        import time
+        time.sleep(10)
       self._make_cache(context)
       candidates = []
       for c in self._cache.values():

2. Add
3. Open any files, then type something
4. The completion window will show up after 10s

Screen shot (if possible)

Upload the log file

deoplete.log

[Shougo]

Reproduced.

[Shougo]

diff --git a/rplugin/python3/deoplete/parent.py b/rplugin/python3/deoplete/parent.py
index 97cb510..b03ea7d 100644
--- a/rplugin/python3/deoplete/parent.py
+++ b/rplugin/python3/deoplete/parent.py
@@ -88,5 +88,5 @@ class Parent(logger.LoggingMixin):
         return queue_id

     def _get(self, queue_id):
-        return [x for x in self._proc.communicate(40)
+        return [x for x in self._proc.communicate(0.02)
                 if x['queue_id'] == queue_id]

Here is the patch for it.

[jsfaint]

Thanks for the quick response, but it's a pity, this patch not works for me.

Patch on deoplete

diff --git a/rplugin/python3/deoplete/parent.py b/rplugin/python3/deoplete/parent.py
index 97cb510..b03ea7d 100644
--- a/rplugin/python3/deoplete/parent.py
+++ b/rplugin/python3/deoplete/parent.py
@@ -88,5 +88,5 @@ class Parent(logger.LoggingMixin):
         return queue_id

     def _get(self, queue_id):
-        return [x for x in self._proc.communicate(40)
+        return [x for x in self._proc.communicate(0.02)
                 if x['queue_id'] == queue_id]
diff --git a/rplugin/python3/deoplete/source/tag.py b/rplugin/python3/deoplete/source/tag.py
index 1dcec7f..7a32695 100644
--- a/rplugin/python3/deoplete/source/tag.py
+++ b/rplugin/python3/deoplete/source/tag.py
@@ -33,6 +33,8 @@ class Source(Base):
         self._make_cache(context)

     def gather_candidates(self, context):
+        import time
+        time.sleep(10)
         self._make_cache(context)
         candidates = []
         for c in self._cache.values():

Here is the new log file
deoplete.log

[Shougo]

It works for me.
But it does not work sometimes.
I don't know why.

[Shougo]

http://drmingdrmer.github.io/tech/programming/2017/11/20/python-concurrent-popen.html

[Shougo]

I should use concurrent.futures.ProcessPoolExecutor() instead.
I will try it later.

[Shougo]

I have tested concurrent.futures.ProcessPoolExecutor().
It is better than before, but it cannot fix the problem completely.
It needs async io support.

neovim/pynvim#294

[Shougo]

diff --git a/rplugin/python3/deoplete/deoplete.py b/rplugin/python3/deoplete/deoplete.py
index 0ce7e54..75f57fb 100644
--- a/rplugin/python3/deoplete/deoplete.py
+++ b/rplugin/python3/deoplete/deoplete.py
@@ -4,6 +4,8 @@
 # License: MIT license
 # ============================================================================
 
+from concurrent.futures import ThreadPoolExecutor
+
 from deoplete import logger
 from deoplete.parent import Parent
 from deoplete.util import (error_tb, find_rplugins)
@@ -38,8 +40,9 @@ class Deoplete(logger.LoggingMixin):
         context['rpc'] = 'deoplete_on_event'
 
         # Init processes
+        self._executor = ThreadPoolExecutor(max_workers=4)
         for n in range(0, self._max_parents):
-            self._parents.append(Parent(vim, context))
+            self._parents.append(Parent(vim, context, self._executor))
         if self._vim.vars['deoplete#_logging']:
             for parent in self._parents:
                 parent.enable_logging()
diff --git a/rplugin/python3/deoplete/parent.py b/rplugin/python3/deoplete/parent.py
index 6dba494..a97e470 100644
--- a/rplugin/python3/deoplete/parent.py
+++ b/rplugin/python3/deoplete/parent.py
@@ -13,7 +13,7 @@ from deoplete.process import Process
 
 class Parent(logger.LoggingMixin):
 
-    def __init__(self, vim, context):
+    def __init__(self, vim, context, executor):
         self.name = 'parent'
 
         self._vim = vim
@@ -21,7 +21,7 @@ class Parent(logger.LoggingMixin):
         self._child = None
         self._queue_id = ''
         self._prev_pos = []
-        self._start_process(context)
+        self._start_process(context, executor)
 
     def enable_logging(self):
         self._put('enable_logging', [])
@@ -68,14 +68,14 @@ class Parent(logger.LoggingMixin):
         if context['event'] == 'VimLeavePre':
             self._stop_process()
 
-    def _start_process(self, context):
+    def _start_process(self, context, executor):
         if self._vim.vars['deoplete#num_processes'] > 1:
             # Parallel
             python3 = self._vim.vars.get('python3_host_prog', 'python3')
             self._proc = Process(
                 [python3, context['dp_main'],
                  self._vim.vars['deoplete#_serveraddr']],
-                context, context['cwd'])
+                context, context['cwd'], executor)
         else:
             # Serial
             from deoplete.child import Child
diff --git a/rplugin/python3/deoplete/process.py b/rplugin/python3/deoplete/process.py
index 728f7fe..5bfc657 100644
--- a/rplugin/python3/deoplete/process.py
+++ b/rplugin/python3/deoplete/process.py
@@ -7,13 +7,12 @@
 import subprocess
 import os
 import msgpack
-from threading import Thread
 from queue import Queue
 from time import time, sleep
 
 
 class Process(object):
-    def __init__(self, commands, context, cwd):
+    def __init__(self, commands, context, cwd, executor):
         startupinfo = None
         if os.name == 'nt':
             startupinfo = subprocess.STARTUPINFO()
@@ -33,18 +32,16 @@ class Process(object):
             encoding='utf-8',
             unicode_errors='surrogateescape')
         self._queue_out = Queue()
-        self._thread = Thread(target=self.enqueue_output)
-        self._thread.start()
+        self._future = executor.submit(self.enqueue_output)
 
     def kill(self):
         if not self._proc:
             return
+        self._future.cancel()
         self._proc.kill()
         self._proc.wait()
         self._proc = None
         self._queue_out = None
-        self._thread.join(1.0)
-        self._thread = None
 
     def enqueue_output(self):
         while self._proc:
diff --git a/rplugin/python3/deoplete/source/tag.py b/rplugin/python3/deoplete/source/tag.py
index b407d03..88f2f9b 100644
--- a/rplugin/python3/deoplete/source/tag.py
+++ b/rplugin/python3/deoplete/source/tag.py
@@ -33,6 +33,8 @@ class Source(Base):
         self._make_cache(context)
 
     def gather_candidates(self, context):
+        import time
+        time.sleep(10)
         self._make_cache(context)
         candidates = []
         for c in self._cache.values():

You can test the patch.

[jsfaint]

@Shougo Thanks for your effort.
I'm just curious that how did ncm handle this condition?
Can you introduce something please? @roxma 😄

[Shougo]

I'm just curious that how did ncm handle this condition?

nvim-completion-manager uses neovim event loop instead.
deoplete does not use it.

[jsfaint]

I tried the patch on windows, it doesn't work on most time.
Here is the log on windows
deoplete.log

[Shougo]

It is better than before, but it cannot fix the problem completely.

[Shougo]

Oh, concurrent.future version makes Vim exiting time will be slowly.
So I cannot merge the patch.

[Shougo]

I will test neovim/pynvim#294 and add support it later.

[Shougo]

neovim/pynvim#294 is merged.
I will add the support later.

[Shougo]

@neovim/pynvim#294 (comment)

I have tested it, but it does not work

[jsfaint]

@Shougo Should I test it now? or maybe later

[Shougo]

I test now...
But some problems are available.

• The candidates are not displayed sometimes. It seems similar problem with the comment.
  Completion menu show up time is long if a source is slow #645 (comment)

• The candidates filtering does not work. I don't know why. It is very confusing problem.

Result: No magic.

[jsfaint]

@Shougo I'm sorry to hear that.

[Shougo]

The candidates filtering does not work. I don't know why. It is very confusing problem.

I have fixed the problem.

[Shougo]

Add a time.sleep(10) in gather_candidates() tag.py

I have tested it in asyncio patch.
It works for me.

[Shougo]

https://gist.github.com/Shougo/b1292a539dcf7058c5e22b253fd46339

Note: It may not work in Windows environment.

I think it is the faster implementation.
Because, it does not have any sleep.

[jsfaint]

The patch in gist was fail to apply on deoplete master

$ git apply asyncio.diff
error: patch fragment without header at line 284: @@ -82,7 +85,8 @@ class Deoplete(logger.LoggingMixin):

[Shougo]

You should use patch -p1 instead.

[jsfaint]

I tried this patch on linux, it works for me.
But it looks the new version of python-neovim fail to work on Windows.
There are many errors when run :UpdateRemotePlugins on Windows

[Shougo]

But it looks the new version of python-neovim fail to work on Windows.
There are many errors when run :UpdateRemotePlugins on Windows

Yes.
It is python-neovim problem.

neovim/pynvim#307

[Shougo]

neovim/pynvim#306

[jsfaint]

Got it, thanks!

[Shougo]

You can test neovim/pynvim#307 branch.

[jsfaint]

neovim-python is upgrade to 0.2.4 which fix the windows issue.
But the gist patch doesn't work on windows.
After apply the patch on deoplete, there is no completion menu show up.

I enabled debug with

let $NVIM_PYTHON_LOG_FILE = 'd:\nvim_log'
let $NVIM_PYTHON_LOG_LEVEL = 'DEBUG'
let g:deoplete#enable_profile = 1
call deoplete#enable_logging('DEBUG', 'd:\deoplete.log')

But only got nvim_log_py3_script, there is no deoplete.log.
nvim_log_py3_script.zip

[Shougo]

But the gist patch doesn't work on windows.

Yes. It is intended behavior.
Current neovim-python does not support asyncio feature in Windows.

https://github.com/neovim/python-client/releases/tag/0.2.4

[jsfaint]

@Shougo Thanks for the information. 👍