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

Jump to bottom

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

Closed
smarterclayton opened this issue Mar 22, 2020 · 6 comments
Closed

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

smarterclayton opened this issue Mar 22, 2020 · 6 comments
Labels
FrozenDueToAge gopls Issues related to the Go language server, gopls. Tools This label describes issues relating to any tools in the x/tools repository. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Milestone
gopls/v0.4.2

Comments

@smarterclayton
Copy link

smarterclayton commented Mar 22, 2020 •
edited

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 gopherbot added Tools This label describes issues relating to any tools in the x/tools repository. gopls Issues related to the Go language server, gopls. labels Mar 22, 2020
@gopherbot
Copy link

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
Copy link
Contributor

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
@heschi
Copy link
Contributor

heschi commented Mar 23, 2020

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

@stamblerre stamblerre added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Mar 23, 2020
@smarterclayton
Copy link
Author

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.

@heschi
Copy link
Contributor

heschi 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.

@stamblerre stamblerre modified the milestones: gopls/v0.4.0, gopls/v0.5.0 Apr 2, 2020
@stamblerre
Copy link
Contributor

Closing this since there have been no updates on this issue for the past few months.

@stamblerre stamblerre modified the milestones: gopls/v0.5.0, gopls/v0.4.2 Jun 24, 2020
@golang golang locked and limited conversation to collaborators Jun 24, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge gopls Issues related to the Go language server, gopls. Tools This label describes issues relating to any tools in the x/tools repository. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Milestone
gopls/v0.4.2
Development

No branches or pull requests
4 participants
@smarterclayton @stamblerre @gopherbot @heschi