Skip to content

Commit b8da986

Browse files
smirasmira
committed
fix: reduce memory allocations (logger)
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]>
1 parent 3367c7b commit b8da986

File tree

13 files changed

+181
-155
lines changed

13 files changed

+181
-155
lines changed

‎go.mod‎

Lines changed: 7 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -8,19 +8,19 @@ require (
88
github.com/grpc-ecosystem/go-grpc-middleware/v2 v2.1.0
99
github.com/jonboulle/clockwork v0.4.1-0.20231224152657-fc59783b0293
1010
github.com/planetscale/vtprotobuf v0.6.1-0.20240917153116-6f2963f01587
11-
github.com/prometheus/client_golang v1.20.4
12-
github.com/siderolabs/discovery-api v0.1.4
11+
github.com/prometheus/client_golang v1.20.5
12+
github.com/siderolabs/discovery-api v0.1.5
1313
github.com/siderolabs/discovery-client v0.1.10
1414
github.com/siderolabs/gen v0.5.0
1515
github.com/siderolabs/go-debug v0.4.0
1616
github.com/siderolabs/proto-codec v0.1.1
1717
github.com/stretchr/testify v1.9.0
1818
go.uber.org/zap v1.27.0
19-
golang.org/x/net v0.29.0
19+
golang.org/x/net v0.30.0
2020
golang.org/x/sync v0.8.0
21-
golang.org/x/time v0.6.0
21+
golang.org/x/time v0.7.0
2222
google.golang.org/grpc v1.67.1
23-
google.golang.org/protobuf v1.34.2
23+
google.golang.org/protobuf v1.35.1
2424
)
2525

