Intense lag and lack of autocomplete relating to gocode

[fluofoxxo]

When typing in a manner that would normally cause the autocomplete to pop up, there is intense lag that seems to last for around a quarter of a second with no autocomplete suggestions appearing. A peek into the Sublime console shows messages that appear alongside the lag spikes:

[15:44:47] margo: agent#007: log: gocode.go:201: gocode didn't respond after 250ms taking 261ms
[15:44:47] margo: agent#007: log: gocode.go:176: gocode didn't accept the request after 101ms
[15:44:48] margo: agent#007: log: gocode.go:176: gocode didn't accept the request after 114ms
[15:44:48] margo: agent#007: log: gocode.go:192: gocode eventually responded after 1.384s

This behavior is observed no matter which package the autocomplete is running on. It occurs on both the next branch and the normal development branch. The local repo for github.com/mdempsky/gocode is on commit 939b4a6, the latest as of today. which gocode shows that it is correctly located in GOPATH's bin directory, which is also located in the path variable (Windows 10 64-bit).

[DisposaBoy]

GoSublime/margo doesn't use external github.com/mdempsky/gocode or gocode binary.

What does your margo.go file look like? also try restartaring Sublime Text if you've upgraded from an older version (assuming you haven't done so already).

[andyone]

@DisposaBoy Same problem for me. After updating to the latest version autocomplete doesn't work at all (for custom packages and for stdlib). I have tried full GoSublime reinstall but it didn't help.

GoSublime r20.01.01-1: _after.init()

** 2020-01-10 02:14:01.416148 **:
GoSublime init r20.01.01-1 (0.002s)
|   install margo: no
|   install state: done
| sublime.version: 3211
| sublime.channel: stable
|       about.ann: a20.01.01-1
|   about.version: r20.01.01-1
|         version: r20.01.01-1
|        platform: windows-x64
|            ~bin: ~\AppData\Roaming\Sublime Text 3\Packages\User\GoSublime\windows-x64\bin
|       margo.exe: ~bin\gosublime.margo_r20.01.01-1_go1.13.5.exe (ok)
|          go.exe: c:\go\bin\go.exe (ok)
|      go.version: go1.13.5
|          GOROOT: c:\go
|          GOPATH: D:\Workspace\gocode\
|           GOBIN: (not set)
|       set.shell: []
|       env.shell:
|       shell.cmd: ['C:\\WINDOWS\\system32\\cmd.exe', '/C', '${CMD}']
|    sh.bootstrap: 
|                >  using shell env GOPATH=D:\Workspace\gocode\
|                >  using shell env GOROOT=c:\go
|                >  using shell env PATH=~\AppData\Roaming\Sublime Text 3\Packages\GoSublime\bin;~\AppData\Roaming\Sublime Text 3\Packages\User\GoSublime\bin;D:\Workspace\gocode\bin;C:\Program Files (x86)\NetSarang\Xshell 6\;C:\Program Files (x86)\Razer Chroma SDK\bin;C:\Program Files\Razer Chroma SDK\bin;C:\Program Files (x86)\Razer\ChromaBroadcast\bin;C:\Program Files\Razer\ChromaBroadcast\bin;C:\Program Files (x86)\Common Files\Oracle\Java\javapath;C:\Program Files (x86)\Common Files\Intel\Shared Libraries\redist\intel64\compiler;C:\Program Files (x86)\Intel\iCLS Client\;C:\Program Files\Intel\iCLS Client\;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\DAL;C:\Program Files\Intel\Intel(R) Management Engine Components\DAL;C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\IPT;C:\Program Files\Intel\Intel(R) Management Engine Components\IPT;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\WINDOWS\System32\WindowsPowerShell\v1.0\;C:\Program Files (x86)\NVIDIA Corporation\PhysX\Common;C:\Program Files\Intel\WiFi\bin\;C:\Program Files\Common Files\Intel\WirelessCommon\;C:\Program Files (x86)\QuickTime\QTSystem\;C:\WINDOWS\System32\OpenSSH\;~\AppData\Local\Microsoft\WindowsApps;~\AppData\Local\atom\bin;C:\Program Files\Microsoft VS Code\bin;C:\Program Files\Git\bin;~\go\bin;~\AppData\Local\hyper\app-2.1.0\resources\bin;C:\WINDOWS\system32\config\systemprofile\AppData\Local\Microsoft\WindowsApps;C:\Go\bin;~\bin
|                >  go version: `go1.13.5` (raw version string `go1.13.5`)
|                >  shell bootstrap took 1.009s
|                >
--------------------------------

  margo: agent#007: ['go', 'install', '-v', '-x', 'margo.sh']:
  WORK=C:\Users\andy\AppData\Local\Temp\go-build231528346

