【已解决】query profile中的PipelineContext有没有详细的解释?以及没有instance执行的总时间,active time并不能反映任务总耗时

Viewed 87

例如下instance,Active time 5.733us,但是VScanner的InitConnectorTime耗时11s,并不能直观的发现query的性能瓶颈在哪里

VNewJdbcScanNode(imp_db.v_imp_base_target) (id=1189):(Active: 5.733us, % non-child: 0.00%)
...
VScanner:
-InitConnectorTime: 11s79ms

下边是Fragment2完整的query profile

Fragment  2:
Instance  1d9c963d29b44aa3-8833e73c53f357bb  (host=TNetworkAddress(hostname:192.168.30.136,  port:9060)):
	VDataStreamSender  (dst_id=1199,  dst_fragments=[{"1d9c963d29b44aa3-8833e73c53f357bc",  "1d9c963d29b44aa3-8833e73c53f357bd",  "1d9c963d29b44aa3-8833e73c53f357bf"}]):(Active:  220.747us,  %  non-child:  0.00%)
		  -  BlocksSent:  5
		  -  BrpcSendTime:  0ns
		  -  BrpcSendTime.Wait:  0ns
		  -  BytesSent:  11.72  KB
		  -  CompressTime:  47.966us
		  -  IgnoreRows:  0
		  -  LocalBytesSent:  17.17  KB
		  -  LocalSendTime:  36.182us
		  -  LocalSentRows:  214
		  -  MemoryUsage:  
			  -  PeakMemoryUsage:  19.02  KB
		  -  OverallThroughput:  51.86849117279053  MB/sec
		  -  RpcAvgTime:  4.921us
		  -  RpcCount:  4
		  -  RpcMaxTime:  19.685us
		  -  RpcMinTime:  19.685us
		  -  RpcSumTime:  19.685us
		  -  SerializeBatchTime:  65.197us
		  -  SplitBlockDistributeByChannelTime:  0ns
		  -  SplitBlockHashComputeTime:  0ns
		  -  UncompressedRowBatchSize:  51.70  KB
	VNewJdbcScanNode(`imp_db`.`v_imp_base_target`)  (id=1189):(Active:  5.733us,  %  non-child:  0.00%)
		  -  RuntimeFilters:  :  
		  -  UseSpecificThreadToken:  False
		  -  AcquireRuntimeFilterTime:  317ns
		  -  AllocateResourceTime:  31.686ms
		  -  GetNextTime:  6.119us
		  -  MaxScannerThreadNum:  1
		  -  MemoryUsage:  
			  -  PeakMemoryUsage:  0.00  
		  -  NumScanners:  1
		  -  OpenTime:  0ns
		  -  ProjectionTime:  0ns
		  -  RowsReturned:  214
		  -  RowsReturnedRate:  37.327751M  /sec
		  -  ScanByteRead:  140.00  KB
		  -  ScanRowsRead:  214
		  -  ScannerWorkerWaitTime:  17.869us
		  -  TotalReadThroughput:  0
		VScanner:
			  -  JdbcDriverClass:  com.mysql.jdbc.Driver
			  -  JdbcDriverUrl:  mysql-connector-java-8.0.30.jar
			  -  JdbcUrl:  jdbc:mysql://192.168.30.145:3306/imp_db?yearIsDateType=false&tinyInt1isBit=false&useUnicode=true&rewriteBatchedStatements=true&characterEncoding=utf-8
			  -  QuerySql:  SELECT  `room_id`,  `room_name`,  `item_code`,  `item_name`,  `target_code`  FROM  `imp_db`.`v_imp_base_target`  WHERE  (`room_id`  =  755386394620198912)  AND  (`item_code`  IN  ('401',  '402',  '403',  '404',  '211',  '212',  '201',  '202',  '221',  '222'))
			  -  PerScannerRunningTime:  [56.064ms,  ]
			  -  PerScannerRowsRead:  [214,  ]
			  -  PerScannerWaitTime:  [17.869us,  ]
			  -  CheckTypeTime:  54.81us
			  -  ConnectorCloseTime:  0ns
			  -  ExecteReadTime:  57.159ms
			  -  GetDataTime:  55.987ms
				  -  CallJniNextTime:  0ns
				  -  ConvertBatchTime:  0ns
			  -  InitConnectorTime:  11s79ms
			  -  LoadJarTime:  5.137ms
			  -  MemoryUsage:  
				  -  FreeBlocks:  128.00  KB
				  -  QueuedBlocks:  0.00  
			  -  NewlyCreateFreeBlocksNum:  2
			  -  ScannerBatchWaitTime:  0ns
			  -  ScannerConvertBlockTime:  0ns
			  -  ScannerCpuTime:  617.904ms
			  -  ScannerCtxSchedCount:  3
			  -  ScannerCtxSchedTime:  6.247us
			  -  ScannerFilterTime:  65.469us
			  -  ScannerGetBlockTime:  55.997ms
			  -  ScannerPrefilterTime:  0ns
			  -  ScannerSchedCount:  1
	PipelineContext:(Active:  11s424ms,  %  non-child:  0.00%)
		  -  PrepareTime:  240.524us
		  -  StartTime:  1.898us
		Pipeline  (pipeline  id=0):
			PipelineTask  (index=0):(Active:  66.222ms,  %  non-child:  0.00%)
				  -  Sink:  ExchangeSinkOperator(dst_id=1199)
				  -  OperatorIds(source2root):  [ScanOperator(node_id=1189)]
				  -  CoreChangeTimes:  0
				  -  ExecuteTime:  31.937ms
					  -  CloseTime:  2.550ms
					  -  FinalizeTime:  137ns
					  -  GetBlockTime:  8.837us
					  -  OpenTime:  31.706ms
					  -  PrepareTime:  15.421us
					  -  SinkTime:  193.607us
				  -  GetBlockCounter:  2
				  -  NumBlockedBySinkTimes:  0
				  -  NumBlockedBySrcTimes:  1
				  -  NumBlockedTimes:  2
				  -  NumScheduleTimes:  4
				  -  NumYieldTimes:  0
				  -  Task1BeginExecuteTime:  11s420ms
				  -  Task2EosTime:  11s420ms
				  -  Task3SrcPendingFinishOverTime:  11s420ms
				  -  Task4DstPendingFinishOverTime:  11s421ms
				  -  Task5TotalTime:  11s424ms
				  -  Task6ClosePipelineTime:  11s424ms
				  -  TaskCpuTime:  738.985us
				  -  WaitBfTime:  0ns
				  -  WaitSinkTime:  0ns
				  -  WaitSourceTime:  11s388ms
				  -  WaitWorkerTime:  346.2us
