:AleFix slow with setbufline

[bo5o]

Information

VIM version

NVIM v0.5.0-dev+1194-gc20ae3aad
Build type: RelWithDebInfo

Operating System: Ubuntu 18.04.5 LTS x86_64

What went wrong

I am working on a rather small Python file (~100 LOC) and :AleFix is very slow (~2s). Profiling shows, that most of the time is spent in ale#util#SetBufferContents()

FUNCTIONS SORTED ON TOTAL TIME
count  total (s)   self (s)  function
    1   1.864103   0.000128  ale#fix#ApplyFixes()
    1   1.863752   0.006731  ale#fix#ApplyQueuedFixes()
    1   1.856948   0.005370  ale#util#SetBufferContents()
    1   0.008518   0.000050  ale#events#SaveEvent()
    1   0.008439   0.000111  ale#fix#Fix()
    2   0.007234   0.000083  ale#python#FindExecutable()
    2   0.007112   0.003778  ale#python#FindVirtualenv()
    2   0.005996   0.000404  ale#command#Run()
    2   0.004467   0.004458  ale#job#Start()
    4   0.004008   0.002895  ale#util#JoinNeovimOutput()
    1   0.003976   0.000053  ale#fixers#black#Fix()
    1   0.003888   0.000022  ale#fixers#black#GetExecutable()
  106   0.003603   0.000995  ale#statusline#Count()
    1   0.003486   0.000038  ale#fixers#isort#Fix()
    1   0.003424   0.000018  ale#fixers#isort#GetExecutable()
  312   0.002889             ale#path#Simplify()
  106   0.001372             ale#engine#IsCheckingBuffer()
    2   0.000816   0.000212  ale#command#FormatCommand()
    2   0.000475   0.000089  ale#util#FunctionArgCount()
   41   0.000422             ale#Var()

Specifically, the call to setbufline takes the longest:

FUNCTION  ale#util#SetBufferContents()
    Defined: ~/.local/share/nvim/plugged/ale/autoload/ale/util.vim:503
Called 1 time
Total time:   1.856948
 Self time:   0.005370

count  total (s)   self (s)
    1   0.000008   0.000005     let l:has_bufline_api = ale#util#HasBuflineApi()

    1              0.000002     if !l:has_bufline_api && a:buffer isnot bufnr('')
                                    return
    1              0.000000     endif

                                " If the file is in DOS mode, we have to remove carriage returns from
                                " the ends of lines before calling setline(), or we will see them
                                " twice.
    1              0.000006     let l:new_lines = getbufvar(a:buffer, '&fileformat') is# 'dos'   ? map(copy(a:lines), 'substitute(v:val, ''\r\+$'', '''', '''')')   : a:lines
    1              0.000003     let l:first_line_to_remove = len(l:new_lines) + 1

                                " Use a Vim API for setting lines in other buffers, if available.
    1              0.000001     if l:has_bufline_api
    1   1.856902   0.005327         call setbufline(a:buffer, 1, l:new_lines)
    1              0.000006         call deletebufline(a:buffer, l:first_line_to_remove, '$')
                                " Fall back on setting lines the old way, for the current buffer.
                                else
                                    let l:old_line_length = line('$')

                                    if l:old_line_length >= l:first_line_to_remove
                                        let l:save = winsaveview()
                                        silent execute   l:first_line_to_remove . ',' . l:old_line_length . 'd_'
                                        call winrestview(l:save)
                                    endif

                                    call setline(1, l:new_lines)
    1              0.000000     endif

    1              0.000001     return l:new_lines

The biggest problem is that these two seconds are blocking, so I can't move the cursor.

Reproducing the bug

Install neovim 0.5 nightly, update ALE to the latest version and open a Python file with black and isort fixers installed and enabled.

:ALEInfo

 Current Filetype: python
