Log histogram of unwind timing.
Test: profile, get go/heapprofd-example-histogram as output.
Bug: 129054982
Change-Id: I46c3646ddd125fb5e8e436fe16070866c916aaff
diff --git a/Android.bp b/Android.bp
index 85af40d..cae2de6 100644
--- a/Android.bp
+++ b/Android.bp
@@ -2897,6 +2897,7 @@
"src/profiling/memory/client.cc",
"src/profiling/memory/client_unittest.cc",
"src/profiling/memory/heapprofd_producer.cc",
+ "src/profiling/memory/heapprofd_producer_unittest.cc",
"src/profiling/memory/interner_unittest.cc",
"src/profiling/memory/proc_utils.cc",
"src/profiling/memory/proc_utils_unittest.cc",
diff --git a/protos/perfetto/trace/perfetto_trace.proto b/protos/perfetto/trace/perfetto_trace.proto
index 16f48e2..4e4aa65 100644
--- a/protos/perfetto/trace/perfetto_trace.proto
+++ b/protos/perfetto/trace/perfetto_trace.proto
@@ -2472,10 +2472,26 @@
}
repeated ProcessHeapSamples process_dumps = 5;
+ message Histogram {
+ message Bucket {
+ // This bucket counts values from the previous bucket's (or -infinity if
+ // this is the first bucket) upper_limit (inclusive) to this upper_limit
+ // (exclusive).
+ optional uint64 upper_limit = 1;
+ // This is the highest bucket. This is set instead of the upper_limit. Any
+ // values larger or equal to the previous bucket's upper_limit are counted
+ // in this bucket.
+ optional bool max_bucket = 2;
+ // Number of values that fall into this range.
+ optional uint64 count = 3;
+ }
+ repeated Bucket buckets = 1;
+ }
message ProcessStats {
optional uint64 unwinding_errors = 1;
optional uint64 heap_samples = 2;
optional uint64 map_reparses = 3;
+ optional Histogram unwinding_time_us = 4;
}
message ProcessHeapSamples {
diff --git a/protos/perfetto/trace/profiling/profile_packet.proto b/protos/perfetto/trace/profiling/profile_packet.proto
index 3f6294f..f9f7b6d 100644
--- a/protos/perfetto/trace/profiling/profile_packet.proto
+++ b/protos/perfetto/trace/profiling/profile_packet.proto
@@ -67,10 +67,26 @@
}
repeated ProcessHeapSamples process_dumps = 5;
+ message Histogram {
+ message Bucket {
+ // This bucket counts values from the previous bucket's (or -infinity if
+ // this is the first bucket) upper_limit (inclusive) to this upper_limit
+ // (exclusive).
+ optional uint64 upper_limit = 1;
+ // This is the highest bucket. This is set instead of the upper_limit. Any
+ // values larger or equal to the previous bucket's upper_limit are counted
+ // in this bucket.
+ optional bool max_bucket = 2;
+ // Number of values that fall into this range.
+ optional uint64 count = 3;
+ }
+ repeated Bucket buckets = 1;
+ }
message ProcessStats {
optional uint64 unwinding_errors = 1;
optional uint64 heap_samples = 2;
optional uint64 map_reparses = 3;
+ optional Histogram unwinding_time_us = 4;
}
message ProcessHeapSamples {
diff --git a/src/profiling/memory/BUILD.gn b/src/profiling/memory/BUILD.gn
index 30d1ee4..e6ce5d4 100644
--- a/src/profiling/memory/BUILD.gn
+++ b/src/profiling/memory/BUILD.gn
@@ -152,6 +152,7 @@
sources = [
"bookkeeping_unittest.cc",
"client_unittest.cc",
+ "heapprofd_producer_unittest.cc",
"interner_unittest.cc",
"proc_utils_unittest.cc",
"sampler_unittest.cc",
diff --git a/src/profiling/memory/heapprofd_end_to_end_test.cc b/src/profiling/memory/heapprofd_end_to_end_test.cc
index c75174e..b0032af 100644
--- a/src/profiling/memory/heapprofd_end_to_end_test.cc
+++ b/src/profiling/memory/heapprofd_end_to_end_test.cc
@@ -180,11 +180,29 @@
return helper;
}
+std::string FormatHistogram(const protos::ProfilePacket_Histogram& hist) {
+ std::string out;
+ std::string prev_upper_limit = "-inf";
+ for (const auto& bucket : hist.buckets()) {
+ std::string upper_limit;
+ if (bucket.max_bucket())
+ upper_limit = "inf";
+ else
+ upper_limit = std::to_string(bucket.upper_limit());
+
+ out += "[" + prev_upper_limit + ", " + upper_limit +
+ "]: " + std::to_string(bucket.count()) + "; ";
+ prev_upper_limit = std::move(upper_limit);
+ }
+ return out + "\n";
+}
+
std::string FormatStats(const protos::ProfilePacket_ProcessStats& stats) {
return std::string("unwinding_errors: ") +
std::to_string(stats.unwinding_errors()) + "\n" +
"heap_samples: " + std::to_string(stats.heap_samples()) + "\n" +
- "map_reparses: " + std::to_string(stats.map_reparses());
+ "map_reparses: " + std::to_string(stats.map_reparses()) + "\n" +
+ "unwinding_time_us: " + FormatHistogram(stats.unwinding_time_us());
}
class HeapprofdEndToEnd : public ::testing::Test {
diff --git a/src/profiling/memory/heapprofd_producer.cc b/src/profiling/memory/heapprofd_producer.cc
index 79e3249..2233009 100644
--- a/src/profiling/memory/heapprofd_producer.cc
+++ b/src/profiling/memory/heapprofd_producer.cc
@@ -60,8 +60,42 @@
return ret;
}
+// Return largest n such that pow(2, n) < value.
+size_t Log2LessThan(uint64_t value) {
+ size_t i = 0;
+ while (value) {
+ i++;
+ value >>= 1;
+ }
+ return i;
+}
+
} // namespace
+const uint64_t LogHistogram::kMaxBucket = 0;
+
+std::vector<std::pair<uint64_t, uint64_t>> LogHistogram::GetData() {
+ std::vector<std::pair<uint64_t, uint64_t>> data;
+ data.reserve(kBuckets);
+ for (size_t i = 0; i < kBuckets; ++i) {
+ if (i == kBuckets - 1)
+ data.emplace_back(kMaxBucket, values_[i]);
+ else
+ data.emplace_back(1 << i, values_[i]);
+ }
+ return data;
+}
+
+size_t LogHistogram::GetBucket(uint64_t value) {
+ if (value == 0)
+ return 0;
+
+ size_t hibit = Log2LessThan(value);
+ if (hibit >= kBuckets)
+ return kBuckets - 1;
+ return hibit;
+}
+
// We create kUnwinderThreads unwinding threads. Bookkeeping is done on the main
// thread.
// TODO(fmayer): Summarize threading document here.
@@ -368,6 +402,15 @@
stats->set_unwinding_errors(process_state.unwinding_errors);
stats->set_heap_samples(process_state.heap_samples);
stats->set_map_reparses(process_state.map_reparses);
+ auto* unwinding_hist = stats->set_unwinding_time_us();
+ for (const auto& p : process_state.unwinding_time_us.GetData()) {
+ auto* bucket = unwinding_hist->add_buckets();
+ if (p.first == LogHistogram::kMaxBucket)
+ bucket->set_max_bucket(true);
+ else
+ bucket->set_upper_limit(p.first);
+ bucket->set_count(p.second);
+ }
};
heap_tracker.Dump(std::move(new_heapsamples), &dump_state);
}
@@ -727,6 +770,7 @@
if (alloc_rec.reparsed_map)
process_state.map_reparses++;
process_state.heap_samples++;
+ process_state.unwinding_time_us.Add(alloc_rec.unwinding_time_us);
heap_tracker.RecordMalloc(alloc_rec.frames, alloc_metadata.alloc_address,
alloc_metadata.total_size,
@@ -775,6 +819,10 @@
return;
ProcessState& process_state = process_state_it->second;
process_state.disconnected = true;
+
+ // TODO(fmayer): Dump on process disconnect rather than data source
+ // destruction. This prevents us needing to hold onto the bookkeeping data
+ // after the process disconnected.
}
} // namespace profiling
diff --git a/src/profiling/memory/heapprofd_producer.h b/src/profiling/memory/heapprofd_producer.h
index 2599384..d9fd386 100644
--- a/src/profiling/memory/heapprofd_producer.h
+++ b/src/profiling/memory/heapprofd_producer.h
@@ -44,6 +44,20 @@
std::string cmdline;
};
+class LogHistogram {
+ public:
+ static const uint64_t kMaxBucket;
+ static constexpr size_t kBuckets = 20;
+
+ void Add(uint64_t value) { values_[GetBucket(value)]++; }
+ std::vector<std::pair<uint64_t, uint64_t>> GetData();
+
+ private:
+ size_t GetBucket(uint64_t value);
+
+ std::array<uint64_t, kBuckets> values_ = {};
+};
+
// TODO(rsavitski): central daemon can do less work if it knows that the global
// operating mode is fork-based, as it then will not be interacting with the
// clients. This can be implemented as an additional mode here.
@@ -148,6 +162,8 @@
uint64_t heap_samples = 0;
uint64_t map_reparses = 0;
uint64_t unwinding_errors = 0;
+
+ LogHistogram unwinding_time_us;
HeapTracker heap_tracker;
};
diff --git a/src/profiling/memory/heapprofd_producer_unittest.cc b/src/profiling/memory/heapprofd_producer_unittest.cc
new file mode 100644
index 0000000..37f0017
--- /dev/null
+++ b/src/profiling/memory/heapprofd_producer_unittest.cc
@@ -0,0 +1,43 @@
+/*
+ * Copyright (C) 2019 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include "src/profiling/memory/heapprofd_producer.h"
+
+#include "gmock/gmock.h"
+#include "gtest/gtest.h"
+
+namespace perfetto {
+namespace profiling {
+
+using ::testing::Contains;
+using ::testing::Pair;
+
+TEST(LogHistogramTest, Simple) {
+ LogHistogram h;
+ h.Add(1);
+ h.Add(0);
+ EXPECT_THAT(h.GetData(), Contains(Pair(2, 1)));
+ EXPECT_THAT(h.GetData(), Contains(Pair(1, 1)));
+}
+
+TEST(LogHistogramTest, Overflow) {
+ LogHistogram h;
+ h.Add(std::numeric_limits<uint64_t>::max());
+ EXPECT_THAT(h.GetData(), Contains(Pair(LogHistogram::kMaxBucket, 1)));
+}
+
+} // namespace profiling
+} // namespace perfetto
diff --git a/src/profiling/memory/unwinding.cc b/src/profiling/memory/unwinding.cc
index 6cd7a01..2250ddb 100644
--- a/src/profiling/memory/unwinding.cc
+++ b/src/profiling/memory/unwinding.cc
@@ -250,7 +250,6 @@
out->frames.emplace_back(frame_data, "");
out->error = true;
}
-
return true;
}
@@ -318,7 +317,10 @@
rec.alloc_metadata = *msg.alloc_header;
rec.pid = peer_pid;
rec.data_source_instance_id = data_source_instance_id;
+ auto start_time_us = base::GetWallTimeNs() / 1000;
DoUnwind(&msg, unwinding_metadata, &rec);
+ rec.unwinding_time_us = static_cast<uint64_t>(
+ ((base::GetWallTimeNs() / 1000) - start_time_us).count());
delegate->PostAllocRecord(std::move(rec));
} else if (msg.record_type == RecordType::Free) {
FreeRecord rec;
diff --git a/src/profiling/memory/unwound_messages.h b/src/profiling/memory/unwound_messages.h
index 582b619..f2e698f 100644
--- a/src/profiling/memory/unwound_messages.h
+++ b/src/profiling/memory/unwound_messages.h
@@ -39,6 +39,7 @@
pid_t pid;
bool error = false;
bool reparsed_map = false;
+ uint64_t unwinding_time_us = 0;
uint64_t data_source_instance_id;
AllocMetadata alloc_metadata;
std::vector<FrameData> frames;