Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Too much time cost in airline#highlighter#highlight() #1779

Closed
yousong opened this issue Aug 21, 2018 · 77 comments
Closed

Too much time cost in airline#highlighter#highlight() #1779

yousong opened this issue Aug 21, 2018 · 77 comments

Comments

@yousong
Copy link
Contributor

yousong commented Aug 21, 2018

environment

Vim

➜  ~/.vim/bundle/vim-airline git:(master) vim --version
VIM - Vi IMproved 8.0 (2016 Sep 12, compiled Jul 11 2018 06:10:39)
Included patches: 1-1605
Compiled by yunion@titan.hq.cloud.yunionyun.com
Huge version without GUI.  Features included (+) or not (-):
+acl               +farsi             +mouse_sgr         -tag_any_white
+arabic            +file_in_path      -mouse_sysmouse    -tcl
+autocmd           +find_in_path      +mouse_urxvt       +termguicolors
-autoservername    +float             +mouse_xterm       +terminal
-balloon_eval      +folding           +multi_byte        +terminfo
+balloon_eval_term -footer            +multi_lang        +termresponse
-browse            +fork()            -mzscheme          +textobjects
++builtin_terms    +gettext           -netbeans_intg     +timers
+byte_offset       -hangul_input      +num64             +title
+channel           +iconv             +packages          -toolbar
+cindent           +insert_expand     +path_extra        +user_commands
-clientserver      +job               -perl              +vertsplit
-clipboard         +jumplist          +persistent_undo   +virtualedit
+cmdline_compl     +keymap            +postscript        +visual
+cmdline_hist      +lambda            +printer           +visualextra
+cmdline_info      +langmap           +profile           +viminfo
+comments          +libcall           +python            +vreplace
+conceal           +linebreak         -python3           +wildignore
+cryptv            +lispindent        +quickfix          +wildmenu
+cscope            +listcmds          +reltime           +windows
+cursorbind        +localmap          +rightleft         +writebackup
+cursorshape       +lua               -ruby              -X11
+dialog_con        +menu              +scrollbind        -xfontset
+diff              +mksession         +signs             -xim
+digraphs          +modify_fname      +smartindent       -xpm
-dnd               +mouse             +startuptime       -xsmp
-ebcdic            -mouseshape        +statusline        -xterm_clipboard
+emacs_tags        +mouse_dec         -sun_workshop      -xterm_save
+eval              -mouse_gpm         +syntax
+ex_extra          -mouse_jsbterm     +tag_binary
+extra_search      +mouse_netterm     +tag_old_static
   system vimrc file: "$VIM/vimrc"
     user vimrc file: "$HOME/.vimrc"
 2nd user vimrc file: "~/.vim/vimrc"
      user exrc file: "$HOME/.exrc"
       defaults file: "$VIMRUNTIME/defaults.vim"
  fall-back for $VIM: "/home/yunion/.usr/share/vim"
Compilation: gcc -c -I. -Iproto -DHAVE_CONFIG_H   -isystem /home/yunion/.usr/include  -isystem /home/yunion/.usr/include -U_FORTIFY_SOURCE -D_FORTIFY_SOURCE=1
Linking: gcc   -L/home/yunion/.usr/lib -Wl,-rpath,/home/yunion/.usr/lib -L/usr/local/lib -Wl,--as-needed -o vim        -lm -lnsl   -lncurses -liconv -ldl  -L/home/yunion/.usr/lib
 -lluajit-5.1  -L/home/yunion/.usr/lib/python2.7/config -lpython2.7 -lpthread -ldl -lutil -lm -Xlinker -export-dynamic

Vim airline version

commit b790fd212088c0c882f16416f07cbd6035882028 (HEAD -> master, origin/master, origin/HEAD)
Merge: c3a814d a141918
Author: Christian Brabandt <cb@256bit.org>
Date:   Mon Jun 18 08:39:53 2018 +0200

    Merge pull request #1750 from Mangero/arduino-whitespace

    Add Arduino to list of C-like languages

CentOS 7 Linux titan 3.10.0-514.26.2.el7.x86_64

Airline configuration

let g:airline_highlighting_cache = 1
" disable tagbar integration (can be slow)
let g:airline#extensions#tagbar#enabled = 0
let g:airline#extensions#wordcount#enabled = 0
let g:airline#extensions#whitespace#enabled = 0
" disable fugitive integration (takes up space)
let g:airline#extensions#branch#enabled = 0
" show filename (no (compressed) path) in the tab
let g:airline#extensions#tabline#enabled = 1
let g:airline#extensions#tabline#fnamemod = ':t'
" save tabline space
let g:airline#extensions#tabline#show_splits = 0
let g:airline#extensions#tabline#show_tab_type = 0
" no need to show "filetype<fileencoding[fileformat]"
let g:airline_section_x = ''
let g:airline_section_y = ''

actual behavior

I use vim with plugin vim-go. The editor seems to slow down gradually over time. I need to quit and reopen to start it over again.

:profile result shows that a lot of time was spent iterating g:airline#themes#{g:airline_theme}#palette[mode] inside function airline#highlighter#highlight()

Full profile.log attached. It was generated just by moving the cursor between different windows a few times.

FUNCTION  airline#highlighter#highlight()
Called 12 times
Total time:   5.199249
 Self time:   0.794295

