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.

Sign up for GitHub

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: Is there a way to reduce the memory usage? #61352

Closed
Kidsunbo opened this issue Jul 14, 2023 · 12 comments
Closed

x/tools/gopls: Is there a way to reduce the memory usage? #61352

Kidsunbo opened this issue Jul 14, 2023 · 12 comments
Assignees
@adonovan
Labels
Analysis Issues related to static analysis (vet, x/tools/go/analysis) gopls/analysis Issues related to running analysis in gopls gopls/performance Issues related to gopls performance (CPU, memory, etc). gopls Issues related to the Go language server, gopls. Tools This label describes issues relating to any tools in the x/tools repository.
Milestone
gopls/v0.13.0

Comments

@Kidsunbo
Copy link

Kidsunbo commented Jul 14, 2023 •
edited

gopls version

Build info
----------
golang.org/x/tools/gopls v0.12.4
    golang.org/x/tools/gopls@v0.12.4 h1:nce5etAamR46d9oNGxop1aRK5rDQ0NqcY/SHIcyfEKY=
    github.com/BurntSushi/toml@v1.2.1 h1:9F2/+DoOYIOksmaJFPw1tGFy1eDnIJXg+UHjuD8lTak=
    github.com/google/go-cmp@v0.5.9 h1:O2Tfq5qg4qc4AmwVlvv0oLiVAGB7enBSJ2x2DqQFi38=
    github.com/sergi/go-diff@v1.1.0 h1:we8PVUC3FE2uYfodKH/nBHMSetSfHDR6scGdBi+erh0=
    golang.org/x/exp@v0.0.0-20220722155223-a9213eeb770e h1:+WEEuIdZHnUeJJmEUjyYC2gfUMj69yZXw17EnHg/otA=
    golang.org/x/exp/typeparams@v0.0.0-20221212164502-fae10dda9338 h1:2O2DON6y3XMJiQRAS1UWU+54aec2uopH3x7MAiqGW6Y=
    golang.org/x/mod@v0.11.0 h1:bUO06HqtnRcc/7l71XBe4WcqTZ+3AH1J59zWDDwLKgU=
    golang.org/x/sync@v0.3.0 h1:ftCYgMx6zT/asHUrPw8BLLscYtGznsLAnjq5RH9P66E=
    golang.org/x/sys@v0.9.0 h1:KS/R3tvhPqvJvwcKfnBHJwwthS11LRhmM5D59eEXa0s=
    golang.org/x/text@v0.10.0 h1:UpjohKhiEgNc0CSauXmwYftY1+LlaC75SJwh0SgCX58=
    golang.org/x/tools@v0.10.1-0.20230622221742-0622ad2359a7 h1:5PWemM67wMSPpO0Y3lOPlyvgO3z56YkZRxPFcdd300g=
    golang.org/x/vuln@v0.0.0-20230110180137-6ad3e3d07815 h1:A9kONVi4+AnuOr1dopsibH6hLi1Huy54cbeJxnq4vmU=
    honnef.co/go/tools@v0.4.2 h1:6qXr+R5w+ktL5UkwEbPp+fEvfyoMPche6GkOpGHZcLc=
    mvdan.cc/gofumpt@v0.4.0 h1:JVf4NN1mIpHogBj7ABpgOyZc65/UUOkKQFkoURsz4MM=
    mvdan.cc/xurls/v2@v2.4.0 h1:tzxjVAj+wSBmDcF6zBB7/myTy3gX9xvi8Tyr28AuQgc=
go: go1.20.6

go env

What did you do?

I have one close-source backend project, gopls takes 20 minutes to index and the memory usage is intolerably high. For comparison, GoLand only uses no more than 5 GB and only 30 sec to finish the indexing.
image

The computer I use is MacBook Pro (16-inch, 2019) with 32 GB memory.

I don't know what causes this but for information, the project has some big Golang source code files with more than 400,000 LOC, which are generated by thrift. I've also tried to index the source code of k8s, it works fine and can finish indexing in seconds and the memory usage is less than 4GB.

What did you expect to see?

The memory usage could be much less and the speed could be faster.

What did you see instead?

The whole process takes so long and uses a lot of memory.

Editor and settings

All the settings are default with the default Golang extension in VSCode.

Logs
@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 Jul 14, 2023
@gopherbot gopherbot added this to the Unreleased milestone Jul 14, 2023
@findleyr
Copy link
Contributor

findleyr commented Jul 14, 2023 •
edited

Hi, do you by any chance have "staticcheck" enabled? Can you share your gopls settings?

@findleyr findleyr modified the milestones: Unreleased, gopls/v0.12.5 Jul 14, 2023
@findleyr findleyr added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Jul 14, 2023
@Kidsunbo
Copy link
Author

Hi, do you by any chance have "staticcheck" enabled? Can you share your gopls settings?

Yeah, the gopls setting is all the default. I didn't change anything after install it. I notice that staticcheck is enabled.
There are three stages when indexing:

  1. gopls takes all available CPU and memory when I open some files in VSCode. I notice that if the package containing the opened file imports less package, the memory is consumed less and the indexing finishes earlier. But it seems that it only indexes that package and the imported packages.
  2. Multiple compile processes start compiling. It takes some time and use a lot of CPU. But the memory is fine.
  3. Staticcheck is running. Same with stage2, memory is fine.

The memory problem only happens in stage1.

@findleyr
Copy link
Contributor

findleyr commented Jul 14, 2023 •
edited

@Kidsunbo sorry I meant the staticcheck analyzers integrated with gopls, via the "staticcheck" setting: https://github.com/golang/tools/blob/master/gopls/doc/settings.md#staticcheck-bool

