Revert "logd: Add minimum time bucket statistics"
This forward port reverts
commit e457b74ce6ee6d799812dc2ec5e4b8b18bcd3e91
No longer as necessary once we add
liblog: Instrument logging of logd write drops
Although this provided an indication of how close statistically we
were to overloading logd it is simpler to understand fails thus to
hunt and peck a corrected value for /proc/sys/net/unix/max_dgram_qlen
Change-Id: I2b30e0fc30625a48fd11a12c2d2cc6a41f26226f
diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index 3d0b38f..edda6c4 100644
--- a/logd/LogBuffer.cpp
+++ b/logd/LogBuffer.cpp
@@ -93,8 +93,7 @@
}
LogBuffer::LogBuffer(LastLogTimes *times)
- : dgramQlenStatistics(false)
- , mTimes(*times) {
+ : mTimes(*times) {
pthread_mutex_init(&mLogElementsLock, NULL);
static const char global_tuneable[] = "persist.logd.size"; // Settings App
@@ -150,23 +149,6 @@
while (last != mLogElements.begin()) {
--it;
if ((*it)->getRealTime() <= realtime) {
- // halves the peak performance, use with caution
- if (dgramQlenStatistics) {
- LogBufferElementCollection::iterator ib = it;
- unsigned short buckets, num = 1;
- for (unsigned short i = 0; (buckets = stats.dgramQlen(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 879baea..b0003de 100644
--- a/logd/LogBuffer.h
+++ b/logd/LogBuffer.h
@@ -37,7 +37,6 @@
pthread_mutex_t mLogElementsLock;
LogStatistics stats;
- bool dgramQlenStatistics;
PruneList mPrune;
@@ -63,11 +62,6 @@
// *strp uses malloc, use free to release.
void formatStatistics(char **strp, uid_t uid, unsigned int logMask);
- void enableDgramQlenStatistics() {
- stats.enableDgramQlenStatistics();
- dgramQlenStatistics = true;
- }
-
void enableStatistics() {
stats.enableStatistics();
}
diff --git a/logd/LogStatistics.cpp b/logd/LogStatistics.cpp
index 53036e6..5a70689 100644
--- a/logd/LogStatistics.cpp
+++ b/logd/LogStatistics.cpp
@@ -395,71 +395,11 @@
LogStatistics::LogStatistics()
: mStatistics(false)
- , dgramQlenStatistics(false)
, start(CLOCK_MONOTONIC) {
log_id_for_each(i) {
mSizes[i] = 0;
mElements[i] = 0;
}
-
- for(unsigned short bucket = 0; dgramQlen(bucket); ++bucket) {
- mMinimum[bucket].tv_sec = mMinimum[bucket].tv_sec_max;
- mMinimum[bucket].tv_nsec = mMinimum[bucket].tv_nsec_max;
- }
-}
-
-// Each bucket below represents a dgramQlen of log messages. By
-// finding the minimum period of time from start to finish
-// of each dgramQlen, we can get a performance expectation for
-// the user space logger. The net result is that the period
-// of time divided by the dgramQlen 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 dgramQlen:
-// 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 dgramQlen 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::dgramQlen(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 == mMinimum[bucket].tv_sec_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,
@@ -709,55 +649,6 @@
pids.clear();
}
- if (dgramQlenStatistics) {
- const unsigned short spaces_time = 6;
- const unsigned long long max_seconds = 100000;
- spaces = 0;
- string.append("\n\nMinimum time between log events per max_dgram_qlen:\n");
- for(unsigned short i = 0; dgramQlen(i); ++i) {
- oldLength = string.length();
- if (spaces < 0) {
- spaces = 0;
- }
- string.appendFormat("%*s%u", spaces, "", dgramQlen(i));
- spaces += spaces_time + oldLength - string.length();
- }
- string.append("\n");
- spaces = 0;
- unsigned short n;
- for(unsigned short i = 0; (n = dgramQlen(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;
diff --git a/logd/LogStatistics.h b/logd/LogStatistics.h
index f6c4329..f892cd0 100644
--- a/logd/LogStatistics.h
+++ b/logd/LogStatistics.h
@@ -145,7 +145,6 @@
size_t mElements[LOG_ID_MAX];
bool mStatistics;
- bool dgramQlenStatistics;
static const unsigned short mBuckets[14];
log_time mMinimum[sizeof(mBuckets) / sizeof(mBuckets[0])];
@@ -157,11 +156,7 @@
LidStatistics &id(log_id_t log_id) { return LogIds[log_id]; }
- void enableDgramQlenStatistics() { dgramQlenStatistics = true; }
void enableStatistics() { mStatistics = true; }
- static unsigned short dgramQlen(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/README.property b/logd/README.property
index b7fcece..60542b2 100644
--- a/logd/README.property
+++ b/logd/README.property
@@ -7,12 +7,6 @@
logd.statistics bool depends Enable logcat -S statistics.
ro.config.low_ram bool false if true, logd.statistics default false
ro.build.type string if user, logd.statistics default false
-logd.statistics.dgram_qlen bool false Record dgram_qlen statistics. This
- represents a performance impact and
- is used to determine the platform's
- minimum domain socket network FIFO
- size (see source for details) based
- on typical load (logcat -S to view)
persist.logd.size number 256K default size of the buffer for all
log ids at initial startup, at runtime
use: logcat -b all -G <value>
diff --git a/logd/main.cpp b/logd/main.cpp
index 7a1ae54..243bee4 100644
--- a/logd/main.cpp
+++ b/logd/main.cpp
@@ -155,9 +155,6 @@
LogBuffer *logBuf = new LogBuffer(times);
- if (property_get_bool("logd.statistics.dgram_qlen", false)) {
- logBuf->enableDgramQlenStatistics();
- }
{
char property[PROPERTY_VALUE_MAX];
property_get("ro.build.type", property, "");
diff --git a/logd/tests/logd_test.cpp b/logd/tests/logd_test.cpp
index 96877a9..46bd9c0 100644
--- a/logd/tests/logd_test.cpp
+++ b/logd/tests/logd_test.cpp
@@ -192,164 +192,6 @@
EXPECT_TRUE(NULL != events_logs);
#endif
- // Parse timing stats
-
- cp = strstr(cp, "Minimum time between log events per dgram_qlen:");
-
- if (cp) {
- while (*cp && (*cp != '\n')) {
- ++cp;
- }
- if (*cp == '\n') {
- ++cp;
- }
-
- char *list_of_spans = cp;
- EXPECT_NE('\0', *list_of_spans);
-
- unsigned short number_of_buckets = 0;
- unsigned short *dgram_qlen = NULL;
- unsigned short bucket = 0;
- while (*cp && (*cp != '\n')) {
- bucket = 0;
- while (isdigit(*cp)) {
- bucket = bucket * 10 + *cp - '0';
- ++cp;
- }
- while (*cp == ' ') {
- ++cp;
- }
- if (!bucket) {
- break;
- }
- unsigned short *new_dgram_qlen = new unsigned short[number_of_buckets + 1];
- EXPECT_TRUE(new_dgram_qlen != NULL);
- if (dgram_qlen) {
- memcpy(new_dgram_qlen, dgram_qlen, sizeof(*dgram_qlen) * number_of_buckets);
- delete [] dgram_qlen;
- }
-
- dgram_qlen = new_dgram_qlen;
- dgram_qlen[number_of_buckets++] = bucket;
- }
-
- char *end_of_spans = cp;
- EXPECT_NE('\0', *end_of_spans);
-
- EXPECT_LT(5, number_of_buckets);
-
- unsigned long long *times = new unsigned long long [number_of_buckets];
- ASSERT_TRUE(times != NULL);
-
- memset(times, 0, sizeof(*times) * number_of_buckets);
-
- while (*cp == '\n') {
- ++cp;
- }
-
- unsigned short number_of_values = 0;
- unsigned long long value;
- while (*cp && (*cp != '\n')) {
- EXPECT_GE(number_of_buckets, number_of_values);
-
- value = 0;
- while (isdigit(*cp)) {
- value = value * 10ULL + *cp - '0';
- ++cp;
- }
-
- switch(*cp) {
- case ' ':
- case '\n':
- value *= 1000ULL;
- /* FALLTHRU */
- case 'm':
- value *= 1000ULL;
- /* FALLTHRU */
- case 'u':
- value *= 1000ULL;
- /* FALLTHRU */
- case 'n':
- default:
- break;
- }
- while (*++cp == ' ');
-
- if (!value) {
- break;
- }
-
- times[number_of_values] = value;
- ++number_of_values;
- }
-
-#ifdef TARGET_USES_LOGD
- EXPECT_EQ(number_of_values, number_of_buckets);
-#endif
-
- FILE *fp;
- ASSERT_TRUE(NULL != (fp = fopen("/proc/sys/net/unix/max_dgram_qlen", "r")));
-
- unsigned max_dgram_qlen = 0;
- fscanf(fp, "%u", &max_dgram_qlen);
-
- fclose(fp);
-
- // Find launch point
- unsigned short launch = 0;
- unsigned long long total = 0;
- do {
- total += times[launch];
- } while (((++launch < number_of_buckets)
- && ((total / launch) >= (times[launch] / 8ULL)))
- || (launch == 1)); // too soon
-
- bool failure = number_of_buckets <= launch;
- if (!failure) {
- unsigned short l = launch;
- if (l >= number_of_buckets) {
- l = number_of_buckets - 1;
- }
- failure = max_dgram_qlen < dgram_qlen[l];
- }
-
- // We can get failure if at any time liblog_benchmarks has been run
- // because designed to overload /proc/sys/net/unix/max_dgram_qlen even
- // at excessive values like 20000. It does so to measure the raw processing
- // performance of logd.
- if (failure) {
- cp = find_benchmark_spam(cp);
- }
-
- if (cp) {
- // Fake a failure, but without the failure code
- if (number_of_buckets <= launch) {
- printf ("Expected: number_of_buckets > launch, actual: %u vs %u\n",
- number_of_buckets, launch);
- }
- if (launch >= number_of_buckets) {
- launch = number_of_buckets - 1;
- }
- if (max_dgram_qlen < dgram_qlen[launch]) {
- printf ("Expected: max_dgram_qlen >= dgram_qlen[%d],"
- " actual: %u vs %u\n",
- launch, max_dgram_qlen, dgram_qlen[launch]);
- }
- } else
-#ifndef TARGET_USES_LOGD
- if (total)
-#endif
- {
- EXPECT_GT(number_of_buckets, launch);
- if (launch >= number_of_buckets) {
- launch = number_of_buckets - 1;
- }
- EXPECT_GE(max_dgram_qlen, dgram_qlen[launch]);
- }
-
- delete [] dgram_qlen;
- delete [] times;
- }
delete [] buf;
}