2626
require (
@@ -36,8 +36,8 @@ require (
3636
github.com/prometheus/common v0.60.0 // indirect
3737
github.com/prometheus/procfs v0.15.1 // indirect
3838
go.uber.org/multierr v1.11.0 // indirect
39-
golang.org/x/sys v0.25.0 // indirect
40-
golang.org/x/text v0.18.0 // indirect
39+
golang.org/x/sys v0.26.0 // indirect
40+
golang.org/x/text v0.19.0 // indirect
4141
google.golang.org/genproto/googleapis/rpc v0.0.0-20240827150818-7e3bb234dfed // indirect
4242
gopkg.in/yaml.v3 v3.0.1 // indirect
4343
)

‎go.sum‎

Lines changed: 14 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -30,8 +30,8 @@ github.com/planetscale/vtprotobuf v0.6.1-0.20240917153116-6f2963f01587 h1:xzZOeC
3030
github.com/planetscale/vtprotobuf v0.6.1-0.20240917153116-6f2963f01587/go.mod h1:t/avpk3KcrXxUnYOhZhMXJlSEyie6gQbtLq5NM3loB8=
3131
github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
3232
github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
33-
github.com/prometheus/client_golang v1.20.4 h1:Tgh3Yr67PaOv/uTqloMsCEdeuFTatm5zIq5+qNN23vI=
34-
github.com/prometheus/client_golang v1.20.4/go.mod h1:PIEt8X02hGcP8JWbeHyeZ53Y/jReSnHgO035n//V5WE=
33+
github.com/prometheus/client_golang v1.20.5 h1:cxppBPuYhUnsO6yo/aoRol4L7q7UFfdm+bR9r+8l63Y=
34+
github.com/prometheus/client_golang v1.20.5/go.mod h1:PIEt8X02hGcP8JWbeHyeZ53Y/jReSnHgO035n//V5WE=
3535
github.com/prometheus/client_model v0.6.1 h1:ZKSh/rekM+n3CeS952MLRAdFwIKqeY8b62p8ais2e9E=
3636
github.com/prometheus/client_model v0.6.1/go.mod h1:OrxVMOVHjw3lKMa8+x6HeMGkHMQyHDk9E3jmP2AmGiY=
3737
github.com/prometheus/common v0.60.0 h1:+V9PAREWNvJMAuJ1x1BaWl9dewMW4YrHZQbx0sJNllA=
@@ -40,8 +40,8 @@ github.com/prometheus/procfs v0.15.1 h1:YagwOFzUgYfKKHX6Dr+sHT7km/hxC76UB0leargg
4040
github.com/prometheus/procfs v0.15.1/go.mod h1:fB45yRUv8NstnjriLhBQLuOUt+WW4BsoGhij/e3PBqk=
4141
github.com/rogpeppe/go-internal v1.10.0 h1:TMyTOH3F/DB16zRVcYyreMH6GnZZrwQVAoYjRBZyWFQ=
4242
github.com/rogpeppe/go-internal v1.10.0/go.mod h1:UQnix2H7Ngw/k4C5ijL5+65zddjncjaFoBhdsK/akog=
43-
github.com/siderolabs/discovery-api v0.1.4 h1:2fMEFSMiWaD1zDiBDY5md8VxItvL1rDQRSOfeXNjYKc=
44-
github.com/siderolabs/discovery-api v0.1.4/go.mod h1:kaBy+G42v2xd/uAF/NIe383sjNTBE2AhxPTyi9SZI0s=
43+
github.com/siderolabs/discovery-api v0.1.5 h1:fcHVkLkWla7C5+9IeOGEUQ4N8Yp9R7a/kcKbiay2QKw=
44+
github.com/siderolabs/discovery-api v0.1.5/go.mod h1:b9jOm9T2puYVcRqCAjWxPcHz2qBqDX8I0OZDOyOFHXg=
4545
github.com/siderolabs/discovery-client v0.1.10 h1:bTAvFLiISSzVXyYL1cIgAz8cPYd9ZfvhxwdebgtxARA=
4646
github.com/siderolabs/discovery-client v0.1.10/go.mod h1:Ew1z07eyJwqNwum84IKYH4S649KEKK5WUmRW49HlXS8=
4747
github.com/siderolabs/gen v0.5.0 h1:Afdjx+zuZDf53eH5DB+E+T2JeCwBXGinV66A6osLgQI=
@@ -58,22 +58,22 @@ go.uber.org/multierr v1.11.0 h1:blXXJkSxSSfBVBlC76pxqeO+LN3aDfLQo+309xJstO0=
5858
go.uber.org/multierr v1.11.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y=
5959
go.uber.org/zap v1.27.0 h1:aJMhYGrd5QSmlpLMr2MftRKl7t8J8PTZPA732ud/XR8=
6060
go.uber.org/zap v1.27.0/go.mod h1:GB2qFLM7cTU87MWRP2mPIjqfIDnGu+VIO4V/SdhGo2E=
61-
golang.org/x/net v0.29.0 h1:5ORfpBpCs4HzDYoodCDBbwHzdR5UrLBZ3sOnUJmFoHo=
62-
golang.org/x/net v0.29.0/go.mod h1:gLkgy8jTGERgjzMic6DS9+SP0ajcu6Xu3Orq/SpETg0=
61+
golang.org/x/net v0.30.0 h1:AcW1SDZMkb8IpzCdQUaIq2sP4sZ4zw+55h6ynffypl4=
62+
golang.org/x/net v0.30.0/go.mod h1:2wGyMJ5iFasEhkwi13ChkO/t1ECNC4X4eBKkVFyYFlU=
6363
golang.org/x/sync v0.8.0 h1:3NFvSEYkUoMifnESzZl15y791HH1qU2xm6eCJU5ZPXQ=
6464
golang.org/x/sync v0.8.0/go.mod h1:Czt+wKu1gCyEFDUtn0jG5QVvpJ6rzVqr5aXyt9drQfk=
65-
golang.org/x/sys v0.25.0 h1:r+8e+loiHxRqhXVl6ML1nO3l1+oFoWbnlu2Ehimmi34=
66-
golang.org/x/sys v0.25.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
67-
golang.org/x/text v0.18.0 h1:XvMDiNzPAl0jr17s6W9lcaIhGUfUORdGCNsuLmPG224=
68-
golang.org/x/text v0.18.0/go.mod h1:BuEKDfySbSR4drPmRPG/7iBdf8hvFMuRexcpahXilzY=
69-
golang.org/x/time v0.6.0 h1:eTDhh4ZXt5Qf0augr54TN6suAUudPcawVZeIAPU7D4U=
70-
golang.org/x/time v0.6.0/go.mod h1:3BpzKBy/shNhVucY/MWOyx10tF3SFh9QdLuxbVysPQM=
65+
golang.org/x/sys v0.26.0 h1:KHjCJyddX0LoSTb3J+vWpupP9p0oznkqVk/IfjymZbo=
66+
golang.org/x/sys v0.26.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
67+
golang.org/x/text v0.19.0 h1:kTxAhCbGbxhK0IwgSKiMO5awPoDQ0RpfiVYBfK860YM=
68+
golang.org/x/text v0.19.0/go.mod h1:BuEKDfySbSR4drPmRPG/7iBdf8hvFMuRexcpahXilzY=
69+
golang.org/x/time v0.7.0 h1:ntUhktv3OPE6TgYxXWv9vKvUSJyIFJlyohwbkEwPrKQ=
70+
golang.org/x/time v0.7.0/go.mod h1:3BpzKBy/shNhVucY/MWOyx10tF3SFh9QdLuxbVysPQM=
7171
google.golang.org/genproto/googleapis/rpc v0.0.0-20240827150818-7e3bb234dfed h1:J6izYgfBXAI3xTKLgxzTmUltdYaLsuBxFCgDHWJ/eXg=
7272
google.golang.org/genproto/googleapis/rpc v0.0.0-20240827150818-7e3bb234dfed/go.mod h1:UqMtugtsSgubUsoxbuAoiCXvqvErP7Gf0so0mK9tHxU=
7373
google.golang.org/grpc v1.67.1 h1:zWnc1Vrcno+lHZCOofnIMvycFcc0QRGIzm9dhnDX68E=
7474
google.golang.org/grpc v1.67.1/go.mod h1:1gLDyUQU7CTLJI90u3nXZ9ekeghjeM7pTDZlqFNg2AA=
75-
google.golang.org/protobuf v1.34.2 h1:6xV6lTsCfpGD21XK49h7MhtcApnLqkfYgPcdHftf6hg=
76-
google.golang.org/protobuf v1.34.2/go.mod h1:qYOHts0dSfpeUzUFpOMr/WGzszTmLH+DiWniOlNbLDw=
75+
google.golang.org/protobuf v1.35.1 h1:m3LfL6/Ca+fqnjnlqQXNpFPABW1UD7mjh8KO2mKFytA=
76+
google.golang.org/protobuf v1.35.1/go.mod h1:9fA7Ob0pmnwhb644+1+CVWFRbNajQ6iRojtC/QF5bRE=
7777
gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
7878
gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c h1:Hei/4ADfdWqJk1ZMxUNpqntNwaWcugrBjAiHlqqRiVk=
7979
gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EVd6muEfDQjcINNoR0C8j2r3qZ4Q=

‎internal/grpclog/grpclog.go‎

Lines changed: 0 additions & 53 deletions
This file was deleted.

‎pkg/server/cert_test.go‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -69,7 +69,7 @@ var onceCert = sync.OnceValues(func() (*tls.Certificate, error) {
6969
return &cert, nil
7070
})
7171

72-
func GetServerTLSConfig(t *testing.T) *tls.Config {
72+
func GetServerTLSConfig(t testing.TB) *tls.Config {
7373
t.Helper()
7474

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

84-
func GetClientTLSConfig(t *testing.T) *tls.Config {
84+
func GetClientTLSConfig(t testing.TB) *tls.Config {
8585
t.Helper()
8686

8787
cert, err := onceCert()

‎pkg/server/client_test.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -365,7 +365,7 @@ func TestClient(t *testing.T) {
365365
// clusterSimulator simulates cluster with a number of affiliates discovering each other.
366366
//
367367
//nolint:gocognit
368-
func clusterSimulator(t *testing.T, endpoint string, logger *zap.Logger, numAffiliates int) {
368+
func clusterSimulator(t testing.TB, endpoint string, logger *zap.Logger, numAffiliates int) {
369369
clusterIDBytes := make([]byte, 32)
370370
_, err := io.ReadFull(rand.Reader, clusterIDBytes)
371371
require.NoError(t, err)

‎pkg/server/limiting.go‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@ package server
88
import (
99
"context"
1010

11+
"github.com/siderolabs/gen/value"
1112
"google.golang.org/grpc"
1213
"google.golang.org/grpc/codes"
1314
"google.golang.org/grpc/status"
@@ -17,7 +18,7 @@ import (
1718

1819
func pause(ctx context.Context, limiter *limiter.IPRateLimiter) error {
1920
iPAddr := PeerAddress(ctx)
20-
if !IsZero(iPAddr) {
21+
if !value.IsZero(iPAddr) {
2122
limit := limiter.Get(iPAddr)
2223

2324
err := limit.Wait(ctx)

‎pkg/server/logging.go‎

Lines changed: 72 additions & 28 deletions
Original file line numberDiff line numberDiff line change
@@ -7,51 +7,95 @@ package server
77

88
import (
99
"context"
10+
"time"
1011

11-
grpc_middleware "github.com/grpc-ecosystem/go-grpc-middleware/v2"
12-
"github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging"
12+
"go.uber.org/zap"
13+
"go.uber.org/zap/zapcore"
1314
"google.golang.org/grpc"
14-
"google.golang.org/protobuf/proto"
15-
"google.golang.org/protobuf/reflect/protoreflect"
15+
"google.golang.org/grpc/status"
1616
)
1717

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

22-
if msg, ok := req.(proto.Message); ok {
23-
r := msg.ProtoReflect()
24-
fields := r.Descriptor().Fields()
21+
if msg, ok := req.(interface {
22+
GetClusterId() string
23+
}); ok {
24+
result = append(result, zap.String("cluster_id", msg.GetClusterId()))
25+
}
2526

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

33-
if peerAddress := PeerAddress(ctx); !IsZero(peerAddress) {
34-
ret = append(ret, "peer.address", peerAddress.String())
33+
if msg, ok := req.(interface {
34+
GetClientVersion() string
35+
}); ok {
36+
result = append(result, zap.String("client_version", msg.GetClientVersion()))
3537
}
3638

37-
return ret
39+
return result
3840
}
3941

40-
// AddLoggingFieldsUnaryServerInterceptor sets peer.address for logging.
41-
func AddLoggingFieldsUnaryServerInterceptor() grpc.UnaryServerInterceptor {
42-
return func(ctx context.Context, req interface{}, _ *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) {
43-
return handler(logging.InjectFields(ctx, fieldExtractor(ctx, req)), req)
42+
// UnaryRequestLogger returns a new unary server interceptor that logs the requests.
43+
func UnaryRequestLogger(logger *zap.Logger) grpc.UnaryServerInterceptor {
44+
return func(ctx context.Context, req any, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (any, error) {
45+
startTime := time.Now()
46+
47+
resp, err := handler(ctx, req)
48+
49+
duration := time.Since(startTime)
50+
code := status.Code(err)
51+
52+
level := zapcore.InfoLevel
53+
54+
if err != nil {
55+
level = zapcore.ErrorLevel
56+
}
57+
58+
logger.Log(level, info.FullMethod,
59+
append(
60+
[]zapcore.Field{
61+
zap.Duration("duration", duration),
62+
zap.Stringer("code", code),
63+
zap.Error(err),
64+
zap.Stringer("peer.address", PeerAddress(ctx)),
65+
},
66+
extractFields(req)...,
67+
)...,
68+
)
69+
70+
return resp, err
4471
}
4572
}
4673

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

52-
wrapped := grpc_middleware.WrapServerStream(ss)
53-
wrapped.WrappedContext = logging.InjectFields(ctx, fieldExtractor(ctx, nil)) //nolint:fatcontext
79+
startTime := time.Now()
80+
81+
err := handler(srv, ss)
82+
83+
duration := time.Since(startTime)
84+
code := status.Code(err)
85+
86+
level := zapcore.InfoLevel
87+
88+
if err != nil {
89+
level = zapcore.ErrorLevel
90+
}
91+
92+
logger.Log(level, info.FullMethod,
93+
zap.Duration("duration", duration),
94+
zap.Stringer("code", code),
95+
zap.Error(err),
96+
zap.Stringer("peer.address", PeerAddress(ctx)),
97+
)
5498

55-
return handler(srv, wrapped)
99+
return err
56100
}
57101
}

‎pkg/server/server.go‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@ import (
1313

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

7071
resp := &pb.HelloResponse{}
7172

72-
if peerAddress := PeerAddress(ctx); !IsZero(peerAddress) {
73+
if peerAddress := PeerAddress(ctx); !value.IsZero(peerAddress) {
7374
resp.ClientIp, _ = peerAddress.MarshalBinary() //nolint:errcheck // never fails
7475
}
7576

0 commit comments

Comments
 (0)