Go-tools: Package loading time in Go 1.10.x
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.
klauspost
All 27 comments
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.
dominikh
on 2 Jan 2019
- No, and there are 6 cores, so GOMAXPROCS should be 6.
- Not easily, unfortunately.
- Packages:
288. LOC using gocloc
Language files blank comment code
-------------------------------------------------------------------------------
Go 2159 36557 36160 263178
- 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
- I am still running the profiler, so I'll get back to you with that info when it is done.
klauspost
on 2 Jan 2019
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
on 2 Jan 2019
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
on 2 Jan 2019
klauspost
on 2 Jan 2019
Upgrading to Go 1.10.7, recompiling and removing pkg doesn't appear to make much of a difference. :/
klauspost
on 2 Jan 2019
Related/caused by https://github.com/golang/go/issues/29427 ?
klauspost
on 2 Jan 2019
~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
on 2 Jan 2019
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
on 2 Jan 2019
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.
klauspost
on 2 Jan 2019
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
heschi
on 2 Jan 2019
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.
klauspost
on 2 Jan 2019
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.
heschi
on 3 Jan 2019
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:
Go 1.11 does not use nearly as much memory.
Edit: Yeah, crashed again, giving the VM 11GB memory and re-running.
klauspost
on 8 Jan 2019
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
pkgfiles, 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.
matloob
on 8 Jan 2019
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?
dominikh
on 23 Jan 2019
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.
matloob
on 23 Jan 2019
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.
dominikh
on 23 Jan 2019
That's true, it's hard to find the right balance...
matloob
on 23 Jan 2019
"Upgrade if you want better performance" is a good motivator to upgrade.
dmitshur
on 23 Jan 2019
@dmitshur except people upgraded staticcheck and got worse staticcheck performance because we started using go/packages ;)
dominikh
on 23 Jan 2019
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.
klauspost
on 23 Jan 2019
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
matloob
on 24 Jan 2019
@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.
dominikh
on 25 Jan 2019
@dominikh Thanks for the info, good to know there isn't a hole.
matloob
on 25 Jan 2019
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 <[email protected] 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
.
klauspost
on 25 Jan 2019
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.
dominikh
on 15 Mar 2019
Related issues
stamm
·
4Comments
dominikh
·
3Comments
axcdnt
·
3Comments
tonyghita
·
4Comments
igungor
·
3Comments
Most helpful comment
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.