Skip to content

Commit

Permalink
fix: reduce memory allocations (logger)
Browse files Browse the repository at this point in the history 
Rework the gRPC logger by using hand-rolled simple version, rework
version parsing to remove regexp matching.

The baseline (via benchmark):

```
BenchmarkViaClientSimulator-32    	    2934	    387398 ns/op	  101921 B/op	     832 allocs/op
```

The baseline + removed logging middleware:

```
BenchmarkViaClientSimulator-32    	    3543	    331166 ns/op	   73581 B/op	     543 allocs/op
```

Reworked logging middleware:

```
BenchmarkViaClientSimulator-32    	    3394	    334066 ns/op	   77985 B/op	     568 allocs/op
```

Plus reworked version parsing:

```
BenchmarkViaClientSimulator-32    	    3510	    325714 ns/op	   66215 B/op	     561 allocs/op
```

So overall, baseline to this PR:

* allocs 101921 -> 66215 B/op
* alloc ops 832 -> 561 allocs/op

Signed-off-by: Andrey Smirnov <[email protected]>
  • Loading branch information
@smira
smira committed Oct 22, 2024
1 parent 3367c7b commit b8da986
Show file tree
Hide file tree
Showing 13 changed files with 181 additions and 155 deletions.
14 changes: 7 additions & 7 deletions go.mod
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,19 +8,19 @@ require (
github.com/grpc-ecosystem/go-grpc-middleware/v2 v2.1.0
github.com/jonboulle/clockwork v0.4.1-0.20231224152657-fc59783b0293
github.com/planetscale/vtprotobuf v0.6.1-0.20240917153116-6f2963f01587
github.com/prometheus/client_golang v1.20.4
github.com/siderolabs/discovery-api v0.1.4
github.com/prometheus/client_golang v1.20.5
github.com/siderolabs/discovery-api v0.1.5
github.com/siderolabs/discovery-client v0.1.10
github.com/siderolabs/gen v0.5.0
github.com/siderolabs/go-debug v0.4.0
github.com/siderolabs/proto-codec v0.1.1
github.com/stretchr/testify v1.9.0
go.uber.org/zap v1.27.0
golang.org/x/net v0.29.0
golang.org/x/net v0.30.0
golang.org/x/sync v0.8.0
golang.org/x/time v0.6.0
golang.org/x/time v0.7.0
google.golang.org/grpc v1.67.1
google.golang.org/protobuf v1.34.2
google.golang.org/protobuf v1.35.1
)

