Add histogram entries (timestamp and flush)

Add functions to write these entries into log

Add functionality to dump them in dumpsys

Bug: 36490717
Test: Write format entries and histogram entries in the log.
      Verify that format entries and histograms are dumped correctly

Change-Id: I2e0b48c63031e62875c08461b98653ecfe1442be
diff --git a/media/libnbaio/NBLog.cpp b/media/libnbaio/NBLog.cpp
index 94ae11e..de2dc25 100644
--- a/media/libnbaio/NBLog.cpp
+++ b/media/libnbaio/NBLog.cpp
@@ -30,7 +30,9 @@
 #include <utils/Log.h>
 #include <utils/String8.h>
 
+#include <map>
 #include <queue>
+#include <utility>
 
 namespace android {
 
@@ -51,12 +53,25 @@
 
 // ---------------------------------------------------------------------------
 
-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)]);
+/*static*/
+std::unique_ptr<NBLog::AbstractEntry> NBLog::AbstractEntry::buildEntry(const uint8_t *ptr) {
+    uint8_t type = EntryIterator(ptr)->type;
+    switch (type) {
+    case EVENT_START_FMT:
+        return std::make_unique<FormatEntry>(FormatEntry(ptr));
+    case EVENT_HISTOGRAM_FLUSH:
+    case EVENT_HISTOGRAM_ENTRY_TS:
+        return std::make_unique<HistogramEntry>(HistogramEntry(ptr));
+    default:
+        ALOGW("Tried to create AbstractEntry of type %d", type);
+        return nullptr;
+    }
 }
 
-NBLog::FormatEntry::FormatEntry(const NBLog::FormatEntry::iterator &it) : FormatEntry(it.ptr) {}
+NBLog::AbstractEntry::AbstractEntry(const uint8_t *entry) : mEntry(entry) {
+}
+
+// ---------------------------------------------------------------------------
 
 const char *NBLog::FormatEntry::formatString() const {
     return (const char*) mEntry + offsetof(entry, data);
@@ -66,7 +81,7 @@
     return mEntry[offsetof(entry, length)];
 }
 