count  total (s)   self (s)
   12              0.000049   let bufnr = a:0 ? a:1 : ''
   12              0.000070   let p = g:airline#themes#{g:airline_theme}#palette

                              " draw the base mode, followed by any overrides
   12              0.000190   let mapped = map(a:modes, 'v:val == a:modes[0] ? v:val : a:modes[0]."_".v:val')
   12              0.000096   let suffix = a:modes[0] == 'inactive' ? '_inactive' : ''
   30              0.000096   for mode in mapped
   18              0.000088     if mode == 'inactive' && winnr('$') == 1
                                  " there exist no inactive windows, don't need to create all those
                                  " highlighting groups
                                  continue
                                endif
   18              0.000162     if exists('g:airline#themes#{g:airline_theme}#palette[mode]')
   12              0.000107       let dict = g:airline#themes#{g:airline_theme}#palette[mode]
 3324              0.012849       for kvp in items(dict)
 3312              0.015744         let mode_colors = kvp[1]
 3312              0.013170         let name = kvp[0]
 3312              0.015946         if name is# 'airline_c' && !empty(bufnr) && suffix is# '_inactive'
    6              0.000025           let name = 'airline_c'.bufnr
    6              0.000007         endif
 3312   1.091446   0.044705         call airline#highlighter#exec(name.suffix, mode_colors)

 9936              0.031345         for accent in keys(s:accents)
 6624              0.030404           if !has_key(p.accents, accent)
                                        continue
                                      endif
 6624              0.037262           let colors = copy(mode_colors)
 6624              0.035839           if p.accents[accent][0] != ''
 3312              0.017361             let colors[0] = p.accents[accent][0]
 3312              0.004331           endif
 6624              0.025435           if p.accents[accent][2] != ''
 3312              0.015959             let colors[2] = p.accents[accent][2]
 3312              0.004185           endif
 6624              0.021166           if len(colors) >= 5
 6624              0.040522             let colors[4] = get(p.accents[accent], 4, '')
 6624              0.008942           else
                                        call add(colors, get(p.accents[accent], 4, ''))
                                      endif
 6624   2.076114   0.098259           call airline#highlighter#exec(name.suffix.'_'.accent, colors)
 6624              0.009903         endfor
 3312              0.004052       endfor

                                  " TODO: optimize this
 3216              0.010949       for sep in items(s:separators)
 3204   1.443267   0.062909         call <sid>exec_separator(dict, sep[1][0], sep[1][1], sep[1][2], suffix)
 3204              0.004769       endfor
   12              0.000038     endif
   18              0.000020   endfor
@chrisbra
Copy link
Member

see #1026, the FAQ and the related information. If you have further suggestions how to improve the performance, I am all ears ;)

@chrisbra
Copy link
Member

BTW: it might also be related to your airline theme and syntax highlighting. Check the output of :syntime

@yousong
Copy link
Contributor Author

yousong commented Aug 21, 2018

I have read #1026 before, I tried. The result is adding g:airline_highlighting_cache=1 to my config. It does not resolve my issue.

I also tried syntime on , syntime report , but the output had no interesting output as far as I could tell. I will try to log the output next time in case it may.

From the profile log output, I think the issue reported here is different from that of #1026, the editor works fine at startup, but the performance degrades over time, possibly things continue to add up in the palette dict. I was expecting advice on this.

@yousong
Copy link
Contributor Author

yousong commented Aug 21, 2018

The airline#highlighter#highlight() func called only 12 times, yet it loops 3324 times inside. That just does not smell right.

@chrisbra
Copy link
Member

The airline#highlighter#highlight() func called only 12 times, yet it loops 3324 times inside. That just does not smell right.

Indeed. I'l have another look

@chrisbra chrisbra reopened this Aug 21, 2018
yousong added a commit to yousong/dconf that referenced this issue Aug 22, 2018
Seems like now I have tweaked the configuration to a minimal that serves
no notable real function other than just a slightly more fresh good
looking, yet the lag is just untolerable.  Disable it for now until
vim-airline/vim-airline#1779 is fixed
@languitar
Copy link
Contributor

I was hit by this as well and had to switch to some other statusline until this is fixed.

@chrisbra
Copy link
Member

chrisbra commented Oct 10, 2018 via email

@languitar
Copy link
Contributor

languitar commented Oct 10, 2018

Here is my profile.log for that session:
https://gist.github.com/languitar/eecdacb3a81dd23fea6e37bc0e3b0b10

Things definitely get slower over time.

@chrisbra
Copy link
Member

chrisbra commented Oct 10, 2018 via email

@languitar
Copy link
Contributor

Yes, I tried setting the caching, but then I frequently get broken renderings in airline.

@chrisbra
Copy link
Member

chrisbra commented Oct 10, 2018 via email

@languitar
Copy link
Contributor

In in active windows, some UTF-8 characters are rendered wrong. I'll try to provide a screenshot when I'm back at work.

@chrisbra
Copy link
Member

chrisbra commented Oct 11, 2018 via email

@languitar
Copy link
Contributor

Yes, otherwise that works well.

@languitar
Copy link
Contributor

2018-10-11t11 55 11 02 00
left is without caching, right is with caching. See the artifcat at the bottom in the right version.

@chrisbra
Copy link
Member

chrisbra commented Oct 11, 2018 via email

@languitar
Copy link
Contributor

it's neovim in terminal. There's no gui verison I could test.

@chrisbra
Copy link
Member

