You can not select more than 25 topics
Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.
1078 lines
31 KiB
1078 lines
31 KiB
/*
|
|
* 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"
|
|
//#define LOG_NDEBUG 0
|
|
|
|
#include <climits>
|
|
#include <stdarg.h>
|
|
#include <stdint.h>
|
|
#include <stdio.h>
|
|
#include <string.h>
|
|
#include <sys/prctl.h>
|
|
#include <time.h>
|
|
#include <new>
|
|
#include <audio_utils/roundup.h>
|
|
#include <media/nbaio/NBLog.h>
|
|
#include <utils/Log.h>
|
|
#include <utils/String8.h>
|
|
|
|
#include <queue>
|
|
|
|
namespace android {
|
|
|
|
int NBLog::Entry::readAt(size_t offset) const
|
|
{
|
|
// FIXME This is too slow, despite the name it is used during writing
|
|
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;
|
|
}
|
|
|
|
// ---------------------------------------------------------------------------
|
|
|
|
NBLog::FormatEntry::FormatEntry(const uint8_t *entry) : mEntry(entry) {
|
|
ALOGW_IF(entry[offsetof(struct entry, type)] != EVENT_START_FMT,
|
|
"Created format entry with invalid event type %d", entry[offsetof(struct entry, type)]);
|
|
}
|
|
|
|
NBLog::FormatEntry::FormatEntry(const NBLog::FormatEntry::iterator &it) : FormatEntry(it.ptr) {}
|
|
|
|
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::FormatEntry::iterator NBLog::FormatEntry::args() const {
|
|
auto it = begin();
|
|
// skip start fmt
|
|
++it;
|
|
// skip timestamp
|
|
++it;
|
|
// Skip author if present
|
|
if (it->type == EVENT_AUTHOR) {
|
|
++it;
|
|
}
|
|
return it;
|
|
}
|
|
|
|
timespec NBLog::FormatEntry::timestamp() const {
|
|
auto it = begin();
|
|
// skip start fmt
|
|
++it;
|
|
return it.payload<timespec>();
|
|
}
|
|
|
|
pid_t NBLog::FormatEntry::author() const {
|
|
auto it = begin();
|
|
// skip start fmt
|
|
++it;
|
|
// skip timestamp
|
|
++it;
|
|
// if there is an author entry, return it, return -1 otherwise
|
|
if (it->type == EVENT_AUTHOR) {
|
|
return it.payload<int>();
|
|
}
|
|
return -1;
|
|
}
|
|
|
|
NBLog::FormatEntry::iterator NBLog::FormatEntry::copyWithAuthor(
|
|
std::unique_ptr<audio_utils_fifo_writer> &dst, int author) const {
|
|
auto it = begin();
|
|
// copy fmt start entry
|
|
it.copyTo(dst);
|
|
// copy timestamp
|
|
(++it).copyTo(dst);
|
|
// insert author entry
|
|
size_t authorEntrySize = NBLog::Entry::kOverhead + sizeof(author);
|
|
uint8_t authorEntry[authorEntrySize];
|
|
authorEntry[offsetof(entry, type)] = EVENT_AUTHOR;
|
|
authorEntry[offsetof(entry, length)] =
|
|
authorEntry[authorEntrySize + NBLog::Entry::kPreviousLengthOffset] =
|
|
sizeof(author);
|
|
*(int*) (&authorEntry[offsetof(entry, data)]) = author;
|
|
dst->write(authorEntry, authorEntrySize);
|
|
// copy rest of entries
|
|
while ((++it)->type != EVENT_END_FMT) {
|
|
it.copyTo(dst);
|
|
}
|
|
it.copyTo(dst);
|
|
++it;
|
|
return it;
|
|
}
|
|
|
|
void NBLog::FormatEntry::iterator::copyTo(std::unique_ptr<audio_utils_fifo_writer> &dst) const {
|
|
size_t length = ptr[offsetof(entry, length)] + NBLog::Entry::kOverhead;
|
|
dst->write(ptr, length);
|
|
}
|
|
|
|
void NBLog::FormatEntry::iterator::copyData(uint8_t *dst) const {
|
|
memcpy((void*) dst, ptr + offsetof(entry, data), ptr[offsetof(entry, length)]);
|
|
}
|
|
|
|
NBLog::FormatEntry::iterator NBLog::FormatEntry::begin() const {
|
|
return iterator(mEntry);
|
|
}
|
|
|
|
NBLog::FormatEntry::iterator::iterator()
|
|
: ptr(nullptr) {}
|
|
|
|
NBLog::FormatEntry::iterator::iterator(const uint8_t *entry)
|
|
: ptr(entry) {}
|
|
|
|
NBLog::FormatEntry::iterator::iterator(const NBLog::FormatEntry::iterator &other)
|
|
: ptr(other.ptr) {}
|
|
|
|
const NBLog::FormatEntry::entry& NBLog::FormatEntry::iterator::operator*() const {
|
|
return *(entry*) ptr;
|
|
}
|
|
|
|
const NBLog::FormatEntry::entry* NBLog::FormatEntry::iterator::operator->() const {
|
|
return (entry*) ptr;
|
|
}
|
|
|
|
NBLog::FormatEntry::iterator& NBLog::FormatEntry::iterator::operator++() {
|
|
ptr += ptr[offsetof(entry, length)] + NBLog::Entry::kOverhead;
|
|
return *this;
|
|
}
|
|
|
|
NBLog::FormatEntry::iterator& NBLog::FormatEntry::iterator::operator--() {
|
|
ptr -= ptr[NBLog::Entry::kPreviousLengthOffset] + NBLog::Entry::kOverhead;
|
|
return *this;
|
|
}
|
|
|
|
NBLog::FormatEntry::iterator NBLog::FormatEntry::iterator::next() const {
|
|
iterator aux(*this);
|
|
return ++aux;
|
|
}
|
|
|
|
NBLog::FormatEntry::iterator NBLog::FormatEntry::iterator::prev() const {
|
|
iterator aux(*this);
|
|
return --aux;
|
|
}
|
|
|
|
int NBLog::FormatEntry::iterator::operator-(const NBLog::FormatEntry::iterator &other) const {
|
|
return ptr - other.ptr;
|
|
}
|
|
|
|
bool NBLog::FormatEntry::iterator::operator!=(const iterator &other) const {
|
|
return ptr != other.ptr;
|
|
}
|
|
|
|
bool NBLog::FormatEntry::iterator::hasConsistentLength() const {
|
|
return ptr[offsetof(entry, length)] == ptr[ptr[offsetof(entry, length)] +
|
|
NBLog::Entry::kOverhead + NBLog::Entry::kPreviousLengthOffset];
|
|
}
|
|
|
|
// ---------------------------------------------------------------------------
|
|
|
|
#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>& 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::logTimestamp(const struct timespec &ts)
|
|
{
|
|
if (!mEnabled) {
|
|
return;
|
|
}
|
|
log(EVENT_TIMESTAMP, &ts, sizeof(ts));
|
|
}
|
|
|
|
void NBLog::Writer::logInteger(const int x)
|
|
{
|
|
if (!mEnabled) {
|
|
return;
|
|
}
|
|
log(EVENT_INTEGER, &x, sizeof(x));
|
|
}
|
|
|
|
void NBLog::Writer::logFloat(const float x)
|
|
{
|
|
if (!mEnabled) {
|
|
return;
|
|
}
|
|
log(EVENT_FLOAT, &x, sizeof(x));
|
|
}
|
|
|
|
void NBLog::Writer::logPID()
|
|
{
|
|
if (!mEnabled) {
|
|
return;
|
|
}
|
|
log(EVENT_PID, mPidTag, mPidTagSize);
|
|
}
|
|
|
|
void NBLog::Writer::logStart(const char *fmt)
|
|
{
|
|
if (!mEnabled) {
|
|
return;
|
|
}
|
|
size_t length = strlen(fmt);
|
|
if (length > Entry::kMaxLength) {
|
|
length = Entry::kMaxLength;
|
|
}
|
|
log(EVENT_START_FMT, fmt, length);
|
|
}
|
|
|
|
void NBLog::Writer::logEnd()
|
|
{
|
|
if (!mEnabled) {
|
|
return;
|
|
}
|
|
Entry entry = Entry(EVENT_END_FMT, NULL, 0);
|
|
log(&entry, true);
|
|
}
|
|
|
|
void NBLog::Writer::logFormat(const char *fmt, ...)
|
|
{
|
|
if (!mEnabled) {
|
|
return;
|
|
}
|
|
|
|
va_list ap;
|
|
va_start(ap, fmt);
|
|
Writer::logVFormat(fmt, ap);
|
|
va_end(ap);
|
|
}
|
|
|
|
void NBLog::Writer::logVFormat(const char *fmt, va_list argp)
|
|
{
|
|
if (!mEnabled) {
|
|
return;
|
|
}
|
|
Writer::logStart(fmt);
|
|
int i;
|
|
double f;
|
|
char* s;
|
|
struct timespec t;
|
|
Writer::logTimestamp();
|
|
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 *);
|
|
Writer::log(s);
|
|
break;
|
|
|
|
case 't': // timestamp
|
|
t = va_arg(argp, struct timespec);
|
|
Writer::logTimestamp(t);
|
|
break;
|
|
|
|
case 'd': // integer
|
|
i = va_arg(argp, int);
|
|
Writer::logInteger(i);
|
|
break;
|
|
|
|
case 'f': // float
|
|
f = va_arg(argp, double); // float arguments are promoted to double in vararg lists
|
|
Writer::logFloat((float)f);
|
|
break;
|
|
|
|
case 'p': // pid
|
|
Writer::logPID();
|
|
break;
|
|
|
|
// the "%\0" case finishes parsing
|
|
case '\0':
|
|
--p;
|
|
break;
|
|
|
|
case '%':
|
|
break;
|
|
|
|
default:
|
|
ALOGW("NBLog Writer parsed invalid format specifier: %c", *p);
|
|
break;
|
|
}
|
|
}
|
|
Writer::logEnd();
|
|
}
|
|
|
|
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;
|
|
}
|
|
switch (event) {
|
|
case EVENT_STRING:
|
|
case EVENT_TIMESTAMP:
|
|
case EVENT_INTEGER:
|
|
case EVENT_FLOAT:
|
|
case EVENT_PID:
|
|
case EVENT_START_FMT:
|
|
break;
|
|
case EVENT_RESERVED:
|
|
default:
|
|
return;
|
|
}
|
|
Entry entry(event, data, length);
|
|
log(&entry, true /*trusted*/);
|
|
}
|
|
|
|
void NBLog::Writer::log(const NBLog::Entry *entry, bool trusted)
|
|
{
|
|
if (!mEnabled) {
|
|
return;
|
|
}
|
|
if (!trusted) {
|
|
log(entry->mEvent, entry->mData, entry->mLength);
|
|
return;
|
|
}
|
|
size_t need = entry->mLength + Entry::kOverhead; // mEvent, mLength, data[length], mLength
|
|
// need = number of bytes remaining to write
|
|
|
|
// 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.
|
|
uint8_t temp[Entry::kMaxLength + Entry::kOverhead];
|
|
for (size_t i = 0; i < need; i++) {
|
|
temp[i] = entry->readAt(i);
|
|
}
|
|
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)
|
|
{
|
|
}
|
|
|
|
void NBLog::LockedWriter::log(const char *string)
|
|
{
|
|
Mutex::Autolock _l(mLock);
|
|
Writer::log(string);
|
|
}
|
|
|
|
void NBLog::LockedWriter::logf(const char *fmt, ...)
|
|
{
|
|
// FIXME should not take the lock until after formatting is done
|
|
Mutex::Autolock _l(mLock);
|
|
va_list ap;
|
|
va_start(ap, fmt);
|
|
Writer::logvf(fmt, ap);
|
|
va_end(ap);
|
|
}
|
|
|
|
void NBLog::LockedWriter::logvf(const char *fmt, va_list ap)
|
|
{
|
|
// FIXME should not take the lock until after formatting is done
|
|
Mutex::Autolock _l(mLock);
|
|
Writer::logvf(fmt, ap);
|
|
}
|
|
|
|
void NBLog::LockedWriter::logTimestamp()
|
|
{
|
|
// FIXME should not take the lock until after the clock_gettime() syscall
|
|
Mutex::Autolock _l(mLock);
|
|
Writer::logTimestamp();
|
|
}
|
|
|
|
void NBLog::LockedWriter::logTimestamp(const struct timespec &ts)
|
|
{
|
|
Mutex::Autolock _l(mLock);
|
|
Writer::logTimestamp(ts);
|
|
}
|
|
|
|
void NBLog::LockedWriter::logInteger(const int x)
|
|
{
|
|
Mutex::Autolock _l(mLock);
|
|
Writer::logInteger(x);
|
|
}
|
|
|
|
void NBLog::LockedWriter::logFloat(const float x)
|
|
{
|
|
Mutex::Autolock _l(mLock);
|
|
Writer::logFloat(x);
|
|
}
|
|
|
|
void NBLog::LockedWriter::logPID()
|
|
{
|
|
Mutex::Autolock _l(mLock);
|
|
Writer::logPID();
|
|
}
|
|
|
|
void NBLog::LockedWriter::logStart(const char *fmt)
|
|
{
|
|
Mutex::Autolock _l(mLock);
|
|
Writer::logStart(fmt);
|
|
}
|
|
|
|
|
|
void NBLog::LockedWriter::logEnd()
|
|
{
|
|
Mutex::Autolock _l(mLock);
|
|
Writer::logEnd();
|
|
}
|
|
|
|
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);
|
|
}
|
|
|
|
// ---------------------------------------------------------------------------
|
|
|
|
NBLog::Reader::Reader(const void *shared, size_t size)
|
|
: mShared((/*const*/ Shared *) shared), /*mIMemory*/
|
|
mFd(-1), mIndent(0),
|
|
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>& iMemory, size_t size)
|
|
: Reader(iMemory != 0 ? (Shared *) iMemory->pointer() : NULL, size)
|
|
{
|
|
mIMemory = iMemory;
|
|
}
|
|
|
|
NBLog::Reader::~Reader()
|
|
{
|
|
delete mFifoReader;
|
|
delete mFifo;
|
|
}
|
|
|
|
uint8_t *NBLog::Reader::findLastEntryOfType(uint8_t *front, uint8_t *back, uint8_t type) {
|
|
while (back + Entry::kPreviousLengthOffset >= front) {
|
|
uint8_t *prev = back - back[Entry::kPreviousLengthOffset] - Entry::kOverhead;
|
|
if (prev < front || prev + prev[offsetof(FormatEntry::entry, length)] +
|
|
Entry::kOverhead != back) {
|
|
|
|
// prev points to an out of limits or inconsistent entry
|
|
return nullptr;
|
|
}
|
|
if (prev[offsetof(FormatEntry::entry, type)] == type) {
|
|
return prev;
|
|
}
|
|
back = prev;
|
|
}
|
|
return nullptr; // no entry found
|
|
}
|
|
|
|
std::unique_ptr<NBLog::Reader::Snapshot> NBLog::Reader::getSnapshot()
|
|
{
|
|
if (mFifoReader == NULL) {
|
|
return std::unique_ptr<NBLog::Reader::Snapshot>(new Snapshot());
|
|
}
|
|
// make a copy to avoid race condition with writer
|
|
size_t capacity = mFifo->capacity();
|
|
|
|
// 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;
|
|
audio_utils_iovec iovec[2];
|
|
ssize_t availToRead = mFifoReader->obtain(iovec, capacity, NULL /*timeout*/, &lost);
|
|
if (availToRead <= 0) {
|
|
return std::unique_ptr<NBLog::Reader::Snapshot>(new Snapshot());
|
|
}
|
|
|
|
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 END_FMT). So is safe to traverse backwards.
|
|
// TODO: handle client corruption (in the middle of a buffer)
|
|
|
|
uint8_t *back = snapshot->mData + availToRead;
|
|
uint8_t *front = snapshot->mData;
|
|
|
|
// Find last END_FMT. <back> is sitting on an entry which might be the middle of a FormatEntry.
|
|
// We go backwards until we find an EVENT_END_FMT.
|
|
uint8_t *lastEnd = findLastEntryOfType(front, back, EVENT_END_FMT);
|
|
if (lastEnd == nullptr) {
|
|
snapshot->mEnd = snapshot->mBegin = FormatEntry::iterator(front);
|
|
} else {
|
|
// end of snapshot points to after last END_FMT entry
|
|
snapshot->mEnd = FormatEntry::iterator(lastEnd + Entry::kOverhead);
|
|
// find first START_FMT
|
|
uint8_t *firstStart = nullptr;
|
|
uint8_t *firstStartTmp = lastEnd;
|
|
while ((firstStartTmp = findLastEntryOfType(front, firstStartTmp, EVENT_START_FMT))
|
|
!= nullptr) {
|
|
firstStart = firstStartTmp;
|
|
}
|
|
// firstStart is null if no START_FMT entry was found before lastEnd
|
|
if (firstStart == nullptr) {
|
|
snapshot->mBegin = snapshot->mEnd;
|
|
} else {
|
|
snapshot->mBegin = FormatEntry::iterator(firstStart);
|
|
}
|
|
}
|
|
|
|
// advance fifo reader index to after last entry read.
|
|
mFifoReader->release(snapshot->mEnd - front);
|
|
|
|
snapshot->mLost = lost;
|
|
return snapshot;
|
|
|
|
}
|
|
|
|
void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapshot)
|
|
{
|
|
#if 0
|
|
struct timespec ts;
|
|
time_t maxSec = -1;
|
|
while (entry - start >= (int) Entry::kOverhead) {
|
|
if (prevEntry - start < 0 || !prevEntry.hasConsistentLength()) {
|
|
break;
|
|
}
|
|
if (prevEntry->type == EVENT_TIMESTAMP) {
|
|
if (prevEntry->length != sizeof(struct timespec)) {
|
|
// corrupt
|
|
break;
|
|
}
|
|
prevEntry.copyData((uint8_t*) &ts);
|
|
if (ts.tv_sec > maxSec) {
|
|
maxSec = ts.tv_sec;
|
|
}
|
|
}
|
|
--entry;
|
|
--prevEntry;
|
|
}
|
|
#endif
|
|
mFd = fd;
|
|
mIndent = indent;
|
|
String8 timestamp, body;
|
|
size_t lost = snapshot.lost() + (snapshot.begin() - FormatEntry::iterator(snapshot.data()));
|
|
if (lost > 0) {
|
|
body.appendFormat("warning: lost %zu bytes worth of events", lost);
|
|
// TODO timestamp empty here, only other choice to wait for the first timestamp event in the
|
|
// log to push it out. Consider keeping the timestamp/body between calls to readAt().
|
|
dumpLine(timestamp, body);
|
|
}
|
|
#if 0
|
|
size_t width = 1;
|
|
while (maxSec >= 10) {
|
|
++width;
|
|
maxSec /= 10;
|
|
}
|
|
if (maxSec >= 0) {
|
|
timestamp.appendFormat("[%*s]", (int) width + 4, "");
|
|
}
|
|
bool deferredTimestamp = false;
|
|
#endif
|
|
for (auto entry = snapshot.begin(); entry != snapshot.end();) {
|
|
switch (entry->type) {
|
|
#if 0
|
|
case EVENT_STRING:
|
|
body.appendFormat("%.*s", (int) entry.length(), entry.data());
|
|
break;
|
|
case EVENT_TIMESTAMP: {
|
|
// already checked that length == sizeof(struct timespec);
|
|
entry.copyData((const uint8_t*) &ts);
|
|
long prevNsec = ts.tv_nsec;
|
|
long deltaMin = LONG_MAX;
|
|
long deltaMax = -1;
|
|
long deltaTotal = 0;
|
|
auto aux(entry);
|
|
for (;;) {
|
|
++aux;
|
|
if (end - aux >= 0 || aux.type() != EVENT_TIMESTAMP) {
|
|
break;
|
|
}
|
|
struct timespec tsNext;
|
|
aux.copyData((const uint8_t*) &tsNext);
|
|
if (tsNext.tv_sec != ts.tv_sec) {
|
|
break;
|
|
}
|
|
long delta = tsNext.tv_nsec - prevNsec;
|
|
if (delta < 0) {
|
|
break;
|
|
}
|
|
if (delta < deltaMin) {
|
|
deltaMin = delta;
|
|
}
|
|
if (delta > deltaMax) {
|
|
deltaMax = delta;
|
|
}
|
|
deltaTotal += delta;
|
|
prevNsec = tsNext.tv_nsec;
|
|
}
|
|
size_t n = (aux - entry) / (sizeof(struct timespec) + 3 /*Entry::kOverhead?*/);
|
|
if (deferredTimestamp) {
|
|
dumpLine(timestamp, body);
|
|
deferredTimestamp = false;
|
|
}
|
|
timestamp.clear();
|
|
if (n >= kSquashTimestamp) {
|
|
timestamp.appendFormat("[%d.%03d to .%.03d by .%.03d to .%.03d]",
|
|
(int) ts.tv_sec, (int) (ts.tv_nsec / 1000000),
|
|
(int) ((ts.tv_nsec + deltaTotal) / 1000000),
|
|
(int) (deltaMin / 1000000), (int) (deltaMax / 1000000));
|
|
entry = aux;
|
|
// advance = 0;
|
|
break;
|
|
}
|
|
timestamp.appendFormat("[%d.%03d]", (int) ts.tv_sec,
|
|
(int) (ts.tv_nsec / 1000000));
|
|
deferredTimestamp = true;
|
|
}
|
|
break;
|
|
case EVENT_INTEGER:
|
|
appendInt(&body, entry.data());
|
|
break;
|
|
case EVENT_FLOAT:
|
|
appendFloat(&body, entry.data());
|
|
break;
|
|
case EVENT_PID:
|
|
appendPID(&body, entry.data(), entry.length());
|
|
break;
|
|
#endif
|
|
case EVENT_START_FMT:
|
|
// right now, this is the only supported case
|
|
entry = handleFormat(FormatEntry(entry), ×tamp, &body);
|
|
break;
|
|
case EVENT_END_FMT:
|
|
body.appendFormat("warning: got to end format event");
|
|
++entry;
|
|
break;
|
|
case EVENT_RESERVED:
|
|
default:
|
|
body.appendFormat("warning: unexpected event %d", entry->type);
|
|
++entry;
|
|
break;
|
|
}
|
|
|
|
if (!body.isEmpty()) {
|
|
dumpLine(timestamp, body);
|
|
// deferredTimestamp = false;
|
|
}
|
|
}
|
|
// if (deferredTimestamp) {
|
|
// dumpLine(timestamp, body);
|
|
// }
|
|
}
|
|
|
|
void NBLog::Reader::dump(int fd, size_t indent)
|
|
{
|
|
// get a snapshot, dump it
|
|
std::unique_ptr<Snapshot> snap = getSnapshot();
|
|
dump(fd, indent, *snap);
|
|
}
|
|
|
|
void NBLog::Reader::dumpLine(const String8 ×tamp, String8 &body)
|
|
{
|
|
if (mFd >= 0) {
|
|
dprintf(mFd, "%.*s%s %s\n", mIndent, "", timestamp.string(), body.string());
|
|
} else {
|
|
ALOGI("%.*s%s %s", mIndent, "", timestamp.string(), body.string());
|
|
}
|
|
body.clear();
|
|
}
|
|
|
|
bool NBLog::Reader::isIMemory(const sp<IMemory>& iMemory) const
|
|
{
|
|
return iMemory != 0 && mIMemory != 0 && iMemory->pointer() == mIMemory->pointer();
|
|
}
|
|
|
|
void NBLog::appendTimestamp(String8 *body, const void *data) {
|
|
struct timespec ts;
|
|
memcpy(&ts, data, sizeof(struct timespec));
|
|
body->appendFormat("[%d.%03d]", (int) ts.tv_sec,
|
|
(int) (ts.tv_nsec / 1000000));
|
|
}
|
|
|
|
void NBLog::appendInt(String8 *body, const void *data) {
|
|
int x = *((int*) data);
|
|
body->appendFormat("<%d>", x);
|
|
}
|
|
|
|
void NBLog::appendFloat(String8 *body, const void *data) {
|
|
float f;
|
|
memcpy(&f, data, sizeof(float));
|
|
body->appendFormat("<%f>", f);
|
|
}
|
|
|
|
void NBLog::appendPID(String8 *body, const void* data, size_t length) {
|
|
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);
|
|
}
|
|
|
|
NBLog::FormatEntry::iterator NBLog::Reader::handleFormat(const FormatEntry &fmtEntry,
|
|
String8 *timestamp,
|
|
String8 *body) {
|
|
// log timestamp
|
|
struct timespec ts = fmtEntry.timestamp();
|
|
timestamp->clear();
|
|
timestamp->appendFormat("[%d.%03d]", (int) ts.tv_sec,
|
|
(int) (ts.tv_nsec / 1000000));
|
|
|
|
// log author (if present)
|
|
handleAuthor(fmtEntry, body);
|
|
|
|
// log string
|
|
NBLog::FormatEntry::iterator 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_END_FMT) {
|
|
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_STRING,
|
|
"NBLog Reader incompatible event for string specifier: %d", event);
|
|
body->append((const char*) datum, length);
|
|
break;
|
|
|
|
case 't': // timestamp
|
|
ALOGW_IF(event != EVENT_TIMESTAMP,
|
|
"NBLog Reader incompatible event for timestamp specifier: %d", event);
|
|
appendTimestamp(body, datum);
|
|
break;
|
|
|
|
case 'd': // integer
|
|
ALOGW_IF(event != EVENT_INTEGER,
|
|
"NBLog Reader incompatible event for integer specifier: %d", event);
|
|
appendInt(body, datum);
|
|
break;
|
|
|
|
case 'f': // float
|
|
ALOGW_IF(event != EVENT_FLOAT,
|
|
"NBLog Reader incompatible event for float specifier: %d", event);
|
|
appendFloat(body, datum);
|
|
break;
|
|
|
|
case 'p': // pid
|
|
ALOGW_IF(event != EVENT_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_END_FMT, "Expected end of format, got %d", arg->type);
|
|
++arg;
|
|
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 NBLog::NamedReader &reader) {
|
|
mNamedReaders.push_back(reader);
|
|
}
|
|
|
|
// items placed in priority queue during merge
|
|
// composed by a timestamp and the index of the snapshot where the timestamp came from
|
|
struct MergeItem
|
|
{
|
|
struct timespec ts;
|
|
int index;
|
|
MergeItem(struct timespec ts, int index): ts(ts), index(index) {}
|
|
};
|
|
|
|
// operators needed for priority queue in merge
|
|
bool operator>(const struct timespec &t1, const struct timespec &t2) {
|
|
return t1.tv_sec > t2.tv_sec || (t1.tv_sec == t2.tv_sec && t1.tv_nsec > t2.tv_nsec);
|
|
}
|
|
|
|
bool operator>(const struct MergeItem &i1, const struct MergeItem &i2) {
|
|
return i1.ts > i2.ts ||
|
|
(i1.ts.tv_sec == i2.ts.tv_sec && i1.ts.tv_nsec == i2.ts.tv_nsec && i1.index > i2.index);
|
|
}
|
|
|
|
// Merge registered readers, sorted by timestamp
|
|
void NBLog::Merger::merge() {
|
|
int nLogs = mNamedReaders.size();
|
|
std::vector<std::unique_ptr<NBLog::Reader::Snapshot>> snapshots(nLogs);
|
|
std::vector<NBLog::FormatEntry::iterator> offsets(nLogs);
|
|
for (int i = 0; i < nLogs; ++i) {
|
|
snapshots[i] = mNamedReaders[i].reader()->getSnapshot();
|
|
offsets[i] = snapshots[i]->begin();
|
|
}
|
|
// initialize offsets
|
|
// TODO custom heap implementation could allow to update top, improving performance
|
|
// for bursty buffers
|
|
std::priority_queue<MergeItem, std::vector<MergeItem>, std::greater<MergeItem>> timestamps;
|
|
for (int i = 0; i < nLogs; ++i)
|
|
{
|
|
if (offsets[i] != snapshots[i]->end()) {
|
|
timespec ts = FormatEntry(offsets[i]).timestamp();
|
|
timestamps.emplace(ts, i);
|
|
}
|
|
}
|
|
|
|
while (!timestamps.empty()) {
|
|
// find minimum timestamp
|
|
int index = timestamps.top().index;
|
|
// copy it to the log, increasing offset
|
|
offsets[index] = FormatEntry(offsets[index]).copyWithAuthor(mFifoWriter, index);
|
|
// update data structures
|
|
timestamps.pop();
|
|
if (offsets[index] != snapshots[index]->end()) {
|
|
timespec ts = FormatEntry(offsets[index]).timestamp();
|
|
timestamps.emplace(ts, index);
|
|
}
|
|
}
|
|
}
|
|
|
|
const std::vector<NBLog::NamedReader> *NBLog::Merger::getNamedReaders() const {
|
|
return &mNamedReaders;
|
|
}
|
|
|
|
NBLog::MergeReader::MergeReader(const void *shared, size_t size, Merger &merger)
|
|
: Reader(shared, size), mNamedReaders(merger.getNamedReaders()) {}
|
|
|
|
size_t NBLog::MergeReader::handleAuthor(const NBLog::FormatEntry &fmtEntry, String8 *body) {
|
|
int author = fmtEntry.author();
|
|
const char* name = (*mNamedReaders)[author].name();
|
|
body->appendFormat("%s: ", name);
|
|
return NBLog::Entry::kOverhead + sizeof(author);
|
|
}
|
|
|
|
NBLog::MergeThread::MergeThread(NBLog::Merger &merger)
|
|
: mMerger(merger),
|
|
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, wait kThreadSleepPeriodUs and then merge
|
|
nsecs_t waitTime = mTimeoutUs > 0 ? kThreadSleepPeriodUs * 1000 : LLONG_MAX;
|
|
mCond.waitRelative(mMutex, waitTime);
|
|
doMerge = mTimeoutUs > 0;
|
|
mTimeoutUs -= kThreadSleepPeriodUs;
|
|
}
|
|
if (doMerge) {
|
|
mMerger.merge();
|
|
}
|
|
return true;
|
|
}
|
|
|
|
void NBLog::MergeThread::wakeup() {
|
|
setTimeoutUs(kThreadWakeupPeriodUs);
|
|
}
|
|
|
|
void NBLog::MergeThread::setTimeoutUs(int time) {
|
|
AutoMutex _l(mMutex);
|
|
mTimeoutUs = time;
|
|
mCond.signal();
|
|
}
|
|
|
|
} // namespace android
|