[metrics] Report some ART metadata
Adds reporting for some metadata associated with ART metrics,
including timestamp relative to ART startup, the session id, and the
process's user id. It additionally outputs placeholders for the
compilation reason and compiler filter, but these need some additional
plumbing from the Runtime and OatFileManager to fill in, so those will
come in a followup CL.
This CL also includes a fair amount of refactoring around metrics
reporting and handling the session data.
Example output:
*** ART internal metrics ***
Metadata:
timestamp_since_start_ms: 768
session_id: 5026277321588503825
uid: 123456
compilation_reason: Unknown
compiler_filter: (unspecified)
Metrics:
ClassVerificationTotalTime: count = 4167
JitMethodCompileTime: range = 0...1000000, buckets: 7,0,0,0,0,0
*** Done dumping ART internal metrics ***
Test: ./test/run-test --host --jit 2232-write-metrics-to-log
Change-Id: Ic74b503b135d71099d9e26bf660b60e4cc3a46bc
diff --git a/libartbase/base/metrics/metrics.h b/libartbase/base/metrics/metrics.h
index 18f84e9..20bbc52 100644
--- a/libartbase/base/metrics/metrics.h
+++ b/libartbase/base/metrics/metrics.h
@@ -22,12 +22,13 @@
#include <array>
#include <atomic>
#include <optional>
-#include <ostream>
+#include <sstream>
#include <string_view>
#include <thread>
#include <vector>
#include "android-base/logging.h"
+#include "base/compiler_filter.h"
#include "base/time_utils.h"
#pragma clang diagnostic push
@@ -79,10 +80,59 @@
#undef ART_HISTOGRAM
};
+// We log compilation reasons as part of the metadata we report. Since elsewhere compilation reasons
+// are specified as a string, we define them as an enum here which indicates the reasons that we
+// support.
+enum class CompilationReason {
+ kError,
+ kUnknown,
+ kFirstBoot,
+ kBoot,
+ kInstall,
+ kBgDexopt,
+ kABOTA,
+ kInactive,
+ kShared,
+ kInstallWithDexMetadata,
+};
+
+constexpr const char* CompilationReasonName(CompilationReason reason) {
+ switch (reason) {
+ case CompilationReason::kError:
+ return "Error";
+ case CompilationReason::kUnknown:
+ return "Unknown";
+ case CompilationReason::kFirstBoot:
+ return "FirstBoot";
+ case CompilationReason::kBoot:
+ return "Boot";
+ case CompilationReason::kInstall:
+ return "Install";
+ case CompilationReason::kBgDexopt:
+ return "BgDexopt";
+ case CompilationReason::kABOTA:
+ return "ABOTA";
+ case CompilationReason::kInactive:
+ return "Inactive";
+ case CompilationReason::kShared:
+ return "Shared";
+ case CompilationReason::kInstallWithDexMetadata:
+ return "InstallWithDexMetadata";
+ }
+}
+
+// SessionData contains metadata about a metrics session (basically the lifetime of an ART process).
+// This information should not change for the lifetime of the session.
struct SessionData {
- const uint64_t session_id;
- const std::string_view package_name;
- // TODO: compiler filter / dexopt state
+ static SessionData CreateDefault();
+
+ static constexpr int64_t kInvalidSessionId = -1;
+ static constexpr int32_t kInvalidUserId = -1;
+
+ int64_t session_id;
+ int32_t uid;
+ CompilationReason compilation_reason;
+ std::optional<CompilerFilter::Filter> compiler_filter;
};
// MetricsBackends are used by a metrics reporter to write metrics to some external location. For
@@ -91,7 +141,6 @@
public:
virtual ~MetricsBackend() {}
- protected:
// Begins an ART metrics session.
//
// This is called by the metrics reporter when the runtime is starting up. The session_data
@@ -100,12 +149,9 @@
// for this process.
virtual void BeginSession(const SessionData& session_data) = 0;
- // Marks the end of a metrics session.
- //
- // The metrics reporter will call this when metrics reported ends (e.g. when the runtime is
- // shutting down). No further metrics will be reported for this session. Note that EndSession is
- // not guaranteed to be called, since clean shutdowns for the runtime are quite rare in practice.
- virtual void EndSession() = 0;
+ protected:
+ // Called by the metrics reporter to indicate that a new metrics report is starting.
+ virtual void BeginReport(uint64_t timestamp_millis) = 0;
// Called by the metrics reporter to give the current value of the counter with id counter_type.
//
@@ -129,10 +175,14 @@
int64_t maximum_value,
const std::vector<uint32_t>& buckets) = 0;
+ // Called by the metrics reporter to indicate that the current metrics report is complete.
+ virtual void EndReport() = 0;
+
template <DatumId counter_type>
friend class MetricsCounter;
template <DatumId histogram_type, size_t num_buckets, int64_t low_value, int64_t high_value>
friend class MetricsHistogram;
+ friend class ArtMetrics;
};
template <DatumId counter_type>
@@ -208,13 +258,16 @@
static_assert(std::atomic<value_t>::is_always_lock_free);
};
-// A backend that writes metrics in a human-readable format to an std::ostream.
-class StreamBackend : public MetricsBackend {
+// A backend that writes metrics in a human-readable format to a string.
+//
+// This is used as a base for LogBackend and FileBackend.
+class StringBackend : public MetricsBackend {
public:
- explicit StreamBackend(std::ostream& os);
+ StringBackend();
void BeginSession(const SessionData& session_data) override;
- void EndSession() override;
+
+ void BeginReport(uint64_t timestamp_millis) override;
void ReportCounter(DatumId counter_type, uint64_t value) override;
@@ -223,8 +276,40 @@
int64_t high_value,
const std::vector<uint32_t>& buckets) override;
+ void EndReport() override;
+
+ std::string GetAndResetBuffer();
+
private:
- std::ostream& os_;
+ std::ostringstream os_;
+ std::optional<SessionData> session_data_;
+};
+
+// A backend that writes metrics in human-readable format to the log (i.e. logcat).
+class LogBackend : public StringBackend {
+ public:
+ explicit LogBackend(android::base::LogSeverity level);
+
+ void BeginReport(uint64_t timestamp_millis) override;
+ void EndReport() override;
+
+ private:
+ android::base::LogSeverity level_;
+};
+
+// A backend that writes metrics to a file.
+//
+// These are currently written in the same human-readable format used by StringBackend and
+// LogBackend, but we will probably want a more machine-readable format in the future.
+class FileBackend : public StringBackend {
+ public:
+ explicit FileBackend(std::string filename);
+
+ void BeginReport(uint64_t timestamp_millis) override;
+ void EndReport() override;
+
+ private:
+ std::string filename_;
};
/**
@@ -323,14 +408,7 @@
#undef ART_HISTOGRAM
private:
- // This field is only included to allow us expand the ART_COUNTERS and ART_HISTOGRAMS macro in
- // the initializer list in ArtMetrics::ArtMetrics. See metrics.cc for how it's used.
- //
- // It's declared as a zero-length array so it has no runtime space impact.
-#pragma clang diagnostic push
-#pragma clang diagnostic ignored "-Wunused-private-field"
- int unused_[0];
-#pragma clang diagnostic pop // -Wunused-private-field
+ uint64_t beginning_timestamp_;
#define ART_COUNTER(name) MetricsCounter<DatumId::k##name> name##_;
ART_COUNTERS(ART_COUNTER)
diff --git a/libartbase/base/metrics/metrics_common.cc b/libartbase/base/metrics/metrics_common.cc
index 81d7215..c650fdf 100644
--- a/libartbase/base/metrics/metrics_common.cc
+++ b/libartbase/base/metrics/metrics_common.cc
@@ -16,8 +16,10 @@
#include <sstream>
+#include "android-base/file.h"
#include "android-base/logging.h"
#include "base/macros.h"
+#include "base/scoped_flock.h"
#include "metrics.h"
#pragma clang diagnostic push
@@ -46,7 +48,22 @@
}
}
-ArtMetrics::ArtMetrics() : unused_ {}
+SessionData SessionData::CreateDefault() {
+#ifdef _WIN32
+ int32_t uid = kInvalidUserId; // Windows does not support getuid();
+#else
+ int32_t uid = static_cast<int32_t>(getuid());
+#endif
+
+ return SessionData{
+ .compilation_reason = CompilationReason::kUnknown,
+ .compiler_filter = std::nullopt,
+ .session_id = kInvalidSessionId,
+ .uid = uid,
+ };
+}
+
+ArtMetrics::ArtMetrics() : beginning_timestamp_ {MilliTime()}
#define ART_COUNTER(name) \
, name##_ {}
ART_COUNTERS(ART_COUNTER)
@@ -59,6 +76,8 @@
}
void ArtMetrics::ReportAllMetrics(MetricsBackend* backend) const {
+ backend->BeginReport(MilliTime() - beginning_timestamp_);
+
// Dump counters
#define ART_COUNTER(name) name()->Report(backend);
ART_COUNTERS(ART_COUNTER)
@@ -68,34 +87,58 @@
#define ART_HISTOGRAM(name, num_buckets, low_value, high_value) name()->Report(backend);
ART_HISTOGRAMS(ART_HISTOGRAM)
#undef ART_HISTOGRAM
+
+ backend->EndReport();
}
void ArtMetrics::DumpForSigQuit(std::ostream& os) const {
- os << "\n*** ART internal metrics ***\n\n";
- StreamBackend backend{os};
+ StringBackend backend;
ReportAllMetrics(&backend);
- os << "\n*** Done dumping ART internal metrics ***\n";
+ os << backend.GetAndResetBuffer();
}
-StreamBackend::StreamBackend(std::ostream& os) : os_{os} {}
+StringBackend::StringBackend() {}
-void StreamBackend::BeginSession([[maybe_unused]] const SessionData& session_data) {
- // Not needed for now.
+std::string StringBackend::GetAndResetBuffer() {
+ std::string result = os_.str();
+ os_.clear();
+ os_.str("");
+ return result;
}
-void StreamBackend::EndSession() {
- // Not needed for now.
+void StringBackend::BeginSession(const SessionData& session_data) {
+ session_data_ = session_data;
}
-void StreamBackend::ReportCounter(DatumId counter_type, uint64_t value) {
- os_ << DatumName(counter_type) << ": count = " << value << "\n";
+void StringBackend::BeginReport(uint64_t timestamp_since_start_ms) {
+ os_ << "\n*** ART internal metrics ***\n";
+ os_ << " Metadata:\n";
+ os_ << " timestamp_since_start_ms: " << timestamp_since_start_ms << "\n";
+ if (session_data_.has_value()) {
+ os_ << " session_id: " << session_data_->session_id << "\n";
+ os_ << " uid: " << session_data_->uid << "\n";
+ os_ << " compilation_reason: " << CompilationReasonName(session_data_->compilation_reason)
+ << "\n";
+ os_ << " compiler_filter: "
+ << (session_data_->compiler_filter.has_value()
+ ? CompilerFilter::NameOfFilter(session_data_->compiler_filter.value())
+ : "(unspecified)")
+ << "\n";
+ }
+ os_ << " Metrics:\n";
}
-void StreamBackend::ReportHistogram(DatumId histogram_type,
+void StringBackend::EndReport() { os_ << "*** Done dumping ART internal metrics ***\n"; }
+
+void StringBackend::ReportCounter(DatumId counter_type, uint64_t value) {
+ os_ << " " << DatumName(counter_type) << ": count = " << value << "\n";
+}
+
+void StringBackend::ReportHistogram(DatumId histogram_type,
int64_t minimum_value_,
int64_t maximum_value_,
const std::vector<uint32_t>& buckets) {
- os_ << DatumName(histogram_type) << ": range = " << minimum_value_ << "..." << maximum_value_;
+ os_ << " " << DatumName(histogram_type) << ": range = " << minimum_value_ << "..." << maximum_value_;
if (buckets.size() > 0) {
os_ << ", buckets: ";
bool first = true;
@@ -112,6 +155,39 @@
}
}
+LogBackend::LogBackend(android::base::LogSeverity level) : level_{level} {}
+
+void LogBackend::BeginReport(uint64_t timestamp_since_start_ms) {
+ GetAndResetBuffer();
+ StringBackend::BeginReport(timestamp_since_start_ms);
+}
+
+void LogBackend::EndReport() {
+ StringBackend::EndReport();
+ LOG_STREAM(level_) << GetAndResetBuffer();
+}
+
+FileBackend::FileBackend(std::string filename) : filename_{filename} {}
+
+void FileBackend::BeginReport(uint64_t timestamp_since_start_ms) {
+ GetAndResetBuffer();
+ StringBackend::BeginReport(timestamp_since_start_ms);
+}
+
+void FileBackend::EndReport() {
+ StringBackend::EndReport();
+ std::string error_message;
+ auto file{
+ LockedFile::Open(filename_.c_str(), O_CREAT | O_WRONLY | O_APPEND, true, &error_message)};
+ if (file.get() == nullptr) {
+ LOG(WARNING) << "Could open metrics file '" << filename_ << "': " << error_message;
+ } else {
+ if (!android::base::WriteStringToFd(GetAndResetBuffer(), file.get()->Fd())) {
+ PLOG(WARNING) << "Error writing metrics to file";
+ }
+ }
+}
+
} // namespace metrics
} // namespace art
diff --git a/libartbase/base/metrics/metrics_test.cc b/libartbase/base/metrics/metrics_test.cc
index f568ea0..4643f14 100644
--- a/libartbase/base/metrics/metrics_test.cc
+++ b/libartbase/base/metrics/metrics_test.cc
@@ -208,20 +208,20 @@
// Makes sure all defined metrics are included when dumping through StreamBackend.
TEST_F(MetricsTest, StreamBackendDumpAllMetrics) {
ArtMetrics metrics;
- std::stringstream os;
- StreamBackend backend(os);
+ StringBackend backend;
metrics.ReportAllMetrics(&backend);
// Make sure the resulting string lists all the counters.
+ const std::string result = backend.GetAndResetBuffer();
#define COUNTER(name) \
- EXPECT_NE(os.str().find(DatumName(DatumId::k##name)), std::string::npos)
+ EXPECT_NE(result.find(DatumName(DatumId::k##name)), std::string::npos)
ART_COUNTERS(COUNTER);
#undef COUNTER
// Make sure the resulting string lists all the histograms.
#define HISTOGRAM(name, num_buckets, minimum_value, maximum_value) \
- EXPECT_NE(os.str().find(DatumName(DatumId::k##name)), std::string::npos)
+ EXPECT_NE(result.find(DatumName(DatumId::k##name)), std::string::npos)
ART_HISTOGRAMS(HISTOGRAM);
#undef HISTOGRAM
}
diff --git a/libartbase/base/metrics/metrics_test.h b/libartbase/base/metrics/metrics_test.h
index 72ca90e..4a7dad8 100644
--- a/libartbase/base/metrics/metrics_test.h
+++ b/libartbase/base/metrics/metrics_test.h
@@ -34,7 +34,8 @@
class TestBackendBase : public MetricsBackend {
public:
void BeginSession([[maybe_unused]] const SessionData& session_data) override {}
- void EndSession() override {}
+
+ void BeginReport([[maybe_unused]] uint64_t timestamp_since_start_ms) override {}
void ReportCounter([[maybe_unused]] DatumId counter_type,
[[maybe_unused]] uint64_t value) override {}
@@ -43,6 +44,8 @@
[[maybe_unused]] int64_t low_value_,
[[maybe_unused]] int64_t high_value,
[[maybe_unused]] const std::vector<uint32_t>& buckets) override {}
+
+ void EndReport() override {}
};
template <DatumId counter_type>