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 94ad114099..46912d37e3 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 6893fee9f9..983b28a647 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 @@ -142,11 +143,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}; @@ -265,8 +264,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 {