IMPALA-4362: Misc. fixes for PFE counters * ExecTime was always 0, because it wasn't updated before the profile was reported to the coordinator * Made ExecTree* counters children of their respective parents * Moved ExecTreePrepareTime into the right profile * Renamed timings profile to something a bit more obvious.
Change-Id: Iaa9dccdcd91297a11a093b921f8d84d32f32be84 Reviewed-on: http://gerrit.cloudera.org:8080/4829 Reviewed-by: Henry Robinson <[email protected]> Tested-by: Internal Jenkins Project: http://git-wip-us.apache.org/repos/asf/incubator-impala/repo Commit: http://git-wip-us.apache.org/repos/asf/incubator-impala/commit/d363b4d0 Tree: http://git-wip-us.apache.org/repos/asf/incubator-impala/tree/d363b4d0 Diff: http://git-wip-us.apache.org/repos/asf/incubator-impala/diff/d363b4d0 Branch: refs/heads/master Commit: d363b4d09890a7366e14a68e0ebfafbab2f8867b Parents: 0dbfe16 Author: Henry Robinson <[email protected]> Authored: Mon Oct 24 17:22:17 2016 -0700 Committer: Internal Jenkins <[email protected]> Committed: Wed Oct 26 03:22:08 2016 +0000 ---------------------------------------------------------------------- be/src/runtime/plan-fragment-executor.cc | 34 ++++++++++++++++++--------- 1 file changed, 23 insertions(+), 11 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/incubator-impala/blob/d363b4d0/be/src/runtime/plan-fragment-executor.cc ---------------------------------------------------------------------- diff --git a/be/src/runtime/plan-fragment-executor.cc b/be/src/runtime/plan-fragment-executor.cc index a791e61..bfb80ea 100644 --- a/be/src/runtime/plan-fragment-executor.cc +++ b/be/src/runtime/plan-fragment-executor.cc @@ -61,6 +61,12 @@ namespace impala { const string PlanFragmentExecutor::PER_HOST_PEAK_MEM_COUNTER = "PerHostPeakMemUsage"; +namespace { +const string OPEN_TIMER_NAME = "OpenTime"; +const string PREPARE_TIMER_NAME = "PrepareTime"; +const string EXEC_TIMER_NAME = "ExecTime"; +} + PlanFragmentExecutor::PlanFragmentExecutor( ExecEnv* exec_env, const ReportStatusCallback& report_status_cb) : exec_env_(exec_env), @@ -118,10 +124,10 @@ Status PlanFragmentExecutor::PrepareInternal(const TExecPlanFragmentParams& requ // total_time_counter() is in the runtime_state_ so start it up now. SCOPED_TIMER(profile()->total_time_counter()); - timings_profile_ = - obj_pool()->Add(new RuntimeProfile(obj_pool(), "PlanFragmentExecutor")); + timings_profile_ = obj_pool()->Add( + new RuntimeProfile(obj_pool(), "Fragment Instance Lifecycle Timings")); profile()->AddChild(timings_profile_); - SCOPED_TIMER(ADD_TIMER(timings_profile_, "PrepareTime")); + SCOPED_TIMER(ADD_TIMER(timings_profile_, PREPARE_TIMER_NAME)); // reservation or a query option. int64_t bytes_limit = -1; @@ -202,7 +208,8 @@ Status PlanFragmentExecutor::PrepareInternal(const TExecPlanFragmentParams& requ } RuntimeState* state = runtime_state_.get(); - RuntimeProfile::Counter* prepare_timer = ADD_TIMER(profile(), "ExecTreePrepareTime"); + RuntimeProfile::Counter* prepare_timer = + ADD_CHILD_TIMER(timings_profile_, "ExecTreePrepareTime", PREPARE_TIMER_NAME); { SCOPED_TIMER(prepare_timer); // Until IMPALA-4233 is fixed, we still need to create the codegen object before @@ -283,7 +290,7 @@ void PlanFragmentExecutor::PrintVolumeIds( Status PlanFragmentExecutor::Open() { SCOPED_TIMER(profile()->total_time_counter()); - SCOPED_TIMER(ADD_TIMER(timings_profile_, "OpenTime")); + SCOPED_TIMER(ADD_TIMER(timings_profile_, OPEN_TIMER_NAME)); VLOG_QUERY << "Open(): instance_id=" << runtime_state_->fragment_instance_id(); Status status = OpenInternal(); UpdateStatus(status); @@ -312,19 +319,24 @@ Status PlanFragmentExecutor::OpenInternal() { OptimizeLlvmModule(); { - SCOPED_TIMER(ADD_TIMER(timings_profile_, "ExecTreeOpenTime")); + SCOPED_TIMER(ADD_CHILD_TIMER(timings_profile_, "ExecTreeOpenTime", OPEN_TIMER_NAME)); RETURN_IF_ERROR(exec_tree_->Open(runtime_state_.get())); } return sink_->Open(runtime_state_.get()); } Status PlanFragmentExecutor::Exec() { - SCOPED_TIMER(ADD_TIMER(timings_profile_, "ExecTime")); + Status status; { - lock_guard<mutex> l(status_lock_); - RETURN_IF_ERROR(status_); + // Must go out of scope before FragmentComplete(), otherwise counter will not be + // updated by time final profile is sent, and will always be 0. + SCOPED_TIMER(ADD_TIMER(timings_profile_, EXEC_TIMER_NAME)); + { + lock_guard<mutex> l(status_lock_); + RETURN_IF_ERROR(status_); + } + status = ExecInternal(); } - Status status = ExecInternal(); // If there's no error, ExecInternal() completed the fragment instance's execution. if (status.ok()) { @@ -341,7 +353,7 @@ Status PlanFragmentExecutor::Exec() { Status PlanFragmentExecutor::ExecInternal() { RuntimeProfile::Counter* plan_exec_timer = - ADD_TIMER(timings_profile_, "ExecTreeExecTime"); + ADD_CHILD_TIMER(timings_profile_, "ExecTreeExecTime", EXEC_TIMER_NAME); bool exec_tree_complete = false; do { Status status;
