Closed as not planned
Description
What version of Go are you using (go version
)?
$ go version go version go1.19.1 linux/amd64
Does this issue reproduce with the latest release?
Yes
What operating system and processor architecture are you using (go env
)?
go env
Output
$ go env GO111MODULE="" GOARCH="amd64" GOBIN="" GOCACHE="/home/thockin/.cache/go-build" GOENV="/home/thockin/.config/go/env" GOEXE="" GOEXPERIMENT="" GOFLAGS="" GOHOSTARCH="amd64" GOHOSTOS="linux" GOINSECURE="" GOMODCACHE="/home/thockin/src/go/pkg/mod" GONOPROXY="" GONOSUMDB="" GOOS="linux" GOPATH="/home/thockin/src/go" GOPRIVATE="" GOPROXY="https://proxy.golang.org,direct" GOROOT="/usr/local/go" GOSUMDB="sum.golang.org" GOTMPDIR="" GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64" GOVCS="" GOVERSION="go1.19.1" GCCGO="gccgo" GOAMD64="v1" AR="ar" CC="gcc" CXX="g++" CGO_ENABLED="1" GOMOD="/tmp/opt/go.mod" GOWORK="" 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 -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build991974462=/tmp/go-build -gno-record-gcc-switches"
What did you do?
Using github.com/go-logr/logr, I ran a benchmark that shows an optimization that is missing. In fact, we wrote the code this way because Russ et al said this optimization could be done in future, so this is not so much a bug report as it is a feature request.
Here is the benchamark:
package main
import (
"testing"
"github.com/go-logr/logr"
)
//go:noinline
func doV9(b *testing.B, log logr.Logger) {
b.ReportAllocs()
for i := 0; i < b.N; i++ {
log.V(9).Info("multi",
"bool", true, "string", "str", "int", 42,
"float", 3.14, "struct", struct{ X, Y int }{93, 76})
}
}
//go:noinline
func doManualV9(b *testing.B, log logr.Logger) {
b.ReportAllocs()
for i := 0; i < b.N; i++ {
// This manual optimization should not be needed?
if logV := log.V(9); logV.Enabled() {
logV.Info("multi",
"bool", true, "string", "str", "int", 42,
"float", 3.14, "struct", struct{ X, Y int }{93, 76})
}
}
}
// This is a simple repro all in one package.
type Repro struct {
enabled bool
}
//go:noinline
func (r Repro) Info(msg string, keysAndValues ...interface{}) {
// It looks like the slice allocation is elided?
if r.enabled {
r.Impl(msg, keysAndValues...)
}
}
//go:noinline
func (r Repro) Impl(_ string, _ ...interface{}) {
panic("this should not get called")
}
//go:noinline
func doLocalRepro(b *testing.B, repro Repro) {
b.ReportAllocs()
for i := 0; i < b.N; i++ {
repro.Info("multi",
"bool", true, "string", "str", "int", 42,
"float", 3.14, "struct", struct{ X, Y int }{93, 76})
}
}
func BenchmarkLocalReproDisabled(b *testing.B) {
r := Repro{false}
doLocalRepro(b, r)
}
func BenchmarkDiscardV9(b *testing.B) {
var log logr.Logger = logr.Discard()
doV9(b, log)
}
func BenchmarkDiscardManualV9(b *testing.B) {
var log logr.Logger = logr.Discard()
doManualV9(b, log)
}
What did you expect to see?
I expected all cases to show 0 allocations. It should be able to see that the variadic slice is only used if the log-level is enabled, and thereby elide the whole thing. It seems that works within a package but not across packages.
What did you see instead?
Allocations where they are not needed.
BenchmarkLocalReproDisabled-6 100000000 10.12 ns/op 0 B/op 0 allocs/op
BenchmarkDiscardV9-6 15072631 79.46 ns/op 176 B/op 2 allocs/op
BenchmarkDiscardManualV9-6 552702112 2.008 ns/op 0 B/op 0 allocs/op
cc @pohly