Available Linters: ['bandit', 'flake8', 'jedils', 'mypy', 'prospector', 'pycodestyle', 'pydocstyle', 'pyflakes', 'pylama', 'pylint', 'pyls', 'pyre', 'pyright', 'vulture']
  Enabled Linters: ['flake8', 'mypy', 'pylint']
  Ignored Linters: []
 Suggested Fixers: 
  'add_blank_lines_for_python_control_statements' - Add blank lines before control statements.
  'autoimport' - Fix import issues with autoimport.
  'autopep8' - Fix PEP8 issues with autopep8.
  'black' - Fix PEP8 issues with black.
  'isort' - Sort Python imports with isort.
  'remove_trailing_lines' - Remove all blank lines at the end of a file.
  'reorder-python-imports' - Sort Python imports with reorder-python-imports.
  'trim_whitespace' - Remove all trailing whitespace characters at the end of every line.
  'yapf' - Fix Python files with yapf.
 Linter Variables:

let g:ale_python_auto_pipenv = 0
let g:ale_python_black_auto_pipenv = 0
let g:ale_python_black_change_directory = 1
let g:ale_python_black_executable = 'black'
let g:ale_python_black_options = ''
let g:ale_python_black_use_global = 0
let g:ale_python_flake8_auto_pipenv = 0
let g:ale_python_flake8_change_directory = 'project'
let g:ale_python_flake8_executable = 'flake8'
let g:ale_python_flake8_options = ''
let g:ale_python_flake8_use_global = 0
let g:ale_python_isort_auto_pipenv = 0
let g:ale_python_isort_executable = 'isort'
let g:ale_python_isort_options = ''
let g:ale_python_isort_use_global = 0
let g:ale_python_mypy_auto_pipenv = 0
let g:ale_python_mypy_executable = 'mypy'
let g:ale_python_mypy_ignore_invalid_syntax = 0
let g:ale_python_mypy_options = ''
let g:ale_python_mypy_show_notes = 1
let g:ale_python_mypy_use_global = 0
let g:ale_python_pylint_auto_pipenv = 0
let g:ale_python_pylint_change_directory = 1
let g:ale_python_pylint_executable = 'pylint'
let g:ale_python_pylint_options = ''
let g:ale_python_pylint_use_global = 0
let g:ale_python_pylint_use_msg_id = 0
 Global Variables:
