From 837db0b7e68b5f492b023285f878f8efe785821a Mon Sep 17 00:00:00 2001 From: djshow832 Date: Thu, 25 Jan 2024 10:58:50 +0800 Subject: [PATCH] router, backend: replace time.Time with mono-time to optimize duration calculation (#461) --- .gitignore | 1 + pkg/manager/router/backend_observer.go | 5 +-- pkg/manager/router/health_check.go | 3 +- pkg/manager/router/metrics.go | 9 ++--- pkg/manager/router/router.go | 3 +- pkg/manager/router/router_score.go | 3 +- pkg/proxy/backend/backend_conn_mgr.go | 7 ++-- pkg/proxy/backend/metrics.go | 5 +-- pkg/util/monotime/monotime.go | 41 +++++++++++++++++++++++ pkg/util/monotime/monotime_test.go | 46 ++++++++++++++++++++++++++ 10 files changed, 109 insertions(+), 14 deletions(-) create mode 100644 pkg/util/monotime/monotime.go create mode 100644 pkg/util/monotime/monotime_test.go diff --git a/.gitignore b/.gitignore index c6c53611..d94bb902 100644 --- a/.gitignore +++ b/.gitignore @@ -8,5 +8,6 @@ vendor work .vscode/ .cover* +coverage.dat grafonnet-lib dist diff --git a/pkg/manager/router/backend_observer.go b/pkg/manager/router/backend_observer.go index 2a580109..3da87d38 100644 --- a/pkg/manager/router/backend_observer.go +++ b/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 { diff --git a/pkg/manager/router/health_check.go b/pkg/manager/router/health_check.go index 0fb61bbd..1bb1ef31 100644 --- a/pkg/manager/router/health_check.go +++ b/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 { diff --git a/pkg/manager/router/metrics.go b/pkg/manager/router/metrics.go index 909bebd3..3a0f58ab 100644 --- a/pkg/manager/router/metrics.go +++ b/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,11 +39,11 @@ 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()) } @@ -50,8 +51,8 @@ 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()) } diff --git a/pkg/manager/router/router.go b/pkg/manager/router/router.go index c37b4253..e476d61f 100644 --- a/pkg/manager/router/router.go +++ b/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 } diff --git a/pkg/manager/router/router_score.go b/pkg/manager/router/router_score.go index 97e5ff68..dca4df4e 100644 --- a/pkg/manager/router/router_score.go +++ b/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++ { diff --git a/pkg/proxy/backend/backend_conn_mgr.go b/pkg/proxy/backend/backend_conn_mgr.go index 2103685a..eca620e7 100644 --- a/pkg/proxy/backend/backend_conn_mgr.go +++ b/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 { diff --git a/pkg/proxy/backend/metrics.go b/pkg/proxy/backend/metrics.go index 7f9ea870..9f0d4885 100644 --- a/pkg/proxy/backend/metrics.go +++ b/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()) } diff --git a/pkg/util/monotime/monotime.go b/pkg/util/monotime/monotime.go new file mode 100644 index 00000000..085a805b --- /dev/null +++ b/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 +} diff --git a/pkg/util/monotime/monotime_test.go b/pkg/util/monotime/monotime_test.go new file mode 100644 index 00000000..ed40db4b --- /dev/null +++ b/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) +}