summaryrefslogtreecommitdiffstats
path: root/logd/LogStatistics.cpp
diff options
context:
space:
mode:
Diffstat (limited to 'logd/LogStatistics.cpp')
-rw-r--r--logd/LogStatistics.cpp457
1 files changed, 414 insertions, 43 deletions
diff --git a/logd/LogStatistics.cpp b/logd/LogStatistics.cpp
index 49ee50d..81c9bab 100644
--- a/logd/LogStatistics.cpp
+++ b/logd/LogStatistics.cpp
@@ -14,6 +14,7 @@
* limitations under the License.
*/
+#include <fcntl.h>
#include <stdarg.h>
#include <time.h>
@@ -23,12 +24,50 @@
#include "LogStatistics.h"
-PidStatistics::PidStatistics(pid_t pid)
+PidStatistics::PidStatistics(pid_t pid, char *name)
: pid(pid)
, mSizesTotal(0)
, mElementsTotal(0)
, mSizes(0)
- , mElements(0) { }
+ , mElements(0)
+ , name(name)
+ , mGone(false)
+{ }
+
+#ifdef DO_NOT_ERROR_IF_PIDSTATISTICS_USES_A_COPY_CONSTRUCTOR
+PidStatistics::PidStatistics(const PidStatistics &copy)
+ : pid(copy->pid)
+ , name(copy->name ? strdup(copy->name) : NULL)
+ , mSizesTotal(copy->mSizesTotal)
+ , mElementsTotal(copy->mElementsTotal)
+ , mSizes(copy->mSizes)
+ , mElements(copy->mElements)
+ , mGone(copy->mGone)
+{ }
+#endif
+
+PidStatistics::~PidStatistics() {
+ free(name);
+}
+
+bool PidStatistics::pidGone() {
+ if (mGone) {
+ return true;
+ }
+ if (pid == gone) {
+ return true;
+ }
+ if (kill(pid, 0) && (errno != EPERM)) {
+ mGone = true;
+ return true;
+ }
+ return false;
+}
+
+void PidStatistics::setName(char *new_name) {
+ free(name);
+ name = new_name;
+}
void PidStatistics::add(unsigned short size) {
mSizesTotal += size;
@@ -40,7 +79,7 @@ void PidStatistics::add(unsigned short size) {
bool PidStatistics::subtract(unsigned short size) {
mSizes -= size;
--mElements;
- return mElements == 0 && kill(pid, 0);
+ return (mElements == 0) && pidGone();
}
void PidStatistics::addTotal(size_t size, size_t element) {
@@ -50,8 +89,32 @@ void PidStatistics::addTotal(size_t size, size_t element) {
}
}
+// must call free to release return value
+char *PidStatistics::pidToName(pid_t pid) {
+ char *retval = NULL;
+ if (pid != gone) {
+ char buffer[512];
+ snprintf(buffer, sizeof(buffer), "/proc/%u/cmdline", pid);
+ int fd = open(buffer, O_RDONLY);
+ if (fd >= 0) {
+ ssize_t ret = read(fd, buffer, sizeof(buffer));
+ if (ret > 0) {
+ buffer[sizeof(buffer)-1] = '\0';
+ // frameworks intermediate state
+ if (strcmp(buffer, "<pre-initialized>")) {
+ retval = strdup(buffer);
+ }
+ }
+ close(fd);
+ }
+ }
+ return retval;
+}
+
UidStatistics::UidStatistics(uid_t uid)
- : uid(uid) {
+ : uid(uid)
+ , mSizes(0)
+ , mElements(0) {
Pids.clear();
}
@@ -64,6 +127,9 @@ UidStatistics::~UidStatistics() {
}
void UidStatistics::add(unsigned short size, pid_t pid) {
+ mSizes += size;
+ ++mElements;
+
PidStatistics *p;
PidStatisticsCollection::iterator last;
PidStatisticsCollection::iterator it;
@@ -71,19 +137,12 @@ void UidStatistics::add(unsigned short size, pid_t pid) {
p = *it;
if (pid == p->getPid()) {
p->add(size);
- // poor-man sort, bubble upwards if bigger than last
- if ((last != it) && ((*last)->sizesTotal() < p->sizesTotal())) {
- Pids.erase(it);
- Pids.insert(last, p);
- }
return;
}
}
- // poor-man sort, insert if bigger than last or last is the gone entry.
- bool insert = (last != it)
- && ((p->getPid() == p->gone)
- || ((*last)->sizesTotal() < (size_t) size));
- p = new PidStatistics(pid);
+ // insert if the gone entry.
+ bool insert = (last != it) && (p->getPid() == p->gone);
+ p = new PidStatistics(pid, pidToName(pid));
if (insert) {
Pids.insert(last, p);
} else {
@@ -93,6 +152,9 @@ void UidStatistics::add(unsigned short size, pid_t pid) {
}
void UidStatistics::subtract(unsigned short size, pid_t pid) {
+ mSizes -= size;
+ --mElements;
+
PidStatisticsCollection::iterator it;
for (it = begin(); it != end(); ++it) {
PidStatistics *p = *it;
@@ -121,28 +183,57 @@ void UidStatistics::subtract(unsigned short size, pid_t pid) {
}
}
+void UidStatistics::sort() {
+ for (bool pass = true; pass;) {
+ pass = false;
+ PidStatisticsCollection::iterator it = begin();
+ if (it != end()) {
+ PidStatisticsCollection::iterator lt = it;
+ PidStatistics *l = (*lt);
+ while (++it != end()) {
+ PidStatistics *n = (*it);
+ if ((n->getPid() != n->gone) && (n->sizes() > l->sizes())) {
+ pass = true;
+ Pids.erase(it);
+ Pids.insert(lt, n);
+ it = lt;
+ n = l;
+ }
+ lt = it;
+ l = n;
+ }
+ }
+ }
+}
+
size_t UidStatistics::sizes(pid_t pid) {
- size_t sizes = 0;
+ if (pid == pid_all) {
+ return sizes();
+ }
+
PidStatisticsCollection::iterator it;
for (it = begin(); it != end(); ++it) {
PidStatistics *p = *it;
- if ((pid == pid_all) || (pid == p->getPid())) {
- sizes += p->sizes();
+ if (pid == p->getPid()) {
+ return p->sizes();
}
}
- return sizes;
+ return 0;
}
size_t UidStatistics::elements(pid_t pid) {
- size_t elements = 0;
+ if (pid == pid_all) {
+ return elements();
+ }
+
PidStatisticsCollection::iterator it;
for (it = begin(); it != end(); ++it) {
PidStatistics *p = *it;
- if ((pid == pid_all) || (pid == p->getPid())) {
- elements += p->elements();
+ if (pid == p->getPid()) {
+ return p->elements();
}
}
- return elements;
+ return 0;
}
size_t UidStatistics::sizesTotal(pid_t pid) {
@@ -221,6 +312,29 @@ void LidStatistics::subtract(unsigned short size, uid_t uid, pid_t pid) {
}
}
+void LidStatistics::sort() {
+ for (bool pass = true; pass;) {
+ pass = false;
+ UidStatisticsCollection::iterator it = begin();
+ if (it != end()) {
+ UidStatisticsCollection::iterator lt = it;
+ UidStatistics *l = (*lt);
+ while (++it != end()) {
+ UidStatistics *n = (*it);
+ if (n->sizes() > l->sizes()) {
+ pass = true;
+ Uids.erase(it);
+ Uids.insert(lt, n);
+ it = lt;
+ n = l;
+ }
+ lt = it;
+ l = n;
+ }
+ }
+ }
+}
+
size_t LidStatistics::sizes(uid_t uid, pid_t pid) {
size_t sizes = 0;
UidStatisticsCollection::iterator it;
@@ -275,6 +389,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 = mMinimum[bucket].tv_sec_max;
+ mMinimum[bucket].tv_nsec = mMinimum[bucket].tv_nsec_max;
+ }
+}
+
+// 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 == 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,
@@ -337,11 +511,11 @@ size_t LogStatistics::elementsTotal(log_id_t log_id, uid_t uid, pid_t pid) {
void LogStatistics::format(char **buf,
uid_t uid, unsigned int logMask, log_time oldest) {
- const unsigned short spaces_current = 13;
- const unsigned short spaces_total = 19;
+ static const unsigned short spaces_current = 13;
+ static const unsigned short spaces_total = 19;
if (*buf) {
- free(buf);
+ free(*buf);
*buf = NULL;
}
@@ -350,10 +524,22 @@ void LogStatistics::format(char **buf,
short spaces = 2;
log_id_for_each(i) {
- if (logMask & (1 << i)) {
- oldLength = string.length();
- string.appendFormat("%*s%s", spaces, "", android_log_id_to_name(i));
- spaces += spaces_total + oldLength - string.length();
+ if (!logMask & (1 << i)) {
+ continue;
+ }
+ 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();
+
+ LidStatistics &l = id(i);
+ l.sort();
+
+ UidStatisticsCollection::iterator iu;
+ for (iu = l.begin(); iu != l.end(); ++iu) {
+ (*iu)->sort();
}
}
@@ -369,6 +555,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,18 +577,170 @@ 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;
}
+ // Construct list of worst spammers by Pid
+ static const unsigned char num_spammers = 10;
+ bool header = false;
+
log_id_for_each(i) {
if (!(logMask & (1 << i))) {
continue;
}
- bool header = false;
+ PidStatisticsCollection pids;
+ pids.clear();
+
+ LidStatistics &l = id(i);
+ UidStatisticsCollection::iterator iu;
+ for (iu = l.begin(); iu != l.end(); ++iu) {
+ UidStatistics &u = *(*iu);
+ PidStatisticsCollection::iterator ip;
+ for (ip = u.begin(); ip != u.end(); ++ip) {
+ PidStatistics *p = (*ip);
+ if (p->getPid() == p->gone) {
+ break;
+ }
+
+ size_t mySizes = p->sizes();
+
+ PidStatisticsCollection::iterator q;
+ unsigned char num = 0;
+ for (q = pids.begin(); q != pids.end(); ++q) {
+ if (mySizes > (*q)->sizes()) {
+ pids.insert(q, p);
+ break;
+ }
+ // do we need to traverse deeper in the list?
+ if (++num > num_spammers) {
+ break;
+ }
+ }
+ if (q == pids.end()) {
+ pids.push_back(p);
+ }
+ }
+ }
+
+ size_t threshold = sizes(i);
+ if (threshold < 65536) {
+ threshold = 65536;
+ }
+ threshold /= 100;
+
+ PidStatisticsCollection::iterator pt = pids.begin();
+
+ for(int line = 0;
+ (pt != pids.end()) && (line < num_spammers);
+ ++line, pt = pids.erase(pt)) {
+ PidStatistics *p = *pt;
+
+ size_t sizes = p->sizes();
+ if (sizes < threshold) {
+ break;
+ }
+
+ char *name = p->getName();
+ pid_t pid = p->getPid();
+ if (!name || !*name) {
+ name = pidToName(pid);
+ if (name) {
+ if (*name) {
+ p->setName(name);
+ } else {
+ free(name);
+ name = NULL;
+ }
+ }
+ }
+
+ if (!header) {
+ string.appendFormat("\n\nChattiest clients:\n"
+ "log id %-*s PID[?] name",
+ spaces_total, "size/total");
+ header = true;
+ }
+
+ size_t sizesTotal = p->sizesTotal();
+
+ android::String8 sz("");
+ sz.appendFormat((sizes != sizesTotal) ? "%zu/%zu" : "%zu",
+ sizes, sizesTotal);
+
+ android::String8 pd("");
+ pd.appendFormat("%u%c", pid, p->pidGone() ? '?' : ' ');
+
+ string.appendFormat("\n%-7s%-*s %-7s%s",
+ line ? "" : android_log_id_to_name(i),
+ spaces_total, sz.string(), pd.string(),
+ name ? name : "");
+ }
+
+ pids.clear();
+ }
+
+ 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;
+ }
+
+ header = false;
bool first = true;
UidStatisticsCollection::iterator ut;
@@ -433,21 +774,22 @@ void LogStatistics::format(char **buf,
if (!oneline) {
first = true;
- } else if (!first && spaces) {
+ } else if (!first && (spaces > 0)) {
string.appendFormat("%*s", spaces, "");
}
spaces = 0;
uid_t u = up->getUid();
- pid_t p = (*pt)->getPid();
+ PidStatistics *pp = *pt;
+ pid_t p = pp->getPid();
intermediate = string.format(oneline
? ((p == PidStatistics::gone)
? "%d/?"
- : "%d/%d")
+ : "%d/%d%c")
: "%d",
- u, p);
- string.appendFormat((first) ? "\n%-12s" : "%-12s",
+ u, p, pp->pidGone() ? '?' : '\0');
+ string.appendFormat(first ? "\n%-12s" : "%-12s",
intermediate.string());
intermediate.clear();
@@ -458,10 +800,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;
}
@@ -477,8 +825,8 @@ void LogStatistics::format(char **buf,
size_t gone_els = 0;
for(; pt != up->end(); ++pt) {
- PidStatistics *pp = *pt;
- pid_t p = pp->getPid();
+ pp = *pt;
+ p = pp->getPid();
// If a PID no longer has any current logs, and is not
// active anymore, skip & report totals for gone.
@@ -490,7 +838,7 @@ void LogStatistics::format(char **buf,
continue;
}
els = pp->elements();
- bool gone = kill(p, 0);
+ bool gone = pp->pidGone();
if (gone && (els == 0)) {
// ToDo: garbage collection: move this statistical bucket
// from its current UID/PID to UID/? (races and
@@ -502,13 +850,13 @@ void LogStatistics::format(char **buf,
continue;
}
- if (!first && spaces) {
+ if (!first && (spaces > 0)) {
string.appendFormat("%*s", spaces, "");
}
spaces = 0;
- intermediate = string.format((gone) ? "%d/%d?" : "%d/%d", u, p);
- string.appendFormat((first) ? "\n%-12s" : "%-12s",
+ intermediate = string.format(gone ? "%d/%d?" : "%d/%d", u, p);
+ string.appendFormat(first ? "\n%-12s" : "%-12s",
intermediate.string());
intermediate.clear();
@@ -517,10 +865,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,12 +885,12 @@ void LogStatistics::format(char **buf,
}
if (gone_els) {
- if (!first && spaces) {
+ if (!first && (spaces > 0)) {
string.appendFormat("%*s", spaces, "");
}
intermediate = string.format("%d/?", u);
- string.appendFormat((first) ? "\n%-12s" : "%-12s",
+ string.appendFormat(first ? "\n%-12s" : "%-12s",
intermediate.string());
intermediate.clear();
@@ -553,3 +907,20 @@ void LogStatistics::format(char **buf,
*buf = strdup(string.string());
}
+
+uid_t LogStatistics::pidToUid(pid_t pid) {
+ log_id_for_each(i) {
+ LidStatistics &l = id(i);
+ UidStatisticsCollection::iterator iu;
+ for (iu = l.begin(); iu != l.end(); ++iu) {
+ UidStatistics &u = *(*iu);
+ PidStatisticsCollection::iterator ip;
+ for (ip = u.begin(); ip != u.end(); ++ip) {
+ if ((*ip)->getPid() == pid) {
+ return u.getUid();
+ }
+ }
+ }
+ }
+ return getuid(); // associate this with the logger
+}
generated by cgit v1.1 at 2025-08-15 23:04:05 +0000