x/tools/gopls: completion often uses all of 1s time budget

[xuhezhong]

gopls version

Build info

golang.org/x/tools/gopls v0.15.3
golang.org/x/tools/gopls@v0.15.3 h1:zbdOidFrPTc8Bx0YrN5QKgJ0zCjyGi0L27sKQ/bDG5o=
github.com/BurntSushi/toml@v1.2.1 h1:9F2/+DoOYIOksmaJFPw1tGFy1eDnIJXg+UHjuD8lTak=
github.com/google/go-cmp@v0.6.0 h1:ofyhxvXcZhMsU5ulbFiLKl/XBFqE1GSq7atu8tAmTRI=
golang.org/x/exp/typeparams@v0.0.0-20221212164502-fae10dda9338 h1:2O2DON6y3XMJiQRAS1UWU+54aec2uopH3x7MAiqGW6Y=
golang.org/x/mod@v0.15.0 h1:SernR4v+D55NyBH2QiEQrlBAnj1ECL6AGrA5+dPaMY8=
golang.org/x/sync@v0.6.0 h1:5BMeUDZ7vkXGfEr1x9B4bRcTH4lpkTkpdh0T/J+qjbQ=
golang.org/x/sys@v0.17.0 h1:25cE3gD+tdBA7lp7QfhuV+rJiE9YXTcS3VG1SqssI/Y=
golang.org/x/telemetry@v0.0.0-20240209200032-7b892fcb8a78 h1:vcVnuftN4J4UKLRcgetjzfU9FjjgXUUYUc3JhFplgV4=
golang.org/x/text@v0.14.0 h1:ScX5w1eTa3QqT8oi6+ziP7dTV1S2+ALU0bI+0zXKWiQ=
golang.org/x/tools@v0.18.1-0.20240412183611-d92ae0781217 h1:uH9jJYgeLCvblH0S+03kFO0qUDxRkbLRLFiKVVDl7ak=
golang.org/x/vuln@v1.0.1 h1:KUas02EjQK5LTuIx1OylBQdKKZ9jeugs+HiqO5HormU=
honnef.co/go/tools@v0.4.6 h1:oFEHCKeID7to/3autwsWfnuv69j3NsfcXbvJKuIcep8=
mvdan.cc/gofumpt@v0.6.0 h1:G3QvahNDmpD+Aek/bNOLrFR2XC6ZAdo62dZu65gmwGo=
mvdan.cc/xurls/v2@v2.5.0 h1:lyBNOm8Wo71UknhUs4QTFUNNMyxy2JEIaKKo0RWOh+8=
go: go1.22.0

go env

set GO111MODULE=on
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\value\AppData\Local\go-build
set GOENV=E:\Users\value\AppData\Roaming\go\env
set GOEXE=.exe
set GOEXPERIMENT=
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMODCACHE=D:\gez\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=D:\\gez
set GOPRIVATE=
set GOPROXY=https://goproxy.cn/
set GOROOT=C:\Program Files\Go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLCHAIN=auto
set GOTOOLDIR=C:\Program Files\Go\pkg\tool\windows_amd64
set GOVCS=
set GOVERSION=go1.22.0
set GCCGO=gccgo
set GOAMD64=v1
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=D:\gez\src\rent-manager\go.mod
set GOWORK=
set CGO_CFLAGS=-O2 -g
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-O2 -g
set CGO_FFLAGS=-O2 -g
set CGO_LDFLAGS=-O2 -g
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=C:\Users\value\AppData\Local\Temp\go-build1699389175=/tmp/go-build -gno-record-gcc-switches

What did you do?

no

What did you see happen?

completion is slow

What did you expect to see?

How to improve the completion speed

Editor and settings

