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.