From ace588cc1e78f3a83a0e410113009fb31a0f9af7 Mon Sep 17 00:00:00 2001 From: Eric Tan Date: Wed, 12 Sep 2018 11:44:43 -0700 Subject: [PATCH] nblog: split NBLog.cpp into multiple files NBLog.cpp was deleted and split up into Entry.cpp, Merger.cpp, Reader.cpp, Timeline.cpp, and Writer.cpp. NBLog.h was split up into Entry.h, Events.h, Merger.h, Reader.h, Timeline.h, and Writer.h. NBLog.h now includes all of these new headers except Merger.h, which is managed exclusively by MediaLogService. Other changes: - changed NBLog from a class to a namespace - changed NBLog::thread_info_t.type to enum and replaced magic numbers - fixed some fragile build dependencies in libaudioclient and medialog No other changes were made, and all functionalities that existed prior to this commit remain the same. Test: build, dumpsys media.log Bug: 68148948 Change-Id: I1ce6dcb7b30d004f90584edfad7103a89f7bab0c --- media/audioserver/Android.mk | 1 + media/libaudioclient/Android.bp | 11 +- .../libaudioclient/include/media/AudioMixer.h | 7 +- media/libnblog/Android.bp | 6 +- media/libnblog/Entry.cpp | 262 ++++ media/libnblog/Merger.cpp | 297 ++++ media/libnblog/NBLog.cpp | 1246 ----------------- media/libnblog/PerformanceAnalysis.cpp | 2 - media/libnblog/Reader.cpp | 421 ++++++ media/libnblog/ReportPerformance.cpp | 26 +- media/libnblog/Timeline.cpp | 50 + media/libnblog/Writer.cpp | 320 +++++ media/libnblog/include/media/nblog/Entry.h | 232 +++ media/libnblog/include/media/nblog/Events.h | 142 ++ media/libnblog/include/media/nblog/Merger.h | 154 ++ media/libnblog/include/media/nblog/NBLog.h | 670 +-------- .../include/media/nblog/PerformanceAnalysis.h | 12 +- media/libnblog/include/media/nblog/Reader.h | 135 ++ .../include/media/nblog/ReportPerformance.h | 4 +- media/libnblog/include/media/nblog/Timeline.h | 66 + media/libnblog/include/media/nblog/Writer.h | 139 ++ services/audioflinger/FastMixer.cpp | 3 +- services/medialog/MediaLogService.cpp | 1 + services/medialog/MediaLogService.h | 1 + 24 files changed, 2260 insertions(+), 1948 deletions(-) create mode 100644 media/libnblog/Entry.cpp create mode 100644 media/libnblog/Merger.cpp delete mode 100644 media/libnblog/NBLog.cpp create mode 100644 media/libnblog/Reader.cpp create mode 100644 media/libnblog/Timeline.cpp create mode 100644 media/libnblog/Writer.cpp create mode 100644 media/libnblog/include/media/nblog/Entry.h create mode 100644 media/libnblog/include/media/nblog/Events.h create mode 100644 media/libnblog/include/media/nblog/Merger.h create mode 100644 media/libnblog/include/media/nblog/Reader.h create mode 100644 media/libnblog/include/media/nblog/Timeline.h create mode 100644 media/libnblog/include/media/nblog/Writer.h diff --git a/media/audioserver/Android.mk b/media/audioserver/Android.mk index 8a97299eb0..ddf98f65bf 100644 --- a/media/audioserver/Android.mk +++ b/media/audioserver/Android.mk @@ -18,6 +18,7 @@ LOCAL_SHARED_LIBRARIES := \ libmedia \ libmedialogservice \ libnbaio \ + libnblog \ libsoundtriggerservice \ libutils diff --git a/media/libaudioclient/Android.bp b/media/libaudioclient/Android.bp index 6146c0e2f5..1fa1c6e168 100644 --- a/media/libaudioclient/Android.bp +++ b/media/libaudioclient/Android.bp @@ -40,16 +40,17 @@ cc_library_shared { "TrackPlayerBase.cpp", ], shared_libs: [ - "liblog", - "libcutils", - "libutils", - "libbinder", - "libdl", "libaudioutils", "libaudiomanager", + "libbinder", + "libcutils", + "libdl", + "liblog", "libmedia_helper", "libmediametrics", "libmediautils", + "libnblog", + "libutils", ], export_shared_lib_headers: ["libbinder"], diff --git a/media/libaudioclient/include/media/AudioMixer.h b/media/libaudioclient/include/media/AudioMixer.h index cf7d90fe71..aa036a8e1f 100644 --- a/media/libaudioclient/include/media/AudioMixer.h +++ b/media/libaudioclient/include/media/AudioMixer.h @@ -18,17 +18,18 @@ #ifndef ANDROID_AUDIO_MIXER_H #define ANDROID_AUDIO_MIXER_H +#include #include #include #include #include #include +#include #include #include #include #include -#include #include #include #include @@ -41,6 +42,10 @@ namespace android { +namespace NBLog { +class Writer; +} // namespace NBLog + // ---------------------------------------------------------------------------- class AudioMixer diff --git a/media/libnblog/Android.bp b/media/libnblog/Android.bp index 4a4aac1f87..118832040f 100644 --- a/media/libnblog/Android.bp +++ b/media/libnblog/Android.bp @@ -3,9 +3,13 @@ cc_library_shared { name: "libnblog", srcs: [ - "NBLog.cpp", + "Entry.cpp", + "Merger.cpp", "PerformanceAnalysis.cpp", + "Reader.cpp", "ReportPerformance.cpp", + "Timeline.cpp", + "Writer.cpp", ], shared_libs: [ diff --git a/media/libnblog/Entry.cpp b/media/libnblog/Entry.cpp new file mode 100644 index 0000000000..e875639b7c --- /dev/null +++ b/media/libnblog/Entry.cpp @@ -0,0 +1,262 @@ +/* + * Copyright (C) 2018 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#define LOG_TAG "NBLog" +//#define LOG_NDEBUG 0 + +#include +#include +#include + +#include +#include +#include +#include + +namespace android { +namespace NBLog { + +int Entry::copyEntryDataAt(size_t offset) const +{ + // FIXME This is too slow + if (offset == 0) { + return mEvent; + } else if (offset == 1) { + return mLength; + } else if (offset < (size_t) (mLength + 2)) { + return (int) ((char *) mData)[offset - 2]; + } else if (offset == (size_t) (mLength + 2)) { + return mLength; + } else { + return 0; // FIXME is this an error? + } +} + +EntryIterator::EntryIterator() // Dummy initialization. + : mPtr(nullptr) +{ +} + +EntryIterator::EntryIterator(const uint8_t *entry) + : mPtr(entry) +{ +} + +EntryIterator::EntryIterator(const EntryIterator &other) + : mPtr(other.mPtr) +{ +} + +const entry& EntryIterator::operator*() const +{ + return *(entry*) mPtr; +} + +const entry* EntryIterator::operator->() const +{ + return (entry*) mPtr; +} + +EntryIterator& EntryIterator::operator++() +{ + mPtr += mPtr[offsetof(entry, length)] + Entry::kOverhead; + return *this; +} + +EntryIterator& EntryIterator::operator--() +{ + mPtr -= mPtr[Entry::kPreviousLengthOffset] + Entry::kOverhead; + return *this; +} + +EntryIterator EntryIterator::next() const +{ + EntryIterator aux(*this); + return ++aux; +} + +EntryIterator EntryIterator::prev() const +{ + EntryIterator aux(*this); + return --aux; +} + +bool EntryIterator::operator!=(const EntryIterator &other) const +{ + return mPtr != other.mPtr; +} + +int EntryIterator::operator-(const EntryIterator &other) const +{ + return mPtr - other.mPtr; +} + +bool EntryIterator::hasConsistentLength() const +{ + return mPtr[offsetof(entry, length)] == mPtr[mPtr[offsetof(entry, length)] + + Entry::kOverhead + Entry::kPreviousLengthOffset]; +} + +void EntryIterator::copyTo(std::unique_ptr &dst) const +{ + size_t length = mPtr[offsetof(entry, length)] + Entry::kOverhead; + dst->write(mPtr, length); +} + +void EntryIterator::copyData(uint8_t *dst) const +{ + memcpy((void*) dst, mPtr + offsetof(entry, data), mPtr[offsetof(entry, length)]); +} + +// --------------------------------------------------------------------------- + +std::unique_ptr AbstractEntry::buildEntry(const uint8_t *ptr) +{ + if (ptr == nullptr) { + return nullptr; + } + const uint8_t type = EntryIterator(ptr)->type; + switch (type) { + case EVENT_FMT_START: + return std::make_unique(FormatEntry(ptr)); + case EVENT_AUDIO_STATE: + case EVENT_HISTOGRAM_ENTRY_TS: + return std::make_unique(HistogramEntry(ptr)); + default: + ALOGW("Tried to create AbstractEntry of type %d", type); + return nullptr; + } +} + +EntryIterator FormatEntry::begin() const +{ + return EntryIterator(mEntry); +} + +const char *FormatEntry::formatString() const +{ + return (const char*) mEntry + offsetof(entry, data); +} + +size_t FormatEntry::formatStringLength() const +{ + return mEntry[offsetof(entry, length)]; +} + +EntryIterator FormatEntry::args() const +{ + auto it = begin(); + ++it; // skip start fmt + ++it; // skip timestamp + ++it; // skip hash + // Skip author if present + if (it->type == EVENT_FMT_AUTHOR) { + ++it; + } + return it; +} + +int64_t FormatEntry::timestamp() const +{ + auto it = begin(); + ++it; // skip start fmt + return it.payload(); +} + +log_hash_t FormatEntry::hash() const +{ + auto it = begin(); + ++it; // skip start fmt + ++it; // skip timestamp + // unaligned 64-bit read not supported + log_hash_t hash; + memcpy(&hash, it->data, sizeof(hash)); + return hash; +} + +int FormatEntry::author() const +{ + auto it = begin(); + ++it; // skip start fmt + ++it; // skip timestamp + ++it; // skip hash + // if there is an author entry, return it, return -1 otherwise + return it->type == EVENT_FMT_AUTHOR ? it.payload() : -1; +} + +EntryIterator FormatEntry::copyWithAuthor( + std::unique_ptr &dst, int author) const +{ + auto it = begin(); + it.copyTo(dst); // copy fmt start entry + (++it).copyTo(dst); // copy timestamp + (++it).copyTo(dst); // copy hash + // insert author entry + size_t authorEntrySize = Entry::kOverhead + sizeof(author); + uint8_t authorEntry[authorEntrySize]; + 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_FMT_END) { + it.copyTo(dst); + } + it.copyTo(dst); + ++it; + return it; +} + +int64_t HistogramEntry::timestamp() const +{ + return EntryIterator(mEntry).payload().ts; +} + +log_hash_t HistogramEntry::hash() const +{ + return EntryIterator(mEntry).payload().hash; +} + +int HistogramEntry::author() const +{ + EntryIterator it(mEntry); + return it->length == sizeof(HistTsEntryWithAuthor) + ? it.payload().author : -1; +} + +EntryIterator HistogramEntry::copyWithAuthor( + std::unique_ptr &dst, int author) const +{ + // Current histogram entry has {type, length, struct HistTsEntry, length}. + // We now want {type, length, struct HistTsEntryWithAuthor, length} + uint8_t buffer[Entry::kOverhead + sizeof(HistTsEntryWithAuthor)]; + // Copy content until the point we want to add the author + memcpy(buffer, mEntry, sizeof(entry) + sizeof(HistTsEntry)); + // Copy the author + *(int*) (buffer + sizeof(entry) + sizeof(HistTsEntry)) = author; + // Update lengths + buffer[offsetof(entry, length)] = sizeof(HistTsEntryWithAuthor); + buffer[offsetof(entry, data) + sizeof(HistTsEntryWithAuthor) + offsetof(ending, length)] + = sizeof(HistTsEntryWithAuthor); + // Write new buffer into FIFO + dst->write(buffer, sizeof(buffer)); + return EntryIterator(mEntry).next(); +} + +} // namespace NBLog +} // namespace android diff --git a/media/libnblog/Merger.cpp b/media/libnblog/Merger.cpp new file mode 100644 index 0000000000..5f6e0d19c5 --- /dev/null +++ b/media/libnblog/Merger.cpp @@ -0,0 +1,297 @@ +/* + * Copyright (C) 2018 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#define LOG_TAG "NBLog" +//#define LOG_NDEBUG 0 + +#include +#include +#include +#include +#include + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +namespace android { +namespace NBLog { + +Merger::Merger(const void *shared, size_t size): + 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 Merger::addReader(const sp &reader) +{ + // FIXME This is called by binder thread in MediaLogService::registerWriter + // but the access to shared variable mReaders is not yet protected by a lock. + mReaders.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 +{ + int64_t ts; + int index; + MergeItem(int64_t ts, int index): ts(ts), index(index) {} +}; + +bool operator>(const struct MergeItem &i1, const struct MergeItem &i2) +{ + return i1.ts > i2.ts || (i1.ts == i2.ts && i1.index > i2.index); +} + +// Merge registered readers, sorted by timestamp, and write data to a single FIFO in local memory +void Merger::merge() +{ + if (true) return; // Merging is not necessary at the moment, so this is to disable it + // and bypass compiler warnings about member variables not being used. + const int nLogs = mReaders.size(); + std::vector> snapshots(nLogs); + std::vector offsets; + offsets.reserve(nLogs); + for (int i = 0; i < nLogs; ++i) { + snapshots[i] = mReaders[i]->getSnapshot(); + offsets.push_back(snapshots[i]->begin()); + } + // initialize offsets + // TODO custom heap implementation could allow to update top, improving performance + // for bursty buffers + std::priority_queue, std::greater> timestamps; + for (int i = 0; i < nLogs; ++i) + { + if (offsets[i] != snapshots[i]->end()) { + std::unique_ptr abstractEntry = AbstractEntry::buildEntry(offsets[i]); + if (abstractEntry == nullptr) { + continue; + } + timestamps.emplace(abstractEntry->timestamp(), i); + } + } + + while (!timestamps.empty()) { + int index = timestamps.top().index; // find minimum timestamp + // copy it to the log, increasing offset + offsets[index] = AbstractEntry::buildEntry(offsets[index])-> + copyWithAuthor(mFifoWriter, index); + // update data structures + timestamps.pop(); + if (offsets[index] != snapshots[index]->end()) { + int64_t ts = AbstractEntry::buildEntry(offsets[index])->timestamp(); + timestamps.emplace(ts, index); + } + } +} + +const std::vector>& Merger::getReaders() const +{ + //AutoMutex _l(mLock); + return mReaders; +} + +// --------------------------------------------------------------------------- + +MergeReader::MergeReader(const void *shared, size_t size, Merger &merger) + : Reader(shared, size, "MergeReader"), mReaders(merger.getReaders()) +{ +} + +// Takes raw content of the local merger FIFO, processes log entries, and +// writes the data to a map of class PerformanceAnalysis, based on their thread ID. +void MergeReader::processSnapshot(Snapshot &snapshot, int author) +{ + ReportPerformance::PerformanceData& data = mThreadPerformanceData[author]; + // 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: { + const HistTsEntry payload = it.payload(); + // TODO: hash for histogram ts and audio state need to match + // and correspond to audio production source file location + mThreadPerformanceAnalysis[author][0 /*hash*/].logTsEntry(payload.ts); + } break; + case EVENT_AUDIO_STATE: { + mThreadPerformanceAnalysis[author][0 /*hash*/].handleStateChange(); + } break; + case EVENT_THREAD_INFO: { + const thread_info_t info = it.payload(); + // TODO make PerformanceData hold a type of thread_info_t. + // Currently, thread_info_t is defined in NBLog.h, which includes + // PerformanceAnalysis.h. PerformanceData is defined in PerformanceAnalysis.h, + // where including NBLog.h would result in circular includes. The organization + // of files will need to change to avoid this problem. + data.threadInfo = info; + } break; + case EVENT_LATENCY: { + const double latencyMs = it.payload(); + data.latencyHist.add(latencyMs); + } break; + case EVENT_WORK_TIME: { + const int64_t monotonicNs = it.payload(); + const double monotonicMs = monotonicNs * 1e-6; + data.workHist.add(monotonicMs); + data.active += monotonicNs; + } break; + case EVENT_WARMUP_TIME: { + const double timeMs = it.payload(); + data.warmupHist.add(timeMs); + } break; + case EVENT_UNDERRUN: + data.underruns++; + break; + case EVENT_OVERRUN: + data.overruns++; + break; + case EVENT_RESERVED: + case EVENT_UPPER_BOUND: + ALOGW("warning: unexpected event %d", it->type); + default: + break; + } + } +} + +void MergeReader::getAndProcessSnapshot() +{ + // get a snapshot of each reader and process them + // TODO insert lock here + const size_t nLogs = mReaders.size(); + std::vector> snapshots(nLogs); + for (size_t i = 0; i < nLogs; i++) { + snapshots[i] = mReaders[i]->getSnapshot(); + } + // TODO unlock lock here + for (size_t i = 0; i < nLogs; i++) { + if (snapshots[i] != nullptr) { + processSnapshot(*(snapshots[i]), i); + } + } + checkPushToMediaMetrics(); +} + +void MergeReader::checkPushToMediaMetrics() +{ + const nsecs_t now = systemTime(); + for (auto& item : mThreadPerformanceData) { + ReportPerformance::PerformanceData& data = item.second; + if (now - data.start >= kPeriodicMediaMetricsPush) { + (void)ReportPerformance::sendToMediaMetrics(data); + data.reset(); // data is persistent per thread + } + } +} + +void MergeReader::dump(int fd, int indent) +{ + // TODO: add a mutex around media.log dump + ReportPerformance::dump(fd, indent, mThreadPerformanceAnalysis); + Json::Value root(Json::arrayValue); + for (const auto& item : mThreadPerformanceData) { + const ReportPerformance::PerformanceData& data = item.second; + std::unique_ptr threadData = ReportPerformance::dumpToJson(data); + if (threadData == nullptr) { + continue; + } + (*threadData)["threadNum"] = item.first; + root.append(*threadData); + } + Json::StyledWriter writer; + std::string rootStr = writer.write(root); + write(fd, rootStr.c_str(), rootStr.size()); +} + +void MergeReader::handleAuthor(const AbstractEntry &entry, String8 *body) +{ + int author = entry.author(); + if (author == -1) { + return; + } + // FIXME Needs a lock + const char* name = mReaders[author]->name().c_str(); + body->appendFormat("%s: ", name); +} + +// --------------------------------------------------------------------------- + +MergeThread::MergeThread(Merger &merger, MergeReader &mergeReader) + : mMerger(merger), + mMergeReader(mergeReader), + mTimeoutUs(0) +{ +} + +MergeThread::~MergeThread() +{ + // set exit flag, set timeout to 0 to force threadLoop to exit and wait for the thread to join + requestExit(); + setTimeoutUs(0); + join(); +} + +bool MergeThread::threadLoop() +{ + bool doMerge; + { + AutoMutex _l(mMutex); + // If mTimeoutUs is negative, wait on the condition variable until it's positive. + // If it's positive, merge. The minimum period between waking the condition variable + // is handled in AudioFlinger::MediaLogNotifier::threadLoop(). + mCond.wait(mMutex); + doMerge = mTimeoutUs > 0; + mTimeoutUs -= kThreadSleepPeriodUs; + } + if (doMerge) { + // Merge data from all the readers + mMerger.merge(); + // Process the data collected by mMerger and write it to PerformanceAnalysis + // FIXME: decide whether to call getAndProcessSnapshot every time + // or whether to have a separate thread that calls it with a lower frequency + mMergeReader.getAndProcessSnapshot(); + } + return true; +} + +void MergeThread::wakeup() +{ + setTimeoutUs(kThreadWakeupPeriodUs); +} + +void MergeThread::setTimeoutUs(int time) +{ + AutoMutex _l(mMutex); + mTimeoutUs = time; + mCond.signal(); +} + +} // namespace NBLog +} // namespace android diff --git a/media/libnblog/NBLog.cpp b/media/libnblog/NBLog.cpp deleted file mode 100644 index aee0ea39e0..0000000000 --- a/media/libnblog/NBLog.cpp +++ /dev/null @@ -1,1246 +0,0 @@ -/* - * Copyright (C) 2013 The Android Open Source Project - * - * Licensed under the Apache License, Version 2.0 (the "License"); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. - * - * - */ - -#define LOG_TAG "NBLog" - -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include - -#include -#include - -namespace android { - -int NBLog::Entry::copyEntryDataAt(size_t offset) const -{ - // FIXME This is too slow - if (offset == 0) - return mEvent; - else if (offset == 1) - return mLength; - else if (offset < (size_t) (mLength + 2)) - return ((char *) mData)[offset - 2]; - else if (offset == (size_t) (mLength + 2)) - return mLength; - else - return 0; -} - -// --------------------------------------------------------------------------- - -/*static*/ -std::unique_ptr NBLog::AbstractEntry::buildEntry(const uint8_t *ptr) -{ - if (ptr == nullptr) { - return nullptr; - } - const uint8_t type = EntryIterator(ptr)->type; - switch (type) { - case EVENT_FMT_START: - return std::make_unique(FormatEntry(ptr)); - case EVENT_AUDIO_STATE: - case EVENT_HISTOGRAM_ENTRY_TS: - return std::make_unique(HistogramEntry(ptr)); - default: - ALOGW("Tried to create AbstractEntry of type %d", type); - return nullptr; - } -} - -NBLog::AbstractEntry::AbstractEntry(const uint8_t *entry) : mEntry(entry) -{ -} - -// --------------------------------------------------------------------------- - -NBLog::EntryIterator NBLog::FormatEntry::begin() const -{ - return EntryIterator(mEntry); -} - -const char *NBLog::FormatEntry::formatString() const -{ - return (const char*) mEntry + offsetof(entry, data); -} - -size_t NBLog::FormatEntry::formatStringLength() const -{ - return mEntry[offsetof(entry, length)]; -} - -NBLog::EntryIterator NBLog::FormatEntry::args() const -{ - auto it = begin(); - ++it; // skip start fmt - ++it; // skip timestamp - ++it; // skip hash - // Skip author if present - if (it->type == EVENT_FMT_AUTHOR) { - ++it; - } - return it; -} - -int64_t NBLog::FormatEntry::timestamp() const -{ - auto it = begin(); - ++it; // skip start fmt - return it.payload(); -} - -NBLog::log_hash_t NBLog::FormatEntry::hash() const -{ - auto it = begin(); - ++it; // skip start fmt - ++it; // skip timestamp - // unaligned 64-bit read not supported - log_hash_t hash; - memcpy(&hash, it->data, sizeof(hash)); - return hash; -} - -int NBLog::FormatEntry::author() const -{ - auto it = begin(); - ++it; // skip start fmt - ++it; // skip timestamp - ++it; // skip hash - // if there is an author entry, return it, return -1 otherwise - return it->type == EVENT_FMT_AUTHOR ? it.payload() : -1; -} - -NBLog::EntryIterator NBLog::FormatEntry::copyWithAuthor( - std::unique_ptr &dst, int author) const -{ - auto it = begin(); - it.copyTo(dst); // copy fmt start entry - (++it).copyTo(dst); // copy timestamp - (++it).copyTo(dst); // copy hash - // insert author entry - size_t authorEntrySize = Entry::kOverhead + sizeof(author); - uint8_t authorEntry[authorEntrySize]; - 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_FMT_END) { - it.copyTo(dst); - } - it.copyTo(dst); - ++it; - return it; -} - -void NBLog::EntryIterator::copyTo(std::unique_ptr &dst) const -{ - size_t length = mPtr[offsetof(entry, length)] + Entry::kOverhead; - dst->write(mPtr, length); -} - -void NBLog::EntryIterator::copyData(uint8_t *dst) const -{ - memcpy((void*) dst, mPtr + offsetof(entry, data), mPtr[offsetof(entry, length)]); -} - -NBLog::EntryIterator::EntryIterator() // Dummy initialization. - : mPtr(nullptr) -{ -} - -NBLog::EntryIterator::EntryIterator(const uint8_t *entry) - : mPtr(entry) -{ -} - -NBLog::EntryIterator::EntryIterator(const NBLog::EntryIterator &other) - : mPtr(other.mPtr) -{ -} - -const NBLog::entry& NBLog::EntryIterator::operator*() const -{ - return *(entry*) mPtr; -} - -const NBLog::entry* NBLog::EntryIterator::operator->() const -{ - return (entry*) mPtr; -} - -NBLog::EntryIterator& NBLog::EntryIterator::operator++() -{ - mPtr += mPtr[offsetof(entry, length)] + Entry::kOverhead; - return *this; -} - -NBLog::EntryIterator& NBLog::EntryIterator::operator--() -{ - mPtr -= mPtr[Entry::kPreviousLengthOffset] + Entry::kOverhead; - return *this; -} - -NBLog::EntryIterator NBLog::EntryIterator::next() const -{ - EntryIterator aux(*this); - return ++aux; -} - -NBLog::EntryIterator NBLog::EntryIterator::prev() const -{ - EntryIterator aux(*this); - return --aux; -} - -int NBLog::EntryIterator::operator-(const NBLog::EntryIterator &other) const -{ - return mPtr - other.mPtr; -} - -bool NBLog::EntryIterator::operator!=(const EntryIterator &other) const -{ - return mPtr != other.mPtr; -} - -bool NBLog::EntryIterator::hasConsistentLength() const -{ - return mPtr[offsetof(entry, length)] == mPtr[mPtr[offsetof(entry, length)] + - Entry::kOverhead + Entry::kPreviousLengthOffset]; -} - -// --------------------------------------------------------------------------- - -int64_t NBLog::HistogramEntry::timestamp() const -{ - return EntryIterator(mEntry).payload().ts; -} - -NBLog::log_hash_t NBLog::HistogramEntry::hash() const -{ - return EntryIterator(mEntry).payload().hash; -} - -int NBLog::HistogramEntry::author() const -{ - EntryIterator it(mEntry); - return it->length == sizeof(HistTsEntryWithAuthor) - ? it.payload().author : -1; -} - -NBLog::EntryIterator NBLog::HistogramEntry::copyWithAuthor( - std::unique_ptr &dst, int author) const -{ - // Current histogram entry has {type, length, struct HistTsEntry, length}. - // We now want {type, length, struct HistTsEntryWithAuthor, length} - uint8_t buffer[Entry::kOverhead + sizeof(HistTsEntryWithAuthor)]; - // Copy content until the point we want to add the author - memcpy(buffer, mEntry, sizeof(entry) + sizeof(HistTsEntry)); - // Copy the author - *(int*) (buffer + sizeof(entry) + sizeof(HistTsEntry)) = author; - // Update lengths - buffer[offsetof(entry, length)] = sizeof(HistTsEntryWithAuthor); - buffer[offsetof(entry, data) + sizeof(HistTsEntryWithAuthor) + offsetof(ending, length)] - = sizeof(HistTsEntryWithAuthor); - // Write new buffer into FIFO - dst->write(buffer, sizeof(buffer)); - return EntryIterator(mEntry).next(); -} - -// --------------------------------------------------------------------------- - -#if 0 // FIXME see note in NBLog.h -NBLog::Timeline::Timeline(size_t size, void *shared) - : mSize(roundup(size)), mOwn(shared == NULL), - mShared((Shared *) (mOwn ? new char[sharedSize(size)] : shared)) -{ - new (mShared) Shared; -} - -NBLog::Timeline::~Timeline() -{ - mShared->~Shared(); - if (mOwn) { - delete[] (char *) mShared; - } -} -#endif - -/*static*/ -size_t NBLog::Timeline::sharedSize(size_t size) -{ - // TODO fifo now supports non-power-of-2 buffer sizes, so could remove the roundup - return sizeof(Shared) + roundup(size); -} - -// --------------------------------------------------------------------------- - -NBLog::Writer::Writer() - : mShared(NULL), mFifo(NULL), mFifoWriter(NULL), mEnabled(false), mPidTag(NULL), mPidTagSize(0) -{ -} - -NBLog::Writer::Writer(void *shared, size_t size) - : 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), - mEnabled(mFifoWriter != NULL) -{ - // caching pid and process name - pid_t id = ::getpid(); - char procName[16]; - int status = prctl(PR_GET_NAME, procName); - if (status) { // error getting process name - procName[0] = '\0'; - } - size_t length = strlen(procName); - mPidTagSize = length + sizeof(pid_t); - mPidTag = new char[mPidTagSize]; - memcpy(mPidTag, &id, sizeof(pid_t)); - memcpy(mPidTag + sizeof(pid_t), procName, length); -} - -NBLog::Writer::Writer(const sp& iMemory, size_t size) - : Writer(iMemory != 0 ? (Shared *) iMemory->pointer() : NULL, size) -{ - mIMemory = iMemory; -} - -NBLog::Writer::~Writer() -{ - delete mFifoWriter; - delete mFifo; - delete[] mPidTag; -} - -void NBLog::Writer::log(const char *string) -{ - if (!mEnabled) { - return; - } - LOG_ALWAYS_FATAL_IF(string == NULL, "Attempted to log NULL string"); - size_t length = strlen(string); - if (length > Entry::kMaxLength) { - length = Entry::kMaxLength; - } - log(EVENT_STRING, string, length); -} - -void NBLog::Writer::logf(const char *fmt, ...) -{ - if (!mEnabled) { - return; - } - va_list ap; - va_start(ap, fmt); - Writer::logvf(fmt, ap); // the Writer:: is needed to avoid virtual dispatch for LockedWriter - va_end(ap); -} - -void NBLog::Writer::logvf(const char *fmt, va_list ap) -{ - if (!mEnabled) { - return; - } - char buffer[Entry::kMaxLength + 1 /*NUL*/]; - int length = vsnprintf(buffer, sizeof(buffer), fmt, ap); - if (length >= (int) sizeof(buffer)) { - length = sizeof(buffer) - 1; - // NUL termination is not required - // buffer[length] = '\0'; - } - if (length >= 0) { - log(EVENT_STRING, buffer, length); - } -} - -void NBLog::Writer::logTimestamp() -{ - if (!mEnabled) { - return; - } - struct timespec ts; - if (!clock_gettime(CLOCK_MONOTONIC, &ts)) { - log(EVENT_TIMESTAMP, &ts, sizeof(ts)); - } -} - -void NBLog::Writer::logStart(const char *fmt) -{ - if (!mEnabled) { - return; - } - size_t length = strlen(fmt); - if (length > Entry::kMaxLength) { - length = Entry::kMaxLength; - } - log(EVENT_FMT_START, fmt, length); -} - -void NBLog::Writer::logTimestampFormat() -{ - if (!mEnabled) { - return; - } - const nsecs_t ts = systemTime(); - if (ts > 0) { - log(EVENT_FMT_TIMESTAMP, &ts, sizeof(ts)); - } else { - ALOGE("Failed to get timestamp"); - } -} - -void NBLog::Writer::logEventHistTs(Event event, log_hash_t hash) -{ - if (!mEnabled) { - return; - } - HistTsEntry data; - data.hash = hash; - data.ts = systemTime(); - if (data.ts > 0) { - log(event, &data, sizeof(data)); - } else { - ALOGE("Failed to get timestamp"); - } -} - -void NBLog::Writer::logFormat(const char *fmt, log_hash_t hash, ...) -{ - if (!mEnabled) { - return; - } - va_list ap; - va_start(ap, hash); - Writer::logVFormat(fmt, hash, ap); - va_end(ap); -} - -void NBLog::Writer::logVFormat(const char *fmt, log_hash_t hash, va_list argp) -{ - if (!mEnabled) { - return; - } - Writer::logStart(fmt); - int i; - double d; - float f; - char* s; - size_t length; - int64_t t; - 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 != '%') { - continue; - } - switch(*++p) { - case 's': // string - s = va_arg(argp, char *); - 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); - log(EVENT_FMT_TIMESTAMP, &t, sizeof(t)); - break; - - case 'd': // integer - i = va_arg(argp, int); - log(EVENT_FMT_INTEGER, &i, sizeof(i)); - break; - - case 'f': // float - 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 - log(EVENT_FMT_PID, mPidTag, mPidTagSize); - break; - - // the "%\0" case finishes parsing - case '\0': - --p; - break; - - case '%': - break; - - default: - ALOGW("NBLog Writer parsed invalid format specifier: %c", *p); - break; - } - } - Entry etr(EVENT_FMT_END, nullptr, 0); - log(etr, true); -} - -void NBLog::Writer::log(Event event, const void *data, size_t length) -{ - if (!mEnabled) { - return; - } - if (data == NULL || length > Entry::kMaxLength) { - // TODO Perhaps it makes sense to display truncated data or at least a - // message that the data is too long? The current behavior can create - // a confusion for a programmer debugging their code. - return; - } - // Ignore if invalid event - if (event == EVENT_RESERVED || event >= EVENT_UPPER_BOUND) { - return; - } - Entry etr(event, data, length); - log(etr, true /*trusted*/); -} - -void NBLog::Writer::log(const NBLog::Entry &etr, bool trusted) -{ - if (!mEnabled) { - return; - } - if (!trusted) { - log(etr.mEvent, etr.mData, etr.mLength); - return; - } - const size_t need = etr.mLength + Entry::kOverhead; // mEvent, mLength, data[mLength], mLength - // need = number of bytes written to FIFO - - // FIXME optimize this using memcpy for the data part of the Entry. - // The Entry could have a method copyTo(ptr, offset, size) to optimize the copy. - // checks size of a single log Entry: type, length, data pointer and ending - uint8_t temp[Entry::kMaxLength + Entry::kOverhead]; - // write this data to temp array - for (size_t i = 0; i < need; i++) { - temp[i] = etr.copyEntryDataAt(i); - } - // write to circular buffer - mFifoWriter->write(temp, need); -} - -bool NBLog::Writer::isEnabled() const -{ - return mEnabled; -} - -bool NBLog::Writer::setEnabled(bool enabled) -{ - bool old = mEnabled; - mEnabled = enabled && mShared != NULL; - return old; -} - -// --------------------------------------------------------------------------- - -NBLog::LockedWriter::LockedWriter() - : Writer() -{ -} - -NBLog::LockedWriter::LockedWriter(void *shared, size_t size) - : Writer(shared, size) -{ -} - -bool NBLog::LockedWriter::isEnabled() const -{ - Mutex::Autolock _l(mLock); - return Writer::isEnabled(); -} - -bool NBLog::LockedWriter::setEnabled(bool enabled) -{ - Mutex::Autolock _l(mLock); - return Writer::setEnabled(enabled); -} - -void NBLog::LockedWriter::log(const Entry &entry, bool trusted) { - Mutex::Autolock _l(mLock); - Writer::log(entry, trusted); -} - -// --------------------------------------------------------------------------- - -// 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::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 -}; - -// 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::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) - : mName(name), - mShared((/*const*/ Shared *) shared), /*mIMemory*/ - mFifo(mShared != NULL ? - new audio_utils_fifo(size, sizeof(uint8_t), - mShared->mBuffer, mShared->mRear, NULL /*throttlesFront*/) : NULL), - mFifoReader(mFifo != NULL ? new audio_utils_fifo_reader(*mFifo) : NULL) -{ -} - -NBLog::Reader::Reader(const sp& iMemory, size_t size, const std::string &name) - : Reader(iMemory != 0 ? (Shared *) iMemory->pointer() : NULL, size, name) -{ - mIMemory = iMemory; -} - -NBLog::Reader::~Reader() -{ - delete mFifoReader; - delete mFifo; -} - -const uint8_t *NBLog::Reader::findLastValidEntry(const uint8_t *front, const uint8_t *back, - const std::unordered_set &invalidTypes) { - if (front == nullptr || back == nullptr) { - return nullptr; - } - while (back + Entry::kPreviousLengthOffset >= front) { - const uint8_t *prev = back - back[Entry::kPreviousLengthOffset] - Entry::kOverhead; - 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 invalidTypes does not contain the type, then the type is valid. - if (invalidTypes.find(type) == invalidTypes.end()) { - return prev; - } - back = prev; - } - return nullptr; // no entry found -} - -// Copies content of a Reader FIFO into its Snapshot -// The Snapshot has the same raw data, but represented as a sequence of entries -// and an EntryIterator making it possible to process the data. -std::unique_ptr NBLog::Reader::getSnapshot() -{ - if (mFifoReader == NULL) { - return std::unique_ptr(new Snapshot()); - } - - // This emulates the behaviour of audio_utils_fifo_reader::read, but without incrementing the - // reader index. The index is incremented after handling corruption, to after the last complete - // entry of the buffer - size_t lost = 0; - audio_utils_iovec iovec[2]; - const size_t capacity = mFifo->capacity(); - ssize_t availToRead; - // A call to audio_utils_fifo_reader::obtain() places the read pointer one buffer length - // before the writer's pointer (since mFifoReader was constructed with flush=false). The - // do while loop is an attempt to read all of the FIFO's contents regardless of how behind - // the reader is with respect to the writer. However, the following scheduling sequence is - // possible and can lead to a starvation situation: - // - Writer T1 writes, overrun with respect to Reader T2 - // - T2 calls obtain() and gets EOVERFLOW, T2 ptr placed one buffer size behind T1 ptr - // - T1 write, overrun - // - T2 obtain(), EOVERFLOW (and so on...) - // To address this issue, we limit the number of tries for the reader to catch up with - // the writer. - int tries = 0; - size_t lostTemp; - do { - availToRead = mFifoReader->obtain(iovec, capacity, NULL /*timeout*/, &lostTemp); - lost += lostTemp; - } while (availToRead < 0 || ++tries <= kMaxObtainTries); - - if (availToRead <= 0) { - ALOGW_IF(availToRead < 0, "NBLog Reader %s failed to catch up with Writer", mName.c_str()); - return std::unique_ptr(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(new Snapshot(availToRead)); - memcpy(snapshot->mData, (const char *) mFifo->buffer() + iovec[0].mOffset, iovec[0].mLength); - if (iovec[1].mLength > 0) { - memcpy(snapshot->mData + (iovec[0].mLength), - (const char *) mFifo->buffer() + iovec[1].mOffset, iovec[1].mLength); - } - - // 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 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 FMT_END. 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 FMT_END entry - snapshot->mEnd = EntryIterator(lastEnd).next(); - // find first FMT_START - const uint8_t *firstStart = nullptr; - const uint8_t *firstStartTmp = snapshot->mEnd; - while ((firstStartTmp = findLastValidEntry(front, firstStartTmp, invalidBeginTypes)) - != nullptr) { - firstStart = firstStartTmp; - } - // firstStart is null if no FMT_START entry was found before lastEnd - if (firstStart == nullptr) { - snapshot->mBegin = snapshot->mEnd; - } else { - snapshot->mBegin = EntryIterator(firstStart); - } - } - - // advance fifo reader index to after last entry read. - mFifoReader->release(snapshot->mEnd - front); - - snapshot->mLost = lost; - return snapshot; -} - -// TODO separate this method from the rest of NBLog -// Takes raw content of the local merger FIFO, processes log entries, and -// writes the data to a map of class PerformanceAnalysis, based on their thread ID. -void NBLog::MergeReader::processSnapshot(NBLog::Snapshot &snapshot, int author) -{ - ReportPerformance::PerformanceData& data = mThreadPerformanceData[author]; - // 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: { - const HistTsEntry payload = it.payload(); - // TODO: hash for histogram ts and audio state need to match - // and correspond to audio production source file location - mThreadPerformanceAnalysis[author][0 /*hash*/].logTsEntry(payload.ts); - } break; - case EVENT_AUDIO_STATE: { - mThreadPerformanceAnalysis[author][0 /*hash*/].handleStateChange(); - } break; - case EVENT_THREAD_INFO: { - const thread_info_t info = it.payload(); - // TODO make PerformanceData hold a type of thread_info_t. - // Currently, thread_info_t is defined in NBLog.h, which includes - // PerformanceAnalysis.h. PerformanceData is defined in PerformanceAnalysis.h, - // where including NBLog.h would result in circular includes. The organization - // of files will need to change to avoid this problem. - data.type = info.type; - data.frameCount = info.frameCount; - data.sampleRate = info.sampleRate; - } break; - case EVENT_LATENCY: { - const double latencyMs = it.payload(); - data.latencyHist.add(latencyMs); - } break; - case EVENT_WORK_TIME: { - const int64_t monotonicNs = it.payload(); - const double monotonicMs = monotonicNs * 1e-6; - data.workHist.add(monotonicMs); - data.active += monotonicNs; - } break; - case EVENT_WARMUP_TIME: { - const double timeMs = it.payload(); - data.warmupHist.add(timeMs); - } break; - case EVENT_UNDERRUN: - data.underruns++; - break; - case EVENT_OVERRUN: - data.overruns++; - break; - case EVENT_RESERVED: - case EVENT_UPPER_BOUND: - ALOGW("warning: unexpected event %d", it->type); - default: - break; - } - } -} - -void NBLog::MergeReader::getAndProcessSnapshot() -{ - // get a snapshot of each reader and process them - // TODO insert lock here - const size_t nLogs = mReaders.size(); - std::vector> snapshots(nLogs); - for (size_t i = 0; i < nLogs; i++) { - snapshots[i] = mReaders[i]->getSnapshot(); - } - // TODO unlock lock here - for (size_t i = 0; i < nLogs; i++) { - if (snapshots[i] != nullptr) { - processSnapshot(*(snapshots[i]), i); - } - } - checkPushToMediaMetrics(); -} - -void NBLog::MergeReader::checkPushToMediaMetrics() -{ - const nsecs_t now = systemTime(); - for (auto& item : mThreadPerformanceData) { - ReportPerformance::PerformanceData& data = item.second; - if (now - data.start >= kPeriodicMediaMetricsPush) { - (void)ReportPerformance::sendToMediaMetrics(data); - data.reset(); // data is persistent per thread - } - } -} - -void NBLog::MergeReader::dump(int fd, int indent) -{ - // TODO: add a mutex around media.log dump - ReportPerformance::dump(fd, indent, mThreadPerformanceAnalysis); - Json::Value root(Json::arrayValue); - for (const auto& item : mThreadPerformanceData) { - const ReportPerformance::PerformanceData& data = item.second; - std::unique_ptr threadData = ReportPerformance::dumpToJson(data); - if (threadData == nullptr) { - continue; - } - (*threadData)["threadNum"] = item.first; - root.append(*threadData); - } - Json::StyledWriter writer; - std::string rootStr = writer.write(root); - dprintf(fd, "%s", rootStr.c_str()); -} - -// TODO for future compatibility, would prefer to have a dump() go to string, and then go -// to fd only when invoked through binder. -void NBLog::DumpReader::dump(int fd, size_t indent) -{ - if (fd < 0) return; - std::unique_ptr snapshot = getSnapshot(); - if (snapshot == nullptr) { - return; - } - String8 timestamp, body; - - // TODO all logged types should have a printable format. - for (EntryIterator it = snapshot->begin(); it != snapshot->end(); ++it) { - switch (it->type) { - case EVENT_FMT_START: - it = handleFormat(FormatEntry(it), ×tamp, &body); - break; - case EVENT_WORK_TIME: { - const int64_t monotonicNs = it.payload(); - body.appendFormat("Thread cycle: %ld ns", (long)monotonicNs); - } break; - case EVENT_LATENCY: { - const double latencyMs = it.payload(); - body.appendFormat("latency: %.3f ms", latencyMs); - } break; - case EVENT_WARMUP_TIME: { - const double timeMs = it.payload(); - body.appendFormat("warmup time: %.3f ms", timeMs); - } break; - case EVENT_UNDERRUN: - body.appendFormat("underrun"); - break; - case EVENT_OVERRUN: - body.appendFormat("overrun"); - break; - case EVENT_FMT_END: - case EVENT_RESERVED: - case EVENT_UPPER_BOUND: - body.appendFormat("warning: unexpected event %d", it->type); - default: - break; - } - if (!body.isEmpty()) { - dprintf(fd, "%.*s%s %s\n", (int)indent, "", timestamp.string(), body.string()); - body.clear(); - } - timestamp.clear(); - } -} - -bool NBLog::Reader::isIMemory(const sp& iMemory) const -{ - return iMemory != 0 && mIMemory != 0 && iMemory->pointer() == mIMemory->pointer(); -} - -void NBLog::DumpReader::appendTimestamp(String8 *body, const void *data) -{ - if (body == nullptr || data == nullptr) { - return; - } - int64_t ts; - memcpy(&ts, data, sizeof(ts)); - body->appendFormat("[%d.%03d]", (int) (ts / (1000 * 1000 * 1000)), - (int) ((ts / (1000 * 1000)) % 1000)); -} - -void NBLog::DumpReader::appendInt(String8 *body, const void *data) -{ - if (body == nullptr || data == nullptr) { - return; - } - int x = *((int*) data); - body->appendFormat("<%d>", x); -} - -void NBLog::DumpReader::appendFloat(String8 *body, const void *data) -{ - if (body == nullptr || data == nullptr) { - return; - } - float f; - memcpy(&f, data, sizeof(f)); - body->appendFormat("<%f>", f); -} - -void NBLog::DumpReader::appendPID(String8 *body, const void* data, size_t length) -{ - if (body == nullptr || data == nullptr) { - return; - } - pid_t id = *((pid_t*) data); - char * name = &((char*) data)[sizeof(pid_t)]; - body->appendFormat("", id, (int) (length - sizeof(pid_t)), name); -} - -String8 NBLog::DumpReader::bufferDump(const uint8_t *buffer, size_t size) -{ - String8 str; - if (buffer == nullptr) { - return str; - } - str.append("[ "); - for(size_t i = 0; i < size; i++) { - str.appendFormat("%d ", buffer[i]); - } - str.append("]"); - return str; -} - -String8 NBLog::DumpReader::bufferDump(const EntryIterator &it) -{ - return bufferDump(it, it->length + Entry::kOverhead); -} - -NBLog::EntryIterator NBLog::DumpReader::handleFormat(const FormatEntry &fmtEntry, - String8 *timestamp, - String8 *body) -{ - // log timestamp - const int64_t ts = fmtEntry.timestamp(); - timestamp->clear(); - timestamp->appendFormat("[%d.%03d]", (int) (ts / (1000 * 1000 * 1000)), - (int) ((ts / (1000 * 1000)) % 1000)); - - // log unique hash - log_hash_t hash = fmtEntry.hash(); - // print only lower 16bit of hash as hex and line as int to reduce spam in the log - body->appendFormat("%.4X-%d ", (int)(hash >> 16) & 0xFFFF, (int) hash & 0xFFFF); - - // log author (if present) - handleAuthor(fmtEntry, body); - - // log string - EntryIterator arg = fmtEntry.args(); - - 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] != '%') { - body->append(&fmt[fmt_offset], 1); // TODO optimize to write consecutive strings at once - continue; - } - // case "%%"" - if (fmt[++fmt_offset] == '%') { - body->append("%"); - continue; - } - // case "%\0" - if (fmt_offset == fmt_length) { - continue; - } - - NBLog::Event event = (NBLog::Event) arg->type; - size_t length = arg->length; - - // TODO check length for event type is correct - - if (event == EVENT_FMT_END) { - break; - } - - // TODO: implement more complex formatting such as %.3f - const uint8_t *datum = arg->data; // pointer to the current event args - switch(fmt[fmt_offset]) - { - case 's': // 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_FMT_TIMESTAMP, - "NBLog Reader incompatible event for timestamp specifier: %d", event); - appendTimestamp(body, datum); - break; - - case 'd': // 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_FMT_FLOAT, - "NBLog Reader incompatible event for float specifier: %d", event); - appendFloat(body, datum); - break; - - case 'p': // pid - ALOGW_IF(event != EVENT_FMT_PID, - "NBLog Reader incompatible event for pid specifier: %d", event); - appendPID(body, datum, length); - break; - - default: - ALOGW("NBLog Reader encountered unknown character %c", fmt[fmt_offset]); - } - ++arg; - } - ALOGW_IF(arg->type != EVENT_FMT_END, "Expected end of format, got %d", arg->type); - return arg; -} - -NBLog::Merger::Merger(const void *shared, size_t size): - 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 sp &reader) -{ - // FIXME This is called by binder thread in MediaLogService::registerWriter - // but the access to shared variable mReaders is not yet protected by a lock. - mReaders.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 -{ - int64_t ts; - int index; - MergeItem(int64_t ts, int index): ts(ts), index(index) {} -}; - -bool operator>(const struct MergeItem &i1, const struct MergeItem &i2) -{ - return i1.ts > i2.ts || (i1.ts == i2.ts && i1.index > i2.index); -} - -// Merge registered readers, sorted by timestamp, and write data to a single FIFO in local memory -void NBLog::Merger::merge() -{ - if (true) return; // Merging is not necessary at the moment, so this is to disable it - // and bypass compiler warnings about member variables not being used. - const int nLogs = mReaders.size(); - std::vector> snapshots(nLogs); - std::vector offsets; - offsets.reserve(nLogs); - for (int i = 0; i < nLogs; ++i) { - snapshots[i] = mReaders[i]->getSnapshot(); - offsets.push_back(snapshots[i]->begin()); - } - // initialize offsets - // TODO custom heap implementation could allow to update top, improving performance - // for bursty buffers - std::priority_queue, std::greater> timestamps; - for (int i = 0; i < nLogs; ++i) - { - if (offsets[i] != snapshots[i]->end()) { - std::unique_ptr abstractEntry = AbstractEntry::buildEntry(offsets[i]); - if (abstractEntry == nullptr) { - continue; - } - timestamps.emplace(abstractEntry->timestamp(), i); - } - } - - while (!timestamps.empty()) { - int index = timestamps.top().index; // find minimum timestamp - // copy it to the log, increasing offset - offsets[index] = AbstractEntry::buildEntry(offsets[index])-> - copyWithAuthor(mFifoWriter, index); - // update data structures - timestamps.pop(); - if (offsets[index] != snapshots[index]->end()) { - int64_t ts = AbstractEntry::buildEntry(offsets[index])->timestamp(); - timestamps.emplace(ts, index); - } - } -} - -const std::vector>& NBLog::Merger::getReaders() const -{ - //AutoMutex _l(mLock); - return mReaders; -} - -// --------------------------------------------------------------------------- - -NBLog::MergeReader::MergeReader(const void *shared, size_t size, Merger &merger) - : Reader(shared, size, "MergeReader"), mReaders(merger.getReaders()) -{ -} - -void NBLog::MergeReader::handleAuthor(const NBLog::AbstractEntry &entry, String8 *body) -{ - int author = entry.author(); - if (author == -1) { - return; - } - // FIXME Needs a lock - const char* name = mReaders[author]->name().c_str(); - body->appendFormat("%s: ", name); -} - -// --------------------------------------------------------------------------- - -NBLog::MergeThread::MergeThread(NBLog::Merger &merger, NBLog::MergeReader &mergeReader) - : mMerger(merger), - mMergeReader(mergeReader), - mTimeoutUs(0) -{ -} - -NBLog::MergeThread::~MergeThread() -{ - // set exit flag, set timeout to 0 to force threadLoop to exit and wait for the thread to join - requestExit(); - setTimeoutUs(0); - join(); -} - -bool NBLog::MergeThread::threadLoop() -{ - bool doMerge; - { - AutoMutex _l(mMutex); - // If mTimeoutUs is negative, wait on the condition variable until it's positive. - // If it's positive, merge. The minimum period between waking the condition variable - // is handled in AudioFlinger::MediaLogNotifier::threadLoop(). - mCond.wait(mMutex); - doMerge = mTimeoutUs > 0; - mTimeoutUs -= kThreadSleepPeriodUs; - } - if (doMerge) { - // Merge data from all the readers - mMerger.merge(); - // Process the data collected by mMerger and write it to PerformanceAnalysis - // FIXME: decide whether to call getAndProcessSnapshot every time - // or whether to have a separate thread that calls it with a lower frequency - mMergeReader.getAndProcessSnapshot(); - } - return true; -} - -void NBLog::MergeThread::wakeup() -{ - setTimeoutUs(kThreadWakeupPeriodUs); -} - -void NBLog::MergeThread::setTimeoutUs(int time) -{ - AutoMutex _l(mMutex); - mTimeoutUs = time; - mCond.signal(); -} - -} // namespace android diff --git a/media/libnblog/PerformanceAnalysis.cpp b/media/libnblog/PerformanceAnalysis.cpp index ca9bc2c2ae..c6b5b3f31d 100644 --- a/media/libnblog/PerformanceAnalysis.cpp +++ b/media/libnblog/PerformanceAnalysis.cpp @@ -47,7 +47,6 @@ #include namespace android { - namespace ReportPerformance { void Histogram::add(double value) @@ -367,5 +366,4 @@ void dumpLine(int fd, int indent, const String8 &body) { } } // namespace ReportPerformance - } // namespace android diff --git a/media/libnblog/Reader.cpp b/media/libnblog/Reader.cpp new file mode 100644 index 0000000000..f86bb99949 --- /dev/null +++ b/media/libnblog/Reader.cpp @@ -0,0 +1,421 @@ +/* + * Copyright (C) 2018 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#define LOG_TAG "NBLog" +//#define LOG_NDEBUG 0 + +#include +#include +#include +#include + +#include +#include +#include +#include +#include +#include +#include +#include + +namespace android { +namespace NBLog { + +Reader::Reader(const void *shared, size_t size, const std::string &name) + : mName(name), + mShared((/*const*/ Shared *) shared), /*mIMemory*/ + mFifo(mShared != NULL ? + new audio_utils_fifo(size, sizeof(uint8_t), + mShared->mBuffer, mShared->mRear, NULL /*throttlesFront*/) : NULL), + mFifoReader(mFifo != NULL ? new audio_utils_fifo_reader(*mFifo) : NULL) +{ +} + +Reader::Reader(const sp& iMemory, size_t size, const std::string &name) + : Reader(iMemory != 0 ? (Shared *) iMemory->pointer() : NULL, size, name) +{ + mIMemory = iMemory; +} + +Reader::~Reader() +{ + delete mFifoReader; + delete mFifo; +} + +// Copies content of a Reader FIFO into its Snapshot +// The Snapshot has the same raw data, but represented as a sequence of entries +// and an EntryIterator making it possible to process the data. +std::unique_ptr Reader::getSnapshot() +{ + if (mFifoReader == NULL) { + return std::unique_ptr(new Snapshot()); + } + + // This emulates the behaviour of audio_utils_fifo_reader::read, but without incrementing the + // reader index. The index is incremented after handling corruption, to after the last complete + // entry of the buffer + size_t lost = 0; + audio_utils_iovec iovec[2]; + const size_t capacity = mFifo->capacity(); + ssize_t availToRead; + // A call to audio_utils_fifo_reader::obtain() places the read pointer one buffer length + // before the writer's pointer (since mFifoReader was constructed with flush=false). The + // do while loop is an attempt to read all of the FIFO's contents regardless of how behind + // the reader is with respect to the writer. However, the following scheduling sequence is + // possible and can lead to a starvation situation: + // - Writer T1 writes, overrun with respect to Reader T2 + // - T2 calls obtain() and gets EOVERFLOW, T2 ptr placed one buffer size behind T1 ptr + // - T1 write, overrun + // - T2 obtain(), EOVERFLOW (and so on...) + // To address this issue, we limit the number of tries for the reader to catch up with + // the writer. + int tries = 0; + size_t lostTemp; + do { + availToRead = mFifoReader->obtain(iovec, capacity, NULL /*timeout*/, &lostTemp); + lost += lostTemp; + } while (availToRead < 0 || ++tries <= kMaxObtainTries); + + if (availToRead <= 0) { + ALOGW_IF(availToRead < 0, "NBLog Reader %s failed to catch up with Writer", mName.c_str()); + return std::unique_ptr(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(new Snapshot(availToRead)); + memcpy(snapshot->mData, (const char *) mFifo->buffer() + iovec[0].mOffset, iovec[0].mLength); + if (iovec[1].mLength > 0) { + memcpy(snapshot->mData + (iovec[0].mLength), + (const char *) mFifo->buffer() + iovec[1].mOffset, iovec[1].mLength); + } + + // 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 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 FMT_END. 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 FMT_END entry + snapshot->mEnd = EntryIterator(lastEnd).next(); + // find first FMT_START + const uint8_t *firstStart = nullptr; + const uint8_t *firstStartTmp = snapshot->mEnd; + while ((firstStartTmp = findLastValidEntry(front, firstStartTmp, invalidBeginTypes)) + != nullptr) { + firstStart = firstStartTmp; + } + // firstStart is null if no FMT_START entry was found before lastEnd + if (firstStart == nullptr) { + snapshot->mBegin = snapshot->mEnd; + } else { + snapshot->mBegin = EntryIterator(firstStart); + } + } + + // advance fifo reader index to after last entry read. + mFifoReader->release(snapshot->mEnd - front); + + snapshot->mLost = lost; + return snapshot; +} + +bool Reader::isIMemory(const sp& iMemory) const +{ + return iMemory != 0 && mIMemory != 0 && iMemory->pointer() == mIMemory->pointer(); +} + +// 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 Event +// type to the two sets below whenever a new 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 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 Reader::invalidBeginTypes { + EVENT_FMT_AUTHOR, + EVENT_FMT_END, + EVENT_FMT_FLOAT, + EVENT_FMT_HASH, + EVENT_FMT_INTEGER, + EVENT_FMT_PID, + EVENT_FMT_STRING, + EVENT_FMT_TIMESTAMP, +}; + +// 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 Reader::invalidEndTypes { + EVENT_FMT_AUTHOR, + EVENT_FMT_FLOAT, + EVENT_FMT_HASH, + EVENT_FMT_INTEGER, + EVENT_FMT_PID, + EVENT_FMT_START, + EVENT_FMT_STRING, + EVENT_FMT_TIMESTAMP, +}; + +const uint8_t *Reader::findLastValidEntry(const uint8_t *front, const uint8_t *back, + const std::unordered_set &invalidTypes) { + if (front == nullptr || back == nullptr) { + return nullptr; + } + while (back + Entry::kPreviousLengthOffset >= front) { + const uint8_t *prev = back - back[Entry::kPreviousLengthOffset] - Entry::kOverhead; + const Event type = (const Event)prev[offsetof(entry, type)]; + if (prev < front + || prev + prev[offsetof(entry, length)] + Entry::kOverhead != back + || type <= EVENT_RESERVED || type >= EVENT_UPPER_BOUND) { + // prev points to an out of limits or inconsistent entry + return nullptr; + } + // if invalidTypes does not contain the type, then the type is valid. + if (invalidTypes.find(type) == invalidTypes.end()) { + return prev; + } + back = prev; + } + return nullptr; // no entry found +} + +// TODO for future compatibility, would prefer to have a dump() go to string, and then go +// to fd only when invoked through binder. +void DumpReader::dump(int fd, size_t indent) +{ + if (fd < 0) return; + std::unique_ptr snapshot = getSnapshot(); + if (snapshot == nullptr) { + return; + } + String8 timestamp, body; + + // TODO all logged types should have a printable format. + for (EntryIterator it = snapshot->begin(); it != snapshot->end(); ++it) { + switch (it->type) { + case EVENT_FMT_START: + it = handleFormat(FormatEntry(it), ×tamp, &body); + break; + case EVENT_WORK_TIME: { + const int64_t monotonicNs = it.payload(); + body.appendFormat("Thread cycle: %ld ns", (long)monotonicNs); + } break; + case EVENT_LATENCY: { + const double latencyMs = it.payload(); + body.appendFormat("latency: %.3f ms", latencyMs); + } break; + case EVENT_WARMUP_TIME: { + const double timeMs = it.payload(); + body.appendFormat("warmup time: %.3f ms", timeMs); + } break; + case EVENT_UNDERRUN: + body.appendFormat("underrun"); + break; + case EVENT_OVERRUN: + body.appendFormat("overrun"); + break; + case EVENT_FMT_END: + case EVENT_RESERVED: + case EVENT_UPPER_BOUND: + body.appendFormat("warning: unexpected event %d", it->type); + default: + break; + } + if (!body.isEmpty()) { + dprintf(fd, "%.*s%s %s\n", (int)indent, "", timestamp.string(), body.string()); + body.clear(); + } + timestamp.clear(); + } +} + +EntryIterator DumpReader::handleFormat(const FormatEntry &fmtEntry, + String8 *timestamp, String8 *body) +{ + // log timestamp + const int64_t ts = fmtEntry.timestamp(); + timestamp->clear(); + timestamp->appendFormat("[%d.%03d]", (int) (ts / (1000 * 1000 * 1000)), + (int) ((ts / (1000 * 1000)) % 1000)); + + // log unique hash + log_hash_t hash = fmtEntry.hash(); + // print only lower 16bit of hash as hex and line as int to reduce spam in the log + body->appendFormat("%.4X-%d ", (int)(hash >> 16) & 0xFFFF, (int) hash & 0xFFFF); + + // log author (if present) + handleAuthor(fmtEntry, body); + + // log string + EntryIterator arg = fmtEntry.args(); + + 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] != '%') { + body->append(&fmt[fmt_offset], 1); // TODO optimize to write consecutive strings at once + continue; + } + // case "%%"" + if (fmt[++fmt_offset] == '%') { + body->append("%"); + continue; + } + // case "%\0" + if (fmt_offset == fmt_length) { + continue; + } + + Event event = (Event) arg->type; + size_t length = arg->length; + + // TODO check length for event type is correct + + if (event == EVENT_FMT_END) { + break; + } + + // TODO: implement more complex formatting such as %.3f + const uint8_t *datum = arg->data; // pointer to the current event args + switch(fmt[fmt_offset]) + { + case 's': // 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_FMT_TIMESTAMP, + "NBLog Reader incompatible event for timestamp specifier: %d", event); + appendTimestamp(body, datum); + break; + + case 'd': // 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_FMT_FLOAT, + "NBLog Reader incompatible event for float specifier: %d", event); + appendFloat(body, datum); + break; + + case 'p': // pid + ALOGW_IF(event != EVENT_FMT_PID, + "NBLog Reader incompatible event for pid specifier: %d", event); + appendPID(body, datum, length); + break; + + default: + ALOGW("NBLog Reader encountered unknown character %c", fmt[fmt_offset]); + } + ++arg; + } + ALOGW_IF(arg->type != EVENT_FMT_END, "Expected end of format, got %d", arg->type); + return arg; +} + +void DumpReader::appendInt(String8 *body, const void *data) +{ + if (body == nullptr || data == nullptr) { + return; + } + //int x = *((int*) data); + int x; + memcpy(&x, data, sizeof(x)); + body->appendFormat("<%d>", x); +} + +void DumpReader::appendFloat(String8 *body, const void *data) +{ + if (body == nullptr || data == nullptr) { + return; + } + float f; + memcpy(&f, data, sizeof(f)); + body->appendFormat("<%f>", f); +} + +void DumpReader::appendPID(String8 *body, const void* data, size_t length) +{ + if (body == nullptr || data == nullptr) { + return; + } + pid_t id = *((pid_t*) data); + char * name = &((char*) data)[sizeof(pid_t)]; + body->appendFormat("", id, (int) (length - sizeof(pid_t)), name); +} + +void DumpReader::appendTimestamp(String8 *body, const void *data) +{ + if (body == nullptr || data == nullptr) { + return; + } + int64_t ts; + memcpy(&ts, data, sizeof(ts)); + body->appendFormat("[%d.%03d]", (int) (ts / (1000 * 1000 * 1000)), + (int) ((ts / (1000 * 1000)) % 1000)); +} + +String8 DumpReader::bufferDump(const uint8_t *buffer, size_t size) +{ + String8 str; + if (buffer == nullptr) { + return str; + } + str.append("[ "); + for(size_t i = 0; i < size; i++) { + str.appendFormat("%d ", buffer[i]); + } + str.append("]"); + return str; +} + +String8 DumpReader::bufferDump(const EntryIterator &it) +{ + return bufferDump(it, it->length + Entry::kOverhead); +} + +} // namespace NBLog +} // namespace android diff --git a/media/libnblog/ReportPerformance.cpp b/media/libnblog/ReportPerformance.cpp index aab67c6317..bf8a1dcee1 100644 --- a/media/libnblog/ReportPerformance.cpp +++ b/media/libnblog/ReportPerformance.cpp @@ -15,6 +15,7 @@ */ #define LOG_TAG "ReportPerformance" +//#define LOG_NDEBUG 0 #include #include @@ -30,23 +31,22 @@ #include #include #include -#include +#include #include #include #include #include namespace android { - namespace ReportPerformance { std::unique_ptr dumpToJson(const PerformanceData& data) { std::unique_ptr rootPtr = std::make_unique(Json::objectValue); Json::Value& root = *rootPtr; - root["type"] = data.type; - root["frameCount"] = (Json::Value::Int)data.frameCount; - root["sampleRate"] = (Json::Value::Int)data.sampleRate; + root["type"] = (Json::Value::Int)data.threadInfo.type; + root["frameCount"] = (Json::Value::Int)data.threadInfo.frameCount; + root["sampleRate"] = (Json::Value::Int)data.threadInfo.sampleRate; root["workMsHist"] = data.workHist.toString(); root["latencyMsHist"] = data.latencyHist.toString(); root["warmupMsHist"] = data.warmupHist.toString(); @@ -102,15 +102,10 @@ bool sendToMediaMetrics(const PerformanceData& data) // we want to send them only if there are performance metrics to send. if (item->count() > 0) { // Add thread info fields. - const int type = data.type; - // TODO have a int-to-string mapping defined somewhere else for other thread types. - if (type == 2) { - item->setCString(kThreadType, "FASTMIXER"); - } else { - item->setCString(kThreadType, "UNKNOWN"); - } - item->setInt32(kThreadFrameCount, data.frameCount); - item->setInt32(kThreadSampleRate, data.sampleRate); + const char * const typeString = NBLog::threadTypeToString(data.threadInfo.type); + item->setCString(kThreadType, typeString); + item->setInt32(kThreadFrameCount, data.threadInfo.frameCount); + item->setInt32(kThreadSampleRate, data.threadInfo.sampleRate); // Add time info fields. item->setInt64(kThreadActive, data.active / 1000000); item->setInt64(kThreadDuration, (systemTime() - data.start) / 1000000); @@ -211,6 +206,5 @@ void writeToFile(const std::deque> &hists, pfs.close(); } -} // namespace ReportPerformance - +} // namespace ReportPerformance } // namespace android diff --git a/media/libnblog/Timeline.cpp b/media/libnblog/Timeline.cpp new file mode 100644 index 0000000000..c09b03bf3a --- /dev/null +++ b/media/libnblog/Timeline.cpp @@ -0,0 +1,50 @@ +/* + * Copyright (C) 2018 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#include + +#include +#include + +namespace android { +namespace NBLog { + +#if 0 // FIXME see note in Timeline.h +NBLog::Timeline::Timeline(size_t size, void *shared) + : mSize(roundup(size)), mOwn(shared == NULL), + mShared((Shared *) (mOwn ? new char[sharedSize(size)] : shared)) +{ + new (mShared) Shared; +} + +NBLog::Timeline::~Timeline() +{ + mShared->~Shared(); + if (mOwn) { + delete[] (char *) mShared; + } +} +#endif + +/*static*/ +size_t Timeline::sharedSize(size_t size) +{ + // TODO fifo now supports non-power-of-2 buffer sizes, so could remove the roundup + return sizeof(Shared) + roundup(size); +} + +} // namespace NBLog +} // namespace android diff --git a/media/libnblog/Writer.cpp b/media/libnblog/Writer.cpp new file mode 100644 index 0000000000..da3bd52a50 --- /dev/null +++ b/media/libnblog/Writer.cpp @@ -0,0 +1,320 @@ +/* + * Copyright (C) 2018 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#define LOG_TAG "NBLog" +//#define LOG_NDEBUG 0 + +#include +#include +#include + +#include +#include +#include +#include +#include +#include +#include +#include + +namespace android { +namespace NBLog { + +Writer::Writer(void *shared, size_t size) + : 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), + mEnabled(mFifoWriter != NULL) +{ + // caching pid and process name + pid_t id = ::getpid(); + char procName[16]; + int status = prctl(PR_GET_NAME, procName); + if (status) { // error getting process name + procName[0] = '\0'; + } + size_t length = strlen(procName); + mPidTagSize = length + sizeof(pid_t); + mPidTag = new char[mPidTagSize]; + memcpy(mPidTag, &id, sizeof(pid_t)); + memcpy(mPidTag + sizeof(pid_t), procName, length); +} + +Writer::Writer(const sp& iMemory, size_t size) + : Writer(iMemory != 0 ? (Shared *) iMemory->pointer() : NULL, size) +{ + mIMemory = iMemory; +} + +Writer::~Writer() +{ + delete mFifoWriter; + delete mFifo; + delete[] mPidTag; +} + +void Writer::log(const char *string) +{ + if (!mEnabled) { + return; + } + LOG_ALWAYS_FATAL_IF(string == NULL, "Attempted to log NULL string"); + size_t length = strlen(string); + if (length > Entry::kMaxLength) { + length = Entry::kMaxLength; + } + log(EVENT_STRING, string, length); +} + +void Writer::logf(const char *fmt, ...) +{ + if (!mEnabled) { + return; + } + va_list ap; + va_start(ap, fmt); + Writer::logvf(fmt, ap); // the Writer:: is needed to avoid virtual dispatch for LockedWriter + va_end(ap); +} + +void Writer::logTimestamp() +{ + if (!mEnabled) { + return; + } + struct timespec ts; + if (!clock_gettime(CLOCK_MONOTONIC, &ts)) { + log(EVENT_TIMESTAMP, &ts, sizeof(ts)); + } +} + +void Writer::logFormat(const char *fmt, log_hash_t hash, ...) +{ + if (!mEnabled) { + return; + } + va_list ap; + va_start(ap, hash); + Writer::logVFormat(fmt, hash, ap); + va_end(ap); +} + +void Writer::logEventHistTs(Event event, log_hash_t hash) +{ + if (!mEnabled) { + return; + } + HistTsEntry data; + data.hash = hash; + data.ts = systemTime(); + if (data.ts > 0) { + log(event, &data, sizeof(data)); + } else { + ALOGE("Failed to get timestamp"); + } +} + +bool Writer::isEnabled() const +{ + return mEnabled; +} + +bool Writer::setEnabled(bool enabled) +{ + bool old = mEnabled; + mEnabled = enabled && mShared != NULL; + return old; +} + +void Writer::log(const Entry &etr, bool trusted) +{ + if (!mEnabled) { + return; + } + if (!trusted) { + log(etr.mEvent, etr.mData, etr.mLength); + return; + } + const size_t need = etr.mLength + Entry::kOverhead; // mEvent, mLength, data[mLength], mLength + // need = number of bytes written to FIFO + + // FIXME optimize this using memcpy for the data part of the Entry. + // The Entry could have a method copyTo(ptr, offset, size) to optimize the copy. + // checks size of a single log Entry: type, length, data pointer and ending + uint8_t temp[Entry::kMaxLength + Entry::kOverhead]; + // write this data to temp array + for (size_t i = 0; i < need; i++) { + temp[i] = etr.copyEntryDataAt(i); + } + // write to circular buffer + mFifoWriter->write(temp, need); +} + +void Writer::log(Event event, const void *data, size_t length) +{ + if (!mEnabled) { + return; + } + if (data == NULL || length > Entry::kMaxLength) { + // TODO Perhaps it makes sense to display truncated data or at least a + // message that the data is too long? The current behavior can create + // a confusion for a programmer debugging their code. + return; + } + // Ignore if invalid event + if (event == EVENT_RESERVED || event >= EVENT_UPPER_BOUND) { + return; + } + Entry etr(event, data, length); + log(etr, true /*trusted*/); +} + +void Writer::logvf(const char *fmt, va_list ap) +{ + if (!mEnabled) { + return; + } + char buffer[Entry::kMaxLength + 1 /*NUL*/]; + int length = vsnprintf(buffer, sizeof(buffer), fmt, ap); + if (length >= (int) sizeof(buffer)) { + length = sizeof(buffer) - 1; + // NUL termination is not required + // buffer[length] = '\0'; + } + if (length >= 0) { + log(EVENT_STRING, buffer, length); + } +} + +void Writer::logStart(const char *fmt) +{ + if (!mEnabled) { + return; + } + size_t length = strlen(fmt); + if (length > Entry::kMaxLength) { + length = Entry::kMaxLength; + } + log(EVENT_FMT_START, fmt, length); +} + +void Writer::logTimestampFormat() +{ + if (!mEnabled) { + return; + } + const nsecs_t ts = systemTime(); + if (ts > 0) { + log(EVENT_FMT_TIMESTAMP, &ts, sizeof(ts)); + } else { + ALOGE("Failed to get timestamp"); + } +} + +void Writer::logVFormat(const char *fmt, log_hash_t hash, va_list argp) +{ + if (!mEnabled) { + return; + } + Writer::logStart(fmt); + int i; + double d; + float f; + char* s; + size_t length; + int64_t t; + 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 != '%') { + continue; + } + switch(*++p) { + case 's': // string + s = va_arg(argp, char *); + 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); + log(EVENT_FMT_TIMESTAMP, &t, sizeof(t)); + break; + + case 'd': // integer + i = va_arg(argp, int); + log(EVENT_FMT_INTEGER, &i, sizeof(i)); + break; + + case 'f': // float + 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 + log(EVENT_FMT_PID, mPidTag, mPidTagSize); + break; + + // the "%\0" case finishes parsing + case '\0': + --p; + break; + + case '%': + break; + + default: + ALOGW("NBLog Writer parsed invalid format specifier: %c", *p); + break; + } + } + Entry etr(EVENT_FMT_END, nullptr, 0); + log(etr, true); +} + +// --------------------------------------------------------------------------- + +LockedWriter::LockedWriter(void *shared, size_t size) + : Writer(shared, size) +{ +} + +bool LockedWriter::isEnabled() const +{ + Mutex::Autolock _l(mLock); + return Writer::isEnabled(); +} + +bool LockedWriter::setEnabled(bool enabled) +{ + Mutex::Autolock _l(mLock); + return Writer::setEnabled(enabled); +} + +void LockedWriter::log(const Entry &entry, bool trusted) { + Mutex::Autolock _l(mLock); + Writer::log(entry, trusted); +} + +} // namespace NBLog +} // namespace android diff --git a/media/libnblog/include/media/nblog/Entry.h b/media/libnblog/include/media/nblog/Entry.h new file mode 100644 index 0000000000..53f00b6b23 --- /dev/null +++ b/media/libnblog/include/media/nblog/Entry.h @@ -0,0 +1,232 @@ +/* + * Copyright (C) 2018 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#ifndef ANDROID_MEDIA_NBLOG_ENTRY_H +#define ANDROID_MEDIA_NBLOG_ENTRY_H + +#include +#include +#include +#include + +#include + +class audio_utils_fifo_writer; + +namespace android { +namespace NBLog { + +// entry representation in memory +struct entry { + const uint8_t type; + const uint8_t length; + const uint8_t data[0]; +}; + +// entry tail representation (after data) +struct ending { + uint8_t length; + uint8_t next[0]; +}; + +// representation of a single log entry in shared memory +// byte[0] mEvent +// byte[1] mLength +// byte[2] mData[0] +// ... +// byte[2+i] mData[i] +// ... +// byte[2+mLength-1] mData[mLength-1] +// byte[2+mLength] duplicate copy of mLength to permit reverse scan +// byte[3+mLength] start of next log entry +class Entry { +public: + Entry(Event event, const void *data, size_t length) + : mEvent(event), mLength(length), mData(data) {} + ~Entry() {} + + // used during writing to format Entry information as follows: + // [type][length][data ... ][length] + int copyEntryDataAt(size_t offset) const; + +private: + friend class Writer; + Event mEvent; // event type + uint8_t mLength; // length of additional data, 0 <= mLength <= kMaxLength + const void *mData; // event type-specific data + static const size_t kMaxLength = 255; +public: + // mEvent, mLength, mData[...], duplicate mLength + static const size_t kOverhead = sizeof(entry) + sizeof(ending); + // endind length of previous entry + static const ssize_t kPreviousLengthOffset = - sizeof(ending) + + offsetof(ending, length); +}; + +// entry iterator +class EntryIterator { +public: + // Used for dummy initialization. Performing operations on a default-constructed + // EntryIterator other than assigning it to another valid EntryIterator + // is undefined behavior. + EntryIterator(); + // Caller's responsibility to make sure entry is not nullptr. + // Passing in nullptr can result in undefined behavior. + explicit EntryIterator(const uint8_t *entry); + EntryIterator(const EntryIterator &other); + + // dereference underlying entry + const entry& operator*() const; + const entry* operator->() const; + // advance to next entry + EntryIterator& operator++(); // ++i + // back to previous entry + EntryIterator& operator--(); // --i + // returns an EntryIterator corresponding to the next entry + EntryIterator next() const; + // returns an EntryIterator corresponding to the previous entry + EntryIterator prev() const; + bool operator!=(const EntryIterator &other) const; + int operator-(const EntryIterator &other) const; + + bool hasConsistentLength() const; + void copyTo(std::unique_ptr &dst) const; + void copyData(uint8_t *dst) const; + + // memcpy preferred to reinterpret_cast to avoid potentially unsupported + // unaligned memory access. +#if 0 + template + inline const T& payload() { + return *reinterpret_cast(mPtr + offsetof(entry, data)); + } +#else + template + inline T payload() const { + static_assert(std::is_trivially_copyable::value + && !std::is_pointer::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; + } + +private: + const uint8_t *mPtr; // Should not be nullptr except for dummy initialization +}; + +// --------------------------------------------------------------------------- +// The following classes are used for merging into the Merger's buffer. + +class AbstractEntry { +public: + virtual ~AbstractEntry() {} + + // build concrete entry of appropriate class from ptr. + static std::unique_ptr buildEntry(const uint8_t *ptr); + + // get format entry timestamp + virtual int64_t timestamp() const = 0; + + // get format entry's unique id + virtual log_hash_t hash() const = 0; + + // entry's author index (-1 if none present) + // a Merger has a vector of Readers, author simply points to the index of the + // Reader that originated the entry + // TODO consider changing to uint32_t + virtual int author() const = 0; + + // copy entry, adding author before timestamp, returns iterator to end of entry + virtual EntryIterator copyWithAuthor(std::unique_ptr &dst, + int author) const = 0; + +protected: + // Entry starting in the given pointer, which shall not be nullptr. + explicit AbstractEntry(const uint8_t *entry) : mEntry(entry) {} + // copies ordinary entry from src to dst, and returns length of entry + // size_t copyEntry(audio_utils_fifo_writer *dst, const iterator &it); + const uint8_t * const mEntry; +}; + +// API for handling format entry operations + +// a formatted entry has the following structure: +// * 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 +// * ... +// * FMT_END entry +class FormatEntry : public AbstractEntry { +public: + // explicit FormatEntry(const EntryIterator &it); + explicit FormatEntry(const uint8_t *ptr) : AbstractEntry(ptr) {} + ~FormatEntry() override = default; + + EntryIterator begin() const; + + // 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) + EntryIterator args() const; + + // get format entry timestamp + int64_t timestamp() const override; + + // get format entry's unique id + log_hash_t hash() const override; + + // entry's author index (-1 if none present) + // a Merger has a vector of Readers, author simply points to the index of the + // Reader that originated the entry + int author() const override; + + // copy entry, adding author before timestamp, returns size of original entry + EntryIterator copyWithAuthor(std::unique_ptr &dst, + int author) const override; +}; + +class HistogramEntry : public AbstractEntry { +public: + explicit HistogramEntry(const uint8_t *ptr) : AbstractEntry(ptr) {} + ~HistogramEntry() override = default; + + int64_t timestamp() const override; + + log_hash_t hash() const override; + + int author() const override; + + EntryIterator copyWithAuthor(std::unique_ptr &dst, + int author) const override; +}; + +} // namespace NBLog +} // namespace android + +#endif // ANDROID_MEDIA_NBLOG_ENTRY_H diff --git a/media/libnblog/include/media/nblog/Events.h b/media/libnblog/include/media/nblog/Events.h new file mode 100644 index 0000000000..9212ce45ee --- /dev/null +++ b/media/libnblog/include/media/nblog/Events.h @@ -0,0 +1,142 @@ +/* + * Copyright (C) 2018 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#ifndef ANDROID_MEDIA_NBLOG_EVENTS_H +#define ANDROID_MEDIA_NBLOG_EVENTS_H + +#include +#include +#include + +namespace android { +namespace NBLog { + +// 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. +// XXX Note that as of the current design, Events should not be renumbered (i.e. reordered) +// if they ever leave memory (for example, written to file, uploaded to cloud, etc.). +// TODO make some sort of interface to keep these "contract" constants. +enum Event : uint8_t { + EVENT_RESERVED, + EVENT_STRING, // ASCII string, not NUL-terminated + // TODO: make timestamp optional + EVENT_TIMESTAMP, // clock_gettime(CLOCK_MONOTONIC) + + // Types for Format Entry, i.e. formatted entry + EVENT_FMT_START, // logFormat start event: entry includes format string, + // following entries contain format arguments + // format arguments + EVENT_FMT_AUTHOR, // author index (present in merged logs) tracks entry's + // original log + EVENT_FMT_FLOAT, // floating point value entry + EVENT_FMT_HASH, // unique HASH of log origin, originates from hash of file name + // and line number + EVENT_FMT_INTEGER, // integer value entry + EVENT_FMT_PID, // process ID and process name + EVENT_FMT_STRING, // string value entry + EVENT_FMT_TIMESTAMP, // timestamp value entry + // end of format arguments + EVENT_FMT_END, // end of logFormat argument list + + // Types for wakeup timestamp histograms + EVENT_AUDIO_STATE, // audio on/off event: logged on FastMixer::onStateChange call + EVENT_HISTOGRAM_ENTRY_TS, // single datum for timestamp histogram + + // Types representing audio performance metrics + EVENT_LATENCY, // difference between frames presented by HAL and frames + // written to HAL output sink, divided by sample rate. + EVENT_OVERRUN, // predicted thread overrun event timestamp + EVENT_THREAD_INFO, // thread type, frameCount and sampleRate, which give context + // for the metrics below. + EVENT_UNDERRUN, // predicted thread underrun event timestamp + EVENT_WARMUP_TIME, // thread warmup time + EVENT_WORK_TIME, // the time a thread takes to do work, e.g. read, write, etc. + + EVENT_UPPER_BOUND, // to check for invalid events +}; + +// NBLog custom-defined structs. Some NBLog Event types map to these structs. + +using log_hash_t = uint64_t; + +// used for EVENT_HISTOGRAM_ENTRY_TS (not mapped) +struct HistTsEntry { + log_hash_t hash; + int64_t ts; +}; //TODO __attribute__((packed)); + +// used for EVENT_HISTOGRAM_ENTRY_TS (not mapped) +struct HistTsEntryWithAuthor { + log_hash_t hash; + int64_t ts; + int author; +}; //TODO __attribute__((packed)); + +enum ThreadType { + UNKNOWN, + MIXER, + CAPTURE, + FASTMIXER, + FASTCAPTURE, +}; + +inline const char *threadTypeToString(ThreadType type) { + switch (type) { + case MIXER: + return "MIXER"; + case CAPTURE: + return "CAPTURE"; + case FASTMIXER: + return "FASTMIXER"; + case FASTCAPTURE: + return "FASTCAPTURE"; + case UNKNOWN: + default: + return "UNKNOWN"; + } +} + +// mapped from EVENT_THREAD_INFO +struct thread_info_t { + ThreadType type; + size_t frameCount; // number of frames per read or write buffer + unsigned sampleRate; // in frames per second +}; + +template struct get_mapped; +#define MAP_EVENT_TO_TYPE(E, T) \ +template<> struct get_mapped { \ + static_assert(std::is_trivially_copyable::value \ + && !std::is_pointer::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_OVERRUN, int64_t); +MAP_EVENT_TO_TYPE(EVENT_THREAD_INFO, thread_info_t); +MAP_EVENT_TO_TYPE(EVENT_UNDERRUN, int64_t); +MAP_EVENT_TO_TYPE(EVENT_WARMUP_TIME, double); +MAP_EVENT_TO_TYPE(EVENT_WORK_TIME, int64_t); + +} // namespace NBLog +} // namespace android + +#endif // ANDROID_MEDIA_NBLOG_EVENTS_H diff --git a/media/libnblog/include/media/nblog/Merger.h b/media/libnblog/include/media/nblog/Merger.h new file mode 100644 index 0000000000..ac63a7e450 --- /dev/null +++ b/media/libnblog/include/media/nblog/Merger.h @@ -0,0 +1,154 @@ +/* + * Copyright (C) 2018 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#ifndef ANDROID_MEDIA_NBLOG_MERGER_H +#define ANDROID_MEDIA_NBLOG_MERGER_H + +#include +#include +#include +#include + +#include +#include +#include +#include +#include +#include +#include + +namespace android { + +class String8; + +namespace NBLog { + +struct Shared; + +// TODO update comments to reflect current functionalities + +// This class is used to read data from each thread's individual FIFO in shared memory +// and write it to a single FIFO in local memory. +class Merger : public RefBase { +public: + Merger(const void *shared, size_t size); + + ~Merger() override = default; + + void addReader(const sp &reader); + // TODO add removeReader + void merge(); + + // FIXME This is returning a reference to a shared variable that needs a lock + const std::vector>& getReaders() const; + +private: + // vector of the readers the merger is supposed to merge from. + // every reader reads from a writer's buffer + // FIXME Needs to be protected by a lock + std::vector> mReaders; + + Shared * const mShared; // raw pointer to shared memory + std::unique_ptr mFifo; // FIFO itself + std::unique_ptr mFifoWriter; // used to write to FIFO +}; + +// This class has a pointer to the FIFO in local memory which stores the merged +// data collected by NBLog::Merger from all Readers. It is used to process +// this data and write the result to PerformanceAnalysis. +class MergeReader : public Reader { +public: + MergeReader(const void *shared, size_t size, Merger &merger); + + // process a particular snapshot of the reader + void processSnapshot(Snapshot &snap, int author); + + // call getSnapshot of the content of the reader's buffer and process the data + void getAndProcessSnapshot(); + + // check for periodic push of performance data to media metrics, and perform + // the send if it is time to do so. + void checkPushToMediaMetrics(); + + void dump(int fd, int indent = 0); + +private: + // FIXME Needs to be protected by a lock, + // because even though our use of it is read-only there may be asynchronous updates + // The object is owned by the Merger class. + const std::vector>& mReaders; + + // analyzes, compresses and stores the merged data + // contains a separate instance for every author (thread), and for every source file + // location within each author + ReportPerformance::PerformanceAnalysisMap mThreadPerformanceAnalysis; + + // compresses and stores audio performance data from each thread's buffers. + // first parameter is author, i.e. thread index. + std::map mThreadPerformanceData; + + // how often to push data to Media Metrics + static constexpr nsecs_t kPeriodicMediaMetricsPush = s2ns((nsecs_t)2 * 60 * 60); // 2 hours + + // handle author entry by looking up the author's name and appending it to the body + // returns number of bytes read from fmtEntry + void handleAuthor(const AbstractEntry &fmtEntry, String8 *body); +}; + +// MergeThread is a thread that contains a Merger. It works as a retriggerable one-shot: +// when triggered, it awakes for a lapse of time, during which it periodically merges; if +// retriggered, the timeout is reset. +// The thread is triggered on AudioFlinger binder activity. +class MergeThread : public Thread { +public: + MergeThread(Merger &merger, MergeReader &mergeReader); + ~MergeThread() override; + + // Reset timeout and activate thread to merge periodically if it's idle + void wakeup(); + + // Set timeout period until the merging thread goes idle again + void setTimeoutUs(int time); + +private: + bool threadLoop() override; + + // the merger who actually does the work of merging the logs + Merger& mMerger; + + // the mergereader used to process data merged by mMerger + MergeReader& mMergeReader; + + // mutex for the condition variable + Mutex mMutex; + + // condition variable to activate merging on timeout >= 0 + Condition mCond; + + // time left until the thread blocks again (in microseconds) + int mTimeoutUs; + + // merging period when the thread is awake + static const int kThreadSleepPeriodUs = 1000000 /*1s*/; + + // initial timeout value when triggered + static const int kThreadWakeupPeriodUs = 3000000 /*3s*/; +}; + +} // namespace NBLog +} // namespace android + +#endif // ANDROID_MEDIA_NBLOG_MERGER_H diff --git a/media/libnblog/include/media/nblog/NBLog.h b/media/libnblog/include/media/nblog/NBLog.h index e43b0262c5..fd73538df0 100644 --- a/media/libnblog/include/media/nblog/NBLog.h +++ b/media/libnblog/include/media/nblog/NBLog.h @@ -19,670 +19,10 @@ #ifndef ANDROID_MEDIA_NBLOG_H #define ANDROID_MEDIA_NBLOG_H -#include -#include -#include -#include -#include - -#include -#include -#include -#include -#include -#include -#include - -namespace android { - -class String8; - -class NBLog { - -public: - - using log_hash_t = uint64_t; - - // FIXME Everything needed for client (writer API and registration) should be isolated - // from the rest of the implementation. - 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) - - // Types for Format Entry, i.e. formatted entry - EVENT_FMT_START, // logFormat start event: entry includes format string, - // following entries contain format arguments - // 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 - - // Types representing audio performance metrics - EVENT_THREAD_INFO, // thread type, frameCount and sampleRate, which give context - // for the metrics below. - 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_WARMUP_TIME, // thread warmup time - EVENT_UNDERRUN, // predicted thread underrun event timestamp - EVENT_OVERRUN, // predicted thread overrun event timestamp - - EVENT_UPPER_BOUND, // to check for invalid events - }; - - // NBLog custom-defined structs. Some NBLog Event types map to these structs. - - // mapped from EVENT_THREAD_INFO - struct thread_info_t { - // TODO make type an enum - int type; // Thread type: 0 for MIXER, 1 for CAPTURE, - // 2 for FASTMIXER, 3 for FASTCAPTURE - size_t frameCount; // number of frames per read or write buffer - unsigned sampleRate; // in frames per second - }; - - template struct get_mapped; -#define MAP_EVENT_TO_TYPE(E, T) \ - template<> struct get_mapped { \ - static_assert(std::is_trivially_copyable::value \ - && !std::is_pointer::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_THREAD_INFO, thread_info_t); - MAP_EVENT_TO_TYPE(EVENT_LATENCY, double); - MAP_EVENT_TO_TYPE(EVENT_WORK_TIME, int64_t); - MAP_EVENT_TO_TYPE(EVENT_WARMUP_TIME, double); - MAP_EVENT_TO_TYPE(EVENT_UNDERRUN, int64_t); - MAP_EVENT_TO_TYPE(EVENT_OVERRUN, int64_t); - -private: - - // --------------------------------------------------------------------------- - - // entry representation in memory - struct entry { - const uint8_t type; - const uint8_t length; - const uint8_t data[0]; - }; - - // entry tail representation (after data) - struct ending { - uint8_t length; - uint8_t next[0]; - }; - - // entry iterator - class EntryIterator { - public: - // Used for dummy initialization. Performing operations on a default-constructed - // EntryIterator other than assigning it to another valid EntryIterator - // is undefined behavior. - EntryIterator(); - // Caller's responsibility to make sure entry is not nullptr. - // Passing in nullptr can result in undefined behavior. - explicit EntryIterator(const uint8_t *entry); - EntryIterator(const EntryIterator &other); - - // dereference underlying entry - const entry& operator*() const; - const entry* operator->() const; - // advance to next entry - EntryIterator& operator++(); // ++i - // back to previous entry - EntryIterator& operator--(); // --i - // returns an EntryIterator corresponding to the next entry - EntryIterator next() const; - // returns an EntryIterator corresponding to the previous entry - EntryIterator prev() const; - bool operator!=(const EntryIterator &other) const; - int operator-(const EntryIterator &other) const; - - bool hasConsistentLength() const; - void copyTo(std::unique_ptr &dst) const; - void copyData(uint8_t *dst) const; - - // memcpy preferred to reinterpret_cast to avoid potentially unsupported - // unaligned memory access. -#if 0 - template - inline const T& payload() { - return *reinterpret_cast(mPtr + offsetof(entry, data)); - } -#else - template - inline T payload() const { - static_assert(std::is_trivially_copyable::value - && !std::is_pointer::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; - } - - private: - const uint8_t *mPtr; // Should not be nullptr except for dummy initialization - }; - - // --------------------------------------------------------------------------- - // The following classes are used for merging into the Merger's buffer. - - class AbstractEntry { - public: - virtual ~AbstractEntry() {} - - // build concrete entry of appropriate class from ptr. - static std::unique_ptr buildEntry(const uint8_t *ptr); - - // get format entry timestamp - virtual int64_t timestamp() const = 0; - - // get format entry's unique id - virtual log_hash_t hash() const = 0; - - // entry's author index (-1 if none present) - // a Merger has a vector of Readers, author simply points to the index of the - // Reader that originated the entry - // TODO consider changing to uint32_t - virtual int author() const = 0; - - // copy entry, adding author before timestamp, returns iterator to end of entry - virtual EntryIterator copyWithAuthor(std::unique_ptr &dst, - int author) const = 0; - - protected: - // Entry starting in the given pointer, which shall not be nullptr. - explicit AbstractEntry(const uint8_t *entry); - // copies ordinary entry from src to dst, and returns length of entry - // size_t copyEntry(audio_utils_fifo_writer *dst, const iterator &it); - const uint8_t *mEntry; - }; - - // API for handling format entry operations - - // a formatted entry has the following structure: - // * 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 - // * ... - // * FMT_END entry - class FormatEntry : public AbstractEntry { - public: - // explicit FormatEntry(const EntryIterator &it); - explicit FormatEntry(const uint8_t *ptr) : AbstractEntry(ptr) {} - virtual ~FormatEntry() {} - - EntryIterator begin() const; - - // 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) - EntryIterator args() const; - - // get format entry timestamp - virtual int64_t timestamp() const override; - - // get format entry's unique id - virtual log_hash_t hash() const override; - - // entry's author index (-1 if none present) - // a Merger has a vector of Readers, author simply points to the index of the - // Reader that originated the entry - virtual int author() const override; - - // copy entry, adding author before timestamp, returns size of original entry - virtual EntryIterator copyWithAuthor(std::unique_ptr &dst, - int author) const override; - }; - - class HistogramEntry : public AbstractEntry { - public: - explicit HistogramEntry(const uint8_t *ptr) : AbstractEntry(ptr) { - } - virtual ~HistogramEntry() {} - - virtual int64_t timestamp() const override; - - virtual log_hash_t hash() const override; - - virtual int author() const override; - - virtual EntryIterator copyWithAuthor(std::unique_ptr &dst, - int author) const override; - }; - - // --------------------------------------------------------------------------- - - // representation of a single log entry in shared memory - // byte[0] mEvent - // byte[1] mLength - // byte[2] mData[0] - // ... - // byte[2+i] mData[i] - // ... - // byte[2+mLength-1] mData[mLength-1] - // byte[2+mLength] duplicate copy of mLength to permit reverse scan - // byte[3+mLength] start of next log entry - class Entry { - public: - Entry(Event event, const void *data, size_t length) - : mEvent(event), mLength(length), mData(data) { } - /*virtual*/ ~Entry() { } - - // used during writing to format Entry information as follows: - // [type][length][data ... ][length] - int copyEntryDataAt(size_t offset) const; - - private: - friend class Writer; - Event mEvent; // event type - uint8_t mLength; // length of additional data, 0 <= mLength <= kMaxLength - const void *mData; // event type-specific data - static const size_t kMaxLength = 255; - public: - // mEvent, mLength, mData[...], duplicate mLength - static const size_t kOverhead = sizeof(entry) + sizeof(ending); - // endind length of previous entry - static const ssize_t kPreviousLengthOffset = - sizeof(ending) + - offsetof(ending, length); - }; - - // TODO move these somewhere else - struct HistTsEntry { - log_hash_t hash; - int64_t ts; - }; //TODO __attribute__((packed)); - - struct HistTsEntryWithAuthor { - log_hash_t hash; - int64_t ts; - int author; - }; //TODO __attribute__((packed)); - - struct HistIntEntry { - log_hash_t hash; - int value; - }; //TODO __attribute__((packed)); - -public: - - // Located in shared memory, must be POD. - // Exactly one process must explicitly call the constructor or use placement new. - // Since this is a POD, the destructor is empty and unnecessary to call it explicitly. - struct Shared { - Shared() /* mRear initialized via default constructor */ { } - /*virtual*/ ~Shared() { } - - audio_utils_fifo_index mRear; // index one byte past the end of most recent Entry - char mBuffer[0]; // circular buffer for entries - }; - -public: - - // --------------------------------------------------------------------------- - - // FIXME Timeline was intended to wrap Writer and Reader, but isn't actually used yet. - // For now it is just a namespace for sharedSize(). - class Timeline : public RefBase { - public: -#if 0 - Timeline(size_t size, void *shared = NULL); - virtual ~Timeline(); -#endif - - // Input parameter 'size' is the desired size of the timeline in byte units. - // Returns the size rounded up to a power-of-2, plus the constant size overhead for indices. - static size_t sharedSize(size_t size); - -#if 0 - private: - friend class Writer; - friend class Reader; - - const size_t mSize; // circular buffer size in bytes, must be a power of 2 - bool mOwn; // whether I own the memory at mShared - Shared* const mShared; // pointer to shared memory -#endif - }; - - // --------------------------------------------------------------------------- - // 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. - class Writer : public RefBase { - public: - Writer(); // dummy nop implementation without shared memory - - // 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). - Writer(void *shared, size_t size); - Writer(const sp& iMemory, size_t size); - - virtual ~Writer(); - - // FIXME needs comments, and some should be private - 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(data); - template - void log(typename get_mapped::type data) { - log(E, &data, sizeof(data)); - } - - virtual bool isEnabled() const; - - // return value for all of these is the previous isEnabled() - virtual bool setEnabled(bool enabled); // but won't enable if no shared memory - bool enable() { return setEnabled(true); } - bool disable() { return setEnabled(false); } - - sp 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 - // Log a single Entry with corresponding event, data, and length. - void log(Event event, const void *data, size_t length); - - 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 mIMemory; // ref-counted version, initialized in constructor - // and then const - audio_utils_fifo * const mFifo; // FIFO itself, non-NULL - // unless constructor fails - audio_utils_fifo_writer * const mFifoWriter; // used to write to FIFO, non-NULL - // unless dummy constructor used - bool mEnabled; // whether to actually log - - // cached pid and process name to use in %p format specifier - // total tag length is mPidTagSize and process name is not zero terminated - char *mPidTag; - size_t mPidTagSize; - }; - - // --------------------------------------------------------------------------- - - // Similar to Writer, but safe for multiple threads to call concurrently - class LockedWriter : public Writer { - public: - LockedWriter(); - LockedWriter(void *shared, size_t size); - - 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 - // --------------------------------------------------------------------------- - - class Snapshot; // Forward declaration needed for Reader::getSnapshot() - - class Reader : public RefBase { - public: - // 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, const std::string &name); - Reader(const sp& iMemory, size_t size, const std::string &name); - virtual ~Reader(); - - // get snapshot of readers fifo buffer, effectively consuming the buffer - std::unique_ptr getSnapshot(); - bool isIMemory(const sp& iMemory) const; - 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; - - // invalidBeginTypes and invalidEndTypes are used to align the Snapshot::begin() and - // Snapshot::end() EntryIterators to valid entries. - static const std::unordered_set invalidBeginTypes; - static const std::unordered_set invalidEndTypes; - - // declared as const because audio_utils_fifo() constructor - sp mIMemory; // ref-counted version, assigned only in constructor - - const std::string mName; // name of reader (actually name of writer) - /*const*/ Shared* const mShared; // raw pointer to shared memory, actually const but not - audio_utils_fifo * const mFifo; // FIFO itself, - // non-NULL unless constructor fails - audio_utils_fifo_reader * const mFifoReader; // used to read from FIFO, - // non-NULL unless constructor fails - - // 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 *findLastValidEntry(const uint8_t *front, const uint8_t *back, - const std::unordered_set &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 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) - : Reader(shared, size, name) {} - DumpReader(const sp& iMemory, size_t size, const std::string &name) - : Reader(iMemory, size, name) {} - void dump(int fd, size_t indent = 0); - private: - void handleAuthor(const AbstractEntry& fmtEntry __unused, String8* body __unused) {} - EntryIterator handleFormat(const FormatEntry &fmtEntry, String8 *timestamp, String8 *body); - - 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 void appendTimestamp(String8 *body, const void *data); - - // The bufferDump functions are used for debugging only. - static String8 bufferDump(const uint8_t *buffer, size_t size); - static String8 bufferDump(const EntryIterator &it); - }; - - // --------------------------------------------------------------------------- - // TODO move Merger, MergeReader, and MergeThread to a separate file. - - // This class is used to read data from each thread's individual FIFO in shared memory - // and write it to a single FIFO in local memory. - class Merger : public RefBase { - public: - Merger(const void *shared, size_t size); - - virtual ~Merger() {} - - void addReader(const sp &reader); - // TODO add removeReader - void merge(); - - // FIXME This is returning a reference to a shared variable that needs a lock - const std::vector>& getReaders() const; - - private: - // vector of the readers the merger is supposed to merge from. - // every reader reads from a writer's buffer - // FIXME Needs to be protected by a lock - std::vector> mReaders; - - Shared * const mShared; // raw pointer to shared memory - std::unique_ptr mFifo; // FIFO itself - std::unique_ptr mFifoWriter; // used to write to FIFO - }; - - // This class has a pointer to the FIFO in local memory which stores the merged - // data collected by NBLog::Merger from all Readers. It is used to process - // this data and write the result to PerformanceAnalysis. - class MergeReader : public Reader { - public: - MergeReader(const void *shared, size_t size, Merger &merger); - - void dump(int fd, int indent = 0); - - // process a particular snapshot of the reader - void processSnapshot(Snapshot &snap, int author); - - // call getSnapshot of the content of the reader's buffer and process the data - void getAndProcessSnapshot(); - - // check for periodic push of performance data to media metrics, and perform - // the send if it is time to do so. - void checkPushToMediaMetrics(); - - private: - // FIXME Needs to be protected by a lock, - // because even though our use of it is read-only there may be asynchronous updates - // The object is owned by the Merger class. - const std::vector>& mReaders; - - // analyzes, compresses and stores the merged data - // contains a separate instance for every author (thread), and for every source file - // location within each author - ReportPerformance::PerformanceAnalysisMap mThreadPerformanceAnalysis; - - // compresses and stores audio performance data from each thread's buffers. - // first parameter is author, i.e. thread index. - std::map mThreadPerformanceData; - - // how often to push data to Media Metrics - static constexpr nsecs_t kPeriodicMediaMetricsPush = s2ns((nsecs_t)2 * 60 * 60); // 2 hours - - // handle author entry by looking up the author's name and appending it to the body - // returns number of bytes read from fmtEntry - void handleAuthor(const AbstractEntry &fmtEntry, String8 *body); - }; - - // MergeThread is a thread that contains a Merger. It works as a retriggerable one-shot: - // when triggered, it awakes for a lapse of time, during which it periodically merges; if - // retriggered, the timeout is reset. - // The thread is triggered on AudioFlinger binder activity. - class MergeThread : public Thread { - public: - MergeThread(Merger &merger, MergeReader &mergeReader); - virtual ~MergeThread() override; - - // Reset timeout and activate thread to merge periodically if it's idle - void wakeup(); - - // Set timeout period until the merging thread goes idle again - void setTimeoutUs(int time); - - private: - virtual bool threadLoop() override; - - // the merger who actually does the work of merging the logs - Merger& mMerger; - - // the mergereader used to process data merged by mMerger - MergeReader& mMergeReader; - - // mutex for the condition variable - Mutex mMutex; - - // condition variable to activate merging on timeout >= 0 - Condition mCond; - - // time left until the thread blocks again (in microseconds) - int mTimeoutUs; - - // merging period when the thread is awake - static const int kThreadSleepPeriodUs = 1000000 /*1s*/; - - // initial timeout value when triggered - static const int kThreadWakeupPeriodUs = 3000000 /*3s*/; - }; - -}; // class NBLog - -} // namespace android +#include +#include +#include +#include +#include #endif // ANDROID_MEDIA_NBLOG_H diff --git a/media/libnblog/include/media/nblog/PerformanceAnalysis.h b/media/libnblog/include/media/nblog/PerformanceAnalysis.h index 80eddb188b..6f284ea8d4 100644 --- a/media/libnblog/include/media/nblog/PerformanceAnalysis.h +++ b/media/libnblog/include/media/nblog/PerformanceAnalysis.h @@ -22,6 +22,7 @@ #include #include +#include #include #include @@ -139,11 +140,9 @@ struct PerformanceData { static constexpr Histogram::Config kWarmupConfig = { 5., 10, 10.}; // Thread Info - // TODO make type an enum - int type = -1; // Thread type: 0 for MIXER, 1 for CAPTURE, - // 2 for FASTMIXER, 3 for FASTCAPTURE - size_t frameCount = 0; - unsigned sampleRate = 0; + NBLog::thread_info_t threadInfo{ + NBLog::UNKNOWN /*threadType*/, 0 /*frameCount*/, 0 /*sampleRate*/ + }; // Performance Data Histogram workHist{kWorkConfig}; @@ -262,8 +261,7 @@ private: void dump(int fd, int indent, PerformanceAnalysisMap &threadPerformanceAnalysis); void dumpLine(int fd, int indent, const String8 &body); -} // namespace ReportPerformance - +} // namespace ReportPerformance } // namespace android #endif // ANDROID_MEDIA_PERFORMANCEANALYSIS_H diff --git a/media/libnblog/include/media/nblog/Reader.h b/media/libnblog/include/media/nblog/Reader.h new file mode 100644 index 0000000000..bf1c32157c --- /dev/null +++ b/media/libnblog/include/media/nblog/Reader.h @@ -0,0 +1,135 @@ +/* + * Copyright (C) 2018 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#ifndef ANDROID_MEDIA_NBLOG_READER_H +#define ANDROID_MEDIA_NBLOG_READER_H + +#include +#include +#include +#include + +#include +#include +#include + +class audio_utils_fifo; +class audio_utils_fifo_reader; + +namespace android { + +class IMemory; +class String8; + +namespace NBLog { + +struct Shared; + +// NBLog Reader API + +class Snapshot; // Forward declaration needed for Reader::getSnapshot() + +class Reader : public RefBase { +public: + // 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, const std::string &name); + Reader(const sp& iMemory, size_t size, const std::string &name); + ~Reader() override; + + // get snapshot of readers fifo buffer, effectively consuming the buffer + std::unique_ptr getSnapshot(); + bool isIMemory(const sp& iMemory) const; + 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; + + // invalidBeginTypes and invalidEndTypes are used to align the Snapshot::begin() and + // Snapshot::end() EntryIterators to valid entries. + static const std::unordered_set invalidBeginTypes; + static const std::unordered_set invalidEndTypes; + + // declared as const because audio_utils_fifo() constructor + sp mIMemory; // ref-counted version, assigned only in constructor + + const std::string mName; // name of reader (actually name of writer) + /*const*/ Shared* const mShared; // raw pointer to shared memory, actually const but not + audio_utils_fifo * const mFifo; // FIFO itself, + // non-NULL unless constructor fails + audio_utils_fifo_reader * const mFifoReader; // used to read from FIFO, + // non-NULL unless constructor fails + + // 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 *findLastValidEntry(const uint8_t *front, const uint8_t *back, + const std::unordered_set &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 Reader::getSnapshot(); + + uint8_t * const mData = nullptr; + size_t mLost = 0; + EntryIterator mBegin; + EntryIterator mEnd; +}; + +// TODO move this to MediaLogService? +class DumpReader : public NBLog::Reader { +public: + DumpReader(const void *shared, size_t size, const std::string &name) + : Reader(shared, size, name) {} + DumpReader(const sp& iMemory, size_t size, const std::string &name) + : Reader(iMemory, size, name) {} + void dump(int fd, size_t indent = 0); +private: + void handleAuthor(const AbstractEntry& fmtEntry __unused, String8* body __unused) {} + EntryIterator handleFormat(const FormatEntry &fmtEntry, String8 *timestamp, String8 *body); + + 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 void appendTimestamp(String8 *body, const void *data); + + // The bufferDump functions are used for debugging only. + static String8 bufferDump(const uint8_t *buffer, size_t size); + static String8 bufferDump(const EntryIterator &it); +}; + +} // namespace NBLog +} // namespace android + +#endif // ANDROID_MEDIA_NBLOG_READER_H diff --git a/media/libnblog/include/media/nblog/ReportPerformance.h b/media/libnblog/include/media/nblog/ReportPerformance.h index 09bb2a00b7..b69ed3b52d 100644 --- a/media/libnblog/include/media/nblog/ReportPerformance.h +++ b/media/libnblog/include/media/nblog/ReportPerformance.h @@ -27,7 +27,6 @@ class Value; } namespace android { - namespace ReportPerformance { struct PerformanceData; @@ -78,8 +77,7 @@ void writeToFile(const std::deque> &hists, const std::deque &peakTimestamps, const char * kDirectory, bool append, int author, log_hash_t hash); -} // namespace ReportPerformance - +} // namespace ReportPerformance } // namespace android #endif // ANDROID_MEDIA_REPORTPERFORMANCE_H diff --git a/media/libnblog/include/media/nblog/Timeline.h b/media/libnblog/include/media/nblog/Timeline.h new file mode 100644 index 0000000000..d4f0cff4c6 --- /dev/null +++ b/media/libnblog/include/media/nblog/Timeline.h @@ -0,0 +1,66 @@ +/* + * Copyright (C) 2018 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#ifndef ANDROID_MEDIA_NBLOG_TIMELINE_H +#define ANDROID_MEDIA_NBLOG_TIMELINE_H + +#include + +#include +#include + +namespace android { +namespace NBLog { + +// Located in shared memory, must be POD. +// Exactly one process must explicitly call the constructor or use placement new. +// Since this is a POD, the destructor is empty and unnecessary to call it explicitly. +struct Shared { + Shared() /* mRear initialized via default constructor */ {} + ~Shared() {} + + audio_utils_fifo_index mRear; // index one byte past the end of most recent Entry + char mBuffer[0]; // circular buffer for entries +}; + +// FIXME Timeline was intended to wrap Writer and Reader, but isn't actually used yet. +// For now it is just a namespace for sharedSize(). +class Timeline : public RefBase { +public: +#if 0 + Timeline(size_t size, void *shared = NULL); + virtual ~Timeline(); +#endif + + // Input parameter 'size' is the desired size of the timeline in byte units. + // Returns the size rounded up to a power-of-2, plus the constant size overhead for indices. + static size_t sharedSize(size_t size); + +#if 0 +private: + friend class Writer; + friend class Reader; + + const size_t mSize; // circular buffer size in bytes, must be a power of 2 + bool mOwn; // whether I own the memory at mShared + Shared* const mShared; // pointer to shared memory +#endif +}; + +} // namespace NBLog +} // namespace android + +#endif // ANDROID_MEDIA_NBLOG_TIMELINE_H diff --git a/media/libnblog/include/media/nblog/Writer.h b/media/libnblog/include/media/nblog/Writer.h new file mode 100644 index 0000000000..7fcd39600f --- /dev/null +++ b/media/libnblog/include/media/nblog/Writer.h @@ -0,0 +1,139 @@ +/* + * Copyright (C) 2018 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#ifndef ANDROID_MEDIA_NBLOG_WRITER_H +#define ANDROID_MEDIA_NBLOG_WRITER_H + +#include +#include + +#include +#include +#include +#include + +class audio_utils_fifo; +class audio_utils_fifo_writer; + +namespace android { + +class IMemory; + +namespace NBLog { + +class Entry; +struct Shared; + +// NBLog Writer Interface + +// 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. +class Writer : public RefBase { +public: + Writer() = default; // dummy nop implementation without shared memory + + // 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). + Writer(void *shared, size_t size); + Writer(const sp& iMemory, size_t size); + + ~Writer() override; + + // FIXME needs comments, and some should be private + 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(data); + template + void log(typename get_mapped::type data) { + log(E, &data, sizeof(data)); + } + + virtual bool isEnabled() const; + + // return value for all of these is the previous isEnabled() + virtual bool setEnabled(bool enabled); // but won't enable if no shared memory + bool enable() { return setEnabled(true); } + bool disable() { return setEnabled(false); } + + sp 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 + // Log a single Entry with corresponding event, data, and length. + void log(Event event, const void *data, size_t length); + + 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 mIMemory{}; // ref-counted version, initialized in constructor + // and then const + audio_utils_fifo * const mFifo{}; // FIFO itself, non-NULL + // unless constructor fails + // or dummy constructor used + audio_utils_fifo_writer * const mFifoWriter{}; // used to write to FIFO, non-NULL + // unless dummy constructor used + bool mEnabled = false; // whether to actually log + + // cached pid and process name to use in %p format specifier + // total tag length is mPidTagSize and process name is not zero terminated + char *mPidTag{}; + size_t mPidTagSize = 0; +}; + +// --------------------------------------------------------------------------- + +// Similar to Writer, but safe for multiple threads to call concurrently +class LockedWriter : public Writer { +public: + LockedWriter() = default; + LockedWriter(void *shared, size_t size); + + 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; +}; + +} // namespace NBLog +} // namespace android + +#endif // ANDROID_MEDIA_NBLOG_WRITER_H diff --git a/services/audioflinger/FastMixer.cpp b/services/audioflinger/FastMixer.cpp index f650b66cfe..d7b7fe8589 100644 --- a/services/audioflinger/FastMixer.cpp +++ b/services/audioflinger/FastMixer.cpp @@ -195,8 +195,7 @@ void FastMixer::onStateChange() // to avoid blocking here and to prevent possible priority inversion mMixer = new AudioMixer(frameCount, mSampleRate); // FIXME See the other FIXME at FastMixer::setNBLogWriter() - // TODO define an int to thread type mapping for the "2" below. - const NBLog::thread_info_t info = { 2 /*FastMixer*/, frameCount, mSampleRate }; + const NBLog::thread_info_t info = { NBLog::FASTMIXER, frameCount, mSampleRate }; LOG_THREAD_INFO(info); const size_t mixerFrameSize = mSinkChannelCount * audio_bytes_per_sample(mMixerBufferFormat); diff --git a/services/medialog/MediaLogService.cpp b/services/medialog/MediaLogService.cpp index b23832e114..0598ce7809 100644 --- a/services/medialog/MediaLogService.cpp +++ b/services/medialog/MediaLogService.cpp @@ -20,6 +20,7 @@ #include #include #include +#include #include #include #include "MediaLogService.h" diff --git a/services/medialog/MediaLogService.h b/services/medialog/MediaLogService.h index a1572f98aa..21df898959 100644 --- a/services/medialog/MediaLogService.h +++ b/services/medialog/MediaLogService.h @@ -19,6 +19,7 @@ #include #include +#include #include namespace android {