[02:14:02] margo: agent#007: ['C:\\Users\\andy\\AppData\\Roaming\\Sublime Text 3\\Packages\\GoSublime\\bin\\margo.sh.exe', 'start', 'margo.sublime', '-codec', 'msgpack']
[02:14:02] margo: agent#007: log: Using margo extension: C:\Users\andy\AppData\Roaming\Sublime Text 3\Packages\User\GoSublime\src\margo
[02:14:02] margo: agent#007: log: ``` go install -v -tags="margo margo_extension" margo.sh/cmd/margo.sublime ```
[02:14:03] margo: agent#007: log: ``` "C:\\Users\\andy\\AppData\\Roaming\\Sublime Text 3\\Packages\\GoSublime\\bin\\margo.sublime.exe" -codec msgpack ```
[02:14:03] margo: agent#007: log: oom_win.go:8: SetMemoryLimit: not supported on Windows
[02:14:03] margo: agent#007: log: store.go:137: started
Package Control: Skipping automatic upgrade, last run at 2020-01-10 01:23:03, next run at 2020-01-10 02:23:03 or after
[02:14:04] margo: agent#007: log: ``` go install margo.sh/vendor/golang.org/x/tools/cmd/guru ```
[02:14:04] margo: agent#007: log: margocode.go:325: VFS.Scan GOPATH ( D:\Workspace\gocode ): 310 packages preloaded in 237ms
[02:14:05] margo: agent#007: log: margocode.go:325: VFS.Scan GOROOT ( c:\go ): 378 packages preloaded in 445ms
[02:14:44] margo: agent#007: log: gocode.go:201: gocode didn't respond after 249ms taking 250ms
[02:14:45] margo: agent#007: log: gocode.go:176: gocode didn't accept the request after 103ms
[02:14:46] margo: agent#007: log: gocode.go:192: gocode eventually responded after 1.562s
[02:14:46] margo: agent#007: log: gocode.go:201: gocode didn't respond after 250ms taking 250ms
[02:14:47] margo: agent#007: log: gocode.go:176: gocode didn't accept the request after 103ms
[02:14:48] margo: agent#007: log: gocode.go:192: gocode eventually responded after 1.936s
[02:14:48] margo: agent#007: log: gocode.go:201: gocode didn't respond after 250ms taking 251ms
[02:14:49] margo: agent#007: log: gocode.go:192: gocode eventually responded after 1.12s

[andyone]

I found the fix. I have increased this timeout to 500 milliseconds, and autocomplete started working. I think this timeout is too small if there is a lot of code to analyze and code is stored on HDD.

[andyone]

I am not sure that autocompletion should work like that. Every invocation of autocomplete, in my case, reads more than 50 megabytes of data from disk. Of course, 100-200 milliseconds isn't enough for that. So if you want to type return and you had have 3 invocations of autocomplete, it read almost 150 megabytes just in 1-2 seconds, and dozen gigabytes of data for the whole session.

[andyone]

Every invocation of autocomplete, in my case, reads more than 50 megabytes of data from disk.

Downgraded to 19.10.22. Every autocomplete invocation reads ~ 10-20 kilobytes. So something dramatically changed in the latest version for the worse.

[DisposaBoy]

@andyone How are you measuring the amount of data read?

The latest version switches to a go/types the imports importer one that uses source code for everything except cgo. You can switch back to the previous default by configuring the golang.MarGocodeCtl reducer.

  &golang.MarGocodeCtl{
    ImporterMode: golang.SrcImporterWithFallback,
  }

With that said, the old version uses source code too so I'm sure what changed. Maybe caching is broken and it's type-checking the packages more more often than it needs to.

[andyone]

How are you measuring the amount of data read?

There is a special tool on Windows — Process Explorer. It shows all the information about the process on the system. I have recorded autocomplete invocations in 3 situations:

• v20.01.01
• v20.01.01 + SrcImporterWithFallback
• v19.10.22

The same file, Sublime was restarted before every test.

Also, v20 requires some changes with timeouts as I have mentioned before:

Recordings (don't look on fps, I have recorded all of them with 1fps framerate):

v20.01.01

v20.01.01 + SrcImporterWithFallback

v19.10.22

[DisposaBoy]

Thanks for the recordings @andyone, I think iotop on Linux does something similar, I'll investigate and see...

[DisposaBoy]

To keep this updated...

It still needs more investigating, but what I've found so far is that the main cause is due to type-checking. i.e. when typing, Sublime Text will automatically trigger a request for completions, we see that the file has changed and do another type-check - which should be fine as most of it is cached - but in order to check the current package, we go through all the importing steps again which results in re-reading all files from disk (partial read to determine which files to include and full read to parse).

I've pushed some changes to the next branch which should get rid of all that reading from disk again, so hopefully it helps, but there's still more work to do there, esp. for CPU usage and lowering the blocking limits to improve typing latency and UX even if completion doesn't work.

I was kind of able to reproduce this in a VM with low resources and it helps there, but I'm not yet sure if it solves the problem. Hopefully in the next few days/weekend I'm able to get a Windows VM setup and reproduce it there to get a better idea of where we stand.

[DisposaBoy]

I believe this should be fixed in the latest release v20.02.01 - at lease I can no reproduce it in a Windows VM. Please comment if it's still present and I will re-open this issue.

[vany-egorov]

v20.02.01 works fine on Windows10 and Sublime3210. Thanks!

[andyone]

I confirm, with v20.02.01 all works fine. Thanks!

[DisposaBoy]

Great! thanks for confirming.