From aa3da68a444c56b043054323b92927791524e533 Mon Sep 17 00:00:00 2001 From: lzmhhh123 Date: Fri, 11 Sep 2020 14:28:25 +0800 Subject: [PATCH 1/6] executor: add coprocessor cache hit rate in explain analyze --- distsql/select_result.go | 8 ++++++++ planner/core/cbo_test.go | 3 +++ store/tikv/coprocessor.go | 3 +++ util/execdetails/execdetails.go | 2 ++ 4 files changed, 16 insertions(+) diff --git a/distsql/select_result.go b/distsql/select_result.go index 2e896705e9897..7da5db8200c03 100644 --- a/distsql/select_result.go +++ b/distsql/select_result.go @@ -329,6 +329,7 @@ type selectResultRuntimeStats struct { totalProcessTime time.Duration totalWaitTime time.Duration rpcStat tikv.RegionRequestRuntimeStats + CoprCacheHit int64 } func (s *selectResultRuntimeStats) mergeCopRuntimeStats(copStats *tikv.CopRuntimeStats, respTime time.Duration) { @@ -341,6 +342,9 @@ func (s *selectResultRuntimeStats) mergeCopRuntimeStats(copStats *tikv.CopRuntim s.totalProcessTime += copStats.ProcessTime s.totalWaitTime += copStats.WaitTime s.rpcStat.Merge(copStats.RegionRequestRuntimeStats) + if copStats.CoprCacheHit { + s.CoprCacheHit++ + } } func (s *selectResultRuntimeStats) merge(other *selectResultRuntimeStats) { @@ -353,6 +357,7 @@ func (s *selectResultRuntimeStats) merge(other *selectResultRuntimeStats) { s.totalProcessTime += other.totalProcessTime s.totalWaitTime += other.totalWaitTime s.rpcStat.Merge(other.rpcStat) + s.CoprCacheHit += other.CoprCacheHit } func (s *selectResultRuntimeStats) String() string { @@ -367,6 +372,7 @@ func (s *selectResultRuntimeStats) String() string { s.backoffSleep = nil s.totalWaitTime = 0 s.totalProcessTime = 0 + s.CoprCacheHit = 0 s.rpcStat = tikv.RegionRequestRuntimeStats{} return stats.String() } @@ -419,6 +425,8 @@ func (s *selectResultRuntimeStats) String() string { buf.WriteString(", rpc_time: ") buf.WriteString(time.Duration(copRPC.Consume).String()) } + buf.WriteString(fmt.Sprintf(", copr_cache_hit_rate: %v", + strconv.FormatFloat(float64(s.CoprCacheHit)/float64(len(s.copRespTime)), 'f',2, 64))) buf.WriteString("}") rpcStatsStr := s.rpcStat.String() diff --git a/planner/core/cbo_test.go b/planner/core/cbo_test.go index f1bddd269d7e0..485ca945c08ad 100644 --- a/planner/core/cbo_test.go +++ b/planner/core/cbo_test.go @@ -99,6 +99,9 @@ func (s *testAnalyzeSuite) TestExplainAnalyze(c *C) { execInfo := row[5].(string) c.Assert(strings.Contains(execInfo, "time"), Equals, true) c.Assert(strings.Contains(execInfo, "loops"), Equals, true) + if strings.Contains(row[0].(string), "Reader") || strings.Contains(row[0].(string), "IndexLookUp") { + c.Assert(strings.Contains(execInfo, "copr_cache_hit_rate"), Equals, true) + } } } diff --git a/store/tikv/coprocessor.go b/store/tikv/coprocessor.go index 7256a0fe5b06e..6783b865ea5cb 100644 --- a/store/tikv/coprocessor.go +++ b/store/tikv/coprocessor.go @@ -1063,6 +1063,7 @@ func (worker *copIteratorWorker) handleCopResponse(bo *Backoffer, rpcCtx *RPCCon data := make([]byte, len(cacheValue.Data)) copy(data, cacheValue.Data) resp.pbResp.Data = data + resp.detail.CoprCacheHit = true } else { // Cache not hit or cache hit but not valid: update the cache if the response can be cached. if cacheKey != nil && resp.pbResp.CanBeCached && resp.pbResp.CacheLastVersion > 0 { @@ -1088,6 +1089,8 @@ func (worker *copIteratorWorker) handleCopResponse(bo *Backoffer, rpcCtx *RPCCon type CopRuntimeStats struct { execdetails.ExecDetails RegionRequestRuntimeStats + + CoprCacheHit bool } func (worker *copIteratorWorker) handleTiDBSendReqErr(err error, task *copTask, ch chan<- *copResponse) error { diff --git a/util/execdetails/execdetails.go b/util/execdetails/execdetails.go index c8e5e245d17ad..c10a31e8025cf 100644 --- a/util/execdetails/execdetails.go +++ b/util/execdetails/execdetails.go @@ -312,6 +312,8 @@ type CopRuntimeStats struct { // same tikv-server instance. We have to use a list to maintain all tasks // executed on each instance. stats map[string][]*BasicRuntimeStats + + copCacheHit bool } // RecordOneCopTask records a specific cop tasks's execution detail. From 5a8b97bca9476a4a63d770c884b097d747f14141 Mon Sep 17 00:00:00 2001 From: lzmhhh123 Date: Fri, 11 Sep 2020 14:38:48 +0800 Subject: [PATCH 2/6] fix fmt --- distsql/select_result.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/distsql/select_result.go b/distsql/select_result.go index bc96a9043c122..fa7ec2d474afb 100644 --- a/distsql/select_result.go +++ b/distsql/select_result.go @@ -427,8 +427,8 @@ func (s *selectResultRuntimeStats) String() string { buf.WriteString(", rpc_time: ") buf.WriteString(time.Duration(copRPC.Consume).String()) } - buf.WriteString(fmt.Sprintf(", copr_cache_hit_rate: %v", - strconv.FormatFloat(float64(s.CoprCacheHit)/float64(len(s.copRespTime)), 'f',2, 64))) + buf.WriteString(fmt.Sprintf(", copr_cache_hit_rate: %v", + strconv.FormatFloat(float64(s.CoprCacheHit)/float64(len(s.copRespTime)), 'f', 2, 64))) buf.WriteString("}") } From 7709c6ff7d6dce8d719541a35ba274e3c3170db8 Mon Sep 17 00:00:00 2001 From: lzmhhh123 Date: Fri, 11 Sep 2020 14:41:47 +0800 Subject: [PATCH 3/6] rename coprCacheHit to coprCacheHitNum --- distsql/select_result.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/distsql/select_result.go b/distsql/select_result.go index fa7ec2d474afb..47a0fec321ae6 100644 --- a/distsql/select_result.go +++ b/distsql/select_result.go @@ -325,7 +325,7 @@ type selectResultRuntimeStats struct { totalProcessTime time.Duration totalWaitTime time.Duration rpcStat tikv.RegionRequestRuntimeStats - CoprCacheHit int64 + CoprCacheHitNum int64 } func (s *selectResultRuntimeStats) mergeCopRuntimeStats(copStats *tikv.CopRuntimeStats, respTime time.Duration) { @@ -339,7 +339,7 @@ func (s *selectResultRuntimeStats) mergeCopRuntimeStats(copStats *tikv.CopRuntim s.totalWaitTime += copStats.WaitTime s.rpcStat.Merge(copStats.RegionRequestRuntimeStats) if copStats.CoprCacheHit { - s.CoprCacheHit++ + s.CoprCacheHitNum++ } } @@ -377,7 +377,7 @@ func (s *selectResultRuntimeStats) Merge(rs execdetails.RuntimeStats) { s.totalProcessTime += other.totalProcessTime s.totalWaitTime += other.totalWaitTime s.rpcStat.Merge(other.rpcStat) - s.CoprCacheHit += other.CoprCacheHit + s.CoprCacheHitNum += other.CoprCacheHitNum } func (s *selectResultRuntimeStats) String() string { @@ -428,7 +428,7 @@ func (s *selectResultRuntimeStats) String() string { buf.WriteString(time.Duration(copRPC.Consume).String()) } buf.WriteString(fmt.Sprintf(", copr_cache_hit_rate: %v", - strconv.FormatFloat(float64(s.CoprCacheHit)/float64(len(s.copRespTime)), 'f', 2, 64))) + strconv.FormatFloat(float64(s.CoprCacheHitNum)/float64(len(s.copRespTime)), 'f', 2, 64))) buf.WriteString("}") } From 9bb478be9cf643a57663c751fcf22e3abb1cdcec Mon Sep 17 00:00:00 2001 From: lzmhhh123 Date: Fri, 11 Sep 2020 14:44:34 +0800 Subject: [PATCH 4/6] rm unnecessory fields --- util/execdetails/execdetails.go | 2 -- 1 file changed, 2 deletions(-) diff --git a/util/execdetails/execdetails.go b/util/execdetails/execdetails.go index 7ae048a267ac4..3da02d56185a2 100644 --- a/util/execdetails/execdetails.go +++ b/util/execdetails/execdetails.go @@ -363,8 +363,6 @@ type CopRuntimeStats struct { // same tikv-server instance. We have to use a list to maintain all tasks // executed on each instance. stats map[string][]*BasicRuntimeStats - - copCacheHit bool } // RecordOneCopTask records a specific cop tasks's execution detail. From cdc4a471fa86a16aba4aeaa8d88bff85c702f7bf Mon Sep 17 00:00:00 2001 From: lzmhhh123 Date: Fri, 11 Sep 2020 14:50:46 +0800 Subject: [PATCH 5/6] fix test --- distsql/distsql_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/distsql/distsql_test.go b/distsql/distsql_test.go index a0378d63e72e6..cdf8399442edc 100644 --- a/distsql/distsql_test.go +++ b/distsql/distsql_test.go @@ -175,7 +175,7 @@ func (s *testSuite) TestSelectResultRuntimeStats(c *C) { stmtStats.RegisterStats(1, s1) stmtStats.RegisterStats(1, &s2) stats := stmtStats.GetRootStats(1) - expect := "time:1s, loops:1, cop_task: {num: 4, max: 1s, min: 1ms, avg: 500.5ms, p95: 1s, max_proc_keys: 200, p95_proc_keys: 200, tot_proc: 2s, tot_wait: 2s}, backoff{RegionMiss: 2ms}" + expect := "time:1s, loops:1, cop_task: {num: 4, max: 1s, min: 1ms, avg: 500.5ms, p95: 1s, max_proc_keys: 200, p95_proc_keys: 200, tot_proc: 2s, tot_wait: 2s, copr_cache_hit_rate: 0.00}, backoff{RegionMiss: 2ms}" c.Assert(stats.String(), Equals, expect) // Test for idempotence. c.Assert(stats.String(), Equals, expect) From 2161de8c771fb1151671c47eb09fb01978d71e3c Mon Sep 17 00:00:00 2001 From: lzmhhh123 Date: Mon, 14 Sep 2020 13:30:35 +0800 Subject: [PATCH 6/6] change hit-rate to hit-ratio --- distsql/distsql_test.go | 2 +- distsql/select_result.go | 2 +- planner/core/cbo_test.go | 2 +- 3 files changed, 3 insertions(+), 3 deletions(-) diff --git a/distsql/distsql_test.go b/distsql/distsql_test.go index cdf8399442edc..5a5cfa8230db1 100644 --- a/distsql/distsql_test.go +++ b/distsql/distsql_test.go @@ -175,7 +175,7 @@ func (s *testSuite) TestSelectResultRuntimeStats(c *C) { stmtStats.RegisterStats(1, s1) stmtStats.RegisterStats(1, &s2) stats := stmtStats.GetRootStats(1) - expect := "time:1s, loops:1, cop_task: {num: 4, max: 1s, min: 1ms, avg: 500.5ms, p95: 1s, max_proc_keys: 200, p95_proc_keys: 200, tot_proc: 2s, tot_wait: 2s, copr_cache_hit_rate: 0.00}, backoff{RegionMiss: 2ms}" + expect := "time:1s, loops:1, cop_task: {num: 4, max: 1s, min: 1ms, avg: 500.5ms, p95: 1s, max_proc_keys: 200, p95_proc_keys: 200, tot_proc: 2s, tot_wait: 2s, copr_cache_hit_ratio: 0.00}, backoff{RegionMiss: 2ms}" c.Assert(stats.String(), Equals, expect) // Test for idempotence. c.Assert(stats.String(), Equals, expect) diff --git a/distsql/select_result.go b/distsql/select_result.go index 47a0fec321ae6..42cc246f4c536 100644 --- a/distsql/select_result.go +++ b/distsql/select_result.go @@ -427,7 +427,7 @@ func (s *selectResultRuntimeStats) String() string { buf.WriteString(", rpc_time: ") buf.WriteString(time.Duration(copRPC.Consume).String()) } - buf.WriteString(fmt.Sprintf(", copr_cache_hit_rate: %v", + buf.WriteString(fmt.Sprintf(", copr_cache_hit_ratio: %v", strconv.FormatFloat(float64(s.CoprCacheHitNum)/float64(len(s.copRespTime)), 'f', 2, 64))) buf.WriteString("}") } diff --git a/planner/core/cbo_test.go b/planner/core/cbo_test.go index 485ca945c08ad..07c2d212c533d 100644 --- a/planner/core/cbo_test.go +++ b/planner/core/cbo_test.go @@ -100,7 +100,7 @@ func (s *testAnalyzeSuite) TestExplainAnalyze(c *C) { c.Assert(strings.Contains(execInfo, "time"), Equals, true) c.Assert(strings.Contains(execInfo, "loops"), Equals, true) if strings.Contains(row[0].(string), "Reader") || strings.Contains(row[0].(string), "IndexLookUp") { - c.Assert(strings.Contains(execInfo, "copr_cache_hit_rate"), Equals, true) + c.Assert(strings.Contains(execInfo, "copr_cache_hit_ratio"), Equals, true) } } }