require (
Expand All @@ -36,8 +36,8 @@ require (
github.com/prometheus/common v0.60.0 // indirect
github.com/prometheus/procfs v0.15.1 // indirect
go.uber.org/multierr v1.11.0 // indirect
golang.org/x/sys v0.25.0 // indirect
golang.org/x/text v0.18.0 // indirect
golang.org/x/sys v0.26.0 // indirect
golang.org/x/text v0.19.0 // indirect
google.golang.org/genproto/googleapis/rpc v0.0.0-20240827150818-7e3bb234dfed // indirect
gopkg.in/yaml.v3 v3.0.1 // indirect
)
28 changes: 14 additions & 14 deletions go.sum
View file
Original file line number Diff line number Diff line change
Expand Up @@ -30,8 +30,8 @@ github.com/planetscale/vtprotobuf v0.6.1-0.20240917153116-6f2963f01587 h1:xzZOeC
github.com/planetscale/vtprotobuf v0.6.1-0.20240917153116-6f2963f01587/go.mod h1:t/avpk3KcrXxUnYOhZhMXJlSEyie6gQbtLq5NM3loB8=
github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
github.com/prometheus/client_golang v1.20.4 h1:Tgh3Yr67PaOv/uTqloMsCEdeuFTatm5zIq5+qNN23vI=
github.com/prometheus/client_golang v1.20.4/go.mod h1:PIEt8X02hGcP8JWbeHyeZ53Y/jReSnHgO035n//V5WE=
github.com/prometheus/client_golang v1.20.5 h1:cxppBPuYhUnsO6yo/aoRol4L7q7UFfdm+bR9r+8l63Y=
github.com/prometheus/client_golang v1.20.5/go.mod h1:PIEt8X02hGcP8JWbeHyeZ53Y/jReSnHgO035n//V5WE=
github.com/prometheus/client_model v0.6.1 h1:ZKSh/rekM+n3CeS952MLRAdFwIKqeY8b62p8ais2e9E=
github.com/prometheus/client_model v0.6.1/go.mod h1:OrxVMOVHjw3lKMa8+x6HeMGkHMQyHDk9E3jmP2AmGiY=
github.com/prometheus/common v0.60.0 h1:+V9PAREWNvJMAuJ1x1BaWl9dewMW4YrHZQbx0sJNllA=
Expand All @@ -40,8 +40,8 @@ github.com/prometheus/procfs v0.15.1 h1:YagwOFzUgYfKKHX6Dr+sHT7km/hxC76UB0leargg
github.com/prometheus/procfs v0.15.1/go.mod h1:fB45yRUv8NstnjriLhBQLuOUt+WW4BsoGhij/e3PBqk=
github.com/rogpeppe/go-internal v1.10.0 h1:TMyTOH3F/DB16zRVcYyreMH6GnZZrwQVAoYjRBZyWFQ=
github.com/rogpeppe/go-internal v1.10.0/go.mod h1:UQnix2H7Ngw/k4C5ijL5+65zddjncjaFoBhdsK/akog=
github.com/siderolabs/discovery-api v0.1.4 h1:2fMEFSMiWaD1zDiBDY5md8VxItvL1rDQRSOfeXNjYKc=
github.com/siderolabs/discovery-api v0.1.4/go.mod h1:kaBy+G42v2xd/uAF/NIe383sjNTBE2AhxPTyi9SZI0s=
github.com/siderolabs/discovery-api v0.1.5 h1:fcHVkLkWla7C5+9IeOGEUQ4N8Yp9R7a/kcKbiay2QKw=
github.com/siderolabs/discovery-api v0.1.5/go.mod h1:b9jOm9T2puYVcRqCAjWxPcHz2qBqDX8I0OZDOyOFHXg=
github.com/siderolabs/discovery-client v0.1.10 h1:bTAvFLiISSzVXyYL1cIgAz8cPYd9ZfvhxwdebgtxARA=
github.com/siderolabs/discovery-client v0.1.10/go.mod h1:Ew1z07eyJwqNwum84IKYH4S649KEKK5WUmRW49HlXS8=
github.com/siderolabs/gen v0.5.0 h1:Afdjx+zuZDf53eH5DB+E+T2JeCwBXGinV66A6osLgQI=
Expand All @@ -58,22 +58,22 @@ go.uber.org/multierr v1.11.0 h1:blXXJkSxSSfBVBlC76pxqeO+LN3aDfLQo+309xJstO0=
go.uber.org/multierr v1.11.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y=
go.uber.org/zap v1.27.0 h1:aJMhYGrd5QSmlpLMr2MftRKl7t8J8PTZPA732ud/XR8=
go.uber.org/zap v1.27.0/go.mod h1:GB2qFLM7cTU87MWRP2mPIjqfIDnGu+VIO4V/SdhGo2E=
golang.org/x/net v0.29.0 h1:5ORfpBpCs4HzDYoodCDBbwHzdR5UrLBZ3sOnUJmFoHo=
golang.org/x/net v0.29.0/go.mod h1:gLkgy8jTGERgjzMic6DS9+SP0ajcu6Xu3Orq/SpETg0=
golang.org/x/net v0.30.0 h1:AcW1SDZMkb8IpzCdQUaIq2sP4sZ4zw+55h6ynffypl4=
golang.org/x/net v0.30.0/go.mod h1:2wGyMJ5iFasEhkwi13ChkO/t1ECNC4X4eBKkVFyYFlU=
golang.org/x/sync v0.8.0 h1:3NFvSEYkUoMifnESzZl15y791HH1qU2xm6eCJU5ZPXQ=
golang.org/x/sync v0.8.0/go.mod h1:Czt+wKu1gCyEFDUtn0jG5QVvpJ6rzVqr5aXyt9drQfk=
golang.org/x/sys v0.25.0 h1:r+8e+loiHxRqhXVl6ML1nO3l1+oFoWbnlu2Ehimmi34=
golang.org/x/sys v0.25.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
golang.org/x/text v0.18.0 h1:XvMDiNzPAl0jr17s6W9lcaIhGUfUORdGCNsuLmPG224=
golang.org/x/text v0.18.0/go.mod h1:BuEKDfySbSR4drPmRPG/7iBdf8hvFMuRexcpahXilzY=
golang.org/x/time v0.6.0 h1:eTDhh4ZXt5Qf0augr54TN6suAUudPcawVZeIAPU7D4U=
golang.org/x/time v0.6.0/go.mod h1:3BpzKBy/shNhVucY/MWOyx10tF3SFh9QdLuxbVysPQM=
golang.org/x/sys v0.26.0 h1:KHjCJyddX0LoSTb3J+vWpupP9p0oznkqVk/IfjymZbo=
golang.org/x/sys v0.26.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
golang.org/x/text v0.19.0 h1:kTxAhCbGbxhK0IwgSKiMO5awPoDQ0RpfiVYBfK860YM=
golang.org/x/text v0.19.0/go.mod h1:BuEKDfySbSR4drPmRPG/7iBdf8hvFMuRexcpahXilzY=
golang.org/x/time v0.7.0 h1:ntUhktv3OPE6TgYxXWv9vKvUSJyIFJlyohwbkEwPrKQ=
golang.org/x/time v0.7.0/go.mod h1:3BpzKBy/shNhVucY/MWOyx10tF3SFh9QdLuxbVysPQM=
google.golang.org/genproto/googleapis/rpc v0.0.0-20240827150818-7e3bb234dfed h1:J6izYgfBXAI3xTKLgxzTmUltdYaLsuBxFCgDHWJ/eXg=
google.golang.org/genproto/googleapis/rpc v0.0.0-20240827150818-7e3bb234dfed/go.mod h1:UqMtugtsSgubUsoxbuAoiCXvqvErP7Gf0so0mK9tHxU=
google.golang.org/grpc v1.67.1 h1:zWnc1Vrcno+lHZCOofnIMvycFcc0QRGIzm9dhnDX68E=
google.golang.org/grpc v1.67.1/go.mod h1:1gLDyUQU7CTLJI90u3nXZ9ekeghjeM7pTDZlqFNg2AA=
google.golang.org/protobuf v1.34.2 h1:6xV6lTsCfpGD21XK49h7MhtcApnLqkfYgPcdHftf6hg=
google.golang.org/protobuf v1.34.2/go.mod h1:qYOHts0dSfpeUzUFpOMr/WGzszTmLH+DiWniOlNbLDw=
google.golang.org/protobuf v1.35.1 h1:m3LfL6/Ca+fqnjnlqQXNpFPABW1UD7mjh8KO2mKFytA=
google.golang.org/protobuf v1.35.1/go.mod h1:9fA7Ob0pmnwhb644+1+CVWFRbNajQ6iRojtC/QF5bRE=
gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c h1:Hei/4ADfdWqJk1ZMxUNpqntNwaWcugrBjAiHlqqRiVk=
gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EVd6muEfDQjcINNoR0C8j2r3qZ4Q=
Expand Down
53 changes: 0 additions & 53 deletions internal/grpclog/grpclog.go
View file

This file was deleted.

4 changes: 2 additions & 2 deletions pkg/server/cert_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -69,7 +69,7 @@ var onceCert = sync.OnceValues(func() (*tls.Certificate, error) {
return &cert, nil
})

func GetServerTLSConfig(t *testing.T) *tls.Config {
func GetServerTLSConfig(t testing.TB) *tls.Config {
t.Helper()

cert, err := onceCert()
Expand All @@ -81,7 +81,7 @@ func GetServerTLSConfig(t *testing.T) *tls.Config {
}
}

func GetClientTLSConfig(t *testing.T) *tls.Config {
func GetClientTLSConfig(t testing.TB) *tls.Config {
t.Helper()

cert, err := onceCert()
Expand Down
2 changes: 1 addition & 1 deletion pkg/server/client_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -365,7 +365,7 @@ func TestClient(t *testing.T) {
// clusterSimulator simulates cluster with a number of affiliates discovering each other.
//
//nolint:gocognit
func clusterSimulator(t *testing.T, endpoint string, logger *zap.Logger, numAffiliates int) {
func clusterSimulator(t testing.TB, endpoint string, logger *zap.Logger, numAffiliates int) {
clusterIDBytes := make([]byte, 32)
_, err := io.ReadFull(rand.Reader, clusterIDBytes)
require.NoError(t, err)
Expand Down
3 changes: 2 additions & 1 deletion pkg/server/limiting.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@ package server
import (
"context"

"github.com/siderolabs/gen/value"
"google.golang.org/grpc"
"google.golang.org/grpc/codes"
"google.golang.org/grpc/status"
Expand All @@ -17,7 +18,7 @@ import (

func pause(ctx context.Context, limiter *limiter.IPRateLimiter) error {
iPAddr := PeerAddress(ctx)
if !IsZero(iPAddr) {
if !value.IsZero(iPAddr) {
limit := limiter.Get(iPAddr)

err := limit.Wait(ctx)
Expand Down
100 changes: 72 additions & 28 deletions pkg/server/logging.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,51 +7,95 @@ package server

import (
"context"
"time"

grpc_middleware "github.com/grpc-ecosystem/go-grpc-middleware/v2"
"github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
"google.golang.org/grpc"
"google.golang.org/protobuf/proto"
"google.golang.org/protobuf/reflect/protoreflect"
"google.golang.org/grpc/status"
)

// fieldExtractor prepares tags for logging and tracing out of the request.
func fieldExtractor(ctx context.Context, req interface{}) logging.Fields {
var ret logging.Fields
func extractFields(req any) []zapcore.Field {
var result []zapcore.Field

if msg, ok := req.(proto.Message); ok {
r := msg.ProtoReflect()
fields := r.Descriptor().Fields()
if msg, ok := req.(interface {
GetClusterId() string
}); ok {
result = append(result, zap.String("cluster_id", msg.GetClusterId()))
}

for _, name := range []string{"cluster_id", "affiliate_id", "client_version"} {
if field := fields.ByName(protoreflect.Name(name)); field != nil {
ret = append(ret, name, r.Get(field).String())
}
}
if msg, ok := req.(interface {
GetAffiliateId() string
}); ok {
result = append(result, zap.String("affiliate_id", msg.GetAffiliateId()))
}

if peerAddress := PeerAddress(ctx); !IsZero(peerAddress) {
ret = append(ret, "peer.address", peerAddress.String())
if msg, ok := req.(interface {
GetClientVersion() string
}); ok {
result = append(result, zap.String("client_version", msg.GetClientVersion()))
}

return ret
return result
}

// AddLoggingFieldsUnaryServerInterceptor sets peer.address for logging.
func AddLoggingFieldsUnaryServerInterceptor() grpc.UnaryServerInterceptor {
return func(ctx context.Context, req interface{}, _ *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) {
return handler(logging.InjectFields(ctx, fieldExtractor(ctx, req)), req)
// UnaryRequestLogger returns a new unary server interceptor that logs the requests.
func UnaryRequestLogger(logger *zap.Logger) grpc.UnaryServerInterceptor {
return func(ctx context.Context, req any, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (any, error) {
startTime := time.Now()

resp, err := handler(ctx, req)

duration := time.Since(startTime)
code := status.Code(err)

level := zapcore.InfoLevel

if err != nil {
level = zapcore.ErrorLevel
}

logger.Log(level, info.FullMethod,
append(
[]zapcore.Field{
zap.Duration("duration", duration),
zap.Stringer("code", code),
zap.Error(err),
zap.Stringer("peer.address", PeerAddress(ctx)),
},
extractFields(req)...,
)...,
)

return resp, err
}
}

// AddLoggingFieldsStreamServerInterceptor sets peer.address for logging.
func AddLoggingFieldsStreamServerInterceptor() grpc.StreamServerInterceptor {
return func(srv interface{}, ss grpc.ServerStream, _ *grpc.StreamServerInfo, handler grpc.StreamHandler) error {
// StreamRequestLogger returns a new stream server interceptor that logs the requests.
func StreamRequestLogger(logger *zap.Logger) grpc.StreamServerInterceptor {
return func(srv any, ss grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error {
ctx := ss.Context()

wrapped := grpc_middleware.WrapServerStream(ss)
wrapped.WrappedContext = logging.InjectFields(ctx, fieldExtractor(ctx, nil)) //nolint:fatcontext
startTime := time.Now()

err := handler(srv, ss)

duration := time.Since(startTime)
code := status.Code(err)

level := zapcore.InfoLevel

if err != nil {
level = zapcore.ErrorLevel
}

logger.Log(level, info.FullMethod,
zap.Duration("duration", duration),
zap.Stringer("code", code),
zap.Error(err),
zap.Stringer("peer.address", PeerAddress(ctx)),
)

return handler(srv, wrapped)
return err
}
}
3 changes: 2 additions & 1 deletion pkg/server/server.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,7 @@ import (

prom "github.com/prometheus/client_golang/prometheus"
"github.com/siderolabs/discovery-api/api/v1alpha1/server/pb"
"github.com/siderolabs/gen/value"
"go.uber.org/zap"
"google.golang.org/grpc/codes"
"google.golang.org/grpc/status"
Expand Down Expand Up @@ -69,7 +70,7 @@ func (srv *ClusterServer) Hello(ctx context.Context, req *pb.HelloRequest) (*pb.

resp := &pb.HelloResponse{}

if peerAddress := PeerAddress(ctx); !IsZero(peerAddress) {
if peerAddress := PeerAddress(ctx); !value.IsZero(peerAddress) {
resp.ClientIp, _ = peerAddress.MarshalBinary() //nolint:errcheck // never fails
}

Expand Down
Loading

0 comments on commit b8da986

Please sign in to comment.