{
"git.autofetch": true,
"go.addTags":{
"tags": "json",
"options": "",
"transform": "camelcase"
},
"go.lintOnSave":"package",
"go.vetOnSave": "off",
"go.lintTool":"golangci-lint",
"go.lintFlags":[
// "-min_confidence=0.9",
// "all,-ST1020,-ST1003,-ST1006"
],
"go.formatTool":"gofmt",
"go.testFlags": [
"-v",
"-count=1"
],
"go.useLanguageServer": true,
"go.languageServerFlags": [
"-remote=auto","-logfile=auto","-debug=localhost:5050","-rpc.trace"
],
"[go]": {
"editor.snippetSuggestions":"top",
"editor.formatOnSave": true,
"editor.codeActionsOnSave": {
"source.organizeImports": "explicit"
},
"editor.suggest.snippetsPreventQuickSuggestions": false
},
"editor.quickSuggestions": {
"strings": true
},
"gopls": {
"ui.completion.completeFunctionCalls": true,
"ui.diagnostic.staticcheck": false,
"ui.completion.usePlaceholders": false,
"ui.completion.matcher": "Fuzzy",
"ui.semanticTokens": true,
"ui.codelenses": {
"gc_details": false,
"generate": false,
"regenerate_cgo": true,
"tidy": false,
"upgrade_dependency": false,
"vendor": false,
"test": false
},
"ui.completion.completionBudget": "1s",
"ui.vulncheck":"On",
"allExperiments": true,
"ui.completion.experimentalPostfixCompletions": true,
"build.templateExtensions": [
".go"
],
"zeroConfig": false,
"analyses": {
"nilness": false
}
},
"cSpell.diagnosticLevel": "Hint",
"cSpell.userWords": [
"bson",
"Infof",
"querys"
],
"cSpell.showCommandsInEditorContextMenu": false,
"security.workspace.trust.untrustedFiles": "open",
"window.openFoldersInNewWindow": "on",
"go-struct-tag.cases": [
"camel"
],
"workbench.iconTheme": "material-icon-theme",
"go.inlayHints.constantValues": true,
"extensions.ignoreRecommendations": true,
"go.editorContextMenuCommands": {
"toggleTestFile": false,
"addImport": false,
"testCoverage": false,
"playground": false
},
"json.schemaDownload.enable": false,
"workbench.editorAssociations": {
".exe": "default"
},
"go.toolsEnvVars": {},
"leetcode.endpoint": "leetcode-cn",
"leetcode.defaultLanguage": "golang",
"leetcode.workspaceFolder": "C:\Users\value\.leetcode",
"leetcode.hint.configWebviewMarkdown": false,
"leetcode.hint.commandShortcut": false,
"fittencode.inlineCompletion.enable": true,
"go.toolsManagement.autoUpdate": true,
"go.delveConfig": {},
"files.associations": {
".go":"go"
},
"go.inlayHints.rangeVariableTypes": true,
"leetcode.hint.commentDescription": false,
"Lingma.LocalStoragePath": "C:\Users\value\.lingma"
}

Logs

$/cancelRequest last: 0s, longest: 25.3429ms
$/progress last: 0s, longest: 558.2µs
client/registerCapability last: 2.3282ms, longest: 22.2058ms
gocommand.Runner.Run last: 1.4592542s, longest: 1.4592542s
gocommand.Runner.RunRaw last: 1.4592542s, longest: 1.4592542s
gopls/handshake last: 279.2767ms, longest: 279.2767ms
initialize last: 1.4941373s, longest: 1.4941373s
initialized last: 3.5351ms, longest: 3.5351ms
protocol.canceller last: 0s, longest: 25.3429ms
queued last: 0s, longest: 7.7154184s
textDocument/codeAction last: 6.9961ms, longest: 7.7154184s
textDocument/codeLens last: 2.028921s, longest: 7.1807699s
textDocument/completion last: 1.8880714s, longest: 5.6789887s
textDocument/didChange last: 1.11ms, longest: 6.3120549s
textDocument/didOpen last: 11.552ms, longest: 11.552ms
textDocument/didSave last: 1.0021ms, longest: 3.0005ms
textDocument/documentLink last: 25.8237ms, longest: 5.3391951s
textDocument/documentSymbol last: 1.2762219s, longest: 7.1998994s
textDocument/foldingRange last: 12.4753ms, longest: 5.9395043s
textDocument/formatting last: 46.6567ms, longest: 46.6567ms
textDocument/inlayHint last: 1.8887478s, longest: 8.048331s
textDocument/publishDiagnostics last: 15.8979ms, longest: 22.8799ms
textDocument/semanticTokens/full last: 1.1832525s, longest: 6.3649223s
textDocument/semanticTokens/range last: 5.9401569s, longest: 5.9401569s
textDocument/signatureHelp last: 2.0988934s, longest: 2.0988934s
window/logMessage last: 511.8µs, longest: 59.5579ms
window/workDoneProgress/create last: 791.6519ms, longest: 791.6519ms
workspace/configuration last: 7.248ms, longest: 7.248ms
workspace/didChangeWatchedFiles last: 17.9947ms, longest: 1.8196535s

