search

golang / go

The Go programming language
https://go.dev
BSD 3-Clause "New" or "Revised" License
122.15k stars 17.46k forks source link

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

Open xuhezhong opened 2 months ago

xuhezhong commented 2 months ago

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 commented 2 months ago

Similar Issues

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

xuhezhong commented 2 months ago

unhelpful @gabyhelp

findleyr commented 2 months ago

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 commented 2 months ago

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. image Is the performance of cpu too poor?

findleyr commented 2 months ago

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 commented 2 months ago

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 commented 2 months ago

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

findleyr commented 2 months ago

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 commented 2 months ago

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?

image

xuhezhong commented 2 months ago

When I modify flag to serve. image

$/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 commented 1 month ago

@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?

Screenshot 2024-07-18 at 4 18 58 PM

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.

Screenshot 2024-07-18 at 4 34 06 PM
xuhezhong commented 1 month ago

image

xuhezhong commented 1 month ago

image Oh,sorry! I didn't get it.

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

hyangah commented 2 weeks ago

Thanks!

The longest request in https://github.com/golang/go/issues/68063#issuecomment-2237819470 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?