You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@impala.apache.org by jo...@apache.org on 2018/12/19 19:20:38 UTC
impala git commit: IMPALA-5200: Count child time for parent's total
time
Repository: impala
Updated Branches:
refs/heads/master 0c957fcd5 -> ba6ca11d8
IMPALA-5200: Count child time for parent's total time
One problem with the total time counter on runtime
profiles is that a parent's time may not be updated
if execution is stuck in a child node. The child
can accumulate time while the parent is stuck at
zero. This leads to incorrect or misleading
calculations of total time or non-child time
for the parent node during execution.
This makes a modest change in calculation for total
time for parent nodes. It takes advantage of the
fact that the parent should count all of the time
from all of its children as total time for itself.
Specifically, if a parent has accumulated X in its
total timer and its children have accumulated Y
summed across all of their timers, then a parent's
total time should be at least max(X, Y). There is no way
to know the appropriate overlap between X and Y,
so this uses a conservative calculation assuming
complete overlap.
This prevents a parent node from reporting itself
as 100% non-child time when it is actually stuck
executing child code. However, it does not help
if a child node is stuck and is not reporting its
own time.
Testing:
- Added test case to runtime-profile-test
- Core tests pass
Change-Id: Id6c1191c39fd18b6be45325366a74cf54908c77e
Reviewed-on: http://gerrit.cloudera.org:8080/11791
Reviewed-by: Joe McDonnell <jo...@cloudera.com>
Tested-by: Impala Public Jenkins <im...@cloudera.com>
Project: http://git-wip-us.apache.org/repos/asf/impala/repo
Commit: http://git-wip-us.apache.org/repos/asf/impala/commit/ba6ca11d
Tree: http://git-wip-us.apache.org/repos/asf/impala/tree/ba6ca11d
Diff: http://git-wip-us.apache.org/repos/asf/impala/diff/ba6ca11d
Branch: refs/heads/master
Commit: ba6ca11d8b073fce20f8f9d824b3dc8a2f331082
Parents: 0c957fc
Author: Joe McDonnell <jo...@cloudera.com>
Authored: Thu Oct 25 11:56:52 2018 -0700
Committer: Joe McDonnell <jo...@cloudera.com>
Committed: Wed Dec 19 18:57:58 2018 +0000
----------------------------------------------------------------------
be/src/util/runtime-profile-test.cc | 96 ++++++++++++++++++++++++++++++++
be/src/util/runtime-profile.cc | 40 +++++++------
be/src/util/runtime-profile.h | 6 ++
3 files changed, 125 insertions(+), 17 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/impala/blob/ba6ca11d/be/src/util/runtime-profile-test.cc
----------------------------------------------------------------------
diff --git a/be/src/util/runtime-profile-test.cc b/be/src/util/runtime-profile-test.cc
index 19f513a..73553d2 100644
--- a/be/src/util/runtime-profile-test.cc
+++ b/be/src/util/runtime-profile-test.cc
@@ -318,6 +318,102 @@ TEST(CountersTest, MergeAndUpdateChildOrder) {
deserialized_profile->PrettyPrint(&dummy);
}
+TEST(CountersTest, TotalTimeCounters) {
+ ObjectPool pool;
+
+ // Set up a three layer profile: parent -> child1 -> child2
+ RuntimeProfile* parent = RuntimeProfile::Create(&pool, "Parent");
+ RuntimeProfile* child1 = RuntimeProfile::Create(&pool, "Child1");
+ RuntimeProfile* child2 = RuntimeProfile::Create(&pool, "Child2");
+ child1->AddChild(child2);
+ parent->AddChild(child1);
+
+ // Part 1: Test accumulation of time up from child2 to child1 to parent
+ // One millisecond passes in child2
+ int64_t one_milli_ns = 1 * NANOS_PER_MICRO * MICROS_PER_MILLI;
+ child2->total_time_counter()->Add(1 * NANOS_PER_MICRO * MICROS_PER_MILLI);
+ parent->ComputeTimeInProfile();
+ EXPECT_EQ(child2->total_time(), one_milli_ns);
+ EXPECT_EQ(child2->local_time(), one_milli_ns);
+
+ // Child1 is a parent of child2, so it is expected to contain at least as much time
+ // as in child2. In this case, it is equal. However, none of the time is local.
+ EXPECT_EQ(child1->total_time(), one_milli_ns);
+ EXPECT_EQ(child1->local_time(), 0);
+
+ // The parent is in the same situation as child1
+ EXPECT_EQ(parent->total_time(), one_milli_ns);
+ EXPECT_EQ(parent->local_time(), 0);
+
+ // Time now accumulates up to child1
+ child1->total_time_counter()->Add(child2->total_time());
+ parent->ComputeTimeInProfile();
+
+ // This doesn't change anything for anyone
+ EXPECT_EQ(child2->total_time(), one_milli_ns);
+ EXPECT_EQ(child2->local_time(), one_milli_ns);
+ EXPECT_EQ(child1->total_time(), one_milli_ns);
+ EXPECT_EQ(child1->local_time(), 0);
+ EXPECT_EQ(parent->total_time(), one_milli_ns);
+ EXPECT_EQ(parent->local_time(), 0);
+
+ // Time now accumulates up to parent
+ parent->total_time_counter()->Add(child1->total_time());
+ parent->ComputeTimeInProfile();
+
+ // This doesn't change anything for the parent
+ EXPECT_EQ(child2->total_time(), one_milli_ns);
+ EXPECT_EQ(child2->local_time(), one_milli_ns);
+ EXPECT_EQ(child1->total_time(), one_milli_ns);
+ EXPECT_EQ(child1->local_time(), 0);
+ EXPECT_EQ(parent->total_time(), one_milli_ns);
+ EXPECT_EQ(parent->local_time(), 0);
+
+ // Part 2: Time accumulated in middle child
+ // Add 1ms to the middle child
+ child1->total_time_counter()->Add(one_milli_ns);
+ parent->ComputeTimeInProfile();
+
+ // Child2 did not change
+ EXPECT_EQ(child2->total_time(), one_milli_ns);
+ EXPECT_EQ(child2->local_time(), one_milli_ns);
+
+ // Child1 has 1ms more of total time and local time
+ EXPECT_EQ(child1->total_time(), 2 * one_milli_ns);
+ EXPECT_EQ(child1->local_time(), one_milli_ns);
+
+ // Parent has more total time, but no local time
+ EXPECT_EQ(parent->total_time(), 2 * one_milli_ns);
+ EXPECT_EQ(parent->local_time(), 0);
+
+ // Accumulate the middle child up to the parent
+ parent->total_time_counter()->Add(one_milli_ns);
+ parent->ComputeTimeInProfile();
+
+ // Doesn't change anything
+ EXPECT_EQ(child2->total_time(), one_milli_ns);
+ EXPECT_EQ(child2->local_time(), one_milli_ns);
+ EXPECT_EQ(child1->total_time(), 2 * one_milli_ns);
+ EXPECT_EQ(child1->local_time(), one_milli_ns);
+ EXPECT_EQ(parent->total_time(), 2 * one_milli_ns);
+ EXPECT_EQ(parent->local_time(), 0);
+
+ // Part 3: Time accumulated at parent
+ // Add 1ms to the parent
+ parent->total_time_counter()->Add(one_milli_ns);
+ parent->ComputeTimeInProfile();
+
+ // Child1 and child2 don't change
+ EXPECT_EQ(child2->total_time(), one_milli_ns);
+ EXPECT_EQ(child2->local_time(), one_milli_ns);
+ EXPECT_EQ(child1->total_time(), 2 * one_milli_ns);
+ EXPECT_EQ(child1->local_time(), one_milli_ns);
+
+ // Parent has 1ms more total time and local time
+ EXPECT_EQ(parent->total_time(), 3 * one_milli_ns);
+ EXPECT_EQ(parent->local_time(), one_milli_ns);
+}
+
TEST(CountersTest, HighWaterMarkCounters) {
ObjectPool pool;
RuntimeProfile* profile = RuntimeProfile::Create(&pool, "Profile");
http://git-wip-us.apache.org/repos/asf/impala/blob/ba6ca11d/be/src/util/runtime-profile.cc
----------------------------------------------------------------------
diff --git a/be/src/util/runtime-profile.cc b/be/src/util/runtime-profile.cc
index 44c32fe..cdb9dd9 100644
--- a/be/src/util/runtime-profile.cc
+++ b/be/src/util/runtime-profile.cc
@@ -408,7 +408,26 @@ void RuntimeProfile::ComputeTimeInProfile() {
}
void RuntimeProfile::ComputeTimeInProfile(int64_t total) {
- if (total == 0) return;
+ // Recurse on children. After this, childrens' total time is up to date.
+ {
+ lock_guard<SpinLock> l(children_lock_);
+ for (int i = 0; i < children_.size(); ++i) {
+ children_[i].first->ComputeTimeInProfile();
+ }
+ }
+
+ // Get total time from children
+ int64_t children_total_time = 0;
+ {
+ lock_guard<SpinLock> l(children_lock_);
+ for (int i = 0; i < children_.size(); ++i) {
+ children_total_time += children_[i].first->total_time();
+ }
+ }
+ // IMPALA-5200: Take the max, because the parent includes all of the time from the
+ // children, whether or not its total time counter has been updated recently enough
+ // to see this.
+ total_time_ns_ = max(children_total_time, total_time_counter()->value());
// If a local time counter exists, use its value as local time. Otherwise, derive the
// local time from total time and the child time.
@@ -421,14 +440,9 @@ void RuntimeProfile::ComputeTimeInProfile(int64_t total) {
has_local_time_counter = true;
}
}
+
if (!has_local_time_counter) {
- // Add all the total times of all the children.
- int64_t total_child_time = 0;
- lock_guard<SpinLock> l(children_lock_);
- for (int i = 0; i < children_.size(); ++i) {
- total_child_time += children_[i].first->total_time_counter()->value();
- }
- local_time_ns_ = total_time_counter()->value() - total_child_time;
+ local_time_ns_ = total_time_ns_ - children_total_time;
if (!is_averaged_profile_) {
local_time_ns_ -= inactive_timer()->value();
}
@@ -436,16 +450,8 @@ void RuntimeProfile::ComputeTimeInProfile(int64_t total) {
// Counters have some margin, set to 0 if it was negative.
local_time_ns_ = ::max<int64_t>(0, local_time_ns_);
local_time_percent_ =
- static_cast<double>(local_time_ns_) / total_time_counter()->value();
+ static_cast<double>(local_time_ns_) / total_time_ns_;
local_time_percent_ = ::min(1.0, local_time_percent_) * 100;
-
- // Recurse on children
- {
- lock_guard<SpinLock> l(children_lock_);
- for (int i = 0; i < children_.size(); ++i) {
- children_[i].first->ComputeTimeInProfile(total);
- }
- }
}
void RuntimeProfile::AddChild(RuntimeProfile* child, bool indent, RuntimeProfile* loc) {
http://git-wip-us.apache.org/repos/asf/impala/blob/ba6ca11d/be/src/util/runtime-profile.h
----------------------------------------------------------------------
diff --git a/be/src/util/runtime-profile.h b/be/src/util/runtime-profile.h
index c1c0462..8bba192 100644
--- a/be/src/util/runtime-profile.h
+++ b/be/src/util/runtime-profile.h
@@ -265,6 +265,7 @@ class RuntimeProfile { // NOLINT: This struct is not packed, but there are not s
Counter* total_time_counter() { return counter_map_[TOTAL_TIME_COUNTER_NAME]; }
Counter* inactive_timer() { return counter_map_[INACTIVE_TIME_COUNTER_NAME]; }
int64_t local_time() { return local_time_ns_; }
+ int64_t total_time() { return total_time_ns_; }
/// Prints the contents of the profile in a name: value format.
/// Does not hold locks when it makes any function calls.
@@ -484,6 +485,11 @@ class RuntimeProfile { // NOLINT: This struct is not packed, but there are not s
/// ComputeTimeInProfile()
int64_t local_time_ns_;
+ /// Total time spent in this node. Computed in ComputeTimeInProfile() and is
+ /// the maximum of the total time spent in children and the value of
+ /// counter_total_time_.
+ int64_t total_time_ns_;
+
/// The Exec Summary
TExecSummary t_exec_summary_;