5x slower than plain "go vet" with just "govet" enabled

[atombender]

golangci-lint seems to have become much slower recently. As a test case, I see that golangci-lint with govet takes about 6.4 seconds, compared to plain go vet at 1.25 seconds.

Just with govet enabled:

$ time /usr/local/bin/golangci-lint run --disable-all --enable=govet --tests -v
INFO [config_reader] Config search paths: [./ /Users/alex/Projects/Transparensee/pond /Users/alex/Projects/Transparensee /Users/alex/Projects /Users/alex /Users /]
INFO [config_reader] Config search paths: [./ /Users/alex/Projects/Transparensee/pond /Users/alex/Projects/Transparensee /Users/alex/Projects /Users/alex /Users /]
INFO [lintersdb] Active 1 linters: [govet]
INFO [load/path_resolver] Skipped dirs: [.git .vscode]
INFO [load/path_resolver] Paths resolving took 212.852477ms: [blobstore blobstore/filestore blobstore/gcs blobstore/mocks cmd/pond cmd/pondctl e2e pkg/client proto proto/mocks server server server/database server/database/mocks utils]
INFO [load] Can't get cur project path: currently no in gopath: "/Users/alex/.go" isn't a prefix of "/Users/alex/Projects/Transparensee/pond"
INFO [load] Program loading took 6.151314387s
INFO [load] Not compiling packages: [./server_test ./cmd/pondctl ./server ./proto github.com/stretchr/testify/require github.com/gogo/protobuf/types github.com/stretchr/testify/mock github.com/t11e/pond/server go.uber.org/zap github.com/gogo/protobuf/gogoproto google.golang.org/grpc github.com/spf13/cobra google.golang.org/grpc/status github.com/jackc/pgx cloud.google.com/go/storage google.golang.org/grpc/metadata github.com/stretchr/testify/assert github.com/t11e/pond/proto]
INFO [runner] worker.1 took 152.927µs
INFO [runner] worker.6 took 247.58µs
INFO [runner] worker.2 took 267.053µs
INFO [runner] worker.5 took 246.144µs
INFO [runner] worker.8 took 287.753µs
INFO [runner] worker.3 took 237.41µs
INFO [runner] worker.4 took 328.038µs
INFO [runner] worker.7 took 14.485719ms with stages: govet: 14.195536ms
INFO [runner] Workers idle times: #1: 13.961513ms, #2: 13.944989ms, #3: 13.925121ms, #4: 13.910302ms, #5: 13.938923ms, #6: 13.955198ms, #8: 13.930439ms
INFO [runner] processing took 3.138µs with stages: max_same_issues: 741ns, path_prettifier: 605ns, cgo: 255ns, diff: 243ns, autogenerated_exclude: 237ns, nolint: 235ns, max_from_linter: 200ns, exclude: 175ns, uniq_by_line: 123ns, skip_files: 111ns, source_code: 110ns, max_per_file_from_linter: 103ns
INFO Memory: 53 samples, avg is 277.0MB, max is 406.4MB
INFO Execution took 6.382269647s
/usr/local/bin/golangci-lint run --disable-all --enable=govet  --tests -v  18.78s user 14.14s system 501% cpu 6.558 total

Plain go vet:

$ time go vet github.com/t11e/pond/...
go vet github.com/t11e/pond/...  1.28s user 1.06s system 217% cpu 1.073 total

Environment:

$ golangci-lint --version
golangci-lint has version 1.10.1 built from c37ad66 on 2018-08-27T20:41:14Z

go version && go env
go version go1.11 darwin/amd64
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/alex/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/alex/.go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/opt/go/libexec"
GOTMPDIR=""
GOTOOLDIR="/usr/local/opt/go/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/alex/Projects/Transparensee/pond/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/qs/wpmg19r12_9_nz7pvvs2_82r0000gn/T/go-build299194979=/tmp/go-build -gno-record-gcc-switches -fno-common"

[jirfag]

hi!
try option use-installed-packages: true in .golangci.yml, example is here

[atombender]

Thanks, that solves it. I wonder what the purpose of having this default by false?

[jirfag]

it's false by default because this option makes sense only when we don't launch any slow linters, e.g. run only govet. In other cases this option slows down things.
And running only govet isn't a typical use-case for golangci-lint: for this purpose you can just run go vet as standalone tool.

[atombender]

I see. I don't ever run with just govet, but I noticed it was a linter that was particularly slow compared to running it manually.

What's interesting is that use-installed-packages: true seems to affect behaviour when running with Go 1.11 modules; it skips a bunch of files due to import problems:

WARN [runner] Can't run linter govet: can't run govet on installed packages: can't typecheck package: /Users/alex/Projects/Transparensee/extro/cmd/createtest/main.go:7:10: could not import golang.org/x/net/context (can't find import: golang.org/x/net/context)|/Users/alex/Projects/Transparensee/extro/cmd/createtest/main.go:9:2: could not import github.com/jackc/pgx (can't find import: github.com/jackc/pgx)|/Users/alex/Projects/Transparensee/extro/cmd/createtest/main.go:10:8: could not import github.com/jessevdk/go-flags (can't find import: github.com/jessevdk/go-flags)|/Users/alex/Projects/Transparensee/extro/cmd/createtest/main.go:11:2: could not import github.com/pkg/errors (can't find import: github.com/pkg/errors)|/Users/alex/Projects/Transparensee/extro/cmd/createtest/main.go:13:2: could not import github.com/t11e/extro/database (can't find import: github.com/t11e/extro/database)