-NBLog::FormatEntry::iterator NBLog::FormatEntry::args() const {
+NBLog::EntryIterator NBLog::FormatEntry::args() const {
     auto it = begin();
     // skip start fmt
     ++it;
@@ -100,7 +115,7 @@
     return hash;
 }
 
-pid_t NBLog::FormatEntry::author() const {
+int NBLog::FormatEntry::author() const {
     auto it = begin();
     // skip start fmt
     ++it;
@@ -115,7 +130,7 @@
     return -1;
 }
 
-NBLog::FormatEntry::iterator NBLog::FormatEntry::copyWithAuthor(
+NBLog::EntryIterator NBLog::FormatEntry::copyWithAuthor(
         std::unique_ptr<audio_utils_fifo_writer> &dst, int author) const {
     auto it = begin();
     // copy fmt start entry
@@ -142,71 +157,107 @@
     return it;
 }
 
-void NBLog::FormatEntry::iterator::copyTo(std::unique_ptr<audio_utils_fifo_writer> &dst) const {
+void NBLog::EntryIterator::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 {
+void NBLog::EntryIterator::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::EntryIterator NBLog::FormatEntry::begin() const {
+    return EntryIterator(mEntry);
 }
 
-NBLog::FormatEntry::iterator::iterator()
+NBLog::EntryIterator::EntryIterator()
     : ptr(nullptr) {}
 
-NBLog::FormatEntry::iterator::iterator(const uint8_t *entry)
+NBLog::EntryIterator::EntryIterator(const uint8_t *entry)
     : ptr(entry) {}
 
-NBLog::FormatEntry::iterator::iterator(const NBLog::FormatEntry::iterator &other)
+NBLog::EntryIterator::EntryIterator(const NBLog::EntryIterator &other)
     : ptr(other.ptr) {}
 
-const NBLog::FormatEntry::entry& NBLog::FormatEntry::iterator::operator*() const {
+const NBLog::entry& NBLog::EntryIterator::operator*() const {
     return *(entry*) ptr;
 }
 
-const NBLog::FormatEntry::entry* NBLog::FormatEntry::iterator::operator->() const {
+const NBLog::entry* NBLog::EntryIterator::operator->() const {
     return (entry*) ptr;
 }
 
-NBLog::FormatEntry::iterator& NBLog::FormatEntry::iterator::operator++() {
+NBLog::EntryIterator& NBLog::EntryIterator::operator++() {
     ptr += ptr[offsetof(entry, length)] + NBLog::Entry::kOverhead;
     return *this;
 }
 
-NBLog::FormatEntry::iterator& NBLog::FormatEntry::iterator::operator--() {
+NBLog::EntryIterator& NBLog::EntryIterator::operator--() {
     ptr -= ptr[NBLog::Entry::kPreviousLengthOffset] + NBLog::Entry::kOverhead;
     return *this;
 }
 
-NBLog::FormatEntry::iterator NBLog::FormatEntry::iterator::next() const {
-    iterator aux(*this);
+NBLog::EntryIterator NBLog::EntryIterator::next() const {
+    EntryIterator aux(*this);
     return ++aux;
 }
 
-NBLog::FormatEntry::iterator NBLog::FormatEntry::iterator::prev() const {
-    iterator aux(*this);
+NBLog::EntryIterator NBLog::EntryIterator::prev() const {
+    EntryIterator aux(*this);
     return --aux;
 }
 
-int NBLog::FormatEntry::iterator::operator-(const NBLog::FormatEntry::iterator &other) const {
+int NBLog::EntryIterator::operator-(const NBLog::EntryIterator &other) const {
     return ptr - other.ptr;
 }
 
-bool NBLog::FormatEntry::iterator::operator!=(const iterator &other) const {
+bool NBLog::EntryIterator::operator!=(const EntryIterator &other) const {
     return ptr != other.ptr;
 }
 
-bool NBLog::FormatEntry::iterator::hasConsistentLength() const {
+bool NBLog::EntryIterator::hasConsistentLength() const {
     return ptr[offsetof(entry, length)] == ptr[ptr[offsetof(entry, length)] +
         NBLog::Entry::kOverhead + NBLog::Entry::kPreviousLengthOffset];
 }
 
 // ---------------------------------------------------------------------------
 
+timespec NBLog::HistogramEntry::timestamp() const {
+    return EntryIterator(mEntry).payload<HistTsEntry>().ts;
+}
+
+NBLog::log_hash_t NBLog::HistogramEntry::hash() const {
+    return EntryIterator(mEntry).payload<HistTsEntry>().hash;
+}
+
+int NBLog::HistogramEntry::author() const {
+    EntryIterator it(mEntry);
+    if (it->length == sizeof(HistTsEntryWithAuthor)) {
+        return it.payload<HistTsEntryWithAuthor>().author;
+    } else {
+        return -1;
+    }
+}
+
+NBLog::EntryIterator NBLog::HistogramEntry::copyWithAuthor(
+        std::unique_ptr<audio_utils_fifo_writer> &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[sizeof(buffer) + Entry::kPreviousLengthOffset] = 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),
@@ -386,6 +437,36 @@
     log(EVENT_HASH, &hash, sizeof(hash));
 }
 
+void NBLog::Writer::logHistTS(log_hash_t hash)
+{
+    if (!mEnabled) {
+        return;
+    }
+    HistTsEntry data;
+    data.hash = hash;
+    int error = clock_gettime(CLOCK_MONOTONIC, &data.ts);
+    if (error == 0) {
+        log(EVENT_HISTOGRAM_ENTRY_TS, &data, sizeof(data));
+    } else {
+        ALOGE("Failed to get timestamp: error %d", error);
+    }
+}
+
+void NBLog::Writer::logHistFlush(log_hash_t hash)
+{
+    if (!mEnabled) {
+        return;
+    }
+    HistTsEntry data;
+    data.hash = hash;
+    int error = clock_gettime(CLOCK_MONOTONIC, &data.ts);
+    if (error == 0) {
+        log(EVENT_HISTOGRAM_FLUSH, &data, sizeof(data));
+    } else {
+        ALOGE("Failed to get timestamp: error %d", error);
+    }
+}
+
 void NBLog::Writer::logFormat(const char *fmt, log_hash_t hash, ...)
 {
     if (!mEnabled) {
@@ -467,17 +548,8 @@
         //      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_HASH:
-    case EVENT_START_FMT:
-        break;
-    case EVENT_RESERVED:
-    default:
+    // Ignore if invalid event
+    if (event == EVENT_RESERVED || event >= EVENT_UPPER_BOUND) {
         return;
     }
     Entry entry(event, data, length);
@@ -616,6 +688,11 @@
 
 // ---------------------------------------------------------------------------
 
+const std::set<NBLog::Event> NBLog::Reader::startingTypes {NBLog::Event::EVENT_START_FMT,
+                                                           NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS};
+const std::set<NBLog::Event> NBLog::Reader::endingTypes   {NBLog::Event::EVENT_END_FMT,
+                                                           NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS,
+                                                           NBLog::Event::EVENT_HISTOGRAM_FLUSH};
 NBLog::Reader::Reader(const void *shared, size_t size)
     : mShared((/*const*/ Shared *) shared), /*mIMemory*/
       mFd(-1), mIndent(0),
@@ -638,16 +715,17 @@
     delete mFifo;
 }
 
-uint8_t *NBLog::Reader::findLastEntryOfType(uint8_t *front, uint8_t *back, uint8_t type) {
+const uint8_t *NBLog::Reader::findLastEntryOfTypes(const uint8_t *front, const uint8_t *back,
+                                            const std::set<Event> &types) {
     while (back + Entry::kPreviousLengthOffset >= front) {
-        uint8_t *prev = back - back[Entry::kPreviousLengthOffset] - Entry::kOverhead;
-        if (prev < front || prev + prev[offsetof(FormatEntry::entry, length)] +
+        const uint8_t *prev = back - back[Entry::kPreviousLengthOffset] - Entry::kOverhead;
+        if (prev < front || prev + prev[offsetof(entry, length)] +
                             Entry::kOverhead != back) {
 
             // prev points to an out of limits or inconsistent entry
             return nullptr;
         }
-        if (prev[offsetof(FormatEntry::entry, type)] == type) {
+        if (types.find((const Event) prev[offsetof(entry, type)]) != types.end()) {
             return prev;
         }
         back = prev;
@@ -686,21 +764,21 @@
     // 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;
+    const uint8_t *back = snapshot->mData + availToRead;
+    const 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);
+    const uint8_t *lastEnd = findLastEntryOfTypes(front, back, endingTypes);
     if (lastEnd == nullptr) {
-        snapshot->mEnd = snapshot->mBegin = FormatEntry::iterator(front);
+        snapshot->mEnd = snapshot->mBegin = EntryIterator(front);
     } else {
         // end of snapshot points to after last END_FMT entry
-        snapshot->mEnd = FormatEntry::iterator(lastEnd + Entry::kOverhead);
+        snapshot->mEnd = EntryIterator(lastEnd).next();
         // find first START_FMT
-        uint8_t *firstStart = nullptr;
-        uint8_t *firstStartTmp = lastEnd;
-        while ((firstStartTmp = findLastEntryOfType(front, firstStartTmp, EVENT_START_FMT))
+        const uint8_t *firstStart = nullptr;
+        const uint8_t *firstStartTmp = snapshot->mEnd;
+        while ((firstStartTmp = findLastEntryOfTypes(front, firstStartTmp, startingTypes))
                 != nullptr) {
             firstStart = firstStartTmp;
         }
@@ -708,7 +786,7 @@
         if (firstStart == nullptr) {
             snapshot->mBegin = snapshot->mEnd;
         } else {
-            snapshot->mBegin = FormatEntry::iterator(firstStart);
+            snapshot->mBegin = EntryIterator(firstStart);
         }
     }
 
@@ -720,6 +798,10 @@
 
 }
 
+int deltaMs(timespec *t1, timespec *t2) {
+    return (t2->tv_sec - t1->tv_sec) * 1000 + t2->tv_nsec / 1000000 - t1->tv_nsec / 1000000;
+}
+
 void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapshot)
 {
 #if 0
@@ -746,7 +828,7 @@
     mFd = fd;
     mIndent = indent;
     String8 timestamp, body;
-    size_t lost = snapshot.lost() + (snapshot.begin() - FormatEntry::iterator(snapshot.data()));
+    size_t lost = snapshot.lost() + (snapshot.begin() - EntryIterator(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
@@ -764,6 +846,9 @@
     }
     bool deferredTimestamp = false;
 #endif
+    std::map<std::pair<log_hash_t, int>, std::vector<int>> hists;
+    std::map<std::pair<log_hash_t, int>, timespec*> lastTSs;
+
     for (auto entry = snapshot.begin(); entry != snapshot.end();) {
         switch (entry->type) {
 #if 0
@@ -835,6 +920,37 @@
             // right now, this is the only supported case
             entry = handleFormat(FormatEntry(entry), &timestamp, &body);
             break;
+        case EVENT_HISTOGRAM_ENTRY_TS: {
+            HistTsEntryWithAuthor *data = (HistTsEntryWithAuthor *) (entry->data);
+            // TODO This memcpies are here to avoid unaligned memory access crash.
+            // There's probably a more efficient way to do it
+            log_hash_t hash;
+            memcpy(&hash, &(data->hash), sizeof(hash));
+            const std::pair<log_hash_t, int> key(hash, data->author);
+            if (lastTSs[key] != nullptr) {
+                timespec ts1;
+                memcpy(&ts1, lastTSs[key], sizeof(timespec));
+                timespec ts2;
+                memcpy(&ts2, &data->ts, sizeof(timespec));
+                // TODO might want to filter excessively high outliers, which are usually caused
+                // by the thread being inactive.
+                hists[key].push_back(deltaMs(&ts1, &ts2));
+            }
+            lastTSs[key] = &(data->ts);
+            ++entry;
+            break;
+        }
+        case EVENT_HISTOGRAM_FLUSH:
+            body.appendFormat("Histograms:\n");
+            for (auto const &hist : hists) {
+                body.appendFormat("Histogram %X - ", (int)hist.first.first);
+                handleAuthor(HistogramEntry(entry), &body);
+                drawHistogram(&body, hist.second);
+            }
+            hists.clear();
+            lastTSs.clear();
+            ++entry;
+            break;
         case EVENT_END_FMT:
             body.appendFormat("warning: got to end format event");
             ++entry;
@@ -902,7 +1018,7 @@
     body->appendFormat("<PID: %d, name: %.*s>", id, (int) (length - sizeof(pid_t)), name);
 }
 
-NBLog::FormatEntry::iterator NBLog::Reader::handleFormat(const FormatEntry &fmtEntry,
+NBLog::EntryIterator NBLog::Reader::handleFormat(const FormatEntry &fmtEntry,
                                                          String8 *timestamp,
                                                          String8 *body) {
     // log timestamp
@@ -920,7 +1036,7 @@
     handleAuthor(fmtEntry, body);
 
     // log string
-    NBLog::FormatEntry::iterator arg = fmtEntry.args();
+    NBLog::EntryIterator arg = fmtEntry.args();
 
     const char* fmt = fmtEntry.formatString();
     size_t fmt_length = fmtEntry.formatStringLength();
@@ -993,6 +1109,75 @@
     return arg;
 }
 
+static int widthOf(int x) {
+    int width = 0;
+    while (x > 0) {
+        ++width;
+        x /= 10;
+    }
+    return width;
+}
+
+static std::map<int, int> buildBuckets(const std::vector<int> &samples) {
+    // TODO allow buckets of variable resolution
+    std::map<int, int> buckets;
+    for (int x : samples) {
+        ++buckets[x];
+    }
+    return buckets;
+}
+
+// TODO put this function in separate file. Make it return a std::string instead of modifying body
+void NBLog::Reader::drawHistogram(String8 *body, const std::vector<int> &samples, int maxHeight) {
+    std::map<int, int> buckets = buildBuckets(samples);
+    // TODO add option for log scale
+    static const char *underscores = "________________";
+    static const char *spaces = "                ";
+
+    auto it = buckets.begin();
+    int maxLabel = it->first;
+    int maxVal = it->second;
+    while (++it != buckets.end()) {
+        if (it->first > maxLabel) {
+            maxLabel = it->first;
+        }
+        if (it->second > maxVal) {
+            maxVal = it->second;
+        }
+    }
+    int height = maxVal;
+    int leftPadding = widthOf(maxVal);
+    int colWidth = std::max(std::max(widthOf(maxLabel) + 1, 3), leftPadding + 2);
+    int scalingFactor = 1;
+    if (height > maxHeight) {
+        scalingFactor = (height + maxHeight) / maxHeight;
+        height /= scalingFactor;
+    }
+    body->appendFormat("\n");
+    body->appendFormat("%*s", leftPadding + 2, " ");
+    for (auto const &x : buckets)
+    {
+        body->appendFormat("[%*d]", colWidth - 2, x.second);
+    }
+    body->appendFormat("\n");
+    for (int row = height * scalingFactor; row > 0; row -= scalingFactor)
+    {
+        body->appendFormat("%*d|", leftPadding, row);
+        for (auto const &x : buckets) {
+            body->appendFormat("%.*s%s", colWidth - 2,
+                   (row == scalingFactor) ? underscores : spaces,
+                   x.second < row ? ((row == scalingFactor) ? "__" : "  ") : "[]");
+        }
+        body->appendFormat("\n");
+    }
+    body->appendFormat("%*s", leftPadding + 1, " ");
+    for (auto const &x : buckets)
+    {
+        body->appendFormat("%*d", colWidth, x.first);
+    }
+    body->appendFormat("\n");
+}
+
 // ---------------------------------------------------------------------------
 
 NBLog::Merger::Merger(const void *shared, size_t size):
@@ -1031,7 +1216,7 @@
 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);
+    std::vector<NBLog::EntryIterator> offsets(nLogs);
     for (int i = 0; i < nLogs; ++i) {
         snapshots[i] = mNamedReaders[i].reader()->getSnapshot();
         offsets[i] = snapshots[i]->begin();
@@ -1043,7 +1228,7 @@
     for (int i = 0; i < nLogs; ++i)
     {
         if (offsets[i] != snapshots[i]->end()) {
-            timespec ts = FormatEntry(offsets[i]).timestamp();
+            timespec ts = AbstractEntry::buildEntry(offsets[i])->timestamp();
             timestamps.emplace(ts, i);
         }
     }
@@ -1052,11 +1237,12 @@
         // find minimum timestamp
         int index = timestamps.top().index;
         // copy it to the log, increasing offset
-        offsets[index] = FormatEntry(offsets[index]).copyWithAuthor(mFifoWriter, index);
+        offsets[index] = AbstractEntry::buildEntry(offsets[index])->copyWithAuthor(mFifoWriter,
+                                                                                   index);
         // update data structures
         timestamps.pop();
         if (offsets[index] != snapshots[index]->end()) {
-            timespec ts = FormatEntry(offsets[index]).timestamp();
+            timespec ts = AbstractEntry::buildEntry(offsets[index])->timestamp();
             timestamps.emplace(ts, index);
         }
     }
@@ -1069,11 +1255,10 @@
 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();
+void NBLog::MergeReader::handleAuthor(const NBLog::AbstractEntry &entry, String8 *body) {
+    int author = entry.author();
     const char* name = (*mNamedReaders)[author].name();
     body->appendFormat("%s: ", name);
-    return NBLog::Entry::kOverhead + sizeof(author);
 }
 
 NBLog::MergeThread::MergeThread(NBLog::Merger &merger)
diff --git a/media/libnbaio/include/NBLog.h b/media/libnbaio/include/NBLog.h
index 6ea33bd..d116ec6 100644
--- a/media/libnbaio/include/NBLog.h
+++ b/media/libnbaio/include/NBLog.h
@@ -24,6 +24,7 @@
 #include <utils/Mutex.h>
 #include <utils/threads.h>
 
+#include <set>
 #include <vector>
 
 namespace android {
@@ -41,7 +42,7 @@
 
 private:
 
-enum Event {
+enum Event : uint8_t {
     EVENT_RESERVED,
     EVENT_STRING,               // ASCII string, not NUL-terminated
     // TODO: make timestamp optional
@@ -54,7 +55,11 @@
                                 // entries contain format arguments
     EVENT_HASH,                 // unique HASH of log origin, originates from hash of file name
                                 // and line number
+    EVENT_HISTOGRAM_ENTRY_TS,   // single datum for timestamp histogram
+    EVENT_HISTOGRAM_FLUSH,      // show histogram on log
     EVENT_END_FMT,              // end of logFormat argument list
+
+    EVENT_UPPER_BOUND,          // to check for invalid events
 };
 
 
@@ -71,90 +76,135 @@
 //    * ...
 //    * END_FMT entry
 
-class FormatEntry {
+// 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:
-    // build a Format Entry starting in the given pointer
-    class iterator;
-    explicit FormatEntry(const uint8_t *entry);
-    explicit FormatEntry(const iterator &it);
+    EntryIterator();
+    explicit EntryIterator(const uint8_t *entry);
+    EntryIterator(const EntryIterator &other);
 
-    // entry representation in memory
-    struct entry {
-        const uint8_t type;
-        const uint8_t length;
-        const uint8_t data[0];
-    };
+    // 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
+    EntryIterator        next() const;
+    EntryIterator        prev() const;
+    bool            operator!=(const EntryIterator &other) const;
+    int             operator-(const EntryIterator &other) const;
 
-    // entry tail representation (after data)
-    struct ending {
-        uint8_t length;
-        uint8_t next[0];
-    };
+    bool            hasConsistentLength() const;
+    void            copyTo(std::unique_ptr<audio_utils_fifo_writer> &dst) const;
+    void            copyData(uint8_t *dst) const;
 
-    // entry iterator
-    class iterator {
-    public:
-        iterator();
-        iterator(const uint8_t *entry);
-        iterator(const iterator &other);
+    template<typename T>
+    inline const T& payload() {
+        return *reinterpret_cast<const T *>(ptr + offsetof(entry, data));
+    }
 
-        // dereference underlying entry
-        const entry&    operator*() const;
-        const entry*    operator->() const;
-        // advance to next entry
-        iterator&       operator++(); // ++i
-        // back to previous entry
-        iterator&       operator--(); // --i
-        iterator        next() const;
-        iterator        prev() const;
-        bool            operator!=(const iterator &other) const;
-        int             operator-(const iterator &other) const;
+    inline operator const uint8_t*() const {
+        return ptr;
+    }
 
-        bool            hasConsistentLength() const;
-        void            copyTo(std::unique_ptr<audio_utils_fifo_writer> &dst) const;
-        void            copyData(uint8_t *dst) const;
+private:
+    const uint8_t  *ptr;
+};
 
-        template<typename T>
-        inline const T& payload() {
-            return *reinterpret_cast<const T *>(ptr + offsetof(entry, data));
-        }
+class AbstractEntry {
+public:
 
-    private:
-        friend class FormatEntry;
-        const uint8_t  *ptr;
-    };
+    // Entry starting in the given pointer
+    explicit AbstractEntry(const uint8_t *entry);
 
-    // 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)
-    iterator    args() const;
+    // build concrete entry of appropriate class from pointer
+    static std::unique_ptr<AbstractEntry> buildEntry(const uint8_t *ptr);
 
     // get format entry timestamp
-    timespec    timestamp() const;
+    // TODO consider changing to uint64_t
+    virtual timespec     timestamp() const = 0;
 
     // get format entry's unique id
-    log_hash_t  hash() const;
+    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
-    int         author() const;
+    // TODO consider changing to uint32_t
+    virtual int          author() const = 0;
 
-    // copy entry, adding author before timestamp, returns size of original entry
-    iterator    copyWithAuthor(std::unique_ptr<audio_utils_fifo_writer> &dst, int author) const;
+    // copy entry, adding author before timestamp, returns iterator to end of entry
+    virtual EntryIterator    copyWithAuthor(std::unique_ptr<audio_utils_fifo_writer> &dst,
+                                       int author) const = 0;
 
-    iterator    begin() const;
-
-private:
+protected:
     // 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;
 };
 
+class FormatEntry : public AbstractEntry {
+public:
+    // explicit FormatEntry(const EntryIterator &it);
+    explicit FormatEntry(const uint8_t *ptr) : AbstractEntry(ptr) {}
+
+    // 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 timespec    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<audio_utils_fifo_writer> &dst,
+                                       int author) const override;
+
+            EntryIterator    begin() const;
+};
+
+class HistogramEntry : public AbstractEntry {
+public:
+    explicit HistogramEntry(const uint8_t *ptr) : AbstractEntry(ptr) {
+    }
+
+    virtual timespec    timestamp() const override;
+
+    virtual log_hash_t  hash() const override;
+
+    virtual int         author() const override;
+
+    virtual EntryIterator    copyWithAuthor(std::unique_ptr<audio_utils_fifo_writer> &dst,
+                                       int author) const override;
+
+};
+
 // ---------------------------------------------------------------------------
 
 // representation of a single log entry in private memory
@@ -173,12 +223,28 @@
     static const size_t kMaxLength = 255;
 public:
     // mEvent, mLength, mData[...], duplicate mLength
-    static const size_t kOverhead = sizeof(FormatEntry::entry) + sizeof(FormatEntry::ending);
+    static const size_t kOverhead = sizeof(entry) + sizeof(ending);
     // endind length of previous entry
-    static const size_t kPreviousLengthOffset = - sizeof(FormatEntry::ending) +
-                                                offsetof(FormatEntry::ending, length);
+    static const size_t kPreviousLengthOffset = - sizeof(ending) +
+                                                offsetof(ending, length);
 };
 
+struct HistTsEntry {
+    log_hash_t hash;
+    timespec ts;
+}; //TODO __attribute__((packed));
+
+struct HistTsEntryWithAuthor {
+    log_hash_t hash;
+    timespec ts;
+    int author;
+}; //TODO __attribute__((packed));
+
+struct HistIntEntry {
+    log_hash_t hash;
+    int value;
+}; //TODO __attribute__((packed));
+
 // representation of a single log entry in shared memory
 //  byte[0]             mEvent
 //  byte[1]             mLength
@@ -265,7 +331,8 @@
     virtual void    logStart(const char *fmt);
     virtual void    logEnd();
     virtual void    logHash(log_hash_t hash);
-
+    virtual void    logHistTS(log_hash_t hash);
+    virtual void    logHistFlush(log_hash_t hash);
 
     virtual bool    isEnabled() const;
 
@@ -344,18 +411,18 @@
 
         // iterator to beginning of readable segment of snapshot
         // data between begin and end has valid entries
-        FormatEntry::iterator begin() { return mBegin; }
+        EntryIterator begin() { return mBegin; }
 
         // iterator to end of readable segment of snapshot
-        FormatEntry::iterator end() { return mEnd; }
+        EntryIterator end() { return mEnd; }
 
 
     private:
         friend class Reader;
         uint8_t              *mData;
         size_t                mLost;
-        FormatEntry::iterator mBegin;
-        FormatEntry::iterator mEnd;
+        EntryIterator mBegin;
+        EntryIterator mEnd;
     };
 
     // Input parameter 'size' is the desired size of the timeline in byte units.
@@ -374,6 +441,8 @@
     bool     isIMemory(const sp<IMemory>& iMemory) const;
 
 private:
+    static const std::set<Event> startingTypes;
+    static const std::set<Event> endingTypes;
     /*const*/ Shared* const mShared;    // raw pointer to shared memory, actually const but not
                                         // declared as const because audio_utils_fifo() constructor
     sp<IMemory> mIMemory;       // ref-counted version, assigned only in constructor
@@ -386,15 +455,18 @@
 
     void    dumpLine(const String8& timestamp, String8& body);
 
-    FormatEntry::iterator   handleFormat(const FormatEntry &fmtEntry,
+    EntryIterator   handleFormat(const FormatEntry &fmtEntry,
                                          String8 *timestamp,
                                          String8 *body);
     // dummy method for handling absent author entry
-    virtual size_t handleAuthor(const FormatEntry &fmtEntry, String8 *body) { return 0; }
+    virtual void handleAuthor(const AbstractEntry &fmtEntry, String8 *body) {}
+
+    static void drawHistogram(String8 *body, const std::vector<int> &samples, int maxHeight = 10);
 
     // Searches for the last entry of type <type> in the range [front, back)
     // back has to be entry-aligned. Returns nullptr if none enconuntered.
-    static uint8_t *findLastEntryOfType(uint8_t *front, uint8_t *back, uint8_t type);
+    static const uint8_t *findLastEntryOfTypes(const uint8_t *front, const uint8_t *back,
+                                         const std::set<Event> &types);
 
     static const size_t kSquashTimestamp = 5; // squash this many or more adjacent timestamps
 };
@@ -447,7 +519,7 @@
     const std::vector<NamedReader> *mNamedReaders;
     // handle author entry by looking up the author's name and appending it to the body
     // returns number of bytes read from fmtEntry
-    size_t handleAuthor(const FormatEntry &fmtEntry, String8 *body);
+    void handleAuthor(const AbstractEntry &fmtEntry, String8 *body);
 };
 
 // MergeThread is a thread that contains a Merger. It works as a retriggerable one-shot:
diff --git a/services/audioflinger/TypedLogger.h b/services/audioflinger/TypedLogger.h
index b922eb7..cc28095 100644
--- a/services/audioflinger/TypedLogger.h
+++ b/services/audioflinger/TypedLogger.h
@@ -32,6 +32,7 @@
 return hash
 
 offset_basis and FNV_prime values depend on the size of the hash output
+Following values are defined by FNV and should not be changed arbitrarily
 */
 
 template<typename T>
@@ -74,9 +75,16 @@
            std::min(line, 0xFFFFu);
 }
 
-#define LOGT(fmt, ...) logWriterTLS->logFormat(fmt, \
-        hash(__FILE__, __LINE__), \
-        ##__VA_ARGS__) // TODO: check null pointer
+// Write formatted entry to log
+#define LOGT(fmt, ...) logWriterTLS->logFormat((fmt), \
+                                               hash(__FILE__, __LINE__), \
+                                               ##__VA_ARGS__) // TODO: check null pointer
+
+// Write histogram timestamp entry
+#define LOG_HIST_TS() logWriterTLS->logHistTS(hash(__FILE__, __LINE__))
+
+// flush all histogram
+#define LOG_HIST_FLUSH() logWriterTLS->logHistFlush(hash(__FILE__, __LINE__))
 
 namespace android {
 extern "C" {
diff --git a/services/medialog/MediaLogService.h b/services/medialog/MediaLogService.h
index c6b99f1..06c721f 100644
--- a/services/medialog/MediaLogService.h
+++ b/services/medialog/MediaLogService.h
@@ -49,7 +49,8 @@
     // Internal dump
     static const int kDumpLockRetries = 50;
     static const int kDumpLockSleepUs = 20000;
-    static const size_t kMergeBufferSize = 16 * 1024; // TODO determine good value for this
+    // Size of merge buffer, in bytes
+    static const size_t kMergeBufferSize = 64 * 1024; // TODO determine good value for this
     static bool dumpTryLock(Mutex& mutex);
 
     Mutex               mLock;