chrisbra commented Oct 11, 2018 via email

@languitar
Copy link
Contributor

termite v13. Same thing happens in stock vim.

@languitar
Copy link
Contributor

Btw, my configuration is online here: https://github.com/languitar/config-vim

@chrisbra
Copy link
Member

Several things to test:

  1. Try with different terminals and also with a gui version
  2. disable the unicode characters first, it actually looks a bit like a font problem (you can see those artifacts on the left side of your screenshot too)
  3. show the output of :echo eval(&stl[2:])
  4. try to provide a minimal example, that shows those problems. Then I have a chance to fix the caching problem.

thanks

@languitar
Copy link
Contributor

languitar commented Oct 15, 2018

  1. Try with different terminals and also with a gui version

Which terminal does support termguicolors that I could test on this setup?

  1. disable the unicode characters first, it actually looks a bit like a font problem (you can see those artifacts on the left side of your screenshot too)

What kind of artifacts? The staircase symbol is actually what I configured. However, without caching, it doesn't stick out of the status line for inactive windows.

  1. show the output of :echo eval(&stl[2:])

Without caching:

%{airline#check_mode(1)}%#airline_a#%( %#airline_a_bold#%{airline#util#wrap(airline#parts#mode(),0)}%#airline_a#%{airline#util#appen
d(airline#parts#crypt(),0)}%{airline#util#append(airline#parts#paste(),0)}%{airline#util#append(airline#extensions#keymap#status(),0
)}%{airline#util#append(airline#parts#spell(),0)}%{airline#util#append("",0)}%{airline#util#append("",0)}%{airline#util#append(airli
ne#parts#iminsert(),0)} %)%#airline_a_to_airline_b#▙%#airline_b#%( %{airline#util#wrap(airline#extensions#branch#get_head(),0)} %)%#
airline_b_to_airline_c#▙%#airline_c#%( %<%<%{airline#extensions#fugitiveline#bufname()}%m %#airline_c_red#%{airline#util#wrap(airlin
e#parts#readonly(),0)}%#airline_c# %)%=%#airline_c_to_airline_x#▟%#airline_x#%( %{airline#util#prepend(airline#extensions#gutentags#
status(),0)}%{airline#util#prepend("",0)}%{airline#util#wrap(airline#parts#filetype(),0)} %)%#airline_x_to_airline_y#▟%#airline_y#%(
 %{airline#util#wrap(airline#parts#ffenc(),0)} %)%#airline_y_to_airline_z#▟%#airline_z#%( %4l/%L %)%#airline_z_to_airline_warning#▟%
#airline_warning#%( %{airline#util#wrap(airline#extensions#languageclient#get_warning(),0)}%{airline#util#wrap(airline#extensions#wh
itespace#check(),0)} %)%( %{airline#util#wrap(airline#extensions#languageclient#get_error(),0)} %)
  1. try to provide a minimal example, that shows those problems. Then I have a chance to fix the caching problem.
scriptencoding utf8
set hidden

" bundle settings
filetype off

call plug#begin('~/.local/share/nvim/bundle/')

Plug 'chriskempson/base16-vim'
Plug 'bling/vim-airline'
Plug 'vim-airline/vim-airline-themes'

call plug#end()

colorscheme base16-bright
" only happens with this setting
let g:airline_theme="base16"

set termguicolors

let g:airline_powerline_fonts=0
let g:airline_left_sep='▙'
let g:airline_right_sep='▟'

let g:airline_highlighting_cache=1

The important thing seems to be the base16-bright theme. Without that, the artifacts do not appear. If I use "base16-bright" the issue is also fixed.

@languitar
Copy link
Contributor

Ok, things are not entirely gone with the "base16-bright" theme, but at least things are better.

@chrisbra
Copy link
Member

Ah, your staircase separator confused me.

Which terminal does support termguicolors that I could test on this setup?

perhaps gnome-terminal or xfce-terminal? (just plain, without tmux or similar)

Without caching...

could that be a dup of #1807?

@languitar
Copy link
Contributor

Ah, your staircase separator confused me.

Which terminal does support termguicolors that I could test on this setup?

perhaps gnome-terminal or xfce-terminal? (just plain, without tmux or similar)

Also happens in gnome-terminal.

Without caching...

could that be a dup of #1807?

As far as I can tell, not. The statusline deactivates properly, but the colors of some symbols are off in the deactivated statusline. Moreover, this simply doesn't happen without caching.

@chrisbra
Copy link
Member

As far as I can tell, not. The statusline deactivates properly, but the colors of some symbols are off in the deactivated statusline. Moreover, this simply doesn't happen without caching.

So how do I reproduce this?

@chrisbra
Copy link
Member

Well, re-creating the highlighting groups is expensive. What kind of a system is this? I think this will get better, once the vim9 script branch is merged. But I need to re-do this

@skylarmb
Copy link

skylarmb commented May 6, 2021

2021, same issue persists. I cant use this plugin at all on my macbook air, its just not powerful enough... I have 37 plugins installed yet Airline seems to take 90% of my cpu time

FUNCTIONS SORTED ON TOTAL TIME
count  total (s)   self (s)  function
  264   4.581206   0.069433  airline#check_mode()
   16   4.494055   0.273587  airline#highlighter#highlight()
 2184   3.909782   0.257406  <SNR>132_exec_separator()
 6994   3.092190   1.310224  airline#highlighter#get_highlight()
 4368   2.279014   0.138221  airline#themes#get_highlight()
  191   1.991047             provider#python3#Call()
  190   1.978191             UltiSnips#TrackChange()
27976   1.703343             <SNR>132_get_syn()
 2626   1.684373   0.366774  airline#highlighter#exec()
  264   0.531249   0.031849  airline#extensions#branch#get_head()
  264   0.477169   0.016490  airline#extensions#branch#head()
  126   0.387008             <SNR>122_parse_screen()
  264   0.369182   0.048208  <SNR>134_update_branch()
  264   0.290786   0.024917  <SNR>134_update_git_branch()
  264   0.258194   0.012128  <SNR>134_config_fugitive_branch()
  264   0.246067   0.011044  FugitiveHead()
  264   0.225434   0.047352  fugitive#Head()
    6   0.216495   0.171167  coc#float#create_cursor_float()
 1134   0.208297             <SNR>132_GetHiCmd()
  264   0.178082   0.121602  fugitive#Find()

FUNCTIONS SORTED ON SELF TIME
count  total (s)   self (s)  function
  191              1.991047  provider#python3#Call()
  190              1.978191  UltiSnips#TrackChange()
27976              1.703343  <SNR>132_get_syn()
 6994   3.092190   1.310224  airline#highlighter#get_highlight()
  126              0.387008  <SNR>122_parse_screen()
 2626   1.684373   0.366774  airline#highlighter#exec()
   16   4.494055   0.273587  airline#highlighter#highlight()
 2184   3.909782   0.257406  <SNR>132_exec_separator()
 1134              0.208297  <SNR>132_GetHiCmd()
    6   0.216495   0.171167  coc#float#create_cursor_float()
 4368   2.279014   0.138221  airline#themes#get_highlight()
  264   0.178082   0.121602  fugitive#Find()
 2626              0.116937  <SNR>132_CheckDefined()
  264   0.175864   0.088699  airline#extensions#hunks#get_hunks()
  264   0.091497   0.084252  <SNR>134_update_untracked()
 6994              0.078623  <SNR>132_get_array()
  386   0.083163   0.078616  <SNR>95_notify()
  264   4.581206   0.069433  airline#check_mode()
  528              0.063893  airline#extensions#coc#get()
  264   0.076821   0.062234  airline#extensions#whitespace#check()


@chrisbra
Copy link
Member

chrisbra commented May 6, 2021 via email

@chrisbra
Copy link
Member

chrisbra commented May 7, 2021

BTW: This:

191              1.991047  provider#python3#Call()
190              1.978191  UltiSnips#TrackChange()

This definitely does not come from airline

@skylarmb
Copy link

skylarmb commented May 7, 2021

@chrisbra yes, I know, this profiling was informative in multiple ways and I also ended up disabled UltiSnips.

FYI for anyone looking for an alternative, https://github.com/itchyny/lightline.vim seems to take nearly zero cpu time in comparison to this plugin.

@skylarmb
Copy link

skylarmb commented May 7, 2021

I understand this is an open source project. I posted because this issue was considered solved/closed, and I just wanted to say that from my perspective, on low end hardware, it's not.

If I get a chance, I will look into maybe seeing if I can add a flag to disable some of the expensive parts of this plugins operations with the downside of losing some functionality while keeping the awesome themeing support and other features I love.

@chrisbra
Copy link
Member

chrisbra commented May 7, 2021

well, as said, Using caching has very much speed up the performance for me and until very recently I haven't heard any complaints. I am a bit confused, why there are so many complaints now, because I cannot reproduce and I usually work on a slow virtual machine.
Note: you still haven't said, what is a minimal configuration to trigger this issue and whether you followed the advise from the wiki regarding performance improvements. What is known is, redefining highlighting groups on the fly is expansive for vim and there is no proper API to do this from proper vim script. Not sure what lightline does different in this regard and as said previously, the partly rewrite in Vim9 script should improve things a lot.

@chrisbra
Copy link
Member

chrisbra commented May 8, 2021

BTW: This is a profile with vim and vim9 script and :let g:airline_experimental=1 and revision e7eea7c

FUNCTIONS SORTED ON TOTAL TIME
count  total (s)   self (s)  function
    5   0.463143   0.000559  <SNR>160_UpdateView()
    5   0.384754   0.000910  <SNR>160_GetDiff()
    5   0.383609   0.002452  <SNR>160_MakeDiff_new()
    5   0.208631   0.000636  <SNR>167_ExecuteCtags()
  70   0.188457   0.002373  airline#extensions#tagbar#currenttag()
    5   0.187828   0.000902  <SNR>160_ReturnGitRepPath()
  12   0.186069   0.003826  <SNR>167_AutoUpdate()
  24   0.184659   0.001482  tagbar#currenttag()
    3   0.170980   0.026903  <SNR>167_ProcessFile()
  24   0.164601   0.000700  <SNR>167_Init()
    6   0.116569   0.001450  changes#Init()
    3   0.113381   0.000476  <SNR>167_ExecuteCtagsOnFile()
    3   0.112834   0.000505  <SNR>160_GuessVCSSystem()
  70   0.067325   0.009897  airline#check_mode()
  19   0.059677   0.001357  airline#extensions#tabline#get()
    1   0.059585   0.000401  <SNR>167_CheckForExCtags()
  26   0.056508   0.015575  274()
  15   0.053643   0.001070  airline#highlighter#highlight()
  14   0.051446   0.001644  airline#extensions#tabline#tabs#get()
    8   0.050910   0.001587  277()

FUNCTIONS SORTED ON SELF TIME
count  total (s)   self (s)  function
    3   0.170980   0.026903  <SNR>167_ProcessFile()
  998              0.026391  airline#themes#get_highlight()
2195   0.046639   0.025531  airline#highlighter#get_highlight()
  41   0.026107   0.025530  <SNR>46_Highlight_Matching_Pair()
  36   0.025471   0.024288  <SNR>167_GetNearbyTag()
8780              0.019473  <SNR>134_get_syn()
  26   0.056508   0.015575  274()
  61   0.027487   0.010331  airline#extensions#whitespace#check()
  70   0.067325   0.009897  airline#check_mode()
  841   0.027700   0.009647  airline#highlighter#exec()
    2              0.008236  airline#extensions#tabline#redraw()
    7              0.007671  <SNR>142_conflict_marker()
  499   0.048781   0.007388  <SNR>134_exec_separator()
    7              0.007222  <SNR>142_check_mixed_indent()
  68   0.011889   0.006700  tagbar#prototypes#basetag#new()
  61   0.023415   0.006285  <SNR>167_ParseTagline()
  187              0.006089  <SNR>155_get_accented_line()
  61   0.015804   0.006050  <SNR>140_update_untracked()
  621              0.005990  airline#util#winwidth()
  61   0.011317   0.005897  airline#extensions#hunks#get_hunks()

Still some airline functions in there, but overall much better.

@quolpr
Copy link

quolpr commented May 10, 2021

@chrisbra I am using neovim

➜  ~ nvim -v
NVIM v0.4.4
Build type: Release
LuaJIT 2.1.0-beta3
Compilation: clang -U_FORTIFY_SOURCE -D_FORTIFY_SOURCE=1 -DNDEBUG -DMIN_LOG_LEVEL=3 -Wall -Wextra -pedantic -Wno-unused-parameter -Wstrict-prototypes -std=gnu99 -Wshadow -Wconversion -Wmissing-prototypes -Wimplicit-fallthrough -Wvla -fstack-protector-strong -fno-common -fdiagnostics-color=auto -DINCLUDE_GENERATED_DECLARATIONS -D_GNU_SOURCE -DNVIM_MSGPACK_HAS_FLOAT32 -DNVIM_UNIBI_HAS_VAR_FROM -I/tmp/neovim-20210220-9964-1eolqf4/neovim-0.4.4/build/config -I/tmp/neovim-20210220-9964-1eolqf4/neovim-0.4.4/src -I/opt/homebrew/include -I/opt/homebrew/opt/luv/include -I/Library/Developer/CommandLineTools/SDKs/MacOSX.sdk/usr/include -I/opt/homebrew/opt/gettext/include -I/tmp/neovim-20210220-9964-1eolqf4/neovim-0.4.4/build/src/nvim/auto -I/tmp/neovim-20210220-9964-1eolqf4/neovim-0.4.4/build/include
Compiled by brew@HMBRW-A-001-M1-005.local

Features: +acl +iconv +tui
See ":help feature-compile"

   system vimrc file: "$VIM/sysinit.vim"
  fall-back for $VIM: "/opt/homebrew/Cellar/neovim/0.4.4_1/share/nvim"

Run :checkhealth for more info

And mac os 11.4(beta) on m1

@quolpr
Copy link

quolpr commented May 10, 2021

@skylarmb I guess it could be an issue in the external plugin for vim-airline, if the bottleneck in python3 call

In my case, the issue is the highlighter functions.

And, I found that it starts lags when I use neovim for a long time, and when I switch vim window from fern(file explorer) to file editing. The stack trace that I supplied was made when I was doing that switch. Sorry to forget to mention.

@chrisbra
Copy link
Member

chrisbra commented May 10, 2021 via email

@dmitmel
Copy link

dmitmel commented Aug 3, 2021

I think I may have found either the reason for this issue, or at least another source of slowdowns. I discovered this because I have been setting up Neovim's builtin LSP client which has this functionality for opening a "hover" window with the information for the symbol under the cursor (screenshot). I have been observing that my nvim setup would slow down over time, and today I got fed up with this and began investigating. Don't know why, but I thought that the floating windows were related to the issue, so I came up with a simple stress test which was a Python script which would repeatedly simulate presses of shift+K to trigger this hover window. The test was a success because it would consistently slow Vim down to a crawl after a few minutes of automatically pressing K. Anyway, after performing such a test, I ran the profiler and got a similar profile to the users above, i.e. most time is spent in the airline#highlighter module, s:get_syn in particular. After that I came up with this minimal vimrc which can be used for reproducing the bug:

set rtp+=~/.config/nvim/plugged/vim-airline

let s:iteration = 0
let s:existing_winnr = v:null

function! StressTestTimerCallback(timer) abort
  if s:existing_winnr && nvim_win_is_valid(s:existing_winnr)
    call nvim_win_close(s:existing_winnr, v:true)
  endif

  " Triggered on the last iteration.
  if empty(timer_info(a:timer))
    return
  endif

  let hlgroups_rough_count = len(split(execute('highlight'), "\n"))
  let text = printf('iteration:%d hlgroups:%d', s:iteration, hlgroups_rough_count)

  let bufnr = nvim_create_buf(v:false, v:true)
  call nvim_buf_set_option(bufnr, 'bufhidden', 'wipe')
  call nvim_buf_set_lines(bufnr, 0, -1, v:true, [text])
  call nvim_buf_set_option(bufnr, 'modifiable', v:false)
  let winnr = nvim_open_win(bufnr, v:false, {
  \ 'width': strdisplaywidth(text), 'height': 1,
  \ 'relative': 'cursor', 'row': 1, 'col': 0,
  \ 'style': 'minimal' })

  let s:existing_winnr = winnr
  let s:iteration += 1
endfunction

function! StressTestStart(total_iterations) abort
  let s:iteration = 0
  let s:existing_winnr = v:null
  call timer_start(100, 'StressTestTimerCallback', {'repeat': a:total_iterations})
endfunction

Needless to say, it requires Neovim, though it only seems to be effective on v0.5.0. To reproduce:

  1. save the code to a file, like minimal_init.vim
  2. run nvim -u minimal_init.vim
  3. :call StressTest(200), 200 is the number of opened-and-immediately-closed floating windows, adjust because the lag may take some time to become apparent
  4. The lag can be observed by switching to insert mode and back, for example.

Anyway... the issue in my setup seems to be that Airline creates a ton of highlight groups in airline#highlighter#exec for new windows and new buffers, but doesn't delete them. I doubt that this is specific to floating windows, it's just that the example above was the shortest thing I could come up with, though even opening new buffers causes a leak of highlight groups as well. Splitting windows and closing the splits might also do the trick. So yeah, I believe that the other users are essentially having "leaks" of highlight groups as well, and that s:get_syn is having trouble because of this. (Also I have to mention that prepending noautocmd to the line with nvim_open_win remedies the problem, but this should be applied only to plugins which are opening floating windows themselves and does not solve the underlying issue in Airline.)

Oh, and also, len(split(execute('highlight'), "\n")) is not an accurate measure of the total number of highlight groups because of the wrapping in :highlight, but it is enough to prove the point.

P. S. Here's my profile after running the prototype stress test for 13 minutes: profile.log.

@chrisbra
Copy link
Member

chrisbra commented Aug 3, 2021

so you are basically creating 200 random buffers? We could possibly clear the highlighting, if the old buffer no longer exists. But the highlighting group would still be there. That hints, that Vims datastructure is not optimized for too many highlighting groups (ping @brammool)

Also, can you please show the output of echo split(execute('highlight'), "\n") just resize the window large enough, such that no wrapping occurs. Just for 50 buffers should be enough.

@chrisbra
Copy link
Member

chrisbra commented Aug 3, 2021

it would also be interesting to see, how it runs on Vim9 Script

@chrisbra
Copy link
Member

chrisbra commented Aug 3, 2021

Anyway... the issue in my setup seems to be that Airline creates a ton of highlight groups in airline#highlighter#exec for new windows and new buffers, but doesn't delete them.

Oh and that is not possible.

@chrisbra
Copy link
Member

chrisbra commented Aug 3, 2021

FUNCTION  <SNR>126_get_syn()
    Defined: ~/.config/nvim/plugged/vim-airline/autoload/airline/highlighter.vim:44
Called 356588 times
Total time:  21.819761
 Self time:  21.819761

count  total (s)   self (s)
356588              0.365869     let color = ''
356588              9.068191     if hlexists(a:group)
241780              5.570819       let color = synIDattr(synIDtrans(hlID(a:group)), a:what, a:mode)
356588              0.171991     endif
356588              0.536942     if empty(color) || color == -1
                                  " should always exist
114808              3.668305       let color = synIDattr(synIDtrans(hlID('Normal')), a:what, a:mode)
                                  " however, just in case
114808              0.188707       if empty(color) || color == -1
                                    let color = 'NONE'
114808              0.042864       endif
356588              0.119569     endif
356588              0.284614     return color

So what we can see here is, hlexists() and synIDattr() are the bottleneck. That is calling inside Vims C core, I cannot improve it here with Vimscript.

@chrisbra
Copy link
Member

chrisbra commented Aug 3, 2021

Also, have you tried following the advice in the wiki? Basically about the caching and using a theme that does not switch colors?

@dmitmel
Copy link

dmitmel commented Aug 3, 2021

so you are basically creating 200 random buffers?

Yes, but only because that's a reliable way of forcing the performance issue, intended to help debugging. While working as usual hlgroups are still being leaked, but the slowdown becomes apparent much earlier than when Vim slows down to a crawl as with my stress test.

EDIT: and 200 random windows.

Also, have you tried following the advice in the wiki? Basically about the caching and using a theme that does not switch colors?

No, but I believe that I found a bug in the default implementation.

@chrisbra
Copy link
Member

chrisbra commented Aug 3, 2021

EDIT: and 200 random windows.

well, the highlighting groups are bound to buffers and you call something called nvim_create_buf(v:false, v:true) which makes it sound like it creates buffers.

No, but I believe that I found a bug in the default implementation.

of Vim? possible As I said the current API does not allow to delete highlighting groups. That is nothing vim-airline can fix. We might have to dig into the vim source to fix that.

@chrisbra
Copy link
Member

chrisbra commented Aug 3, 2021

nevertheless, I'll put it on my plate to dig this up in Vims source

@dmitmel
Copy link

dmitmel commented Aug 3, 2021

of Vim? possible As I said the current API does not allow to delete highlighting groups. That is nothing vim-airline can fix. We might have to dig into the vim source to fix that.

(of Airline) Pardon my ignorance, didn't remember. As a matter of fact I've worked around the slowdowns in my setup using noautocmd when opening floating windows, but I'll test hlgroup caching as well.

@dmitmel
Copy link

dmitmel commented Aug 3, 2021

well, the highlighting groups are bound to buffers and you call something called nvim_create_buf(v:false, v:true) which makes it sound like it creates buffers.

By the way: just creating random buffers and opening them in a single window doesn't trigger the leak.

@dmitmel
Copy link

dmitmel commented Aug 3, 2021

Strange. Groups are still being leaked even with caching enabled.

EDIT: ...though the slowdown is not as bad

@dmitmel
Copy link

dmitmel commented Aug 3, 2021

By the way, you don't even need some overcomplicated floating window setup, apparently, to reproduce the issue. Either I'm misunderstanding something, or Airline leaks groups even when just opening new buffers (with caching enabled, obviously). Try opening, like, five of them, then splitting the window and cycling through the buffers in both windows, and filtering groups with :filter /airline_c\d/ highlight or something.

Gonna attempt reproducing on a minimal vimrc.

@chrisbra
Copy link
Member

chrisbra commented Aug 3, 2021

Yes, I believe it is expected. It doesn't leak anything. It's just, once a buffer is displayed in a window it creates inactive highlighting groups, so that the statusline can display correctly even if the same buffer is in one window active while also displayed in another inactive window. And then it needs to create additional groups for those powerline glyphs, so that you have the nice from one foreground color to the next foreground color transition. And possibly again for the different accents. There is nothing leaking here.

@dmitmel
Copy link

dmitmel commented Aug 3, 2021

Try this:

  1. " minimal_vimrc.vim
    set nocompatible
    let g:airline_highlighting_cache = 1
    set rtp+=~/.config/nvim/plugged/vim-airline
  2. vim -u minimal_vimrc.vim a b c d e

  3. :bn 5 times to load load Airline for all buffers

  4. :filter /airline_c\d/ highlight
    airline_c1_inactive xxx ctermfg=239 ctermbg=236 guifg=#4e4e4e guibg=#303030
    airline_c2_inactive xxx ctermfg=239 ctermbg=236 guifg=#4e4e4e guibg=#303030
    airline_c3_inactive xxx ctermfg=239 ctermbg=236 guifg=#4e4e4e guibg=#303030
    airline_c4_inactive xxx ctermfg=239 ctermbg=236 guifg=#4e4e4e guibg=#303030
    airline_c5_inactive xxx ctermfg=239 ctermbg=236 guifg=#4e4e4e guibg=#303030
  5. :vsplit or :split, doesn't matter, need to create a second window

  6. Same, cycle through the buffers with :bn, but this time switch between windows with Ctrl+w w or something (I was switching after every :bn, this creates even more hlgroups)

  7. :filter /airline_c\d/ highlight
    airline_c1_inactive xxx ctermfg=239 ctermbg=236 guifg=#4e4e4e guibg=#303030
    airline_c2_inactive xxx ctermfg=239 ctermbg=236 guifg=#4e4e4e guibg=#303030
    airline_c3_inactive xxx ctermfg=239 ctermbg=236 guifg=#4e4e4e guibg=#303030
    airline_c4_inactive xxx ctermfg=239 ctermbg=236 guifg=#4e4e4e guibg=#303030
    airline_c5_inactive xxx ctermfg=239 ctermbg=236 guifg=#4e4e4e guibg=#303030
    airline_c1_to_airline_x xxx ctermfg=234 guifg=#202020
    airline_c1_inactive_bold xxx term=bold cterm=bold ctermfg=239 ctermbg=236 gui=bold guifg=#4e4e4e guibg=#303030
    airline_c1_inactive_red xxx ctermfg=160 ctermbg=236 guifg=#ff0000 guibg=#303030
    airline_c1_to_airline_x_inactive xxx ctermfg=236 ctermbg=236 guifg=#303030 guibg=#303030
    airline_c1_to_airline_x_bold xxx term=bold cterm=bold ctermfg=234 gui=bold guifg=#202020
    airline_c1_to_airline_x_red xxx ctermfg=160 guifg=#ff0000
    airline_c1_to_airline_x_inactive_inactive xxx ctermfg=236 ctermbg=236 guifg=#303030 guibg=#303030
    airline_c1_to_airline_x_inactive_inactive_bold xxx term=bold cterm=bold ctermfg=236 ctermbg=236 gui=bold guifg=#303030 guibg=#303030
    airline_c1_to_airline_x_inactive_inactive_red xxx ctermfg=160 ctermbg=236 guifg=#ff0000 guibg=#303030
    airline_c2_to_airline_x xxx ctermfg=234 guifg=#202020
    airline_c2_inactive_bold xxx term=bold cterm=bold ctermfg=239 ctermbg=236 gui=bold guifg=#4e4e4e guibg=#303030
    airline_c2_inactive_red xxx ctermfg=160 ctermbg=236 guifg=#ff0000 guibg=#303030
    airline_c2_to_airline_x_inactive xxx ctermfg=236 ctermbg=236 guifg=#303030 guibg=#303030
    airline_c2_to_airline_x_inactive_inactive xxx ctermfg=236 ctermbg=236 guifg=#303030 guibg=#303030
    airline_c2_to_airline_x_inactive_inactive_bold xxx term=bold cterm=bold ctermfg=236 ctermbg=236 gui=bold guifg=#303030 guibg=#303030
    airline_c2_to_airline_x_inactive_inactive_red xxx ctermfg=160 ctermbg=236 guifg=#ff0000 guibg=#303030
    airline_c2_to_airline_x_bold xxx term=bold cterm=bold ctermfg=234 gui=bold guifg=#202020
    airline_c2_to_airline_x_red xxx ctermfg=160 guifg=#ff0000
    airline_c3_to_airline_x xxx ctermfg=234 guifg=#202020
    airline_c3_inactive_bold xxx term=bold cterm=bold ctermfg=239 ctermbg=236 gui=bold guifg=#4e4e4e guibg=#303030
    airline_c3_inactive_red xxx ctermfg=160 ctermbg=236 guifg=#ff0000 guibg=#303030
    airline_c3_to_airline_x_inactive xxx ctermfg=236 ctermbg=236 guifg=#303030 guibg=#303030
    airline_c3_to_airline_x_inactive_inactive xxx ctermfg=236 ctermbg=236 guifg=#303030 guibg=#303030
    airline_c3_to_airline_x_inactive_inactive_bold xxx term=bold cterm=bold ctermfg=236 ctermbg=236 gui=bold guifg=#303030 guibg=#303030
    airline_c3_to_airline_x_inactive_inactive_red xxx ctermfg=160 ctermbg=236 guifg=#ff0000 guibg=#303030
    airline_c3_to_airline_x_bold xxx term=bold cterm=bold ctermfg=234 gui=bold guifg=#202020
    airline_c3_to_airline_x_red xxx ctermfg=160 guifg=#ff0000
    airline_c4_to_airline_x xxx ctermfg=234 guifg=#202020
    airline_c4_inactive_bold xxx term=bold cterm=bold ctermfg=239 ctermbg=236 gui=bold guifg=#4e4e4e guibg=#303030
    airline_c4_inactive_red xxx ctermfg=160 ctermbg=236 guifg=#ff0000 guibg=#303030
    airline_c4_to_airline_x_inactive xxx ctermfg=236 ctermbg=236 guifg=#303030 guibg=#303030
    airline_c4_to_airline_x_inactive_inactive xxx ctermfg=236 ctermbg=236 guifg=#303030 guibg=#303030
    airline_c4_to_airline_x_inactive_inactive_bold xxx term=bold cterm=bold ctermfg=236 ctermbg=236 gui=bold guifg=#303030 guibg=#303030
    airline_c4_to_airline_x_inactive_inactive_red xxx ctermfg=160 ctermbg=236 guifg=#ff0000 guibg=#303030
    airline_c4_to_airline_x_bold xxx term=bold cterm=bold ctermfg=234 gui=bold guifg=#202020
    airline_c4_to_airline_x_red xxx ctermfg=160 guifg=#ff0000
    airline_c5_to_airline_x xxx ctermfg=234 guifg=#202020
    airline_c5_inactive_bold xxx term=bold cterm=bold ctermfg=239 ctermbg=236 gui=bold guifg=#4e4e4e guibg=#303030
    airline_c5_inactive_red xxx ctermfg=160 ctermbg=236 guifg=#ff0000 guibg=#303030
    airline_c5_to_airline_x_inactive xxx ctermfg=236 ctermbg=236 guifg=#303030 guibg=#303030
    airline_c5_to_airline_x_inactive_inactive xxx ctermfg=236 ctermbg=236 guifg=#303030 guibg=#303030
    airline_c5_to_airline_x_inactive_inactive_bold xxx term=bold cterm=bold ctermfg=236 ctermbg=236 gui=bold guifg=#303030 guibg=#303030
    airline_c5_to_airline_x_inactive_inactive_red xxx ctermfg=160 ctermbg=236 guifg=#ff0000 guibg=#303030
    airline_c5_to_airline_x_bold xxx term=bold cterm=bold ctermfg=234 gui=bold guifg=#202020
    airline_c5_to_airline_x_red xxx ctermfg=160 guifg=#ff0000

There is nothing leaking here.

But then... what is caching supposed to do? Oh, and I observe the same behavior with or without caching.

@chrisbra
Copy link
Member

chrisbra commented Aug 3, 2021

Yes, as I said airline creates new highlighting groups, once a buffer is displayed in a non-active window, because one buffer could be modified the groups need to differ. Hm, perhaps we can link them to a default group since they are usually all the same. Also I am wondering why we have several _inactive_inactive groups. that does not look right.

caching prevents highlighting groups to be re-defined, even if they already exist.

@dmitmel
Copy link

dmitmel commented Aug 3, 2021

Regardless, the fact still stands that hlexists and synIDattr don't like having to loop through a lot of defined hlgroups. Do you think this is a bug on the Vim side (i.e. the functions being slow) or on the Airline side (creating identical hlgroups)?

@chrisbra
Copy link
Member

chrisbra commented Aug 3, 2021

probably a mixture of both. A solution could be to use pre-defined groups, instead of creating a bunch of groups for each buffer for all different buffer states (and possibly we can save some of those, if we are not using powerline glyphs).

But still the core vim functions are slow.

@brammool
Copy link

brammool commented Aug 4, 2021 via email

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

7 participants