From 903156ddaaad85f89210d809dddc17a9000342a4 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Wed, 19 Apr 2017 14:39:21 -0700 Subject: [PATCH] logd: add Chattiest LOG_TAG statistics Report global LOG_TAG usage. Test: gTest liblog-unit-tests, logd-unit-tests & logcat-unit-tests Test: manual: inspect logcat -S results around 'Chattiest TAGs' Bug: 37254265 Change-Id: I32473a1d9131c87e4fb7841d5cc0ea9cc14c63cd --- logd/LogStatistics.cpp | 79 +++++++++++++++++++++ logd/LogStatistics.h | 156 +++++++++++++++++++++++++++++++++++++++-- 2 files changed, 230 insertions(+), 5 deletions(-) diff --git a/logd/LogStatistics.cpp b/logd/LogStatistics.cpp index 0b6b28cf8..594bd0dd5 100644 --- a/logd/LogStatistics.cpp +++ b/logd/LogStatistics.cpp @@ -32,6 +32,7 @@ static const uint64_t hourSec = 60 * 60; static const uint64_t monthSec = 31 * 24 * hourSec; size_t LogStatistics::SizesTotal; +size_t TagNameEntry::droppedElsewhere; LogStatistics::LogStatistics() : enable(false) { log_time now(CLOCK_REALTIME); @@ -152,6 +153,8 @@ void LogStatistics::add(LogBufferElement* element) { tagTable.add(tag, element); } } + + tagNameTable.add(TagNameEntry(element).getKey(), element); } void LogStatistics::subtract(LogBufferElement* element) { @@ -191,6 +194,8 @@ void LogStatistics::subtract(LogBufferElement* element) { tagTable.subtract(tag, element); } } + + tagNameTable.subtract(TagNameEntry(element).getKey(), element); } // Atomically set an entry to drop @@ -225,6 +230,8 @@ void LogStatistics::drop(LogBufferElement* element) { tagTable.drop(tag, element); } } + + tagNameTable.drop(TagNameEntry(element).getKey(), element); } // caller must own and free character string @@ -505,6 +512,71 @@ std::string TagEntry::format(const LogStatistics& /* stat */, return formatLine(name, size, pruned); } +std::string TagNameEntry::formatHeader(const std::string& name, + log_id_t /* id */) const { + return formatLine(name, std::string("Size"), std::string("Prune")) + + formatLine(std::string(" TID/PID/UID LOG_TAG NAME"), + std::string("BYTES"), std::string("NUM")); +} + +std::string TagNameEntry::format(const LogStatistics& /* stat */, + log_id_t /* id */) const { + std::string name; + pid_t tid = getTid(); + pid_t pid = getPid(); + std::string pidstr; + if (pid != (pid_t)-1) { + pidstr = android::base::StringPrintf("%u", pid); + if ((tid != (pid_t)-1) && (tid != pid)) pidstr = "/" + pidstr; + } + int len = 9 - pidstr.length(); + if (len < 0) len = 0; + if ((tid == (pid_t)-1) || (tid == pid)) { + name = android::base::StringPrintf("%*s", len, ""); + } else { + name = android::base::StringPrintf("%*u", len, tid); + } + name += pidstr; + uid_t uid = getUid(); + if (uid != (uid_t)-1) { + name += android::base::StringPrintf("/%u", uid); + } + + std::string size = android::base::StringPrintf("%zu", getSizes()); + + const char* nameTmp = getName(); + if (nameTmp) { + size_t lenSpace = std::max(16 - name.length(), (size_t)1); + size_t len = EntryBaseConstants::total_len - + EntryBaseConstants::pruned_len - size.length() - + name.length() - lenSpace - 2; + size_t lenNameTmp = strlen(nameTmp); + while ((len < lenNameTmp) && (lenSpace > 1)) { + ++len; + --lenSpace; + } + name += android::base::StringPrintf("%*s", (int)lenSpace, ""); + if (len < lenNameTmp) { + name += "..."; + nameTmp += lenNameTmp - std::max(len - 3, (size_t)1); + } + name += nameTmp; + } + + std::string pruned = ""; + + // Because of TagNameEntry::droppedElsewhere, dropped count can get + // modified for "chatty" tags. Since the size is always zero this + // modification is a "can not happen". + TagNameEntry& me = const_cast(*this); + size_t dropped = me.getDropped(); + if (dropped) { + pruned = android::base::StringPrintf("%zu", dropped); + } + + return formatLine(name, size, pruned); +} + static std::string formatMsec(uint64_t val) { static const unsigned subsecDigits = 3; static const uint64_t sec = MS_PER_SEC; @@ -725,6 +797,13 @@ std::string LogStatistics::format(uid_t uid, pid_t pid, output += tidTable.format(*this, uid, pid, name); } + if (enable) { + name = "Chattiest TAGs"; + if (pid) name += android::base::StringPrintf(" for PID %d", pid); + name += ":"; + output += tagNameTable.format(*this, uid, pid, name); + } + if (enable && (logMask & (1 << LOG_ID_EVENTS))) { name = "Chattiest events log buffer TAGs"; if (pid) name += android::base::StringPrintf(" for PID %d", pid); diff --git a/logd/LogStatistics.h b/logd/LogStatistics.h index e6f01d64d..84dbff3cf 100644 --- a/logd/LogStatistics.h +++ b/logd/LogStatistics.h @@ -18,10 +18,14 @@ #define _LOGD_LOG_STATISTICS_H__ #include +#include +#include #include +#include #include #include // std::max +#include #include #include // std::string #include @@ -77,7 +81,7 @@ class LogHashtable { std::unique_ptr sort(uid_t uid, pid_t pid, size_t len) const { if (!len) { - std::unique_ptr sorted(NULL); + std::unique_ptr sorted(nullptr); return sorted; } @@ -318,7 +322,7 @@ struct PidEntry : public EntryBaseDropped { : EntryBaseDropped(element), pid(element.pid), uid(element.uid), - name(element.name ? strdup(element.name) : NULL) { + name(element.name ? strdup(element.name) : nullptr) { } ~PidEntry() { free(name); @@ -340,7 +344,7 @@ struct PidEntry : public EntryBaseDropped { inline void add(pid_t newPid) { if (name && !fastcmp(name, "zygote", 6)) { free(name); - name = NULL; + name = nullptr; } if (!name) { name = android::pidToName(newPid); @@ -388,7 +392,7 @@ struct TidEntry : public EntryBaseDropped { tid(element.tid), pid(element.pid), uid(element.uid), - name(element.name ? strdup(element.name) : NULL) { + name(element.name ? strdup(element.name) : nullptr) { } ~TidEntry() { free(name); @@ -413,7 +417,7 @@ struct TidEntry : public EntryBaseDropped { inline void add(pid_t incomingTid) { if (name && !fastcmp(name, "zygote", 6)) { free(name); - name = NULL; + name = nullptr; } if (!name) { name = android::tidToName(incomingTid); @@ -477,6 +481,141 @@ struct TagEntry : public EntryBaseDropped { std::string format(const LogStatistics& stat, log_id_t id) const; }; +struct TagNameEntry : public EntryBaseDropped { + // We do not care that a dropped entry does, or does not exist, because + // the size will always report zero. But if it does, we need to account + // for the ones that transitioned from a known tag to chatty so that we + // do not spring a leak on the dropped counts. + static size_t droppedElsewhere; + + pid_t tid; + pid_t pid; + uid_t uid; + std::string* alloc; + std::experimental::string_view name; // Saves space if const char* + + explicit TagNameEntry(LogBufferElement* element) + : EntryBaseDropped(element), + tid(element->getTid()), + pid(element->getPid()), + uid(element->getUid()), + alloc(nullptr) { + if (element->isBinary()) { + uint32_t tag = element->getTag(); + if (tag) { + const char* cp = android::tagToName(tag); + if (cp) { + name = std::experimental::string_view(cp, strlen(cp)); + return; + } + } + alloc = new std::string( + android::base::StringPrintf("[%" PRIu32 "]", tag)); + if (!alloc) return; + name = std::experimental::string_view(alloc->c_str(), alloc->size()); + return; + } + const char* msg = element->getMsg(); + if (!msg) { + name = std::experimental::string_view("chatty", strlen("chatty")); + return; + } + ++msg; + unsigned short len = element->getMsgLen(); + len = (len <= 1) ? 0 : strnlen(msg, len - 1); + if (!len) { + name = std::experimental::string_view("", strlen("")); + return; + } + alloc = new std::string(msg, len); + if (!alloc) return; + name = std::experimental::string_view(alloc->c_str(), alloc->size()); + } + + explicit TagNameEntry(TagNameEntry&& rval) + : tid(rval.tid), + pid(rval.pid), + uid(rval.uid), + alloc(rval.alloc), + name(rval.name.data(), rval.name.length()) { + rval.alloc = nullptr; + } + + explicit TagNameEntry(const TagNameEntry& rval) + : tid(rval.tid), + pid(rval.pid), + uid(rval.uid), + alloc(rval.alloc ? new std::string(*rval.alloc) : nullptr), + name(alloc ? alloc->data() : rval.name.data(), rval.name.length()) { + } + + ~TagNameEntry() { + if (alloc) delete alloc; + } + + const std::experimental::string_view& getKey() const { + return name; + } + const pid_t& getTid() const { + return tid; + } + const pid_t& getPid() const { + return pid; + } + const uid_t& getUid() const { + return uid; + } + const char* getName() const { + return name.data(); + } + size_t getNameAllocLength() const { + return alloc ? alloc->length() + 1 : 0; + } + + size_t getDropped() { + if (__predict_false(name == "chatty")) { // plug the leak + dropped += droppedElsewhere; + droppedElsewhere = 0; + } + return EntryBaseDropped::getDropped(); + } + + inline void add(LogBufferElement* element) { + if (uid != element->getUid()) { + uid = -1; + } + if (pid != element->getPid()) { + pid = -1; + } + if (tid != element->getTid()) { + tid = -1; + } + // Fixup of dropped can be deferred. + EntryBaseDropped::add(element); + } + + inline bool subtract(LogBufferElement* element) { + if (__predict_false(name == "chatty")) { // plug the leak + dropped += droppedElsewhere; + droppedElsewhere = 0; + } + return EntryBaseDropped::subtract(element); + } + + inline void drop(LogBufferElement* element) { + if (__predict_false(name == "chatty")) { // plug the leak + dropped += droppedElsewhere; + droppedElsewhere = 0; + } else { + ++droppedElsewhere; + } + return EntryBaseDropped::drop(element); + } + + std::string formatHeader(const std::string& name, log_id_t id) const; + std::string format(const LogStatistics& stat, log_id_t id) const; +}; + template class LogFindWorst { std::unique_ptr sorted; @@ -550,9 +689,15 @@ class LogStatistics { // security tag list tagTable_t securityTagTable; + // global tag list + typedef LogHashtable + tagNameTable_t; + tagNameTable_t tagNameTable; + size_t sizeOf() const { size_t size = sizeof(*this) + pidTable.sizeOf() + tidTable.sizeOf() + tagTable.sizeOf() + securityTagTable.sizeOf() + + tagNameTable.sizeOf() + (pidTable.size() * sizeof(pidTable_t::iterator)) + (tagTable.size() * sizeof(tagTable_t::iterator)); for (auto it : pidTable) { @@ -563,6 +708,7 @@ class LogStatistics { const char* name = it.second.getName(); if (name) size += strlen(name) + 1; } + for (auto it : tagNameTable) size += it.second.getNameAllocLength(); log_id_for_each(id) { size += uidTable[id].sizeOf(); size += uidTable[id].size() * sizeof(uidTable_t::iterator);