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

x/tools/gopls: sustained 100% cpu use from gopls for hours after editor interactions stop #38009

Open
smarterclayton opened this issue Mar 22, 2020 · 5 comments

Comments

@smarterclayton
Copy link

@smarterclayton smarterclayton commented Mar 22, 2020

What did you do?

  1. Clone https://github.com/openshift/origin.git (downstream of github.com/kubernetes/kubernetes, has larger dependency tree)
  2. Open in most recent vscode
Version: 1.43.1
Commit: fe22a9645b44368865c0ba92e2fb881ff1afce94
Date: 2020-03-18T07:01:41.240Z
Electron: 7.1.11
Chrome: 78.0.3904.130
Node.js: 12.8.1
V8: 7.8.279.23-electron.0
OS: Darwin x64 19.2.0
  1. Disable build / lint / vet on save
  2. Open test/extended/builds/prometheus_builds.go
  3. Type or edit text, save, use typeahead
  4. Leave VSCode open (no more actions)
  5. Wait 10-15m

Observe that gopls -mode=stdio serve -rpc.trace --debug=localhost:6060 process is using 100% CPU even after no further actions.

gopls continues to use CPU for hours even while no use of vscode has continued.

What did you expect to see?

What did you see instead?

pprof.samples.cpu.002.pb.gz
pprof.samples.cpu.003.pb.gz