If you are using the defaults, I assume this is not enabled, unless your editor changes the defaults.

Which editor are you using? Nevermind, I see that you are using VS Code!

Can you share the output of gopls stats -anon? Would you also be willing to grab a profile?

@seankhliao seankhliao added WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. and removed WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. labels Jul 14, 2023
@Kidsunbo
Copy link
Author

Kidsunbo commented Jul 15, 2023 •
edited

Sure, here is the output of gopls stats -anon.

Initializing workspace...     done (34.534946727s)
Gathering bug reports...      done (122.796093ms)
Querying memstats...          done (1.047511462s)
Querying workspace stats...   done (16.829792ms)
Collecting directory info...  done (14.952613ms)
{
  "DirStats": {
    "Files": 967,
    "TestdataFiles": 0,
    "GoFiles": 922,
    "ModFiles": 1,
    "Dirs": 232
  },
  "GOARCH": "amd64",
  "GOOS": "darwin",
  "GoVersion": "go1.20.6",
  "GoplsVersion": "v0.12.4",
  "InitialWorkspaceLoadDuration": "34.534946727s",
  "MemStats": {
    "HeapAlloc": 941055336,
    "HeapInUse": 1035337728,
    "TotalAlloc": 30576936664
  },
  "WorkspaceStats": {
    "Files": {
      "Total": 10552,
      "Largest": 8091936,
      "Errs": 0
    },
    "Views": [
      {
        "GoCommandVersion": "go1.20.6",
        "AllPackages": {
          "Packages": 2318,
          "LargestPackage": 187,
          "CompiledGoFiles": 10865,
          "Modules": 460
        },
        "WorkspacePackages": {
          "Packages": 204,
          "LargestPackage": 104,
          "CompiledGoFiles": 1238,
          "Modules": 1
        },
        "Diagnostics": 5
      }
    ]
  }
}

Maybe it's due to I restarted my Mac. This time the process seems to be OK. It finished in just a few minutes. But is the TotalAlloc still a little high or expected?

As for the profile, I didn't find it in /tmp. In addition, all the projects that trigger the problem are close-source projects in my company. I think I am not allowed to share the profile which might contain debug info or something. Sorry for that.

@findleyr
Copy link
Contributor

Thanks @Kidsunbo.

