Why the execution of golangci-lint takes so much time

[Moser-ss]

In the documentation, it says the execution of golangci-lint could take 1s or 35s without cache, but in my project, I am getting a bigger time to execute the command.
For example, I had a run that took 110629ms, and it is a small project. In my machine normally took 4s (based on the output of the time command)
In the GitHub action I am using the same setup we have in the documentation

Job definition

  lint:
    name: lint
    runs-on: ubuntu-latest
    steps:
      - uses: actions/checkout@v2
      - name: golangci-lint
        uses: golangci/golangci-lint-action@v2
        with:
          version: v1.29
          args: --timeout 3m0s

Job output

Run golangci/golangci-lint-action@v2
prepare environment
go env
Installed Go in 230ms
Requested golangci-lint 'v1.29', using 'v1.29.0', calculation took 261ms
Installing golangci-lint v1.29.0...
Downloading https://github.com/golangci/golangci-lint/releases/download/v1.29.0/golangci-lint-1.29.0-linux-amd64.tar.gz ...
Cache not found for input keys: golangci-lint.cache-2690-bc8b7dd79789a0f804ae3b455ac3675f98516b1a, golangci-lint.cache-2690-, golangci-lint.cache-
/usr/bin/tar xz --overwrite --warning=no-unknown-keyword -C /home/runner -f /home/runner/work/_temp/2680cbd8-7cef-4ae9-b3f8-76eda97557b9
Installed golangci-lint into /home/runner/golangci-lint-1.29.0-linux-amd64/golangci-lint in 693ms
Prepared env in 957ms

run golangci-lint
  Running [/home/runner/golangci-lint-1.29.0-linux-amd64/golangci-lint run --out-format=github-actions --timeout 3m0s] in [] ...
  golangci-lint found no issues
  Ran golangci-lint in 110629ms

Local machine output

time golangci-lint run --out-format=github-actions --timeout 3m0s
golangci-lint run --out-format=github-actions --timeout 3m0s  4.34s user 5.27s system 399% cpu 2.404 total

[hongbo-miao]

Just add more info if helps. 😃

My golangci-lint action recently 50% time failed because of timeout issue since a week ago. Mine is a small project too at this moment.

Below are two pull requests which is not related to with Go part (defined in working-directory) at all:

Here is when it is normal
https://github.com/Hongbo-Miao/hongbomiao.com/runs/3297080244?check_suite_focus=true

  Running [/home/runner/golangci-lint-1.40.1-linux-amd64/golangci-lint run --out-format=github-actions --path-prefix=api-go] in [/home/runner/work/hongbomiao.com/hongbomiao.com/api-go] ...
  golangci-lint found no issues
  Ran golangci-lint in 6029ms

And here is when it is slow
https://github.com/Hongbo-Miao/hongbomiao.com/runs/3298464932?check_suite_focus=true

  Running [/home/runner/golangci-lint-1.40.1-linux-amd64/golangci-lint run --out-format=github-actions --path-prefix=api-go] in [/home/runner/work/hongbomiao.com/hongbomiao.com/api-go] ...
  level=error msg="Timeout exceeded: try increasing it by passing --timeout option"
  
  Error: golangci-lint exit with code 4
  Ran golangci-lint in 71047ms

As you see, both runs happen recently, however, when golangci-lint is slow, it can take a very long time.

[ngfgrant]

We are also increasingly seeing this behaviour in our builds. Is there anything I can do to help?

[SVilgelm]

It really depends on the number of enabled linters. Some linters requires whole project to be loaded, other linters are just slow by their nature.
I would recommend to add --verbose flag to see what linters takes the most time and try to adjust a configuration or disable those linters.

lint:
    name: lint
    runs-on: ubuntu-latest
    steps:
      - uses: actions/checkout@v2
      - uses: actions/setup-go@v2
      - name: golangci-lint
        uses: golangci/golangci-lint-action@v2
        with:
          skip-go-installation: true
          version: latest
          args: --timeout 3m --verbose

[Z-a-r-a-k-i]

Here is the log of my github action:

Cache restored successfully
  Restored cache for golangci-lint from key 'golangci-lint.cache-[27](https://github.com/zenlaw/mlbuddy/actions/runs/4084996956/jobs/7042382282#step:4:28)70-nogomod' in 10656ms
  Prepared env in 10656ms