[gabyhelp]

Similar Issues

• x/tools/gopls: slow performance #43259
• x/tools/gopls: IDE shows undeclared name on every symbols when accessing from other files #34951
• x/tools/gopls: not working #37119
• x/tools/gopls: no completion/suggestion/linting working on large projects #66787
• x/tools/gopls: feedback is extremely slow with large monorepo #44188
• x/tools/gopls: gopls falls behind user input in large repository #45089
• x/tools/gopls: gopls compiles after every newstart on large projects #53332
• x/tools/gopls: don't load invalid build configurations unless they contain Go code #43093
• x/tools/gopls: go.mod: Please provide completions for package versions #58769
• x/tools/gopls: Completion not working in modules with "vendor" as their name #54071

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[xuhezhong]

unhelpful @gabyhelp

[findleyr]

That is indeed quite slow.

I see that your completion budget is 1s. Is there a reason you increased it from the default of 100ms? Decreasing the budget will cause completion to abort its deep search sooner.

[xuhezhong]

I tried to change it to 100ms, and it looked slower.

$/cancelRequest last: 0s, longest: 6.288ms
$/progress last: 5.0001ms, longest: 5.0001ms
$/setTrace last: 0s, longest: 0s
client/registerCapability last: 5.2767ms, longest: 122.8193ms
gocommand.Runner.Run last: 4.0762691s, longest: 4.0762691s
gocommand.Runner.RunRaw last: 4.0762691s, longest: 4.0762691s
gopls/handshake last: 460.2974ms, longest: 460.2974ms
initialize last: 4.1573762s, longest: 4.1573762s
initialized last: 3.3838ms, longest: 3.3838ms
protocol.canceller last: 0s, longest: 6.1035ms
queued last: 579.8669ms, longest: 11.6191875s
textDocument/codeAction last: 1.8757006s, longest: 11.6218308s
textDocument/codeLens last: 2.861111s, longest: 8.334985s
textDocument/completion last: 2.4040361s, longest: 11.6619728s
textDocument/definition last: 2.2651238s, longest: 5.2827827s
textDocument/didChange last: 573.1µs, longest: 6.3075205s
textDocument/didOpen last: 73.3626ms, longest: 73.3626ms
textDocument/didSave last: 16.0028ms, longest: 16.0028ms
textDocument/documentHighlight last: 2.1993ms, longest: 665.4831ms
textDocument/documentLink last: 1.6344522s, longest: 8.2514029s
textDocument/documentSymbol last: 585.1718ms, longest: 11.6356173s
textDocument/foldingRange last: 1.3212396s, longest: 6.9483335s
textDocument/formatting last: 1.6698799s, longest: 1.6698799s
textDocument/hover last: 213.2719ms, longest: 310.9122ms
textDocument/inlayHint last: 2.2132582s, longest: 10.7460395s
textDocument/publishDiagnostics last: 639.9µs, longest: 524.3932ms
textDocument/semanticTokens/full last: 1.5372664s, longest: 9.6960405s
textDocument/semanticTokens/range last: 404.7153ms, longest: 4.1919914s
textDocument/signatureHelp last: 1.9193696s, longest: 1.9193696s
window/logMessage last: 999.3µs, longest: 65.0027ms
window/workDoneProgress/create last: 666.9018ms, longest: 666.9018ms
workspace/configuration last: 4.92ms, longest: 36.7196ms
workspace/didChangeConfiguration last: 1.0024ms, longest: 1.0024ms
workspace/didChangeWatchedFiles last: 4.0003ms, longest: 4.0003ms