Type: cpu
Time: Mar 22, 2020 at 7:16pm (EDT)
Duration: 30.15s, Total samples = 28.12s (93.26%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top30
Showing nodes accounting for 27.95s, 99.40% of 28.12s total
Dropped 37 nodes (cum <= 0.14s)
      flat  flat%   sum%        cum   cum%
    27.92s 99.29% 99.29%     27.92s 99.29%  syscall.syscall
     0.03s  0.11% 99.40%     27.93s 99.32%  os.statNolog
         0     0% 99.40%     27.96s 99.43%  golang.org/x/tools/internal/jsonrpc2.(*Conn).Run.func1
         0     0% 99.40%     27.96s 99.43%  golang.org/x/tools/internal/lsp.(*Server).DidChangeWatchedFiles
         0     0% 99.40%     27.96s 99.43%  golang.org/x/tools/internal/lsp.(*Server).didChangeWatchedFiles
         0     0% 99.40%     27.96s 99.43%  golang.org/x/tools/internal/lsp.(*Server).didModifyFiles
         0     0% 99.40%     27.96s 99.43%  golang.org/x/tools/internal/lsp/cache.(*Session).DidModifyFiles
         0     0% 99.40%     27.96s 99.43%  golang.org/x/tools/internal/lsp/cache.(*snapshot).clone
         0     0% 99.40%     27.96s 99.43%  golang.org/x/tools/internal/lsp/cache.(*view).invalidateContent
         0     0% 99.40%     27.96s 99.43%  golang.org/x/tools/internal/lsp/protocol.serverHandler.Deliver
         0     0% 99.40%     27.93s 99.32%  os.Stat
         0     0% 99.40%     27.90s 99.22%  syscall.Stat
(pprof) tree syscall

----------------------------------------------------------+-------------
      flat  flat%   sum%        cum   cum%   calls calls% + context
----------------------------------------------------------+-------------
                                            27.59s 99.93% |   syscall.Stat
    27.61s 98.33% 98.33%     27.61s 98.33%                | syscall.syscall
----------------------------------------------------------+-------------
         0     0% 98.33%     27.59s 98.25%                | golang.org/x/tools/internal/jsonrpc2.(*Conn).Run.func1
                                            27.59s   100% |   golang.org/x/tools/internal/lsp/protocol.serverHandler.Deliver
----------------------------------------------------------+-------------
                                            27.59s   100% |   golang.org/x/tools/internal/lsp/protocol.serverHandler.Deliver
         0     0% 98.33%     27.59s 98.25%                | golang.org/x/tools/internal/lsp.(*Server).DidChangeWatchedFiles
                                            27.59s   100% |   golang.org/x/tools/internal/lsp.(*Server).didChangeWatchedFiles
----------------------------------------------------------+-------------
                                            27.59s   100% |   golang.org/x/tools/internal/lsp.(*Server).DidChangeWatchedFiles
         0     0% 98.33%     27.59s 98.25%                | golang.org/x/tools/internal/lsp.(*Server).didChangeWatchedFiles
                                            27.59s   100% |   golang.org/x/tools/internal/lsp.(*Server).didModifyFiles
----------------------------------------------------------+-------------
                                            27.59s   100% |   golang.org/x/tools/internal/lsp.(*Server).didChangeWatchedFiles
         0     0% 98.33%     27.59s 98.25%                | golang.org/x/tools/internal/lsp.(*Server).didModifyFiles
                                            27.58s   100% |   golang.org/x/tools/internal/lsp/cache.(*Session).DidModifyFiles
----------------------------------------------------------+-------------
                                            27.58s   100% |   golang.org/x/tools/internal/lsp.(*Server).didModifyFiles
         0     0% 98.33%     27.58s 98.22%                | golang.org/x/tools/internal/lsp/cache.(*Session).DidModifyFiles
                                            27.56s 99.93% |   golang.org/x/tools/internal/lsp/cache.(*view).invalidateContent
----------------------------------------------------------+-------------
                                            27.56s   100% |   golang.org/x/tools/internal/lsp/cache.(*view).invalidateContent
         0     0% 98.33%     27.56s 98.15%                | golang.org/x/tools/internal/lsp/cache.(*snapshot).clone
                                            27.56s   100% |   os.Stat
----------------------------------------------------------+-------------
                                            27.56s   100% |   golang.org/x/tools/internal/lsp/cache.(*Session).DidModifyFiles
         0     0% 98.33%     27.56s 98.15%                | golang.org/x/tools/internal/lsp/cache.(*view).invalidateContent
                                            27.56s   100% |   golang.org/x/tools/internal/lsp/cache.(*snapshot).clone
----------------------------------------------------------+-------------
                                            27.59s   100% |   golang.org/x/tools/internal/jsonrpc2.(*Conn).Run.func1
         0     0% 98.33%     27.59s 98.25%                | golang.org/x/tools/internal/lsp/protocol.serverHandler.Deliver
                                            27.59s   100% |   golang.org/x/tools/internal/lsp.(*Server).DidChangeWatchedFiles
----------------------------------------------------------+-------------
                                            27.56s 99.86% |   golang.org/x/tools/internal/lsp/cache.(*snapshot).clone
         0     0% 98.33%     27.60s 98.29%                | os.Stat
                                            27.60s   100% |   os.statNolog

Build info

golang.org/x/tools/gopls v0.3.4
    golang.org/x/tools/gopls@v0.3.4 h1:4GC7q/pXQ/tsxHBGVdsMdlB4gCxVC06m/7rIXg1Px4E=
    github.com/BurntSushi/toml@v0.3.1 h1:WXkYYl6Yr3qBf1K79EBnL4mak0OimBfB0XUf9Vl28OQ=
    github.com/sergi/go-diff@v1.0.0 h1:Kpca3qRNrduNnOQeazBd0ysaKrUJiIuISHxogkT9RPQ=
    golang.org/x/mod@v0.1.1-0.20191105210325-c90efee705ee h1:WG0RUwxtNT4qqaXX3DPA8zHFNm/D9xaBpxzHt1WcA/E=
    golang.org/x/sync@v0.0.0-20190423024810-112230192c58 h1:8gQV6CLnAEikrhgkHFbMAEhagSSnXWGV915qUMm9mrU=
    golang.org/x/tools@v0.0.0-20200316194252-fafb6e2e8a4a h1:hKrQy/q8/Xivoqgw6nGiz1jqpn1WGBLDcWLZwW0983E=
    golang.org/x/xerrors@v0.0.0-20191011141410-1b5146add898 h1:/atklqdjdhuosWIl6AIbOeHJjicWYPqR9bpxqxYG2pA=
    honnef.co/go/tools@v0.0.1-2020.1.3 h1:sXmLre5bzIR6ypkjXCDI3jHPssRhc8KD/Ome589sc3U=
    mvdan.cc/xurls/v2@v2.1.0 h1:KaMb5GLhlcSX+e+qhbRJODnUUBvlw01jt4yrjFIHAuA=

Go info

go version go1.13.8 darwin/amd64

GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/clayton/Library/Caches/go-build"
GOENV="/Users/clayton/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/clayton/projects/origin"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/Cellar/go/1.13.8/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.13.8/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/qh/s8g0w_492w7c73kx2vpxl7cm0000gn/T/go-build285495415=/tmp/go-build -gno-record-gcc-switches -fno-common"
@gopherbot gopherbot added this to the Unreleased milestone Mar 22, 2020
@gopherbot

This comment has been minimized.

Copy link

@gopherbot gopherbot commented Mar 22, 2020

Thank you for filing a gopls issue! Please take a look at the Troubleshooting guide, and make sure that you have provided all of the relevant information here.

@stamblerre stamblerre changed the title x/tools/gopls: Sustained 100% cpu use from gopls for hours after editor interactions stop x/tools/gopls: sustained 100% cpu use from gopls for hours after editor interactions stop Mar 23, 2020
@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Mar 23, 2020

Thanks for the report! Were you continuing to edit the files in another editor or on disk while VS Code was not in use? It seems like all of the goroutines are in the code that handles changes to files on disk.

@stamblerre stamblerre modified the milestones: Unreleased, gopls/v0.4.0 Mar 23, 2020
@heschik

This comment has been minimized.

Copy link
Contributor

@heschik heschik commented Mar 23, 2020

Any chance this is microsoft/vscode-go#3109 (comment) ?

@smarterclayton

This comment has been minimized.

Copy link
Author

@smarterclayton smarterclayton commented Mar 26, 2020

I was not continuing to edit the particular files in question on disk in the majority of scenarios (was in other Go projects), but I may have run go builds in those other projects impacting the cache.

In regards to 3109 I am not using go-group-imports (explicitly), but will double check.

@heschik

This comment has been minimized.

Copy link
Contributor

@heschik heschik commented Mar 26, 2020

OK. In that case I think a log would be the best next step -- all evidence points to the editor sending a never-ending stream of didChange notifications and we need to see what those are.

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

Successfully merging a pull request may close this issue.

None yet
4 participants
You can’t perform that action at this time.