run golangci-lint
  Running [/home/runner/golangci-lint-1.50.1-linux-amd64/golangci-lint run --out-format=github-actions --path-prefix=go --timeout=5m --verbose] in [/home/runner/work/mlbuddy/mlbuddy/go] ...
  level=info msg="[config_reader] Config search paths: [./ /home/runner/work/mlbuddy/mlbuddy/go /home/runner/work/mlbuddy/mlbuddy /home/runner/work/mlbuddy /home/runner/work /home/runner /home /]"
  level=info msg="[config_reader] Used config file .golangci.yml"
  level=info msg="[lintersdb] Active 34 linters: [asasalint bidichk bodyclose decorder depguard dogsled dupl durationcheck errcheck errchkjson errname exportloopref gochecknoinits goconst gocritic gofmt goimports gosimple govet ineffassign misspell nakedret nilerr nilnil prealloc reassign revive staticcheck typecheck unconvert unparam unused wastedassign whitespace]"
  level=info msg="[loader] Go packages loading at mode 575 (exports_file|files|imports|name|types_sizes|compiled_files|deps) took 1m35.053058522s"
  level=info msg="[runner/filename_unadjuster] Pre-built 0 adjustments in 204.32521ms"
  level=info msg="[linters_context/goanalysis] analyzers took 3m43.845635486s with top 10 stages: buildir: 1m19.355022917s, dupl: 14.699625389s, buildssa: 9.692789106s, goimports: 8.3816698[28](https://github.com/zenlaw/mlbuddy/actions/runs/4084996956/jobs/7042382282#step:4:29)s, gocritic: 8.3[29](https://github.com/zenlaw/mlbuddy/actions/runs/4084996956/jobs/7042382282#step:4:31)872555s, gofmt: 6.651901432s, S1038: 5.990133641s, whitespace: 4.560082207s, the_only_name: 4.350220759s, misspell: 3.517186867s"
  level=warning msg="[linters_context] wastedassign is disabled because of generics. You can track the evolution of the generics support by following the https://github.com/golangci/golangci-lint/issues/2649."
  level=info msg="[runner] Issues before processing: 2101, after processing: 0"
  level=info msg="[runner] Processors filtering stat (out/in): filename_unadjuster: 2101/2101, path_prettifier: 2101/2101, skip_files: 952/2101, skip_dirs: 952/952, identifier_marker: [30](https://github.com/zenlaw/mlbuddy/actions/runs/4084996956/jobs/7042382282#step:4:32)2/302, exclude: 302/302, nolint: 0/14, cgo: 2101/2101, autogenerated_exclude: 302/952, exclude-rules: 14/302"
  level=info msg="[runner] processing took 36.24[31](https://github.com/zenlaw/mlbuddy/actions/runs/4084996956/jobs/7042382282#step:4:33)15ms with stages: exclude-rules: 11.972664ms, identifier_marker: 8.45254ms, nolint: 6.058687ms, skip_files: 3.485522ms, path_prettifier: 2.981491ms, autogenerated_exclude: 1.777214ms, exclude: 799.351µs, skip_dirs: 311.02µs, cgo: 200.713µs, filename_unadjuster: 198.913µs, max_same_issues: 2µs, uniq_by_line: 600ns, max_from_linter: 400ns, diff: 400ns, path_shortener: 300ns, severity-rules: 300ns, sort_results: 300ns, source_code: 300ns, max_per_file_from_linter: 300ns, path_prefixer: 100ns"
  level=info msg="[runner] linters took 1m5.076635566s with stages: goanalysis_metalinter: 1m5.039783912s, wastedassign: 151.01µs"
  level=info msg="File cache stats: 205 entries of total size 3.8MiB"
  level=info msg="Memory: 1601 samples, avg is 536.3MB, max is 2852.9MB"
  level=info msg="Execution took 2m40.[34](https://github.com/zenlaw/mlbuddy/actions/runs/4084996956/jobs/7042382282#step:4:36)6306058s"

As I said previously, locally it takes 3sec:

golangci-lint run --timeout=120s --verbose ./...
INFO [config_reader] Config search paths: [./ /home/zaraki/dev/mlbuddy/go /home/zaraki/dev/mlbuddy /home/zaraki/dev /home/zaraki /home /]
INFO [config_reader] Used config file ../.golangci.yml
INFO [lintersdb] Active 34 linters: [asasalint bidichk bodyclose decorder depguard dogsled dupl durationcheck errcheck errchkjson errname exportloopref gochecknoinits goconst gocritic gofmt goimports gosimple govet ineffassign misspell nakedret nilerr nilnil prealloc reassign revive staticcheck typecheck unconvert unparam unused wastedassign whitespace]
INFO [loader] Go packages loading at mode 575 (compiled_files|deps|types_sizes|exports_file|files|imports|name) took 494.9541ms
INFO [runner/filename_unadjuster] Pre-built 0 adjustments in 88.3914ms
INFO [linters_context/goanalysis] analyzers took 0s with no stages
WARN [linters_context] wastedassign is disabled because of generics. You can track the evolution of the generics support by following the https://github.com/golangci/golangci-lint/issues/2649.
INFO [runner] Issues before processing: 2101, after processing: 0
INFO [runner] Processors filtering stat (out/in): cgo: 2101/2101, exclude: 302/302, filename_unadjuster: 2101/2101, autogenerated_exclude: 302/952, skip_files: 952/2101, skip_dirs: 952/952, identifier_marker: 302/302, nolint: 0/14, path_prettifier: 2101/2101, exclude-rules: 14/302
INFO [runner] processing took 18.6419ms with stages: exclude-rules: 6.3786ms, identifier_marker: 4.3327ms, nolint: 2.9144ms, skip_files: 1.6102ms, autogenerated_exclude: 1.5918ms, path_prettifier: 1.1131ms, exclude: 410.9µs, skip_dirs: 136.7µs, cgo: 87.6µs, filename_unadjuster: 61.3µs, max_same_issues: 1.1µs, uniq_by_line: 600ns, max_from_linter: 500ns, diff: 500ns, path_shortener: 400ns, path_prefixer: 300ns, severity-rules: 300ns, sort_results: 300ns, source_code: 300ns, max_per_file_from_linter: 300ns
INFO [runner] linters took 506.4199ms with stages: goanalysis_metalinter: 487.6298ms, wastedassign: 25.7µs
INFO File cache stats: 0 entries of total size 0B
INFO Memory: 13 samples, avg is 64.5MB, max is 106.2MB
INFO Execution took 1.1154662s

[Z-a-r-a-k-i]

Updated to from version 1.50.1 to 1.51.1 divided execution time almost by 3 !

  level=info msg="Memory: 683 samples, avg is 1207.0MB, max is 3156.9MB"
  level=info msg="Execution took 1m8.175037756s"
  
  golangci-lint found no issues
  Ran golangci-lint in 68381ms

Thank you!

[paveljanda]

Same here. Good job, guys! 👍

[andig]

I found caching to be super slow (> 1minute):

