[fix](executor)Fix duplicate timer and add open timer #20448

1 Currently, Node's total timer couter has timed twice(in Open and alloc_resource), this may cause timer in profile is not correct.
2 Add more timer to find more code which may cost much time.
This commit is contained in:
wangbo
2023-06-06 08:55:52 +08:00
committed by GitHub
parent 4f77578d8a
commit 1fc48e83f2
4 changed files with 14 additions and 2 deletions

View File

@ -458,6 +458,8 @@ Status HashJoinNode::prepare(RuntimeState* state) {
_probe_side_output_timer = ADD_TIMER(probe_phase_profile, "ProbeWhenProbeSideOutputTime");
_join_filter_timer = ADD_TIMER(runtime_profile(), "JoinFilterTimer");
_open_timer = ADD_TIMER(runtime_profile(), "OpenTime");
_allocate_resource_timer = ADD_TIMER(runtime_profile(), "AllocateResourceTime");
_push_down_timer = ADD_TIMER(runtime_profile(), "PublishRuntimeFilterTime");
_push_compute_timer = ADD_TIMER(runtime_profile(), "PushDownComputeTime");
@ -745,14 +747,15 @@ void HashJoinNode::_prepare_probe_block() {
Status HashJoinNode::open(RuntimeState* state) {
SCOPED_TIMER(_runtime_profile->total_time_counter());
SCOPED_TIMER(_open_timer);
RETURN_IF_ERROR(VJoinNodeBase::open(state));
RETURN_IF_CANCELLED(state);
return Status::OK();
}
Status HashJoinNode::alloc_resource(doris::RuntimeState* state) {
SCOPED_TIMER(_allocate_resource_timer);
RETURN_IF_ERROR(VJoinNodeBase::alloc_resource(state));
SCOPED_TIMER(_runtime_profile->total_time_counter());
for (size_t i = 0; i < _runtime_filter_descs.size(); i++) {
if (auto bf = _runtime_filters[i]->get_bloomfilter()) {
RETURN_IF_ERROR(bf->init_with_fixed_length());

View File

@ -290,6 +290,9 @@ private:
RuntimeProfile::Counter* _build_side_merge_block_timer;
RuntimeProfile::Counter* _build_runtime_filter_timer;
RuntimeProfile::Counter* _open_timer;
RuntimeProfile::Counter* _allocate_resource_timer;
RuntimeProfile::Counter* _build_blocks_memory_usage;
RuntimeProfile::Counter* _hash_table_memory_usage;
RuntimeProfile::HighWaterMarkCounter* _build_arena_memory_usage;

View File

@ -150,22 +150,26 @@ Status VScanNode::prepare(RuntimeState* state) {
// could add here, not in the _init_profile() function
_get_next_timer = ADD_TIMER(_runtime_profile, "GetNextTime");
_acquire_runtime_filter_timer = ADD_TIMER(_runtime_profile, "AcuireRuntimeFilterTime");
_open_timer = ADD_TIMER(_runtime_profile, "OpenTime");
_alloc_resource_timer = ADD_TIMER(_runtime_profile, "AllocateResourceTime");
return Status::OK();
}
Status VScanNode::open(RuntimeState* state) {
SCOPED_TIMER(_runtime_profile->total_time_counter());
SCOPED_TIMER(_open_timer);
RETURN_IF_CANCELLED(state);
return ExecNode::open(state);
}
Status VScanNode::alloc_resource(RuntimeState* state) {
SCOPED_TIMER(_alloc_resource_timer);
if (_opened) {
return Status::OK();
}
_input_tuple_desc = state->desc_tbl().get_tuple_descriptor(_input_tuple_id);
_output_tuple_desc = state->desc_tbl().get_tuple_descriptor(_output_tuple_id);
SCOPED_TIMER(_runtime_profile->total_time_counter());
RETURN_IF_ERROR(ExecNode::alloc_resource(state));
RETURN_IF_ERROR(_acquire_runtime_filter());
RETURN_IF_ERROR(_process_conjuncts());

View File

@ -343,6 +343,8 @@ protected:
RuntimeProfile::Counter* _num_scanners;
RuntimeProfile::Counter* _get_next_timer = nullptr;
RuntimeProfile::Counter* _open_timer = nullptr;
RuntimeProfile::Counter* _alloc_resource_timer = nullptr;
RuntimeProfile::Counter* _acquire_runtime_filter_timer = nullptr;
// time of get block from scanner
RuntimeProfile::Counter* _scan_timer = nullptr;