It looks like you have a medium-large workspace, but perhaps with some large packages. We have two existing bugs related to opening a package that depends on a particularly large package (#61178 and #61207).

Based on the symptoms you describe, it sounds like static analysis is taking a long time. It may not take a long time now, because it successfully analyzed all your dependencies (and now those results are cached).

As for the profile, I didn't find it in /tmp. In addition, all the projects that trigger the problem are close-source projects in my company. I think I am not allowed to share the profile which might contain debug info or something.

Profiles in general do not contain private information (they contain timing information for functions in the gopls executable). However, all we really need is the top functions, which you can inspect before sharing. If you could do this, it would be very useful:

  • Start gopls with -debug=localhost:6060
  • From a terminal, run go tool pprof -seconds 10 -top -cum http://localhost:6060/debug/pprof/profile

That will output the top functions consuming CPU in gopls, during the 10 seconds that it samples. Try to catch gopls in the act of burning through CPU/memory. If you can share the results, it will tell us the root cause.

@Kidsunbo
Copy link
Author

Thanks @Kidsunbo.

It looks like you have a medium-large workspace, but perhaps with some large packages. We have two existing bugs related to opening a package that depends on a particularly large package (#61178 and #61207).

Based on the symptoms you describe, it sounds like static analysis is taking a long time. It may not take a long time now, because it successfully analyzed all your dependencies (and now those results are cached).

As for the profile, I didn't find it in /tmp. In addition, all the projects that trigger the problem are close-source projects in my company. I think I am not allowed to share the profile which might contain debug info or something.

Profiles in general do not contain private information (they contain timing information for functions in the gopls executable). However, all we really need is the top functions, which you can inspect before sharing. If you could do this, it would be very useful:

  • Start gopls with -debug=localhost:6060
  • From a terminal, run go tool pprof -seconds 10 -top -cum http://localhost:6060/debug/pprof/profile

That will output the top functions consuming CPU in gopls, during the 10 seconds that it samples. Try to catch gopls in the act of burning through CPU/memory. If you can share the results, it will tell us the root cause.

Sure, here is the output:

Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=10
Please wait... (10s)
Saved profile in /Users/sunbo/pprof/pprof.samples.cpu.002.pb.gz
Type: cpu
Time: Jul 16, 2023 at 10:47am (CST)
Duration: 10.11s, Total samples = 38.46s (380.59%)
Showing nodes accounting for 33.78s, 87.83% of 38.46s total
Dropped 517 nodes (cum <= 0.19s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%     28.95s 75.27%  golang.org/x/sync/errgroup.(*Group).Go.func1
         0     0%     0%     23.73s 61.70%  go/types.(*Checker).Files (inline)
         0     0%     0%     23.73s 61.70%  go/types.(*Checker).checkFiles
         0     0%     0%     22.76s 59.18%  golang.org/x/tools/gopls/internal/lsp/cache.(*analysisNode).run
         0     0%     0%     22.76s 59.18%  golang.org/x/tools/gopls/internal/lsp/cache.(*analysisNode).runCached
         0     0%     0%     22.76s 59.18%  golang.org/x/tools/gopls/internal/lsp/cache.(*snapshot).Analyze.func3.1
         0     0%     0%     22.74s 59.13%  golang.org/x/tools/gopls/internal/lsp/cache.(*analysisNode).typeCheck
     0.01s 0.026% 0.026%     18.81s 48.91%  runtime.systemstack
     0.32s  0.83%  0.86%     17.02s 44.25%  runtime.mallocgc
    13.60s 35.36% 36.22%     15.26s 39.68%  runtime.scanobject
     0.03s 0.078% 36.30%     14.14s 36.77%  runtime.deductAssistCredit
     0.01s 0.026% 36.32%     14.11s 36.69%  runtime.gcAssistAlloc
         0     0% 36.32%     14.10s 36.66%  runtime.gcAssistAlloc.func1
     0.25s  0.65% 36.97%     14.10s 36.66%  runtime.gcAssistAlloc1
     0.03s 0.078% 37.05%     13.85s 36.01%  runtime.gcDrainN
     0.15s  0.39% 37.44%     11.99s 31.18%  go/types.(*Checker).processDelayed
     0.02s 0.052% 37.49%     11.77s 30.60%  runtime.newobject (partial-inline)
     0.07s  0.18% 37.68%     11.63s 30.24%  go/types.(*Checker).funcDecl.func1
     0.05s  0.13% 37.81%     11.56s 30.06%  go/types.(*Checker).funcBody
         0     0% 37.81%        11s 28.60%  go/types.(*Checker).stmtList
     0.20s  0.52% 38.33%     10.92s 28.39%  go/types.(*Checker).stmt
     0.01s 0.026% 38.35%     10.28s 26.73%  go/types.(*Checker).rawExpr
     0.07s  0.18% 38.53%      9.31s 24.21%  go/types.(*Checker).exprInternal
     0.08s  0.21% 38.74%      8.57s 22.28%  go/types.(*Checker).packageObjects
     0.07s  0.18% 38.92%      8.32s 21.63%  go/types.(*Checker).objDecl
         0     0% 38.92%      7.45s 19.37%  go/types.(*Checker).expr
         0     0% 38.92%      6.14s 15.96%  golang.org/x/tools/gopls/internal/lsp/cache.ParseGoSrc
         0     0% 38.92%      6.12s 15.91%  go/parser.ParseFile
         0     0% 38.92%      6.10s 15.86%  go/parser.(*parser).parseFile
     2.03s  5.28% 44.20%      5.82s 15.13%  runtime.mapassign
     0.22s  0.57% 44.77%      5.35s 13.91%  go/types.(*Checker).recordTypeAndValue
     0.02s 0.052% 44.83%      5.05s 13.13%  go/types.(*Checker).exprList
     0.02s 0.052% 44.88%      5.03s 13.08%  go/types.(*Checker).callExpr
         0     0% 44.88%      4.82s 12.53%  go/parser.(*parser).parseDecl
         0     0% 44.88%      4.71s 12.25%  go/parser.(*parser).parseFuncDecl
     0.09s  0.23% 45.11%      4.29s 11.15%  go/types.(*Checker).funcDecl
     0.08s  0.21% 45.32%      4.23s 11.00%  go/types.(*Checker).funcType
         0     0% 45.32%      3.97s 10.32%  golang.org/x/tools/gopls/internal/lsp/cache.(*analysisNode).run.func1
         0     0% 45.32%      3.97s 10.32%  golang.org/x/tools/gopls/internal/lsp/cache.parseGoImpl
         0     0% 45.32%      3.73s  9.70%  go/parser.(*parser).parseBody
         0     0% 45.32%      3.70s  9.62%  go/types.(*Checker).multiExpr
     0.02s 0.052% 45.37%      3.62s  9.41%  go/parser.(*parser).parseStmtList
     0.41s  1.07% 46.44%      3.59s  9.33%  go/ast.Walk
         0     0% 46.44%      3.48s  9.05%  go/parser.(*parser).parseStmt
         0     0% 46.44%      3.21s  8.35%  sync.(*Once).Do (inline)
         0     0% 46.44%      3.21s  8.35%  sync.(*Once).doSlow
     0.02s 0.052% 46.49%      3.06s  7.96%  runtime.growslice
     0.01s 0.026% 46.52%      2.97s  7.72%  go/types.(*Checker).record
         0     0% 46.52%      2.81s  7.31%  go/types.(*Checker).initVars
     0.10s  0.26% 46.78%      2.80s  7.28%  go/types.(*Checker).collectParams
         0     0% 46.78%      2.67s  6.94%  go/types.(*Checker).binary
         0     0% 46.78%      2.64s  6.86%  go/types.(*Checker).varDecl
     0.15s  0.39% 47.17%      2.52s  6.55%  go/types.(*Checker).selector
         0     0% 47.17%      2.51s  6.53%  go/types.(*Checker).assignVars
     0.05s  0.13% 47.30%      2.48s  6.45%  go/types.(*Checker).collectObjects
         0     0% 47.30%      2.45s  6.37%  go/ast.Inspect (inline)
         0     0% 47.30%      2.45s  6.37%  go/ast.walkDeclList
         0     0% 47.30%      2.42s  6.29%  go/types.(*Checker).exprOrType
     0.01s 0.026% 47.32%      2.37s  6.16%  go/parser.(*parser).parseSimpleStmt
         0     0% 47.32%      2.31s  6.01%  go/types.(*Checker).indexedElts
         0     0% 47.32%      2.29s  5.95%  go/types.(*Checker).updateExprType (inline)
         0     0% 47.32%      2.29s  5.95%  go/types.(*Checker).updateExprType0
     0.06s  0.16% 47.48%      2.24s  5.82%  go/types.(*Checker).walkDecl
         0     0% 47.48%      2.23s  5.80%  golang.org/x/tools/gopls/internal/lsp/cache.(*typeCheckBatch).checkPackage.func1
         0     0% 47.48%      2.22s  5.77%  golang.org/x/tools/gopls/internal/lsp/cache.(*snapshot).forEachPackageInternal.func2
         0     0% 47.48%      2.22s  5.77%  golang.org/x/tools/gopls/internal/lsp/cache.(*typeCheckBatch).checkPackage
         0     0% 47.48%      2.22s  5.77%  golang.org/x/tools/gopls/internal/lsp/cache.(*typeCheckBatch).handleSyntaxPackage
         0     0% 47.48%      2.21s  5.75%  golang.org/x/tools/gopls/internal/lsp/cache.typeCheckImpl
         0     0% 47.48%      2.21s  5.75%  golang.org/x/tools/internal/memoize.(*Promise).run.func2
         0     0% 47.48%      2.20s  5.72%  golang.org/x/tools/gopls/internal/lsp/cache.(*parseCache).startParse.func1
         0     0% 47.48%      2.20s  5.72%  golang.org/x/tools/gopls/internal/lsp/cache.doTypeCheck
         0     0% 47.48%      2.20s  5.72%  golang.org/x/tools/internal/memoize.(*Promise).run.func2.1
         0     0% 47.48%      2.20s  5.72%  runtime/trace.WithRegion
     0.01s 0.026% 47.50%      2.17s  5.64%  go/types.(*Checker).assignment
         0     0% 47.50%      2.15s  5.59%  go/types.(*Checker).definedType
         0     0% 47.50%      2.13s  5.54%  go/parser.(*parser).parseExprList
         0     0% 47.50%      2.13s  5.54%  go/parser.(*parser).parseList (partial-inline)
     2.11s  5.49% 52.99%      2.11s  5.49%  runtime.memclrNoHeapPointers
     0.01s 0.026% 53.02%      2.08s  5.41%  go/types.(*Checker).varType
     0.03s 0.078% 53.09%      2.02s  5.25%  go/parser.(*parser).parseIfStmt
         0     0% 53.09%      2.02s  5.25%  go/types.(*Checker).simpleStmt
         0     0% 53.09%      2.01s  5.23%  golang.org/x/tools/gopls/internal/lsp/cache.(*syntaxPackage).xrefs
         0     0% 53.09%      2.01s  5.23%  golang.org/x/tools/gopls/internal/lsp/cache.(*syntaxPackage).xrefs.func1
         0     0% 53.09%      2.01s  5.23%  golang.org/x/tools/gopls/internal/lsp/source/xrefs.Index
         0     0% 53.09%      1.99s  5.17%  go/types.(*Checker).walkDecls (inline)
     0.08s  0.21% 53.30%      1.95s  5.07%  go/ast.walkStmtList
     0.55s  1.43% 54.73%      1.95s  5.07%  go/types.(*Checker).collectObjects.func1
     0.60s  1.56% 56.29%      1.95s  5.07%  runtime.mapassign_fast64ptr
     0.02s 0.052% 56.34%      1.91s  4.97%  go/ast.inspector.Visit
     0.02s 0.052% 56.40%      1.87s  4.86%  go/parser.(*parser).parseBinaryExpr
         0     0% 56.40%      1.87s  4.86%  go/parser.(*parser).parseExpr
         0     0% 56.40%      1.87s  4.86%  runtime.(*mheap).alloc.func1
         0     0% 56.40%      1.87s  4.86%  runtime.(*mheap).allocSpan
     0.14s  0.36% 56.76%      1.78s  4.63%  go/types.(*Checker).ident
         0     0% 56.76%      1.74s  4.52%  go/parser.(*parser).parseUnaryExpr
     0.02s 0.052% 56.81%      1.73s  4.50%  go/parser.(*parser).parsePrimaryExpr
     1.71s  4.45% 61.26%      1.71s  4.45%  runtime.madvise
         0     0% 61.26%      1.71s  4.45%  runtime.sysUsed (inline)
         0     0% 61.26%      1.71s  4.45%  runtime.sysUsedOS (inline)
     0.02s 0.052% 61.31%      1.65s  4.29%  go/types.(*Checker).typInternal
         0     0% 61.31%      1.54s  4.00%  go/parser.(*parser).parseBlockStmt
         0     0% 61.31%      1.53s  3.98%  runtime.gcBgMarkWorker.func2
     0.01s 0.026% 61.34%      1.53s  3.98%  runtime.gcDrain
         0     0% 61.34%      1.52s  3.95%  runtime.gcBgMarkWorker
     0.04s   0.1% 61.44%      1.52s  3.95%  runtime.typedmemmove
     0.16s  0.42% 61.86%      1.50s  3.90%  golang.org/x/tools/gopls/internal/lsp/source/xrefs.Index.func3
         0     0% 61.86%      1.47s  3.82%  go/types.(*Checker).openScope
     0.86s  2.24% 64.09%      1.46s  3.80%  runtime.findObject
     0.68s  1.77% 65.86%      1.45s  3.77%  runtime.evacuate
         0     0% 65.86%      1.45s  3.77%  runtime.growWork
     0.06s  0.16% 66.02%      1.43s  3.72%  go/ast.walkExprList
     0.11s  0.29% 66.30%      1.37s  3.56%  runtime.mapassign_faststr
     0.06s  0.16% 66.46%      1.37s  3.56%  runtime.wbBufFlush
         0     0% 66.46%      1.33s  3.46%  go/parser.(*parser).next
     0.56s  1.46% 67.91%      1.30s  3.38%  runtime.gcWriteBarrier
         0     0% 67.91%      1.30s  3.38%  runtime.wbBufFlush.func1
     0.35s  0.91% 68.82%      1.30s  3.38%  runtime.wbBufFlush1
         0     0% 68.82%      1.23s  3.20%  go/parser.(*parser).next0
     1.23s  3.20% 72.02%      1.23s  3.20%  runtime.memmove
     0.03s 0.078% 72.10%      1.22s  3.17%  go/parser.resolveFile
         0     0% 72.10%      1.20s  3.12%  golang.org/x/tools/internal/gcimporter.IExportShallow
         0     0% 72.10%      1.20s  3.12%  golang.org/x/tools/internal/gcimporter.iexportCommon
     0.05s  0.13% 72.23%      1.18s  3.07%  go/scanner.(*Scanner).Scan
         0     0% 72.23%      1.18s  3.07%  golang.org/x/tools/gopls/internal/lsp/cache.execActions.func1
         0     0% 72.23%      1.18s  3.07%  golang.org/x/tools/gopls/internal/lsp/cache.execActions.func1.1
     0.02s 0.052% 72.28%      1.17s  3.04%  runtime.(*hmap).newoverflow
         0     0% 72.28%      1.15s  2.99%  golang.org/x/tools/gopls/internal/lsp/cache.(*action).exec
     0.08s  0.21% 72.49%      1.14s  2.96%  go/parser.(*resolver).Visit
     0.03s 0.078% 72.57%      1.12s  2.91%  go/parser.(*parser).parseIdent
         0     0% 72.57%      1.12s  2.91%  go/types.(*Checker).shortVarDecl
         0     0% 72.57%      1.10s  2.86%  golang.org/x/tools/gopls/internal/lsp/cache.(*action).exec.func6
         0     0% 72.57%      1.06s  2.76%  go/types.(*Scope).Insert
         0     0% 72.57%      1.05s  2.73%  go/types.(*Checker).recordUse
     0.05s  0.13% 72.70%      1.01s  2.63%  go/types.(*Checker).arguments
     0.03s 0.078% 72.78%      1.01s  2.63%  go/types.(*Checker).unary
         0     0% 72.78%      1.01s  2.63%  go/types.(*Scope).insert (inline)
     0.23s   0.6% 73.37%      0.93s  2.42%  runtime.bulkBarrierPreWrite
         0     0% 73.37%      0.91s  2.37%  go/types.(*Checker).exprWithHint
         0     0% 73.37%      0.91s  2.37%  runtime.hashGrow
         0     0% 73.37%      0.90s  2.34%  golang.org/x/tools/internal/gcimporter.(*iexporter).doDecl
         0     0% 73.37%      0.90s  2.34%  runtime.makeBucketArray
     0.02s 0.052% 73.43%      0.89s  2.31%  go/parser.(*parser).parseCallOrConversion
         0     0% 73.43%      0.89s  2.31%  go/parser.(*parser).parseForStmt
     0.02s 0.052% 73.48%      0.89s  2.31%  go/types.NewScope (inline)
         0     0% 73.48%      0.88s  2.29%  go/types.(*Checker).declare
         0     0% 73.48%      0.87s  2.26%  runtime.newarray
         0     0% 73.48%      0.84s  2.18%  go/parser.(*parser).parseIfHeader
     0.02s 0.052% 73.53%      0.84s  2.18%  runtime.slicebytetostring
     0.01s 0.026% 73.56%      0.81s  2.11%  golang.org/x/tools/go/types/objectpath.(*Encoder).For
     0.17s  0.44% 74.00%      0.78s  2.03%  go/scanner.(*Scanner).scanIdentifier
         0     0% 74.00%      0.75s  1.95%  go/types.(*Checker).typeDecl
         0     0% 74.00%      0.74s  1.92%  go/parser.(*parser).parseParameters
     0.33s  0.86% 74.86%      0.74s  1.92%  runtime.evacuate_fast64
         0     0% 74.86%      0.74s  1.92%  runtime.growWork_fast64
         0     0% 74.86%      0.73s  1.90%  go/types.(*Checker).assignVar
     0.01s 0.026% 74.88%      0.73s  1.90%  go/types.(*Checker).recordDef (inline)
         0     0% 74.88%      0.73s  1.90%  runtime.makeslice
     0.04s   0.1% 74.99%      0.70s  1.82%  go/types.lookupFieldOrMethod
         0     0% 74.99%      0.69s  1.79%  go/parser.(*resolver).walkBody
     0.01s 0.026% 75.01%      0.69s  1.79%  go/types.LookupFieldOrMethod
     0.69s  1.79% 76.81%      0.69s  1.79%  runtime.heapBitsForAddr
     0.04s   0.1% 76.91%      0.64s  1.66%  go/parser.(*resolver).walkStmts (inline)
         0     0% 76.91%      0.63s  1.64%  golang.org/x/tools/go/analysis/passes/inspect.run
         0     0% 76.91%      0.63s  1.64%  golang.org/x/tools/go/ast/inspector.New (inline)
         0     0% 76.91%      0.63s  1.64%  golang.org/x/tools/go/ast/inspector.traverse
         0     0% 76.91%      0.62s  1.61%  go/types.(*Checker).validVarType
     0.01s 0.026% 76.94%      0.62s  1.61%  go/types.(*objset).insert
     0.01s 0.026% 76.96%      0.60s  1.56%  go/parser.(*parser).parseOperand
         0     0% 76.96%      0.60s  1.56%  go/parser.(*parser).parseReturnStmt
         0     0% 76.96%      0.59s  1.53%  go/parser.(*parser).expect
         0     0% 76.96%      0.59s  1.53%  go/parser.(*parser).parseParameterList
     0.03s 0.078% 77.04%      0.59s  1.53%  go/types.(*Checker).collectMethods
         0     0% 77.04%      0.58s  1.51%  bytes.(*Buffer).grow
         0     0% 77.04%      0.58s  1.51%  go/parser.(*parser).parseSwitchStmt
         0     0% 77.04%      0.58s  1.51%  go/types.(*Checker).recordSelection
         0     0% 77.04%      0.57s  1.48%  go/parser.(*parser).parseCaseClause
     0.08s  0.21% 77.25%      0.57s  1.48%  golang.org/x/tools/internal/gcimporter.(*exportWriter).param
     0.11s  0.29% 77.54%      0.53s  1.38%  go/types.(*Checker).structType
         0     0% 77.54%      0.48s  1.25%  go/types.(*Checker).sprintf
         0     0% 77.54%      0.48s  1.25%  golang.org/x/tools/internal/gcimporter.(*exportWriter).typ
         0     0% 77.54%      0.47s  1.22%  golang.org/x/tools/internal/gcimporter.(*iexporter).typOff
     0.18s  0.47% 78.00%      0.47s  1.22%  runtime.mapaccess1_faststr
         0     0% 78.00%      0.46s  1.20%  go/parser.(*parser).parseRhs (inline)
     0.02s 0.052% 78.06%      0.46s  1.20%  go/types.(*Scope).Lookup (inline)
         0     0% 78.06%      0.46s  1.20%  go/types.(*object).Id (partial-inline)
         0     0% 78.06%      0.46s  1.20%  go/types.Id
         0     0% 78.06%      0.46s  1.20%  go/types.sprintf
         0     0% 78.06%      0.44s  1.14%  go/types.(*Checker).labels
     0.01s 0.026% 78.08%      0.43s  1.12%  go/types.(*Checker).blockBranches
         0     0% 78.08%      0.43s  1.12%  runtime.(*mSpanStateBox).get (inline)
     0.43s  1.12% 79.20%      0.43s  1.12%  runtime/internal/atomic.(*Uint8).Load (inline)
         0     0% 79.20%      0.42s  1.09%  go/types.(*Checker).blockBranches.func4
         0     0% 79.20%      0.42s  1.09%  go/types.(*Scope).squash
         0     0% 79.20%      0.42s  1.09%  go/types.(*operand).setConst
         0     0% 79.20%      0.42s  1.09%  runtime.makemap_small
         0     0% 79.20%      0.41s  1.07%  go/constant.MakeFromLiteral
     0.02s 0.052% 79.25%      0.41s  1.07%  runtime.gcWriteBarrierDX
         0     0% 79.25%      0.40s  1.04%  go/types.(*Checker).initOrder
     0.01s 0.026% 79.28%      0.39s  1.01%  go/types.dependencyGraph
     0.17s  0.44% 79.72%      0.39s  1.01%  golang.org/x/tools/go/ast/inspector.traverse.func1
         0     0% 79.72%      0.37s  0.96%  runtime.memclrHasPointers
         0     0% 79.72%      0.35s  0.91%  go/parser.(*parser).parseParamDecl
         0     0% 79.72%      0.35s  0.91%  go/parser.(*parser).parseSelector
     0.01s 0.026% 79.75%      0.35s  0.91%  golang.org/x/tools/go/ast/inspector.(*Inspector).Preorder
     0.34s  0.88% 80.63%      0.34s  0.88%  aeshashbody
     0.01s 0.026% 80.66%      0.34s  0.88%  go/parser.(*parser).tryIdentOrType
     0.27s   0.7% 81.36%      0.33s  0.86%  go/types.(*Checker).resolveBaseTypeName
     0.33s  0.86% 82.22%      0.33s  0.86%  runtime.evacuated (inline)
         0     0% 82.22%      0.33s  0.86%  sort.Slice
         0     0% 82.22%      0.33s  0.86%  sort.pdqsort_func
         0     0% 82.22%      0.32s  0.83%  bytes.(*Buffer).Write
     0.01s 0.026% 82.24%      0.32s  0.83%  go/types.NewParam (inline)
         0     0% 82.24%      0.31s  0.81%  go/parser.(*parser).expectSemi
         0     0% 82.24%      0.31s  0.81%  go/parser.(*parser).parseType
         0     0% 82.24%      0.30s  0.78%  go/types.(*Checker).recordScope
         0     0% 82.24%      0.30s  0.78%  go/types.ExprString
         0     0% 82.24%      0.30s  0.78%  golang.org/x/tools/go/analysis/passes/printf.run
     0.29s  0.75% 83.00%      0.29s  0.75%  go/ast.(*FieldList).NumFields (inline)
     0.01s 0.026% 83.02%      0.29s  0.75%  go/types.(*Checker).recordUntyped
         0     0% 83.02%      0.29s  0.75%  go/types.(*Checker).rememberUntyped (inline)
         0     0% 83.02%      0.29s  0.75%  golang.org/x/tools/go/analysis/passes/printf.checkCall
         0     0% 83.02%      0.29s  0.75%  net/http.(*ServeMux).ServeHTTP
         0     0% 83.02%      0.29s  0.75%  net/http.(*conn).serve
         0     0% 83.02%      0.29s  0.75%  net/http.HandlerFunc.ServeHTTP
         0     0% 83.02%      0.29s  0.75%  net/http.serverHandler.ServeHTTP
         0     0% 83.02%      0.28s  0.73%  golang.org/x/tools/go/analysis/passes/printf.checkCall.func1
         0     0% 83.02%      0.28s  0.73%  runtime.concatstrings
     0.10s  0.26% 83.28%      0.27s   0.7%  go/scanner.(*Scanner).next
         0     0% 83.28%      0.27s   0.7%  go/token.IsExported
         0     0% 83.28%      0.27s   0.7%  go/types.(*Checker).comparison
         0     0% 83.28%      0.27s   0.7%  go/types.(*Checker).initVar
         0     0% 83.28%      0.27s   0.7%  go/types.(*Checker).typ (inline)
     0.14s  0.36% 83.65%      0.27s   0.7%  go/types.lookupMethod
         0     0% 83.65%      0.27s   0.7%  golang.org/x/tools/internal/gcimporter.(*exportWriter).paramList
         0     0% 83.65%      0.27s   0.7%  golang.org/x/tools/internal/gcimporter.(*exportWriter).signature
         0     0% 83.65%      0.27s   0.7%  golang.org/x/tools/internal/gcimporter.(*iexporter).newWriter (inline)
         0     0% 83.65%      0.26s  0.68%  go/types.(*Named).lookupMethod
         0     0% 83.65%      0.26s  0.68%  go/types.(*Scope).LookupParent
         0     0% 83.65%      0.26s  0.68%  net/http/pprof.Index
         0     0% 83.65%      0.26s  0.68%  net/http/pprof.collectProfile
         0     0% 83.65%      0.26s  0.68%  net/http/pprof.handler.ServeHTTP
         0     0% 83.65%      0.26s  0.68%  net/http/pprof.handler.serveDeltaProfile
     0.17s  0.44% 84.09%      0.26s  0.68%  runtime.greyobject
         0     0% 84.09%      0.26s  0.68%  sort.Sort
         0     0% 84.09%      0.26s  0.68%  sort.pdqsort
     0.26s  0.68% 84.76%      0.26s  0.68%  unicode/utf8.DecodeRuneInString
         0     0% 84.76%      0.25s  0.65%  bytes.growSlice
     0.24s  0.62% 85.39%      0.25s  0.65%  go/ast.(*FuncType).Pos (partial-inline)
         0     0% 85.39%      0.25s  0.65%  go/ast.NewScope (inline)
         0     0% 85.39%      0.25s  0.65%  go/types.(*Checker).declStmt
     0.15s  0.39% 85.78%      0.25s  0.65%  runtime.bulkBarrierPreWriteSrcOnly
         0     0% 85.78%      0.25s  0.65%  runtime.concatstring3
         0     0% 85.78%      0.25s  0.65%  runtime.rawstring (inline)
         0     0% 85.78%      0.25s  0.65%  runtime.rawstringtmp
         0     0% 85.78%      0.25s  0.65%  runtime/pprof.(*Profile).WriteTo
         0     0% 85.78%      0.25s  0.65%  runtime/pprof.writeHeap
         0     0% 85.78%      0.25s  0.65%  runtime/pprof.writeHeapInternal
         0     0% 85.78%      0.25s  0.65%  runtime/pprof.writeHeapProto
     0.01s 0.026% 85.80%      0.24s  0.62%  runtime.gcWriteBarrierCX
     0.24s  0.62% 86.43%      0.24s  0.62%  runtime.memhash64
     0.02s 0.052% 86.48%      0.23s   0.6%  go/types.(*Checker).declStmt.func1
         0     0% 86.48%      0.23s   0.6%  golang.org/x/tools/gopls/internal/lsp/filecache.gc
     0.01s 0.026% 86.51%      0.22s  0.57%  bytes.(*Buffer).WriteString
         0     0% 86.51%      0.22s  0.57%  go/parser.(*resolver).declare
         0     0% 86.51%      0.22s  0.57%  go/parser.(*resolver).openScope (inline)
     0.02s 0.052% 86.56%      0.22s  0.57%  go/types.(*Checker).sliceExpr
     0.01s 0.026% 86.58%      0.22s  0.57%  go/types.NewFunc (inline)
     0.04s   0.1% 86.69%      0.22s  0.57%  runtime.heapBitsSetType
         0     0% 86.69%      0.21s  0.55%  go/parser.(*resolver).resolve
         0     0% 86.69%      0.21s  0.55%  go/types.(*Checker).later (inline)
         0     0% 86.69%      0.21s  0.55%  go/types.concat (inline)
     0.01s 0.026% 86.71%      0.21s  0.55%  golang.org/x/tools/internal/gcimporter.(*exportWriter).doTyp
         0     0% 86.71%      0.21s  0.55%  golang.org/x/tools/internal/gcimporter.(*intWriter).uint64
     0.21s  0.55% 87.26%      0.21s  0.55%  memeqbody
         0     0% 87.26%      0.21s  0.55%  path/filepath.Walk
         0     0% 87.26%      0.21s  0.55%  path/filepath.walk
     0.21s  0.55% 87.81%      0.21s  0.55%  runtime.(*bmap).overflow (inline)
     0.01s 0.026% 87.83%      0.20s  0.52%  go/types.(*Checker).interfaceType

@Kidsunbo
Copy link
Author

Thanks @Kidsunbo.

It looks like you have a medium-large workspace, but perhaps with some large packages. We have two existing bugs related to opening a package that depends on a particularly large package (#61178 and #61207).

Based on the symptoms you describe, it sounds like static analysis is taking a long time. It may not take a long time now, because it successfully analyzed all your dependencies (and now those results are cached).

As for the profile, I didn't find it in /tmp. In addition, all the projects that trigger the problem are close-source projects in my company. I think I am not allowed to share the profile which might contain debug info or something.

Profiles in general do not contain private information (they contain timing information for functions in the gopls executable). However, all we really need is the top functions, which you can inspect before sharing. If you could do this, it would be very useful:

  • Start gopls with -debug=localhost:6060
  • From a terminal, run go tool pprof -seconds 10 -top -cum http://localhost:6060/debug/pprof/profile

That will output the top functions consuming CPU in gopls, during the 10 seconds that it samples. Try to catch gopls in the act of burning through CPU/memory. If you can share the results, it will tell us the root cause.

I run the command three times, and here is the generated pb file.
pprof.samples.cpu.001.pb.gz
pprof.samples.cpu.002.pb.gz
pprof.samples.cpu.003.pb.gz

@Kidsunbo
Copy link
Author

Kidsunbo commented Jul 16, 2023 •
edited

Thanks @Kidsunbo.

It looks like you have a medium-large workspace, but perhaps with some large packages. We have two existing bugs related to opening a package that depends on a particularly large package (#61178 and #61207).

Based on the symptoms you describe, it sounds like static analysis is taking a long time. It may not take a long time now, because it successfully analyzed all your dependencies (and now those results are cached).

As for the profile, I didn't find it in /tmp. In addition, all the projects that trigger the problem are close-source projects in my company. I think I am not allowed to share the profile which might contain debug info or something.

Profiles in general do not contain private information (they contain timing information for functions in the gopls executable). However, all we really need is the top functions, which you can inspect before sharing. If you could do this, it would be very useful:

  • Start gopls with -debug=localhost:6060
  • From a terminal, run go tool pprof -seconds 10 -top -cum http://localhost:6060/debug/pprof/profile

That will output the top functions consuming CPU in gopls, during the 10 seconds that it samples. Try to catch gopls in the act of burning through CPU/memory. If you can share the results, it will tell us the root cause.

I also pprof the heap which should be more related to the problem:

(pprof) top -cum
Showing nodes accounting for 42.71MB, 0.19% of 23085.89MB total
Dropped 541 nodes (cum <= 115.43MB)
Showing top 10 nodes out of 210
      flat  flat%   sum%        cum   cum%
         0     0%     0% 17907.32MB 77.57%  golang.org/x/sync/errgroup.(*Group).Go.func1
         0     0%     0% 12379.86MB 53.63%  go/types.(*Checker).checkFiles
         0     0%     0% 12343.49MB 53.47%  go/types.(*Checker).Files (inline)
       1MB 0.0043% 0.0043%  9151.34MB 39.64%  golang.org/x/tools/gopls/internal/lsp/cache.(*analysisNode).typeCheck
    2.50MB 0.011% 0.015%  9126.84MB 39.53%  golang.org/x/tools/gopls/internal/lsp/cache.(*analysisNode).run
         0     0% 0.015%  9061.40MB 39.25%  golang.org/x/tools/gopls/internal/lsp/cache.(*analysisNode).runCached
         0     0% 0.015%  9022.05MB 39.08%  golang.org/x/tools/gopls/internal/lsp/cache.(*snapshot).Analyze.func3.1
       1MB 0.0043% 0.019%  7171.92MB 31.07%  go/parser.ParseFile
   38.21MB  0.17%  0.19%  7020.44MB 30.41%  go/parser.(*parser).parseFile
         0     0%  0.19%     6981MB 30.24%  golang.org/x/tools/gopls/internal/lsp/cache.ParseGoSrc

heap.zip

@jamalc jamalc assigned jamalc and adonovan and unassigned jamalc Jul 20, 2023
@adonovan
Copy link
Member

See: https://go.dev/cl/511715

@adonovan adonovan added gopls/performance Issues related to gopls performance (CPU, memory, etc). gopls/analysis Issues related to running analysis in gopls Analysis Issues related to static analysis (vet, x/tools/go/analysis) and removed WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. labels Jul 25, 2023
@findleyr
Copy link
Contributor

I believe we have made progress on the runaway resource usage caused by analysis. In particular, we have reduced parallelism so that analysis should never hit the same high water mark.

@Kidsunbo could you please try out the prerelease to see if it improves the situation for you?

go install golang.org/x/tools/gopls@v0.13.0-pre.2

We have ideas for how to improve the cost of analysis facts, but that is a separate issue.

Also: @xiaokentrl I see you 👎ed a few comments: are you also experiencing problems with memory usage? If so, could you share what you are experiencing?

@Kidsunbo
Copy link
Author

Kidsunbo commented Jul 27, 2023 •
edited

I believe we have made progress on the runaway resource usage caused by analysis. In particular, we have reduced parallelism so that analysis should never hit the same high water mark.

@Kidsunbo could you please try out the prerelease to see if it improves the situation for you?

go install golang.org/x/tools/gopls@v0.13.0-pre.2

We have ideas for how to improve the cost of analysis facts, but that is a separate issue.

Also: @xiaokentrl I see you 👎ed a few comments: are you also experiencing problems with memory usage? If so, could you share what you are experiencing?

Yeah, much better, you guys did a good job. And now there is the progress to learn about how many packages have been indexed, which is good.
But maybe this should be fixed? VSCode seems not to display properly.
image

I think now this issue can be closed. It does not exhaust my resource. Thank you so much.

@gopherbot
Copy link

Change https://go.dev/cl/513735 mentions this issue: gopls/internal/lsp/cache: keep analysis progress reports on one line

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@adonovan adonovan

Labels
Analysis Issues related to static analysis (vet, x/tools/go/analysis) gopls/analysis Issues related to running analysis in gopls gopls/performance Issues related to gopls performance (CPU, memory, etc). gopls Issues related to the Go language server, gopls. Tools This label describes issues relating to any tools in the x/tools repository.
Projects
None yet
Milestone
gopls/v0.13.0
Development

No branches or pull requests
6 participants
@adonovan @gopherbot @seankhliao @Kidsunbo @jamalc @findleyr