NBLog: refactor Writer API for extensibility
No new functionality was added, and no existing functionality was
removed.
Event types have been renamed and reorganized according to
functionality. A compile-time mapping from Event to C++ data type allows
for a generic Event log() template function to avoid the need to add a
new logging function when a new Event is added to enum NBLog::Event.
Most LockedWriter functions were deleted because they did not involve
accessing shared variables. Only the functions that accessed shared
variables were kept in LockedWriter.
Test: dumpsys media.log -r
Bug: 68148948
Change-Id: I8a27f1690795cdb0b84e92033b7cbf4588ba175e
diff --git a/media/libnblog/NBLog.cpp b/media/libnblog/NBLog.cpp
index f1d7523..f73e2ae 100644
--- a/media/libnblog/NBLog.cpp
+++ b/media/libnblog/NBLog.cpp
@@ -68,7 +68,7 @@
}
const uint8_t type = EntryIterator(ptr)->type;
switch (type) {
- case EVENT_START_FMT:
+ case EVENT_FMT_START:
return std::make_unique<FormatEntry>(FormatEntry(ptr));
case EVENT_AUDIO_STATE:
case EVENT_HISTOGRAM_ENTRY_TS:
@@ -107,7 +107,7 @@
++it; // skip timestamp
++it; // skip hash
// Skip author if present
- if (it->type == EVENT_AUTHOR) {
+ if (it->type == EVENT_FMT_AUTHOR) {
++it;
}
return it;
@@ -138,7 +138,7 @@
++it; // skip timestamp
++it; // skip hash
// if there is an author entry, return it, return -1 otherwise
- return it->type == EVENT_AUTHOR ? it.payload<int>() : -1;
+ return it->type == EVENT_FMT_AUTHOR ? it.payload<int>() : -1;
}
NBLog::EntryIterator NBLog::FormatEntry::copyWithAuthor(
@@ -151,14 +151,14 @@
// insert author entry
size_t authorEntrySize = Entry::kOverhead + sizeof(author);
uint8_t authorEntry[authorEntrySize];
- authorEntry[offsetof(entry, type)] = EVENT_AUTHOR;
+ authorEntry[offsetof(entry, type)] = EVENT_FMT_AUTHOR;
authorEntry[offsetof(entry, length)] =
authorEntry[authorEntrySize + Entry::kPreviousLengthOffset] =
sizeof(author);
*(int*) (&authorEntry[offsetof(entry, data)]) = author;
dst->write(authorEntry, authorEntrySize);
// copy rest of entries
- while ((++it)->type != EVENT_END_FMT) {
+ while ((++it)->type != EVENT_FMT_END) {
it.copyTo(dst);
}
it.copyTo(dst);
@@ -394,46 +394,12 @@
if (!mEnabled) {
return;
}
- int64_t ts = get_monotonic_ns();
- if (ts > 0) {
+ struct timespec ts;
+ if (!clock_gettime(CLOCK_MONOTONIC, &ts)) {
log(EVENT_TIMESTAMP, &ts, sizeof(ts));
- } else {
- ALOGE("Failed to get timestamp");
}
}
-void NBLog::Writer::logTimestamp(const int64_t ts)
-{
- if (!mEnabled) {
- return;
- }
- log(EVENT_TIMESTAMP, &ts, sizeof(ts));
-}
-
-void NBLog::Writer::logInteger(const int x)
-{
- if (!mEnabled) {
- return;
- }
- log(EVENT_INTEGER, &x, sizeof(x));
-}
-
-void NBLog::Writer::logFloat(const float x)
-{
- if (!mEnabled) {
- return;
- }
- log(EVENT_FLOAT, &x, sizeof(x));
-}
-
-void NBLog::Writer::logPID()
-{
- if (!mEnabled) {
- return;
- }
- log(EVENT_PID, mPidTag, mPidTagSize);
-}
-
void NBLog::Writer::logStart(const char *fmt)
{
if (!mEnabled) {
@@ -443,24 +409,20 @@
if (length > Entry::kMaxLength) {
length = Entry::kMaxLength;
}
- log(EVENT_START_FMT, fmt, length);
+ log(EVENT_FMT_START, fmt, length);
}
-void NBLog::Writer::logEnd()
+void NBLog::Writer::logTimestampFormat()
{
if (!mEnabled) {
return;
}
- Entry entry = Entry(EVENT_END_FMT, NULL, 0);
- log(entry, true);
-}
-
-void NBLog::Writer::logHash(log_hash_t hash)
-{
- if (!mEnabled) {
- return;
+ int64_t ts = get_monotonic_ns();
+ if (ts > 0) {
+ log(EVENT_FMT_TIMESTAMP, &ts, sizeof(ts));
+ } else {
+ ALOGE("Failed to get timestamp");
}
- log(EVENT_HASH, &hash, sizeof(hash));
}
void NBLog::Writer::logEventHistTs(Event event, log_hash_t hash)
@@ -478,22 +440,6 @@
}
}
-void NBLog::Writer::logLatency(double latencyMs)
-{
- if (!mEnabled) {
- return;
- }
- log(EVENT_LATENCY, &latencyMs, sizeof(latencyMs));
-}
-
-void NBLog::Writer::logMonotonicCycleTime(uint32_t monotonicNs)
-{
- if (!mEnabled) {
- return;
- }
- log(EVENT_MONOTONIC_CYCLE_TIME, &monotonicNs, sizeof(monotonicNs));
-}
-
void NBLog::Writer::logFormat(const char *fmt, log_hash_t hash, ...)
{
if (!mEnabled) {
@@ -512,11 +458,13 @@
}
Writer::logStart(fmt);
int i;
- double f;
+ double d;
+ float f;
char* s;
+ size_t length;
int64_t t;
- Writer::logTimestamp();
- Writer::logHash(hash);
+ Writer::logTimestampFormat();
+ log(EVENT_FMT_HASH, &hash, sizeof(hash));
for (const char *p = fmt; *p != '\0'; p++) {
// TODO: implement more complex formatting such as %.3f
if (*p != '%') {
@@ -525,26 +473,31 @@
switch(*++p) {
case 's': // string
s = va_arg(argp, char *);
- Writer::log(s);
+ length = strlen(s);
+ if (length > Entry::kMaxLength) {
+ length = Entry::kMaxLength;
+ }
+ log(EVENT_FMT_STRING, s, length);
break;
case 't': // timestamp
t = va_arg(argp, int64_t);
- Writer::logTimestamp(t);
+ log(EVENT_FMT_TIMESTAMP, &t, sizeof(t));
break;
case 'd': // integer
i = va_arg(argp, int);
- Writer::logInteger(i);
+ log(EVENT_FMT_INTEGER, &i, sizeof(i));
break;
case 'f': // float
- f = va_arg(argp, double); // float arguments are promoted to double in vararg lists
- Writer::logFloat((float)f);
+ d = va_arg(argp, double); // float arguments are promoted to double in vararg lists
+ f = (float)d;
+ log(EVENT_FMT_FLOAT, &f, sizeof(f));
break;
case 'p': // pid
- Writer::logPID();
+ log(EVENT_FMT_PID, mPidTag, mPidTagSize);
break;
// the "%\0" case finishes parsing
@@ -560,7 +513,8 @@
break;
}
}
- Writer::logEnd();
+ Entry etr(EVENT_FMT_END, nullptr, 0);
+ log(etr, true);
}
void NBLog::Writer::log(Event event, const void *data, size_t length)
@@ -630,79 +584,6 @@
{
}
-void NBLog::LockedWriter::log(const char *string)
-{
- Mutex::Autolock _l(mLock);
- Writer::log(string);
-}
-
-void NBLog::LockedWriter::logf(const char *fmt, ...)
-{
- // FIXME should not take the lock until after formatting is done
- Mutex::Autolock _l(mLock);
- va_list ap;
- va_start(ap, fmt);
- Writer::logvf(fmt, ap);
- va_end(ap);
-}
-
-void NBLog::LockedWriter::logvf(const char *fmt, va_list ap)
-{
- // FIXME should not take the lock until after formatting is done
- Mutex::Autolock _l(mLock);
- Writer::logvf(fmt, ap);
-}
-
-void NBLog::LockedWriter::logTimestamp()
-{
- // FIXME should not take the lock until after the clock_gettime() syscall
- Mutex::Autolock _l(mLock);
- Writer::logTimestamp();
-}
-
-void NBLog::LockedWriter::logTimestamp(const int64_t ts)
-{
- Mutex::Autolock _l(mLock);
- Writer::logTimestamp(ts);
-}
-
-void NBLog::LockedWriter::logInteger(const int x)
-{
- Mutex::Autolock _l(mLock);
- Writer::logInteger(x);
-}
-
-void NBLog::LockedWriter::logFloat(const float x)
-{
- Mutex::Autolock _l(mLock);
- Writer::logFloat(x);
-}
-
-void NBLog::LockedWriter::logPID()
-{
- Mutex::Autolock _l(mLock);
- Writer::logPID();
-}
-
-void NBLog::LockedWriter::logStart(const char *fmt)
-{
- Mutex::Autolock _l(mLock);
- Writer::logStart(fmt);
-}
-
-
-void NBLog::LockedWriter::logEnd()
-{
- Mutex::Autolock _l(mLock);
- Writer::logEnd();
-}
-
-void NBLog::LockedWriter::logHash(log_hash_t hash)
-{
- Mutex::Autolock _l(mLock);
- Writer::logHash(hash);
-}
-
bool NBLog::LockedWriter::isEnabled() const
{
Mutex::Autolock _l(mLock);
@@ -715,21 +596,47 @@
return Writer::setEnabled(enabled);
}
+void NBLog::LockedWriter::log(const Entry &entry, bool trusted) {
+ Mutex::Autolock _l(mLock);
+ Writer::log(entry, trusted);
+}
+
// ---------------------------------------------------------------------------
-const std::unordered_set<NBLog::Event> NBLog::Reader::startingTypes {
- NBLog::Event::EVENT_START_FMT,
- NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS,
- NBLog::Event::EVENT_AUDIO_STATE,
- NBLog::Event::EVENT_LATENCY,
- NBLog::Event::EVENT_MONOTONIC_CYCLE_TIME
+// We make a set of the invalid types rather than the valid types when aligning
+// Snapshot EntryIterators to valid entries during log corruption checking.
+// This is done in order to avoid the maintenance overhead of adding a new NBLog::Event
+// type to the two sets below whenever a new NBLog::Event type is created, as it is
+// very likely that new types added will be valid types.
+// Currently, invalidBeginTypes and invalidEndTypes are used to handle the special
+// case of a Format Entry, which consists of a variable number of simple log entries.
+// If a new NBLog::Event is added that consists of a variable number of simple log entries,
+// then these sets need to be updated.
+
+// We want the beginning of a Snapshot to point to an entry that is not in
+// the middle of a formatted entry and not an FMT_END.
+const std::unordered_set<NBLog::Event> NBLog::Reader::invalidBeginTypes {
+ NBLog::Event::EVENT_FMT_TIMESTAMP,
+ NBLog::Event::EVENT_FMT_HASH,
+ NBLog::Event::EVENT_FMT_STRING,
+ NBLog::Event::EVENT_FMT_INTEGER,
+ NBLog::Event::EVENT_FMT_FLOAT,
+ NBLog::Event::EVENT_FMT_PID,
+ NBLog::Event::EVENT_FMT_AUTHOR,
+ NBLog::Event::EVENT_FMT_END
};
-const std::unordered_set<NBLog::Event> NBLog::Reader::endingTypes {
- NBLog::Event::EVENT_END_FMT,
- NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS,
- NBLog::Event::EVENT_AUDIO_STATE,
- NBLog::Event::EVENT_LATENCY,
- NBLog::Event::EVENT_MONOTONIC_CYCLE_TIME
+
+// We want the end of a Snapshot to point to an entry that is not in
+// the middle of a formatted entry and not a FMT_START.
+const std::unordered_set<NBLog::Event> NBLog::Reader::invalidEndTypes {
+ NBLog::Event::EVENT_FMT_START,
+ NBLog::Event::EVENT_FMT_TIMESTAMP,
+ NBLog::Event::EVENT_FMT_HASH,
+ NBLog::Event::EVENT_FMT_STRING,
+ NBLog::Event::EVENT_FMT_INTEGER,
+ NBLog::Event::EVENT_FMT_FLOAT,
+ NBLog::Event::EVENT_FMT_PID,
+ NBLog::Event::EVENT_FMT_AUTHOR
};
NBLog::Reader::Reader(const void *shared, size_t size, const std::string &name)
@@ -754,17 +661,22 @@
delete mFifo;
}
-const uint8_t *NBLog::Reader::findLastEntryOfTypes(const uint8_t *front, const uint8_t *back,
- const std::unordered_set<Event> &types) {
+const uint8_t *NBLog::Reader::findLastValidEntry(const uint8_t *front, const uint8_t *back,
+ const std::unordered_set<Event> &invalidTypes) {
+ if (front == nullptr || back == nullptr) {
+ return nullptr;
+ }
while (back + Entry::kPreviousLengthOffset >= front) {
const uint8_t *prev = back - back[Entry::kPreviousLengthOffset] - Entry::kOverhead;
- if (prev < front || prev + prev[offsetof(entry, length)] +
- Entry::kOverhead != back) {
-
+ const Event type = (const Event)prev[offsetof(entry, type)];
+ if (prev < front
+ || prev + prev[offsetof(entry, length)] + Entry::kOverhead != back
+ || type <= NBLog::EVENT_RESERVED || type >= NBLog::EVENT_UPPER_BOUND) {
// prev points to an out of limits or inconsistent entry
return nullptr;
}
- if (types.find((const Event) prev[offsetof(entry, type)]) != types.end()) {
+ // if invalidTypes does not contain the type, then the type is valid.
+ if (invalidTypes.find(type) == invalidTypes.end()) {
return prev;
}
back = prev;
@@ -778,7 +690,7 @@
std::unique_ptr<NBLog::Snapshot> NBLog::Reader::getSnapshot()
{
if (mFifoReader == NULL) {
- return std::make_unique<Snapshot>();
+ return std::unique_ptr<Snapshot>(new Snapshot());
}
// This emulates the behaviour of audio_utils_fifo_reader::read, but without incrementing the
@@ -808,9 +720,20 @@
if (availToRead <= 0) {
ALOGW_IF(availToRead < 0, "NBLog Reader %s failed to catch up with Writer", mName.c_str());
- return std::make_unique<Snapshot>();
+ return std::unique_ptr<Snapshot>(new Snapshot());
}
+ // Change to #if 1 for debugging. This statement is useful for checking buffer fullness levels
+ // (as seen by reader) and how much data was lost. If you find that the fullness level is
+ // getting close to full, or that data loss is happening to often, then you should
+ // probably try some of the following:
+ // - log less data
+ // - log less often
+ // - increase the initial shared memory allocation for the buffer
+#if 0
+ ALOGD("getSnapshot name=%s, availToRead=%zd, capacity=%zu, fullness=%.3f, lost=%zu",
+ name().c_str(), availToRead, capacity, (double)availToRead / (double)capacity, lost);
+#endif
std::unique_ptr<Snapshot> snapshot(new Snapshot(availToRead));
memcpy(snapshot->mData, (const char *) mFifo->buffer() + iovec[0].mOffset, iovec[0].mLength);
if (iovec[1].mLength > 0) {
@@ -821,28 +744,28 @@
// Handle corrupted buffer
// Potentially, a buffer has corrupted data on both beginning (due to overflow) and end
// (due to incomplete format entry). But even if the end format entry is incomplete,
- // it ends in a complete entry (which is not an END_FMT). So is safe to traverse backwards.
+ // it ends in a complete entry (which is not an FMT_END). So is safe to traverse backwards.
// TODO: handle client corruption (in the middle of a buffer)
const uint8_t *back = snapshot->mData + availToRead;
const uint8_t *front = snapshot->mData;
- // Find last END_FMT. <back> is sitting on an entry which might be the middle of a FormatEntry.
- // We go backwards until we find an EVENT_END_FMT.
- const uint8_t *lastEnd = findLastEntryOfTypes(front, back, endingTypes);
+ // Find last FMT_END. <back> is sitting on an entry which might be the middle of a FormatEntry.
+ // We go backwards until we find an EVENT_FMT_END.
+ const uint8_t *lastEnd = findLastValidEntry(front, back, invalidEndTypes);
if (lastEnd == nullptr) {
snapshot->mEnd = snapshot->mBegin = EntryIterator(front);
} else {
- // end of snapshot points to after last END_FMT entry
+ // end of snapshot points to after last FMT_END entry
snapshot->mEnd = EntryIterator(lastEnd).next();
- // find first START_FMT
+ // find first FMT_START
const uint8_t *firstStart = nullptr;
const uint8_t *firstStartTmp = snapshot->mEnd;
- while ((firstStartTmp = findLastEntryOfTypes(front, firstStartTmp, startingTypes))
+ while ((firstStartTmp = findLastValidEntry(front, firstStartTmp, invalidBeginTypes))
!= nullptr) {
firstStart = firstStartTmp;
}
- // firstStart is null if no START_FMT entry was found before lastEnd
+ // firstStart is null if no FMT_START entry was found before lastEnd
if (firstStart == nullptr) {
snapshot->mBegin = snapshot->mEnd;
} else {
@@ -861,43 +784,30 @@
// writes the data to a map of class PerformanceAnalysis, based on their thread ID.
void NBLog::MergeReader::getAndProcessSnapshot(NBLog::Snapshot &snapshot, int author)
{
- for (const entry &etr : snapshot) {
- switch (etr.type) {
+ // We don't do "auto it" because it reduces readability in this case.
+ for (EntryIterator it = snapshot.begin(); it != snapshot.end(); ++it) {
+ switch (it->type) {
case EVENT_HISTOGRAM_ENTRY_TS: {
- HistTsEntry *data = (HistTsEntry *) (etr.data);
- // TODO This memcpies are here to avoid unaligned memory access crash.
- // There's probably a more efficient way to do it
- log_hash_t hash;
- memcpy(&hash, &(data->hash), sizeof(hash));
- int64_t ts;
- memcpy(&ts, &data->ts, sizeof(ts));
+ HistTsEntry payload = it.payload<HistTsEntry>();
// TODO: hash for histogram ts and audio state need to match
// and correspond to audio production source file location
- mThreadPerformanceAnalysis[author][0 /*hash*/].logTsEntry(ts);
+ mThreadPerformanceAnalysis[author][0 /*hash*/].logTsEntry(payload.ts);
} break;
case EVENT_AUDIO_STATE: {
- HistTsEntry *data = (HistTsEntry *) (etr.data);
- // TODO This memcpies are here to avoid unaligned memory access crash.
- // There's probably a more efficient way to do it
- log_hash_t hash;
- memcpy(&hash, &(data->hash), sizeof(hash));
mThreadPerformanceAnalysis[author][0 /*hash*/].handleStateChange();
} break;
case EVENT_LATENCY: {
- double latencyMs;
- memcpy(&latencyMs, etr.data, sizeof(latencyMs));
+ double latencyMs = it.payload<double>();
mPerformanceData.addLatencyEntry(author, latencyMs);
} break;
- case EVENT_MONOTONIC_CYCLE_TIME: {
- uint32_t monotonicNs;
- memcpy(&monotonicNs, etr.data, sizeof(monotonicNs));
+ case EVENT_WORK_TIME: {
+ uint64_t monotonicNs = it.payload<uint64_t>();
const double monotonicMs = monotonicNs * 1e-6;
mPerformanceData.addCycleTimeEntry(author, monotonicMs);
} break;
- case EVENT_END_FMT:
case EVENT_RESERVED:
case EVENT_UPPER_BOUND:
- ALOGW("warning: unexpected event %d", etr.type);
+ ALOGW("warning: unexpected event %d", it->type);
default:
break;
}
@@ -940,22 +850,20 @@
String8 timestamp, body;
// TODO all logged types should have a printable format.
- for (auto it = snapshot->begin(); it != snapshot->end(); ++it) {
+ for (EntryIterator it = snapshot->begin(); it != snapshot->end(); ++it) {
switch (it->type) {
- case EVENT_START_FMT:
+ case EVENT_FMT_START:
it = handleFormat(FormatEntry(it), ×tamp, &body);
break;
- case EVENT_MONOTONIC_CYCLE_TIME: {
- uint32_t monotonicNs;
- memcpy(&monotonicNs, it->data, sizeof(monotonicNs));
- body.appendFormat("Thread cycle: %u ns", monotonicNs);
+ case EVENT_WORK_TIME: {
+ uint64_t monotonicNs = it.payload<uint64_t>();
+ body.appendFormat("Thread cycle: %lu ns", (unsigned long)monotonicNs);
} break;
case EVENT_LATENCY: {
- double latencyMs;
- memcpy(&latencyMs, it->data, sizeof(latencyMs));
+ double latencyMs = it.payload<double>();
body.appendFormat("latency: %.3f ms", latencyMs);
} break;
- case EVENT_END_FMT:
+ case EVENT_FMT_END:
case EVENT_RESERVED:
case EVENT_UPPER_BOUND:
body.appendFormat("warning: unexpected event %d", it->type);
@@ -1078,7 +986,7 @@
// TODO check length for event type is correct
- if (event == EVENT_END_FMT) {
+ if (event == EVENT_FMT_END) {
break;
}
@@ -1087,31 +995,31 @@
switch(fmt[fmt_offset])
{
case 's': // string
- ALOGW_IF(event != EVENT_STRING,
+ ALOGW_IF(event != EVENT_FMT_STRING,
"NBLog Reader incompatible event for string specifier: %d", event);
body->append((const char*) datum, length);
break;
case 't': // timestamp
- ALOGW_IF(event != EVENT_TIMESTAMP,
+ ALOGW_IF(event != EVENT_FMT_TIMESTAMP,
"NBLog Reader incompatible event for timestamp specifier: %d", event);
appendTimestamp(body, datum);
break;
case 'd': // integer
- ALOGW_IF(event != EVENT_INTEGER,
+ ALOGW_IF(event != EVENT_FMT_INTEGER,
"NBLog Reader incompatible event for integer specifier: %d", event);
appendInt(body, datum);
break;
case 'f': // float
- ALOGW_IF(event != EVENT_FLOAT,
+ ALOGW_IF(event != EVENT_FMT_FLOAT,
"NBLog Reader incompatible event for float specifier: %d", event);
appendFloat(body, datum);
break;
case 'p': // pid
- ALOGW_IF(event != EVENT_PID,
+ ALOGW_IF(event != EVENT_FMT_PID,
"NBLog Reader incompatible event for pid specifier: %d", event);
appendPID(body, datum, length);
break;
@@ -1121,7 +1029,7 @@
}
++arg;
}
- ALOGW_IF(arg->type != EVENT_END_FMT, "Expected end of format, got %d", arg->type);
+ ALOGW_IF(arg->type != EVENT_FMT_END, "Expected end of format, got %d", arg->type);
return arg;
}
diff --git a/media/libnblog/include/media/nblog/NBLog.h b/media/libnblog/include/media/nblog/NBLog.h
index 763d743..561e8c7 100644
--- a/media/libnblog/include/media/nblog/NBLog.h
+++ b/media/libnblog/include/media/nblog/NBLog.h
@@ -20,6 +20,7 @@
#define ANDROID_MEDIA_NBLOG_H
#include <map>
+#include <type_traits>
#include <unordered_set>
#include <vector>
@@ -45,33 +46,58 @@
class Writer;
class Reader;
+ // TODO have a comment somewhere explaining the whole process for adding a new EVENT_
+
+ // NBLog Event types. The Events are named to provide contextual meaning for what is logged.
+ // If adding a new standalone Event here, update the event-to-type mapping by adding a
+ // MAP_EVENT_TO_TYPE statement below.
enum Event : uint8_t {
EVENT_RESERVED,
EVENT_STRING, // ASCII string, not NUL-terminated
// TODO: make timestamp optional
EVENT_TIMESTAMP, // clock_gettime(CLOCK_MONOTONIC)
- EVENT_INTEGER, // integer value entry
- EVENT_FLOAT, // floating point value entry
- EVENT_PID, // process ID and process name
- EVENT_AUTHOR, // author index (present in merged logs) tracks entry's
- // original log
- EVENT_START_FMT, // logFormat start event: entry includes format string,
+
+ // Types for Format Entry, i.e. formatted entry
+ EVENT_FMT_START, // logFormat start event: entry includes format string,
// following entries contain format arguments
- EVENT_HASH, // unique HASH of log origin, originates from hash of file name
+ // format arguments
+ EVENT_FMT_TIMESTAMP, // timestamp value entry
+ EVENT_FMT_HASH, // unique HASH of log origin, originates from hash of file name
// and line number
+ EVENT_FMT_STRING, // string value entry
+ EVENT_FMT_INTEGER, // integer value entry
+ EVENT_FMT_FLOAT, // floating point value entry
+ EVENT_FMT_PID, // process ID and process name
+ EVENT_FMT_AUTHOR, // author index (present in merged logs) tracks entry's
+ // original log
+ // end of format arguments
+ EVENT_FMT_END, // end of logFormat argument list
+
+ // Types for wakeup timestamp histograms
EVENT_HISTOGRAM_ENTRY_TS, // single datum for timestamp histogram
EVENT_AUDIO_STATE, // audio on/off event: logged on FastMixer::onStateChange call
- EVENT_END_FMT, // end of logFormat argument list
// Types representing audio performance metrics
- EVENT_LATENCY, // TODO classify specifically what this is
- EVENT_CPU_FREQUENCY, // instantaneous CPU frequency in kHz
- EVENT_MONOTONIC_CYCLE_TIME, // thread per-cycle monotonic time
- EVENT_CPU_CYCLE_TIME, // thread per-cycle cpu time
+ EVENT_LATENCY, // difference between frames presented by HAL and frames
+ // written to HAL output sink, divided by sample rate.
+ EVENT_WORK_TIME, // the time a thread takes to do work, e.g. read, write, etc.
EVENT_UPPER_BOUND, // to check for invalid events
};
+ template <Event E> struct get_mapped;
+#define MAP_EVENT_TO_TYPE(E, T) \
+ template<> struct get_mapped<E> { \
+ static_assert(std::is_trivially_copyable<T>::value \
+ && !std::is_pointer<T>::value, \
+ "NBLog::Event must map to trivially copyable, non-pointer type."); \
+ typedef T type; \
+ }
+
+ // Maps an NBLog Event type to a C++ POD type.
+ MAP_EVENT_TO_TYPE(EVENT_LATENCY, double);
+ MAP_EVENT_TO_TYPE(EVENT_WORK_TIME, uint64_t);
+
private:
// ---------------------------------------------------------------------------
@@ -119,10 +145,24 @@
void copyTo(std::unique_ptr<audio_utils_fifo_writer> &dst) const;
void copyData(uint8_t *dst) const;
+ // memcpy preferred to reinterpret_cast to avoid potentially unsupported
+ // unaligned memory access.
+#if 0
template<typename T>
inline const T& payload() {
return *reinterpret_cast<const T *>(mPtr + offsetof(entry, data));
}
+#else
+ template<typename T>
+ inline T payload() {
+ static_assert(std::is_trivially_copyable<T>::value
+ && !std::is_pointer<T>::value,
+ "NBLog::EntryIterator payload must be trivially copyable, non-pointer type.");
+ T payload;
+ memcpy(&payload, mPtr + offsetof(entry, data), sizeof(payload));
+ return payload;
+ }
+#endif
inline operator const uint8_t*() const {
return mPtr;
@@ -169,14 +209,14 @@
// API for handling format entry operations
// a formatted entry has the following structure:
- // * START_FMT entry, containing the format string
+ // * FMT_START entry, containing the format string
// * TIMESTAMP entry
// * HASH entry
// * author entry of the thread that generated it (optional, present in merged log)
// * format arg1
// * format arg2
// * ...
- // * END_FMT entry
+ // * FMT_END entry
class FormatEntry : public AbstractEntry {
public:
// explicit FormatEntry(const EntryIterator &it);
@@ -262,6 +302,7 @@
offsetof(ending, length);
};
+ // TODO move these somewhere else
struct HistTsEntry {
log_hash_t hash;
int64_t ts;
@@ -320,6 +361,8 @@
};
// ---------------------------------------------------------------------------
+ // NBLog Writer API
+ // ---------------------------------------------------------------------------
// Writer is thread-safe with respect to Reader, but not with respect to multiple threads
// calling Writer methods. If you need multi-thread safety for writing, use LockedWriter.
@@ -335,24 +378,22 @@
virtual ~Writer();
// FIXME needs comments, and some should be private
- virtual void log(const char *string);
- virtual void logf(const char *fmt, ...) __attribute__ ((format (printf, 2, 3)));
- virtual void logvf(const char *fmt, va_list ap);
- virtual void logTimestamp();
- virtual void logTimestamp(const int64_t ts);
- virtual void logInteger(const int x);
- virtual void logFloat(const float x);
- virtual void logPID();
- virtual void logStart(const char *fmt);
- virtual void logEnd();
- virtual void logHash(log_hash_t hash);
- // The functions below are not in LockedWriter yet.
- virtual void logFormat(const char *fmt, log_hash_t hash, ...);
- virtual void logVFormat(const char *fmt, log_hash_t hash, va_list ap);
- virtual void logEventHistTs(Event event, log_hash_t hash);
- virtual void logLatency(double latencyMs);
- virtual void logMonotonicCycleTime(uint32_t monotonicNs);
- // End of functions that are not in LockedWriter yet.
+ void log(const char *string);
+ void logf(const char *fmt, ...) __attribute__ ((format (printf, 2, 3)));
+ void logTimestamp();
+ void logFormat(const char *fmt, log_hash_t hash, ...);
+ void logEventHistTs(Event event, log_hash_t hash);
+
+ // Log data related to Event E. See the event-to-type mapping for the type of data
+ // corresponding to the event. For example, if you see a mapping statement:
+ // MAP_TYPE_TO_EVENT(E, T);
+ // then the usage of this method would be:
+ // T data = doComputation();
+ // tlNBLogWriter->log<NBLog::E>(data);
+ template<Event E>
+ void log(typename get_mapped<E>::type data) {
+ log(E, &data, sizeof(data));
+ }
virtual bool isEnabled() const;
@@ -363,12 +404,24 @@
sp<IMemory> getIMemory() const { return mIMemory; }
+ // Public logging function implementations should always use one of the
+ // two log() function calls below to write to shared memory.
+ protected:
+ // Writes a single Entry to the FIFO if the writer is enabled.
+ // This is protected and virtual because LockedWriter uses a lock to protect
+ // writing to the FIFO before writing to this function.
+ virtual void log(const Entry &entry, bool trusted = false);
+
private:
// 0 <= length <= kMaxLength
- // writes a single Entry to the FIFO
+ // Log a single Entry with corresponding event, data, and length.
void log(Event event, const void *data, size_t length);
- // checks validity of an event before calling log above this one
- void log(const Entry &entry, bool trusted = false);
+
+ void logvf(const char *fmt, va_list ap);
+ // helper functions for logging parts of a formatted entry
+ void logStart(const char *fmt);
+ void logTimestampFormat();
+ void logVFormat(const char *fmt, log_hash_t hash, va_list ap);
Shared* const mShared; // raw pointer to shared memory
sp<IMemory> mIMemory; // ref-counted version, initialized in constructor
@@ -393,54 +446,20 @@
LockedWriter();
LockedWriter(void *shared, size_t size);
- virtual void log(const char *string);
- virtual void logf(const char *fmt, ...) __attribute__ ((format (printf, 2, 3)));
- virtual void logvf(const char *fmt, va_list ap);
- virtual void logTimestamp();
- virtual void logTimestamp(const int64_t ts);
- virtual void logInteger(const int x);
- virtual void logFloat(const float x);
- virtual void logPID();
- virtual void logStart(const char *fmt);
- virtual void logEnd();
- virtual void logHash(log_hash_t hash);
-
- virtual bool isEnabled() const;
- virtual bool setEnabled(bool enabled);
+ bool isEnabled() const override;
+ bool setEnabled(bool enabled) override;
private:
+ // Lock needs to be obtained before writing to FIFO.
+ void log(const Entry &entry, bool trusted = false) override;
mutable Mutex mLock;
};
// ---------------------------------------------------------------------------
+ // NBLog Reader API
+ // ---------------------------------------------------------------------------
- // A snapshot of a readers buffer
- // This is raw data. No analysis has been done on it
- class Snapshot {
- public:
- Snapshot() = default;
-
- explicit Snapshot(size_t bufferSize) : mData(new uint8_t[bufferSize]) {}
-
- ~Snapshot() { delete[] mData; }
-
- // amount of data lost (given by audio_utils_fifo_reader)
- size_t lost() const { return mLost; }
-
- // iterator to beginning of readable segment of snapshot
- // data between begin and end has valid entries
- EntryIterator begin() const { return mBegin; }
-
- // iterator to end of readable segment of snapshot
- EntryIterator end() const { return mEnd; }
-
- private:
- friend class Reader;
- uint8_t * const mData{};
- size_t mLost{0};
- EntryIterator mBegin;
- EntryIterator mEnd;
- };
+ class Snapshot; // Forward declaration needed for Reader::getSnapshot()
class Reader : public RefBase {
public:
@@ -456,10 +475,12 @@
const std::string &name() const { return mName; }
private:
+ // Amount of tries for reader to catch up with writer in getSnapshot().
static constexpr int kMaxObtainTries = 3;
- // startingTypes and endingTypes are used to check for log corruption.
- static const std::unordered_set<Event> startingTypes;
- static const std::unordered_set<Event> endingTypes;
+ // invalidBeginTypes and invalidEndTypes are used to align the Snapshot::begin() and
+ // Snapshot::end() EntryIterators to valid entries.
+ static const std::unordered_set<Event> invalidBeginTypes;
+ static const std::unordered_set<Event> invalidEndTypes;
// declared as const because audio_utils_fifo() constructor
sp<IMemory> mIMemory; // ref-counted version, assigned only in constructor
@@ -470,12 +491,39 @@
audio_utils_fifo_reader * const mFifoReader; // used to read from FIFO,
// non-NULL unless constructor fails
- // Searches for the last entry of type <type> in the range [front, back)
+ // Searches for the last valid entry in the range [front, back)
// back has to be entry-aligned. Returns nullptr if none enconuntered.
- static const uint8_t *findLastEntryOfTypes(const uint8_t *front, const uint8_t *back,
- const std::unordered_set<Event> &types);
+ static const uint8_t *findLastValidEntry(const uint8_t *front, const uint8_t *back,
+ const std::unordered_set<Event> &invalidTypes);
};
+ // A snapshot of a readers buffer
+ // This is raw data. No analysis has been done on it
+ class Snapshot {
+ public:
+ ~Snapshot() { delete[] mData; }
+
+ // amount of data lost (given by audio_utils_fifo_reader)
+ size_t lost() const { return mLost; }
+
+ // iterator to beginning of readable segment of snapshot
+ // data between begin and end has valid entries
+ EntryIterator begin() const { return mBegin; }
+
+ // iterator to end of readable segment of snapshot
+ EntryIterator end() const { return mEnd; }
+
+ private:
+ Snapshot() = default;
+ explicit Snapshot(size_t bufferSize) : mData(new uint8_t[bufferSize]) {}
+ friend std::unique_ptr<Snapshot> Reader::getSnapshot();
+ uint8_t * const mData = nullptr;
+ size_t mLost = 0;
+ EntryIterator mBegin;
+ EntryIterator mEnd;
+ };
+
+ // TODO move this to MediaLogService?
class DumpReader : public Reader {
public:
DumpReader(const void *shared, size_t size, const std::string &name)
@@ -491,7 +539,7 @@
static void appendFloat(String8 *body, const void *data);
static void appendPID(String8 *body, const void *data, size_t length);
static void appendTimestamp(String8 *body, const void *data);
- //static size_t fmtEntryLength(const uint8_t *data); // TODO Eric remove if not used
+ // The bufferDump functions are used for debugging only.
static String8 bufferDump(const uint8_t *buffer, size_t size);
static String8 bufferDump(const EntryIterator &it);
};