Is this a problem with vet, or golangci-lint?

[atombender]

(I notice that a bunch of linters, like typecheck and megacheck, also don't understand Go modules.)

[jirfag]

it will be solved by #178

[aaronlehmann]

I'm experiencing this same problem with golangci-lint 1.18.0, but it seems like the use-installed-packages flag no longer exists. Is there a current solution to the problem?

[jirfag]

Hi @aaronlehmann , thank you!

1. Do you run only govet in golangci-lint? why if yes?
2. I've reduced govet work time by 25% on this repo in Speed up packages loading #693.
3. I'll continue researching work time difference

[aaronlehmann]

Do you run only govet in golangci-lint? why if yes?

Normally I run many linters, but performance was a lot slower than gometalinter, and I tracked down the difference to go vet.

Here are some benchmarks showing what I mean:

$ time go vet ./...

real    0m17.862s
user    1m43.516s
sys     0m22.268s
$ time go vet ./...

real    0m5.302s
user    0m21.332s
sys     0m11.820s
$ time golangci-lint run

real    0m32.683s
user    1m7.324s
sys     2m39.892s
$ time golangci-lint run

real    0m34.040s
user    1m9.764s
sys     2m47.400s

$ go version
go version go1.13 linux/amd64
$ golangci-lint --version
golangci-lint has version v1.18.1-0.20190911144626-bf67a3eef3ec built from (unknown, mod sum: "h1:2hgPZ5e/Xx5qznnizFOYiiau5hz9rwpnE0Se0d3wasU=") on (unknown)

It's interesting to me that the "system" time is so high.

Here is my .golangci.yml:

run:
  skip-dirs:
    - lookups
  modules-download-mode: vendor
  deadline: 20m

linters-settings:
  govet:
    check-shadowing: false
    settings:
      printf:
        funcs:
          - (github.com/blueowldev/backend/logger.RequestLog).Infof
          - (github.com/blueowldev/backend/logger.RequestLog).Tracef
          - (github.com/blueowldev/backend/logger.RequestLog).Errorf
          - (github.com/blueowldev/backend/logger.RequestLog).Alertf

linters:
  # inverted configuration with `enable-all` and `disable` is not scalable during updates of golangci-lint
  disable-all: true
  enable:
    - govet
issues:
  max-same-issues: 0
  exclude-rules:
    - text: "weak cryptographic primitive"
      linters:
        - gosec
    - text: "Rollback` is not checked"
      linters:
        - errcheck
    - text: "StopAll` is not checked"
      linters:
        - errcheck
    # scopelint breaks on this file for some reason
    - path: billing/billcore/generate.go
      linters:
        - scopelint
    # SQL injection is not a concern inside migrations or tests
    - path: migrate.go
      linters:
        - gosec
    - path: _test.go
      linters:
        - gosec

I've reduced govet work time by 25% on this repo in #693.

This made a big difference!

$ time golangci-lint run
real    0m9.965s
user    0m22.556s
sys     0m30.876s

golangci-lint has version v1.18.1-0.20190914154818-c9a92552385e built from (unknown, mod sum: "h1:oiCHfLWXxKdZAHrNK0uOpiCkqfq/wESZUrNTAuf54To=") on (unknown)

Thank you for looking into this. I consider the issue resolved.

[aaronlehmann]

I'm not sure if it's because of the same change, but peak memory use also seems much lower now. I'm seeing about 3.2 GB, instead of 9 GB before I upgraded.

[jirfag]

If you are running only govet the time difference can be huge. But if you will run many linters times should be similar

[jirfag]

It was finally fixed by using go/analysis facts caching in #699

[aaronlehmann]

#699 seems to have made things a lot slower.

Before:

real    0m26.390s
user    1m9.332s
sys     0m45.512s

After:

real    1m5.048s
user    3m11.196s
sys     3m29.260s

The first run with the new version was even slower (at least a few minutes), but I didn't manage to capture the timing. Also, memory use is much higher than before. On the first run, I saw it using 15 GB, up from 3.2 GB before.

Is there any way to turn offf the facts caching?

[jirfag]

@aaronlehmann
Please, try the latest version v1.20.0 - speed increased a lot.

I will reopen the issue if it still exists.

[aaronlehmann]

v1.20.0 seems to be only slightly slower than c9a9255, which I was using before (not dramatically slower like just after #699).

With v1.20.0 I'm seeing a lot of strange failures that I can't reliably reproduce like WARN [runner] Can't run linter goanalysis_metalinter: fact_purity: failed prerequisites: buildssa@<redacted> [<redacted>]. Sometimes one run will fail that way, and the next run, with no changes to the source code, will work fine.

[jirfag]

Good, please make a new issue about these warnings