MediaMetrics: Change dumpsys format
As the dumpsys no longer needs to be parseable by a program
convert to a more human readable form.
1) Make default time REALTIME consistently.
2) Dump time as a human readable string.
3) Remove dumpsys versioning code.
4) Delimiter changes.
Test: atest mediametrics_tests
Test: adb shell dumpsys media.metrics
Bug: 138583596
Change-Id: I6ee7d81a18e0e220b258c722d232c05805118abb
diff --git a/media/libmediametrics/MediaMetricsItem.cpp b/media/libmediametrics/MediaMetricsItem.cpp
index 62af0f7..4371668 100644
--- a/media/libmediametrics/MediaMetricsItem.cpp
+++ b/media/libmediametrics/MediaMetricsItem.cpp
@@ -210,31 +210,66 @@
}
const char *mediametrics::Item::toCString() {
- return toCString(PROTO_LAST);
-}
-
-const char * mediametrics::Item::toCString(int version) {
- std::string val = toString(version);
+ std::string val = toString();
return strdup(val.c_str());
}
-std::string mediametrics::Item::toString() const {
- return toString(PROTO_LAST);
+/*
+ * Similar to audio_utils/clock.h but customized for displaying mediametrics time.
+ */
+
+void nsToString(int64_t ns, char *buffer, size_t bufferSize, PrintFormat format)
+{
+ if (bufferSize == 0) return;
+
+ const int one_second = 1000000000;
+ const time_t sec = ns / one_second;
+ struct tm tm;
+
+ // Supported on bionic, glibc, and macOS, but not mingw.
+ if (localtime_r(&sec, &tm) == NULL) {
+ buffer[0] = '\0';
+ return;
+ }
+
+ switch (format) {
+ default:
+ case kPrintFormatLong:
+ if (snprintf(buffer, bufferSize, "%02d-%02d %02d:%02d:%02d.%03d",
+ tm.tm_mon + 1, // localtime_r uses months in 0 - 11 range
+ tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec,
+ (int)(ns % one_second / 1000000)) < 0) {
+ buffer[0] = '\0'; // null terminate on format error, which should not happen
+ }
+ break;
+ case kPrintFormatShort:
+ if (snprintf(buffer, bufferSize, "%02d:%02d:%02d.%03d",
+ tm.tm_hour, tm.tm_min, tm.tm_sec,
+ (int)(ns % one_second / 1000000)) < 0) {
+ buffer[0] = '\0'; // null terminate on format error, which should not happen
+ }
+ break;
+ }
}
-std::string mediametrics::Item::toString(int version) const {
+std::string mediametrics::Item::toString() const {
std::string result;
char buffer[kMaxPropertyStringSize];
- snprintf(buffer, sizeof(buffer), "[%d:%s:%d:%d:%lld:%s:%zu:",
- version, mKey.c_str(), mPid, mUid, (long long)mTimestamp,
- mPkgName.c_str(), mProps.size());
+ snprintf(buffer, sizeof(buffer), "{%s, (%s), (%s, %d, %d)",
+ mKey.c_str(),
+ timeStringFromNs(mTimestamp, kPrintFormatLong).time,
+ mPkgName.c_str(), mPid, mUid
+ );
result.append(buffer);
+ bool first = true;
for (auto &prop : *this) {
prop.toStringBuffer(buffer, sizeof(buffer));
- result.append(buffer);
+ result += first ? ", (" : ", ";
+ result += buffer;
+ first = false;
}
- result.append("]");
+ result.append(")}");
return result;
}
diff --git a/media/libmediametrics/include/media/MediaMetricsItem.h b/media/libmediametrics/include/media/MediaMetricsItem.h
index 6141b36..b40eb4c 100644
--- a/media/libmediametrics/include/media/MediaMetricsItem.h
+++ b/media/libmediametrics/include/media/MediaMetricsItem.h
@@ -149,6 +149,85 @@
kTypeRate = 5,
};
+/*
+ * Time printing
+ *
+ * kPrintFormatLong time string is 19 characters (including null termination).
+ * Example Long Form: "03-27 16:47:06.187"
+ * MM DD HH MM SS MS
+ *
+ * kPrintFormatShort time string is 13 characters (including null termination).
+ * Example Short Form: "16:47:06.187"
+ * HH MM SS MS
+ */
+
+enum PrintFormat {
+ kPrintFormatLong = 0,
+ kPrintFormatShort = 1,
+};
+
+/**
+ * Converts real time in ns to a time string object, with format similar to logcat.
+ *
+ * \param ns input real time in nanoseconds to convert.
+ * \param buffer the buffer location to put the converted string.
+ * \param bufferSize the size of buffer in bytes.
+ * \param format format, from enum PrintFormat.
+ */
+void nsToString(
+ int64_t ns, char *buffer, size_t bufferSize, PrintFormat format = kPrintFormatLong);
+
+// Contains the time string
+struct time_string_t {
+ char time[19]; /* minimum size buffer */
+};
+
+/**
+ * Converts real time in ns to a time string object, with format similar to logcat.
+ *
+ * \param ns input real time in nanoseconds to convert.
+ * \param format format, from enum PrintFormat.
+ * \return a time_string_t object with the time string encoded.
+ */
+static inline time_string_t timeStringFromNs(int64_t ns, PrintFormat format = kPrintFormatLong) {
+ time_string_t ts;
+ nsToString(ns, ts.time, sizeof(ts.time), format);
+ return ts;
+}
+
+/**
+ * Finds the end of the common time prefix.
+ *
+ * This is as an option to remove the common time prefix to avoid
+ * unnecessary duplicated strings.
+ *
+ * \param time1 a time string from timeStringFromNs
+ * \param time2 a time string from timeStringFromNs
+ * \return the position where the common time prefix ends. For abbreviated
+ * printing of time2, offset the character pointer by this position.
+ */
+static inline size_t commonTimePrefixPosition(const char *time1, const char *time2) {
+ size_t i;
+
+ // Find location of the first mismatch between strings
+ for (i = 0; ; ++i) {
+ if (time1[i] != time2[i]) {
+ break;
+ }
+ if (time1[i] == 0) {
+ return i; // strings match completely
+ }
+ }
+
+ // Go backwards until we find a delimeter or space.
+ for (; i > 0
+ && isdigit(time1[i]) // still a number
+ && time1[i - 1] != ' '
+ ; --i) {
+ }
+ return i;
+}
+
/**
* The MediaMetrics Item has special Item properties,
* derived internally or through dedicated setters.
@@ -341,35 +420,35 @@
template <> // static
void toStringBuffer(
const char *name, const int32_t& value, char *buffer, size_t length) {
- snprintf(buffer, length, "%s=%d:", name, value);
+ snprintf(buffer, length, "%s=%d", name, value);
}
template <> // static
void toStringBuffer(
const char *name, const int64_t& value, char *buffer, size_t length) {
- snprintf(buffer, length, "%s=%lld:", name, (long long)value);
+ snprintf(buffer, length, "%s=%lld", name, (long long)value);
}
template <> // static
void toStringBuffer(
const char *name, const double& value, char *buffer, size_t length) {
- snprintf(buffer, length, "%s=%e:", name, value);
+ snprintf(buffer, length, "%s=%e", name, value);
}
template <> // static
void toStringBuffer(
const char *name, const std::pair<int64_t, int64_t>& value,
char *buffer, size_t length) {
- snprintf(buffer, length, "%s=%lld/%lld:",
+ snprintf(buffer, length, "%s=%lld/%lld",
name, (long long)value.first, (long long)value.second);
}
template <> // static
void toStringBuffer(
const char *name, const std::string& value, char *buffer, size_t length) {
// TODO sanitize string for ':' '='
- snprintf(buffer, length, "%s=%s:", name, value.c_str());
+ snprintf(buffer, length, "%s=%s", name, value.c_str());
}
template <> // static
void toStringBuffer(
const char *name, const std::monostate&, char *buffer, size_t length) {
- snprintf(buffer, length, "%s=():", name);
+ snprintf(buffer, length, "%s=()", name);
}
template <typename T>
@@ -839,13 +918,6 @@
return iterator(mProps.cend());
}
- enum {
- PROTO_V0 = 0,
- PROTO_FIRST = PROTO_V0,
- PROTO_V1 = 1,
- PROTO_LAST = PROTO_V1,
- };
-
// T must be convertible to mKey
template <typename T>
explicit Item(T key)
@@ -1043,9 +1115,7 @@
std::string toString() const;
- std::string toString(int version) const;
const char *toCString();
- const char *toCString(int version);
/**
* Returns true if the item has a property with a target value.
diff --git a/services/mediametrics/MediaMetricsService.cpp b/services/mediametrics/MediaMetricsService.cpp
index 3b95f7a..4f8589c 100644
--- a/services/mediametrics/MediaMetricsService.cpp
+++ b/services/mediametrics/MediaMetricsService.cpp
@@ -79,8 +79,7 @@
MediaMetricsService::MediaMetricsService()
: mMaxRecords(kMaxRecords),
mMaxRecordAgeNs(kMaxRecordAgeNs),
- mMaxRecordsExpiredAtOnce(kMaxExpiredAtOnce),
- mDumpProtoDefault(mediametrics::Item::PROTO_V1)
+ mMaxRecordsExpiredAtOnce(kMaxExpiredAtOnce)
{
ALOGD("%s", __func__);
}
@@ -171,12 +170,12 @@
}
if (!isTrusted || item->getTimestamp() == 0) {
- // WestWorld logs two times for events: ElapsedRealTimeNs (BOOTTIME) and
- // WallClockTimeNs (REALTIME). The new audio keys use BOOTTIME.
+ // Westworld logs two times for events: ElapsedRealTimeNs (BOOTTIME) and
+ // WallClockTimeNs (REALTIME), but currently logs REALTIME to cloud.
//
- // TODO: Reevaluate time base with other teams.
- const bool useBootTime = startsWith(item->getKey(), "audio.");
- const int64_t now = systemTime(useBootTime ? SYSTEM_TIME_BOOTTIME : SYSTEM_TIME_REALTIME);
+ // For consistency and correlation with other logging mechanisms
+ // we use REALTIME here.
+ const int64_t now = systemTime(SYSTEM_TIME_REALTIME);
item->setTimestamp(now);
}
@@ -206,7 +205,6 @@
// crack any parameters
const String16 protoOption("-proto");
- int chosenProto = mDumpProtoDefault;
const String16 clearOption("-clear");
bool clear = false;
const String16 sinceOption("-since");
@@ -221,21 +219,7 @@
} else if (args[i] == protoOption) {
i++;
if (i < n) {
- String8 value(args[i]);
- int proto = mediametrics::Item::PROTO_V0;
- char *endp;
- const char *p = value.string();
- proto = strtol(p, &endp, 10);
- if (endp != p || *endp == '\0') {
- if (proto < mediametrics::Item::PROTO_FIRST) {
- proto = mediametrics::Item::PROTO_FIRST;
- } else if (proto > mediametrics::Item::PROTO_LAST) {
- proto = mediametrics::Item::PROTO_LAST;
- }
- chosenProto = proto;
- } else {
- result.append("unable to parse value for -proto\n\n");
- }
+ // ignore
} else {
result.append("missing value for -proto\n\n");
}
@@ -281,8 +265,8 @@
std::lock_guard _l(mLock);
result.appendFormat("Dump of the %s process:\n", kServiceName);
- dumpHeaders_l(result, chosenProto, ts_since);
- dumpRecent_l(result, chosenProto, ts_since, only.c_str());
+ dumpHeaders_l(result, ts_since);
+ dumpRecent_l(result, ts_since, only.c_str());
if (clear) {
mItemsDiscarded += mItems.size();
@@ -303,9 +287,8 @@
}
// dump headers
-void MediaMetricsService::dumpHeaders_l(String8 &result, int dumpProto, nsecs_t ts_since)
+void MediaMetricsService::dumpHeaders_l(String8 &result, nsecs_t ts_since)
{
- result.appendFormat("Protocol Version: %d\n", dumpProto);
if (mediametrics::Item::isEnabled()) {
result.append("Metrics gathering: enabled\n");
} else {
@@ -326,25 +309,25 @@
}
void MediaMetricsService::dumpRecent_l(
- String8 &result, int dumpProto, nsecs_t ts_since, const char * only)
+ String8 &result, nsecs_t ts_since, const char * only)
{
if (only != nullptr && *only == '\0') {
only = nullptr;
}
result.append("\nFinalized Metrics (oldest first):\n");
- dumpQueue_l(result, dumpProto, ts_since, only);
+ dumpQueue_l(result, ts_since, only);
// show who is connected and injecting records?
// talk about # records fed to the 'readers'
// talk about # records we discarded, perhaps "discarded w/o reading" too
}
-void MediaMetricsService::dumpQueue_l(String8 &result, int dumpProto) {
- dumpQueue_l(result, dumpProto, (nsecs_t) 0, nullptr /* only */);
+void MediaMetricsService::dumpQueue_l(String8 &result) {
+ dumpQueue_l(result, (nsecs_t) 0, nullptr /* only */);
}
void MediaMetricsService::dumpQueue_l(
- String8 &result, int dumpProto, nsecs_t ts_since, const char * only) {
+ String8 &result, nsecs_t ts_since, const char * only) {
int slot = 0;
if (mItems.empty()) {
@@ -363,7 +346,7 @@
continue;
}
result.appendFormat("%5d: %s\n",
- slot, item->toString(dumpProto).c_str());
+ slot, item->toString().c_str());
slot++;
}
}
diff --git a/services/mediametrics/MediaMetricsService.h b/services/mediametrics/MediaMetricsService.h
index 74a114a..935bee2 100644
--- a/services/mediametrics/MediaMetricsService.h
+++ b/services/mediametrics/MediaMetricsService.h
@@ -85,11 +85,11 @@
bool expirations_l(const std::shared_ptr<const mediametrics::Item>& item);
// support for generating output
- void dumpQueue_l(String8 &result, int dumpProto);
- void dumpQueue_l(String8 &result, int dumpProto, nsecs_t, const char *only);
- void dumpHeaders_l(String8 &result, int dumpProto, nsecs_t ts_since);
- void dumpSummaries_l(String8 &result, int dumpProto, nsecs_t ts_since, const char * only);
- void dumpRecent_l(String8 &result, int dumpProto, nsecs_t ts_since, const char * only);
+ void dumpQueue_l(String8 &result);
+ void dumpQueue_l(String8 &result, nsecs_t, const char *only);
+ void dumpHeaders_l(String8 &result, nsecs_t ts_since);
+ void dumpSummaries_l(String8 &result, nsecs_t ts_since, const char * only);
+ void dumpRecent_l(String8 &result, nsecs_t ts_since, const char * only);
// The following variables accessed without mLock
@@ -100,7 +100,6 @@
const nsecs_t mMaxRecordAgeNs;
// max to expire per expirations_l() invocation
const size_t mMaxRecordsExpiredAtOnce;
- const int mDumpProtoDefault;
std::atomic<int64_t> mItemsSubmitted{}; // accessed outside of lock.
diff --git a/services/mediametrics/TimeMachine.h b/services/mediametrics/TimeMachine.h
index 4d24ce4..87de1c4 100644
--- a/services/mediametrics/TimeMachine.h
+++ b/services/mediametrics/TimeMachine.h
@@ -157,9 +157,22 @@
}
std::stringstream ss;
ss << key << "." << tsPair.first << "={";
- do {
- ss << eptr->first << ":" << eptr->second << ",";
- } while (++eptr != timeSequence.end());
+
+ time_string_t last_timestring{}; // last timestring used.
+ while (true) {
+ const time_string_t timestring = mediametrics::timeStringFromNs(eptr->first);
+ // find common prefix offset.
+ const size_t offset = commonTimePrefixPosition(timestring.time,
+ last_timestring.time);
+ last_timestring = timestring;
+ ss << "(" << (offset == 0 ? "" : "~") << ×tring.time[offset]
+ << ") " << eptr->second;
+ if (++eptr == timeSequence.end()) {
+ ss << "}";
+ break;
+ }
+ ss << ", ";
+ }
ss << "};\n";
return ss.str();
}
diff --git a/services/mediametrics/TransactionLog.h b/services/mediametrics/TransactionLog.h
index 0c5d12b..27e2c14 100644
--- a/services/mediametrics/TransactionLog.h
+++ b/services/mediametrics/TransactionLog.h
@@ -155,7 +155,7 @@
--ll;
for (const auto &item : itemMap.second) {
if (ll <= 0) break;
- ss << " { " << item.first << ", " << item.second->toString() << " }\n";
+ ss << " " << item.second->toString() << "\n";
--ll;
}
}