feat: Optimize trace chain elements

go.mod

@@ -3,6 +3,7 @@ module github.com/networkservicemesh/sdk
 go 1.23
 
 require (
+	github.com/OneOfOne/xxhash v1.2.8
 	github.com/RoaringBitmap/roaring v0.9.4
 	github.com/antonfisher/nested-logrus-formatter v1.3.1
 	github.com/benbjohnson/clock v1.3.0
@@ -50,7 +51,6 @@ require (
 require (
 	cloud.google.com/go/compute v1.23.1 // indirect
 	github.com/Microsoft/go-winio v0.6.1 // indirect
-	github.com/OneOfOne/xxhash v1.2.8 // indirect
 	github.com/agnivade/levenshtein v1.1.1 // indirect
 	github.com/armon/go-metrics v0.0.0-20190430140413-ec5e00d3c878 // indirect
 	github.com/beorn7/perks v1.0.1 // indirect

pkg/networkservice/core/trace/README.md

@@ -0,0 +1,34 @@
+## Logging levels
+
+- TRACE, DEBUG: these levels print diff, since diff is expensive operation (see diff between Trace and Info tests) it's recommended to use only for debugging.
+- INFO: prints short information about requests and connections.
+- FATAL, ERROR, WARN: Print only logs from chain elements that are using these levels directly in the source code e.g., `log.FromContext(ctx).Warn("todo")`
+
+## Benchmarks
+
+**Release v1.14.1**
+```
+Benchmark_ShortRequest_Info-8   	    3924	    344671 ns/op	   25641 B/op	     178 allocs/op
+Benchmark_LongRequest_Info-8   	        340	        3765718 ns/op	  273254 B/op	     861 allocs/op
+
+Benchmark_ShortRequest_Trace-8   	      79	  13600986 ns/op	  344445 B/op	    8475 allocs/op
+Benchmark_LongRequest_Trace-8   	       2	 916385562 ns/op	20998324 B/op	  694678 allocs/op
+
+Benchmark_LongRequest_Trace_NoDiff-8   	       2	 565520104 ns/op	12236116 B/op	  585667 allocs/op
+Benchmark_LongRequest_Diff_Warn-8   	  340	        3765718 ns/op	  273254 B/op	     861 allocs/op
+
+```
+
+
+**Release v1.14.2**
+```
+Benchmark_ShortRequest_Info-8   	    4090	    350181 ns/op	   24246 B/op	     177 allocs/op
+Benchmark_LongRequest_Info-8   	          373	   3064039 ns/op	  253359 B/op	     857 allocs/op
+
+Benchmark_ShortRequest_Trace-8   	     543	   2599280 ns/op	  237262 B/op	    1825 allocs/op
+Benchmark_LongRequest_Trace-8   	       9	 131145361 ns/op	22433480 B/op	   20749 allocs/op
+
+Benchmark_LongRequest_Trace_NoDiff-8   	      18	  72167456 ns/op	10900859 B/op	   13685 allocs/op
+
+Benchmark_LongRequest_Diff_Warn-8   	   31128	     36019 ns/op	    9600 B/op	     200 allocs/op
+```

pkg/networkservice/core/trace/client.go

@@ -1,4 +1,4 @@
-// Copyright (c) 2023 Cisco and/or its affiliates.
+// Copyright (c) 2023-2024 Cisco and/or its affiliates.
 //
 // SPDX-License-Identifier: Apache-2.0
 //
@@ -32,27 +32,35 @@ import (
 )
 
 type traceClient struct {
-	verbose networkservice.NetworkServiceClient
-	concise networkservice.NetworkServiceClient
+	verbose  networkservice.NetworkServiceClient
+	concise  networkservice.NetworkServiceClient
+	original networkservice.NetworkServiceClient
 }
 
 // NewNetworkServiceClient - wraps tracing around the supplied networkservice.NetworkServiceClient
 func NewNetworkServiceClient(traced networkservice.NetworkServiceClient) networkservice.NetworkServiceClient {
 	return &traceClient{
-		verbose: traceverbose.NewNetworkServiceClient(traced),
-		concise: traceconcise.NewNetworkServiceClient(traced),
+		verbose:  traceverbose.NewNetworkServiceClient(traced),
+		concise:  traceconcise.NewNetworkServiceClient(traced),
+		original: traced,
 	}
 }
 
 func (t *traceClient) Request(ctx context.Context, request *networkservice.NetworkServiceRequest, opts ...grpc.CallOption) (*networkservice.Connection, error) {
-	if logrus.GetLevel() == logrus.TraceLevel {
+	if logrus.GetLevel() <= logrus.WarnLevel {
+		return t.original.Request(ctx, request)
+	}
+	if logrus.GetLevel() >= logrus.DebugLevel {
 		return t.verbose.Request(ctx, request, opts...)
 	}
 	return t.concise.Request(ctx, request, opts...)
 }
 
 func (t *traceClient) Close(ctx context.Context, conn *networkservice.Connection, opts ...grpc.CallOption) (*empty.Empty, error) {
-	if logrus.GetLevel() == logrus.TraceLevel {
+	if logrus.GetLevel() <= logrus.WarnLevel {
+		return t.original.Close(ctx, conn)
+	}
+	if logrus.GetLevel() >= logrus.DebugLevel {
 		return t.verbose.Close(ctx, conn, opts...)
 	}
 	return t.concise.Close(ctx, conn, opts...)

pkg/networkservice/core/trace/server.go

@@ -1,4 +1,4 @@
-// Copyright (c) 2023 Cisco and/or its affiliates.
+// Copyright (c) 2023-2024 Cisco and/or its affiliates.
 //
 // SPDX-License-Identifier: Apache-2.0
 //
@@ -30,27 +30,34 @@ import (
 )
 
 type traceServer struct {
-	verbose networkservice.NetworkServiceServer
-	concise networkservice.NetworkServiceServer
+	verbose, concise, original networkservice.NetworkServiceServer
 }
 
 // NewNetworkServiceServer - wraps tracing around the supplied traced
 func NewNetworkServiceServer(traced networkservice.NetworkServiceServer) networkservice.NetworkServiceServer {
 	return &traceServer{
-		verbose: traceverbose.NewNetworkServiceServer(traced),
-		concise: traceconcise.NewNetworkServiceServer(traced),
+		verbose:  traceverbose.NewNetworkServiceServer(traced),
+		concise:  traceconcise.NewNetworkServiceServer(traced),
+		original: traced,
 	}
 }
 
 func (t *traceServer) Request(ctx context.Context, request *networkservice.NetworkServiceRequest) (*networkservice.Connection, error) {
-	if logrus.GetLevel() == logrus.TraceLevel {
+	if logrus.GetLevel() <= logrus.WarnLevel {
+		return t.original.Request(ctx, request)
+	}
+	if logrus.GetLevel() >= logrus.DebugLevel {
 		return t.verbose.Request(ctx, request)
 	}
+
 	return t.concise.Request(ctx, request)
 }
 
 func (t *traceServer) Close(ctx context.Context, conn *networkservice.Connection) (*empty.Empty, error) {
-	if logrus.GetLevel() == logrus.TraceLevel {
+	if logrus.GetLevel() <= logrus.WarnLevel {
+		return t.original.Close(ctx, conn)
+	}
+	if logrus.GetLevel() >= logrus.DebugLevel {
 		return t.verbose.Close(ctx, conn)
 	}
 	return t.concise.Close(ctx, conn)

pkg/networkservice/core/trace/server_bench_test.go

@@ -0,0 +1,173 @@
+// Copyright (c) 2024 Cisco Systems, Inc.
+//
+// SPDX-License-Identifier: Apache-2.0
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at:
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package trace_test
+
+import (
+	"context"
+	"fmt"
+	"io"
+	"testing"
+
+	"github.com/networkservicemesh/api/pkg/api/networkservice"
+
+	"github.com/networkservicemesh/sdk/pkg/networkservice/common/null"
+	"github.com/networkservicemesh/sdk/pkg/networkservice/core/chain"
+	"github.com/networkservicemesh/sdk/pkg/networkservice/core/trace/testutil"
+	"github.com/networkservicemesh/sdk/pkg/networkservice/utils/checks/checkrequest"
+	"github.com/networkservicemesh/sdk/pkg/tools/log"
+	"github.com/networkservicemesh/sdk/pkg/tools/nanoid"
+
+	"github.com/sirupsen/logrus"
+)
+
+func newTestRequest(size int) *networkservice.NetworkServiceRequest {
+	res := testutil.NewConnection()
+
+	res.GetConnection().Path = &networkservice.Path{}
+	res.GetConnection().Labels = make(map[string]string)
+
+	for i := 0; i < size; i++ {
+		res.GetConnection().GetPath().PathSegments = append(res.GetConnection().GetPath().PathSegments,
+			&networkservice.PathSegment{
+				Name:  nanoid.MustGenerateString(15),
+				Token: nanoid.MustGenerateString(25),
+				Id:    nanoid.MustGenerateString(20),
+			})
+	}
+
+	res.GetConnection().Id = res.GetConnection().GetPath().GetPathSegments()[0].Id
+
+	return res
+}
+
+func newTestServerChain(size int) networkservice.NetworkServiceServer {
+	var servers []networkservice.NetworkServiceServer
+
+	for i := 0; i < size; i++ {
+		id := i
+		servers = append(servers, checkrequest.NewServer(nil, func(_ *testing.T, nsr *networkservice.NetworkServiceRequest) {
+			nsr.GetConnection().GetLabels()["common-label"] = fmt.Sprint(id)
+		}))
+	}
+
+	return chain.NewNetworkServiceServer(servers...)
+}
+
+func newTestStaticServerChain(size int) networkservice.NetworkServiceServer {
+	var servers []networkservice.NetworkServiceServer
+
+	for i := 0; i < size; i++ {
+		servers = append(servers, null.NewServer())
+	}
+
+	return chain.NewNetworkServiceServer(servers...)
+}
+
+func Benchmark_ShortRequest_Info(b *testing.B) {
+	var s = newTestServerChain(10)
+	var request = newTestRequest(5)
+	var ctx = context.Background()
+
+	logrus.SetLevel(logrus.InfoLevel)
+	logrus.SetOutput(io.Discard)
+	log.EnableTracing(true)
+
+	b.ResetTimer()
+
+	for range b.N {
+		_, _ = s.Request(ctx, request)
+	}
+}
+
+func Benchmark_LongRequest_Info(b *testing.B) {
+	var s = newTestServerChain(100)
+	var request = newTestRequest(100)
+	var ctx = context.Background()
+
+	logrus.SetLevel(logrus.InfoLevel)
+	logrus.SetOutput(io.Discard)
+	log.EnableTracing(true)
+
+	b.ResetTimer()
+
+	for range b.N {
+		_, _ = s.Request(ctx, request)
+	}
+}
+
+func Benchmark_ShortRequest_Trace(b *testing.B) {
+	var s = newTestServerChain(10)
+	var request = newTestRequest(5)
+	var ctx = context.Background()
+
+	logrus.SetLevel(logrus.TraceLevel)
+	logrus.SetOutput(io.Discard)
+	log.EnableTracing(true)
+
+	b.ResetTimer()
+
+	for range b.N {
+		_, _ = s.Request(ctx, request)
+	}
+}
+func Benchmark_LongRequest_Trace(b *testing.B) {
+	var s = newTestServerChain(100)
+	var request = newTestRequest(100)
+	var ctx = context.Background()
+
+	logrus.SetLevel(logrus.TraceLevel)
+	logrus.SetOutput(io.Discard)
+	log.EnableTracing(true)
+
+	b.ResetTimer()
+
+	for range b.N {
+		_, _ = s.Request(ctx, request)
+	}
+}
+
+func Benchmark_LongRequest_Trace_NoDiff(b *testing.B) {
+	var s = newTestStaticServerChain(100)
+	var request = newTestRequest(100)
+	var ctx = context.Background()
+
+	logrus.SetLevel(logrus.TraceLevel)
+	logrus.SetOutput(io.Discard)
+	log.EnableTracing(true)
+
+	b.ResetTimer()
+
+	for range b.N {
+		_, _ = s.Request(ctx, request)
+	}
+}
+
+func Benchmark_LongRequest_Diff_Warn(b *testing.B) {
+	var s = newTestStaticServerChain(100)
+	var request = newTestRequest(100)
+	var ctx = context.Background()
+
+	logrus.SetLevel(logrus.WarnLevel)
+	logrus.SetOutput(io.Discard)
+	log.EnableTracing(true)
+
+	b.ResetTimer()
+
+	for range b.N {
+		_, _ = s.Request(ctx, request)
+	}
+}