/* * 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) // 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 Reader::getSnapshot(bool flush) { 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. if (flush) { mFifoReader->release(snapshot->mEnd - front); } snapshot->mLost = lost; return snapshot; } bool Reader::isIMemory(const sp& 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 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(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(); body.appendFormat("EVENT_LATENCY,%.3f", latencyMs); } break; case EVENT_OVERRUN: { const int64_t ts = it.payload(); body.appendFormat("EVENT_OVERRUN,%lld", static_cast(ts)); } break; case EVENT_THREAD_INFO: { const thread_info_t info = it.payload(); body.appendFormat("EVENT_THREAD_INFO,%d,%s", static_cast(info.id), threadTypeToString(info.type)); } break; case EVENT_UNDERRUN: { const int64_t ts = it.payload(); body.appendFormat("EVENT_UNDERRUN,%lld", static_cast(ts)); } break; case EVENT_WARMUP_TIME: { const double timeMs = it.payload(); body.appendFormat("EVENT_WARMUP_TIME,%.3f", timeMs); } break; case EVENT_WORK_TIME: { const int64_t monotonicNs = it.payload(); body.appendFormat("EVENT_WORK_TIME,%lld", static_cast(monotonicNs)); } break; case EVENT_THREAD_PARAMS: { const thread_params_t params = it.payload(); 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("", 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