|  | /* | 
|  | * 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 <memory> | 
|  | #include <stddef.h> | 
|  | #include <string> | 
|  | #include <unordered_set> | 
|  |  | 
|  | #include <audio_utils/fifo.h> | 
|  | #include <binder/IMemory.h> | 
|  | #include <media/nblog/Entry.h> | 
|  | #include <media/nblog/Events.h> | 
|  | #include <media/nblog/Reader.h> | 
|  | #include <media/nblog/Timeline.h> | 
|  | #include <utils/Log.h> | 
|  | #include <utils/String8.h> | 
|  |  | 
|  | 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>& iMemory, size_t size, const std::string &name) | 
|  | // TODO: Using unsecurePointer() has some associated security pitfalls | 
|  | //       (see declaration for details). | 
|  | //       Either document why it is safe in this case or address the | 
|  | //       issue (e.g. by copying). | 
|  | : Reader(iMemory != 0 ? (Shared *) iMemory->unsecurePointer() : 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<Snapshot> Reader::getSnapshot(bool flush) | 
|  | { | 
|  | if (mFifoReader == NULL) { | 
|  | return std::unique_ptr<Snapshot>(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<Snapshot>(new Snapshot()); | 
|  | } | 
|  |  | 
|  | // Change to #if 1 for debugging. This statement is useful for checking buffer fullness levels | 
|  | // (as seen by reader) and how much data was lost. If you find that the fullness level is | 
|  | // getting close to full, or that data loss is happening to often, then you should | 
|  | // probably try some of the following: | 
|  | // - log less data | 
|  | // - log less often | 
|  | // - increase the initial shared memory allocation for the buffer | 
|  | #if 0 | 
|  | ALOGD("getSnapshot name=%s, availToRead=%zd, capacity=%zu, fullness=%.3f, lost=%zu", | 
|  | name().c_str(), availToRead, capacity, (double)availToRead / (double)capacity, lost); | 
|  | #endif | 
|  | std::unique_ptr<Snapshot> snapshot(new Snapshot(availToRead)); | 
|  | memcpy(snapshot->mData, (const char *) mFifo->buffer() + iovec[0].mOffset, iovec[0].mLength); | 
|  | if (iovec[1].mLength > 0) { | 
|  | 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. <back> is sitting on an entry which might be the middle of a FormatEntry. | 
|  | // We go backwards until we find an EVENT_FMT_END. | 
|  | const uint8_t *lastEnd = findLastValidEntry(front, back, invalidEndTypes); | 
|  | if (lastEnd == nullptr) { | 
|  | snapshot->mEnd = snapshot->mBegin = EntryIterator(front); | 
|  | } else { | 
|  | // end of snapshot points to after last 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. | 
|  | if (flush) { | 
|  | mFifoReader->release(snapshot->mEnd - front); | 
|  | } | 
|  |  | 
|  | snapshot->mLost = lost; | 
|  | return snapshot; | 
|  | } | 
|  |  | 
|  | bool Reader::isIMemory(const sp<IMemory>& iMemory) const | 
|  | { | 
|  | return iMemory != 0 && mIMemory != 0 && | 
|  | iMemory->unsecurePointer() == mIMemory->unsecurePointer(); | 
|  | } | 
|  |  | 
|  | // 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<Event> 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<Event> 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<Event> &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> snapshot = getSnapshot(false /*flush*/); | 
|  | if (snapshot == nullptr) { | 
|  | return; | 
|  | } | 
|  | String8 timestamp, body; | 
|  |  | 
|  | // TODO all logged types should have a printable format. | 
|  | // TODO can we make the printing generic? | 
|  | 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_LATENCY: { | 
|  | const double latencyMs = it.payload<double>(); | 
|  | body.appendFormat("EVENT_LATENCY,%.3f", latencyMs); | 
|  | } break; | 
|  | case EVENT_OVERRUN: { | 
|  | const int64_t ts = it.payload<int64_t>(); | 
|  | body.appendFormat("EVENT_OVERRUN,%lld", static_cast<long long>(ts)); | 
|  | } break; | 
|  | case EVENT_THREAD_INFO: { | 
|  | const thread_info_t info = it.payload<thread_info_t>(); | 
|  | body.appendFormat("EVENT_THREAD_INFO,%d,%s", static_cast<int>(info.id), | 
|  | threadTypeToString(info.type)); | 
|  | } break; | 
|  | case EVENT_UNDERRUN: { | 
|  | const int64_t ts = it.payload<int64_t>(); | 
|  | body.appendFormat("EVENT_UNDERRUN,%lld", static_cast<long long>(ts)); | 
|  | } break; | 
|  | case EVENT_WARMUP_TIME: { | 
|  | const double timeMs = it.payload<double>(); | 
|  | body.appendFormat("EVENT_WARMUP_TIME,%.3f", timeMs); | 
|  | } break; | 
|  | case EVENT_WORK_TIME: { | 
|  | const int64_t monotonicNs = it.payload<int64_t>(); | 
|  | body.appendFormat("EVENT_WORK_TIME,%lld", static_cast<long long>(monotonicNs)); | 
|  | } break; | 
|  | case EVENT_THREAD_PARAMS: { | 
|  | const thread_params_t params = it.payload<thread_params_t>(); | 
|  | body.appendFormat("EVENT_THREAD_PARAMS,%zu,%u", params.frameCount, params.sampleRate); | 
|  | } break; | 
|  | case EVENT_FMT_END: | 
|  | case EVENT_RESERVED: | 
|  | case EVENT_UPPER_BOUND: | 
|  | body.appendFormat("warning: unexpected event %d", it->type); | 
|  | break; | 
|  | 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) | 
|  | { | 
|  | String8 timestampLocal; | 
|  | String8 bodyLocal; | 
|  | if (timestamp == nullptr) { | 
|  | timestamp = ×tampLocal; | 
|  | } | 
|  | if (body == nullptr) { | 
|  | body = &bodyLocal; | 
|  | } | 
|  |  | 
|  | // 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("<PID: %d, name: %.*s>", 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 |