server: skip unnecessary sprintf which executes proto.Size()

server/etcdserver/util.go

@@ -104,6 +104,9 @@ func (nc *notifier) notify(err error) {
 }
 
 func warnOfExpensiveRequest(lg *zap.Logger, warningApplyDuration time.Duration, now time.Time, reqStringer fmt.Stringer, respMsg proto.Message, err error) {
+	if time.Since(now) <= warningApplyDuration {
+		return
+	}
 	var resp string
 	if !isNil(respMsg) {
 		resp = fmt.Sprintf("size:%d", proto.Size(respMsg))
@@ -127,6 +130,9 @@ func warnOfFailedRequest(lg *zap.Logger, now time.Time, reqStringer fmt.Stringer
 }
 
 func warnOfExpensiveReadOnlyTxnRequest(lg *zap.Logger, warningApplyDuration time.Duration, now time.Time, r *pb.TxnRequest, txnResponse *pb.TxnResponse, err error) {
+	if time.Since(now) <= warningApplyDuration {
+		return
+	}
 	reqStringer := pb.NewLoggableTxnRequest(r)
 	var resp string
 	if !isNil(txnResponse) {
@@ -145,28 +151,28 @@ func warnOfExpensiveReadOnlyTxnRequest(lg *zap.Logger, warningApplyDuration time
 }
 
 func warnOfExpensiveReadOnlyRangeRequest(lg *zap.Logger, warningApplyDuration time.Duration, now time.Time, reqStringer fmt.Stringer, rangeResponse *pb.RangeResponse, err error) {
+	if time.Since(now) <= warningApplyDuration {
+		return
+	}
 	var resp string
 	if !isNil(rangeResponse) {
 		resp = fmt.Sprintf("range_response_count:%d size:%d", len(rangeResponse.Kvs), rangeResponse.Size())
 	}
 	warnOfExpensiveGenericRequest(lg, warningApplyDuration, now, reqStringer, "read-only range ", resp, err)
 }
 
+// callers need make sure time has passed warningApplyDuration
 func warnOfExpensiveGenericRequest(lg *zap.Logger, warningApplyDuration time.Duration, now time.Time, reqStringer fmt.Stringer, prefix string, resp string, err error) {
-	d := time.Since(now)
-
-	if d > warningApplyDuration {
-		lg.Warn(
-			"apply request took too long",
-			zap.Duration("took", d),
-			zap.Duration("expected-duration", warningApplyDuration),
-			zap.String("prefix", prefix),
-			zap.String("request", reqStringer.String()),
-			zap.String("response", resp),
-			zap.Error(err),
-		)
-		slowApplies.Inc()
-	}
+	lg.Warn(
+		"apply request took too long",
+		zap.Duration("took", time.Since(now)),
+		zap.Duration("expected-duration", warningApplyDuration),
+		zap.String("prefix", prefix),
+		zap.String("request", reqStringer.String()),
+		zap.String("response", resp),
+		zap.Error(err),
+	)
+	slowApplies.Inc()
 }
 
 func isNil(msg proto.Message) bool {

server/etcdserver/util_bench_test.go

@@ -0,0 +1,50 @@
+// Copyright 2021 The etcd Authors
+//
+// 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 etcdserver
+
+import (
+	"errors"
+	"go.etcd.io/etcd/raft/v3/raftpb"
+	"testing"
+	"time"
+)
+
+func BenchmarkWarnOfExpensiveRequestNoLog(b *testing.B) {
+	m := &raftpb.Message{
+		Type:       0,
+		To:         0,
+		From:       1,
+		Term:       2,
+		LogTerm:    3,
+		Index:      0,
+		Entries:    []raftpb.Entry{
+			{
+				Term:  0,
+				Index: 0,
+				Type:  0,
+				Data:  make([]byte, 1024),
+			},
+		},
+		Commit:     0,
+		Snapshot:   raftpb.Snapshot{},
+		Reject:     false,
+		RejectHint: 0,
+		Context:    nil,
+	}
+	err := errors.New("benchmarking warn of expensive request")
+	for n := 0; n < b.N; n++ {
+		warnOfExpensiveRequest(testLogger, time.Second, time.Now(), nil, m, err)
+	}
+}