logging: too slow Logger on non GCE environment

[ukai]

Client

logging

Environment

desktop machine

Go Environment

$ go version
go version go1.22.4 linux/amd64

$ go env
GO111MODULE='on'
GOARCH='amd64'
GOBIN='/usr/local/google/home/ukai/src/infra/infra/go/bin'
GOCACHE='/usr/local/google/home/ukai/src/infra/infra/go/golang/gocache'
GOENV='/usr/local/google/home/ukai/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMODCACHE='/usr/local/google/home/ukai/src/infra/infra/go/golang/modcache'
GONOPROXY='*.googlesource.com,*.git.corp.google.com,google.com'
GONOSUMDB='*.googlesource.com,*.git.corp.google.com,google.com'
GOOS='linux'
GOPATH='/usr/local/google/home/ukai/go'
GOPRIVATE='*.googlesource.com,*.git.corp.google.com,google.com'
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/usr/local/google/home/ukai/src/infra/infra/go/golang/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='local'
GOTOOLDIR='/usr/local/google/home/ukai/src/infra/infra/go/golang/go/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.22.4'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='gcc'
CXX='g++'
CGO_ENABLED='1'
GOMOD='/usr/local/google/home/ukai/src/infra/infra/go/src/go.chromium.org/luci/go.mod'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build1645801680=/tmp/go-build -gno-record-gcc-switches'

Code

https://chromium.googlesource.com/infra/infra/+/refs/heads/main/go/src/infra/build/siso/o11y/clog/clog.go#54

Expected behavior

Logger finishes soon.

Actual behavior

Logger takes 7.31s

Screenshots

Additional context

e.g. Started after upgrading to v0.50.0.

[ukai]

can't we skip detectResource if CommonResource LoggerOption is used?

[gkevinzheng]

@ukai I'm interested in what's taking detectResource a long time. Is it because it's trying to hit the metadata server?

[ukai]

I think so, as it shows in trace. metadata.(*Client).Get -> metadata.(*Cilent).getETag -> metadata.sleep ?

[gkevinzheng]

Yeah, if you're running this on a non GCP environment the retries from querying the metadata server for automatic resource detection will make Logger really slow.

[gannett-ggreer]

I have the same issue trying to use GCS with the library locally on my Mac. I had to do this to get the non-GCE code (specifically this test: https://github.com/googleapis/google-cloud-go/blob/compute/metadata/v0.3.0/compute/metadata/metadata.go#L123-L189) to not take forever:

route add -host 169.254.169.254 127.0.0.1
echo "127.0.0.1 metadata.google.internal." >> /etc/hosts

Before:

FAIL	github.com/re/da/ct/ed	224.089s

After:

FAIL	github.com/re/da/ct/ed	3.102s

(Caveat: the blocking trace actually points to the ProjectID() call at golang.org/x/oauth2/google.FindDefaultCredentialsWithParams but that would mean OnGCE() returned true, and that shouldn't have happened on my Mac.)

Our tests re-instantiate the client for every test case (because we're using record/replay) so even a 5 second timeout is painful. We keep the default credentials call enabled because we use GOOGLE_APPLICATION_CREDENTIALS when recording.