summaryrefslogtreecommitdiffstats
path: root/logd
diff options
context:
space:
mode:
Diffstat (limited to 'logd')
-rw-r--r--logd/LogBuffer.cpp21
-rw-r--r--logd/LogBuffer.h7
-rw-r--r--logd/LogStatistics.cpp136
-rw-r--r--logd/LogStatistics.h10
-rw-r--r--logd/main.cpp9
5 files changed, 178 insertions, 5 deletions
diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index 1c5cef03b..aa4426408 100644
--- a/logd/LogBuffer.cpp
+++ b/logd/LogBuffer.cpp
@@ -37,11 +37,11 @@
LogBuffer::LogBuffer(LastLogTimes *times)
: mTimes(*times) {
pthread_mutex_init(&mLogElementsLock, NULL);
-#ifdef USERDEBUG_BUILD
+ dgram_qlen_statistics = false;
+
log_id_for_each(i) {
mMaxSize[i] = LOG_BUFFER_SIZE;
}
-#endif
}
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;
while (--it != mLogElements.begin()) {
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;
}
last = it;
diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h
index cbbb2ce3e..c3460cadf 100644
--- a/logd/LogBuffer.h
+++ b/logd/LogBuffer.h
@@ -36,6 +36,8 @@ class LogBuffer {
LogStatistics stats;
+ bool dgram_qlen_statistics;
+
#ifdef USERDEBUG_BUILD
PruneList mPrune;
@@ -64,6 +66,11 @@ public:
// *strp uses malloc, use free to release.
void formatStatistics(char **strp, uid_t uid, unsigned int logMask);
+ void enableDgramQlenStatistics() {
+ stats.enableDgramQlenStatistics();
+ dgram_qlen_statistics = true;
+ }
+
#ifdef USERDEBUG_BUILD
int initPrune(char *cp) { return mPrune.init(cp); }
// *strp uses malloc, use free to release.
diff --git a/logd/LogStatistics.cpp b/logd/LogStatistics.cpp
index 49ee50d0a..5622ee5b1 100644
--- a/logd/LogStatistics.cpp
+++ b/logd/LogStatistics.cpp
@@ -275,6 +275,66 @@ LogStatistics::LogStatistics()
mSizes[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,
@@ -352,6 +412,9 @@ void LogStatistics::format(char **buf,
log_id_for_each(i) {
if (logMask & (1 << i)) {
oldLength = string.length();
+ if (spaces < 0) {
+ spaces = 0;
+ }
string.appendFormat("%*s%s", spaces, "", android_log_id_to_name(i));
spaces += spaces_total + oldLength - string.length();
}
@@ -369,6 +432,9 @@ void LogStatistics::format(char **buf,
continue;
}
oldLength = string.length();
+ if (spaces < 0) {
+ spaces = 0;
+ }
string.appendFormat("%*s%zu/%zu", spaces, "",
sizesTotal(i), elementsTotal(i));
spaces += spaces_total + oldLength - string.length();
@@ -388,12 +454,64 @@ void LogStatistics::format(char **buf,
size_t els = elements(i);
if (els) {
oldLength = string.length();
+ if (spaces < 0) {
+ spaces = 0;
+ }
string.appendFormat("%*s%zu/%zu", spaces, "", sizes(i), els);
spaces -= string.length() - oldLength;
}
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) {
if (!(logMask & (1 << i))) {
continue;
@@ -433,7 +551,7 @@ void LogStatistics::format(char **buf,
if (!oneline) {
first = true;
- } else if (!first && spaces) {
+ } else if (!first && (spaces > 0)) {
string.appendFormat("%*s", spaces, "");
}
spaces = 0;
@@ -458,10 +576,16 @@ void LogStatistics::format(char **buf,
size_t els = up->elements();
if (els == elsTotal) {
+ if (spaces < 0) {
+ spaces = 0;
+ }
string.appendFormat("%*s=", spaces, "");
spaces = -1;
} else if (els) {
oldLength = string.length();
+ if (spaces < 0) {
+ spaces = 0;
+ }
string.appendFormat("%*s%zu/%zu", spaces, "", up->sizes(), els);
spaces -= string.length() - oldLength;
}
@@ -502,7 +626,7 @@ void LogStatistics::format(char **buf,
continue;
}
- if (!first && spaces) {
+ if (!first && (spaces > 0)) {
string.appendFormat("%*s", spaces, "");
}
spaces = 0;
@@ -517,10 +641,16 @@ void LogStatistics::format(char **buf,
spaces += spaces_total + oldLength - string.length();
if (els == elsTotal) {
+ if (spaces < 0) {
+ spaces = 0;
+ }
string.appendFormat("%*s=", spaces, "");
spaces = -1;
} else if (els) {
oldLength = string.length();
+ if (spaces < 0) {
+ spaces = 0;
+ }
string.appendFormat("%*s%zu/%zu", spaces, "",
pp->sizes(), els);
spaces -= string.length() - oldLength;
@@ -531,7 +661,7 @@ void LogStatistics::format(char **buf,
}
if (gone_els) {
- if (!first && spaces) {
+ if (!first && (spaces > 0)) {
string.appendFormat("%*s", spaces, "");
}
diff --git a/logd/LogStatistics.h b/logd/LogStatistics.h
index d44afa2f6..6a2626316 100644
--- a/logd/LogStatistics.h
+++ b/logd/LogStatistics.h
@@ -114,6 +114,11 @@ class LogStatistics {
size_t mSizes[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:
const log_time start;
@@ -121,6 +126,11 @@ public:
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 subtract(unsigned short size, log_id_t log_id, uid_t uid, pid_t pid);
diff --git a/logd/main.cpp b/logd/main.cpp
index 6216b95c3..8792d3224 100644
--- a/logd/main.cpp
+++ b/logd/main.cpp
@@ -24,9 +24,12 @@
#include <sys/capability.h>
#include <sys/stat.h>
#include <sys/types.h>
+#include <unistd.h>
#include <linux/prctl.h>
+#include <cutils/properties.h>
+
#include "private/android_filesystem_config.h"
#include "CommandListener.h"
#include "LogBuffer.h"
@@ -92,6 +95,12 @@ int main() {
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
// connects, log entries in the LogBuffer are written to the client.
generated by cgit v1.2.3 (git 2.25.1) at 2025-04-27 16:51:23 +0000