GoDoc 8 second lag

[artemvmin]

What did you do? (required: The issue will be closed when not provided)

:GoDoc<CR> with the cursor over a function

What did you expect to happen?

Instantly show me the godoc for the function or field.

What happened instead?

8 seconds of lag every time the command is issued.

FUNCTIONS SORTED ON TOTAL TIME
count  total (s)   self (s)  function
    1   8.938043   0.000088  go#doc#Open()
    1   8.886164   0.000342  <SNR>348_godocWord()
    1   8.885691   0.002050  go#tool#Imports()
   36   8.883359   0.001051  go#util#ExecInDir()
   36   8.882308   0.001797  go#util#ExecInWorkDir()
   36   8.878612   0.002003  go#util#Exec()
   36   8.867614   0.002393  <SNR>203_exec()
   36   8.861831   0.008472  <SNR>203_system()
    1   0.051630   0.000268  go#lsp#Doc()

FUNCTION  <SNR>348_godocWord()
    Defined: ~/.vim/plugged/vim-go/autoload/go/doc.vim:203
Called 1 time
Total time:   8.886164
 Self time:   0.000342

count  total (s)   self (s)
    1              0.000002   let words = a:000
    1              0.000001   if a:0 is 0
    1              0.000002     let oldiskeyword = &iskeyword
                                " TODO(bc): include / in iskeyword when filetype is godoc?
    1              0.000027     setlocal iskeyword+=.
    1              0.000011     let word = expand('<cword>')
    1              0.000021     let &iskeyword = oldiskeyword
    1              0.000014     let word = substitute(word, '[^a-zA-Z0-9\\/._~-]', '', 'g')
    1              0.000009     let words = split(word, '\.\ze[^./]\+$')
    1              0.000001   endif

    1              0.000003   if !len(words)
                                return []
    1              0.000001   endif

    1              0.000005   let pkg = words[0]
    1              0.000002   if len(words) == 1
                                let exported_name = ''
                                if &filetype is 'godoc'
                                  if pkg =~ '^[A-Z]'
                                    let exported_name = pkg
                                    let pkg = b:go_package_name
                                  endif
                                endif
    1              0.000000   else
    1              0.000003     let exported_name = words[1]
    1              0.000000   endif

    1              0.000003   if &filetype isnot 'godoc'
    1   8.886037   0.000215     let packages = go#tool#Imports()
    1              0.000004     if has_key(packages, pkg)
    1              0.000003       let pkg = packages[pkg]
    1              0.000001     endif
    1              0.000000   endif


    1              0.000003   return [pkg, exported_name]

I have two fixes:

1. Commenting out the go#tool#Imports() call (https://github.com/fatih/vim-go/blob/master/autoload/go/doc.vim#L232-L237).
2. Reverting to one commit prior 39545de, which appears to have introduced the regression.

I believe the reason for this is that the old code called go doc directly:

function! go#doc#Open(newmode, mode, ...) abort
  " With argument: run "godoc [arg]".
  if len(a:000)
    let [l:out, l:err] = go#util#Exec(['go', 'doc'] + a:000)
  else " Without argument: use gopls to get documentation
    ...

Whereas the new code has to go through the goimports flow.

Notes:

• :GoImports<CR> experiences no lag and returns immediately.
• I have tested this against several of my Golang repositories and all exhibit the same excruciating delay.

Configuration (MUST fill this out):

vim-go version:

Latest (1.28)

vimrc you used to reproduce:

call plug#begin('~/.vim/plugged')
Plug 'fatih/vim-go', { 'for': 'go' }
call plug#end()
filetype plugin indent on
syntax on
<details><summary>vimrc</summary>

Vim version (first three lines from :version):

VIM - Vi IMproved 9.0 (2022 Jun 28, compiled Mar 05 2023 09:42:26)
Included patches: 1-1378
Modified by team+vim@tracker.debian.org

Go version (go version):

go1.21

gopls version

v0.11.0

[bhcleek]

Thank you for the thorough report. Let's see if you can get things sorted out.

:GoImports experiences no lag and returns immediately.

🤔 that's not terribly surprising: :GoImports is not related to go#tool#Imports

I have tested this against several of my Golang repositories and all exhibit the same excruciating delay.

Are these largish repositories? Does the delay occur on subsequent attempts, or is it only the first attempt? Does it matter if gopls initialization has completed before you try?

Reverting to one commit prior 39545de, which appears to have introduced the regression.
I believe the reason for this is that the old code called go doc directly:

The code you linked shows that it didn't call go doc directly in the case you're referring to. It only called go doc directly when there was no :GoDoc argument (i.e. when not getting the documentation based on the cursor location).

Whereas the new code has to go through the goimports flow.

The old code also went through go#tool#Imports: 39545de#diff-b7ba3665f97314c2e07d66db434c07065d522ce92dbeeaf557e383f6c504c5fbL204.