let g:ale_cache_executable_check_failures = v:null
let g:ale_change_sign_column_color = 0
let g:ale_command_wrapper = ''
let g:ale_completion_delay = v:null
let g:ale_completion_enabled = 0
let g:ale_completion_max_suggestions = v:null
let g:ale_disable_lsp = 0
let g:ale_echo_cursor = 1
let g:ale_echo_msg_error_str = 'Error'
let g:ale_echo_msg_format = '[%linter%] %code%: %s'
let g:ale_echo_msg_info_str = 'Info'
let g:ale_echo_msg_warning_str = 'Warning'
let g:ale_enabled = 1
let g:ale_fix_on_save = 1
let g:ale_fixers = {'sh': ['shfmt'], 'html': ['prettier'], 'typescript': ['eslint'], 'go': ['gofmt'], 'markdown': ['prettier'], 'vue': ['eslint'], 'yaml': ['prettier'], 'htmldjango': ['html-beautify
'], 'python': ['black', 'isort'], 'tex': ['latexindent'], '*': ['remove_trailing_lines', 'trim_whitespace'], 'javascript': ['eslint'], 'json': ['prettier'], 'sql': ['pgformatter'], 'css': ['prettier']}
let g:ale_history_enabled = 1
let g:ale_history_log_output = 1
let g:ale_keep_list_window_open = 0
let g:ale_lint_delay = 200
let g:ale_lint_on_enter = 1
let g:ale_lint_on_filetype_changed = 1
let g:ale_lint_on_insert_leave = 1
let g:ale_lint_on_save = 1
let g:ale_lint_on_text_changed = 0
let g:ale_linter_aliases = {}
let g:ale_linters = {'sh': ['shellcheck', 'bashate'], 'typescript': ['eslint', 'tsserver'], 'markdown': ['markdownlint'], 'vue': ['eslint', 'vls'], 'Dockerfile': ['hadolint'], 'yaml': ['yamllint'], 'python': ['flake8', 'mypy', 'pylint'], 'xml': ['xmllint'], 'vim': ['vint'], 'tex': ['chktex'], 'sql': ['sqlint'], 'javascript': ['eslint'], 'gitcommit': ['gitlint'], 'zsh': ['shellcheck'], 'json': ['jsonlint'], 'vimwiki': ['markdownlint']}
let g:ale_linters_explicit = 0
let g:ale_linters_ignore = {}
let g:ale_list_vertical = 0
let g:ale_list_window_size = 10
let g:ale_loclist_msg_format = '[%linter%] %code%: %s'
let g:ale_max_buffer_history_size = 20
let g:ale_max_signs = -1
let g:ale_maximum_file_size = v:null
let g:ale_open_list = 0
let g:ale_pattern_options = {'\.min\.css$': {'ale_linters': [], 'ale_fixers': []}, 'site-packages\/.*$': {'ale_linters': [], 'ale_fixers': []}, 'node_modules\/.*$': {'ale_linters': [], 'ale_fixers': []}, '\.min\.js$': {'ale_linters': [], 'ale_fixers': []}, 'crontab$': {'ale_linters': [], 'ale_fixers': ['trim_whitespace']}, '\.git\/(?!COMMIT_EDITMSG)$': {'ale_linters': [], 'ale_fixers': []}}
let g:ale_pattern_options_enabled = v:null
let g:ale_root = {}
let g:ale_set_balloons = 0
let g:ale_set_highlights = 1
let g:ale_set_loclist = 0
let g:ale_set_quickfix = 1
let g:ale_set_signs = 1
let g:ale_sign_column_always = 0
let g:ale_sign_error = ''
let g:ale_sign_info = ''
let g:ale_sign_offset = 1000000
let g:ale_sign_style_error = ''
let g:ale_sign_style_warning = ''
let g:ale_sign_warning = ''
let g:ale_sign_highlight_linenrs = 0
let g:ale_statusline_format = v:null
let g:ale_type_map = {}
let g:ale_use_global_executables = v:null
let g:ale_virtualtext_cursor = 0
let g:ale_warn_about_trailing_blank_lines = 1
let g:ale_warn_about_trailing_whitespace = 1
  Command History:
(finished - exit code 0) ['/usr/bin/zsh', '-c', 'cd ''<project>'' && ''<virtualenv>/black'' - < ''/tmp/nvimkTnYvX/12/test.py''']
(finished - exit code 0) ['/usr/bin/zsh', '-c', 'cd ''<project>'' && ''<virtualenv>/isort'' - < ''/tmp/nvimkTnYvX/13/test.py''']

[bo5o]

I narrowed down the issue. Disabling treesitter for python solves the problem.

FUNCTIONS SORTED ON TOTAL TIME
count  total (s)   self (s)  function
    1   0.048810   0.000128  ale#fix#ApplyFixes()
    1   0.048475   0.007672  ale#fix#ApplyQueuedFixes()
    9   0.038978   0.000405  ale#python#FindExecutable()
    9   0.038371   0.020308  ale#python#FindVirtualenv()
    1   0.035338   0.000046  ale#Queue()
    1   0.034697   0.000035  ale#engine#RunLinters()
    3   0.018789   0.000359  ale#engine#HandleLoclist()
    1   0.016812   0.000100  ale#events#SaveEvent()
    1   0.016632   0.000219  ale#fix#Fix()
 1410   0.015747             ale#path#Simplify()
    3   0.015342   0.000426  ale#engine#SetResults()
    5   0.014710   0.001102  ale#command#Run()
    3   0.013986   0.000035  ale#linter#GetCommand()
    5   0.010455   0.010424  ale#job#Start()
    3   0.010333   0.000072  ale_linters#python#flake8#GetExecutable()
    3   0.010298   0.000047  ale#linter#GetExecutable()
    1   0.010229   0.000115  ale#fixers#black#Fix()
    1   0.010024   0.000052  ale#fixers#black#GetExecutable()
    1   0.007035   0.000028  ale_linters#python#flake8#RunWithVersionCheck()
    3   0.007032   0.000041  ale#semver#RunWithVersionCheck()

[bo5o]

I posted the issue on nvim-treesitter/nvim-treesitter

[hsanson]

This seems related to #3634 but so far no viable workaround has been found AFAIK. That issue mentions very large files but this case is not that big and your investigation seems to indicate treesitter may have something to do with the slowness. Thanks for reporting.

[baldore]

Just to mention that this happened to me with Javascript using eslint_d. The file is not that big (only 159 lines). Disabled treesitter and works like a charm again!

[vimpostor]

Can someone test if the following patch fixes that performance problem. I haven't yet been able to reliably reproduce the performance issue on my system, otherwise I would test it myself (alternatively provide me a complete file where you can reproduce the performance problem).

0001-Avoid-performance-problems-with-setbufline-and-Trees.patch.txt

Also available at https://github.com/vimpostor/ale/tree/slow_fixer

This uses nvim_buf_set_lines() instead, which should be faster.

If this does indeed improve performance, I can create a PR (I have to test some edge cases first), so I'd appreciate it if someone could test this. :)

[bo5o]

Here are my results.

dense-analysis/ale/tree/master@8b3b16d

FUNCTION  ale#util#SetBufferContents()
    Defined: ~/.local/share/nvim/plugged/ale/autoload/ale/util.vim:503
Called 1 time
Total time:   1.452711
 Self time:   0.135938
                                                      ...
    1              0.000001     if l:has_bufline_api
    1   1.450276   0.135625         call setbufline(a:buffer, 1, l:new_lines)
    1   0.002391   0.000272         call deletebufline(a:buffer, l:first_line_to_remove, '$')
                                " Fall back on setting lines the old way, for the current buffer.

vimpostor/ale/tree/slow_fixer@f977e09

FUNCTION  ale#util#SetBufferContents()
    Defined: ~/.local/share/nvim/plugged/ale/autoload/ale/util.vim:503
Called 1 time
Total time:   0.017660
 Self time:   0.008204
                                                      ...
    1              0.000001     if l:has_bufline_api
    1              0.000003         if has('nvim')
    1   0.017605   0.008151             call nvim_buf_set_lines(a:buffer, 0, l:first_line_to_remove, 0, l:new_lines)
                                    else
                                        call setbufline(a:buffer, 1, l:new_lines)
                                        call deletebufline(a:buffer, l:first_line_to_remove, '$')
    1              0.000001         endif
                                " Fall back on setting lines the old way, for the current buffer.

Overall speedup as expected. This has been mentioned here as well: https://github.com/nvim-treesitter/nvim-treesitter/issues/1118#issuecomment-873658538

EDIT: Added git commit hashes.

[bo5o]

There is a weird error that was introduced by the patch. Sometimes ale will now duplicate the last line at the end of the file, producing syntax errors etc.

[vimpostor]

There is a weird error that was introduced by the patch. Sometimes ale will now duplicate the last line at the end of the file, producing syntax errors etc.

Thanks very much for testing! I will fix that bug tomorrow.

[vimpostor]

@cbows I have fixed that bug with duplicate lines at the end now. It would be highly appreciated if you could test if #3974 works for you now.

[Draiken]

@vimpostor did you ever manage to fix this issue? I am trying to debug slowness in ALE with fixers and came across this issue and this other issue you created in core vim too, but I didn't find an obvious culprit with VIM profiling. Although for me this is likely not the same issue since I don't use nvim.

[vimpostor]

@vimpostor did you ever manage to fix this issue?

Yes, I did find the solution in #3974, and you can apply the patch from that PR to fix the slowness. Unfortunately it has an unintended sideeffect of shifting the signcolumn briefly, which seems to be a bug in neovim.

Edit: I have fixed the flickering issues, could you please try out if #3974 (check out https://github.com/vimpostor/ale/tree/slow_fixer) works for you?

[Draiken]

Sorry, I gave up on ALE after hours trying to figure out these performance issues. I moved on to COC and the performance is ridiculously better. My code actually gets formatted/fixed within a second now.

[vimpostor]

@hsanson Can you reopen #3974 please? Others may still be interested in the performance improvements.