From f93b4006e0b1afdf304b39d13f96d9766ec14a30 Mon Sep 17 00:00:00 2001 From: Tom Cherry Date: Wed, 3 Jun 2020 09:23:49 -0700 Subject: [PATCH 1/3] logd: use libbase logging We can use libbase logging to output to the kernel log instead of the 'prdebug' function, so use that instead. Bonus #1: we can now use CHECK(). Bonus #2: logging unit tests automatically output to stderr. Bonus #3: We see dependent library's logs instead of losing them to the void. Test: logging unit tests Test: logs show appropriately in dmesg / stderr Test: CHECK() works Change-Id: I92f8056b4820dc4998996cf46460568085299700 --- logd/ChattyLogBuffer.cpp | 4 +-- logd/CommandListener.cpp | 3 +- logd/LogBufferTest.cpp | 8 ----- logd/LogReader.cpp | 5 +-- logd/LogTags.cpp | 30 ++++++++-------- logd/LogUtils.h | 1 - logd/SimpleLogBuffer.cpp | 14 ++++---- logd/fuzz/log_buffer_log_fuzzer.cpp | 7 ---- logd/main.cpp | 56 +++++++++++------------------ 9 files changed, 51 insertions(+), 77 deletions(-) diff --git a/logd/ChattyLogBuffer.cpp b/logd/ChattyLogBuffer.cpp index 62c8629c4..f92fe65c8 100644 --- a/logd/ChattyLogBuffer.cpp +++ b/logd/ChattyLogBuffer.cpp @@ -217,12 +217,12 @@ LogBufferElementCollection::iterator ChattyLogBuffer::Erase(LogBufferElementColl log_id_for_each(i) { for (auto b : mLastWorst[i]) { if (bad == b.second) { - android::prdebug("stale mLastWorst[%d] key=%d mykey=%d\n", i, b.first, key); + LOG(ERROR) << StringPrintf("stale mLastWorst[%d] key=%d mykey=%d", i, b.first, key); } } for (auto b : mLastWorstPidOfSystem[i]) { if (bad == b.second) { - android::prdebug("stale mLastWorstPidOfSystem[%d] pid=%d\n", i, b.first); + LOG(ERROR) << StringPrintf("stale mLastWorstPidOfSystem[%d] pid=%d", i, b.first); } } } diff --git a/logd/CommandListener.cpp b/logd/CommandListener.cpp index c6ab22deb..9764c443e 100644 --- a/logd/CommandListener.cpp +++ b/logd/CommandListener.cpp @@ -31,6 +31,7 @@ #include +#include #include #include #include @@ -298,7 +299,7 @@ int CommandListener::ReinitCmd::runCommand(SocketClient* cli, int /*argc*/, char** /*argv*/) { setname(); - android::prdebug("logd reinit"); + LOG(INFO) << "logd reinit"; buf()->Init(); prune()->init(nullptr); diff --git a/logd/LogBufferTest.cpp b/logd/LogBufferTest.cpp index ced4a215f..e651b4fec 100644 --- a/logd/LogBufferTest.cpp +++ b/logd/LogBufferTest.cpp @@ -43,14 +43,6 @@ bool __android_logger_valid_buffer_size(unsigned long) { } #endif -void android::prdebug(const char* fmt, ...) { - va_list ap; - va_start(ap, fmt); - vfprintf(stderr, fmt, ap); - fprintf(stderr, "\n"); - va_end(ap); -} - char* android::uidToName(uid_t) { return nullptr; } diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp index 42d4574e9..f71133da1 100644 --- a/logd/LogReader.cpp +++ b/logd/LogReader.cpp @@ -23,6 +23,7 @@ #include +#include #include #include #include @@ -201,9 +202,9 @@ bool LogReader::onDataAvailable(SocketClient* cli) { } } - android::prdebug( + LOG(INFO) << android::base::StringPrintf( "logdr: UID=%d GID=%d PID=%d %c tail=%lu logMask=%x pid=%d " - "start=%" PRIu64 "ns deadline=%" PRIi64 "ns\n", + "start=%" PRIu64 "ns deadline=%" PRIi64 "ns", cli->getUid(), cli->getGid(), cli->getPid(), nonBlock ? 'n' : 'b', tail, logMask, (int)pid, start.nsec(), static_cast(deadline.time_since_epoch().count())); diff --git a/logd/LogTags.cpp b/logd/LogTags.cpp index 3afe3ee6e..8e18f9d46 100644 --- a/logd/LogTags.cpp +++ b/logd/LogTags.cpp @@ -29,6 +29,7 @@ #include #include +#include #include #include #include @@ -115,10 +116,11 @@ bool LogTags::RebuildFileEventLogTags(const char* filename, bool warn) { } if (warn) { - android::prdebug( - ((fd < 0) ? "%s failed to rebuild" - : "%s missing, damaged or truncated; rebuilt"), - filename); + if (fd < 0) { + LOG(ERROR) << filename << " failed to rebuild"; + } else { + LOG(ERROR) << filename << " missing, damaged or truncated; rebuilt"; + } } if (fd >= 0) { @@ -182,8 +184,7 @@ void LogTags::AddEventLogTags(uint32_t tag, uid_t uid, const std::string& Name, WritePersistEventLogTags(tag, uid, source); } else if (warn && !newOne && source) { // For the files, we want to report dupes. - android::prdebug("Multiple tag %" PRIu32 " %s %s %s", tag, Name.c_str(), - Format.c_str(), source); + LOG(DEBUG) << "Multiple tag " << tag << " " << Name << " " << Format << " " << source; } } @@ -216,7 +217,7 @@ void LogTags::ReadFileEventLogTags(const char* filename, bool warn) { } else if (isdigit(*cp)) { unsigned long Tag = strtoul(cp, &cp, 10); if (warn && (Tag > emptyTag)) { - android::prdebug("tag too large %lu", Tag); + LOG(WARNING) << "tag too large " << Tag; } while ((cp < endp) && (*cp != '\n') && isspace(*cp)) ++cp; if (cp >= endp) break; @@ -231,9 +232,8 @@ void LogTags::ReadFileEventLogTags(const char* filename, bool warn) { std::string Name(name, cp - name); #ifdef ALLOW_NOISY_LOGGING_OF_PROBLEM_WITH_LOTS_OF_TECHNICAL_DEBT static const size_t maximum_official_tag_name_size = 24; - if (warn && - (Name.length() > maximum_official_tag_name_size)) { - android::prdebug("tag name too long %s", Name.c_str()); + if (warn && (Name.length() > maximum_official_tag_name_size)) { + LOG(WARNING) << "tag name too long " << Name; } #endif if (hasAlpha && @@ -264,8 +264,8 @@ void LogTags::ReadFileEventLogTags(const char* filename, bool warn) { filename, warn); } else { if (warn) { - android::prdebug("tag name invalid %.*s", - (int)(cp - name + 1), name); + LOG(ERROR) << android::base::StringPrintf("tag name invalid %.*s", + (int)(cp - name + 1), name); } lineStart = nullptr; } @@ -276,7 +276,7 @@ void LogTags::ReadFileEventLogTags(const char* filename, bool warn) { cp++; } } else if (warn) { - android::prdebug("Cannot read %s", filename); + LOG(ERROR) << "Cannot read " << filename; } } @@ -479,8 +479,8 @@ uint32_t LogTags::nameToTag_locked(const std::string& name, const char* format, static int openFile(const char* name, int mode, bool warning) { int fd = TEMP_FAILURE_RETRY(open(name, mode)); - if ((fd < 0) && warning) { - android::prdebug("Failed open %s (%d)", name, errno); + if (fd < 0 && warning) { + PLOG(ERROR) << "Failed to open " << name; } return fd; } diff --git a/logd/LogUtils.h b/logd/LogUtils.h index 96aa1d349..df78a508a 100644 --- a/logd/LogUtils.h +++ b/logd/LogUtils.h @@ -30,7 +30,6 @@ namespace android { // Furnished in main.cpp. Caller must own and free returned value char* uidToName(uid_t uid); -void prdebug(const char* fmt, ...) __attribute__((__format__(printf, 1, 2))); // Caller must own and free returned value char* pidToName(pid_t pid); diff --git a/logd/SimpleLogBuffer.cpp b/logd/SimpleLogBuffer.cpp index b4b354636..292a7e405 100644 --- a/logd/SimpleLogBuffer.cpp +++ b/logd/SimpleLogBuffer.cpp @@ -16,6 +16,8 @@ #include "SimpleLogBuffer.h" +#include + #include "LogBufferElement.h" SimpleLogBuffer::SimpleLogBuffer(LogReaderList* reader_list, LogTags* tags, LogStatistics* stats) @@ -232,8 +234,8 @@ bool SimpleLogBuffer::Clear(log_id_t id, uid_t uid) { auto reader_threads_lock = std::lock_guard{reader_list_->reader_threads_lock()}; for (const auto& reader_thread : reader_list_->reader_threads()) { if (reader_thread->IsWatching(id)) { - android::prdebug("Kicking blocked reader, %s, from LogBuffer::clear()\n", - reader_thread->name().c_str()); + LOG(WARNING) << "Kicking blocked reader, " << reader_thread->name() + << ", from LogBuffer::clear()"; reader_thread->release_Locked(); } } @@ -350,16 +352,16 @@ void SimpleLogBuffer::KickReader(LogReaderThread* reader, log_id_t id, unsigned if (stats_->Sizes(id) > (2 * max_size_[id])) { // +100% // A misbehaving or slow reader has its connection // dropped if we hit too much memory pressure. - android::prdebug("Kicking blocked reader, %s, from LogBuffer::kickMe()\n", - reader->name().c_str()); + LOG(WARNING) << "Kicking blocked reader, " << reader->name() + << ", from LogBuffer::kickMe()"; reader->release_Locked(); } else if (reader->deadline().time_since_epoch().count() != 0) { // Allow a blocked WRAP deadline reader to trigger and start reporting the log data. reader->triggerReader_Locked(); } else { // tell slow reader to skip entries to catch up - android::prdebug("Skipping %lu entries from slow reader, %s, from LogBuffer::kickMe()\n", - prune_rows, reader->name().c_str()); + LOG(WARNING) << "Skipping " << prune_rows << " entries from slow reader, " << reader->name() + << ", from LogBuffer::kickMe()"; reader->triggerSkip_Locked(id, prune_rows); } } diff --git a/logd/fuzz/log_buffer_log_fuzzer.cpp b/logd/fuzz/log_buffer_log_fuzzer.cpp index 8f90f5068..b576ddff7 100644 --- a/logd/fuzz/log_buffer_log_fuzzer.cpp +++ b/logd/fuzz/log_buffer_log_fuzzer.cpp @@ -79,13 +79,6 @@ int write_log_messages(const uint8_t** pdata, size_t* data_left, LogBuffer* log_ return 1; } -// Because system/core/logd/main.cpp redefines these. -void prdebug(char const* fmt, ...) { - va_list ap; - va_start(ap, fmt); - vfprintf(stderr, fmt, ap); - va_end(ap); -} char* uidToName(uid_t) { return strdup("fake"); } diff --git a/logd/main.cpp b/logd/main.cpp index c2b5a1d5b..773ffb8e1 100644 --- a/logd/main.cpp +++ b/logd/main.cpp @@ -36,7 +36,9 @@ #include +#include #include +#include #include #include #include @@ -70,19 +72,18 @@ static int drop_privs(bool klogd, bool auditd) { sched_param param = {}; if (set_sched_policy(0, SP_BACKGROUND) < 0) { - android::prdebug("failed to set background scheduling policy"); + PLOG(ERROR) << "failed to set background scheduling policy"; return -1; } if (sched_setscheduler((pid_t)0, SCHED_BATCH, ¶m) < 0) { - android::prdebug("failed to set batch scheduler"); + PLOG(ERROR) << "failed to set batch scheduler"; return -1; } - if (!__android_logger_property_get_bool("ro.debuggable", - BOOL_DEFAULT_FALSE) && + if (!__android_logger_property_get_bool("ro.debuggable", BOOL_DEFAULT_FALSE) && prctl(PR_SET_DUMPABLE, 0) == -1) { - android::prdebug("failed to clear PR_SET_DUMPABLE"); + PLOG(ERROR) << "failed to clear PR_SET_DUMPABLE"; return -1; } @@ -105,40 +106,13 @@ static int drop_privs(bool klogd, bool auditd) { return -1; } if (cap_set_proc(caps.get()) < 0) { - android::prdebug("failed to set CAP_SYSLOG or CAP_AUDIT_CONTROL (%d)", errno); + PLOG(ERROR) << "failed to set CAP_SYSLOG or CAP_AUDIT_CONTROL"; return -1; } return 0; } -static int fdDmesg = -1; -void android::prdebug(const char* fmt, ...) { - if (fdDmesg < 0) { - return; - } - - static const char message[] = { - KMSG_PRIORITY(LOG_DEBUG), 'l', 'o', 'g', 'd', ':', ' ' - }; - char buffer[256]; - memcpy(buffer, message, sizeof(message)); - - va_list ap; - va_start(ap, fmt); - int n = vsnprintf(buffer + sizeof(message), - sizeof(buffer) - sizeof(message), fmt, ap); - va_end(ap); - if (n > 0) { - buffer[sizeof(buffer) - 1] = '\0'; - if (!strchr(buffer, '\n')) { - buffer[sizeof(buffer) - 2] = '\0'; - strlcat(buffer, "\n", sizeof(buffer)); - } - write(fdDmesg, buffer, strlen(buffer)); - } -} - char* android::uidToName(uid_t u) { struct Userdata { uid_t uid; @@ -246,8 +220,20 @@ int main(int argc, char* argv[]) { return issueReinit(); } + android::base::InitLogging( + argv, [](android::base::LogId log_id, android::base::LogSeverity severity, + const char* tag, const char* file, unsigned int line, const char* message) { + if (tag && strcmp(tag, "logd") != 0) { + auto prefixed_message = android::base::StringPrintf("%s: %s", tag, message); + android::base::KernelLogger(log_id, severity, "logd", file, line, + prefixed_message.c_str()); + } else { + android::base::KernelLogger(log_id, severity, "logd", file, line, message); + } + }); + static const char dev_kmsg[] = "/dev/kmsg"; - fdDmesg = android_get_control_file(dev_kmsg); + int fdDmesg = android_get_control_file(dev_kmsg); if (fdDmesg < 0) { fdDmesg = TEMP_FAILURE_RETRY(open(dev_kmsg, O_WRONLY | O_CLOEXEC)); } @@ -263,7 +249,7 @@ int main(int argc, char* argv[]) { fdPmesg = TEMP_FAILURE_RETRY( open(proc_kmsg, O_RDONLY | O_NDELAY | O_CLOEXEC)); } - if (fdPmesg < 0) android::prdebug("Failed to open %s\n", proc_kmsg); + if (fdPmesg < 0) PLOG(ERROR) << "Failed to open " << proc_kmsg; } bool auditd = __android_logger_property_get_bool("ro.logd.auditd", BOOL_DEFAULT_TRUE); From 4596b78d12986ae5ffce68d5dc51e192defdc313 Mon Sep 17 00:00:00 2001 From: Tom Cherry Date: Wed, 3 Jun 2020 13:49:24 -0700 Subject: [PATCH 2/3] logd: don't store the map key in its value The keys are already available when iterating through the maps, so this only serves to waste memory. Test: unit tests Change-Id: Iaf4e389eb0f0990e7113cd78be1773e767a356d4 --- logd/LogStatistics.cpp | 55 ++++++++++++++------------- logd/LogStatistics.h | 85 ++++++++++++++++++------------------------ 2 files changed, 66 insertions(+), 74 deletions(-) diff --git a/logd/LogStatistics.cpp b/logd/LogStatistics.cpp index 04fd59d95..625cbdec4 100644 --- a/logd/LogStatistics.cpp +++ b/logd/LogStatistics.cpp @@ -308,8 +308,9 @@ template void LogStatistics::WorstTwoWithThreshold(const LogHashtable& table, size_t threshold, int* worst, size_t* worst_sizes, size_t* second_worst_sizes) const { + std::array max_keys; std::array max_entries; - table.MaxEntries(AID_ROOT, 0, &max_entries); + table.MaxEntries(AID_ROOT, 0, max_keys, max_entries); if (max_entries[0] == nullptr || max_entries[1] == nullptr) { return; } @@ -317,7 +318,7 @@ void LogStatistics::WorstTwoWithThreshold(const LogHashtable& tabl // b/24782000: Allow time horizon to extend roughly tenfold, assume average entry length is // 100 characters. if (*worst_sizes > threshold && *worst_sizes > (10 * max_entries[0]->dropped_count())) { - *worst = max_entries[0]->key(); + *worst = *max_keys[0]; *second_worst_sizes = max_entries[1]->getSizes(); if (*second_worst_sizes < threshold) { *second_worst_sizes = threshold; @@ -340,13 +341,14 @@ void LogStatistics::WorstTwoTags(size_t threshold, int* worst, size_t* worst_siz void LogStatistics::WorstTwoSystemPids(log_id id, size_t worst_uid_sizes, int* worst, size_t* second_worst_sizes) const { auto lock = std::lock_guard{lock_}; + std::array max_keys; std::array max_entries; - pidSystemTable[id].MaxEntries(AID_SYSTEM, 0, &max_entries); + pidSystemTable[id].MaxEntries(AID_SYSTEM, 0, max_keys, max_entries); if (max_entries[0] == nullptr || max_entries[1] == nullptr) { return; } - *worst = max_entries[0]->key(); + *worst = *max_keys[0]; *second_worst_sizes = worst_uid_sizes - max_entries[0]->getSizes() + max_entries[1]->getSizes(); } @@ -412,11 +414,12 @@ void LogStatistics::FormatTmp(const char* nameTmp, uid_t uid, std::string& name, } } -std::string UidEntry::format(const LogStatistics& stat, log_id_t id) const REQUIRES(stat.lock_) { - std::string name = android::base::StringPrintf("%u", uid_); +std::string UidEntry::format(const LogStatistics& stat, log_id_t id, uid_t uid) const + REQUIRES(stat.lock_) { + std::string name = android::base::StringPrintf("%u", uid); std::string size = android::base::StringPrintf("%zu", getSizes()); - stat.FormatTmp(nullptr, uid_, name, size, 6); + stat.FormatTmp(nullptr, uid, name, size, 6); std::string pruned = ""; if (worstUidEnabledForLogid(id)) { @@ -474,19 +477,20 @@ std::string UidEntry::format(const LogStatistics& stat, log_id_t id) const REQUI std::string output = formatLine(name, size, pruned); - if (uid_ != AID_SYSTEM) { + if (uid != AID_SYSTEM) { return output; } static const size_t maximum_sorted_entries = 32; - std::array sorted; - stat.pidSystemTable[id].MaxEntries(uid_, 0, &sorted); + std::array sorted_pids; + std::array sorted_entries; + stat.pidSystemTable[id].MaxEntries(uid, 0, sorted_pids, sorted_entries); std::string byPid; size_t index; bool hasDropped = false; for (index = 0; index < maximum_sorted_entries; ++index) { - const PidEntry* entry = sorted[index]; + const PidEntry* entry = sorted_entries[index]; if (!entry) { break; } @@ -496,7 +500,7 @@ std::string UidEntry::format(const LogStatistics& stat, log_id_t id) const REQUI if (entry->dropped_count()) { hasDropped = true; } - byPid += entry->format(stat, id); + byPid += entry->format(stat, id, *sorted_pids[index]); } if (index > 1) { // print this only if interesting std::string ditto("\" "); @@ -515,9 +519,9 @@ std::string PidEntry::formatHeader(const std::string& name, std::string("BYTES"), std::string("NUM")); } -std::string PidEntry::format(const LogStatistics& stat, log_id_t /* id */) const +std::string PidEntry::format(const LogStatistics& stat, log_id_t, pid_t pid) const REQUIRES(stat.lock_) { - std::string name = android::base::StringPrintf("%5u/%u", pid_, uid_); + std::string name = android::base::StringPrintf("%5u/%u", pid, uid_); std::string size = android::base::StringPrintf("%zu", getSizes()); stat.FormatTmp(name_, uid_, name, size, 12); @@ -538,9 +542,9 @@ std::string TidEntry::formatHeader(const std::string& name, std::string("NUM")); } -std::string TidEntry::format(const LogStatistics& stat, log_id_t /* id */) const +std::string TidEntry::format(const LogStatistics& stat, log_id_t, pid_t tid) const REQUIRES(stat.lock_) { - std::string name = android::base::StringPrintf("%5u/%u", tid(), uid_); + std::string name = android::base::StringPrintf("%5u/%u", tid, uid_); std::string size = android::base::StringPrintf("%zu", getSizes()); stat.FormatTmp(name_, uid_, name, size, 12); @@ -562,8 +566,7 @@ std::string TagEntry::formatHeader(const std::string& name, log_id_t id) const { std::string("BYTES"), std::string(isprune ? "NUM" : "")); } -std::string TagEntry::format(const LogStatistics& /* stat */, - log_id_t /* id */) const { +std::string TagEntry::format(const LogStatistics&, log_id_t, uint32_t) const { std::string name; if (uid_ == (uid_t)-1) { name = android::base::StringPrintf("%7u", key()); @@ -594,8 +597,7 @@ std::string TagNameEntry::formatHeader(const std::string& name, std::string("BYTES"), std::string("")); } -std::string TagNameEntry::format(const LogStatistics& /* stat */, - log_id_t /* id */) const { +std::string TagNameEntry::format(const LogStatistics&, log_id_t, const TagNameKey& key_name) const { std::string name; std::string pidstr; if (pid_ != (pid_t)-1) { @@ -616,7 +618,7 @@ std::string TagNameEntry::format(const LogStatistics& /* stat */, std::string size = android::base::StringPrintf("%zu", getSizes()); - const char* nameTmp = this->name(); + const char* nameTmp = key_name.data(); if (nameTmp) { size_t lenSpace = std::max(16 - name.length(), (size_t)1); size_t len = EntryBase::TOTAL_LEN - EntryBase::PRUNED_LEN - size.length() - name.length() - @@ -684,15 +686,16 @@ std::string LogStatistics::FormatTable(const LogHashtable& table, REQUIRES(lock_) { static const size_t maximum_sorted_entries = 32; std::string output; - std::array sorted; - table.MaxEntries(uid, pid, &sorted); + std::array sorted_keys; + std::array sorted_entries; + table.MaxEntries(uid, pid, sorted_keys, sorted_entries); bool header_printed = false; for (size_t index = 0; index < maximum_sorted_entries; ++index) { - const TEntry* entry = sorted[index]; + const TEntry* entry = sorted_entries[index]; if (!entry) { break; } - if (entry->getSizes() <= (sorted[0]->getSizes() / 100)) { + if (entry->getSizes() <= (sorted_entries[0]->getSizes() / 100)) { break; } if (!header_printed) { @@ -700,7 +703,7 @@ std::string LogStatistics::FormatTable(const LogHashtable& table, output += entry->formatHeader(name, id); header_printed = true; } - output += entry->format(*this, id); + output += entry->format(*this, id, *sorted_keys[index]); } return output; } diff --git a/logd/LogStatistics.h b/logd/LogStatistics.h index 33a4d63f7..9f085dca3 100644 --- a/logd/LogStatistics.h +++ b/logd/LogStatistics.h @@ -44,6 +44,8 @@ for (log_id_t i = LOG_ID_MIN; (i) < LOG_ID_MAX; (i) = (log_id_t)((i) + 1)) class LogStatistics; +class UidEntry; +class PidEntry; struct LogStatisticsElement { uid_t uid; @@ -95,31 +97,43 @@ class LogHashtable { // Returns a sorted array of up to len highest entries sorted by size. If fewer than len // entries are found, their positions are set to nullptr. template - void MaxEntries(uid_t uid, pid_t pid, std::array* out) const { - auto& retval = *out; - retval.fill(nullptr); - for (const_iterator it = map.begin(); it != map.end(); ++it) { - const TEntry& entry = it->second; - - if (uid != AID_ROOT && uid != entry.uid()) { + void MaxEntries(uid_t uid, pid_t pid, std::array& out_keys, + std::array& out_entries) const { + out_keys.fill(nullptr); + out_entries.fill(nullptr); + for (const auto& [key, entry] : map) { + uid_t entry_uid = 0; + if constexpr (std::is_same_v) { + entry_uid = key; + } else { + entry_uid = entry.uid(); + } + if (uid != AID_ROOT && uid != entry_uid) { continue; } - if (pid && entry.pid() && pid != entry.pid()) { + pid_t entry_pid = 0; + if constexpr (std::is_same_v) { + entry_pid = key; + } else { + entry_pid = entry.pid(); + } + if (pid && entry_pid && pid != entry_pid) { continue; } size_t sizes = entry.getSizes(); ssize_t index = len - 1; - while ((!retval[index] || (sizes > retval[index]->getSizes())) && - (--index >= 0)) + while ((!out_entries[index] || sizes > out_entries[index]->getSizes()) && --index >= 0) ; if (++index < (ssize_t)len) { size_t num = len - index - 1; if (num) { - memmove(&retval[index + 1], &retval[index], - num * sizeof(retval[0])); + memmove(&out_keys[index + 1], &out_keys[index], num * sizeof(out_keys[0])); + memmove(&out_entries[index + 1], &out_entries[index], + num * sizeof(out_entries[0])); } - retval[index] = &entry; + out_keys[index] = &key; + out_entries[index] = &entry; } } } @@ -229,10 +243,8 @@ class EntryBaseDropped : public EntryBase { class UidEntry : public EntryBaseDropped { public: explicit UidEntry(const LogStatisticsElement& element) - : EntryBaseDropped(element), uid_(element.uid), pid_(element.pid) {} + : EntryBaseDropped(element), pid_(element.pid) {} - uid_t key() const { return uid_; } - uid_t uid() const { return key(); } pid_t pid() const { return pid_; } void Add(const LogStatisticsElement& element) { @@ -243,10 +255,9 @@ class UidEntry : public EntryBaseDropped { } std::string formatHeader(const std::string& name, log_id_t id) const; - std::string format(const LogStatistics& stat, log_id_t id) const; + std::string format(const LogStatistics& stat, log_id_t id, uid_t uid) const; private: - const uid_t uid_; pid_t pid_; }; @@ -258,23 +269,16 @@ class PidEntry : public EntryBaseDropped { public: explicit PidEntry(pid_t pid) : EntryBaseDropped(), - pid_(pid), uid_(android::pidToUid(pid)), name_(android::pidToName(pid)) {} explicit PidEntry(const LogStatisticsElement& element) - : EntryBaseDropped(element), - pid_(element.pid), - uid_(element.uid), - name_(android::pidToName(pid_)) {} + : EntryBaseDropped(element), uid_(element.uid), name_(android::pidToName(element.pid)) {} PidEntry(const PidEntry& element) : EntryBaseDropped(element), - pid_(element.pid_), uid_(element.uid_), name_(element.name_ ? strdup(element.name_) : nullptr) {} ~PidEntry() { free(name_); } - pid_t key() const { return pid_; } - pid_t pid() const { return key(); } uid_t uid() const { return uid_; } const char* name() const { return name_; } @@ -301,10 +305,9 @@ class PidEntry : public EntryBaseDropped { } std::string formatHeader(const std::string& name, log_id_t id) const; - std::string format(const LogStatistics& stat, log_id_t id) const; + std::string format(const LogStatistics& stat, log_id_t id, pid_t pid) const; private: - const pid_t pid_; uid_t uid_; char* name_; }; @@ -313,26 +316,21 @@ class TidEntry : public EntryBaseDropped { public: TidEntry(pid_t tid, pid_t pid) : EntryBaseDropped(), - tid_(tid), pid_(pid), uid_(android::pidToUid(tid)), name_(android::tidToName(tid)) {} explicit TidEntry(const LogStatisticsElement& element) : EntryBaseDropped(element), - tid_(element.tid), pid_(element.pid), uid_(element.uid), - name_(android::tidToName(tid_)) {} + name_(android::tidToName(element.tid)) {} TidEntry(const TidEntry& element) : EntryBaseDropped(element), - tid_(element.tid_), pid_(element.pid_), uid_(element.uid_), name_(element.name_ ? strdup(element.name_) : nullptr) {} ~TidEntry() { free(name_); } - pid_t key() const { return tid_; } - pid_t tid() const { return key(); } pid_t pid() const { return pid_; } uid_t uid() const { return uid_; } const char* name() const { return name_; } @@ -362,10 +360,9 @@ class TidEntry : public EntryBaseDropped { } std::string formatHeader(const std::string& name, log_id_t id) const; - std::string format(const LogStatistics& stat, log_id_t id) const; + std::string format(const LogStatistics& stat, log_id_t id, pid_t pid) const; private: - const pid_t tid_; pid_t pid_; uid_t uid_; char* name_; @@ -392,7 +389,7 @@ class TagEntry : public EntryBaseDropped { } std::string formatHeader(const std::string& name, log_id_t id) const; - std::string format(const LogStatistics& stat, log_id_t id) const; + std::string format(const LogStatistics& stat, log_id_t id, uint32_t) const; private: const uint32_t tag_; @@ -490,18 +487,11 @@ struct std::hash class TagNameEntry : public EntryBase { public: explicit TagNameEntry(const LogStatisticsElement& element) - : EntryBase(element), - tid_(element.tid), - pid_(element.pid), - uid_(element.uid), - name_(element) {} + : EntryBase(element), tid_(element.tid), pid_(element.pid), uid_(element.uid) {} - const TagNameKey& key() const { return name_; } pid_t tid() const { return tid_; } pid_t pid() const { return pid_; } uid_t uid() const { return uid_; } - const char* name() const { return name_.data(); } - size_t getNameAllocLength() const { return name_.getAllocLength(); } void Add(const LogStatisticsElement& element) { if (uid_ != element.uid) { @@ -517,13 +507,12 @@ class TagNameEntry : public EntryBase { } std::string formatHeader(const std::string& name, log_id_t id) const; - std::string format(const LogStatistics& stat, log_id_t id) const; + std::string format(const LogStatistics& stat, log_id_t id, const TagNameKey& key_name) const; private: pid_t tid_; pid_t pid_; uid_t uid_; - TagNameKey name_; }; // Log Statistics @@ -584,7 +573,7 @@ class LogStatistics { const char* name = it.second.name(); if (name) size += strlen(name) + 1; } - for (auto it : tagNameTable) size += it.second.getNameAllocLength(); + for (auto it : tagNameTable) size += it.first.getAllocLength(); log_id_for_each(id) { size += uidTable[id].sizeOf(); size += uidTable[id].size() * sizeof(uidTable_t::iterator); From b0263af5a8ba63121a5a2a18a83d6bd19a5f59d5 Mon Sep 17 00:00:00 2001 From: Tom Cherry Date: Wed, 3 Jun 2020 15:38:32 -0700 Subject: [PATCH 3/3] logd: remove faulty optimization TagNameKey contains a pointer to a std::string and a std::string_view, such it can both own a string or reference a different string. This is meant to be a memory optimization. This, however, is actually a net pessimization. Due to these three below cases and typical usage pattern. Cases: 1) In the case where TagNameKey owns the string, 3 words are wasted, one for the pointer and two for the std::string_view. 2) In the case where TagNameKey references a short string, the same 3 words are wasted. This is because std::string has a feature called "Short String Optimization" that means std::string does not allocate for strings of sizes <= 10 on 32bit devices and <= 22 on 64bit devices. 3) In the case where TagNameKey references a longer string than the "Short String Optimization" limits, then this saves the string's length in bytes. Usage pattern: After boot on 32 bit cuttlefish, there were 679 entries for the first case, and only 69 in the third case. The 679 entries have an overhead of 679 * 3 * sizeof(void*) = 679 * 12 = 8148 bytes. The 69 strings in the third case have a total length and therefore savings of 1352 bytes. This is a net pessimization of 6796 bytes. I expect this same ratio to be similar throughout the device's uptime. This situation is worse on 64 bit devices. If cuttlefish were 64 bit, then there would have been only 18 items in the third case due to the larger "Short String Optimization" capacity, and the cost for the first case would have doubled. Given the above and the cost of maintaining extra code, this optimization is removed and a std::string is used as the hash table key instead. Test: logging unit tests Change-Id: I957c519b19edca4f7fc531d96b7144cf68bf4e16 --- logd/LogStatistics.cpp | 27 ++++++++++- logd/LogStatistics.h | 106 +++++------------------------------------ 2 files changed, 39 insertions(+), 94 deletions(-) diff --git a/logd/LogStatistics.cpp b/logd/LogStatistics.cpp index 625cbdec4..d49982af0 100644 --- a/logd/LogStatistics.cpp +++ b/logd/LogStatistics.cpp @@ -36,6 +36,30 @@ static const uint64_t monthSec = 31 * 24 * hourSec; std::atomic LogStatistics::SizesTotal; +static std::string TagNameKey(const LogStatisticsElement& element) { + if (IsBinary(element.log_id)) { + uint32_t tag = element.tag; + if (tag) { + const char* cp = android::tagToName(tag); + if (cp) { + return std::string(cp); + } + } + return android::base::StringPrintf("[%" PRIu32 "]", tag); + } + const char* msg = element.msg; + if (!msg) { + return "chatty"; + } + ++msg; + uint16_t len = element.msg_len; + len = (len <= 1) ? 0 : strnlen(msg, len - 1); + if (!len) { + return ""; + } + return std::string(msg, len); +} + LogStatistics::LogStatistics(bool enable_statistics) : enable(enable_statistics) { log_time now(CLOCK_REALTIME); log_id_for_each(id) { @@ -597,7 +621,8 @@ std::string TagNameEntry::formatHeader(const std::string& name, std::string("BYTES"), std::string("")); } -std::string TagNameEntry::format(const LogStatistics&, log_id_t, const TagNameKey& key_name) const { +std::string TagNameEntry::format(const LogStatistics&, log_id_t, + const std::string& key_name) const { std::string name; std::string pidstr; if (pid_ != (pid_t)-1) { diff --git a/logd/LogStatistics.h b/logd/LogStatistics.h index 9f085dca3..200c22810 100644 --- a/logd/LogStatistics.h +++ b/logd/LogStatistics.h @@ -397,93 +397,6 @@ class TagEntry : public EntryBaseDropped { uid_t uid_; }; -struct TagNameKey { - std::string* alloc; - std::string_view name; // Saves space if const char* - - explicit TagNameKey(const LogStatisticsElement& element) - : alloc(nullptr), name("", strlen("")) { - if (IsBinary(element.log_id)) { - uint32_t tag = element.tag; - if (tag) { - const char* cp = android::tagToName(tag); - if (cp) { - name = std::string_view(cp, strlen(cp)); - return; - } - } - alloc = new std::string( - android::base::StringPrintf("[%" PRIu32 "]", tag)); - if (!alloc) return; - name = std::string_view(alloc->c_str(), alloc->size()); - return; - } - const char* msg = element.msg; - if (!msg) { - name = std::string_view("chatty", strlen("chatty")); - return; - } - ++msg; - uint16_t len = element.msg_len; - len = (len <= 1) ? 0 : strnlen(msg, len - 1); - if (!len) { - name = std::string_view("", strlen("")); - return; - } - alloc = new std::string(msg, len); - if (!alloc) return; - name = std::string_view(alloc->c_str(), alloc->size()); - } - - explicit TagNameKey(TagNameKey&& rval) noexcept - : alloc(rval.alloc), name(rval.name.data(), rval.name.length()) { - rval.alloc = nullptr; - } - - explicit TagNameKey(const TagNameKey& rval) - : alloc(rval.alloc ? new std::string(*rval.alloc) : nullptr), - name(alloc ? alloc->data() : rval.name.data(), rval.name.length()) { - } - - ~TagNameKey() { - if (alloc) delete alloc; - } - - operator const std::string_view() const { - return name; - } - - const char* data() const { - return name.data(); - } - size_t length() const { - return name.length(); - } - - bool operator==(const TagNameKey& rval) const { - if (length() != rval.length()) return false; - if (length() == 0) return true; - return fastcmp(data(), rval.data(), length()) == 0; - } - bool operator!=(const TagNameKey& rval) const { - return !(*this == rval); - } - - size_t getAllocLength() const { - return alloc ? alloc->length() + 1 + sizeof(std::string) : 0; - } -}; - -// Hash for TagNameKey -template <> -struct std::hash - : public std::unary_function { - size_t operator()(const TagNameKey& __t) const noexcept { - if (!__t.length()) return 0; - return std::hash()(std::string_view(__t)); - } -}; - class TagNameEntry : public EntryBase { public: explicit TagNameEntry(const LogStatisticsElement& element) @@ -507,7 +420,7 @@ class TagNameEntry : public EntryBase { } std::string formatHeader(const std::string& name, log_id_t id) const; - std::string format(const LogStatistics& stat, log_id_t id, const TagNameKey& key_name) const; + std::string format(const LogStatistics& stat, log_id_t id, const std::string& key_name) const; private: pid_t tid_; @@ -515,7 +428,6 @@ class TagNameEntry : public EntryBase { uid_t uid_; }; -// Log Statistics class LogStatistics { friend UidEntry; friend PidEntry; @@ -556,7 +468,7 @@ class LogStatistics { tagTable_t securityTagTable GUARDED_BY(lock_); // global tag list - typedef LogHashtable tagNameTable_t; + typedef LogHashtable tagNameTable_t; tagNameTable_t tagNameTable; size_t sizeOf() const REQUIRES(lock_) { @@ -573,13 +485,21 @@ class LogStatistics { const char* name = it.second.name(); if (name) size += strlen(name) + 1; } - for (auto it : tagNameTable) size += it.first.getAllocLength(); + for (auto it : tagNameTable) { + size += sizeof(std::string); + size_t len = it.first.size(); + // Account for short string optimization: if the string's length is <= 22 bytes for 64 + // bit or <= 10 bytes for 32 bit, then there is no additional allocation. + if ((sizeof(std::string) == 24 && len > 22) || + (sizeof(std::string) != 24 && len > 10)) { + size += len; + } + } log_id_for_each(id) { size += uidTable[id].sizeOf(); size += uidTable[id].size() * sizeof(uidTable_t::iterator); size += pidSystemTable[id].sizeOf(); - size += - pidSystemTable[id].size() * sizeof(pidSystemTable_t::iterator); + size += pidSystemTable[id].size() * sizeof(pidSystemTable_t::iterator); } return size; }