[artemvmin]

I have tested this against several of my Golang repositories and all exhibit the same excruciating delay.

Are these largish repositories? Does the delay occur on subsequent attempts, or is it only the first attempt? Does it matter if gopls initialization has completed before you try?

E.g. this package itself is not large, but it imports larger libraries (a.k.a. vendors).

This happens on all subsequent calls. I have confirmed that gopls is initialized.

Reverting to one commit prior 39545de, which appears to have introduced the regression.
I believe the reason for this is that the old code called go doc directly:

The code you linked shows that it didn't call go doc directly in the case you're referring to. It only called go doc directly when there was no :GoDoc argument (i.e. when not getting the documentation based on the cursor location).

Whereas the new code has to go through the goimports flow.

The old code also went through go#tool#Imports: 39545de#diff-b7ba3665f97314c2e07d66db434c07065d522ce92dbeeaf557e383f6c504c5fbL204.

Interesting. I guess misunderstood the arg. However, I can confirm that that this is the commit where GoDoc begins to lag on the go#tool#Imports call.

[artemvmin]

Thank you for looking into this!

The size of the repository does affect the delay. For example, it is not perceivable on https://github.com/golang/example.

I would be curious to see if you can reproduce this using the PDCSI directly, e.g. under https://github.com/kubernetes-sigs/gcp-compute-persistent-disk-csi-driver/blob/master/pkg/gce-pd-csi-driver/controller.go.

I think it's notable that the following action fixes the behavior and eliminates the lag. Although I have to say I'm not sure what it's doing in the larger context other than eliminating that 8 second delay caused by go#tool#Imports.

Commenting out the go#tool#Imports() call (https://github.com/fatih/vim-go/blob/master/autoload/go/doc.vim#L232-L237).

Also, if I interrupt the :GoDoc<CR> with Ctrl-C, I immediately get the GoDoc popup window. The contents of the window are identical whether I wait the full 8 seconds or if I interrupt immediately. This is suggesting that the process it's performing is not important at least for the functions, fields, and types that I have tested.

[bhcleek]

I would be curious to see if you can reproduce this using the PDCSI directly

I do see a delay, but not nearly as significant as you've reported.

This is suggesting that the process it's performing is not important at least for the functions, fields, and types that I have tested

That works right up until it doesn't. The call to go#tool#Imports is necessary for many use cases, and its virtually impossible to tell ahead of time whether it's required.

But I do see a way to optimize this. I'll put up a PR soon.

[hamidzr]

I get a similar behavior in my usage. Although I'm using Neovim which I know isn't supported

  10363   │ FUNCTIONS SORTED ON TOTAL TIME
  10364   │ count  total (s)   self (s)  function
  10365   │     2  15.704019   0.000194  go#doc#Open()
  10366   │     2  15.517691   0.000537  <SNR>231_godocWord()
  10367   │     2  15.517129   0.006072  go#tool#Imports()
* 10368   │   276  15.510566   0.009508  go#util#ExecInDir()
  10369   │   276  15.501058   0.005656  go#util#ExecInWorkDir()
  10370   │   276  15.430301   0.006237  go#util#Exec()
  10371   │   276  15.368784   0.007107  <SNR>106_exec()
  10372   │   276  15.342938   0.014858  <SNR>106_system()
  10373   │    54   0.351706   0.007506  airline#check_mode()
  10374   │    32   0.330127   0.046126  airline#highlighter#highlight()
  10375   │  1131   0.222263   0.077228  airline#highlighter#exec()
  10376   │  2185   0.201807   0.101248  airline#highlighter#get_highlight()
  10377   │   459   0.181610   0.015702  <SNR>155_exec_separator()
  10378   │    34   0.106850   0.013174  300()
  10379   │     2   0.104928   0.000128  go#lsp#Doc()
  10380   │     2   0.104170   0.099662  <SNR>234_await()
  10381   │    14   0.101823   0.000841  airline#update_statusline()
  10382   │    22   0.099263   0.000735  <SNR>151_invoke_funcrefs()
  10383   │  8740   0.093318             <SNR>155_get_syn()
  10384   │    14   0.090927   0.016625  coc#highlight#match_ranges()

there were a few other related bits, i'll attached the full log below
profile.log.txt

no issue if I try this:

Reverting to one commit prior 39545de, which appears to have introduced the regression.

[bhcleek]

I've been looking at this and want to correct a misstatement I made previously. The call to go#tool#Imports is new in this flow. It was previously called only in the :GoDocBrowser flow, because that was the only flow that called s:godocWord before 39545de.

I'm still trying to figure out a way to improve the performance here. It's not as simple as I thought it might be, but I think I'm going to be able to improve this.

[agis]

I can confirm that #3559 sped up :GoDoc significantly. On a fairly large project with a lot of deps and subpackages, from ~4sec it's now down to 1sec. or something. Thanks a ton @bhcleek!