Is the package is too large?
Initializing workspace... done (4.1950882s)
Gathering bug reports... done (1.6791823s)
Querying memstats... done (7.8943ms)
Querying workspace stats... done (1.0903ms)
Collecting directory info... done (71.4162ms)
{
"BugReports": [],
"CacheDir": "C:\Users\value\AppData\Local\gopls\0418dd66",
"DirStats": {
"Files": 4053,
"TestdataFiles": 0,
"GoFiles": 1500,
"ModFiles": 15,
"Dirs": 452
},
"GOARCH": "amd64",
"GOOS": "windows",
"GOPACKAGESDRIVER": "",
"GOPLSCACHE": "",
"GoVersion": "go1.22.0",
"GoplsVersion": "v0.15.3",
"InitialWorkspaceLoadDuration": "4.1950882s",
"MemStats": {
"HeapAlloc": 37154912,
"HeapInUse": 50454528,
"TotalAlloc": 91443112
},
"WorkspaceStats": {
"Files": {
"Total": 2134,
"Largest": 879006,
"Errs": 0
},
"Views": [
{
"GoCommandVersion": "go1.22.0",
"AllPackages": {
"Packages": 297,
"LargestPackage": 236,
"CompiledGoFiles": 2427,
"Modules": 39
},
"WorkspacePackages": {
"Packages": 38,
"LargestPackage": 150,
"CompiledGoFiles": 698,
"Modules": 1
},
"Diagnostics": 2
}
]
}
}

Then I found that the use of cpu became higher when completing the code.

Is the performance of cpu too poor?

[findleyr]

Thanks. Indeed, that is too slow. It also doesn't look like your workspace is that large. Do you always experience this, even in a tiny hello world program?

I note that it is not just completion: everything looks very slow from the timings you shared.

Can you please start gopls with -debug=localhost:8080 (or any port you choose), and then grab a profile?

go tool pprof -seconds=10 http://localhost:8080/debug/pprof/profile

Run that command from a terminal, do some typing when gopls is slow. After 10 seconds, the go command will jump into a pprof shell. I'd be interested in the output of top -cum 30. This will help me understand the cause of the slowness you experience.

[xuhezhong]

