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
gugelfrei
Andy Hung 5 years ago
parent 6425bcd8d5
commit 3b4c1f0320

@ -210,31 +210,66 @@ status_t mediametrics::Item::writeToParcel0(Parcel *data) const {
}
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;
}

@ -149,6 +149,85 @@ enum Type {
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 @@ protected:
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 @@ public:
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 @@ public:
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.

@ -79,8 +79,7 @@ bool MediaMetricsService::useUidForPackage(
MediaMetricsService::MediaMetricsService()
: mMaxRecords(kMaxRecords),
mMaxRecordAgeNs(kMaxRecordAgeNs),
mMaxRecordsExpiredAtOnce(kMaxExpiredAtOnce),
mDumpProtoDefault(mediametrics::Item::PROTO_V1)
mMaxRecordsExpiredAtOnce(kMaxExpiredAtOnce)
{
ALOGD("%s", __func__);
}
@ -171,12 +170,12 @@ status_t MediaMetricsService::submitInternal(mediametrics::Item *item, bool rele
}
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 @@ status_t MediaMetricsService::dump(int fd, const Vector<String16>& args)
// 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 @@ status_t MediaMetricsService::dump(int fd, const Vector<String16>& args)
} 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 @@ status_t MediaMetricsService::dump(int fd, const Vector<String16>& args)
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 @@ status_t MediaMetricsService::dump(int fd, const Vector<String16>& args)
}
// 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::dumpHeaders_l(String8 &result, int dumpProto, nsecs_t
}
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 @@ void MediaMetricsService::dumpQueue_l(
continue;
}
result.appendFormat("%5d: %s\n",
slot, item->toString(dumpProto).c_str());
slot, item->toString().c_str());
slot++;
}
}

@ -85,11 +85,11 @@ private:
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 @@ private:
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.

@ -157,9 +157,22 @@ private:
}
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 ? "" : "~") << &timestring.time[offset]
<< ") " << eptr->second;
if (++eptr == timeSequence.end()) {
ss << "}";
break;
}
ss << ", ";
}
ss << "};\n";
return ss.str();
}

@ -155,7 +155,7 @@ public:
--ll;
for (const auto &item : itemMap.second) {
if (ll <= 0) break;
ss << " { " << item.first << ", " << item.second->toString() << " }\n";
ss << " " << item.second->toString() << "\n";
--ll;
}
}

Loading…
Cancel
Save