Loading include/media/nbaio/NBLog.h +138 −7 Original line number Diff line number Diff line Loading @@ -23,6 +23,8 @@ #include <utils/Mutex.h> #include <audio_utils/fifo.h> #include <vector> namespace android { class String8; Loading @@ -40,9 +42,10 @@ enum Event { EVENT_RESERVED, EVENT_STRING, // ASCII string, not NUL-terminated EVENT_TIMESTAMP, // clock_gettime(CLOCK_MONOTONIC) EVENT_INTEGER, EVENT_FLOAT, EVENT_PID, 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, following // entries contain format arguments EVENT_END_FMT, // end of logFormat argument list Loading @@ -68,6 +71,49 @@ public: static const size_t kOverhead = 3; // mEvent, mLength, mData[...], duplicate mLength }; // --------------------------------------------------------------------------- // API for handling format entry operations // a formatted entry has the following structure: // * START_FMT entry, containing the format string // * author entry of the thread that generated it (optional, present in merged log) // * TIMESTAMP entry // * format arg1 // * format arg2 // * ... // * END_FMT entry class FormatEntry { public: // build a Format Entry starting in the given pointer explicit FormatEntry(const uint8_t *entry); // Entry's format string const char* formatString() const; // Enrty's format string length size_t formatStringLength() const; // Format arguments (excluding format string, timestamp and author) const uint8_t *args() const; // get format entry timestamp timespec timestamp() const; // entry's author index (-1 if none present) int author() const; // copy entry, adding author before timestamp, returns size of original entry // (intended for merger) size_t copyTo(std::unique_ptr<audio_utils_fifo_writer> &dst, int author) const; private: // copies ordinary entry from src to dst, and returns length of entry size_t copyEntry(std::unique_ptr<audio_utils_fifo_writer> &dst, const uint8_t *src) const; const uint8_t *mEntry; }; // representation of a single log entry in shared memory // byte[0] mEvent // byte[1] mLength Loading @@ -82,9 +128,8 @@ public: static void appendInt(String8 *body, const void *data); static void appendFloat(String8 *body, const void *data); static void appendPID(String8 *body, const void *data, size_t length); static int handleFormat(const char *fmt, size_t length, const uint8_t *data, String8 *timestamp, String8 *body); static void appendTimestamp(String8 *body, const void *data); static size_t fmtEntryLength(const uint8_t *data); public: Loading Loading @@ -215,6 +260,31 @@ private: class Reader : public RefBase { public: // A snapshot of a readers buffer class Snapshot { public: Snapshot() : mData(NULL), mAvail(0), mLost(0) {} Snapshot(size_t bufferSize) : mData(new uint8_t[bufferSize]) {} ~Snapshot() { delete[] mData; } // copy of the buffer const uint8_t *data() const { return mData; } // amount of data available (given by audio_utils_fifo_reader) size_t available() const { return mAvail; } // amount of data lost (given by audio_utils_fifo_reader) size_t lost() const { return mLost; } private: friend class Reader; const uint8_t *mData; size_t mAvail; size_t mLost; }; // Input parameter 'size' is the desired size of the timeline in byte units. // The size of the shared memory must be at least Timeline::sharedSize(size). Reader(const void *shared, size_t size); Loading @@ -222,6 +292,11 @@ public: virtual ~Reader(); // get snapshot of readers fifo buffer, effectively consuming the buffer std::unique_ptr<Snapshot> getSnapshot(); // dump a particular snapshot of the reader void dump(int fd, size_t indent, Snapshot & snap); // dump the current content of the reader's buffer void dump(int fd, size_t indent = 0); bool isIMemory(const sp<IMemory>& iMemory) const; Loading @@ -237,10 +312,66 @@ private: // non-NULL unless constructor fails void dumpLine(const String8& timestamp, String8& body); int handleFormat(const FormatEntry &fmtEntry, String8 *timestamp, String8 *body); // dummy method for handling absent author entry virtual size_t handleAuthor(const FormatEntry &fmtEntry, String8 *body) { return 0; } static const size_t kSquashTimestamp = 5; // squash this many or more adjacent timestamps }; // Wrapper for a reader with a name. Contains a pointer to the reader and a pointer to the name class NamedReader { public: NamedReader() { mName[0] = '\0'; } // for Vector NamedReader(const sp<NBLog::Reader>& reader, const char *name) : mReader(reader) { strlcpy(mName, name, sizeof(mName)); } ~NamedReader() { } const sp<NBLog::Reader>& reader() const { return mReader; } const char* name() const { return mName; } private: sp<NBLog::Reader> mReader; static const size_t kMaxName = 32; char mName[kMaxName]; }; // --------------------------------------------------------------------------- class Merger : public RefBase { public: Merger(const void *shared, size_t size); virtual ~Merger() {} void addReader(const NamedReader &reader); // TODO add removeReader void merge(); const std::vector<NamedReader> *getNamedReaders() const; private: // vector of the readers the merger is supposed to merge from. // every reader reads from a writer's buffer std::vector<NamedReader> mNamedReaders; uint8_t *mBuffer; Shared * const mShared; std::unique_ptr<audio_utils_fifo> mFifo; std::unique_ptr<audio_utils_fifo_writer> mFifoWriter; static struct timespec getTimestamp(const uint8_t *data); }; class MergeReader : public Reader { public: MergeReader(const void *shared, size_t size, Merger &merger); private: const std::vector<NamedReader> *mNamedReaders; // handle author entry by looking up the author's name and appending it to the body // returns number of bytes read from fmtEntry size_t handleAuthor(const FormatEntry &fmtEntry, String8 *body); }; }; // class NBLog } // namespace android Loading media/audioserver/Android.mk +1 −0 Original line number Diff line number Diff line Loading @@ -12,6 +12,7 @@ LOCAL_SHARED_LIBRARIES := \ libcutils \ liblog \ libmedialogservice \ libnbaio \ libradioservice \ libsoundtriggerservice \ libutils \ Loading media/libnbaio/NBLog.cpp +213 −41 Original line number Diff line number Diff line Loading @@ -29,6 +29,8 @@ #include <utils/Log.h> #include <utils/String8.h> #include <queue> namespace android { int NBLog::Entry::readAt(size_t offset) const Loading @@ -48,6 +50,75 @@ int NBLog::Entry::readAt(size_t offset) const // --------------------------------------------------------------------------- NBLog::FormatEntry::FormatEntry(const uint8_t *entry) : mEntry(entry) { ALOGW_IF(entry[0] != EVENT_START_FMT, "Created format entry with invalid event type %d", entry[0]); } const char *NBLog::FormatEntry::formatString() const { return (const char*) mEntry + 2; } size_t NBLog::FormatEntry::formatStringLength() const { return mEntry[1]; } const uint8_t *NBLog::FormatEntry::args() const { const uint8_t *ptr = mEntry + mEntry[1] + NBLog::Entry::kOverhead; if (ptr[0] != EVENT_TIMESTAMP) { // skip author if present ptr += ptr[1] + NBLog::Entry::kOverhead; } return ptr + ptr[1] + NBLog::Entry::kOverhead; } timespec NBLog::FormatEntry::timestamp() const { const uint8_t *ptr = mEntry + mEntry[1] + NBLog::Entry::kOverhead; if (ptr[0] != EVENT_TIMESTAMP) { // skip authors if present ptr += ptr[1] + NBLog::Entry::kOverhead; } // by this point, we should be standing in the timestamp entry return *((struct timespec*) (&ptr[2])); } pid_t NBLog::FormatEntry::author() const { size_t authorOffset = mEntry[1] + NBLog::Entry::kOverhead; // return -1 if the entry has no author if (mEntry[authorOffset] != EVENT_AUTHOR) { return -1; } return *(pid_t*)(mEntry + authorOffset + 2); } size_t NBLog::FormatEntry::copyTo(std::unique_ptr<audio_utils_fifo_writer> &dst, int author) const { // copy fmt start entry size_t entryOffset = copyEntry(dst, mEntry); // insert author entry size_t authorEntrySize = NBLog::Entry::kOverhead + sizeof(author); uint8_t authorEntry[authorEntrySize]; authorEntry[0] = EVENT_AUTHOR; authorEntry[1] = authorEntry[authorEntrySize - 1] = sizeof(author); *(int*) (&authorEntry[2]) = author; dst->write(authorEntry, authorEntrySize); // copy rest of entries Event lastEvent = EVENT_TIMESTAMP; while (lastEvent != EVENT_END_FMT) { lastEvent = (Event) mEntry[entryOffset]; entryOffset += copyEntry(dst, mEntry + entryOffset); } return entryOffset; } size_t NBLog::FormatEntry::copyEntry(std::unique_ptr<audio_utils_fifo_writer> &dst, const uint8_t *src) const { size_t length = src[1] + NBLog::Entry::kOverhead; dst->write(src, length); return length; } // --------------------------------------------------------------------------- #if 0 // FIXME see note in NBLog.h NBLog::Timeline::Timeline(size_t size, void *shared) : mSize(roundup(size)), mOwn(shared == NULL), Loading Loading @@ -463,43 +534,44 @@ NBLog::Reader::~Reader() delete mFifo; } void NBLog::Reader::dump(int fd, size_t indent) std::unique_ptr<NBLog::Reader::Snapshot> NBLog::Reader::getSnapshot() { if (mFifoReader == NULL) { return; return std::unique_ptr<NBLog::Reader::Snapshot>(new Snapshot()); } // make a copy to avoid race condition with writer size_t capacity = mFifo->capacity(); // TODO Stack-based allocation of large objects may fail. // Currently the log buffers are a page or two, which should be safe. // But if the log buffers ever get a lot larger, // then change this to allocate from heap when necessary. static size_t kReasonableStackObjectSize = 32768; ALOGW_IF(capacity > kReasonableStackObjectSize, "Stack-based allocation of object may fail"); uint8_t copy[capacity]; std::unique_ptr<Snapshot> snapshot(new Snapshot(capacity)); size_t lost; ssize_t actual = mFifoReader->read(copy, capacity, NULL /*timeout*/, &lost); ssize_t actual = mFifoReader->read((void*) snapshot->mData, capacity, NULL /*timeout*/, &(snapshot->mLost)); ALOG_ASSERT(actual <= capacity); size_t avail = actual > 0 ? (size_t) actual : 0; size_t i = avail; snapshot->mAvail = actual > 0 ? (size_t) actual : 0; return snapshot; } void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapshot) { size_t i = snapshot.available(); const uint8_t *snapData = snapshot.data(); Event event; size_t length; struct timespec ts; time_t maxSec = -1; while (i >= Entry::kOverhead) { length = copy[i - 1]; if (length + Entry::kOverhead > i || copy[i - length - 2] != length) { length = snapData[i - 1]; if (length + Entry::kOverhead > i || snapData[i - length - 2] != length) { break; } event = (Event) copy[i - length - Entry::kOverhead]; event = (Event) snapData[i - length - Entry::kOverhead]; if (event == EVENT_TIMESTAMP) { if (length != sizeof(struct timespec)) { // corrupt break; } memcpy(&ts, ©[i - length - 1], sizeof(struct timespec)); memcpy(&ts, &snapData[i - length - 1], sizeof(struct timespec)); if (ts.tv_sec > maxSec) { maxSec = ts.tv_sec; } Loading @@ -509,7 +581,7 @@ void NBLog::Reader::dump(int fd, size_t indent) mFd = fd; mIndent = indent; String8 timestamp, body; lost += i; size_t lost = snapshot.lost() + i; if (lost > 0) { body.appendFormat("warning: lost %zu bytes worth of events", lost); // TODO timestamp empty here, only other choice to wait for the first timestamp event in the Loading @@ -525,10 +597,10 @@ void NBLog::Reader::dump(int fd, size_t indent) timestamp.appendFormat("[%*s]", (int) width + 4, ""); } bool deferredTimestamp = false; while (i < avail) { event = (Event) copy[i]; length = copy[i + 1]; const void *data = ©[i + 2]; while (i < snapshot.available()) { event = (Event) snapData[i]; length = snapData[i + 1]; const void *data = &snapData[i + 2]; size_t advance = length + Entry::kOverhead; switch (event) { case EVENT_STRING: Loading @@ -544,11 +616,11 @@ void NBLog::Reader::dump(int fd, size_t indent) size_t j = i; for (;;) { j += sizeof(struct timespec) + 3 /*Entry::kOverhead?*/; if (j >= avail || (Event) copy[j] != EVENT_TIMESTAMP) { if (j >= snapshot.available() || (Event) snapData[j] != EVENT_TIMESTAMP) { break; } struct timespec tsNext; memcpy(&tsNext, ©[j + 2], sizeof(struct timespec)); memcpy(&tsNext, &snapData[j + 2], sizeof(struct timespec)); if (tsNext.tv_sec != ts.tv_sec) { break; } Loading Loading @@ -594,8 +666,7 @@ void NBLog::Reader::dump(int fd, size_t indent) appendPID(&body, data, length); break; case EVENT_START_FMT: advance += handleFormat((const char*) ©[i + 2], length, ©[i + Entry::kOverhead + length], ×tamp, &body); advance += handleFormat(FormatEntry(snapData + i), ×tamp, &body); break; case EVENT_END_FMT: body.appendFormat("warning: got to end format event"); Loading @@ -617,6 +688,13 @@ void NBLog::Reader::dump(int fd, size_t indent) } } void NBLog::Reader::dump(int fd, size_t indent) { // get a snapshot, dump it std::unique_ptr<Snapshot> snap = getSnapshot(); dump(fd, indent, *snap); } void NBLog::Reader::dumpLine(const String8 ×tamp, String8 &body) { if (mFd >= 0) { Loading Loading @@ -656,17 +734,23 @@ void NBLog::appendPID(String8 *body, const void* data, size_t length) { body->appendFormat("<PID: %d, name: %.*s>", id, (int) (length - sizeof(pid_t)), name); } int NBLog::handleFormat(const char *fmt, size_t fmt_length, const uint8_t *data, String8 *timestamp, String8 *body) { if (data[0] != EVENT_TIMESTAMP) { ALOGW("NBLog Reader Expected timestamp event %d, got %d", EVENT_TIMESTAMP, data[0]); } struct timespec ts; memcpy(&ts, &data[2], sizeof(ts)); int NBLog::Reader::handleFormat(const FormatEntry &fmtEntry, String8 *timestamp, String8 *body) { // log timestamp struct timespec ts = fmtEntry.timestamp(); timestamp->clear(); timestamp->appendFormat("[%d.%03d]", (int) ts.tv_sec, (int) (ts.tv_nsec / 1000000)); size_t data_offset = Entry::kOverhead + sizeof ts; size_t fullLength = NBLog::Entry::kOverhead + sizeof(ts); // log author (if present) fullLength += handleAuthor(fmtEntry, body); // log string const uint8_t *args = fmtEntry.args(); size_t args_offset = 0; const char* fmt = fmtEntry.formatString(); size_t fmt_length = fmtEntry.formatStringLength(); for (size_t fmt_offset = 0; fmt_offset < fmt_length; ++fmt_offset) { if (fmt[fmt_offset] != '%') { Loading @@ -681,20 +765,20 @@ int NBLog::handleFormat(const char *fmt, size_t fmt_length, const uint8_t *data, continue; } NBLog::Event event = (NBLog::Event) data[data_offset]; size_t length = data[data_offset + 1]; NBLog::Event event = (NBLog::Event) args[args_offset]; size_t length = args[args_offset + 1]; // TODO check length for event type is correct if(length != data[data_offset + length + 2]) { if(length != args[args_offset + length + 2]) { ALOGW("NBLog Reader received different lengths %zu and %d for event %d", length, data[data_offset + length + 2], event); args[args_offset + length + 2], event); body->append("<invalid entry>"); ++fmt_offset; continue; } // TODO: implement more complex formatting such as %.3f void * datum = (void*) &data[data_offset + 2]; // pointer to the current event data void * datum = (void*) &args[args_offset + 2]; // pointer to the current event args switch(fmt[fmt_offset]) { case 's': // string Loading Loading @@ -731,10 +815,98 @@ int NBLog::handleFormat(const char *fmt, size_t fmt_length, const uint8_t *data, ALOGW("NBLog Reader encountered unknown character %c", fmt[fmt_offset]); } data_offset += length + Entry::kOverhead; args_offset += length + Entry::kOverhead; } fullLength += args_offset + Entry::kOverhead; return fullLength; } // --------------------------------------------------------------------------- NBLog::Merger::Merger(const void *shared, size_t size): mBuffer(NULL), mShared((Shared *) shared), mFifo(mShared != NULL ? new audio_utils_fifo(size, sizeof(uint8_t), mShared->mBuffer, mShared->mRear, NULL /*throttlesFront*/) : NULL), mFifoWriter(mFifo != NULL ? new audio_utils_fifo_writer(*mFifo) : NULL) {} void NBLog::Merger::addReader(const NBLog::NamedReader &reader) { mNamedReaders.push_back(reader); } // items placed in priority queue during merge // composed by a timestamp and the index of the snapshot where the timestamp came from struct MergeItem { struct timespec ts; int index; MergeItem(struct timespec ts, int index): ts(ts), index(index) {} }; // operators needed for priority queue in merge bool operator>(const struct timespec &t1, const struct timespec &t2) { return t1.tv_sec > t2.tv_sec || (t1.tv_sec == t2.tv_sec && t1.tv_nsec > t2.tv_nsec); } bool operator>(const struct MergeItem &i1, const struct MergeItem &i2) { return i1.ts > i2.ts || (i1.ts.tv_sec == i2.ts.tv_sec && i1.ts.tv_nsec == i2.ts.tv_nsec && i1.index > i2.index); } // Merge registered readers, sorted by timestamp void NBLog::Merger::merge() { int nLogs = mNamedReaders.size(); std::vector<std::unique_ptr<NBLog::Reader::Snapshot>> snapshots(nLogs); for (int i = 0; i < nLogs; ++i) { snapshots[i] = mNamedReaders[i].reader()->getSnapshot(); } // initialize offsets std::vector<size_t> offsets(nLogs, 0); // TODO custom heap implementation could allow to update top, improving performance // for bursty buffers std::priority_queue<MergeItem, std::vector<MergeItem>, std::greater<MergeItem>> timestamps; for (int i = 0; i < nLogs; ++i) { if (snapshots[i]->available() > 0) { timespec ts = FormatEntry(snapshots[i]->data()).timestamp(); MergeItem item(ts, i); timestamps.push(item); } } return data_offset + Entry::kOverhead; // data offset + size of END_FMT event while (!timestamps.empty()) { // find minimum timestamp int index = timestamps.top().index; // copy it to the log size_t length = FormatEntry(snapshots[index]->data() + offsets[index]).copyTo( mFifoWriter, index); // update data structures offsets[index] += length; ALOGW_IF(offsets[index] > snapshots[index]->available(), "Overflown snapshot capacity"); timestamps.pop(); if (offsets[index] != snapshots[index]->available()) { timespec ts = FormatEntry(snapshots[index]->data() + offsets[index]).timestamp(); MergeItem item(ts, index); timestamps.emplace(item); } } } const std::vector<NBLog::NamedReader> *NBLog::Merger::getNamedReaders() const { return &mNamedReaders; } NBLog::MergeReader::MergeReader(const void *shared, size_t size, Merger &merger) : Reader(shared, size), mNamedReaders(merger.getNamedReaders()) {} size_t NBLog::MergeReader::handleAuthor(const NBLog::FormatEntry &fmtEntry, String8 *body) { int author = fmtEntry.author(); const char* name = (*mNamedReaders)[author].name(); body->appendFormat("%s: ", name); return NBLog::Entry::kOverhead + sizeof(author); } } // namespace android services/medialog/MediaLogService.cpp +19 −13 Original line number Diff line number Diff line Loading @@ -26,7 +26,7 @@ namespace android { static const char kDeadlockedString[] = "MediaLogService may be deadlocked\n"; // static const char kDeadlockedString[] = "MediaLogService may be deadlocked\n"; void MediaLogService::registerWriter(const sp<IMemory>& shared, size_t size, const char *name) { Loading @@ -36,9 +36,10 @@ void MediaLogService::registerWriter(const sp<IMemory>& shared, size_t size, con return; } sp<NBLog::Reader> reader(new NBLog::Reader(shared, size)); NamedReader namedReader(reader, name); NBLog::NamedReader namedReader(reader, name); Mutex::Autolock _l(mLock); mNamedReaders.add(namedReader); mMerger.addReader(namedReader); } void MediaLogService::unregisterWriter(const sp<IMemory>& shared) Loading Loading @@ -81,7 +82,8 @@ status_t MediaLogService::dump(int fd, const Vector<String16>& args __unused) return NO_ERROR; } Vector<NamedReader> namedReaders; #if 0 Vector<NBLog::NamedReader> namedReaders; { bool locked = dumpTryLock(mLock); Loading @@ -95,19 +97,23 @@ status_t MediaLogService::dump(int fd, const Vector<String16>& args __unused) } return NO_ERROR; } namedReaders = mNamedReaders; // namedReaders = mNamedReaders; // for (size_t i = 0; i < namedReaders.size(); i++) { // const NBLog::NamedReader& namedReader = namedReaders[i]; // if (fd >= 0) { // dprintf(fd, "\n%s:\n", namedReader.name()); // } else { // ALOGI("%s:", namedReader.name()); // } // namedReader.reader()->dump(fd, 0 /*indent*/); // } mLock.unlock(); } #endif for (size_t i = 0; i < namedReaders.size(); i++) { const NamedReader& namedReader = namedReaders[i]; if (fd >= 0) { dprintf(fd, "\n%s:\n", namedReader.name()); } else { ALOGI("%s:", namedReader.name()); } namedReader.reader()->dump(fd, 0 /*indent*/); } mMerger.merge(); mMergeReader.dump(fd); return NO_ERROR; } Loading services/medialog/MediaLogService.h +14 −16 Original line number Diff line number Diff line Loading @@ -27,8 +27,13 @@ class MediaLogService : public BinderService<MediaLogService>, public BnMediaLog { friend class BinderService<MediaLogService>; // for MediaLogService() public: MediaLogService() : BnMediaLogService() { } virtual ~MediaLogService() { } MediaLogService() : BnMediaLogService(), mMergerShared((NBLog::Shared*) malloc(NBLog::Timeline::sharedSize(kMergeBufferSize))), mMerger(mMergerShared, kMergeBufferSize), mMergeReader(mMergerShared, kMergeBufferSize, mMerger) {ALOGI("Nico creating MergeReader");} virtual ~MediaLogService() { free(mMergerShared); } virtual void onFirstRef() { } static const char* getServiceName() { return "media.log"; } Loading @@ -47,23 +52,16 @@ private: // Internal dump static const int kDumpLockRetries = 50; static const int kDumpLockSleepUs = 20000; static const size_t kMergeBufferSize = 16 * 1024; // TODO determine good value for this static bool dumpTryLock(Mutex& mutex); Mutex mLock; class NamedReader { public: NamedReader() : mReader(0) { mName[0] = '\0'; } // for Vector NamedReader(const sp<NBLog::Reader>& reader, const char *name) : mReader(reader) { strlcpy(mName, name, sizeof(mName)); } ~NamedReader() { } const sp<NBLog::Reader>& reader() const { return mReader; } const char* name() const { return mName; } private: sp<NBLog::Reader> mReader; static const size_t kMaxName = 32; char mName[kMaxName]; }; Vector<NamedReader> mNamedReaders; Vector<NBLog::NamedReader> mNamedReaders; NBLog::Shared *mMergerShared; NBLog::Merger mMerger; NBLog::MergeReader mMergeReader; }; } // namespace android Loading Loading
include/media/nbaio/NBLog.h +138 −7 Original line number Diff line number Diff line Loading @@ -23,6 +23,8 @@ #include <utils/Mutex.h> #include <audio_utils/fifo.h> #include <vector> namespace android { class String8; Loading @@ -40,9 +42,10 @@ enum Event { EVENT_RESERVED, EVENT_STRING, // ASCII string, not NUL-terminated EVENT_TIMESTAMP, // clock_gettime(CLOCK_MONOTONIC) EVENT_INTEGER, EVENT_FLOAT, EVENT_PID, 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, following // entries contain format arguments EVENT_END_FMT, // end of logFormat argument list Loading @@ -68,6 +71,49 @@ public: static const size_t kOverhead = 3; // mEvent, mLength, mData[...], duplicate mLength }; // --------------------------------------------------------------------------- // API for handling format entry operations // a formatted entry has the following structure: // * START_FMT entry, containing the format string // * author entry of the thread that generated it (optional, present in merged log) // * TIMESTAMP entry // * format arg1 // * format arg2 // * ... // * END_FMT entry class FormatEntry { public: // build a Format Entry starting in the given pointer explicit FormatEntry(const uint8_t *entry); // Entry's format string const char* formatString() const; // Enrty's format string length size_t formatStringLength() const; // Format arguments (excluding format string, timestamp and author) const uint8_t *args() const; // get format entry timestamp timespec timestamp() const; // entry's author index (-1 if none present) int author() const; // copy entry, adding author before timestamp, returns size of original entry // (intended for merger) size_t copyTo(std::unique_ptr<audio_utils_fifo_writer> &dst, int author) const; private: // copies ordinary entry from src to dst, and returns length of entry size_t copyEntry(std::unique_ptr<audio_utils_fifo_writer> &dst, const uint8_t *src) const; const uint8_t *mEntry; }; // representation of a single log entry in shared memory // byte[0] mEvent // byte[1] mLength Loading @@ -82,9 +128,8 @@ public: static void appendInt(String8 *body, const void *data); static void appendFloat(String8 *body, const void *data); static void appendPID(String8 *body, const void *data, size_t length); static int handleFormat(const char *fmt, size_t length, const uint8_t *data, String8 *timestamp, String8 *body); static void appendTimestamp(String8 *body, const void *data); static size_t fmtEntryLength(const uint8_t *data); public: Loading Loading @@ -215,6 +260,31 @@ private: class Reader : public RefBase { public: // A snapshot of a readers buffer class Snapshot { public: Snapshot() : mData(NULL), mAvail(0), mLost(0) {} Snapshot(size_t bufferSize) : mData(new uint8_t[bufferSize]) {} ~Snapshot() { delete[] mData; } // copy of the buffer const uint8_t *data() const { return mData; } // amount of data available (given by audio_utils_fifo_reader) size_t available() const { return mAvail; } // amount of data lost (given by audio_utils_fifo_reader) size_t lost() const { return mLost; } private: friend class Reader; const uint8_t *mData; size_t mAvail; size_t mLost; }; // Input parameter 'size' is the desired size of the timeline in byte units. // The size of the shared memory must be at least Timeline::sharedSize(size). Reader(const void *shared, size_t size); Loading @@ -222,6 +292,11 @@ public: virtual ~Reader(); // get snapshot of readers fifo buffer, effectively consuming the buffer std::unique_ptr<Snapshot> getSnapshot(); // dump a particular snapshot of the reader void dump(int fd, size_t indent, Snapshot & snap); // dump the current content of the reader's buffer void dump(int fd, size_t indent = 0); bool isIMemory(const sp<IMemory>& iMemory) const; Loading @@ -237,10 +312,66 @@ private: // non-NULL unless constructor fails void dumpLine(const String8& timestamp, String8& body); int handleFormat(const FormatEntry &fmtEntry, String8 *timestamp, String8 *body); // dummy method for handling absent author entry virtual size_t handleAuthor(const FormatEntry &fmtEntry, String8 *body) { return 0; } static const size_t kSquashTimestamp = 5; // squash this many or more adjacent timestamps }; // Wrapper for a reader with a name. Contains a pointer to the reader and a pointer to the name class NamedReader { public: NamedReader() { mName[0] = '\0'; } // for Vector NamedReader(const sp<NBLog::Reader>& reader, const char *name) : mReader(reader) { strlcpy(mName, name, sizeof(mName)); } ~NamedReader() { } const sp<NBLog::Reader>& reader() const { return mReader; } const char* name() const { return mName; } private: sp<NBLog::Reader> mReader; static const size_t kMaxName = 32; char mName[kMaxName]; }; // --------------------------------------------------------------------------- class Merger : public RefBase { public: Merger(const void *shared, size_t size); virtual ~Merger() {} void addReader(const NamedReader &reader); // TODO add removeReader void merge(); const std::vector<NamedReader> *getNamedReaders() const; private: // vector of the readers the merger is supposed to merge from. // every reader reads from a writer's buffer std::vector<NamedReader> mNamedReaders; uint8_t *mBuffer; Shared * const mShared; std::unique_ptr<audio_utils_fifo> mFifo; std::unique_ptr<audio_utils_fifo_writer> mFifoWriter; static struct timespec getTimestamp(const uint8_t *data); }; class MergeReader : public Reader { public: MergeReader(const void *shared, size_t size, Merger &merger); private: const std::vector<NamedReader> *mNamedReaders; // handle author entry by looking up the author's name and appending it to the body // returns number of bytes read from fmtEntry size_t handleAuthor(const FormatEntry &fmtEntry, String8 *body); }; }; // class NBLog } // namespace android Loading
media/audioserver/Android.mk +1 −0 Original line number Diff line number Diff line Loading @@ -12,6 +12,7 @@ LOCAL_SHARED_LIBRARIES := \ libcutils \ liblog \ libmedialogservice \ libnbaio \ libradioservice \ libsoundtriggerservice \ libutils \ Loading
media/libnbaio/NBLog.cpp +213 −41 Original line number Diff line number Diff line Loading @@ -29,6 +29,8 @@ #include <utils/Log.h> #include <utils/String8.h> #include <queue> namespace android { int NBLog::Entry::readAt(size_t offset) const Loading @@ -48,6 +50,75 @@ int NBLog::Entry::readAt(size_t offset) const // --------------------------------------------------------------------------- NBLog::FormatEntry::FormatEntry(const uint8_t *entry) : mEntry(entry) { ALOGW_IF(entry[0] != EVENT_START_FMT, "Created format entry with invalid event type %d", entry[0]); } const char *NBLog::FormatEntry::formatString() const { return (const char*) mEntry + 2; } size_t NBLog::FormatEntry::formatStringLength() const { return mEntry[1]; } const uint8_t *NBLog::FormatEntry::args() const { const uint8_t *ptr = mEntry + mEntry[1] + NBLog::Entry::kOverhead; if (ptr[0] != EVENT_TIMESTAMP) { // skip author if present ptr += ptr[1] + NBLog::Entry::kOverhead; } return ptr + ptr[1] + NBLog::Entry::kOverhead; } timespec NBLog::FormatEntry::timestamp() const { const uint8_t *ptr = mEntry + mEntry[1] + NBLog::Entry::kOverhead; if (ptr[0] != EVENT_TIMESTAMP) { // skip authors if present ptr += ptr[1] + NBLog::Entry::kOverhead; } // by this point, we should be standing in the timestamp entry return *((struct timespec*) (&ptr[2])); } pid_t NBLog::FormatEntry::author() const { size_t authorOffset = mEntry[1] + NBLog::Entry::kOverhead; // return -1 if the entry has no author if (mEntry[authorOffset] != EVENT_AUTHOR) { return -1; } return *(pid_t*)(mEntry + authorOffset + 2); } size_t NBLog::FormatEntry::copyTo(std::unique_ptr<audio_utils_fifo_writer> &dst, int author) const { // copy fmt start entry size_t entryOffset = copyEntry(dst, mEntry); // insert author entry size_t authorEntrySize = NBLog::Entry::kOverhead + sizeof(author); uint8_t authorEntry[authorEntrySize]; authorEntry[0] = EVENT_AUTHOR; authorEntry[1] = authorEntry[authorEntrySize - 1] = sizeof(author); *(int*) (&authorEntry[2]) = author; dst->write(authorEntry, authorEntrySize); // copy rest of entries Event lastEvent = EVENT_TIMESTAMP; while (lastEvent != EVENT_END_FMT) { lastEvent = (Event) mEntry[entryOffset]; entryOffset += copyEntry(dst, mEntry + entryOffset); } return entryOffset; } size_t NBLog::FormatEntry::copyEntry(std::unique_ptr<audio_utils_fifo_writer> &dst, const uint8_t *src) const { size_t length = src[1] + NBLog::Entry::kOverhead; dst->write(src, length); return length; } // --------------------------------------------------------------------------- #if 0 // FIXME see note in NBLog.h NBLog::Timeline::Timeline(size_t size, void *shared) : mSize(roundup(size)), mOwn(shared == NULL), Loading Loading @@ -463,43 +534,44 @@ NBLog::Reader::~Reader() delete mFifo; } void NBLog::Reader::dump(int fd, size_t indent) std::unique_ptr<NBLog::Reader::Snapshot> NBLog::Reader::getSnapshot() { if (mFifoReader == NULL) { return; return std::unique_ptr<NBLog::Reader::Snapshot>(new Snapshot()); } // make a copy to avoid race condition with writer size_t capacity = mFifo->capacity(); // TODO Stack-based allocation of large objects may fail. // Currently the log buffers are a page or two, which should be safe. // But if the log buffers ever get a lot larger, // then change this to allocate from heap when necessary. static size_t kReasonableStackObjectSize = 32768; ALOGW_IF(capacity > kReasonableStackObjectSize, "Stack-based allocation of object may fail"); uint8_t copy[capacity]; std::unique_ptr<Snapshot> snapshot(new Snapshot(capacity)); size_t lost; ssize_t actual = mFifoReader->read(copy, capacity, NULL /*timeout*/, &lost); ssize_t actual = mFifoReader->read((void*) snapshot->mData, capacity, NULL /*timeout*/, &(snapshot->mLost)); ALOG_ASSERT(actual <= capacity); size_t avail = actual > 0 ? (size_t) actual : 0; size_t i = avail; snapshot->mAvail = actual > 0 ? (size_t) actual : 0; return snapshot; } void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapshot) { size_t i = snapshot.available(); const uint8_t *snapData = snapshot.data(); Event event; size_t length; struct timespec ts; time_t maxSec = -1; while (i >= Entry::kOverhead) { length = copy[i - 1]; if (length + Entry::kOverhead > i || copy[i - length - 2] != length) { length = snapData[i - 1]; if (length + Entry::kOverhead > i || snapData[i - length - 2] != length) { break; } event = (Event) copy[i - length - Entry::kOverhead]; event = (Event) snapData[i - length - Entry::kOverhead]; if (event == EVENT_TIMESTAMP) { if (length != sizeof(struct timespec)) { // corrupt break; } memcpy(&ts, ©[i - length - 1], sizeof(struct timespec)); memcpy(&ts, &snapData[i - length - 1], sizeof(struct timespec)); if (ts.tv_sec > maxSec) { maxSec = ts.tv_sec; } Loading @@ -509,7 +581,7 @@ void NBLog::Reader::dump(int fd, size_t indent) mFd = fd; mIndent = indent; String8 timestamp, body; lost += i; size_t lost = snapshot.lost() + i; if (lost > 0) { body.appendFormat("warning: lost %zu bytes worth of events", lost); // TODO timestamp empty here, only other choice to wait for the first timestamp event in the Loading @@ -525,10 +597,10 @@ void NBLog::Reader::dump(int fd, size_t indent) timestamp.appendFormat("[%*s]", (int) width + 4, ""); } bool deferredTimestamp = false; while (i < avail) { event = (Event) copy[i]; length = copy[i + 1]; const void *data = ©[i + 2]; while (i < snapshot.available()) { event = (Event) snapData[i]; length = snapData[i + 1]; const void *data = &snapData[i + 2]; size_t advance = length + Entry::kOverhead; switch (event) { case EVENT_STRING: Loading @@ -544,11 +616,11 @@ void NBLog::Reader::dump(int fd, size_t indent) size_t j = i; for (;;) { j += sizeof(struct timespec) + 3 /*Entry::kOverhead?*/; if (j >= avail || (Event) copy[j] != EVENT_TIMESTAMP) { if (j >= snapshot.available() || (Event) snapData[j] != EVENT_TIMESTAMP) { break; } struct timespec tsNext; memcpy(&tsNext, ©[j + 2], sizeof(struct timespec)); memcpy(&tsNext, &snapData[j + 2], sizeof(struct timespec)); if (tsNext.tv_sec != ts.tv_sec) { break; } Loading Loading @@ -594,8 +666,7 @@ void NBLog::Reader::dump(int fd, size_t indent) appendPID(&body, data, length); break; case EVENT_START_FMT: advance += handleFormat((const char*) ©[i + 2], length, ©[i + Entry::kOverhead + length], ×tamp, &body); advance += handleFormat(FormatEntry(snapData + i), ×tamp, &body); break; case EVENT_END_FMT: body.appendFormat("warning: got to end format event"); Loading @@ -617,6 +688,13 @@ void NBLog::Reader::dump(int fd, size_t indent) } } void NBLog::Reader::dump(int fd, size_t indent) { // get a snapshot, dump it std::unique_ptr<Snapshot> snap = getSnapshot(); dump(fd, indent, *snap); } void NBLog::Reader::dumpLine(const String8 ×tamp, String8 &body) { if (mFd >= 0) { Loading Loading @@ -656,17 +734,23 @@ void NBLog::appendPID(String8 *body, const void* data, size_t length) { body->appendFormat("<PID: %d, name: %.*s>", id, (int) (length - sizeof(pid_t)), name); } int NBLog::handleFormat(const char *fmt, size_t fmt_length, const uint8_t *data, String8 *timestamp, String8 *body) { if (data[0] != EVENT_TIMESTAMP) { ALOGW("NBLog Reader Expected timestamp event %d, got %d", EVENT_TIMESTAMP, data[0]); } struct timespec ts; memcpy(&ts, &data[2], sizeof(ts)); int NBLog::Reader::handleFormat(const FormatEntry &fmtEntry, String8 *timestamp, String8 *body) { // log timestamp struct timespec ts = fmtEntry.timestamp(); timestamp->clear(); timestamp->appendFormat("[%d.%03d]", (int) ts.tv_sec, (int) (ts.tv_nsec / 1000000)); size_t data_offset = Entry::kOverhead + sizeof ts; size_t fullLength = NBLog::Entry::kOverhead + sizeof(ts); // log author (if present) fullLength += handleAuthor(fmtEntry, body); // log string const uint8_t *args = fmtEntry.args(); size_t args_offset = 0; const char* fmt = fmtEntry.formatString(); size_t fmt_length = fmtEntry.formatStringLength(); for (size_t fmt_offset = 0; fmt_offset < fmt_length; ++fmt_offset) { if (fmt[fmt_offset] != '%') { Loading @@ -681,20 +765,20 @@ int NBLog::handleFormat(const char *fmt, size_t fmt_length, const uint8_t *data, continue; } NBLog::Event event = (NBLog::Event) data[data_offset]; size_t length = data[data_offset + 1]; NBLog::Event event = (NBLog::Event) args[args_offset]; size_t length = args[args_offset + 1]; // TODO check length for event type is correct if(length != data[data_offset + length + 2]) { if(length != args[args_offset + length + 2]) { ALOGW("NBLog Reader received different lengths %zu and %d for event %d", length, data[data_offset + length + 2], event); args[args_offset + length + 2], event); body->append("<invalid entry>"); ++fmt_offset; continue; } // TODO: implement more complex formatting such as %.3f void * datum = (void*) &data[data_offset + 2]; // pointer to the current event data void * datum = (void*) &args[args_offset + 2]; // pointer to the current event args switch(fmt[fmt_offset]) { case 's': // string Loading Loading @@ -731,10 +815,98 @@ int NBLog::handleFormat(const char *fmt, size_t fmt_length, const uint8_t *data, ALOGW("NBLog Reader encountered unknown character %c", fmt[fmt_offset]); } data_offset += length + Entry::kOverhead; args_offset += length + Entry::kOverhead; } fullLength += args_offset + Entry::kOverhead; return fullLength; } // --------------------------------------------------------------------------- NBLog::Merger::Merger(const void *shared, size_t size): mBuffer(NULL), mShared((Shared *) shared), mFifo(mShared != NULL ? new audio_utils_fifo(size, sizeof(uint8_t), mShared->mBuffer, mShared->mRear, NULL /*throttlesFront*/) : NULL), mFifoWriter(mFifo != NULL ? new audio_utils_fifo_writer(*mFifo) : NULL) {} void NBLog::Merger::addReader(const NBLog::NamedReader &reader) { mNamedReaders.push_back(reader); } // items placed in priority queue during merge // composed by a timestamp and the index of the snapshot where the timestamp came from struct MergeItem { struct timespec ts; int index; MergeItem(struct timespec ts, int index): ts(ts), index(index) {} }; // operators needed for priority queue in merge bool operator>(const struct timespec &t1, const struct timespec &t2) { return t1.tv_sec > t2.tv_sec || (t1.tv_sec == t2.tv_sec && t1.tv_nsec > t2.tv_nsec); } bool operator>(const struct MergeItem &i1, const struct MergeItem &i2) { return i1.ts > i2.ts || (i1.ts.tv_sec == i2.ts.tv_sec && i1.ts.tv_nsec == i2.ts.tv_nsec && i1.index > i2.index); } // Merge registered readers, sorted by timestamp void NBLog::Merger::merge() { int nLogs = mNamedReaders.size(); std::vector<std::unique_ptr<NBLog::Reader::Snapshot>> snapshots(nLogs); for (int i = 0; i < nLogs; ++i) { snapshots[i] = mNamedReaders[i].reader()->getSnapshot(); } // initialize offsets std::vector<size_t> offsets(nLogs, 0); // TODO custom heap implementation could allow to update top, improving performance // for bursty buffers std::priority_queue<MergeItem, std::vector<MergeItem>, std::greater<MergeItem>> timestamps; for (int i = 0; i < nLogs; ++i) { if (snapshots[i]->available() > 0) { timespec ts = FormatEntry(snapshots[i]->data()).timestamp(); MergeItem item(ts, i); timestamps.push(item); } } return data_offset + Entry::kOverhead; // data offset + size of END_FMT event while (!timestamps.empty()) { // find minimum timestamp int index = timestamps.top().index; // copy it to the log size_t length = FormatEntry(snapshots[index]->data() + offsets[index]).copyTo( mFifoWriter, index); // update data structures offsets[index] += length; ALOGW_IF(offsets[index] > snapshots[index]->available(), "Overflown snapshot capacity"); timestamps.pop(); if (offsets[index] != snapshots[index]->available()) { timespec ts = FormatEntry(snapshots[index]->data() + offsets[index]).timestamp(); MergeItem item(ts, index); timestamps.emplace(item); } } } const std::vector<NBLog::NamedReader> *NBLog::Merger::getNamedReaders() const { return &mNamedReaders; } NBLog::MergeReader::MergeReader(const void *shared, size_t size, Merger &merger) : Reader(shared, size), mNamedReaders(merger.getNamedReaders()) {} size_t NBLog::MergeReader::handleAuthor(const NBLog::FormatEntry &fmtEntry, String8 *body) { int author = fmtEntry.author(); const char* name = (*mNamedReaders)[author].name(); body->appendFormat("%s: ", name); return NBLog::Entry::kOverhead + sizeof(author); } } // namespace android
services/medialog/MediaLogService.cpp +19 −13 Original line number Diff line number Diff line Loading @@ -26,7 +26,7 @@ namespace android { static const char kDeadlockedString[] = "MediaLogService may be deadlocked\n"; // static const char kDeadlockedString[] = "MediaLogService may be deadlocked\n"; void MediaLogService::registerWriter(const sp<IMemory>& shared, size_t size, const char *name) { Loading @@ -36,9 +36,10 @@ void MediaLogService::registerWriter(const sp<IMemory>& shared, size_t size, con return; } sp<NBLog::Reader> reader(new NBLog::Reader(shared, size)); NamedReader namedReader(reader, name); NBLog::NamedReader namedReader(reader, name); Mutex::Autolock _l(mLock); mNamedReaders.add(namedReader); mMerger.addReader(namedReader); } void MediaLogService::unregisterWriter(const sp<IMemory>& shared) Loading Loading @@ -81,7 +82,8 @@ status_t MediaLogService::dump(int fd, const Vector<String16>& args __unused) return NO_ERROR; } Vector<NamedReader> namedReaders; #if 0 Vector<NBLog::NamedReader> namedReaders; { bool locked = dumpTryLock(mLock); Loading @@ -95,19 +97,23 @@ status_t MediaLogService::dump(int fd, const Vector<String16>& args __unused) } return NO_ERROR; } namedReaders = mNamedReaders; // namedReaders = mNamedReaders; // for (size_t i = 0; i < namedReaders.size(); i++) { // const NBLog::NamedReader& namedReader = namedReaders[i]; // if (fd >= 0) { // dprintf(fd, "\n%s:\n", namedReader.name()); // } else { // ALOGI("%s:", namedReader.name()); // } // namedReader.reader()->dump(fd, 0 /*indent*/); // } mLock.unlock(); } #endif for (size_t i = 0; i < namedReaders.size(); i++) { const NamedReader& namedReader = namedReaders[i]; if (fd >= 0) { dprintf(fd, "\n%s:\n", namedReader.name()); } else { ALOGI("%s:", namedReader.name()); } namedReader.reader()->dump(fd, 0 /*indent*/); } mMerger.merge(); mMergeReader.dump(fd); return NO_ERROR; } Loading
services/medialog/MediaLogService.h +14 −16 Original line number Diff line number Diff line Loading @@ -27,8 +27,13 @@ class MediaLogService : public BinderService<MediaLogService>, public BnMediaLog { friend class BinderService<MediaLogService>; // for MediaLogService() public: MediaLogService() : BnMediaLogService() { } virtual ~MediaLogService() { } MediaLogService() : BnMediaLogService(), mMergerShared((NBLog::Shared*) malloc(NBLog::Timeline::sharedSize(kMergeBufferSize))), mMerger(mMergerShared, kMergeBufferSize), mMergeReader(mMergerShared, kMergeBufferSize, mMerger) {ALOGI("Nico creating MergeReader");} virtual ~MediaLogService() { free(mMergerShared); } virtual void onFirstRef() { } static const char* getServiceName() { return "media.log"; } Loading @@ -47,23 +52,16 @@ private: // Internal dump static const int kDumpLockRetries = 50; static const int kDumpLockSleepUs = 20000; static const size_t kMergeBufferSize = 16 * 1024; // TODO determine good value for this static bool dumpTryLock(Mutex& mutex); Mutex mLock; class NamedReader { public: NamedReader() : mReader(0) { mName[0] = '\0'; } // for Vector NamedReader(const sp<NBLog::Reader>& reader, const char *name) : mReader(reader) { strlcpy(mName, name, sizeof(mName)); } ~NamedReader() { } const sp<NBLog::Reader>& reader() const { return mReader; } const char* name() const { return mName; } private: sp<NBLog::Reader> mReader; static const size_t kMaxName = 32; char mName[kMaxName]; }; Vector<NamedReader> mNamedReaders; Vector<NBLog::NamedReader> mNamedReaders; NBLog::Shared *mMergerShared; NBLog::Merger mMerger; NBLog::MergeReader mMergeReader; }; } // namespace android Loading