From 594d20d5a56175595404221490f33a7cf892c990 Mon Sep 17 00:00:00 2001 From: hongyunyan <649330952@qq.com> Date: Mon, 28 Nov 2022 20:14:00 +0800 Subject: [PATCH] Explain : Support more info from tiflash in explain analyze (#39216) ref pingcap/tidb#39273 --- DEPS.bzl | 4 +- go.mod | 2 +- go.sum | 4 +- util/execdetails/execdetails.go | 81 +++++++++++++++++++++++++--- util/execdetails/execdetails_test.go | 27 ++++++---- 5 files changed, 96 insertions(+), 22 deletions(-) diff --git a/DEPS.bzl b/DEPS.bzl index 1b08a559d9216..43f76556ecdd9 100644 --- a/DEPS.bzl +++ b/DEPS.bzl @@ -2936,8 +2936,8 @@ def go_deps(): name = "com_github_pingcap_tipb", build_file_proto_mode = "disable_global", importpath = "github.com/pingcap/tipb", - sum = "h1:Yoo8j5xQGxjlsC3yt0ndsiAz0WZXED9rzsKmEN0U0DY=", - version = "v0.0.0-20221020071514-cd933387bcb5", + sum = "h1:DbmCfCbcavo0JG+gSp0ySvv1ub/c/j3hsnYzyYPzONo=", + version = "v0.0.0-20221123081521-2fb828910813", ) go_repository( name = "com_github_pkg_browser", diff --git a/go.mod b/go.mod index 5f5b80a88e44e..f225545bfafd1 100644 --- a/go.mod +++ b/go.mod @@ -72,7 +72,7 @@ require ( github.com/pingcap/log v1.1.1-0.20221116035753-734d527bc87c github.com/pingcap/sysutil v0.0.0-20220114020952-ea68d2dbf5b4 github.com/pingcap/tidb/parser v0.0.0-20211011031125-9b13dc409c5e - github.com/pingcap/tipb v0.0.0-20221020071514-cd933387bcb5 + github.com/pingcap/tipb v0.0.0-20221123081521-2fb828910813 github.com/pkg/errors v0.9.1 github.com/prometheus/client_golang v1.13.0 github.com/prometheus/client_model v0.2.0 diff --git a/go.sum b/go.sum index 179064bd8ed06..70c92d02d2881 100644 --- a/go.sum +++ b/go.sum @@ -789,8 +789,8 @@ github.com/pingcap/log v1.1.1-0.20221116035753-734d527bc87c h1:crhkw6DD+07Bg1wYh github.com/pingcap/log v1.1.1-0.20221116035753-734d527bc87c/go.mod h1:DWQW5jICDR7UJh4HtxXSM20Churx4CQL0fwL/SoOSA4= github.com/pingcap/sysutil v0.0.0-20220114020952-ea68d2dbf5b4 h1:HYbcxtnkN3s5tqrZ/z3eJS4j3Db8wMphEm1q10lY/TM= github.com/pingcap/sysutil v0.0.0-20220114020952-ea68d2dbf5b4/go.mod h1:sDCsM39cGiv2vwunZkaFA917vVkqDTGSPbbV7z4Oops= -github.com/pingcap/tipb v0.0.0-20221020071514-cd933387bcb5 h1:Yoo8j5xQGxjlsC3yt0ndsiAz0WZXED9rzsKmEN0U0DY= -github.com/pingcap/tipb v0.0.0-20221020071514-cd933387bcb5/go.mod h1:A7mrd7WHBl1o63LE2bIBGEJMTNWXqhgmYiOvMLxozfs= +github.com/pingcap/tipb v0.0.0-20221123081521-2fb828910813 h1:DbmCfCbcavo0JG+gSp0ySvv1ub/c/j3hsnYzyYPzONo= +github.com/pingcap/tipb v0.0.0-20221123081521-2fb828910813/go.mod h1:A7mrd7WHBl1o63LE2bIBGEJMTNWXqhgmYiOvMLxozfs= github.com/pkg/browser v0.0.0-20180916011732-0a3d74bf9ce4 h1:49lOXmGaUpV9Fz3gd7TFZY106KVlPVa5jcYD1gaQf98= github.com/pkg/browser v0.0.0-20180916011732-0a3d74bf9ce4/go.mod h1:4OwLy04Bl9Ef3GJJCoec+30X3LQs/0/m4HFRt/2LUSA= github.com/pkg/errors v0.8.0/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= diff --git a/util/execdetails/execdetails.go b/util/execdetails/execdetails.go index c1c65499ec288..76e468cf38f50 100644 --- a/util/execdetails/execdetails.go +++ b/util/execdetails/execdetails.go @@ -326,7 +326,7 @@ type basicCopRuntimeStats struct { // String implements the RuntimeStats interface. func (e *basicCopRuntimeStats) String() string { if e.storeType == "tiflash" { - return fmt.Sprintf("time:%v, loops:%d, threads:%d", FormatDuration(time.Duration(e.consume)), e.loop, e.threads) + return fmt.Sprintf("time:%v, loops:%d, threads:%d, ", FormatDuration(time.Duration(e.consume)), e.loop, e.threads) + e.BasicRuntimeStats.tiflashScanContext.String() } return fmt.Sprintf("time:%v, loops:%d", FormatDuration(time.Duration(e.consume)), e.loop) } @@ -334,7 +334,7 @@ func (e *basicCopRuntimeStats) String() string { // Clone implements the RuntimeStats interface. func (e *basicCopRuntimeStats) Clone() RuntimeStats { return &basicCopRuntimeStats{ - BasicRuntimeStats: BasicRuntimeStats{loop: e.loop, consume: e.consume, rows: e.rows}, + BasicRuntimeStats: BasicRuntimeStats{loop: e.loop, consume: e.consume, rows: e.rows, tiflashScanContext: e.tiflashScanContext.Clone()}, threads: e.threads, storeType: e.storeType, } @@ -375,10 +375,19 @@ type CopRuntimeStats struct { func (crs *CopRuntimeStats) RecordOneCopTask(address string, summary *tipb.ExecutorExecutionSummary) { crs.Lock() defer crs.Unlock() + crs.stats[address] = append(crs.stats[address], &basicCopRuntimeStats{BasicRuntimeStats: BasicRuntimeStats{loop: int32(*summary.NumIterations), consume: int64(*summary.TimeProcessedNs), - rows: int64(*summary.NumProducedRows)}, + rows: int64(*summary.NumProducedRows), + tiflashScanContext: TiFlashScanContext{ + totalDmfileScannedPacks: summary.GetTiflashScanContext().GetTotalDmfileScannedPacks(), + totalDmfileSkippedPacks: summary.GetTiflashScanContext().GetTotalDmfileSkippedPacks(), + totalDmfileScannedRows: summary.GetTiflashScanContext().GetTotalDmfileScannedRows(), + totalDmfileSkippedRows: summary.GetTiflashScanContext().GetTotalDmfileSkippedRows(), + totalDmfileRoughSetIndexLoadTimeMs: summary.GetTiflashScanContext().GetTotalDmfileRoughSetIndexLoadTimeMs(), + totalDmfileReadTimeMs: summary.GetTiflashScanContext().GetTotalDmfileReadTimeMs(), + totalCreateSnapshotTimeMs: summary.GetTiflashScanContext().GetTotalCreateSnapshotTimeMs()}}, threads: int32(summary.GetConcurrency()), storeType: crs.storeType}) } @@ -394,14 +403,16 @@ func (crs *CopRuntimeStats) GetActRows() (totalRows int64) { } // MergeBasicStats traverses basicCopRuntimeStats in the CopRuntimeStats and collects some useful information. -func (crs *CopRuntimeStats) MergeBasicStats() (procTimes []time.Duration, totalTime time.Duration, totalTasks, totalLoops, totalThreads int32) { +func (crs *CopRuntimeStats) MergeBasicStats() (procTimes []time.Duration, totalTime time.Duration, totalTasks, totalLoops, totalThreads int32, totalTiFlashScanContext TiFlashScanContext) { procTimes = make([]time.Duration, 0, 32) + totalTiFlashScanContext = TiFlashScanContext{} for _, instanceStats := range crs.stats { for _, stat := range instanceStats { procTimes = append(procTimes, time.Duration(stat.consume)*time.Nanosecond) totalTime += time.Duration(stat.consume) totalLoops += stat.loop totalThreads += stat.threads + totalTiFlashScanContext.Merge(stat.tiflashScanContext) totalTasks++ } } @@ -413,7 +424,7 @@ func (crs *CopRuntimeStats) String() string { return "" } - procTimes, totalTime, totalTasks, totalLoops, totalThreads := crs.MergeBasicStats() + procTimes, totalTime, totalTasks, totalLoops, totalThreads, totalTiFlashScanContext := crs.MergeBasicStats() avgTime := time.Duration(totalTime.Nanoseconds() / int64(totalTasks)) isTiFlashCop := crs.storeType == "tiflash" @@ -422,6 +433,9 @@ func (crs *CopRuntimeStats) String() string { buf.WriteString(fmt.Sprintf("%v_task:{time:%v, loops:%d", crs.storeType, FormatDuration(procTimes[0]), totalLoops)) if isTiFlashCop { buf.WriteString(fmt.Sprintf(", threads:%d}", totalThreads)) + if !totalTiFlashScanContext.Empty() { + buf.WriteString(", " + totalTiFlashScanContext.String()) + } } else { buf.WriteString("}") } @@ -433,6 +447,9 @@ func (crs *CopRuntimeStats) String() string { FormatDuration(procTimes[n*4/5]), FormatDuration(procTimes[n*19/20]), totalLoops, totalTasks)) if isTiFlashCop { buf.WriteString(fmt.Sprintf(", threads:%d}", totalThreads)) + if !totalTiFlashScanContext.Empty() { + buf.WriteString(", " + totalTiFlashScanContext.String()) + } } else { buf.WriteString("}") } @@ -490,6 +507,50 @@ type RuntimeStats interface { Tp() int } +// TiFlashScanContext is used to express the table scan information in tiflash +type TiFlashScanContext struct { + totalDmfileScannedPacks uint64 + totalDmfileScannedRows uint64 + totalDmfileSkippedPacks uint64 + totalDmfileSkippedRows uint64 + totalDmfileRoughSetIndexLoadTimeMs uint64 + totalDmfileReadTimeMs uint64 + totalCreateSnapshotTimeMs uint64 +} + +// Clone implements the deep copy of * TiFlashshScanContext +func (context *TiFlashScanContext) Clone() TiFlashScanContext { + return TiFlashScanContext{ + totalDmfileScannedPacks: context.totalDmfileScannedPacks, + totalDmfileScannedRows: context.totalDmfileScannedRows, + totalDmfileSkippedPacks: context.totalDmfileSkippedPacks, + totalDmfileSkippedRows: context.totalDmfileSkippedRows, + totalDmfileRoughSetIndexLoadTimeMs: context.totalDmfileRoughSetIndexLoadTimeMs, + totalDmfileReadTimeMs: context.totalDmfileReadTimeMs, + totalCreateSnapshotTimeMs: context.totalCreateSnapshotTimeMs, + } +} +func (context *TiFlashScanContext) String() string { + return fmt.Sprintf("tiflash_scan:{dmfile:{total_scanned_packs:%d, total_skipped_packs:%d, total_scanned_rows:%d, total_skipped_rows:%d, total_rough_set_index_load_time: %dms, total_read_time: %dms}, total_create_snapshot_time: %dms}", context.totalDmfileScannedPacks, context.totalDmfileSkippedPacks, context.totalDmfileScannedRows, context.totalDmfileSkippedRows, context.totalDmfileRoughSetIndexLoadTimeMs, context.totalDmfileReadTimeMs, context.totalCreateSnapshotTimeMs) +} + +// Merge make sum to merge the information in TiFlashScanContext +func (context *TiFlashScanContext) Merge(other TiFlashScanContext) { + context.totalDmfileScannedPacks += other.totalDmfileScannedPacks + context.totalDmfileScannedRows += other.totalDmfileScannedRows + context.totalDmfileSkippedPacks += other.totalDmfileSkippedPacks + context.totalDmfileSkippedRows += other.totalDmfileSkippedRows + context.totalDmfileRoughSetIndexLoadTimeMs += other.totalDmfileRoughSetIndexLoadTimeMs + context.totalDmfileReadTimeMs += other.totalDmfileReadTimeMs + context.totalCreateSnapshotTimeMs += other.totalCreateSnapshotTimeMs +} + +// Empty check whether TiFlashScanContext is Empty, if scan no pack and skip no pack, we regard it as empty +func (context *TiFlashScanContext) Empty() bool { + res := (context.totalDmfileScannedPacks == 0 && context.totalDmfileSkippedPacks == 0) + return res +} + // BasicRuntimeStats is the basic runtime stats. type BasicRuntimeStats struct { // executor's Next() called times. @@ -498,6 +559,8 @@ type BasicRuntimeStats struct { consume int64 // executor return row count. rows int64 + // executor extra infos + tiflashScanContext TiFlashScanContext } // GetActRows return total rows of BasicRuntimeStats. @@ -508,9 +571,10 @@ func (e *BasicRuntimeStats) GetActRows() int64 { // Clone implements the RuntimeStats interface. func (e *BasicRuntimeStats) Clone() RuntimeStats { return &BasicRuntimeStats{ - loop: e.loop, - consume: e.consume, - rows: e.rows, + loop: e.loop, + consume: e.consume, + rows: e.rows, + tiflashScanContext: e.tiflashScanContext.Clone(), } } @@ -523,6 +587,7 @@ func (e *BasicRuntimeStats) Merge(rs RuntimeStats) { e.loop += tmp.loop e.consume += tmp.consume e.rows += tmp.rows + e.tiflashScanContext.Merge(tmp.tiflashScanContext) } // Tp implements the RuntimeStats interface. diff --git a/util/execdetails/execdetails_test.go b/util/execdetails/execdetails_test.go index 1f14f9f933509..2740e10b321cb 100644 --- a/util/execdetails/execdetails_test.go +++ b/util/execdetails/execdetails_test.go @@ -135,9 +135,18 @@ func mockExecutorExecutionSummary(TimeProcessedNs, NumProducedRows, NumIteration NumIterations: &NumIterations, XXX_unrecognized: nil} } -func mockExecutorExecutionSummaryForTiFlash(TimeProcessedNs, NumProducedRows, NumIterations, Concurrency uint64, ExecutorID string) *tipb.ExecutorExecutionSummary { +func mockExecutorExecutionSummaryForTiFlash(TimeProcessedNs, NumProducedRows, NumIterations, Concurrency, totalDmfileScannedPacks, totalDmfileScannedRows, totalDmfileSkippedPacks, totalDmfileSkippedRows, totalDmfileRoughSetIndexLoadTimeMs, totalDmfileReadTimeMs, totalCreateSnapshotTimeMs uint64, ExecutorID string) *tipb.ExecutorExecutionSummary { + tiflashScanContext := tipb.TiFlashScanContext{ + TotalDmfileScannedPacks: &totalDmfileScannedPacks, + TotalDmfileSkippedPacks: &totalDmfileSkippedPacks, + TotalDmfileScannedRows: &totalDmfileScannedRows, + TotalDmfileSkippedRows: &totalDmfileSkippedRows, + TotalDmfileRoughSetIndexLoadTimeMs: &totalDmfileRoughSetIndexLoadTimeMs, + TotalDmfileReadTimeMs: &totalDmfileReadTimeMs, + TotalCreateSnapshotTimeMs: &totalCreateSnapshotTimeMs, + } return &tipb.ExecutorExecutionSummary{TimeProcessedNs: &TimeProcessedNs, NumProducedRows: &NumProducedRows, - NumIterations: &NumIterations, Concurrency: &Concurrency, ExecutorId: &ExecutorID, XXX_unrecognized: nil} + NumIterations: &NumIterations, Concurrency: &Concurrency, ExecutorId: &ExecutorID, DetailInfo: &tipb.ExecutorExecutionSummary_TiflashScanContext{TiflashScanContext: &tiflashScanContext}, XXX_unrecognized: nil} } func TestCopRuntimeStats(t *testing.T) { @@ -197,10 +206,10 @@ func TestCopRuntimeStatsForTiFlash(t *testing.T) { tableScanID := 1 aggID := 2 tableReaderID := 3 - stats.RecordOneCopTask(aggID, "tiflash", "8.8.8.8", mockExecutorExecutionSummaryForTiFlash(1, 1, 1, 1, "tablescan_"+strconv.Itoa(tableScanID))) - stats.RecordOneCopTask(aggID, "tiflash", "8.8.8.9", mockExecutorExecutionSummaryForTiFlash(2, 2, 2, 1, "tablescan_"+strconv.Itoa(tableScanID))) - stats.RecordOneCopTask(tableScanID, "tiflash", "8.8.8.8", mockExecutorExecutionSummaryForTiFlash(3, 3, 3, 1, "aggregation_"+strconv.Itoa(aggID))) - stats.RecordOneCopTask(tableScanID, "tiflash", "8.8.8.9", mockExecutorExecutionSummaryForTiFlash(4, 4, 4, 1, "aggregation_"+strconv.Itoa(aggID))) + stats.RecordOneCopTask(aggID, "tiflash", "8.8.8.8", mockExecutorExecutionSummaryForTiFlash(1, 1, 1, 1, 1, 8192, 0, 0, 15, 200, 40, "tablescan_"+strconv.Itoa(tableScanID))) + stats.RecordOneCopTask(aggID, "tiflash", "8.8.8.9", mockExecutorExecutionSummaryForTiFlash(2, 2, 2, 1, 0, 0, 0, 0, 0, 2, 0, "tablescan_"+strconv.Itoa(tableScanID))) + stats.RecordOneCopTask(tableScanID, "tiflash", "8.8.8.8", mockExecutorExecutionSummaryForTiFlash(3, 3, 3, 1, 2, 12000, 1, 6000, 60, 1000, 20, "aggregation_"+strconv.Itoa(aggID))) + stats.RecordOneCopTask(tableScanID, "tiflash", "8.8.8.9", mockExecutorExecutionSummaryForTiFlash(4, 4, 4, 1, 1, 8192, 10, 80000, 40, 2000, 30, "aggregation_"+strconv.Itoa(aggID))) scanDetail := &util.ScanDetail{ TotalKeys: 10, ProcessedKeys: 10, @@ -214,15 +223,15 @@ func TestCopRuntimeStatsForTiFlash(t *testing.T) { require.True(t, stats.ExistsCopStats(tableScanID)) cop := stats.GetOrCreateCopStats(tableScanID, "tiflash") - require.Equal(t, "tiflash_task:{proc max:2ns, min:1ns, avg: 1ns, p80:2ns, p95:2ns, iters:3, tasks:2, threads:2}", cop.String()) + require.Equal(t, "tiflash_task:{proc max:2ns, min:1ns, avg: 1ns, p80:2ns, p95:2ns, iters:3, tasks:2, threads:2}, tiflash_scan:{dmfile:{total_scanned_packs:1, total_skipped_packs:0, total_scanned_rows:8192, total_skipped_rows:0, total_rough_set_index_load_time: 15ms, total_read_time: 202ms}, total_create_snapshot_time: 40ms}", cop.String()) copStats := cop.stats["8.8.8.8"] require.NotNil(t, copStats) copStats[0].SetRowNum(10) copStats[0].Record(time.Second, 10) - require.Equal(t, "time:1s, loops:2, threads:1", copStats[0].String()) - expected := "tiflash_task:{proc max:4ns, min:3ns, avg: 3ns, p80:4ns, p95:4ns, iters:7, tasks:2, threads:2}" + require.Equal(t, "time:1s, loops:2, threads:1, tiflash_scan:{dmfile:{total_scanned_packs:1, total_skipped_packs:0, total_scanned_rows:8192, total_skipped_rows:0, total_rough_set_index_load_time: 15ms, total_read_time: 200ms}, total_create_snapshot_time: 40ms}", copStats[0].String()) + expected := "tiflash_task:{proc max:4ns, min:3ns, avg: 3ns, p80:4ns, p95:4ns, iters:7, tasks:2, threads:2}, tiflash_scan:{dmfile:{total_scanned_packs:3, total_skipped_packs:11, total_scanned_rows:20192, total_skipped_rows:86000, total_rough_set_index_load_time: 100ms, total_read_time: 3000ms}, total_create_snapshot_time: 50ms}" require.Equal(t, expected, stats.GetOrCreateCopStats(aggID, "tiflash").String()) rootStats := stats.GetRootStats(tableReaderID)