logd: Add minimum time bucket statistics (e457b74c) · Commits · e / os / android_system_core

logd/LogBuffer.cpp

+19 −2

Original line number	Original line	Diff line number	Diff line
	@@ -37,11 +37,11 @@
	LogBuffer::LogBuffer(LastLogTimes *times)		LogBuffer::LogBuffer(LastLogTimes *times)
	: mTimes(*times) {		: mTimes(*times) {
	pthread_mutex_init(&mLogElementsLock, NULL);		pthread_mutex_init(&mLogElementsLock, NULL);
	#ifdef USERDEBUG_BUILD		dgram_qlen_statistics = false;

	log_id_for_each(i) {		log_id_for_each(i) {
	mMaxSize[i] = LOG_BUFFER_SIZE;		mMaxSize[i] = LOG_BUFFER_SIZE;
	}		}
	#endif
	}		}

	void LogBuffer::log(log_id_t log_id, log_time realtime,		void LogBuffer::log(log_id_t log_id, log_time realtime,
	@@ -61,6 +61,23 @@ void LogBuffer::log(log_id_t log_id, log_time realtime,
	LogBufferElementCollection::iterator last = it;		LogBufferElementCollection::iterator last = it;
	while (--it != mLogElements.begin()) {		while (--it != mLogElements.begin()) {
	if ((*it)->getRealTime() <= realtime) {		if ((*it)->getRealTime() <= realtime) {
			// halves the peak performance, use with caution
			if (dgram_qlen_statistics) {
			LogBufferElementCollection::iterator ib = it;
			unsigned short buckets, num = 1;
			for (unsigned short i = 0; (buckets = stats.dgram_qlen(i)); ++i) {
			buckets -= num;
			num += buckets;
			while (buckets && (--ib != mLogElements.begin())) {
			--buckets;
			}
			if (buckets) {
			break;
			}
			stats.recordDiff(
			elem->getRealTime() - (*ib)->getRealTime(), i);
			}
			}
	break;		break;
	}		}
	last = it;		last = it;

logd/LogBuffer.h

+7 −0

Original line number	Original line	Diff line number	Diff line
	@@ -36,6 +36,8 @@ class LogBuffer {

	LogStatistics stats;		LogStatistics stats;

			bool dgram_qlen_statistics;

	#ifdef USERDEBUG_BUILD		#ifdef USERDEBUG_BUILD
	PruneList mPrune;		PruneList mPrune;

	@@ -64,6 +66,11 @@ public:
	// *strp uses malloc, use free to release.		// *strp uses malloc, use free to release.
	void formatStatistics(char **strp, uid_t uid, unsigned int logMask);		void formatStatistics(char **strp, uid_t uid, unsigned int logMask);

			void enableDgramQlenStatistics() {
			stats.enableDgramQlenStatistics();
			dgram_qlen_statistics = true;
			}

	#ifdef USERDEBUG_BUILD		#ifdef USERDEBUG_BUILD
	int initPrune(char *cp) { return mPrune.init(cp); }		int initPrune(char *cp) { return mPrune.init(cp); }
	// *strp uses malloc, use free to release.		// *strp uses malloc, use free to release.

logd/LogStatistics.cpp

+133 −3

Original line number	Original line	Diff line number	Diff line
	@@ -275,6 +275,66 @@ LogStatistics::LogStatistics()
	mSizes[i] = 0;		mSizes[i] = 0;
	mElements[i] = 0;		mElements[i] = 0;
	}		}

			dgram_qlen_statistics = false;
			for(unsigned short bucket = 0; dgram_qlen(bucket); ++bucket) {
			mMinimum[bucket].tv_sec = (uint32_t)-1;
			mMinimum[bucket].tv_nsec = 999999999UL;
			}
			}

			// Each bucket below represents a dgram_qlen of log messages. By
			// finding the minimum period of time from start to finish
			// of each dgram_qlen, we can get a performance expectation for
			// the user space logger. The net result is that the period
			// of time divided by the dgram_qlen will give us the average time
			// between log messages; at the point where the average time
			// is greater than the throughput capability of the logger
			// we will not longer require the benefits of the FIFO formed
			// by max_dgram_qlen. We will also expect to see a very visible
			// knee in the average time between log messages at this point,
			// so we do not necessarily have to compare the rate against the
			// measured performance (BM_log_maximum_retry) of the logger.
			//
			// for example (reformatted):
			//
			// Minimum time between log events per dgram_qlen:
			// 1 2 3 5 10 20 30 50 100 200 300 400 500 600
			// 5u2 12u 13u 15u 16u 27u 30u 36u 407u 3m1 3m3 3m9 3m9 5m5
			//
			// demonstrates a clear knee rising at 100, so this means that for this
			// case max_dgram_qlen = 100 would be more than sufficient to handle the
			// worst that the system could stuff into the logger. The
			// BM_log_maximum_retry performance (derated by the log collection) on the
			// same system was 33.2us so we would almost be fine with max_dgram_qlen = 50.
			// BM_log_maxumum_retry with statistics off is roughly 20us, so
			// max_dgram_qlen = 20 would work. We will be more than willing to have
			// a large engineering margin so the rule of thumb that lead us to 100 is
			// fine.
			//
			// bucket dgram_qlen are tuned for /proc/sys/net/unix/max_dgram_qlen = 300
			const unsigned short LogStatistics::mBuckets[] = {
			1, 2, 3, 5, 10, 20, 30, 50, 100, 200, 300, 400, 500, 600
			};

			unsigned short LogStatistics::dgram_qlen(unsigned short bucket) {
			if (bucket >= sizeof(mBuckets) / sizeof(mBuckets[0])) {
			return 0;
			}
			return mBuckets[bucket];
			}

			unsigned long long LogStatistics::minimum(unsigned short bucket) {
			if (mMinimum[bucket].tv_sec == LONG_MAX) {
			return 0;
			}
			return mMinimum[bucket].nsec();
			}

			void LogStatistics::recordDiff(log_time diff, unsigned short bucket) {
			if ((diff.tv_sec \|\| diff.tv_nsec) && (mMinimum[bucket] > diff)) {
			mMinimum[bucket] = diff;
			}
	}		}

	void LogStatistics::add(unsigned short size,		void LogStatistics::add(unsigned short size,
	@@ -352,6 +412,9 @@ void LogStatistics::format(char **buf,
	log_id_for_each(i) {		log_id_for_each(i) {
	if (logMask & (1 << i)) {		if (logMask & (1 << i)) {
	oldLength = string.length();		oldLength = string.length();
			if (spaces < 0) {
			spaces = 0;
			}
	string.appendFormat("%*s%s", spaces, "", android_log_id_to_name(i));		string.appendFormat("%*s%s", spaces, "", android_log_id_to_name(i));
	spaces += spaces_total + oldLength - string.length();		spaces += spaces_total + oldLength - string.length();
	}		}
	@@ -369,6 +432,9 @@ void LogStatistics::format(char **buf,
	continue;		continue;
	}		}
	oldLength = string.length();		oldLength = string.length();
			if (spaces < 0) {
			spaces = 0;
			}
	string.appendFormat("%*s%zu/%zu", spaces, "",		string.appendFormat("%*s%zu/%zu", spaces, "",
	sizesTotal(i), elementsTotal(i));		sizesTotal(i), elementsTotal(i));
	spaces += spaces_total + oldLength - string.length();		spaces += spaces_total + oldLength - string.length();
	@@ -388,12 +454,64 @@ void LogStatistics::format(char **buf,
	size_t els = elements(i);		size_t els = elements(i);
	if (els) {		if (els) {
	oldLength = string.length();		oldLength = string.length();
			if (spaces < 0) {
			spaces = 0;
			}
	string.appendFormat("%*s%zu/%zu", spaces, "", sizes(i), els);		string.appendFormat("%*s%zu/%zu", spaces, "", sizes(i), els);
	spaces -= string.length() - oldLength;		spaces -= string.length() - oldLength;
	}		}
	spaces += spaces_total;		spaces += spaces_total;
	}		}

			if (dgram_qlen_statistics) {
			const unsigned short spaces_time = 6;
			const unsigned long long max_seconds = 100000;
			spaces = 0;
			string.append("\n\nMinimum time between log events per dgram_qlen:\n");
			for(unsigned short i = 0; dgram_qlen(i); ++i) {
			oldLength = string.length();
			if (spaces < 0) {
			spaces = 0;
			}
			string.appendFormat("%*s%u", spaces, "", dgram_qlen(i));
			spaces += spaces_time + oldLength - string.length();
			}
			string.append("\n");
			spaces = 0;
			unsigned short n;
			for(unsigned short i = 0; (n = dgram_qlen(i)); ++i) {
			unsigned long long duration = minimum(i);
			if (duration) {
			duration /= n;
			if (duration >= (NS_PER_SEC * max_seconds)) {
			duration = NS_PER_SEC * (max_seconds - 1);
			}
			oldLength = string.length();
			if (spaces < 0) {
			spaces = 0;
			}
			string.appendFormat("%*s", spaces, "");
			if (duration >= (NS_PER_SEC * 10)) {
			string.appendFormat("%llu",
			(duration + (NS_PER_SEC / 2))
			/ NS_PER_SEC);
			} else if (duration >= (NS_PER_SEC / (1000 / 10))) {
			string.appendFormat("%llum",
			(duration + (NS_PER_SEC / 2 / 1000))
			/ (NS_PER_SEC / 1000));
			} else if (duration >= (NS_PER_SEC / (1000000 / 10))) {
			string.appendFormat("%lluu",
			(duration + (NS_PER_SEC / 2 / 1000000))
			/ (NS_PER_SEC / 1000000));
			} else {
			string.appendFormat("%llun", duration);
			}
			spaces -= string.length() - oldLength;
			}
			spaces += spaces_time;
			}
			}

	log_id_for_each(i) {		log_id_for_each(i) {
	if (!(logMask & (1 << i))) {		if (!(logMask & (1 << i))) {
	continue;		continue;
	@@ -433,7 +551,7 @@ void LogStatistics::format(char **buf,

	if (!oneline) {		if (!oneline) {
	first = true;		first = true;
	} else if (!first && spaces) {		} else if (!first && (spaces > 0)) {
	string.appendFormat("%*s", spaces, "");		string.appendFormat("%*s", spaces, "");
	}		}
	spaces = 0;		spaces = 0;
	@@ -458,10 +576,16 @@ void LogStatistics::format(char **buf,

	size_t els = up->elements();		size_t els = up->elements();
	if (els == elsTotal) {		if (els == elsTotal) {
			if (spaces < 0) {
			spaces = 0;
			}
	string.appendFormat("%*s=", spaces, "");		string.appendFormat("%*s=", spaces, "");
	spaces = -1;		spaces = -1;
	} else if (els) {		} else if (els) {
	oldLength = string.length();		oldLength = string.length();
			if (spaces < 0) {
			spaces = 0;
			}
	string.appendFormat("%*s%zu/%zu", spaces, "", up->sizes(), els);		string.appendFormat("%*s%zu/%zu", spaces, "", up->sizes(), els);
	spaces -= string.length() - oldLength;		spaces -= string.length() - oldLength;
	}		}
	@@ -502,7 +626,7 @@ void LogStatistics::format(char **buf,
	continue;		continue;
	}		}

	if (!first && spaces) {		if (!first && (spaces > 0)) {
	string.appendFormat("%*s", spaces, "");		string.appendFormat("%*s", spaces, "");
	}		}
	spaces = 0;		spaces = 0;
	@@ -517,10 +641,16 @@ void LogStatistics::format(char **buf,
	spaces += spaces_total + oldLength - string.length();		spaces += spaces_total + oldLength - string.length();

	if (els == elsTotal) {		if (els == elsTotal) {
			if (spaces < 0) {
			spaces = 0;
			}
	string.appendFormat("%*s=", spaces, "");		string.appendFormat("%*s=", spaces, "");
	spaces = -1;		spaces = -1;
	} else if (els) {		} else if (els) {
	oldLength = string.length();		oldLength = string.length();
			if (spaces < 0) {
			spaces = 0;
			}
	string.appendFormat("%*s%zu/%zu", spaces, "",		string.appendFormat("%*s%zu/%zu", spaces, "",
	pp->sizes(), els);		pp->sizes(), els);
	spaces -= string.length() - oldLength;		spaces -= string.length() - oldLength;
	@@ -531,7 +661,7 @@ void LogStatistics::format(char **buf,
	}		}

	if (gone_els) {		if (gone_els) {
	if (!first && spaces) {		if (!first && (spaces > 0)) {
	string.appendFormat("%*s", spaces, "");		string.appendFormat("%*s", spaces, "");
	}		}

logd/LogStatistics.h

+10 −0

Original line number	Original line	Diff line number	Diff line
	@@ -114,6 +114,11 @@ class LogStatistics {
	size_t mSizes[LOG_ID_MAX];		size_t mSizes[LOG_ID_MAX];
	size_t mElements[LOG_ID_MAX];		size_t mElements[LOG_ID_MAX];

			bool dgram_qlen_statistics;

			static const unsigned short mBuckets[14];
			log_time mMinimum[sizeof(mBuckets) / sizeof(mBuckets[0])];

	public:		public:
	const log_time start;		const log_time start;

	@@ -121,6 +126,11 @@ public:

	LidStatistics &id(log_id_t log_id) { return LogIds[log_id]; }		LidStatistics &id(log_id_t log_id) { return LogIds[log_id]; }

			void enableDgramQlenStatistics() { dgram_qlen_statistics = true; }
			static unsigned short dgram_qlen(unsigned short bucket);
			unsigned long long minimum(unsigned short bucket);
			void recordDiff(log_time diff, unsigned short bucket);

	void add(unsigned short size, log_id_t log_id, uid_t uid, pid_t pid);		void add(unsigned short size, log_id_t log_id, uid_t uid, pid_t pid);
	void subtract(unsigned short size, log_id_t log_id, uid_t uid, pid_t pid);		void subtract(unsigned short size, log_id_t log_id, uid_t uid, pid_t pid);

logd/main.cpp

+9 −0

Original line number	Original line	Diff line number	Diff line
	@@ -24,9 +24,12 @@
	#include <sys/capability.h>		#include <sys/capability.h>
	#include <sys/stat.h>		#include <sys/stat.h>
	#include <sys/types.h>		#include <sys/types.h>
			#include <unistd.h>

	#include <linux/prctl.h>		#include <linux/prctl.h>

			#include <cutils/properties.h>

	#include "private/android_filesystem_config.h"		#include "private/android_filesystem_config.h"
	#include "CommandListener.h"		#include "CommandListener.h"
	#include "LogBuffer.h"		#include "LogBuffer.h"
	@@ -92,6 +95,12 @@ int main() {

	LogBuffer *logBuf = new LogBuffer(times);		LogBuffer *logBuf = new LogBuffer(times);

			char dgram_qlen_statistics[PROPERTY_VALUE_MAX];
			property_get("logd.dgram_qlen.statistics", dgram_qlen_statistics, "");
			if (atol(dgram_qlen_statistics)) {
			logBuf->enableDgramQlenStatistics();
			}

	// LogReader listens on /dev/socket/logdr. When a client		// LogReader listens on /dev/socket/logdr. When a client
	// connects, log entries in the LogBuffer are written to the client.		// connects, log entries in the LogBuffer are written to the client.