dominikh / go-tools

Staticcheck - The advanced Go linter
https://staticcheck.dev
MIT License
6.24k stars 377 forks source link

Package loading time in Go 1.10.x #377

Closed klauspost closed 5 years ago

klauspost commented 5 years ago

I seem to have an interesting issue where running the checked is extremely slow and CPU is pegged at 100% on one core.

klaus@ubuntu:~/gopath/src/user/package$ staticcheck --debug.print-stats github.com/user/package/...
Package loading: 1h38m31.454171864s
SSA build: 21.67682346s
Other init work: 6.817053264s
Checker inits:
        gosimple: 5.939782ms
        staticcheck: 6.580565926s
        stylecheck: 3.011µs
        unused: 308ns

Jobs:
        SA1023: 605.955µs
        ST1008: 2.835215ms
        SA5007: 12.190218ms
        SA4019: 740.066374ms
        SA5000: 788.664339ms
        SA4016: 1.341984904s
        ST1001: 1.548734657s
        SA2002: 1.751419466s
        SA4012: 1.980239895s
        SA6001: 3.151521396s
        SA4013: 3.616790341s
        SA4002: 3.741031528s
        S1020: 4.209893928s
        SA1013: 4.7203341s
        SA3001: 4.757165187s
        SA5004: 4.79783047s
        S1023: 4.847563802s
        SA1010: 4.898477989s
        SA4001: 4.92993824s
        S1010: 5.170548174s
        SA5002: 5.191772116s
        ST1015: 5.227913934s
        SA4011: 5.260503075s
        S1000: 5.506765333s
        SA4010: 5.602958172s
        SA4015: 5.635165478s
        SA6003: 5.826837105s
        S1006: 6.026174231s
        S1029: 6.288058228s
        S1017: 6.521211728s
        S1005: 6.657113216s
        SA1003: 7.166001256s
        SA4008: 8.185722499s
        SA1020: 8.47647566s
        SA6002: 9.123205597s
        SA1017: 10.400495305s
        SA6000: 11.090975882s
        SA1025: 11.55688655s
        SA5005: 12.273645941s
        SA2000: 12.657624433s
        SA1007: 12.86456794s
        SA4006: 14.983973684s
        SA1021: 15.570106172s
        ST1006: 19.799175166s
        SA1018: 19.7997434s
        SA3000: 19.806420248s
        SA2003: 20.006151449s
        S1021: 20.17263736s
        SA1024: 20.319294594s
        SA1011: 20.714653373s
        SA5003: 22.834504023s
        SA1002: 23.611794013s
        S1018: 23.82204222s
        SA1014: 24.237042124s
        SA1000: 25.042900226s
        SA6005: 29.890880858s
        S1008: 30.267773032s
        S1004: 30.617342398s
        ST1016: 31.025323399s
        S1009: 31.761876835s
        ST1012: 32.49133553s
        S1011: 33.264634843s
        SA9004: 34.480512655s
        S1001: 35.164602355s
        S1019: 36.734606891s
        SA1008: 37.6376481s
        SA9001: 37.677980421s
        SA4004: 38.47965889s
        S1030: 39.069030457s
        S1012: 39.084799926s
        S1016: 39.434007962s
        SA5001: 39.451987822s
        S1031: 39.666953149s
        S1002: 40.197963098s
        ST1011: 40.207626479s
        SA2001: 40.388245786s
        SA1012: 40.413728705s
        SA1016: 40.58124205s
        S1003: 40.626086764s
        SA4003: 40.691722167s
        S1028: 40.739847559s
        S1025: 40.829009563s
        ST1003: 40.984717091s
        ST1013: 40.990694135s
        SA1019: 41.040898529s
        S1024: 41.081448598s
        SA4018: 41.093339685s
        SA9002: 41.156389751s
        SA4000: 41.299867621s
        SA4014: 41.333049609s
        SA1001: 41.433742272s
        SA1015: 41.439050706s
        SA1006: 41.534056007s
        SA1005: 41.571696853s
        SA1004: 41.742200385s
        S1032: 41.787982319s
        S1007: 41.80344573s
        SA9003: 41.851629245s
        ST1005: 42.379658152s
        ST1000: 42.523186901s
        SA4009: 42.574494452s
        SA4017: 43.139778791s
        U1000: 45.419632247s
        Total: 39m54.325734682s

klaus@ubuntu:~/gopath/src/honnef.co/go/tools$ git cat-file commit HEAD
tree 822824557d88c8751120de337fdc352f5d58d041
parent 17562b81b08373b3b11be787d2cf278102bce55d

