router, backend: replace time.Time with mono-time to optimize duratio…

…n calculation (#461)

.gitignore

@@ -8,5 +8,6 @@ vendor
 work
 .vscode/
 .cover*
+coverage.dat
 grafonnet-lib
 dist

pkg/manager/router/backend_observer.go

@@ -12,6 +12,7 @@ import (
 	"github.com/pingcap/tiproxy/lib/util/errors"
 	"github.com/pingcap/tiproxy/lib/util/waitgroup"
 	"github.com/pingcap/tiproxy/pkg/metrics"
+	"github.com/pingcap/tiproxy/pkg/util/monotime"
 	"go.uber.org/zap"
 )
 
@@ -138,7 +139,7 @@ func (bo *BackendObserver) Refresh() {
 
 func (bo *BackendObserver) observe(ctx context.Context) {
 	for ctx.Err() == nil {
-		startTime := time.Now()
+		startTime := monotime.Now()
 		backendInfo, err := bo.fetcher.GetBackendList(ctx)
 		if err != nil {
 			bo.logger.Error("fetching backends encounters error", zap.Error(err))
@@ -151,7 +152,7 @@ func (bo *BackendObserver) observe(ctx context.Context) {
 			bo.notifyIfChanged(bhMap)
 		}
 
-		cost := time.Since(startTime)
+		cost := monotime.Since(startTime)
 		metrics.HealthCheckCycleGauge.Set(cost.Seconds())
 		wait := bo.healthCheckConfig.Interval - cost
 		if wait > 0 {

pkg/manager/router/health_check.go

@@ -15,6 +15,7 @@ import (
 	"github.com/pingcap/tiproxy/lib/config"
 	"github.com/pingcap/tiproxy/lib/util/errors"
 	pnet "github.com/pingcap/tiproxy/pkg/proxy/net"
+	"github.com/pingcap/tiproxy/pkg/util/monotime"
 	"go.uber.org/zap"
 )
 
@@ -90,7 +91,7 @@ func (dhc *DefaultHealthCheck) Check(ctx context.Context, addr string, info *Bac
 	// Also dial the SQL port just in case that the SQL port hangs.
 	var serverVersion string
 	err := dhc.connectWithRetry(ctx, func() error {
-		startTime := time.Now()
+		startTime := monotime.Now()
 		conn, err := net.DialTimeout("tcp", addr, dhc.cfg.DialTimeout)
 		setPingBackendMetrics(addr, err == nil, startTime)
 		if err != nil {

pkg/manager/router/metrics.go

@@ -7,6 +7,7 @@ import (
 	"time"
 
 	"github.com/pingcap/tiproxy/pkg/metrics"
+	"github.com/pingcap/tiproxy/pkg/util/monotime"
 )
 
 func updateBackendStatusMetrics(addr string, prevStatus, curStatus BackendStatus) {
@@ -38,20 +39,20 @@ func succeedToLabel(succeed bool) string {
 	return "fail"
 }
 
-func addMigrateMetrics(from, to string, succeed bool, startTime time.Time) {
+func addMigrateMetrics(from, to string, succeed bool, startTime monotime.Time) {
 	resLabel := succeedToLabel(succeed)
 	metrics.MigrateCounter.WithLabelValues(from, to, resLabel).Inc()
 
-	cost := time.Since(startTime)
+	cost := monotime.Since(startTime)
 	metrics.MigrateDurationHistogram.WithLabelValues(from, to, resLabel).Observe(cost.Seconds())
 }
 
 func readMigrateCounter(from, to string, succeed bool) (int, error) {
 	return metrics.ReadCounter(metrics.MigrateCounter.WithLabelValues(from, to, succeedToLabel(succeed)))
 }
 
-func setPingBackendMetrics(addr string, succeed bool, startTime time.Time) {
-	cost := time.Since(startTime)
+func setPingBackendMetrics(addr string, succeed bool, startTime monotime.Time) {
+	cost := monotime.Since(startTime)
 	metrics.PingBackendGauge.WithLabelValues(addr).Set(cost.Seconds())
 }
 

pkg/manager/router/router.go

@@ -8,6 +8,7 @@ import (
 	"time"
 
 	glist "github.com/bahlo/generic-list-go"
+	"github.com/pingcap/tiproxy/pkg/util/monotime"
 )
 
 // ConnEventReceiver receives connection events.
@@ -142,6 +143,6 @@ type connWrapper struct {
 	// Reference to the target backend if it's redirecting, otherwise nil.
 	redirectingBackend *backendWrapper
 	// Last redirect start time of this connection.
-	lastRedirect time.Time
+	lastRedirect monotime.Time
 	phase        connPhase
 }

pkg/manager/router/router_score.go

@@ -11,6 +11,7 @@ import (
 	glist "github.com/bahlo/generic-list-go"
 	"github.com/pingcap/tiproxy/lib/config"
 	"github.com/pingcap/tiproxy/lib/util/waitgroup"
+	"github.com/pingcap/tiproxy/pkg/util/monotime"
 	"go.uber.org/zap"
 )
 
@@ -335,7 +336,7 @@ func (router *ScoreBasedRouter) rebalanceLoop(ctx context.Context) {
 }
 
 func (router *ScoreBasedRouter) rebalance(maxNum int) {
-	curTime := time.Now()
+	curTime := monotime.Now()
 	router.Lock()
 	defer router.Unlock()
 	for i := 0; i < maxNum; i++ {

pkg/proxy/backend/backend_conn_mgr.go

@@ -24,6 +24,7 @@ import (
 	"github.com/pingcap/tiproxy/lib/util/waitgroup"
 	"github.com/pingcap/tiproxy/pkg/manager/router"
 	pnet "github.com/pingcap/tiproxy/pkg/proxy/net"
+	"github.com/pingcap/tiproxy/pkg/util/monotime"
 	"github.com/siddontang/go/hack"
 	"go.uber.org/zap"
 )
@@ -203,7 +204,7 @@ func (mgr *BackendConnManager) getBackendIO(ctx context.Context, cctx ConnContex
 	// - One TiDB may be just shut down and another is just started but not ready yet
 	bctx, cancel := context.WithTimeout(ctx, mgr.config.ConnectTimeout)
 	selector := r.GetBackendSelector()
-	startTime := time.Now()
+	startTime := monotime.Now()
 	var addr string
 	var origErr error
 	io, err := backoff.RetryNotifyWithData(
@@ -245,7 +246,7 @@ func (mgr *BackendConnManager) getBackendIO(ctx context.Context, cctx ConnContex
 	)
 	cancel()
 
-	duration := time.Since(startTime)
+	duration := monotime.Since(startTime)
 	addGetBackendMetrics(duration, err == nil)
 	if err != nil {
 		mgr.logger.Error("get backend failed", zap.Duration("duration", duration), zap.NamedError("last_err", origErr))
@@ -275,7 +276,7 @@ func (mgr *BackendConnManager) ExecuteCmd(ctx context.Context, request []byte) (
 		return
 	}
 	cmd := pnet.Command(request[0])
-	startTime := time.Now()
+	startTime := monotime.Now()
 
 	// Once the request is accepted, it's treated in the transaction, so we don't check graceful shutdown here.
 	if mgr.closeStatus.Load() >= statusClosing {

pkg/proxy/backend/metrics.go

@@ -8,15 +8,16 @@ import (
 
 	"github.com/pingcap/tiproxy/pkg/metrics"
 	pnet "github.com/pingcap/tiproxy/pkg/proxy/net"
+	"github.com/pingcap/tiproxy/pkg/util/monotime"
 )
 
-func addCmdMetrics(cmd pnet.Command, addr string, startTime time.Time) {
+func addCmdMetrics(cmd pnet.Command, addr string, startTime monotime.Time) {
 	label := cmd.String()
 	metrics.QueryTotalCounter.WithLabelValues(addr, label).Inc()
 
 	// The duration labels are different with TiDB: Labels in TiDB are statement types.
 	// However, the proxy is not aware of the statement types, so we use command types instead.
-	cost := time.Since(startTime)
+	cost := monotime.Since(startTime)
 	metrics.QueryDurationHistogram.WithLabelValues(addr, label).Observe(cost.Seconds())
 }
 

pkg/util/monotime/monotime.go

@@ -0,0 +1,41 @@
+// Copyright 2024 PingCAP, Inc.
+// SPDX-License-Identifier: Apache-2.0
+
+package monotime
+
+import (
+	"time"
+	_ "unsafe"
+)
+
+//go:noescape
+//go:linkname nanotime runtime.nanotime
+func nanotime() int64
+
+// Time is a monotonic clock time which is used to calculate duration.
+// It's 2x faster than time.Time.
+type Time int64
+
+func Now() Time {
+	return Time(nanotime())
+}
+
+func Since(t Time) time.Duration {
+	return time.Duration(Time(nanotime()) - t)
+}
+
+func (t Time) Add(d time.Duration) Time {
+	return t + Time(d)
+}
+
+func (t Time) Sub(d time.Duration) Time {
+	return t - Time(d)
+}
+
+func (t Time) Before(u Time) bool {
+	return t < u
+}
+
+func (t Time) After(u Time) bool {
+	return t > u
+}

pkg/util/monotime/monotime_test.go

@@ -0,0 +1,46 @@
+// Copyright 2024 PingCAP, Inc.
+// SPDX-License-Identifier: Apache-2.0
+
+package monotime
+
+import (
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/require"
+)
+
+func BenchmarkGoNow(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		time.Now()
+	}
+}
+
+func BenchmarkMonoNow(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		Now()
+	}
+}
+
+func BenchmarkGoSince(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		time.Since(time.Now())
+	}
+}
+
+func BenchmarkMonoSince(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		Since(Now())
+	}
+}
+
+func TestAfter(t *testing.T) {
+	t1 := Now()
+	time.Sleep(100 * time.Millisecond)
+	d := Since(t1)
+	require.GreaterOrEqual(t, d, 100*time.Millisecond)
+	require.True(t, Now().After(t1))
+	require.True(t, t1.Before(Now()))
+	require.Greater(t, t1.Add(time.Millisecond), t1)
+	require.Less(t, t1.Sub(time.Millisecond), t1)
+}