Post job cleanup.
[2](https://github.com/evcc-io/evcc/actions/runs/4271567921/jobs/7436121489#step:8:2)
/usr/bin/tar --posix -cf cache.tgz --exclude cache.tgz -P -C /home/runner/work/evcc/evcc --files-from manifest.txt -z
[3](https://github.com/evcc-io/evcc/actions/runs/4271567921/jobs/7436121489#step:8:3)
Cache Size: ~517 MB (542476514 B)
[4](https://github.com/evcc-io/evcc/actions/runs/4271567921/jobs/7436121489#step:8:4)
Cache saved successfully
[5](https://github.com/evcc-io/evcc/actions/runs/4271567921/jobs/7436121489#step:8:5)
Saved cache for golangci-lint from paths '/home/runner/.cache/golangci-lint, /home/runner/.cache/go-build, /home/runner/go/pkg, gzip, 1.0' in 74681ms

[shoover]

Cache may not be hitting like people expect. I was complaining about this issue and a colleague pointed out lack of cache makes the lint action take much longer than local. I confirmed by inserting a build step before the lint action step. This shifted module download time to the build and reduced lint run action time from 55s to 15s for my relatively small project.

My understanding was golangci-lint uses the cache out of the box and setup-go@v4 enables cache by default, but we're missing something. Increasing timeout is an ok workaround but we plan to eventually dig further into build order and cache behavior to see why it's not hitting by default for our jobs.

jobs:
  lint:
    name: Lint
    runs-on: ubuntu-latest
    steps:
      - uses: actions/checkout@v3
      - name: Set up Go
        uses: ./.github/actions/setup-go # actions/setup-go@v4, version 1.20

      # Force a build and see if it speeds up the linter. Effectively: `go build -v ./...`.
      - name: Build Services
        run: tools/build

      - name: golangci-lint
        uses: golangci/golangci-lint-action@v3
        with:
          version: v1.51.2
          args: -v

[tschaub]

In my case, it looks like the unusually long run times are due to network activity. The linter task often succeeds in under the default timeout, but periodically takes much longer. The failure cases typically include a long time in the "[loader] Go packages loading" step and the longest running analyzer is the builddir stage (guessing this downloads modules again?).

E.g.

...
level=info msg="[loader] Go packages loading at mode 575
(name|types_sizes|deps|exports_file|imports|compiled_files|files) took
44.30089838s"
...
level=info msg="[linters_context/goanalysis] analyzers took
2m31.090596881s with top 10 stages: buildir: 2m0.404772666s, fact_deprecated:
4.767967923s, inspect: 4.744719515s, printf: 4.31227593s, ctrlflow:
4.142455528s, fact_purity: 3.30849957s, nilness: 2.668495945s, SA5012:
2.512537762s, typedness: 2.08766655s, unused: 312.17566ms"
...

If I add a build step before linting, the "[loader] Go packages loading" step and the buildir stage times are shorter and more consistent.

go build ./...
golangci-lint run --verbose

I've found this to be a suitable alternative to increasing the --timeout.

[martynasbp]

As others have mentioned, the issue appears to be much worse when linters are run in CI agents.

Just take a look at the run on a laptop with a base model M1 cpu:

INFO [config_reader] Used config file .golangci.yml 
INFO [lintersdb] Active 28 linters: [asasalint asciicheck bidichk bodyclose durationcheck errcheck errorlint exportloopref gocritic goimports gosec gosimple govet grouper importas ineffassign makezero mirror nakedret nilerr nilnil noctx prealloc predeclared revive staticcheck unused whitespace] 
INFO [loader] Go packages loading at mode 575 (files|compiled_files|exports_file|name|types_sizes|deps|imports) took 2.949968875s 
INFO [runner/filename_unadjuster] Pre-built 0 adjustments in 117.666166ms 
INFO [linters_context] importas settings found, but no aliases listed. List aliases under alias: key. 
INFO [linters_context/goanalysis] analyzers took 28.901567164s with top 10 stages: buildir: 6.827493066s, buildssa: 5.202256166s, the_only_name: 4.842389543s, goimports: 722.670206ms, errorlint: 419.00371ms, SA4028: 377.880792ms, mirror: 338.055498ms, SA4013: 336.633207ms, gosec: 333.039999ms, S1038: 313.106999ms 
...
INFO [runner] Issues before processing: 1145, after processing: 0 
INFO [runner] Processors filtering stat (out/in): path_prettifier: 1145/1145, autogenerated_exclude: 958/963, nolint: 0/21, exclude: 958/958, exclude-rules: 21/958, cgo: 1145/1145, filename_unadjuster: 1145/1145, skip_files: 1145/1145, skip_dirs: 963/1145, identifier_marker: 958/958 
INFO [runner] processing took 55.295172ms with stages: exclude-rules: 24.27925ms, identifier_marker: 11.856834ms, autogenerated_exclude: 8.037083ms, path_prettifier: 7.291209ms, nolint: 1.930041ms, skip_dirs: 1.782208ms, cgo: 80.459µs, filename_unadjuster: 34.25µs, max_same_issues: 1.25µs, exclude: 501ns, fixer: 375ns, skip_files: 333ns, sort_results: 250ns, uniq_by_line: 209ns, diff: 209ns, source_code: 209ns, severity-rules: 125ns, max_per_file_from_linter: 125ns, path_prefixer: 84ns, max_from_linter: 84ns, path_shortener: 84ns 
INFO [runner] linters took 5.71648525s with stages: goanalysis_metalinter: 5.661081875s 
INFO File cache stats: 0 entries of total size 0B 
INFO Memory: 88 samples, avg is 847.2MB, max is 1745.9MB 
INFO Execution took 8.793254083s  

And the same run on a CI machine, which normally runs other CI commands faster than a Macbook:

level=info msg="[config_reader] Used config file .golangci.yml"
level=info msg="[lintersdb] Active 28 linters: [asasalint asciicheck bidichk bodyclose durationcheck errcheck errorlint exportloopref gocritic goimports gosec gosimple govet grouper importas ineffassign makezero mirror nakedret nilerr nilnil noctx prealloc predeclared revive staticcheck unused whitespace]"
level=info msg="[loader] Go packages loading at mode 575 (imports|name|types_sizes|compiled_files|deps|exports_file|files) took 4m2.438031916s"
level=info msg="[runner/filename_unadjuster] Pre-built 0 adjustments in 548.211422ms"
level=info msg="[linters_context] importas settings found, but no aliases listed. List aliases under alias: key."
level=info msg="[linters_context/goanalysis] analyzers took 23m13.132830335s with top 10 stages: buildir: 8m49.707783739s, buildssa: 4m19.718706844s, goimports: 53.874175693s, the_only_name: 48.84306619s, gocritic: 41.079408508s, whitespace: 32.758541677s, unused: 26.522488002s, gosec: 26.089537126s, bidichk: 23.362879986s, errorlint: 23.057366141s"
...
level=info msg="[runner] Issues before processing: 1145, after processing: 0"
level=info msg="[runner] Processors filtering stat (out/in): filename_unadjuster: 1145/1145, skip_dirs: 963/1145, path_prettifier: 1145/1145, skip_files: 1145/1145, exclude: 958/958, exclude-rules: 21/958, nolint: 0/21, cgo: 1145/1145, identifier_marker: 958/958, autogenerated_exclude: 958/963"
level=info msg="[runner] processing took 124.259311ms with stages: exclude-rules: 60.614603ms, identifier_marker: 32.556155ms, path_prettifier: 13.356923ms, autogenerated_exclude: 8.573315ms, nolint: 5.273409ms, skip_dirs: 3.635306ms, cgo: 162.3µs, filename_unadjuster: 80.3µs, max_same_issues: 1.7µs, diff: 1.1µs, fixer: 600ns, exclude: 600ns, skip_files: 600ns, max_from_linter: 500ns, source_code: 400ns, uniq_by_line: 400ns, severity-rules: 300ns, sort_results: 300ns, max_per_file_from_linter: 200ns, path_shortener: 200ns, path_prefixer: 100ns"
level=info msg="[runner] linters took 2m54.365468458s with stages: goanalysis_metalinter: 2m54.241068447s"
level=info msg="File cache stats: 0 entries of total size 0B"
level=info msg="Memory: 3523 samples, avg is 605.7MB, max is 2780.0MB"
level=info msg="Execution took 6m57.370822188s"

I understand that the two machines aren't the same, but the runtime difference of almost 50x does raise some eyebrows.

[andig]

I've noticed that post lint caching seems exceptionally slow. Note this (from https://github.com/evcc-io/evcc/actions/runs/8763696742/job/24052878678):

2m 10s
Post job cleanup.
Omitting ~/.cache/go-build from cache directories
Omitting ~/go/pkg from cache directories
/usr/bin/tar --posix -cf cache.tzst --exclude cache.tzst -P -C /home/runner/work/evcc/evcc --files-from manifest.txt --use-compress-program zstdmt
Cache Size: ~0 MB (325880 B)
Cache saved successfully
Saved cache for golangci-lint from paths '/home/runner/.cache/golangci-lint' in 469ms

How can we spend 2 minutes for 0 Bytes of cache?

[trakhimenok]

@andig its 0 MB rounded from 325KB so not the 0B.

[andig]

Absolutely. But still 2 minutes- more than writing that amount to a floppy disk 💾

[ldez]

This issue contains mixed problems.
I will only answer to problems related to the action.

The original issue was with golangci/golangci-lint-action@v2 and golangci-lint v1.29 (2020-07-20).
Since then, many improvements have been made.

The other discussions are related to the cache of the action: the problem was related to Go modules cache.

Since actions/setup-go@v4 the setup-go action handles the Go modules cache, so the cache management of the Go modules has been removed from golangci/golangci-lint-action.

Now, the golangci/golangci-lint-action is much faster, especially when you have a large dependency graph.

[andig]

I will only answer to problems related to the action.

@ldez given that I had already excluded Go modules cache and given that restoring the remaining cache seems unreasonably slow, would you a agree that it's a likely assumption that this might be related to the cache action itself or probably more to the underlying Github/Azure infrastructure?

[ldez]

For sure, the performances are related to the hardware used for the CI.

Note: #297 (comment) you can remove actions/cache@v4 because the cache is already handled by the dedicated actions.