Deoplete.nvim: Dynamic completion candidates update?

[mrbiggfoot]

Different sources have different speeds. Some are very fast - like "buffer" and "around", some may take many seconds to gather candidates from, e.g. "tag" source. Can we show the completion candidates as they become avaliable from the source? I.e. when I start typing, I should instantly get completions from "buffer" and "around", and if I'm willing to wait for so many seconds - the candidates from "tag" would appear and the candidates list will be dynamically redrawn.

[brunogsa]

+1

[Shougo]

Yes, it is on the todo list.

[mrbiggfoot]

I implemented this deoplete source to help dealing with 'tags' slowness in the meantime:
https://github.com/mrbiggfoot/deoplete-filesrc

It is pretty dumb, but works for me. @Shougo if you want you can improve on it and put it into deoplete since it's generic enough.

[Shougo]

I will work for the issue after startup optimization.

[Shougo]

It should be ver.4.0.

[Shougo]

It is the next task after Vim 8 support.
Please wait.

[balta2ar]

@Shougo Hi, I'd like to clarify things about is_async flag of gather_candidates.
I have a completion source that is somewhat slow. It takes about 0.3s to generate results. If I type some input, these 0.3s accumulate after each typed letter and I have to wait until previous requests are processed (even though I don't need them already). But I want to cancel the async request if new input arrives.

I've read the docs here (https://github.com/Shougo/deoplete.nvim/blob/master/doc/deoplete.txt#L980) and https://github.com/zchee/deoplete-jedi/blob/master/rplugin/python3/deoplete/sources/deoplete_jedi.py#L168 source. To do what I want I need to implement some kind of internal worker thread. When gather_candidates is called, I submit my request to my internal queue, set is_async flag to True, and then return an empty list, right?

Next time when gather_candidates is called, I need to check 2 things:

1. If complete_str has changed, I should cancel my current request and summit a new one.
2. Otherwise, I should check whether the request has completed and if it has, set is_async to False, and return an actual list of candidates.

Also, even though the word async is extensively used here, it has nothing to do with async coroutines in Python 3.4..3.6, right?

Is my understanding correct? Please correct me if I'm wrong.

[balta2ar]

It looks like what I need is the same is_async flag but for on_post_filter function. The reason is that I do my custom filtering both in gather_candidates and in on_post_filter. I do not rely on denite's filtering because it didn't match my needs well. I produced best results if I filtered on my own.

Is it possible to make on_post_filter async too?

Is there another way? If I need to apply a custom filter and that filter is known to be slow, what do I do? I would like to be able to cancel filtering requests if the input (complete_str) changes.

[balta2ar]

Apparently VSCode has something very close to my needs, specifically Promises and Cancellation Tokens: https://code.visualstudio.com/docs/extensionAPI/patterns-and-principles#_cancellation-tokens
Could something similar be implemented in deoplete?

[balta2ar]

Could you please explain, how and when to use this flag? The documentation is a bit scarce...

        (Bool)              (Optional)
If it is True, the source depends on the user input.

[Shougo]

When gather_candidates is called, I submit my request to my internal queue, set is_async flag to True, and then return an empty list, right?

Yes.

[Shougo]

Also, even though the word async is extensively used here, it has nothing to do with async coroutines in Python 3.4..3.6, right?

You don't have to use async coroutines.

[Shougo]

Could you please explain, how and when to use this flag? The documentation is a bit scarce...

If the flag is enabled, deoplete does not use the internal cache.
The volatile source is called when the input is changed everytime.

[Shougo]

I do not rely on denite's filtering because it didn't match my needs well. I produced best results if I filtered on my own.

I don't understand what is the your filter.

Is it possible to make on_post_filter async too?

I don't understand it.
on_post_filter is called after gather_candidates().
So if gather_candidates() is async, on_post_filter is also async.

[Shougo]

I would like to be able to cancel filtering requests if the input (complete_str) changes.

It should be new feature.
Please create the new issue.

[balta2ar]

Also, even though the word async is extensively used here, it has nothing to do with async coroutines in Python 3.4..3.6, right?

You don't have to use async coroutines.

How are you going to implement dynamic update them? I'm curious. A callback to update the results?

I don't understand what is the your filter.

It's basically the same fuzzy filtering & ranking in one place but done using a Python C extension. Nothing fancy though.

Is it possible to make on_post_filter async too?

I don't understand it.
on_post_filter is called after gather_candidates().
So if gather_candidates() is async, on_post_filter is also async.

Hm, not exactly. Suppose that I'm going against the suggestions and I'm doing my own filtering in gather_candidates and in on_post_filter. And that filtering is time-consuming. I could offload the filtering into a background thread in gather_candidates and use is_async flag, but then without is_volatile flag the method on_post_filter is still called on every input change. I can't return partial results from on_post_filter, right?

In my case, to be able to cancel time-consuming filtering in the middle (for example, if the input has changed) and to not block deoplete, I had to do the following:

1. Do the filtering in a separate thread and use is_async flag in gather_candidates.
2. Make sure the filtering is granular and can be canceled by a flag. The flag is frequently checked by the thread.
3. Remove on_post_filter and do the filtering in gather_candidates.
4. Set is_volatile=True.

It should be new feature.
Please create the new issue.

I should probably think more about the use cases. Now it looks like just detecting a change in complete_str is enough. Do you have any use cases in mind?

[Shougo]

How are you going to implement dynamic update them?

The solution is multi-process. async coroutines does not save the calculation.

It's basically the same fuzzy filtering & ranking in one place but done using a Python C extension. Nothing fancy though.

Hm. I can add matcher_cpsm like denite.nvim.

[Shougo]

but then without is_volatile flag the method on_post_filter is still called on every input change.

Yes. It is the feature.

I can't return partial results from on_post_filter, right?

Right.

[Shougo]

The current deoplete behavior is hard to cancel the results for deoplete sources.
It should be fixed.

The input change should be detected by is_async flag.

[balta2ar]

Hm. I can add matcher_cpsm like denite.nvim.

That would be useful! Could you please add it? They say they're using multithreading to parallelise matching so it sounds promising. It could be faster than my current solution.

The current deoplete behavior is hard to cancel the results for deoplete sources.
It should be fixed.

On top of that any slow source can slow down the whole deoplete plugin. Having sources in separate processes could solve this issue probably. Another improvement could be to call all sources in parallel (this is what nvim-completion-manager claims to do).

[Shougo]

Another improvement could be to call all sources in parallel (this is what nvim-completion-manager claims to do).

I have the similar solutions. But it takes time to implement. Not easy.
I will improve source async feature before that.

[Shougo]

@balta2ar Please use is_async flag to check the input.
If the input is changed, it will be False.

[Shougo]

@balta2ar I have added matcher_cpsm in deoplete.

[balta2ar]

Please use is_async flag to check the input.
If the input is changed, it will be False

Sorry, I don't quite understand it, why do I need a flag to detect input change? The source plugin can remember last input string and compare with the new one, thus detecting the change by itself. Is there something else to that?

Also, using the same flag both as input and output for different purposes ("input changed" versus "call me again soon") could be very confusing...

Thank you for the cpsm, I'll try it!

[Shougo]

Sorry, I don't quite understand it, why do I need a flag to detect input change? The source plugin can remember last input string and compare with the new one, thus detecting the change by itself. Is there something else to that?

Yes. But all async source needs the feature.
So deoplete should support it.

Also, using the same flag both as input and output for different purposes ("input changed" versus "call me again soon") could be very confusing...

OK. I have changed the flag.
Please use is_refresh instead.

[balta2ar]

Yes. But all async source needs the feature.

Could you give an example, please? I have an async source and I remember the previous input and compare it with the current one, and it's working fine. I may be missing something.

Please use is_refresh instead

May I suggest input_changed flag name? I think it more clearly describes the meaning...

[Shougo]

Could you give an example, please? I have an async source and I remember the previous input and compare it with the current one, and it's working fine. I may be missing something.

Why needs the example? You can replace the check.

May I suggest input_changed flag name? I think it more clearly describes the meaning...

The user may refresh the input manually.
So I think is_refresh is better.

[balta2ar]

Why needs the example? You can replace the check.

So it's just a convenience, OK, I get it now.

[Shougo]

deoplete performance is bad on Windows.
It is well known problem.

If the issue is fixed, the performance problem will be relaxed.

[Shougo]

The problem is very important for me.

I will create new branch for it to test.
It takes more time to develop though.
Please wait.

[Shougo]

I have fixed the plugin bugs.
So I have started the refactoring before the feature implementing.

I will upload the WIP PR if possible.

[Shougo]

My next work is to implement threading.
It seems harder.

[Shougo]

WIP: https://github.com/Shougo/deoplete.nvim/pull/602

[Shougo]

If the feature is implemented, the all sources will be asynchronous.

[Shougo]

Almost done.

You can check the feature using #602.

[Shougo]

I will merge #602 in the weekend.

[mrbiggfoot]

For the record - deoplete stopped working for me after this update. For now I just roll it back - very busy at work and don't have time to debug or file a proper report. But maybe it is something obvious? It just does not work then after a while I'm getting this message:

-Error detected while processing function <SNR>51_completion_async[6]..<SNR>51_completion_begin[29]..deoplete#util#rpcnotify[4]..<SNR>46_notify:
line    6:
E475: Invalid argument: Channel doesn't exist

[Shougo]

@mrbiggfoot The child process is crashed.
I cannot reproduce the problem.
Please create the new issue for it.

[Shougo]

Please test the latest master and #631.

[mrbiggfoot]

That seems to have fixed the original problem, but now ":qa!" is taking ages. Still not ready for prime time. Also, the completion performance was actually worse than before the update... Sorry @Shougo , I don't mean to be complaining. Thank you for your efforts, your work is much appreciated!

[Shougo]

Also, the completion performance was actually worse than before the update...

Really? I cannot reproduce the problem.
It is faster for me.

I think your computer performance is very bad.
It may be not faster.

Note: The change is not for performance.

You have wrote the issue.

Different sources have different speeds. Some are very fast - like "buffer" and "around", some may take many seconds to gather candidates from, e.g. "tag" source. Can we show the completion candidates as they become avaliable from the source?

It does not mean that completion will be faster after that.
Just skipping slow completion sources.

[Shougo]

That seems to have fixed the original problem, but now ":qa!" is taking ages. Still not ready for prime time.

I think you have not tested #631.
Please test it.

[mrbiggfoot]

@Shougo I updated to the latest master and pulled 631. Without 631 it does not even work.
I'm saying that the speed for the completion candidates list to appear is much faster without 471 + 631. It should be at least similar to what it used to be. Also, my computer should be enough for text editing: Intel 4-core CPU @2.20GHz and 10Gb RAM.

[Shougo]

I'm saying that the speed for the completion candidates list to appear is much faster without 471 + 631.

It is the old version?
You can disable the parallel feature by g:deoplete#max_processes to 1.
Please test it.

[mrbiggfoot]

It is the old version?

Old version of neovim? No, I have:

NVIM v0.2.2
Build type: Release
LuaJIT 2.0.5
Compilation: /usr/lib64/ccache/cc -Wconversion -DNVIM_MSGPACK_HAS_FLOAT32 -DNVIM_UNIBI_HAS_VAR_FROM -O2 -DNDEBUG -DMIN_LOG_LEVEL=3 -Wall -Wextra -pedantic -Wno-unused-parameter -Wstrict-prototypes -std=gnu99 -Wvla -fstack-protector --param ssp-buffer-size=4 -Wno-array-bounds -DINCLUDE_GENERATED_DECLARATIONS -D_GNU_SOURCE -I/home/andrew/projects/neovim/neovim-0.2.2/build/config -I/home/andrew/projects/neovim/neovim-0.2.2/src -I/home/andrew/projects/neovim/neovim-0.2.2/.deps/usr/include -I/home/andrew/projects/neovim/neovim-0.2.2/.deps/usr/include -I/home/andrew/projects/neovim/neovim-0.2.2/.deps/usr/include -I/home/andrew/projects/neovim/neovim-0.2.2/.deps/usr/include -I/home/andrew/projects/neovim/neovim-0.2.2/.deps/usr/include -I/home/andrew/projects/neovim/neovim-0.2.2/.deps/usr/include -I/usr/include -I/home/andrew/projects/neovim/neovim-0.2.2/build/src/nvim/auto -I/home/andrew/projects/neovim/neovim-0.2.2/build/include

And it is still bad with max_processes=1. ":qa!" is taking several seconds, and completion candidates speed is still somewhat lower than it used to be. What's worse, it is not consistent: I type, say, "abc", get completions list, then erase "abc" and type it again. Second time the completion list does not appear. But the deoplete process is alive: if I type, say, "xyz" I get different completions list for it.

Resetting to 865747efe41ea1d923758617d71e8e5b59da292e works for me.

[Shougo]

NVIM v0.2.2

It is very old. It is released in 2017 Nov.
Please use neovim HEAD instead.

What's worse, it is not consistent: I type, say, "abc", get completions list, then erase "abc" and type it again. Second time the completion list does not appear.

Because, the completion is dynamic.
It is you wanted behavior.

Please upload the profile log. I will check it later.

[Shougo]

Resetting to 865747e works for me.

Because, the dynamic update feature is not implemented in that version.

[mrbiggfoot]

It is very old. It is released in 2017 Nov.
Please use neovim HEAD instead.

2.2 is the latest stable release. I may give HEAD a try but generally I prefer to use only stable releases.

Because, the completion is dynamic.
It is you wanted behavior.

what?! no, it is not the behavior I wanted. You may want to reread my original post. It has nothing about not showing candidates for the same prefix the second time.

If I were you I would just revert the feature as it now breaks more than it adds. But up to you, the version right before the new feature does almost all that I need (thank you again for the great work).

Because, the dynamic update feature is not implemented in that version.

oh, thaaaaat's why... \

[Shougo]

If I were you I would just revert the feature as it now breaks more than it adds. But up to you, the version right before the new feature does almost all that I need (thank you again for the great work).

I don't revert the version.
It is not just for parallel.

[Shougo]

@mrbiggfoot Unfortunately, I cannot reproduce your problem.
So it is very hard to fix for me.
Fortunately, you can investigate the problem.

I will wait.

[Shougo]

what?! no, it is not the behavior I wanted. You may want to reread my original post. It has nothing about not showing candidates for the same prefix the second time.

The completion is parallel.
If the completion is not calclated quickly, it is skipped if it is second time.

[Shougo]

Of course, I can revert the changes easily.
But why the problem is occured?

Because very few people tested the branch.
More testers/developers effort are needed for the feature.

[Shougo]

@mrbiggfoot You can test the patch.

diff --git a/rplugin/python3/deoplete/parent.py b/rplugin/python3/deoplete/parent.py
index 9444379..5967199 100644
--- a/rplugin/python3/deoplete/parent.py
+++ b/rplugin/python3/deoplete/parent.py
@@ -89,5 +89,5 @@ class Parent(logger.LoggingMixin):
         return queue_id

     def _get(self, queue_id):
-        return [x for x in self._proc.communicate(15)
+        return [x for x in self._proc.communicate(40)
                 if x['queue_id'] == queue_id]
diff --git a/rplugin/python3/deoplete/process.py b/rplugin/python3/deoplete/process.py
index 6c0a523..f30b20e 100644
--- a/rplugin/python3/deoplete/process.py
+++ b/rplugin/python3/deoplete/process.py
@@ -64,9 +64,9 @@ class Process(object):
         start = time()
         outs = []

-        if self._queue_out.empty():
-            sleep(timeout / 1000.0)
-        while not self._queue_out.empty() and time() < start + timeout:
+        while self._queue_out.empty() and time() < start + timeout:
+            sleep(0.01)
+        while not self._queue_out.empty():
             outs.append(self._queue_out.get_nowait())
         return outs

I think it is better than current version.

[Shougo]

What's worse, it is not consistent: I type, say, "abc", get completions list, then erase "abc" and type it again. Second time the completion list does not appear.

It seems bug. Reproduced. I will investigate the problem.

[Shougo]

Patch for the problem.

diff --git a/autoload/deoplete/handler.vim b/autoload/deoplete/handler.vim
index 8375c6d..d7aa0b4 100644
--- a/autoload/deoplete/handler.vim
+++ b/autoload/deoplete/handler.vim
@@ -52,12 +52,6 @@ function! s:do_complete(timer) abort
   endif

   let prev = g:deoplete#_prev_completion
-  if context.event !=# 'Manual'
-        \ && prev.complete_position == getpos('.')
-        \ && prev.candidates ==# context.candidates
-    return
-  endif
-
   let prev.event = context.event
   let prev.candidates = context.candidates
   let prev.complete_position = getpos('.')

[mrbiggfoot]

@Shougo should I apply both patches or just the latest one?
Thank you for the quick turnaround! I'll try to verify the patches ASAP, most likely tomorrow (PST time zone)...

[Shougo]

Please apply both patches.

Earlier one is for completion performance, later one is for no candidates problem.

[Shougo]

@mrbiggfoot Please profile the completion time after patched.
I will check it later.

[mrbiggfoot]

Both logs are from latest master (c5f8165245a1bd0a9a9f3d167ec855994fcd1e14) + 631.
This one is with both patches:
with_patches.log

This one is without patches, just master + 631:
no_patch.log

This one is without the dynamic feature, i.e. master at 865747efe41ea1d923758617d71e8e5b59da292e:
master_865747e.log

I can confirm that the patches fix the problem with second time candidates disappearance. But the performance is not visibly improved, and it still hangs for a long time on ":qa!".

EDIT: this is on neovim 0.2.2. Does it make sense to try the latest neovim build?

[Shougo]

and it still hangs for a long time on ":qa!".

I cannot reproduce the problem.
It needs to investigate. I think you can do it.

[Shougo]

@mrbiggfoot Please use below.

let g:deoplete#enable_profile = 1
call deoplete#enable_logging('DEBUG', 'deoplete.log')

Your log files are don't include some logs.

[Shougo]

I have checked the logs.
It is under WSL?

It seems very slow.

[Shougo]

Your log files are very few especially master_865747e.log.

I have get it is very slow. But I don't understand why.

For example:

2018-02-06 12:29:13,590 DEBUG    [6026] (deoplete.core) completion_begin: date da
2018-02-06 12:29:13,590 DEBUG    [6027] (deoplete.child) _read: 5044 bytes
2018-02-06 12:29:13,590 DEBUG    [6027] (deoplete.child) main_loop: begin
2018-02-06 12:29:13,590 DEBUG    [6027] (deoplete.child) main_loop: merge_results
2018-02-06 12:29:13,600 DEBUG    [6029] (deoplete.child) _read: 5044 bytes
2018-02-06 12:29:13,600 DEBUG    [6029] (deoplete.child) main_loop: begin
2018-02-06 12:29:13,600 DEBUG    [6029] (deoplete.child) main_loop: merge_results
2018-02-06 12:29:13,601 DEBUG    [6029] (deoplete.child) Profile Start: buffer
2018-02-06 12:29:13,601 DEBUG    [6029] (deoplete.child) Profile End  : buffer                    time=0.0002700000
2018-02-06 12:29:13,602 DEBUG    [6029] (deoplete.child) Profile Start: deoppet
2018-02-06 12:29:13,602 DEBUG    [6029] (deoplete.child) Profile End  : deoppet                   time=0.0004640000
2018-02-06 12:29:13,603 DEBUG    [6029] (deoplete.child) Profile Start: neosnippet
2018-02-06 12:29:13,603 DEBUG    [6029] (deoplete.child) Profile End  : neosnippet                time=0.0000140000
2018-02-06 12:29:13,603 DEBUG    [6029] (deoplete.child) Profile Start: tag
2018-02-06 12:29:13,604 DEBUG    [6029] (deoplete.child) Profile End  : tag                       time=0.0007260000
2018-02-06 12:29:13,605 DEBUG    [6029] (deoplete.child) Profile Start: matcher_fuzzy
2018-02-06 12:29:13,605 DEBUG    [6029] (deoplete.child) Profile End  : matcher_fuzzy             time=0.0000620000
2018-02-06 12:29:13,605 DEBUG    [6029] (deoplete.child) Profile Start: sorter_rank
2018-02-06 12:29:13,605 DEBUG    [6029] (deoplete.child) Profile End  : sorter_rank               time=0.0000110000
2018-02-06 12:29:13,605 DEBUG    [6029] (deoplete.child) Profile Start: converter_remove_paren
2018-02-06 12:29:13,605 DEBUG    [6029] (deoplete.child) Profile End  : converter_remove_paren    time=0.0000080000
2018-02-06 12:29:13,605 DEBUG    [6029] (deoplete.child) Profile Start: converter_remove_overlap
2018-02-06 12:29:13,605 DEBUG    [6029] (deoplete.child) Profile End  : converter_remove_overlap  time=0.0000040000
2018-02-06 12:29:13,606 DEBUG    [6029] (deoplete.child) Profile Start: converter_truncate_abbr
2018-02-06 12:29:13,606 DEBUG    [6029] (deoplete.child) Profile End  : converter_truncate_abbr   time=0.0000050000
2018-02-06 12:29:13,606 DEBUG    [6029] (deoplete.child) Profile Start: converter_truncate_menu
2018-02-06 12:29:13,606 DEBUG    [6029] (deoplete.child) Profile End  : converter_truncate_menu   time=0.0000040000
2018-02-06 12:29:13,606 DEBUG    [6029] (deoplete.child) Profile Start: converter_auto_delimiter
2018-02-06 12:29:13,606 DEBUG    [6029] (deoplete.child) Profile End  : converter_auto_delimiter  time=0.0000060000
2018-02-06 12:29:13,607 DEBUG    [6029] (deoplete.child) Profile Start: matcher_fuzzy
2018-02-06 12:29:13,607 DEBUG    [6029] (deoplete.child) Profile End  : matcher_fuzzy             time=0.0000640000
2018-02-06 12:29:13,607 DEBUG    [6029] (deoplete.child) Profile Start: sorter_rank
2018-02-06 12:29:13,607 DEBUG    [6029] (deoplete.child) Profile End  : sorter_rank               time=0.0000150000
2018-02-06 12:29:13,607 DEBUG    [6029] (deoplete.child) Profile Start: converter_remove_paren
2018-02-06 12:29:13,607 DEBUG    [6029] (deoplete.child) Profile End  : converter_remove_paren    time=0.0000090000
2018-02-06 12:29:13,607 DEBUG    [6029] (deoplete.child) Profile Start: converter_remove_overlap
2018-02-06 12:29:13,608 DEBUG    [6029] (deoplete.child) Profile End  : converter_remove_overlap  time=0.0000040000
2018-02-06 12:29:13,608 DEBUG    [6029] (deoplete.child) Profile Start: converter_truncate_abbr
2018-02-06 12:29:13,608 DEBUG    [6029] (deoplete.child) Profile End  : converter_truncate_abbr   time=0.0000090000
2018-02-06 12:29:13,608 DEBUG    [6029] (deoplete.child) Profile Start: converter_truncate_menu
2018-02-06 12:29:13,608 DEBUG    [6029] (deoplete.child) Profile End  : converter_truncate_menu   time=0.0000500000
2018-02-06 12:29:13,608 DEBUG    [6029] (deoplete.child) Profile Start: converter_auto_delimiter
2018-02-06 12:29:13,608 DEBUG    [6029] (deoplete.child) Profile End  : converter_auto_delimiter  time=0.0000120000
2018-02-06 12:29:13,608 DEBUG    [6029] (deoplete.child) Profile Start: matcher_fuzzy
2018-02-06 12:29:13,609 DEBUG    [6029] (deoplete.child) Profile End  : matcher_fuzzy             time=0.0000500000
2018-02-06 12:29:13,609 DEBUG    [6029] (deoplete.child) Profile Start: sorter_rank
2018-02-06 12:29:13,609 DEBUG    [6029] (deoplete.child) Profile End  : sorter_rank               time=0.0000120000
2018-02-06 12:29:13,609 DEBUG    [6029] (deoplete.child) Profile Start: converter_remove_paren
2018-02-06 12:29:13,609 DEBUG    [6029] (deoplete.child) Profile End  : converter_remove_paren    time=0.0000090000
2018-02-06 12:29:13,609 DEBUG    [6029] (deoplete.child) Profile Start: converter_remove_overlap
2018-02-06 12:29:13,609 DEBUG    [6029] (deoplete.child) Profile End  : converter_remove_overlap  time=0.0000050000
2018-02-06 12:29:13,609 DEBUG    [6029] (deoplete.child) Profile Start: converter_truncate_abbr
2018-02-06 12:29:13,609 DEBUG    [6029] (deoplete.child) Profile End  : converter_truncate_abbr   time=0.0000070000
2018-02-06 12:29:13,609 DEBUG    [6029] (deoplete.child) Profile Start: converter_truncate_menu
2018-02-06 12:29:13,609 DEBUG    [6029] (deoplete.child) Profile End  : converter_truncate_menu   time=0.0000060000
2018-02-06 12:29:13,609 DEBUG    [6029] (deoplete.child) Profile Start: converter_auto_delimiter
2018-02-06 12:29:13,609 DEBUG    [6029] (deoplete.child) Profile End  : converter_auto_delimiter  time=0.0000100000
2018-02-06 12:29:13,612 DEBUG    [6031] (deoplete.child) _read: 5044 bytes
2018-02-06 12:29:13,612 DEBUG    [6031] (deoplete.child) main_loop: begin
2018-02-06 12:29:13,612 DEBUG    [6031] (deoplete.child) main_loop: merge_results
2018-02-06 12:29:13,622 DEBUG    [6033] (deoplete.child) _read: 5044 bytes
2018-02-06 12:29:13,622 DEBUG    [6033] (deoplete.child) main_loop: begin
2018-02-06 12:29:13,622 DEBUG    [6033] (deoplete.child) main_loop: merge_results
2018-02-06 12:29:13,623 DEBUG    [6033] (deoplete.child) Profile Start: dictionary
2018-02-06 12:29:13,623 DEBUG    [6033] (deoplete.child) Profile End  : dictionary                time=0.0000330000
2018-02-06 12:29:13,624 DEBUG    [6033] (deoplete.child) Profile Start: around
2018-02-06 12:29:13,625 DEBUG    [6033] (deoplete.child) Profile End  : around                    time=0.0012350000
2018-02-06 12:29:13,626 DEBUG    [6033] (deoplete.child) Profile Start: syntax
2018-02-06 12:29:13,626 DEBUG    [6033] (deoplete.child) Profile End  : syntax                    time=0.0000060000
2018-02-06 12:29:13,627 DEBUG    [6033] (deoplete.child) Profile Start: matcher_fuzzy
2018-02-06 12:29:13,627 DEBUG    [6033] (deoplete.child) Profile End  : matcher_fuzzy             time=0.0000070000
2018-02-06 12:29:13,627 DEBUG    [6033] (deoplete.child) Profile Start: sorter_rank
2018-02-06 12:29:13,627 DEBUG    [6033] (deoplete.child) Profile End  : sorter_rank               time=0.0000150000
2018-02-06 12:29:13,627 DEBUG    [6033] (deoplete.child) Profile Start: converter_remove_paren
2018-02-06 12:29:13,628 DEBUG    [6033] (deoplete.child) Profile End  : converter_remove_paren    time=0.0000110000
2018-02-06 12:29:13,628 DEBUG    [6033] (deoplete.child) Profile Start: converter_remove_overlap
2018-02-06 12:29:13,628 DEBUG    [6033] (deoplete.child) Profile End  : converter_remove_overlap  time=0.0000030000
2018-02-06 12:29:13,628 DEBUG    [6033] (deoplete.child) Profile Start: converter_truncate_abbr
2018-02-06 12:29:13,628 DEBUG    [6033] (deoplete.child) Profile End  : converter_truncate_abbr   time=0.0000030000
2018-02-06 12:29:13,628 DEBUG    [6033] (deoplete.child) Profile Start: converter_truncate_menu
2018-02-06 12:29:13,628 DEBUG    [6033] (deoplete.child) Profile End  : converter_truncate_menu   time=0.0000030000
2018-02-06 12:29:13,628 DEBUG    [6033] (deoplete.child) Profile Start: converter_auto_delimiter
2018-02-06 12:29:13,628 DEBUG    [6033] (deoplete.child) Profile End  : converter_auto_delimiter  time=0.0000040000
2018-02-06 12:29:13,628 DEBUG    [6033] (deoplete.child) Profile Start: matcher_fuzzy
2018-02-06 12:29:13,628 DEBUG    [6033] (deoplete.child) Profile End  : matcher_fuzzy             time=0.0000400000
2018-02-06 12:29:13,628 DEBUG    [6033] (deoplete.child) Profile Start: sorter_rank
2018-02-06 12:29:13,628 DEBUG    [6033] (deoplete.child) Profile End  : sorter_rank               time=0.0000100000
2018-02-06 12:29:13,628 DEBUG    [6033] (deoplete.child) Profile Start: converter_remove_paren
2018-02-06 12:29:13,628 DEBUG    [6033] (deoplete.child) Profile End  : converter_remove_paren    time=0.0000060000
2018-02-06 12:29:13,628 DEBUG    [6033] (deoplete.child) Profile Start: converter_remove_overlap
2018-02-06 12:29:13,628 DEBUG    [6033] (deoplete.child) Profile End  : converter_remove_overlap  time=0.0000030000
2018-02-06 12:29:13,629 DEBUG    [6033] (deoplete.child) Profile Start: converter_truncate_abbr
2018-02-06 12:29:13,629 DEBUG    [6033] (deoplete.child) Profile End  : converter_truncate_abbr   time=0.0000060000
2018-02-06 12:29:13,629 DEBUG    [6033] (deoplete.child) Profile Start: converter_truncate_menu
2018-02-06 12:29:13,629 DEBUG    [6033] (deoplete.child) Profile End  : converter_truncate_menu   time=0.0000060000
2018-02-06 12:29:13,629 DEBUG    [6033] (deoplete.child) Profile Start: converter_auto_delimiter
2018-02-06 12:29:13,629 DEBUG    [6033] (deoplete.child) Profile End  : converter_auto_delimiter  time=0.0000100000
2018-02-06 12:29:13,633 DEBUG    [6026] (deoplete.core) completion_end: date da

Here is my log. Please see the log file time.

[Shougo]

Please see the log time in your log file.

2018-02-05 20:58:46,802 DEBUG    [124891] (deoplete.core) completion_begin:   Sc
2018-02-05 20:58:46,803 DEBUG    [124892] (deoplete.child) _read: 3137 bytes
2018-02-05 20:58:46,805 DEBUG    [124892] (deoplete.child) main_loop: begin
2018-02-05 20:58:46,805 DEBUG    [124892] (deoplete.child) main_loop: merge_results
2018-02-05 20:58:46,806 DEBUG    [124892] (deoplete.child) Profile Start: filesrc
2018-02-05 20:58:46,806 DEBUG    [124892] (deoplete.child) Profile End  : filesrc                   time=0.0000000000
2018-02-05 20:58:46,814 DEBUG    [124894] (deoplete.child) _read: 3136 bytes
2018-02-05 20:58:46,815 DEBUG    [124894] (deoplete.child) main_loop: begin
2018-02-05 20:58:46,816 DEBUG    [124894] (deoplete.child) main_loop: merge_results
2018-02-05 20:58:46,816 DEBUG    [124894] (deoplete.child) Profile Start: around
2018-02-05 20:58:46,819 DEBUG    [124894] (deoplete.child) Profile End  : around                    time=0.0100000000
2018-02-05 20:58:46,821 DEBUG    [124894] (deoplete.child) Profile Start: matcher_fuzzy
2018-02-05 20:58:46,821 DEBUG    [124894] (deoplete.child) Profile End  : matcher_fuzzy             time=0.0000000000
2018-02-05 20:58:46,822 DEBUG    [124894] (deoplete.child) Profile Start: sorter_rank
2018-02-05 20:58:46,822 DEBUG    [124894] (deoplete.child) Profile End  : sorter_rank               time=0.0000000000
2018-02-05 20:58:46,822 DEBUG    [124894] (deoplete.child) Profile Start: converter_remove_overlap
2018-02-05 20:58:46,822 DEBUG    [124894] (deoplete.child) Profile End  : converter_remove_overlap  time=0.0000000000
2018-02-05 20:58:46,822 DEBUG    [124894] (deoplete.child) Profile Start: converter_truncate_abbr
2018-02-05 20:58:46,822 DEBUG    [124894] (deoplete.child) Profile End  : converter_truncate_abbr   time=0.0000000000
2018-02-05 20:58:46,822 DEBUG    [124894] (deoplete.child) Profile Start: converter_truncate_kind
2018-02-05 20:58:46,822 DEBUG    [124894] (deoplete.child) Profile End  : converter_truncate_kind   time=0.0000000000
2018-02-05 20:58:46,822 DEBUG    [124894] (deoplete.child) Profile Start: converter_truncate_menu
2018-02-05 20:58:46,822 DEBUG    [124894] (deoplete.child) Profile End  : converter_truncate_menu   time=0.0000000000
2018-02-05 20:58:47,011 DEBUG    [124896] (deoplete.child) _read: 3137 bytes
2018-02-05 20:58:47,014 DEBUG    [124896] (deoplete.child) main_loop: begin
2018-02-05 20:58:47,014 DEBUG    [124896] (deoplete.child) main_loop: merge_results
2018-02-05 20:58:47,015 DEBUG    [124896] (deoplete.child) Profile Start: buffer
2018-02-05 20:58:47,015 DEBUG    [124896] (deoplete.child) Profile End  : buffer                    time=0.0000000000
2018-02-05 20:58:47,016 DEBUG    [124896] (deoplete.child) Profile Start: matcher_fuzzy
2018-02-05 20:58:47,016 DEBUG    [124896] (deoplete.child) Profile End  : matcher_fuzzy             time=0.0000000000
2018-02-05 20:58:47,016 DEBUG    [124896] (deoplete.child) Profile Start: sorter_rank
2018-02-05 20:58:47,016 DEBUG    [124896] (deoplete.child) Profile End  : sorter_rank               time=0.0000000000
2018-02-05 20:58:47,016 DEBUG    [124896] (deoplete.child) Profile Start: converter_remove_overlap
2018-02-05 20:58:47,016 DEBUG    [124896] (deoplete.child) Profile End  : converter_remove_overlap  time=0.0000000000
2018-02-05 20:58:47,016 DEBUG    [124896] (deoplete.child) Profile Start: converter_truncate_abbr
2018-02-05 20:58:47,016 DEBUG    [124896] (deoplete.child) Profile End  : converter_truncate_abbr   time=0.0000000000
2018-02-05 20:58:47,016 DEBUG    [124896] (deoplete.child) Profile Start: converter_truncate_kind
2018-02-05 20:58:47,016 DEBUG    [124896] (deoplete.child) Profile End  : converter_truncate_kind   time=0.0000000000
2018-02-05 20:58:47,017 DEBUG    [124896] (deoplete.child) Profile Start: converter_truncate_menu
2018-02-05 20:58:47,017 DEBUG    [124896] (deoplete.child) Profile End  : converter_truncate_menu   time=0.0000000000
2018-02-05 20:58:47,023 DEBUG    [124898] (deoplete.child) _read: 3137 bytes
2018-02-05 20:58:47,025 DEBUG    [124898] (deoplete.child) main_loop: begin
2018-02-05 20:58:47,025 DEBUG    [124898] (deoplete.child) main_loop: merge_results
2018-02-05 20:58:47,037 DEBUG    [124891] (deoplete.core) completion_begin:   Sco
2018-02-05 20:58:47,038 DEBUG    [124892] (deoplete.child) _read: 3137 bytes
2018-02-05 20:58:47,039 DEBUG    [124892] (deoplete.child) main_loop: begin
2018-02-05 20:58:47,040 DEBUG    [124892] (deoplete.child) main_loop: merge_results
2018-02-05 20:58:47,049 DEBUG    [124894] (deoplete.child) _read: 3138 bytes
2018-02-05 20:58:47,050 DEBUG    [124894] (deoplete.child) main_loop: begin
2018-02-05 20:58:47,050 DEBUG    [124894] (deoplete.child) main_loop: merge_results
2018-02-05 20:58:47,052 DEBUG    [124894] (deoplete.child) Profile Start: matcher_fuzzy
2018-02-05 20:58:47,053 DEBUG    [124894] (deoplete.child) Profile End  : matcher_fuzzy             time=0.0000000000
2018-02-05 20:58:47,053 DEBUG    [124894] (deoplete.child) Profile Start: sorter_rank
2018-02-05 20:58:47,053 DEBUG    [124894] (deoplete.child) Profile End  : sorter_rank               time=0.0000000000
2018-02-05 20:58:47,053 DEBUG    [124894] (deoplete.child) Profile Start: converter_remove_overlap
2018-02-05 20:58:47,053 DEBUG    [124894] (deoplete.child) Profile End  : converter_remove_overlap  time=0.0000000000
2018-02-05 20:58:47,053 DEBUG    [124894] (deoplete.child) Profile Start: converter_truncate_abbr
2018-02-05 20:58:47,053 DEBUG    [124894] (deoplete.child) Profile End  : converter_truncate_abbr   time=0.0000000000
2018-02-05 20:58:47,053 DEBUG    [124894] (deoplete.child) Profile Start: converter_truncate_kind
2018-02-05 20:58:47,053 DEBUG    [124894] (deoplete.child) Profile End  : converter_truncate_kind   time=0.0000000000
2018-02-05 20:58:47,053 DEBUG    [124894] (deoplete.child) Profile Start: converter_truncate_menu
2018-02-05 20:58:47,054 DEBUG    [124894] (deoplete.child) Profile End  : converter_truncate_menu   time=0.0000000000
2018-02-05 20:58:47,169 DEBUG    [124896] (deoplete.child) _read: 3138 bytes
2018-02-05 20:58:47,171 DEBUG    [124896] (deoplete.child) main_loop: begin
2018-02-05 20:58:47,171 DEBUG    [124896] (deoplete.child) main_loop: merge_results
2018-02-05 20:58:47,180 DEBUG    [124898] (deoplete.child) _read: 3138 bytes
2018-02-05 20:58:47,183 DEBUG    [124898] (deoplete.child) main_loop: begin
2018-02-05 20:58:47,183 DEBUG    [124898] (deoplete.child) main_loop: merge_results
2018-02-05 20:58:47,193 DEBUG    [124891] (deoplete.core) completion_end:   Sc
2018-02-05 20:58:47,193 DEBUG    [124891] (deoplete.core) completion_end:   Sco

[Shougo]

First read is:

2018-02-05 20:58:46,814 DEBUG    [124894] (deoplete.child) _read: 3136 bytes

Second read is:

2018-02-05 20:58:47,011 DEBUG    [124896] (deoplete.child) _read: 3137 bytes

What? 200ms to switch?

[Shougo]

It seems first profile result.
So it may be slower.

I need more profile logs.

[Shougo]

g:deoplete#max_processes is 1?
It is not faster. It should be default.

[mrbiggfoot]

@mrbiggfoot Please use below.

let g:deoplete#enable_profile = 1
call deoplete#enable_logging('DEBUG', 'deoplete.log')

All logs were generated with these settings. If something is missing, it is not my fault. Each time I started neovim, opened the same file and attempted completion beginning with "Sco" once. Let me know if I can do anything else to help debugging it. max_processes was NOT set in all tests, i.e. it was the default.

It is under WSL?

No, it's a VM running on the server.

Your log files are very few especially master_865747e.log.

Maybe that's because the older version does not log as many messages as the newest one? The deoplete settings were the same, and the test itself was the same in all three cases. This test had the speed that I would like to see in the other tests.

I need more profile logs.

What do you want me to do? Attempt the same completion several times? Or different completions? How many times?

[Shougo]

No, it's a VM running on the server.

VM....
It seems slow. I think the VM has very few cores.
4 core is recommended.

Attempt the same completion several times?

Yes.

[Shougo]

The performance problem should be another issue.
Please create the new issue with your environment information.

[Shougo]

I can confirm that the patches fix the problem with second time candidates disappearance.

The problem is already fixed in master

[Shougo]

my computer should be enough for text editing: Intel 4-core CPU @2.20GHz and 10Gb RAM.

No, it's a VM running on the server.

I don't understand your machine environment.
Please provide more information correctly.

[Shougo]

If it is VM, VM cannot use full CPU cores/memory/IO dislike bare-metal machine.

I think it is Linux VM on Windows.

[mrbiggfoot]

Frankly, I don't know the exact server configuration, but it is definitely not windows. The above hardware specs is what I see inside the VM, i.e. the provisioned resources.

[mrbiggfoot]

Latest master (3dee4b1fd272e07aab945ac514625080567e9019) with profile settings:
deoplete.log
attempted the same completion multiple times.

[mrbiggfoot]

FWIW - the behavior is no any different on the latest nightly build of neovim.

[mrbiggfoot]

Is there any log that I can turn on that would help to debug ":qa!" issue?

[Shougo]

I think in VM timer interrupt is very slow.
So deoplete parallel is very slow.

I cannot fix the problem.
But I will add the serial support in deoplete later.

https://github.com/Shougo/deoplete.nvim/issues/638

[Shougo]

Is there any log that I can turn on that would help to debug ":qa!" issue?

I think it is same problem with https://github.com/Shougo/deoplete.nvim/issues/637.
It depends on your configuration and the installed plugins.
Please test it in minimal init.vim.

[Shougo]

Please test the latest version of deoplete in non VM environment.
I think it is faster.

[Shougo]

Latest master (3dee4b1) with profile settings:
deoplete.log
attempted the same completion multiple times.

I have checked the log.
Switching overhead is 100ms ~ 200ms.
It is very high.

[mrbiggfoot]

Please test the latest version of deoplete in non VM environment.

Even if it is faster, it's of no use to me. Sorry, but my work environment is not going to change for some objective reasons. I think I will just stay on the older version for now, which mostly works for me. Thank you!

[Shougo]

Even if it is faster, it's of no use to me. Sorry, but my work environment is not going to change for some objective reasons.

I know it. But I want to know the slowness is whether VM reason.

[Shougo]

I think I will just stay on the older version for now, which mostly works for me. Thank you!

And I will implement searial completion feature instead.

[mrbiggfoot]

I know it. But I want to know the slowness is whether VM reason.

Still, I can't do a fair apples to apples comparison because I don't have a CentOS running on bare metal. The only unix that I have on bare metal is MacOS, which is pretty far from CentOS. So even if I get different results, it could be something else.

[Shougo]

Still, I can't do a fair apples to apples comparison because I don't have a CentOS running on bare metal. The only unix that I have on bare metal is MacOS, which is pretty far from CentOS. So even if I get different results, it could be something else.

Yes. But you know CentOS bare metal is different from CentOS VM.
The performance is different.

[Shougo]

@mrbiggfoot Please test below patch and profile.

diff --git a/rplugin/python3/deoplete/child.py b/rplugin/python3/deoplete/child.py
index 1e14e09..f171be9 100644
--- a/rplugin/python3/deoplete/child.py
+++ b/rplugin/python3/deoplete/child.py
@@ -79,6 +79,7 @@ class Child(logger.LoggingMixin):
                     self._on_event(args[0])
                 elif name == 'merge_results':
                     self._write(self._merge_results(args[0], queue_id))
+                self.debug('main_loop: end')

     def _write(self, expr):
         sys.stdout.buffer.write(self._packer.pack(expr))
@@ -141,6 +142,7 @@ class Child(logger.LoggingMixin):
                 self.debug('Loaded Filter: %s (%s)', f.name, path)

     def _merge_results(self, context, queue_id):
+        self.debug('merged_results: begin')
         results = self._gather_results(context)

         merged_results = []
@@ -162,6 +164,7 @@ class Child(logger.LoggingMixin):

         is_async = len([x for x in results if x['context']['is_async']]) > 0

+        self.debug('merged_results: end')
         return {
             'queue_id': queue_id,
             'is_async': is_async,

[Shougo]

And please test the patch.

diff --git a/rplugin/python3/deoplete/process.py b/rplugin/python3/deoplete/process.py
index d1ac7b3..f6e6c47 100644
--- a/rplugin/python3/deoplete/process.py
+++ b/rplugin/python3/deoplete/process.py
@@ -52,7 +52,10 @@ class Process(object):

     def enqueue_output(self):
         while self._proc:
-            b = self._proc.stdout.read(1)
+            b = self._proc.stdout.raw.read(102400)
+            if b == b'':
+                return
+
             self._unpacker.feed(b)
             for child_out in self._unpacker:
                 self._queue_out.put(child_out)

[brunogsa]

Hi @Shougo

I think I'm also experiencing some issues now, after updating to the last version.
My completion stop working after a while, so I have to restart my nvim.

Also, It feels like my system is slower.
Neovim sometimes stucks, so I have to press CTRL+C to kill the process.

I'm trying to debug, following the docs:

let g:deoplete#enable_profile = 1
call deoplete#enable_logging('DEBUG', 'deoplete.log')

But now I'm retrieving an error when opening nvim:

Error detected while processing /home/brunogsa/.config/nvim/init.vim:
line  434:
E117: Unknown function: deoplete#enable_logging
Press ENTER or type command to continue

I would like to provide more useful information, coud you point me out how can I help?

Thanks for the great work!

[Shougo]

@brunogsa Please test the latest version of deoplete.

[mrbiggfoot]

@Shougo now I don't see the difference in performance (using master at a24d95ef73b800fa026b57dc0fefae018301cc06), or it is very minor. Also, the ":qa!" problem is gone. Thank you!

[Shougo]

OK. Cherrs.

[mrbiggfoot]

Sorry for spamming here, but don't yet want to open an issue for what may well be my own stupidity... the filesource https://github.com/mrbiggfoot/deoplete-filesrc has stopped working. It is not related to this change - it does not work even if I roll it back. But it used to work some time ago. Were there any changes to the source API? I'm not seeing anything relevant in the doc... perhaps you can take a quick look and spot what is wrong immediately?
https://github.com/mrbiggfoot/deoplete-filesrc/blob/master/rplugin/python3/deoplete/sources/filesrc.py
(less than one screen of trivial code, and I checked the class separately and verified that the file path g:deoplete#filesrc#path is set in vim)

[Shougo]

OK. I will test it.
Please upload the sample file.

[Shougo]

I have tested it. And it works.

I think you must expand() g:deoplete#filesrc#path.
Like this.

let g:deoplete#filesrc#path = expand('~/src/neovim/completions')

[Shougo]

https://github.com/mrbiggfoot/deoplete-filesrc/blob/master/rplugin/python3/deoplete/sources/filesrc.py#L23

You can use deoplete.util.expand() for it.

[mrbiggfoot]

Thanks for looking into it @Shougo, but that was not it. I have an absolute path set in that variable. There's something more weird going on... if I open a file like "vim file.cc", my completions from the file work. But if I open that same file via fzf (which I use from vim via fzf.vim) after staring vim, the same completions don't work! The #path var is set properly in both cases. I will investigate more. You already spent a lot of time on this.

[Shougo]

https://github.com/mrbiggfoot/deoplete-filesrc/blob/master/rplugin/python3/deoplete/sources/filesrc.py#L36

close() is needed. You should use with statement instead.

https://github.com/mrbiggfoot/deoplete-filesrc/blob/master/rplugin/python3/deoplete/sources/filesrc.py#L37

You can use f.readlines() instead.

[Shougo]

The code is broken.

    def on_event(self, context):
        if not exists(self.__filepath):
            self.__cache = []
            return

        mtime = getmtime(self.__filepath)
        if mtime == self.__mtime:
            return

        self.__mtime = mtime
        f = open(self.__filepath, 'r')
        self.__cache = list(f.read().split())

[Shougo]

The cache is cleared if if mtime == self.__mtime in previous code.

So,

But if I open that same file via fzf (which I use from vim via fzf.vim) after staring vim, the same completions don't work!

Yes.

It is your source's bug.

[mrbiggfoot]

Thank you again @Shougo, you are right. Stupid mistakes in my code.

You can use f.readlines() instead.

Not quite, readlines() does not trim the newline chars.