Do you always experience this, even in a tiny hello world program?
No, in a tiny hello world program is very good.
PS C:\Users\value> go tool pprof -seconds=10 http://localhost:5050/debug/pprof/profile
Fetching profile over HTTP from http://localhost:5050/debug/pprof/profile?seconds=10
Please wait... (10s)
Saved profile in C:\Users\value\pprof\pprof.gopls.exe.samples.cpu.008.pb.gz
File: gopls.exe
Build ID: D:\gez\bin\gopls.exe2024-06-19 11:34:19.2023561 +0800 CST
Type: cpu
Time: Jun 21, 2024 at 11:06am (CST)
Duration: 10.15s, Total samples = 8.90s (87.67%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top -cum 30
Showing nodes accounting for 8.76s, 98.43% of 8.90s total
Dropped 94 nodes (cum <= 0.04s)
flat flat% sum% cum cum%
0 0% 0% 8.76s 98.43% golang.org/x/tools/internal/fakenet.(*connFeeder).run
8.76s 98.43% 98.43% 8.76s 98.43% runtime.cgocall
0 0% 98.43% 8.76s 98.43% syscall.Syscall6
0 0% 98.43% 8.76s 98.43% syscall.SyscallN
0 0% 98.43% 8.75s 98.31% internal/poll.(*FD).Read
0 0% 98.43% 8.75s 98.31% os.(*File).Read
0 0% 98.43% 8.75s 98.31% os.(*File).read (inline)
0 0% 98.43% 8.75s 98.31% syscall.Read
0 0% 98.43% 8.75s 98.31% syscall.ReadFile (inline)
0 0% 98.43% 8.75s 98.31% syscall.readFile
0 0% 98.43% 0.11s 1.24% golang.org/x/tools/gopls/internal/protocol.Handlers.AsyncHandler.func2.2
0 0% 98.43% 0.11s 1.24% golang.org/x/tools/gopls/internal/protocol.Handlers.MustReplyHandler.func1
0 0% 98.43% 0.08s 0.9% golang.org/x/tools/gopls/internal/lsprpc.(*forwarder).ServeStream.(*forwarder).handler.func3
0 0% 98.43% 0.08s 0.9% golang.org/x/tools/gopls/internal/lsprpc.(*forwarder).ServeStream.ServerHandler.func2
0 0% 98.43% 0.08s 0.9% golang.org/x/tools/gopls/internal/protocol.serverDispatch
0 0% 98.43% 0.06s 0.67% encoding/json.Unmarshal
0 0% 98.43% 0.05s 0.56% encoding/json.(*decodeState).object
0 0% 98.43% 0.05s 0.56% encoding/json.(*decodeState).unmarshal
0 0% 98.43% 0.05s 0.56% encoding/json.(*decodeState).value
(pprof)

[xuhezhong]

When I work under small package, it's very good.

[findleyr]

Wow, that appears to be all disk I/O. Are you perhaps running with a particularly slow filesystem?

Even so, I'd expect that after the initial workspace load disk I/O is not in the fast path of most operations: they should all be hitting cache. I wonder if it is related to the file cache.

Another mystery: I don't see an entry point for the reads in top -cum. I would expect to see a gopls function higher up. Can you perhaps run web for that pprof session, and share the resulting image?

CC @adonovan

[xuhezhong]

Are you perhaps running with a particularly slow filesystem?
No, it's a normal filesystem.windows10,16GB RAM, CPU i5, 240GB SSD.

Even so, I'd expect that after the initial workspace load disk I/O is not in the fast path of most operations: they should all be hitting cache. I wonder if it is related to the file cache.
Did I used flags -remote=auto, so can't see cache?

[xuhezhong]

When I modify flag to serve.

$/cancelRequest last: 0s, longest: 1.0013ms
$/progress last: 0s, longest: 0s
Server.diagnose last: 3.1895002s, longest: 4.3136033s
Server.diagnoseChangedFiles last: 2.5634308s, longest: 2.5634308s
Server.diagnoseSnapshot last: 2.3779088s, longest: 5.7364458s
Server.publishDiagnostics last: 59.5284ms, longest: 111.0395ms
cache.ModTidy last: 4.3049804s, longest: 4.3049804s
cache.ParseGoSrc last: 41.9945ms, longest: 103.9266ms
cache.ParseMod last: 0s, longest: 0s
cache.forEachPackage last: 2.5634308s, longest: 2.882628s
cache.importsState.refreshProcessEnv last: 1.0111812s, longest: 1.0111812s
cache.importsState.runProcessEnvFunc last: 1.2375499s, longest: 1.2375499s
cache.readFile last: 0s, longest: 22.9965ms
cache.resolveImportGraph last: 9.0016ms, longest: 84.3816ms
cache.sharedModCache.refreshDir last: 118.9732ms, longest: 118.9732ms
cache.snapshot.ModTidy last: 0s, longest: 4.3049804s
cache.snapshot.PackageDiagnostics last: 2.5634308s, longest: 2.882628s
cache.snapshot.clone last: 1.0034ms, longest: 11.1503ms
cache.snapshot.load last: 3.3542077s, longest: 3.3542077s
cache.typeCheckBatch.checkPackage last: 72.6665ms, longest: 2.8756253s
cache.typeCheckBatch.checkPackageForImport last: 186.9995ms, longest: 282.9148ms
cache.typeCheckBatch.importPackage last: 90.0169ms, longest: 90.0169ms
client/registerCapability last: 1.8403ms, longest: 8.4835ms
completion.Completion last: 98.1118ms, longest: 1.777517s
gocommand.Runner.Run last: 4.3003531s, longest: 4.3003531s
gocommand.Runner.RunRaw last: 4.3003531s, longest: 4.3003531s
golang.AllImportsFixes last: 1.2375499s, longest: 1.2375499s
golang.DocumentSymbols last: 969.4µs, longest: 1.5246ms
golang.Format last: 14.0052ms, longest: 20.0023ms
golang.Hover last: 1.0632ms, longest: 1.0632ms
golang.InlayHint last: 0s, longest: 895.2011ms
golang.SignatureHelp last: 2.3401226s, longest: 2.3401226s
golang.computeTextEdits last: 1.0021ms, longest: 1.0021ms
imports.FixImports last: 1.2356817s, longest: 1.2356817s
initialize last: 2.1969ms, longest: 2.1969ms
initialized last: 4.2398869s, longest: 4.2398869s
lsp.Server.codeAction last: 396.7522ms, longest: 2.8964613s
lsp.Server.codeLens last: 0s, longest: 0s
lsp.Server.completion last: 98.6212ms, longest: 1.7785167s
lsp.Server.didChange last: 15.0011ms, longest: 15.4615ms
lsp.Server.didChangeWatchedFiles last: 2.0047ms, longest: 3.0027ms
lsp.Server.didOpen last: 170.9577ms, longest: 170.9577ms
lsp.Server.didSave last: 996.5µs, longest: 996.5µs
lsp.Server.documentLink last: 36.4166ms, longest: 63.831ms
lsp.Server.documentSymbol last: 969.4µs, longest: 1.5246ms
lsp.Server.foldingRange last: 3.0065ms, longest: 6.0124ms
lsp.Server.formatting last: 15.0042ms, longest: 20.0023ms
lsp.Server.hover last: 1.0632ms, longest: 1.0632ms
lsp.Server.initialize last: 618.5µs, longest: 618.5µs
lsp.Server.initialized last: 4.2398869s, longest: 4.2398869s
lsp.Server.inlayHint last: 0s, longest: 895.2011ms
lsp.Server.semanticTokens last: 7.5719ms, longest: 1.5393922s
lsp.Server.signatureHelp last: 2.3401226s, longest: 2.3401226s
mod.Diagnostics last: 0s, longest: 4.3049804s
mod.UpgradeDiagnostics last: 0s, longest: 0s
mod.VulnerabilityDiagnostics last: 0s, longest: 0s
queued last: 0s, longest: 4.2198357s
snapshot.Analyze last: 3.1855028s, longest: 3.1855028s
textDocument/codeAction last: 531.2793ms, longest: 2.89923s
textDocument/codeLens last: 1.1061564s, longest: 2.2677262s
textDocument/completion last: 2.2339456s, longest: 3.3155522s
textDocument/didChange last: 19.0016ms, longest: 1.7025203s
textDocument/didOpen last: 4.3934722s, longest: 4.3934722s
textDocument/didSave last: 996.5µs, longest: 1.5579ms
textDocument/documentLink last: 979.076ms, longest: 2.0792358s
textDocument/documentSymbol last: 1.1071258s, longest: 2.6728378s
textDocument/foldingRange last: 1.0766877s, longest: 2.1094241s
textDocument/formatting last: 460.7789ms, longest: 813.4608ms
textDocument/hover last: 1.1005ms, longest: 2.2910967s
textDocument/inlayHint last: 1.2324873s, longest: 2.0673011s
textDocument/publishDiagnostics last: 0s, longest: 1.5235ms
textDocument/semanticTokens/full last: 840.3362ms, longest: 2.5252431s
textDocument/signatureHelp last: 2.3411431s, longest: 2.3411431s
window/logMessage last: 0s, longest: 538.6µs
window/workDoneProgress/create last: 21.1334ms, longest: 21.1334ms
work.Diagnostics last: 0s, longest: 0s
workspace/configuration last: 8.3857ms, longest: 8.3857ms
workspace/didChangeWatchedFiles last: 2.0047ms, longest: 11.0026ms

PS C:\Users\value> go tool pprof -seconds=20 http://localhost:5050/debug/pprof/profile
Fetching profile over HTTP from http://localhost:5050/debug/pprof/profile?seconds=20
Please wait... (20s)
Saved profile in C:\Users\value\pprof\pprof.gopls.exe.samples.cpu.010.pb.gz
File: gopls.exe
Build ID: D:\gez\bin\gopls.exe2024-06-19 11:34:19.2023561 +0800 CST
Type: cpu
Time: Jun 22, 2024 at 9:09pm (CST)
Duration: 20.18s, Total samples = 87.42s (433.20%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top -cum 30
Showing nodes accounting for 26.91s, 30.78% of 87.42s total
Dropped 1075 nodes (cum <= 0.44s)
Showing top 30 nodes out of 220
flat flat% sum% cum cum%
0 0% 0% 29.50s 33.75% golang.org/x/sync/errgroup.(*Group).Go.func1
0 0% 0% 27s 30.89% go/types.(*Checker).Files (inline)
0 0% 0% 27s 30.89% go/types.(*Checker).checkFiles
0.37s 0.42% 0.42% 26.64s 30.47% go/ast.Walk
0 0% 0.42% 26.54s 30.36% golang.org/x/tools/gopls/internal/cache.storePackageResults
0 0% 0.42% 26.34s 30.13% sync.(*Once).Do (inline)
0 0% 0.42% 26.34s 30.13% sync.(*Once).doSlow
0 0% 0.42% 25.63s 29.32% golang.org/x/tools/gopls/internal/cache.(*syntaxPackage).xrefs
0 0% 0.42% 25.63s 29.32% golang.org/x/tools/gopls/internal/cache.(*syntaxPackage).xrefs.func1
0 0% 0.42% 25.63s 29.32% golang.org/x/tools/gopls/internal/cache/xrefs.Index
0 0% 0.42% 25.48s 29.15% go/ast.Inspect (inline)
0.01s 0.011% 0.43% 25.45s 29.11% go/ast.walkDeclList (inline)
0.04s 0.046% 0.48% 25.36s 29.01% go/types.(*Checker).processDelayed
0.01s 0.011% 0.49% 25.27s 28.91% go/types.(*Checker).funcBody
0 0% 0.49% 25.26s 28.89% go/types.(*Checker).funcDecl.func1
0 0% 0.49% 25.18s 28.80% go/ast.walkStmtList (inline)
0.10s 0.11% 0.61% 25.09s 28.70% go/ast.inspector.Visit
0.07s 0.08% 0.69% 25.08s 28.69% go/types.(*Checker).stmtList
0.31s 0.35% 1.04% 25.05s 28.65% go/types.(*Checker).stmt
0.25s 0.29% 1.33% 24.91s 28.49% golang.org/x/tools/gopls/internal/cache/xrefs.Index.func3
0 0% 1.33% 24.75s 28.31% golang.org/x/tools/gopls/internal/cache.(*Snapshot).forEachPackageInternal.func2
0 0% 1.33% 24.75s 28.31% golang.org/x/tools/gopls/internal/cache.(*typeCheckBatch).checkPackage
0 0% 1.33% 24.75s 28.31% golang.org/x/tools/gopls/internal/cache.(*typeCheckBatch).handleSyntaxPackage
1.55s 1.77% 3.10% 23.43s 26.80% golang.org/x/tools/go/types/objectpath.(*Encoder).For
0.13s 0.15% 3.25% 21.75s 24.88% go/types.(*Checker).rawExpr
0.12s 0.14% 3.39% 21.23s 24.29% go/ast.walkExprList (inline)
0.33s 0.38% 3.76% 20.74s 23.72% go/types.(*Checker).exprInternal
7.08s 8.10% 11.86% 18.47s 21.13% golang.org/x/tools/go/types/objectpath.find
16.54s 18.92% 30.78% 16.54s 18.92% runtime.cgocall
0 0% 30.78% 16.54s 18.92% syscall.SyscallN
(pprof)

[hyangah]

@xuhezhong If you visit the /trace/textDocument/completion endpoint of the gopls debug server (or click the textDocument/completion link in the server info page you shared in the last page, there are samples of detailed traces like this. Can you share the traces?

And @findleyr wondered if you can share the pprof web screenshot.

Can you perhaps run web for that pprof session, and share the resulting image?

For this, you can use go tool pprof -http=:12345 -seconds=20 http://localhost:5050/debug/pprof/profile and run completion in the editor. Or, you can also share the collected pprof file (C:\Users\value\pprof\pprof.gopls.exe.samples.cpu.08.pb.gz in your previous case) with us. The pprof file does not contain confidential, private info.

[xuhezhong]

[xuhezhong]

Oh,sorry! I didn't get it.

pprof.gopls.exe.samples.cpu.011.pb.gz

[hyangah]

Thanks!

The longest request in #68063 (comment) shows 1s+ spent cache.typeCheckBatch.checkPackage. I guess this was one of the first requests that hit the slow path.

The last request shows 92ms for actual completion computation, but was waiting in the queue (blocked by other LSP requests).

From the profile flame graph, 61% is in file read op, originated from fakenet.(*connFeeder).run. @findleyr does this fakenet imply LSP stdio read?