OSDN Git Service

Add non-blocking event logger NBLog
authorGlenn Kasten <gkasten@google.com>
Mon, 14 Jan 2013 22:53:13 +0000 (14:53 -0800)
committerGlenn Kasten <gkasten@google.com>
Fri, 25 Jan 2013 23:01:24 +0000 (15:01 -0800)
Change-Id: I6c136cf3d7f46a8af84c69ecfc199dab394c10dc

include/media/nbaio/NBLog.h [new file with mode: 0644]
media/libnbaio/Android.mk
media/libnbaio/NBLog.cpp [new file with mode: 0644]

diff --git a/include/media/nbaio/NBLog.h b/include/media/nbaio/NBLog.h
new file mode 100644 (file)
index 0000000..8fc417f
--- /dev/null
@@ -0,0 +1,188 @@
+/*
+ * 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.
+ */
+
+// Non-blocking event logger intended for safe communication between processes via shared memory
+
+#ifndef ANDROID_MEDIA_NBLOG_H
+#define ANDROID_MEDIA_NBLOG_H
+
+#include <binder/IMemory.h>
+#include <utils/Mutex.h>
+#include <media/nbaio/roundup.h>
+
+namespace android {
+
+class NBLog {
+
+public:
+
+class Writer;
+class Reader;
+
+private:
+
+enum Event {
+    EVENT_RESERVED,
+    EVENT_STRING,               // ASCII string, not NUL-terminated
+    EVENT_TIMESTAMP,            // clock_gettime(CLOCK_MONOTONIC)
+};
+
+// ---------------------------------------------------------------------------
+
+// representation of a single log entry in private memory
+struct Entry {
+    Entry(Event event, const void *data, size_t length)
+        : mEvent(event), mLength(length), mData(data) { }
+    /*virtual*/ ~Entry() { }
+
+    int     readAt(size_t offset) const;
+
+private:
+    friend class Writer;
+    Event       mEvent;     // event type
+    size_t      mLength;    // length of additional data, 0 <= mLength <= 255
+    const void *mData;      // event type-specific data
+};
+
+// 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
+
+// located in shared memory
+struct Shared {
+    Shared() : mRear(0) { }
+    /*virtual*/ ~Shared() { }
+
+    volatile int32_t 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
+
+    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
+};
+
+// ---------------------------------------------------------------------------
+
+// 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
+    Writer(size_t size, void *shared);
+    Writer(size_t size, const sp<IMemory>& iMemory);
+    virtual ~Writer() { }
+
+    virtual void    log(const char *string);
+    virtual void    logf(const char *fmt, ...);
+    virtual void    logvf(const char *fmt, va_list ap);
+    virtual void    logTimestamp();
+    virtual void    logTimestamp(const struct timespec& ts);
+
+    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<IMemory>     getIMemory() const  { return mIMemory; }
+
+private:
+    void    log(Event event, const void *data, size_t length);
+    void    log(const Entry *entry, bool trusted = false);
+
+    const size_t    mSize;      // circular buffer size in bytes, must be a power of 2
+    Shared* const   mShared;    // raw pointer to shared memory
+    const sp<IMemory> mIMemory; // ref-counted version
+    int32_t         mRear;      // my private copy of mShared->mRear
+    bool            mEnabled;   // whether to actually log
+};
+
+// ---------------------------------------------------------------------------
+
+// Similar to Writer, but safe for multiple threads to call concurrently
+class LockedWriter : public Writer {
+public:
+    LockedWriter();
+    LockedWriter(size_t size, void *shared);
+
+    virtual void    log(const char *string);
+    virtual void    logf(const char *fmt, ...);
+    virtual void    logvf(const char *fmt, va_list ap);
+    virtual void    logTimestamp();
+    virtual void    logTimestamp(const struct timespec& ts);
+
+    virtual bool    isEnabled() const;
+    virtual bool    setEnabled(bool enabled);
+
+private:
+    mutable Mutex   mLock;
+};
+
+// ---------------------------------------------------------------------------
+
+class Reader : public RefBase {
+public:
+    Reader(size_t size, const void *shared);
+    Reader(size_t size, const sp<IMemory>& iMemory);
+    virtual ~Reader() { }
+
+    void    dump(int fd, size_t indent = 0);
+    bool    isIMemory(const sp<IMemory>& iMemory) const;
+
+private:
+    const size_t    mSize;      // circular buffer size in bytes, must be a power of 2
+    const Shared* const mShared; // raw pointer to shared memory
+    const sp<IMemory> mIMemory; // ref-counted version
+    int32_t     mFront;         // index of oldest acknowledged Entry
+
+    static const size_t kSquashTimestamp = 5; // squash this many or more adjacent timestamps
+};
+
+};  // class NBLog
+
+}   // namespace android
+
+#endif  // ANDROID_MEDIA_NBLOG_H
index 757272f..d372d20 100644 (file)
@@ -14,6 +14,8 @@ LOCAL_SRC_FILES := \
     roundup.c                       \
     SourceAudioBufferProvider.cpp
 
