Skip to content

Commit

Permalink
Add stats io time consumed for stats main (#20892)
Browse files Browse the repository at this point in the history 
1. 对buildPlan阶段Stats函数执行统计其IO等待时间
2. 对buildPlan阶段stats函数执行补充S3 IO 统计

Approved by: @badboynt1, @reusee, @ouyuanning, @daviszhen, @zhangxu19830126, @triump2020, @aunjgr, @XuPeng-SH, @xzxiong
  • Loading branch information
@qingxinhome
qingxinhome authored Dec 25, 2024
1 parent 10bd227 commit 34f9f9b
Show file tree
Hide file tree
Showing 11 changed files with 186 additions and 96 deletions.
37 changes: 11 additions & 26 deletions pkg/frontend/compiler_context.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -842,11 +842,11 @@ func (tcc *TxnCompilerContext) GetPrimaryKeyDef(dbName string, tableName string,
}

func (tcc *TxnCompilerContext) Stats(obj *plan2.ObjectRef, snapshot *plan2.Snapshot) (*pb.StatsInfo, error) {
stats := statistic.StatsInfoFromContext(tcc.execCtx.reqCtx)
statser := statistic.StatsInfoFromContext(tcc.execCtx.reqCtx)
start := time.Now()
defer func() {
v2.TxnStatementStatsDurationHistogram.Observe(time.Since(start).Seconds())
stats.AddBuildPlanStatsConsumption(time.Since(start))
statser.AddBuildPlanStatsConsumption(time.Since(start))
}()

dbName := obj.GetSchemaName()
Expand Down Expand Up @@ -901,47 +901,26 @@ func (tcc *TxnCompilerContext) Stats(obj *plan2.ObjectRef, snapshot *plan2.Snaps
var statsInfo *pb.StatsInfo
// This is a partition table.
if partitionInfo != nil {
crs := new(perfcounter.CounterSet)
statsInfo = plan2.NewStatsInfo()
for _, partitionTable := range partitionInfo.PartitionTableNames {
parCtx, parTable, err := tcc.getRelation(dbName, partitionTable, sub, snapshot)
if err != nil {
return cached, err
}
newParCtx := perfcounter.AttachS3RequestKey(parCtx, crs)

newParCtx := perfcounter.AttachCalcTableStatsKey(parCtx)
parStats, err := parTable.Stats(newParCtx, true)
if err != nil {
return cached, err
}
statsInfo.Merge(parStats)
}

stats.AddBuildPlanStatsS3Request(statistic.S3Request{
List: crs.FileService.S3.List.Load(),
Head: crs.FileService.S3.Head.Load(),
Put: crs.FileService.S3.Put.Load(),
Get: crs.FileService.S3.Get.Load(),
Delete: crs.FileService.S3.Delete.Load(),
DeleteMul: crs.FileService.S3.DeleteMulti.Load(),
})

} else {
crs := new(perfcounter.CounterSet)
newCtx := perfcounter.AttachS3RequestKey(ctx, crs)

newCtx := perfcounter.AttachCalcTableStatsKey(ctx)
statsInfo, err = table.Stats(newCtx, true)
if err != nil {
return cached, err
}

stats.AddBuildPlanStatsS3Request(statistic.S3Request{
List: crs.FileService.S3.List.Load(),
Head: crs.FileService.S3.Head.Load(),
Put: crs.FileService.S3.Put.Load(),
Get: crs.FileService.S3.Get.Load(),
Delete: crs.FileService.S3.Delete.Load(),
DeleteMul: crs.FileService.S3.DeleteMulti.Load(),
})
}

if statsInfo != nil {
Expand All @@ -958,6 +937,12 @@ func (tcc *TxnCompilerContext) UpdateStatsInCache(tid uint64, s *pb.StatsInfo) {
// statsInCache get the *pb.StatsInfo from session cache. If the info is nil, just return nil and false,
// else, check if the info needs to be updated.
func (tcc *TxnCompilerContext) statsInCache(ctx context.Context, dbName string, table engine.Relation, snapshot *plan2.Snapshot) (*pb.StatsInfo, bool) {
statser := statistic.StatsInfoFromContext(tcc.execCtx.reqCtx)
start := time.Now()
defer func() {
statser.AddStatsStatsInCacheDuration(time.Since(start))
}()

s := tcc.GetStatsCache().GetStatsInfo(table.GetTableID(ctx), true)
if s == nil {
return nil, false
Expand Down
14 changes: 10 additions & 4 deletions pkg/frontend/mysql_cmd_executor.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2013,10 +2013,13 @@ func buildPlan(reqCtx context.Context, ses FeSession, ctx plan2.CompilerContext,
v2.TxnStatementBuildPlanDurationHistogram.Observe(cost.Seconds())
}()

stats := statistic.StatsInfoFromContext(reqCtx)
// NOTE: The context used by buildPlan comes from the CompilerContext object
planContext := ctx.GetContext()
stats := statistic.StatsInfoFromContext(planContext)
stats.PlanStart()
crs := new(perfcounter.CounterSet)
reqCtx = perfcounter.AttachBuildPlanMarkKey(reqCtx, crs)
planContext = perfcounter.AttachBuildPlanMarkKey(planContext, crs)
ctx.SetContext(planContext)
defer func() {
stats.AddBuildPlanS3Request(statistic.S3Request{
List: crs.FileService.S3.List.Load(),
Expand Down Expand Up @@ -3756,12 +3759,14 @@ func (h *marshalPlanHandler) Stats(ctx context.Context, ses FeSession) (statsByt
int64(statsInfo.PlanStage.PlanDuration) +
int64(statsInfo.CompileStage.CompileDuration) +
statsInfo.PrepareRunStage.ScopePrepareDuration +
statsInfo.PrepareRunStage.CompilePreRunOnceDuration - statsInfo.PrepareRunStage.CompilePreRunOnceWaitLock -
statsInfo.PrepareRunStage.CompilePreRunOnceDuration -
statsInfo.PrepareRunStage.CompilePreRunOnceWaitLock -
statsInfo.PlanStage.BuildPlanStatsIOConsumption -
(statsInfo.IOAccessTimeConsumption + statsInfo.S3FSPrefetchFileIOMergerTimeConsumption)

if totalTime < 0 {
if !h.isInternalSubStmt {
ses.Infof(ctx, "negative cpu statement_id:%s, statement_type:%s, statsInfo:[Parse(%d)+BuildPlan(%d)+Compile(%d)+PhyExec(%d)+PrepareRun(%d)-PreRunWaitLock(%d)-IOAccess(%d)-IOMerge(%d) = %d]",
ses.Infof(ctx, "negative cpu statement_id:%s, statement_type:%s, statsInfo:[Parse(%d)+BuildPlan(%d)+Compile(%d)+PhyExec(%d)+PrepareRun(%d)-PreRunWaitLock(%d)-PlanStatsIO(%d)-IOAccess(%d)-IOMerge(%d) = %d]",
uuid.UUID(h.stmt.StatementID).String(),
h.stmt.StatementType,
statsInfo.ParseStage.ParseDuration,
Expand All @@ -3770,6 +3775,7 @@ func (h *marshalPlanHandler) Stats(ctx context.Context, ses FeSession) (statsByt
operatorTimeConsumed,
statsInfo.PrepareRunStage.ScopePrepareDuration+statsInfo.PrepareRunStage.CompilePreRunOnceDuration,
statsInfo.PrepareRunStage.CompilePreRunOnceWaitLock,
statsInfo.PlanStage.BuildPlanStatsIOConsumption,
statsInfo.IOAccessTimeConsumption,
statsInfo.S3FSPrefetchFileIOMergerTimeConsumption,
totalTime,
Expand Down
9 changes: 9 additions & 0 deletions pkg/pb/statsinfo/statsinfo.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -15,11 +15,20 @@
package statsinfo

import (
"context"
"math"

"golang.org/x/exp/constraints"
)

// StatsInfoKeyWithContext associates a statistics key with a context.
// This struct is used to tie a statistics key (Key) with the context (Ctx) during an operation,
// allowing context-related actions and management while handling statistics information.
type StatsInfoKeyWithContext struct {
Ctx context.Context
Key StatsInfoKey
}

func (sc *StatsInfo) NeedUpdate(currentApproxObjNum int64) bool {
if sc.ApproxObjectNumber == 0 || sc.AccurateObjectNumber == 0 {
return true
Expand Down
19 changes: 19 additions & 0 deletions pkg/perfcounter/context.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -134,3 +134,22 @@ type ExecPipelineMarkKey struct{}
func AttachExecPipelineKey(ctx context.Context, counter *CounterSet) context.Context {
return context.WithValue(ctx, ExecPipelineMarkKey{}, counter)
}

// ------------------------------------------------------------------------------------------------
type CalcTableStatsKey struct{}

func AttachCalcTableStatsKey(ctx context.Context) context.Context {
return context.WithValue(ctx, CalcTableStatsKey{}, true)
}

type CalcTableSizeKey struct{}

func AttachCalcTableSizeKey(ctx context.Context) context.Context {
return context.WithValue(ctx, CalcTableSizeKey{}, true)
}

type CalcTableRowsKey struct{}

func AttachCalcTableRowsKey(ctx context.Context) context.Context {
return context.WithValue(ctx, CalcTableRowsKey{}, true)
}
18 changes: 15 additions & 3 deletions pkg/sql/compile/analyze_module.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -511,25 +511,26 @@ func explainResourceOverview(queryResult *util.RunResult, statsInfo *statistic.S
cpuTimeVal := gblStats.OperatorTimeConsumed +
int64(statsInfo.ParseStage.ParseDuration+statsInfo.PlanStage.PlanDuration+statsInfo.CompileStage.CompileDuration) +
statsInfo.PrepareRunStage.ScopePrepareDuration + statsInfo.PrepareRunStage.CompilePreRunOnceDuration -
statsInfo.PrepareRunStage.CompilePreRunOnceWaitLock -
statsInfo.PrepareRunStage.CompilePreRunOnceWaitLock - statsInfo.PlanStage.BuildPlanStatsIOConsumption -
(statsInfo.IOAccessTimeConsumption + statsInfo.S3FSPrefetchFileIOMergerTimeConsumption)

buffer.WriteString("\tCPU Usage: \n")
buffer.WriteString(fmt.Sprintf("\t\t- Total CPU Time: %dns \n", cpuTimeVal))
buffer.WriteString(fmt.Sprintf("\t\t- CPU Time Detail: Parse(%d)+BuildPlan(%d)+Compile(%d)+PhyExec(%d)+PrepareRun(%d)-PreRunWaitLock(%d)-IOAccess(%d)-IOMerge(%d)\n",
buffer.WriteString(fmt.Sprintf("\t\t- CPU Time Detail: Parse(%d)+BuildPlan(%d)+Compile(%d)+PhyExec(%d)+PrepareRun(%d)-PreRunWaitLock(%d)-PlanStatsIO(%d)-IOAccess(%d)-IOMerge(%d)\n",
statsInfo.ParseStage.ParseDuration,
statsInfo.PlanStage.PlanDuration,
statsInfo.CompileStage.CompileDuration,
gblStats.OperatorTimeConsumed,
gblStats.ScopePrepareTimeConsumed+statsInfo.PrepareRunStage.CompilePreRunOnceDuration,
statsInfo.PrepareRunStage.CompilePreRunOnceWaitLock,
statsInfo.PlanStage.BuildPlanStatsIOConsumption,
statsInfo.IOAccessTimeConsumption,
statsInfo.S3FSPrefetchFileIOMergerTimeConsumption))

//-------------------------------------------------------------------------------------------------------
if option.Analyze {
buffer.WriteString("\tQuery Build Plan Stage:\n")
buffer.WriteString(fmt.Sprintf("\t\t- CPU Time: %dns \n", statsInfo.PlanStage.PlanDuration))
buffer.WriteString(fmt.Sprintf("\t\t- CPU Time: %dns \n", int64(statsInfo.PlanStage.PlanDuration)-statsInfo.PlanStage.BuildPlanStatsIOConsumption))
buffer.WriteString(fmt.Sprintf("\t\t- S3List:%d, S3Head:%d, S3Put:%d, S3Get:%d, S3Delete:%d, S3DeleteMul:%d\n",
statsInfo.PlanStage.BuildPlanS3Request.List,
statsInfo.PlanStage.BuildPlanS3Request.Head,
Expand All @@ -538,7 +539,18 @@ func explainResourceOverview(queryResult *util.RunResult, statsInfo *statistic.S
statsInfo.PlanStage.BuildPlanS3Request.Delete,
statsInfo.PlanStage.BuildPlanS3Request.DeleteMul,
))
buffer.WriteString(fmt.Sprintf("\t\t- Build Plan Duration: %dns \n", int64(statsInfo.PlanStage.PlanDuration)))
buffer.WriteString(fmt.Sprintf("\t\t- Call Stats Duration: %dns \n", statsInfo.PlanStage.BuildPlanStatsDuration))
buffer.WriteString(fmt.Sprintf("\t\t- Call StatsInCache Duration: %dns \n", statsInfo.PlanStage.BuildPlanStatsInCacheDuration))
buffer.WriteString(fmt.Sprintf("\t\t- Call Stats IO Consumption: %dns \n", statsInfo.PlanStage.BuildPlanStatsIOConsumption))
buffer.WriteString(fmt.Sprintf("\t\t- Call Stats S3List:%d, S3Head:%d, S3Put:%d, S3Get:%d, S3Delete:%d, S3DeleteMul:%d\n",
statsInfo.PlanStage.BuildPlanStatsS3.List,
statsInfo.PlanStage.BuildPlanStatsS3.Head,
statsInfo.PlanStage.BuildPlanStatsS3.Put,
statsInfo.PlanStage.BuildPlanStatsS3.Get,
statsInfo.PlanStage.BuildPlanStatsS3.Delete,
statsInfo.PlanStage.BuildPlanStatsS3.DeleteMul,
))

//-------------------------------------------------------------------------------------------------------
buffer.WriteString("\tQuery Compile Stage:\n")
Expand Down
33 changes: 10 additions & 23 deletions pkg/sql/compile/sql_executor_context.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@ import (
"strconv"
"strings"
"sync"
"time"

"github.com/matrixorigin/matrixone/pkg/catalog"
"github.com/matrixorigin/matrixone/pkg/common/moerr"
Expand Down Expand Up @@ -117,6 +118,12 @@ func (c *compilerContext) ResolveAccountIds(accountNames []string) ([]uint32, er
}

func (c *compilerContext) Stats(obj *plan.ObjectRef, snapshot *plan.Snapshot) (*pb.StatsInfo, error) {
stats := statistic.StatsInfoFromContext(c.GetContext())
start := time.Now()
defer func() {
stats.AddBuildPlanStatsConsumption(time.Since(start))
}()

dbName := obj.GetSchemaName()
tableName := obj.GetObjName()

Expand Down Expand Up @@ -147,49 +154,29 @@ func (c *compilerContext) Stats(obj *plan.ObjectRef, snapshot *plan.Snapshot) (*
}
}
var statsInfo *pb.StatsInfo
stats := statistic.StatsInfoFromContext(ctx)
// This is a partition table.
if partitionInfo != nil {
crs := new(perfcounter.CounterSet)
statsInfo = plan.NewStatsInfo()
for _, partitionTable := range partitionInfo.PartitionTableNames {
parCtx, parTable, err := c.getRelation(dbName, partitionTable, snapshot)
if err != nil {
return nil, err
}
newParCtx := perfcounter.AttachS3RequestKey(parCtx, crs)

newParCtx := perfcounter.AttachCalcTableStatsKey(parCtx)
parStats, err := parTable.Stats(newParCtx, true)
if err != nil {
return nil, err
}
statsInfo.Merge(parStats)
}

stats.AddBuildPlanStatsS3Request(statistic.S3Request{
List: crs.FileService.S3.List.Load(),
Head: crs.FileService.S3.Head.Load(),
Put: crs.FileService.S3.Put.Load(),
Get: crs.FileService.S3.Get.Load(),
Delete: crs.FileService.S3.Delete.Load(),
DeleteMul: crs.FileService.S3.DeleteMulti.Load(),
})
} else {
crs := new(perfcounter.CounterSet)
newCtx := perfcounter.AttachS3RequestKey(ctx, crs)

newCtx := perfcounter.AttachCalcTableStatsKey(ctx)
statsInfo, err = table.Stats(newCtx, true)
if err != nil {
return nil, err
}

stats.AddBuildPlanStatsS3Request(statistic.S3Request{
List: crs.FileService.S3.List.Load(),
Head: crs.FileService.S3.Head.Load(),
Put: crs.FileService.S3.Put.Load(),
Get: crs.FileService.S3.Get.Load(),
Delete: crs.FileService.S3.Delete.Load(),
DeleteMul: crs.FileService.S3.DeleteMulti.Load(),
})
}
return statsInfo, nil
}
Expand Down
18 changes: 15 additions & 3 deletions pkg/sql/models/show_phyplan.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -88,25 +88,26 @@ func explainResourceOverview(phy *PhyPlan, statsInfo *statistic.StatsInfo, optio
cpuTimeVal := gblStats.OperatorTimeConsumed +
int64(statsInfo.ParseStage.ParseDuration+statsInfo.PlanStage.PlanDuration+statsInfo.CompileStage.CompileDuration) +
statsInfo.PrepareRunStage.ScopePrepareDuration + statsInfo.PrepareRunStage.CompilePreRunOnceDuration -
statsInfo.PrepareRunStage.CompilePreRunOnceWaitLock -
statsInfo.PrepareRunStage.CompilePreRunOnceWaitLock - statsInfo.PlanStage.BuildPlanStatsIOConsumption -
(statsInfo.IOAccessTimeConsumption + statsInfo.S3FSPrefetchFileIOMergerTimeConsumption)

buffer.WriteString("\tCPU Usage: \n")
buffer.WriteString(fmt.Sprintf("\t\t- Total CPU Time: %dns \n", cpuTimeVal))
buffer.WriteString(fmt.Sprintf("\t\t- CPU Time Detail: Parse(%d)+BuildPlan(%d)+Compile(%d)+PhyExec(%d)+PrepareRun(%d)-PreRunWaitLock(%d)-IOAccess(%d)-IOMerge(%d)\n",
buffer.WriteString(fmt.Sprintf("\t\t- CPU Time Detail: Parse(%d)+BuildPlan(%d)+Compile(%d)+PhyExec(%d)+PrepareRun(%d)-PreRunWaitLock(%d)-PlanStatsIO(%d)-IOAccess(%d)-IOMerge(%d)\n",
statsInfo.ParseStage.ParseDuration,
statsInfo.PlanStage.PlanDuration,
statsInfo.CompileStage.CompileDuration,
gblStats.OperatorTimeConsumed,
gblStats.ScopePrepareTimeConsumed+statsInfo.PrepareRunStage.CompilePreRunOnceDuration,
statsInfo.PrepareRunStage.CompilePreRunOnceWaitLock,
statsInfo.PlanStage.BuildPlanStatsIOConsumption,
statsInfo.IOAccessTimeConsumption,
statsInfo.S3FSPrefetchFileIOMergerTimeConsumption))

//-------------------------------------------------------------------------------------------------------
if option == AnalyzeOption {
buffer.WriteString("\tQuery Build Plan Stage:\n")
buffer.WriteString(fmt.Sprintf("\t\t- CPU Time: %dns \n", statsInfo.PlanStage.PlanDuration))
buffer.WriteString(fmt.Sprintf("\t\t- CPU Time: %dns \n", int64(statsInfo.PlanStage.PlanDuration)-statsInfo.PlanStage.BuildPlanStatsIOConsumption))
buffer.WriteString(fmt.Sprintf("\t\t- S3List:%d, S3Head:%d, S3Put:%d, S3Get:%d, S3Delete:%d, S3DeleteMul:%d\n",
statsInfo.PlanStage.BuildPlanS3Request.List,
statsInfo.PlanStage.BuildPlanS3Request.Head,
Expand All @@ -115,7 +116,18 @@ func explainResourceOverview(phy *PhyPlan, statsInfo *statistic.StatsInfo, optio
statsInfo.PlanStage.BuildPlanS3Request.Delete,
statsInfo.PlanStage.BuildPlanS3Request.DeleteMul,
))
buffer.WriteString(fmt.Sprintf("\t\t- Build Plan Duration: %dns \n", int64(statsInfo.PlanStage.PlanDuration)))
buffer.WriteString(fmt.Sprintf("\t\t- Call Stats Duration: %dns \n", statsInfo.PlanStage.BuildPlanStatsDuration))
buffer.WriteString(fmt.Sprintf("\t\t- Call StatsInCache Duration: %dns \n", statsInfo.PlanStage.BuildPlanStatsInCacheDuration))
buffer.WriteString(fmt.Sprintf("\t\t- Call Stats IO Consumption: %dns \n", statsInfo.PlanStage.BuildPlanStatsIOConsumption))
buffer.WriteString(fmt.Sprintf("\t\t- Call Stats S3List:%d, S3Head:%d, S3Put:%d, S3Get:%d, S3Delete:%d, S3DeleteMul:%d\n",
statsInfo.PlanStage.BuildPlanStatsS3.List,
statsInfo.PlanStage.BuildPlanStatsS3.Head,
statsInfo.PlanStage.BuildPlanStatsS3.Put,
statsInfo.PlanStage.BuildPlanStatsS3.Get,
statsInfo.PlanStage.BuildPlanStatsS3.Delete,
statsInfo.PlanStage.BuildPlanStatsS3.DeleteMul,
))

//-------------------------------------------------------------------------------------------------------
buffer.WriteString("\tQuery Compile Stage:\n")
Expand Down
8 changes: 6 additions & 2 deletions pkg/sql/plan/function/func_mo_explain_phy_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -921,7 +921,7 @@ Scope 1 (Magic: Merge, mcpu: 1, Receiver: [0])
S3List:0, S3Head:0, S3Put:0, S3Get:0, S3Delete:0, S3DeleteMul:0, S3InputEstByRows((0+0)/8192):0.0000
CPU Usage:
- Total CPU Time: 91033157ns
- CPU Time Detail: Parse(162026)+BuildPlan(649910)+Compile(299370)+PhyExec(304651393)+PrepareRun(178265)-PreRunWaitLock(0)-IOAccess(214917833)-IOMerge(0)
- CPU Time Detail: Parse(162026)+BuildPlan(649910)+Compile(299370)+PhyExec(304651393)+PrepareRun(178265)-PreRunWaitLock(0)-PlanStatsIO(0)-IOAccess(214917833)-IOMerge(0)
Physical Plan Deployment:
LOCAL SCOPES:
Scope 1 (Magic: Merge, mcpu: 1, Receiver: [0])
Expand Down Expand Up @@ -978,11 +978,15 @@ Scope 1 (Magic: Merge, mcpu: 1, Receiver: [0])
S3List:0, S3Head:0, S3Put:0, S3Get:0, S3Delete:0, S3DeleteMul:0, S3InputEstByRows((0+0)/8192):0.0000
CPU Usage:
- Total CPU Time: 91033157ns
- CPU Time Detail: Parse(162026)+BuildPlan(649910)+Compile(299370)+PhyExec(304651393)+PrepareRun(178265)-PreRunWaitLock(0)-IOAccess(214917833)-IOMerge(0)
- CPU Time Detail: Parse(162026)+BuildPlan(649910)+Compile(299370)+PhyExec(304651393)+PrepareRun(178265)-PreRunWaitLock(0)-PlanStatsIO(0)-IOAccess(214917833)-IOMerge(0)
Query Build Plan Stage:
- CPU Time: 649910ns
- S3List:0, S3Head:0, S3Put:0, S3Get:0, S3Delete:0, S3DeleteMul:0
- Build Plan Duration: 649910ns
- Call Stats Duration: 3457758ns
- Call StatsInCache Duration: 0ns
- Call Stats IO Consumption: 0ns
- Call Stats S3List:0, S3Head:0, S3Put:0, S3Get:0, S3Delete:0, S3DeleteMul:0
Query Compile Stage:
- CPU Time: 299370ns
- S3List:0, S3Head:0, S3Put:0, S3Get:0, S3Delete:0, S3DeleteMul:0
Expand Down
Loading

0 comments on commit 34f9f9b

Please sign in to comment.