klaus@ubuntu:~/gopath/src/honnef.co/go/tools$ go version
go version go1.10.4 linux/amd64
klaus@ubuntu:~/gopath/src/honnef.co/go/tools$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/klaus/.cache/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/klaus/gopath"
GORACE=""
GOROOT="/usr/local/go"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build804420424=/tmp/go-build -gno-record-gcc-switches"

It seems the times in Jobs doesn't add up to the total, and obviously the 1½ hour loading time seems a bit much. It is a big package with lots of dependencies, but this does seem a bit excessive.

I restarted with --debug.cpuprofile="profile.cpu" to get a profile, but obviously it will take a while before the results are available.

dominikh commented 5 years ago

A couple of things.

1) the job times only really make sense with -debug.max-concurrent-jobs=1, since otherwise many jobs run in parallel, and scheduling noise dominates the numbers. But job times are somewhat irrelevant with a 1h package loading time... 2) is there any chance to get access to said package? I'm happy to handle this privately, too. 3) More useful statistics to collect: 1) the number of packages you're trying to check (go list github.com/user/package/... | wc -l) 2) the number of lines of code in the packages combined (cloc, but even plain wc -l will do; I'm just looking for a rough guide on size) 4) do any of the packages use cgo? 5) can you reproduce the same kind of performance with staticcheck 2017.2, assuming you're not using Go modules.

klauspost commented 5 years ago
  1. No, and there are 6 cores, so GOMAXPROCS should be 6.

  2. Not easily, unfortunately.

  3. Packages: 288. LOC using gocloc

    -------------------------------------------------------------------------------
    Language                     files          blank        comment           code
    -------------------------------------------------------------------------------
    Go                            2159          36557          36160         263178
  4. Yes - 2 cgo packages. Interesting, disabling them seems to cause a crash:

    
    klaus@ubuntu:~/gopath/src/github.com/user/package$ env CGO_ENABLED=0 staticcheck --debug.print-stats github.com/user/package/...
    panic: runtime error: invalid memory address or nil pointer dereference
    [signal SIGSEGV: segmentation violation code=0x1 addr=0x8 pc=0x633c0a]

goroutine 1 [running]: golang.org/x/tools/go/packages.createTestVariants.func1(0x0, 0xc4214eaf80) /home/klaus/gopath/src/golang.org/x/tools/go/packages/golist_fallback.go:260 +0x6a golang.org/x/tools/go/packages.createTestVariants.func1(0xc420a3ce00, 0xc4214eaf80) /home/klaus/gopath/src/golang.org/x/tools/go/packages/golist_fallback.go:264 +0x179 golang.org/x/tools/go/packages.createTestVariants.func1(0xc42101e7e0, 0xc4214eaf80) /home/klaus/gopath/src/golang.org/x/tools/go/packages/golist_fallback.go:264 +0x179 golang.org/x/tools/go/packages.createTestVariants.func1(0xc42102b420, 0xc4214eaf80) /home/klaus/gopath/src/golang.org/x/tools/go/packages/golist_fallback.go:264 +0x179 golang.org/x/tools/go/packages.createTestVariants.func1(0xc421040380, 0xc4200ecf80) /home/klaus/gopath/src/golang.org/x/tools/go/packages/golist_fallback.go:264 +0x179 golang.org/x/tools/go/packages.createTestVariants(0xc4200adf00, 0xc42109efc0, 0xc4210bf880) /home/klaus/gopath/src/golang.org/x/tools/go/packages/golist_fallback.go:293 +0x389 golang.org/x/tools/go/packages.golistDriverFallback(0xc4201370e8, 0xc42005ce10, 0x1, 0x1, 0x0, 0x9f6240, 0xc42005ce00) /home/klaus/gopath/src/golang.org/x/tools/go/packages/golist_fallback.go:245 +0x76a golang.org/x/tools/go/packages.goListDriver.func2(0xc4201370e8, 0xc42005cd90, 0x1, 0x1, 0xffffffffffffffff, 0x1, 0x20) /home/klaus/gopath/src/golang.org/x/tools/go/packages/golist.go:133 +0xce golang.org/x/tools/go/packages.goListDriver(0xc4201370e8, 0xc42009e080, 0x1, 0x1, 0xc4201370e0, 0xc420137110, 0xc420137140) /home/klaus/gopath/src/golang.org/x/tools/go/packages/golist.go:144 +0xa7b golang.org/x/tools/go/packages.defaultDriver(0xc4201370e8, 0xc42009e080, 0x1, 0x1, 0xc018a130dcb, 0xc42f76af1d, 0x2f76af1d004455c7) /home/klaus/gopath/src/golang.org/x/tools/go/packages/packages.go:187 +0x68 golang.org/x/tools/go/packages.Load(0xc42006b830, 0xc42009e080, 0x1, 0x1, 0x0, 0x98a94a, 0x6, 0xc5d800, 0xc42006b770) /home/klaus/gopath/src/golang.org/x/tools/go/packages/packages.go:172 +0x6f honnef.co/go/tools/lint/lintutil.Lint(0xc420078360, 0x4, 0x6, 0xc42009e080, 0x1, 0x1, 0xc4214ebe30, 0x410443, 0x8f8c00, 0x8c8880, ...) /home/klaus/gopath/src/honnef.co/go/tools/lint/lintutil/util.go:277 +0x2a0 honnef.co/go/tools/lint/lintutil.ProcessFlagSet(0xc420078360, 0x4, 0x6, 0xc420078300) /home/klaus/gopath/src/honnef.co/go/tools/lint/lintutil/util.go:178 +0x99b main.main() /home/klaus/gopath/src/honnef.co/go/tools/cmd/staticcheck/staticcheck.go:29 +0x2f2



`golang.org/x/tools` is on current master version - 7ed362c6fe3859189faff523eff147ddafcc9177

5. I am still running the profiler, so I'll get back to you with that info when it is done.
klauspost commented 5 years ago

I guess it is the golang.org/x/tools since you are only doing packages.Load in that time. I will dig a bit myself as well.

klauspost commented 5 years ago

Maybe it is related to this: https://github.com/golang/tools/blob/master/go/packages/golist_fallback.go#L24

It claims to be for "versions of Go earlier than 1.10.4", however it obviously gets called for 1.10.4 - I will try cleaning pkg files, since it could be old stuff picked up there. Still waiting for the CPU profile to complete before I can test more.

klauspost commented 5 years ago

cpu

klauspost commented 5 years ago

Upgrading to Go 1.10.7, recompiling and removing pkg doesn't appear to make much of a difference. :/

klauspost commented 5 years ago

Related/caused by https://github.com/golang/go/issues/29427 ?

klauspost commented 5 years ago

~ok the CGO_ENABLED crash is caused by an empty package.~ Seems the cgo issue is fixed in Go 1.11, but still crashes with Go 1.10.7 :(

Without cgo, runtime is about a minute.

Maybe adding a note to resource-usage about disabling cgo would be a good idea.

klauspost commented 5 years ago

Created an issue for the cgo crash: https://github.com/golang/go/issues/29505 - not sure if that'll be fixed - I'll have to see if I can get our org to upgrade to Go 1.11 ;)

klauspost commented 5 years ago

Disabling tests --tests=false seems to be a workaround, but of course "U1000" tests reports some "unused" functions that are only used by tests.

Nothing much you can do, it seems to be mainly a problem in packages package, but some docs would probably be good.

heschi commented 5 years ago

I'm not totally convinced that this is https://golang.org/issue/29427. Please run staticcheck with GOPACKAGESDEBUG=1. That will print a few go list commands and timing information to stderr. Take the slowest and run it with -x to see what's taking so long.

How long does it take to build your package (and its dependencies) with a clean cache? Does it contain massive amounts of autogenerated code? The profile above shows 10 minutes of CPU time dealing with the result of go list, which is pretty crazy.

@matloob

klauspost commented 5 years ago

Please run staticcheck with GOPACKAGESDEBUG=1.

I don't have the code right now, but running it and excluding the tests takes ~20 seconds. Should I just run it normally with cgo and only the env variable set?

How long does it take to build your package (and its dependencies) with a clean cache?

Around 10-15 seconds.

Does it contain massive amounts of autogenerated code?

No.

heschi commented 5 years ago

Can you get a new profile with tip x/tools? The profile you posted makes no sense; it has functions making calls that they've never made, like loadPackage calling runNamedQueries.

klauspost commented 5 years ago

I just found out why the analysis numbers are so weird. It is because the VM is swapping when doing the analysis and including tests. It crashed twice and I'm now running it without anything else running on the VM. If this crashes again, I'll increase the memory for the VM:

This is the memory use once analysis starts:

analysis

top

Go 1.11 does not use nearly as much memory.

Edit: Yeah, crashed again, giving the VM 11GB memory and re-running.

matloob commented 5 years ago

Maybe it is related to this: https://github.com/golang/tools/blob/master/go/packages/golist_fallback.go#L24

It claims to be for "versions of Go earlier than 1.10.4", however it obviously gets called for 1.10.4 - I will try cleaning pkg files, since it could be old stuff picked up there. Still waiting for the CPU profile to complete before I can test more.

The comment is clearly wrong, and I've sent a change to fix it. We thought we'd be able to backport the go list behavior we needed to 1.10.4 from 1.11 but it was infeasible.

FYI, as noted in that comment, go/packages will stop supporting Go 1.10 once Go 1.12 is released.

dominikh commented 5 years ago

Have we come to any conclusion on this issue? Are there any fixes in go/packages or a Go 1.10.x that improved the performance?

matloob commented 5 years ago

I haven't made any changes in the fallback that could have improved it.

Let me do some research and report back later today if we can get a quick win. But given that we'll be deleting the 1.10 support code when 1.12 is released in (hopefully less than) ~1 month, I don't think it's worth making heavy investment here.

dominikh commented 5 years ago

But given that we'll be deleting the 1.10 support code when 1.12 is released in (hopefully less than) ~1 month, I don't think it's worth making heavy investment here.

That doesn't stop people from using an old revision of the code, in case they're stuck with Go 1.10. There is a shocking amount of people stuck on old versions of Go.

Of course "upgrade already!" is a very valid argument, too.

matloob commented 5 years ago

That's true, it's hard to find the right balance...

dmitshur commented 5 years ago

"Upgrade if you want better performance" is a good motivator to upgrade.

dominikh commented 5 years ago

@dmitshur except people upgraded staticcheck and got worse staticcheck performance because we started using go/packages ;)

klauspost commented 5 years ago

Yeah, it is of little use. With tests enabled it oom after loading for about 2 hours. I suspect the weird times in the initial run was because of swapping. I have been unable to complete a run since then.

It may be easy for you to upgrade, but in a production environment an upgrade is always that simple.

matloob commented 5 years ago

Summary: if there are any ideas for what we can do to improve 1.10.x performance, I'd like to hear them. Otherwise, I think of the bug in go/packages as being "unfortunate".

Unfortunately, based on the information we have, it's hard to tell where the slowness is. The fallback is going to be slower than the 1.11 logic, and we won't be able to change that without doing (what I believe is too much work). If there are problems or bugs in the 1.10.x fallback logic where we're doing unnecessary work that can be identified, I'll certainly look into whether those problems are feasible to fix.

I'm hoping that users who can't upgrade to 1.11+ will be able to use old versions of the tools, which continue to work. But if we've dug users into a hole where the old and new tool versions don't work, we'd like to know about it.

Edit: first paragraph

dominikh commented 5 years ago

@klauspost can you compare memory usage between 1.10 and 1.11 and provide concrete numbers? That may help determine if it's unfortunate performance or a bug. If it's "just" a 2x difference, and all the timing information can be explained by swapping and thrashing, then we're probably just well advised to mark 2019.1 as "Go 1.11 only"

@matloob All the tools I know about, certainly staticcheck, have old versions that don't use go/packages and work with 1.10. So at least there's no hole.

matloob commented 5 years ago

@dominikh Thanks for the info, good to know there isn't a hole.

klauspost commented 5 years ago

It crashed with 18gb ram. I am away from my computer, but 1.11 was around an order of magnitude less IIRC.

On Fri, 25 Jan 2019, 00:05 Dominik Honnef <notifications@github.com wrote:

@klauspost https://github.com/klauspost can you compare memory usage between 1.10 and 1.11 and provide concrete numbers? That may help determine if it's unfortunate performance or a bug. If it's "just" a 2x difference, and all the timing information can be explained by swapping and thrashing, then we're probably just well advised to mark 2019.1 as "Go 1.11 only"

@matloob https://github.com/matloob All the tools I know about, certainly staticcheck, have old versions that don't use go/packages and work with 1.10. So at least there's no hole.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/dominikh/go-tools/issues/377#issuecomment-457392094, or mute the thread https://github.com/notifications/unsubscribe-auth/AFZs0HqsoQEsvuq-oVcAWoEtGgiCtFURks5vGjwqgaJpZM4Zmnib .

dominikh commented 5 years ago

With Go 1.12 released, the removal of 1.10 support is around the corner. I'm afraid we're not going to see any more improvements for 1.10…

I'm going to close this issue, hoping that we won't ever run into an issue like this again.