NBLog: Make separate readers for dumping logs and histograms (6af1847b) · Commits · e / os / android_frameworks_av

media/libnblog/NBLog.cpp

+63 −105

Original line number	Diff line number	Diff line
		@@ -20,11 +20,7 @@

		#include <algorithm>
		#include <climits>
		#include <deque>
		#include <fstream>
		#include <iostream>
		#include <math.h>
		#include <numeric>
		#include <unordered_set>
		#include <vector>
		#include <stdarg.h>
		@@ -727,7 +723,7 @@ const std::unordered_set<NBLog::Event> NBLog::Reader::endingTypes {
		};

		NBLog::Reader::Reader(const void *shared, size_t size, const std::string &name)
		: mFd(-1), mIndent(0), mLost(0), mName(name),
		: mName(name),
		mShared((/const/ Shared ) shared), /mIMemory*/
		mFifo(mShared != NULL ?
		new audio_utils_fifo(size, sizeof(uint8_t),
		@@ -769,10 +765,10 @@ const uint8_t NBLog::Reader::findLastEntryOfTypes(const uint8_t front, const u
		// 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<NBLog::Reader::Snapshot> NBLog::Reader::getSnapshot()
		std::unique_ptr<NBLog::Snapshot> NBLog::Reader::getSnapshot()
		{
		if (mFifoReader == NULL) {
		return std::unique_ptr<NBLog::Reader::Snapshot>(new Snapshot());
		return std::make_unique<Snapshot>();
		}

		// This emulates the behaviour of audio_utils_fifo_reader::read, but without incrementing the
		@@ -802,7 +798,7 @@ std::unique_ptr<NBLog::Reader::Snapshot> NBLog::Reader::getSnapshot()

		if (availToRead <= 0) {
		ALOGW_IF(availToRead < 0, "NBLog Reader %s failed to catch up with Writer", mName.c_str());
		return std::make_unique<NBLog::Reader::Snapshot>();
		return std::make_unique<Snapshot>();
		}

		std::unique_ptr<Snapshot> snapshot(new Snapshot(availToRead));
		@@ -853,17 +849,12 @@ std::unique_ptr<NBLog::Reader::Snapshot> NBLog::Reader::getSnapshot()

		// Takes raw content of the local merger FIFO, processes log entries, and
		// writes the data to a map of class PerformanceAnalysis, based on their thread ID.
		void NBLog::MergeReader::getAndProcessSnapshot(NBLog::Reader::Snapshot &snapshot)
		void NBLog::MergeReader::getAndProcessSnapshot(NBLog::Snapshot &snapshot, int author)
		{
		String8 timestamp, body;

		for (auto entry = snapshot.begin(); entry != snapshot.end();) {
		switch (entry->type) {
		case EVENT_START_FMT:
		entry = handleFormat(FormatEntry(entry), &timestamp, &body);
		break;
		for (const entry &etr : snapshot) {
		switch (etr.type) {
		case EVENT_HISTOGRAM_ENTRY_TS: {
		HistTsEntryWithAuthor data = (HistTsEntryWithAuthor ) (entry->data);
		HistTsEntry data = (HistTsEntry ) (etr.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;
		@@ -872,45 +863,41 @@ void NBLog::MergeReader::getAndProcessSnapshot(NBLog::Reader::Snapshot &snapshot
		memcpy(&ts, &data->ts, sizeof(ts));
		// TODO: hash for histogram ts and audio state need to match
		// and correspond to audio production source file location
		mThreadPerformanceAnalysis[data->author][0 /hash/].logTsEntry(ts);
		++entry;
		break;
		}
		mThreadPerformanceAnalysis[author][0 /hash/].logTsEntry(ts);
		} break;
		case EVENT_AUDIO_STATE: {
		HistTsEntryWithAuthor data = (HistTsEntryWithAuthor ) (entry->data);
		HistTsEntry data = (HistTsEntry ) (etr.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));
		// TODO: remove ts if unused
		int64_t ts;
		memcpy(&ts, &data->ts, sizeof(ts));
		mThreadPerformanceAnalysis[data->author][0 /hash/].handleStateChange();
		++entry;
		break;
		}
		mThreadPerformanceAnalysis[author][0 /hash/].handleStateChange();
		} break;
		case EVENT_END_FMT:
		body.appendFormat("warning: got to end format event");
		++entry;
		break;
		case EVENT_RESERVED:
		case EVENT_UPPER_BOUND:
		ALOGW("warning: unexpected event %d", etr.type);
		default:
		body.appendFormat("warning: unexpected event %d", entry->type);
		++entry;
		break;
		}
		}
		// FIXME: decide whether to print the warnings here or elsewhere
		if (!body.isEmpty()) {
		dumpLine(&timestamp, &body);
		}
		}

		void NBLog::MergeReader::getAndProcessSnapshot()
		{
		// get a snapshot, process it
		std::unique_ptr<Snapshot> snap = getSnapshot();
		getAndProcessSnapshot(*snap);
		// get a snapshot of each reader and process them
		// TODO insert lock here
		const size_t nLogs = mReaders.size();
		std::vector<std::unique_ptr<Snapshot>> snapshots(nLogs);
		for (size_t i = 0; i < nLogs; i++) {
		snapshots[i] = mReaders[i]->getSnapshot();
		}
		// TODO unlock lock here
		for (size_t i = 0; i < nLogs; i++) {
		if (snapshots[i] != nullptr) {
		getAndProcessSnapshot(*(snapshots[i]), i);
		}
		}
		}

		void NBLog::MergeReader::dump(int fd, int indent)
		@@ -919,66 +906,41 @@ void NBLog::MergeReader::dump(int fd, int indent)
		ReportPerformance::dump(fd, indent, mThreadPerformanceAnalysis);
		}

		void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapshot)
		// TODO for future compatibility, would prefer to have a dump() go to string, and then go
		// to fd only when invoked through binder.
		void NBLog::DumpReader::dump(int fd, size_t indent)
		{
		mFd = fd;
		mIndent = indent;
		if (fd < 0) return;
		std::unique_ptr<Snapshot> snapshot = getSnapshot();
		if (snapshot == nullptr) {
		return;
		}
		String8 timestamp, body;

		// Range-based for loop isn't used here because handleFormat() returns an EntryIterator
		// that points to the next entry (it handles all of the necessary operator++() calls).
		for (auto entry = snapshot.begin(); entry != snapshot.end();) {
		switch (entry->type) {
		// TODO all logged types should have a printable format.
		for (auto it = snapshot->begin(); it != snapshot->end(); ++it) {
		switch (it->type) {
		case EVENT_START_FMT:
		entry = handleFormat(FormatEntry(entry), &timestamp, &body);
		break;
		case EVENT_HISTOGRAM_ENTRY_TS:
		++entry;
		break;
		case EVENT_AUDIO_STATE:
		++entry;
		break;
		case EVENT_END_FMT:
		body.appendFormat("warning: got to end format event");
		++entry;
		it = handleFormat(FormatEntry(it), &timestamp, &body);
		break;
		case EVENT_MONOTONIC_CYCLE_TIME: {
		uint32_t monotonicNs = (uint32_t ) (entry->data);
		uint32_t monotonicNs;
		memcpy(&monotonicNs, it->data, sizeof(monotonicNs));
		body.appendFormat("Thread cycle took %u ns", monotonicNs);
		++entry;
		} break;
		case EVENT_END_FMT:
		case EVENT_RESERVED:
		case EVENT_UPPER_BOUND:
		body.appendFormat("warning: unexpected event %d", it->type);
		default:
		body.appendFormat("warning: unexpected event %d", entry->type);
		++entry;
		break;
		}
		// FIXME: decide whether to print the warnings here or elsewhere
		if (!body.isEmpty()) {
		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);
		}

		// Writes a string to the console
		void NBLog::Reader::dumpLine(const String8 timestamp, String8 body)
		{
		if (timestamp == nullptr \|\| body == nullptr) {
		return;
		dprintf(fd, "%.*s%s %s\n", (int)indent, "", timestamp.string(), body.string());
		body.clear();
		}
		if (mFd >= 0) {
		dprintf(mFd, "%.*s%s %s\n", mIndent, "", timestamp->string(), body->string());
		} else {
		ALOGI("%.*s%s %s", mIndent, "", timestamp->string(), body->string());
		timestamp.clear();
		}
		body->clear();
		}

		bool NBLog::Reader::isIMemory(const sp<IMemory>& iMemory) const
		@@ -986,9 +948,7 @@ 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)
		void NBLog::DumpReader::appendTimestamp(String8 body, const void data)
		{
		if (body == nullptr \|\| data == nullptr) {
		return;
		@@ -999,7 +959,7 @@ void NBLog::appendTimestamp(String8 body, const void data)
		(int) ((ts / (1000 * 1000)) % 1000));
		}

		void NBLog::appendInt(String8 body, const void data)
		void NBLog::DumpReader::appendInt(String8 body, const void data)
		{
		if (body == nullptr \|\| data == nullptr) {
		return;
		@@ -1008,7 +968,7 @@ void NBLog::appendInt(String8 body, const void data)
		body->appendFormat("<%d>", x);
		}

		void NBLog::appendFloat(String8 body, const void data)
		void NBLog::DumpReader::appendFloat(String8 body, const void data)
		{
		if (body == nullptr \|\| data == nullptr) {
		return;
		@@ -1018,7 +978,7 @@ void NBLog::appendFloat(String8 body, const void data)
		body->appendFormat("<%f>", f);
		}

		void NBLog::appendPID(String8 body, const void data, size_t length)
		void NBLog::DumpReader::appendPID(String8 body, const void data, size_t length)
		{
		if (body == nullptr \|\| data == nullptr) {
		return;
		@@ -1028,7 +988,7 @@ void NBLog::appendPID(String8 body, const void data, size_t length)
		body->appendFormat("<PID: %d, name: %.*s>", id, (int) (length - sizeof(pid_t)), name);
		}

		String8 NBLog::bufferDump(const uint8_t *buffer, size_t size)
		String8 NBLog::DumpReader::bufferDump(const uint8_t *buffer, size_t size)
		{
		String8 str;
		if (buffer == nullptr) {
		@@ -1042,12 +1002,12 @@ String8 NBLog::bufferDump(const uint8_t *buffer, size_t size)
		return str;
		}

		String8 NBLog::bufferDump(const EntryIterator &it)
		String8 NBLog::DumpReader::bufferDump(const EntryIterator &it)
		{
		return bufferDump(it, it->length + Entry::kOverhead);
		}

		NBLog::EntryIterator NBLog::Reader::handleFormat(const FormatEntry &fmtEntry,
		NBLog::EntryIterator NBLog::DumpReader::handleFormat(const FormatEntry &fmtEntry,
		String8 *timestamp,
		String8 *body)
		{
		@@ -1135,7 +1095,6 @@ NBLog::EntryIterator NBLog::Reader::handleFormat(const FormatEntry &fmtEntry,
		++arg;
		}
		ALOGW_IF(arg->type != EVENT_END_FMT, "Expected end of format, got %d", arg->type);
		++arg;
		return arg;
		}

		@@ -1172,10 +1131,10 @@ bool operator>(const struct MergeItem &i1, const struct MergeItem &i2)
		// Merge registered readers, sorted by timestamp, and write data to a single FIFO in local memory
		void NBLog::Merger::merge()
		{
		// FIXME This is called by merge thread
		// but the access to shared variable mNamedReaders is not yet protected by a lock.
		if (true) return; // Merging is not necessary at the moment, so this is to disable it
		// and bypass compiler warnings about member variables not being used.
		const int nLogs = mReaders.size();
		std::vector<std::unique_ptr<NBLog::Reader::Snapshot>> snapshots(nLogs);
		std::vector<std::unique_ptr<Snapshot>> snapshots(nLogs);
		std::vector<EntryIterator> offsets;
		offsets.reserve(nLogs);
		for (int i = 0; i < nLogs; ++i) {
		@@ -1258,13 +1217,12 @@ bool NBLog::MergeThread::threadLoop()
		{
		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);
		// If it's positive, merge. The minimum period between waking the condition variable
		// is handled in AudioFlinger::MediaLogNotifier::threadLoop().
		mCond.wait(mMutex);
		doMerge = mTimeoutUs > 0;
		mTimeoutUs -= kThreadSleepPeriodUs;
		}
		doMerge = false; // Disable merging for now.
		if (doMerge) {
		// Merge data from all the readers
		mMerger.merge();

media/libnblog/include/media/nblog/NBLog.h

+71 −81

Original line number	Diff line number	Diff line
		@@ -19,7 +19,6 @@
		#ifndef ANDROID_MEDIA_NBLOG_H
		#define ANDROID_MEDIA_NBLOG_H

		#include <deque>
		#include <map>
		#include <unordered_set>
		#include <vector>
		@@ -76,17 +75,6 @@ public:
		private:

		// ---------------------------------------------------------------------------
		// API for handling format entry operations

		// a formatted entry has the following structure:
		// * START_FMT entry, containing the format string
		// * TIMESTAMP entry
		// * HASH entry
		// * author entry of the thread that generated it (optional, present in merged log)
		// * format arg1
		// * format arg2
		// * ...
		// * END_FMT entry

		// entry representation in memory
		struct entry {
		@@ -144,6 +132,9 @@ private:
		const uint8_t *mPtr; // Should not be nullptr except for dummy initialization
		};

		// ---------------------------------------------------------------------------
		// The following classes are used for merging into the Merger's buffer.

		class AbstractEntry {
		public:
		virtual ~AbstractEntry() {}
		@@ -175,6 +166,17 @@ private:
		const uint8_t *mEntry;
		};

		// API for handling format entry operations

		// a formatted entry has the following structure:
		// * START_FMT entry, containing the format string
		// * TIMESTAMP entry
		// * HASH entry
		// * author entry of the thread that generated it (optional, present in merged log)
		// * format arg1
		// * format arg2
		// * ...
		// * END_FMT entry
		class FormatEntry : public AbstractEntry {
		public:
		// explicit FormatEntry(const EntryIterator &it);
		@@ -226,7 +228,16 @@ private:

		// ---------------------------------------------------------------------------

		// representation of a single log entry in private memory
		// 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
		class Entry {
		public:
		Entry(Event event, const void *data, size_t length)
		@@ -267,24 +278,6 @@ private:
		int value;
		}; //TODO __attribute__((packed));

		// 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

		static void appendInt(String8 body, const void data);
		static void appendFloat(String8 body, const void data);
		static void appendPID(String8 body, const void data, size_t length);
		static void appendTimestamp(String8 body, const void data);
		static size_t fmtEntryLength(const uint8_t *data);
		static String8 bufferDump(const uint8_t *buffer, size_t size);
		static String8 bufferDump(const EntryIterator &it);
		public:

		// Located in shared memory, must be POD.
		@@ -420,76 +413,56 @@ public:

		// ---------------------------------------------------------------------------

		class Reader : public RefBase {
		public:
		// A snapshot of a readers buffer
		// This is raw data. No analysis has been done on it
		class Snapshot {
		public:
		Snapshot() : mData(NULL), mLost(0) {}
		Snapshot() = default;

		Snapshot(size_t bufferSize) : mData(new uint8_t[bufferSize]) {}
		explicit Snapshot(size_t bufferSize) : mData(new uint8_t[bufferSize]) {}

		~Snapshot() { delete[] mData; }

		// copy of the buffer
		uint8_t *data() const { return mData; }

		// amount of data lost (given by audio_utils_fifo_reader)
		size_t lost() const { return mLost; }

		// iterator to beginning of readable segment of snapshot
		// data between begin and end has valid entries
		EntryIterator begin() { return mBegin; }
		EntryIterator begin() const { return mBegin; }

		// iterator to end of readable segment of snapshot
		EntryIterator end() { return mEnd; }
		EntryIterator end() const { return mEnd; }

		private:
		friend class Reader;
		uint8_t *mData;
		size_t mLost;
		uint8_t * const mData{};
		size_t mLost{0};
		EntryIterator mBegin;
		EntryIterator mEnd;
		};

		class Reader : public RefBase {
		public:
		// Input parameter 'size' is the desired size of the timeline in byte units.
		// The size of the shared memory must be at least Timeline::sharedSize(size).
		Reader(const void *shared, size_t size, const std::string &name);
		Reader(const sp<IMemory>& iMemory, size_t size, const std::string &name);

		virtual ~Reader();

		// get snapshot of readers fifo buffer, effectively consuming the buffer
		std::unique_ptr<Snapshot> getSnapshot();
		// dump a particular snapshot of the reader
		void dump(int fd, size_t indent, Snapshot &snap);
		// dump the current content of the reader's buffer (call getSnapshot() and previous dump())
		void dump(int fd, size_t indent = 0);

		bool isIMemory(const sp<IMemory>& iMemory) const;

		const std::string &name() const { return mName; }

		protected:
		// print a summary of the performance to the console
		void dumpLine(const String8 timestamp, String8 body);
		EntryIterator handleFormat(const FormatEntry &fmtEntry,
		String8 *timestamp,
		String8 *body);
		int mFd; // file descriptor
		int mIndent; // indentation level
		int mLost; // bytes of data lost before buffer was read
		const std::string mName; // name of reader (actually name of writer)
		static constexpr int kMaxObtainTries = 3;

		private:
		static constexpr int kMaxObtainTries = 3;
		// startingTypes and endingTypes are used to check for log corruption.
		static const std::unordered_set<Event> startingTypes;
		static const std::unordered_set<Event> endingTypes;

		// declared as const because audio_utils_fifo() constructor
		sp<IMemory> mIMemory; // ref-counted version, assigned only in constructor

		const std::string mName; // name of reader (actually name of writer)
		/const/ Shared* const mShared; // raw pointer to shared memory, actually const but not
		audio_utils_fifo * const mFifo; // FIFO itself,
		// non-NULL unless constructor fails
		@@ -500,9 +473,26 @@ public:
		// back has to be entry-aligned. Returns nullptr if none enconuntered.
		static const uint8_t findLastEntryOfTypes(const uint8_t front, const uint8_t *back,
		const std::unordered_set<Event> &types);
		};

		// dummy method for handling absent author entry
		virtual void handleAuthor(const AbstractEntry& /fmtEntry/, String8* /body/) {}
		class DumpReader : public Reader {
		public:
		DumpReader(const void *shared, size_t size, const std::string &name)
		: Reader(shared, size, name) {}
		DumpReader(const sp<IMemory>& iMemory, size_t size, const std::string &name)
		: Reader(iMemory, size, name) {}
		void dump(int fd, size_t indent = 0);
		private:
		void handleAuthor(const AbstractEntry& fmtEntry __unused, String8* body __unused) {}
		EntryIterator handleFormat(const FormatEntry &fmtEntry, String8 timestamp, String8 body);

		static void appendInt(String8 body, const void data);
		static void appendFloat(String8 body, const void data);
		static void appendPID(String8 body, const void data, size_t length);
		static void appendTimestamp(String8 body, const void data);
		//static size_t fmtEntryLength(const uint8_t *data); // TODO Eric remove if not used
		static String8 bufferDump(const uint8_t *buffer, size_t size);
		static String8 bufferDump(const EntryIterator &it);
		};

		// ---------------------------------------------------------------------------
		@@ -542,7 +532,7 @@ public:

		void dump(int fd, int indent = 0);
		// process a particular snapshot of the reader
		void getAndProcessSnapshot(Snapshot & snap);
		void getAndProcessSnapshot(Snapshot &snap, int author);
		// call getSnapshot of the content of the reader's buffer and process the data
		void getAndProcessSnapshot();

services/medialog/MediaLogService.cpp

+12 −10

Original line number	Diff line number	Diff line
		@@ -58,9 +58,10 @@ void MediaLogService::registerWriter(const sp<IMemory>& shared, size_t size, con
		shared->size() < NBLog::Timeline::sharedSize(size)) {
		return;
		}
		sp<NBLog::Reader> reader(new NBLog::Reader(shared, size, name));
		sp<NBLog::Reader> reader(new NBLog::Reader(shared, size, name)); // Reader handled by merger
		sp<NBLog::DumpReader> dumpReader(new NBLog::DumpReader(shared, size, name)); // for dumpsys
		Mutex::Autolock _l(mLock);
		mReaders.add(reader);
		mDumpReaders.add(dumpReader);
		mMerger.addReader(reader);
		}

		@@ -70,9 +71,10 @@ void MediaLogService::unregisterWriter(const sp<IMemory>& shared)
		return;
		}
		Mutex::Autolock _l(mLock);
		for (size_t i = 0; i < mReaders.size(); ) {
		if (mReaders[i]->isIMemory(shared)) {
		mReaders.removeAt(i);
		for (size_t i = 0; i < mDumpReaders.size(); ) {
		if (mDumpReaders[i]->isIMemory(shared)) {
		mDumpReaders.removeAt(i);
		// TODO mMerger.removeReaders(shared)
		} else {
		i++;
		}
		@@ -120,18 +122,18 @@ status_t MediaLogService::dump(int fd, const Vector<String16>& args __unused)
		return NO_ERROR;
		}

		for (auto reader : mReaders) {
		for (const auto &dumpReader : mDumpReaders) {
		if (fd >= 0) {
		dprintf(fd, "\n%s:\n", reader->name().c_str());
		reader->dump(fd, 0 /indent/);
		dprintf(fd, "\n%s:\n", dumpReader->name().c_str());
		dumpReader->dump(fd, 0 /indent/);
		} else {
		ALOGI("%s:", reader->name().c_str());
		ALOGI("%s:", dumpReader->name().c_str());
		}
		}
		mLock.unlock();
		}
		}
		//mMergeReader.dump(fd);
		mMergeReader.dump(fd);
		return NO_ERROR;
		}

services/medialog/MediaLogService.h

+1 −1

Original line number	Diff line number	Diff line
		@@ -55,7 +55,7 @@ private:

		Mutex mLock;

		Vector<sp<NBLog::Reader>> mReaders; // protected by mLock
		Vector<sp<NBLog::DumpReader>> mDumpReaders; // protected by mLock

		// FIXME Need comments on all of these, especially about locking
		NBLog::Shared *mMergerShared;