+LOCAL_SRC_FILES += NBLog.cpp
+
 # libsndfile license is incompatible; uncomment to use for local debug only
 #LOCAL_SRC_FILES += LibsndfileSink.cpp LibsndfileSource.cpp
 #LOCAL_C_INCLUDES += path/to/libsndfile/src
@@ -25,6 +27,7 @@ LOCAL_SRC_FILES := \
 LOCAL_MODULE := libnbaio
 
 LOCAL_SHARED_LIBRARIES := \
+    libbinder \
     libcommon_time_client \
     libcutils \
     libutils
diff --git a/media/libnbaio/NBLog.cpp b/media/libnbaio/NBLog.cpp
new file mode 100644 (file)
index 0000000..045bf64
--- /dev/null
@@ -0,0 +1,447 @@
+/*
+ * 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 <stdarg.h>
+#include <stdint.h>
+#include <stdio.h>
+#include <string.h>
+#include <time.h>
+#include <new>
+#include <cutils/atomic.h>
+#include <media/nbaio/NBLog.h>
+#include <utils/Log.h>
+
+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;
+}
+
+// ---------------------------------------------------------------------------
+
+#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)
+{
+    return sizeof(Shared) + roundup(size);
+}
+
+// ---------------------------------------------------------------------------
+
+NBLog::Writer::Writer()
+    : mSize(0), mShared(NULL), mRear(0), mEnabled(false)
+{
+}
+
+NBLog::Writer::Writer(size_t size, void *shared)
+    : mSize(roundup(size)), mShared((Shared *) shared), mRear(0), mEnabled(mShared != NULL)
+{
+}
+
+NBLog::Writer::Writer(size_t size, const sp<IMemory>& iMemory)
+    : mSize(roundup(size)), mShared(iMemory != 0 ? (Shared *) iMemory->pointer() : NULL),
+      mIMemory(iMemory), mRear(0), mEnabled(mShared != NULL)
+{
+}
+
+void NBLog::Writer::log(const char *string)
+{
+    if (!mEnabled) {
+        return;
+    }
+    size_t length = strlen(string);
+    if (length > 255) {
+        length = 255;
+    }
+    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[256];
+    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(struct timespec));
+    }
+}
+
+void NBLog::Writer::logTimestamp(const struct timespec& ts)
+{
+    if (!mEnabled) {
+        return;
+    }
+    log(EVENT_TIMESTAMP, &ts, sizeof(struct timespec));
+}
+
+void NBLog::Writer::log(Event event, const void *data, size_t length)
+{
+    if (!mEnabled) {
+        return;
+    }
+    if (data == NULL || length > 255) {
+        return;
+    }
+    switch (event) {
+    case EVENT_STRING:
+    case EVENT_TIMESTAMP:
+        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 rear = mRear & (mSize - 1);
+    size_t written = mSize - rear;      // written = number of bytes that have been written so far
+    size_t need = entry->mLength + 3;   // mEvent, mLength, data[length], mLength
+                                        // need = number of bytes remaining to write
+    if (written > need) {
+        written = need;
+    }
+    size_t i;
+    // 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.
+    for (i = 0; i < written; ++i) {
+        mShared->mBuffer[rear + i] = entry->readAt(i);
+    }
+    if (rear + written == mSize && (need -= written) > 0)  {
+        for (i = 0; i < need; ++i) {
+            mShared->mBuffer[i] = entry->readAt(written + i);
+        }
+        written += need;
+    }
+    android_atomic_release_store(mRear += written, &mShared->mRear);
+}
+
+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(size_t size, void *shared)
+    : Writer(size, shared)
+{
+}
+
+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);
+}
+
+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(size_t size, const void *shared)
+    : mSize(roundup(size)), mShared((const Shared *) shared), mFront(0)
+{
+}
+
+NBLog::Reader::Reader(size_t size, const sp<IMemory>& iMemory)
+    : mSize(roundup(size)), mShared(iMemory != 0 ? (const Shared *) iMemory->pointer() : NULL),
+      mIMemory(iMemory), mFront(0)
+{
+}
+
+void NBLog::Reader::dump(int fd, size_t indent)
+{
+    int32_t rear = android_atomic_acquire_load(&mShared->mRear);
+    size_t avail = rear - mFront;
+    if (avail == 0) {
+        return;
+    }
+    size_t lost = 0;
+    if (avail > mSize) {
+        lost = avail - mSize;
+        mFront += lost;
+        avail = mSize;
+    }
+    size_t remaining = avail;       // remaining = number of bytes left to read
+    size_t front = mFront & (mSize - 1);
+    size_t read = mSize - front;    // read = number of bytes that have been read so far
+    if (read > remaining) {
+        read = remaining;
+    }
+    // make a copy to avoid race condition with writer
+    uint8_t *copy = new uint8_t[avail];
+    // copy first part of circular buffer up until the wraparound point
+    memcpy(copy, &mShared->mBuffer[front], read);
+    if (front + read == mSize) {
+        if ((remaining -= read) > 0) {
+            // copy second part of circular buffer starting at beginning
+            memcpy(&copy[read], mShared->mBuffer, remaining);
+            read += remaining;
+            // remaining = 0 but not necessary
+        }
+    }
+    mFront += read;
+    size_t i = avail;
+    Event event;
+    size_t length;
+    struct timespec ts;
+    time_t maxSec = -1;
+    while (i >= 3) {
+        length = copy[i - 1];
+        if (length + 3 > i || copy[i - length - 2] != length) {
+            break;
+        }
+        event = (Event) copy[i - length - 3];
+        if (event == EVENT_TIMESTAMP) {
+            if (length != sizeof(struct timespec)) {
+                // corrupt
+                break;
+            }
+            memcpy(&ts, &copy[i - length - 1], sizeof(struct timespec));
+            if (ts.tv_sec > maxSec) {
+                maxSec = ts.tv_sec;
+            }
+        }
+        i -= length + 3;
+    }
+    if (i > 0) {
+        lost += i;
+        if (fd >= 0) {
+            fdprintf(fd, "%*swarning: lost %u bytes worth of events\n", indent, "", lost);
+        } else {
+            ALOGI("%*swarning: lost %u bytes worth of events\n", indent, "", lost);
+        }
+    }
+    size_t width = 1;
+    while (maxSec >= 10) {
+        ++width;
+        maxSec /= 10;
+    }
+    char prefix[32];
+    if (maxSec >= 0) {
+        snprintf(prefix, sizeof(prefix), "[%*s] ", width + 4, "");
+    } else {
+        prefix[0] = '\0';
+    }
+    while (i < avail) {
+        event = (Event) copy[i];
+        length = copy[i + 1];
+        const void *data = &copy[i + 2];
+        size_t advance = length + 3;
+        switch (event) {
+        case EVENT_STRING:
+            if (fd >= 0) {
+                fdprintf(fd, "%*s%s%.*s\n", indent, "", prefix, length, (const char *) data);
+            } else {
+                ALOGI("%*s%s%.*s", indent, "", prefix, length, (const char *) data);
+            } break;
+        case EVENT_TIMESTAMP: {
+            // already checked that length == sizeof(struct timespec);
+            memcpy(&ts, data, sizeof(struct timespec));
+            long prevNsec = ts.tv_nsec;
+            long deltaMin = LONG_MAX;
+            long deltaMax = -1;
+            long deltaTotal = 0;
+            size_t j = i;
+            for (;;) {
+                j += sizeof(struct timespec) + 3;
+                if (j >= avail || (Event) copy[j] != EVENT_TIMESTAMP) {
+                    break;
+                }
+                struct timespec tsNext;
+                memcpy(&tsNext, &copy[j + 2], sizeof(struct timespec));
+                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 = (j - i) / (sizeof(struct timespec) + 3);
+            if (n >= kSquashTimestamp) {
+                if (fd >= 0) {
+                    fdprintf(fd, "%*s[%d.%03d to .%.03d by .%.03d to .%.03d]\n", indent, "",
+                            (int) ts.tv_sec, (int) (ts.tv_nsec / 1000000),
+                            (int) ((ts.tv_nsec + deltaTotal) / 1000000),
+                            (int) (deltaMin / 1000000), (int) (deltaMax / 1000000));
+                } else {
+                    ALOGI("%*s[%d.%03d to .%.03d by .%.03d to .%.03d]\n", indent, "",
+                            (int) ts.tv_sec, (int) (ts.tv_nsec / 1000000),
+                            (int) ((ts.tv_nsec + deltaTotal) / 1000000),
+                            (int) (deltaMin / 1000000), (int) (deltaMax / 1000000));
+                }
+                i = j;
+                advance = 0;
+                break;
+            }
+            if (fd >= 0) {
+                fdprintf(fd, "%*s[%d.%03d]\n", indent, "", (int) ts.tv_sec,
+                        (int) (ts.tv_nsec / 1000000));
+            } else {
+                ALOGI("%*s[%d.%03d]", indent, "", (int) ts.tv_sec,
+                        (int) (ts.tv_nsec / 1000000));
+            }
+            } break;
+        case EVENT_RESERVED:
+        default:
+            if (fd >= 0) {
+                fdprintf(fd, "%*s%swarning: unknown event %d\n", indent, "", prefix, event);
+            } else {
+                ALOGI("%*s%swarning: unknown event %d", indent, "", prefix, event);
+            }
+            break;
+        }
+        i += advance;
+    }
+    // FIXME it would be more efficient to put a char mCopy[256] as a member variable of the dumper
+    delete[] copy;
+}
+
+bool NBLog::Reader::isIMemory(const sp<IMemory>& iMemory) const
+{
+    return iMemory.get() == mIMemory.get();
+}
+
+}   // namespace android