1 Answers
Task1BeginExecuteTime:pipeline task从创建到第一次执行的时间,其中包含了prepare、open、第一次阻塞的时间
Task2EosTime:pipeline task从创建到eos的时间,包含prepare、open、执行、阻塞的总时间但是不包含close这个task的时间
Task3SrcPendingFinishOverTime:pipeline task从创建到source operator第一次结束pending finish的时间
Task4DstPendingFinishOverTime:pipeline task从创建到sink operator第一次结束pending finish的时间
Task5TotalTime:pipeline task从创建到完全结束的时间,在Task2EosTime的基础上加上了close的时间
Task6ClosePipelineTime:pipeline task从创建到完全结束的时间,和Task5TotalTime差不多
WaitSourceTime:source oeprator处于阻塞状态的时间
WaitSinkTime:sink operator处于阻塞状态的时间
WaitBfTime:等待runtime filter导致pipeline task阻塞的时间
WaitWorkerTime:等待执行线程的时间。也就是task为runnable但是还没被执行线程执行的时间。
NumBlockedTimes:进入阻塞状态的次数,阻塞原因包括block for source,block for sink,block for rf
NumBlockedBySrcTimes:因为block for source而被阻塞的次数
NumBlockedBySinkTimes:因为block for sink而被阻塞的次数
NumScheduleTimes:由阻塞队列进入runnable队列的次数
NumYieldTimes:pipeline task在执行过程中由于超出执行时间片而主动让出CPU的次数
CoreChangeTimes:在多次调度中cpu核心切换的次数