Description
TestIntendedInlining has been failing occasionally, for example here, with a report of functions not being inlined:
inl_test.go:273: math/big.addVW was not inlined: unknown reason
inl_test.go:273: math/big.subVW was not inlined: unknown reason
inl_test.go:273: math/big.bigEndianWord was not inlined: unknown reason
Unless the compiler is somehow nondeterministic (unlikely), this looks like a glitch in the test itself.
The test works by running go build -a '-gcflags=all=-m -m' packages..., and parsing the 8+ megabytes of output to look for some expected messages about function inlining. After modifying the test to tee the piped output into a strings.Builder, to be logged if the test fails, we can see what's going on:
... line 54312
# net
../../../../net/cgo_stub.go:11:6: can inline init.0 with cost 3 as: func() { netGo = true }
... line 57070
../../../../net/dial.go:628:15: from &OpError{...} (interface-converted) at ../../../../net/dial.go:628:15
../../../../net/dial.go:628:15: from return nil, &OpError{...} (return) at ../../../../ne# math/big
../../../../math/big/accuracy_string.go:11:6: cannot inline Accuracy.String: function too complex: cost 90 exceeds budget 80
... line 57843
../../../../math/big/nat.go:1t/dial.go:628:3
../../../../net/dial.go:625:53: parameter network leaks to {storage for &OpError{...}} with derefs=0:
../../../../net/dial.go:625:53: flow: {storage for &OpError{...}} = network:
... line 58575
../../../../net/hook.go:21:3: lea240:16: inlining call to nat.make
../../../../math/big/int.go:1211:6: can inline (*Int).Sqrt with cost 78 as: method(*Int) func(*Int) *Int { if x.neg { panic("square root of negative number") }; z.neg = false; z.abs = nat.sqrt(z.abs, x.abs); return z }
... and so on
It seems the output from parallel builds is being interleaved. In line 57071, the label for the start of output for package math/big interrupts a partial line from package net, so the parser doesn't recognise the label and misses the inlining messages from math/big.
The Builder struct has a mutex which is supposed to prevent interleaving of output. For example in cmd/go/internal/work/exec.go we see:
func (b *Builder) Showcmd(dir string, format string, args ...interface{}) {
b.output.Lock()
defer b.output.Unlock()
b.Print(b.fmtcmd(dir, format, args...) + "\n")
}
But it turns out that the lock is not being applied consistently. In cmd/go/internal/work/buildid.go we see:
func (b *Builder) flushOutput(a *Action) {
b.Print(string(a.output))
a.output = nil
}
Two possible remedies come to mind:
(a) do the Lock/Unlock inside the (*Builder).Print function itself to ensure it's always used, or
(b) lock the mutex around any calls to Print which could produce an arbitrary amount of output (in particular, more than the limit for atomic writes to a pipe).
Choosing (a) would involve more locking than strictly necessary, so I'll submit a CL to do (b).