From f74503dd4657c7a61ecdb803dc0434fb1d809ada Mon Sep 17 00:00:00 2001 From: Tom Cherry Date: Fri, 19 Jun 2020 12:21:21 -0700 Subject: [PATCH] logd: optionally track the full size of log buffers ChattyLogBuffer ignores the metadata (timestamp, pid, std::list<> iterators, etc) of log entries when calculating the size used by a given log buffer. For example, if 1MB is the specified size of the 'main' log buffer, logd will use between ~1.3MB and ~2MB of overall memory for 'main' log buffer. LogStatistics does track the overall memory used and labels it 'Overhead', however this 'Overhead' is only informative and is not used for Pruning or Chatty calculations. This is problematic, since it makes logd's memory usage inconsistent: depending on the pattern of logging, there can be substantially more memory used than the specified log buffer size. This is further complicated by the fact that chatty messages are entirely metadata and therefore not counted as contributing to the log buffer size. This change would switch logd to always track the full size of log buffers, but there are two problems with this approach: 1) Unless users double their buffer sizes, then they'd have substantially fewer logs after the change 2) Chatty logic would change and it's difficult to evaluate. Therefore this change only provides the framework to track the full size of log buffers. This allows an apples to apples comparison of ChattyLogBuffer and SerializedLogBuffer. With this option enabled, logd reports the following values: ChattyLogBuffer: Total log size (logcat -g), 'Total' / 'Now' (logcat -S), and 'Overhead' (logcat -S) all report the full size of log entries including metadata. SerializedLogBuffer: Total log size (logcat -g) and 'Overhead' (logcat -S) report the compressed size of the log entries including metadata. 'Total' / 'Now' (logcat -S) reports the uncompressed size of the log entries that are available including metadata. Test: logging statistics are correct Change-Id: If17682af8bb605f31387d7b210b69a301dd48f07 --- logd/LogBufferElement.cpp | 5 ++ logd/LogBufferTest.h | 2 +- logd/LogStatistics.cpp | 83 ++++++++++++++++++++++++----- logd/LogStatistics.h | 60 ++++++++++++++------- logd/SerializedLogBuffer.cpp | 32 +++++------ logd/SerializedLogBuffer.h | 1 + logd/SerializedLogChunk.h | 4 +- logd/SerializedLogEntry.h | 1 + logd/fuzz/log_buffer_log_fuzzer.cpp | 2 +- logd/main.cpp | 2 +- 10 files changed, 142 insertions(+), 50 deletions(-) diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp index dd779f97b..26affa8d4 100644 --- a/logd/LogBufferElement.cpp +++ b/logd/LogBufferElement.cpp @@ -99,6 +99,10 @@ uint32_t LogBufferElement::GetTag() const { } LogStatisticsElement LogBufferElement::ToLogStatisticsElement() const { + // Estimate the size of this element in the parent std::list<> by adding two void*'s + // corresponding to the next/prev pointers and aligning to 64 bit. + uint16_t element_in_list_size = + (sizeof(*this) + 2 * sizeof(void*) + sizeof(uint64_t) - 1) & -sizeof(uint64_t); return LogStatisticsElement{ .uid = uid(), .pid = pid(), @@ -109,6 +113,7 @@ LogStatisticsElement LogBufferElement::ToLogStatisticsElement() const { .msg_len = msg_len(), .dropped_count = dropped_count(), .log_id = log_id(), + .total_len = static_cast(element_in_list_size + msg_len()), }; } diff --git a/logd/LogBufferTest.h b/logd/LogBufferTest.h index 5d57ad1cf..1fd22c236 100644 --- a/logd/LogBufferTest.h +++ b/logd/LogBufferTest.h @@ -87,6 +87,6 @@ class LogBufferTest : public testing::TestWithParam { LogReaderList reader_list_; LogTags tags_; PruneList prune_; - LogStatistics stats_{false}; + LogStatistics stats_{false, true}; std::unique_ptr log_buffer_; }; diff --git a/logd/LogStatistics.cpp b/logd/LogStatistics.cpp index 3cd8fde5b..1705d4808 100644 --- a/logd/LogStatistics.cpp +++ b/logd/LogStatistics.cpp @@ -27,6 +27,7 @@ #include +#include #include #include "LogBufferElement.h" @@ -60,7 +61,8 @@ static std::string TagNameKey(const LogStatisticsElement& element) { return std::string(msg, len); } -LogStatistics::LogStatistics(bool enable_statistics) : enable(enable_statistics) { +LogStatistics::LogStatistics(bool enable_statistics, bool track_total_size) + : enable(enable_statistics), track_total_size_(track_total_size) { log_time now(CLOCK_REALTIME); log_id_for_each(id) { mSizes[id] = 0; @@ -113,10 +115,15 @@ void LogStatistics::AddTotal(log_id_t log_id, uint16_t size) { ++mElementsTotal[log_id]; } -void LogStatistics::Add(const LogStatisticsElement& element) { +void LogStatistics::Add(LogStatisticsElement element) { auto lock = std::lock_guard{lock_}; + + if (!track_total_size_) { + element.total_len = element.msg_len; + } + log_id_t log_id = element.log_id; - uint16_t size = element.msg_len; + uint16_t size = element.total_len; mSizes[log_id] += size; ++mElements[log_id]; @@ -184,10 +191,15 @@ void LogStatistics::Add(const LogStatisticsElement& element) { } } -void LogStatistics::Subtract(const LogStatisticsElement& element) { +void LogStatistics::Subtract(LogStatisticsElement element) { auto lock = std::lock_guard{lock_}; + + if (!track_total_size_) { + element.total_len = element.msg_len; + } + log_id_t log_id = element.log_id; - uint16_t size = element.msg_len; + uint16_t size = element.total_len; mSizes[log_id] -= size; --mElements[log_id]; if (element.dropped_count) { @@ -230,7 +242,9 @@ void LogStatistics::Subtract(const LogStatisticsElement& element) { // Atomically set an entry to drop // entry->setDropped(1) must follow this call, caller should do this explicitly. -void LogStatistics::Drop(const LogStatisticsElement& element) { +void LogStatistics::Drop(LogStatisticsElement element) { + CHECK_EQ(element.dropped_count, 0U); + auto lock = std::lock_guard{lock_}; log_id_t log_id = element.log_id; uint16_t size = element.msg_len; @@ -265,6 +279,43 @@ void LogStatistics::Drop(const LogStatisticsElement& element) { tagNameTable.Subtract(TagNameKey(element), element); } +void LogStatistics::Erase(LogStatisticsElement element) { + CHECK_GT(element.dropped_count, 0U); + CHECK_EQ(element.msg_len, 0U); + + auto lock = std::lock_guard{lock_}; + + if (!track_total_size_) { + element.total_len = 0; + } + + log_id_t log_id = element.log_id; + --mElements[log_id]; + --mDroppedElements[log_id]; + mSizes[log_id] -= element.total_len; + + uidTable[log_id].Erase(element.uid, element); + if (element.uid == AID_SYSTEM) { + pidSystemTable[log_id].Erase(element.pid, element); + } + + if (!enable) { + return; + } + + pidTable.Erase(element.pid, element); + tidTable.Erase(element.tid, element); + + uint32_t tag = element.tag; + if (tag) { + if (log_id == LOG_ID_SECURITY) { + securityTagTable.Erase(tag, element); + } else { + tagTable.Erase(tag, element); + } + } +} + const char* LogStatistics::UidToName(uid_t uid) const { auto lock = std::lock_guard{lock_}; return UidToNameLocked(uid); @@ -876,12 +927,20 @@ std::string LogStatistics::Format(uid_t uid, pid_t pid, unsigned int logMask) co if (els) { oldLength = output.length(); if (spaces < 0) spaces = 0; - // estimate the std::list overhead. - static const size_t overhead = - ((sizeof(LogBufferElement) + sizeof(uint64_t) - 1) & - -sizeof(uint64_t)) + - sizeof(std::list); - size_t szs = mSizes[id] + els * overhead; + size_t szs = 0; + if (overhead_[id]) { + szs = *overhead_[id]; + } else if (track_total_size_) { + szs = mSizes[id]; + } else { + // Legacy fallback for Chatty without track_total_size_ + // Estimate the size of this element in the parent std::list<> by adding two void*'s + // corresponding to the next/prev pointers and aligning to 64 bit. + static const size_t overhead = + (sizeof(LogBufferElement) + 2 * sizeof(void*) + sizeof(uint64_t) - 1) & + -sizeof(uint64_t); + szs = mSizes[id] + els * overhead; + } totalSize += szs; output += android::base::StringPrintf("%*s%zu", spaces, "", szs); spaces -= output.length() - oldLength; diff --git a/logd/LogStatistics.h b/logd/LogStatistics.h index 5f558026c..d440a8c61 100644 --- a/logd/LogStatistics.h +++ b/logd/LogStatistics.h @@ -57,6 +57,7 @@ struct LogStatisticsElement { uint16_t msg_len; uint16_t dropped_count; log_id_t log_id; + uint16_t total_len; }; template @@ -172,6 +173,13 @@ class LogHashtable { } } + void Erase(const TKey& key, const LogStatisticsElement& element) { + iterator it = map.find(key); + if (it != map.end()) { + it->second.Erase(element); + } + } + iterator begin() { return map.begin(); } const_iterator begin() const { return map.begin(); } iterator end() { return map.end(); } @@ -181,15 +189,17 @@ class LogHashtable { class EntryBase { public: EntryBase() : size_(0) {} - explicit EntryBase(const LogStatisticsElement& element) : size_(element.msg_len) {} + explicit EntryBase(const LogStatisticsElement& element) : size_(element.total_len) {} size_t getSizes() const { return size_; } - void Add(const LogStatisticsElement& element) { size_ += element.msg_len; } + void Add(const LogStatisticsElement& element) { size_ += element.total_len; } bool Subtract(const LogStatisticsElement& element) { - size_ -= element.msg_len; - return !size_; + size_ -= element.total_len; + return size_ == 0; } + void Drop(const LogStatisticsElement& element) { size_ -= element.msg_len; } + void Erase(const LogStatisticsElement& element) { size_ -= element.total_len; } static constexpr size_t PRUNED_LEN = 14; static constexpr size_t TOTAL_LEN = 80; @@ -229,11 +239,11 @@ class EntryBaseDropped : public EntryBase { } bool Subtract(const LogStatisticsElement& element) { dropped_ -= element.dropped_count; - return EntryBase::Subtract(element) && !dropped_; + return EntryBase::Subtract(element) && dropped_ == 0; } void Drop(const LogStatisticsElement& element) { dropped_ += 1; - EntryBase::Subtract(element); + EntryBase::Drop(element); } private: @@ -505,20 +515,23 @@ class LogStatistics { } public: - explicit LogStatistics(bool enable_statistics); + LogStatistics(bool enable_statistics, bool track_total_size); void AddTotal(log_id_t log_id, uint16_t size) EXCLUDES(lock_); - void Add(const LogStatisticsElement& entry) EXCLUDES(lock_); - void Subtract(const LogStatisticsElement& entry) EXCLUDES(lock_); - // entry->setDropped(1) must follow this call - void Drop(const LogStatisticsElement& entry) EXCLUDES(lock_); - // Correct for coalescing two entries referencing dropped content - void Erase(const LogStatisticsElement& element) EXCLUDES(lock_) { - auto lock = std::lock_guard{lock_}; - log_id_t log_id = element.log_id; - --mElements[log_id]; - --mDroppedElements[log_id]; - } + + // Add is for adding an element to the log buffer. It may be a chatty element in the case of + // log deduplication. Add the total size of the element to statistics. + void Add(LogStatisticsElement entry) EXCLUDES(lock_); + // Subtract is for removing an element from the log buffer. It may be a chatty element. + // Subtract the total size of the element from statistics. + void Subtract(LogStatisticsElement entry) EXCLUDES(lock_); + // Drop is for converting a normal element into a chatty element. entry->setDropped(1) must + // follow this call. Subtract only msg_len from statistics, since a chatty element will remain. + void Drop(LogStatisticsElement entry) EXCLUDES(lock_); + // Erase is for coalescing two chatty elements into one. Erase() is called on the element that + // is removed from the log buffer. Subtract the total size of the element, which is by + // definition only the size of the LogBufferElement + list overhead for chatty elements. + void Erase(LogStatisticsElement element) EXCLUDES(lock_); void WorstTwoUids(log_id id, size_t threshold, int* worst, size_t* worst_sizes, size_t* second_worst_sizes) const EXCLUDES(lock_); @@ -533,6 +546,9 @@ class LogStatistics { // Snapshot of the sizes for a given log buffer. size_t Sizes(log_id_t id) const EXCLUDES(lock_) { auto lock = std::lock_guard{lock_}; + if (overhead_[id]) { + return *overhead_[id]; + } return mSizes[id]; } // TODO: Get rid of this entirely. @@ -546,6 +562,11 @@ class LogStatistics { uid_t PidToUid(pid_t pid) EXCLUDES(lock_); const char* UidToName(uid_t uid) const EXCLUDES(lock_); + void set_overhead(log_id_t id, size_t size) { + auto lock = std::lock_guard{lock_}; + overhead_[id] = size; + } + private: template void WorstTwoWithThreshold(const LogHashtable& table, size_t threshold, @@ -559,4 +580,7 @@ class LogStatistics { const char* UidToNameLocked(uid_t uid) const REQUIRES(lock_); mutable std::mutex lock_; + bool track_total_size_; + + std::optional overhead_[LOG_ID_MAX] GUARDED_BY(lock_); }; diff --git a/logd/SerializedLogBuffer.cpp b/logd/SerializedLogBuffer.cpp index 0f307945a..aec24c3f4 100644 --- a/logd/SerializedLogBuffer.cpp +++ b/logd/SerializedLogBuffer.cpp @@ -109,19 +109,16 @@ int SerializedLogBuffer::Log(log_id_t log_id, log_time realtime, uid_t uid, pid_ } void SerializedLogBuffer::MaybePrune(log_id_t log_id) { - auto get_total_size = [](const auto& buffer) { - size_t total_size = 0; - for (const auto& chunk : buffer) { - total_size += chunk.PruneSize(); - } - return total_size; - }; - size_t total_size = get_total_size(logs_[log_id]); + size_t total_size = GetSizeUsed(log_id); + size_t after_size = total_size; if (total_size > max_size_[log_id]) { Prune(log_id, total_size - max_size_[log_id], 0); + after_size = GetSizeUsed(log_id); LOG(INFO) << "Pruned Logs from log_id: " << log_id << ", previous size: " << total_size - << " after size: " << get_total_size(logs_[log_id]); + << " after size: " << after_size; } + + stats_->set_overhead(log_id, after_size); } void SerializedLogBuffer::StartDeleterThread() { @@ -349,19 +346,22 @@ bool SerializedLogBuffer::Clear(log_id_t id, uid_t uid) { return Prune(id, ULONG_MAX, uid); } +unsigned long SerializedLogBuffer::GetSizeUsed(log_id_t id) { + size_t total_size = 0; + for (const auto& chunk : logs_[id]) { + total_size += chunk.PruneSize(); + } + return total_size; +} + unsigned long SerializedLogBuffer::GetSize(log_id_t id) { auto lock = std::lock_guard{lock_}; - size_t retval = 2 * max_size_[id] / 3; // See the comment in SetSize(). - return retval; + return max_size_[id]; } // New SerializedLogChunk objects will be allocated according to the new size, but older one are // unchanged. MaybePrune() is called on the log buffer to reduce it to an appropriate size if the // new size is lower. -// ChattyLogBuffer/SimpleLogBuffer don't consider the 'Overhead' of LogBufferElement or the -// std::list<> overhead as part of the log size. SerializedLogBuffer does by its very nature, so -// the 'size' metric is not compatible between them. Their actual memory usage is between 1.5x and -// 2x of what they claim to use, so we conservatively set our internal size as size + size / 2. int SerializedLogBuffer::SetSize(log_id_t id, unsigned long size) { // Reasonable limits ... if (!__android_logger_valid_buffer_size(size)) { @@ -369,7 +369,7 @@ int SerializedLogBuffer::SetSize(log_id_t id, unsigned long size) { } auto lock = std::lock_guard{lock_}; - max_size_[id] = size + size / 2; + max_size_[id] = size; MaybePrune(id); diff --git a/logd/SerializedLogBuffer.h b/logd/SerializedLogBuffer.h index 421d41997..2b2559f9c 100644 --- a/logd/SerializedLogBuffer.h +++ b/logd/SerializedLogBuffer.h @@ -61,6 +61,7 @@ class SerializedLogBuffer final : public LogBuffer { REQUIRES_SHARED(lock_); void NotifyReadersOfPrune(log_id_t log_id, const std::list::iterator& chunk) REQUIRES(reader_list_->reader_threads_lock()); + unsigned long GetSizeUsed(log_id_t id) REQUIRES(lock_); void StartDeleterThread() REQUIRES(lock_); void DeleterThread(); diff --git a/logd/SerializedLogChunk.h b/logd/SerializedLogChunk.h index 65a1e86c4..50bae638c 100644 --- a/logd/SerializedLogChunk.h +++ b/logd/SerializedLogChunk.h @@ -44,7 +44,9 @@ class SerializedLogChunk { // If this buffer has been compressed, we only consider its compressed size when accounting for // memory consumption for pruning. This is since the uncompressed log is only by used by // readers, and thus not a representation of how much these logs cost to keep in memory. - size_t PruneSize() const { return compressed_log_.size() ?: contents_.size(); } + size_t PruneSize() const { + return sizeof(*this) + (compressed_log_.size() ?: contents_.size()); + } void FinishWriting() { writer_active_ = false; diff --git a/logd/SerializedLogEntry.h b/logd/SerializedLogEntry.h index f599abeaa..2f2c244ea 100644 --- a/logd/SerializedLogEntry.h +++ b/logd/SerializedLogEntry.h @@ -59,6 +59,7 @@ class __attribute__((packed)) SerializedLogEntry { .msg_len = msg_len(), .dropped_count = 0, .log_id = log_id, + .total_len = total_len(), }; } diff --git a/logd/fuzz/log_buffer_log_fuzzer.cpp b/logd/fuzz/log_buffer_log_fuzzer.cpp index 1dc996c12..8309f9514 100644 --- a/logd/fuzz/log_buffer_log_fuzzer.cpp +++ b/logd/fuzz/log_buffer_log_fuzzer.cpp @@ -114,7 +114,7 @@ extern "C" int LLVMFuzzerTestOneInput(const uint8_t* data, size_t size) { LogReaderList reader_list; LogTags tags; PruneList prune_list; - LogStatistics stats(true); + LogStatistics stats(true, true); std::unique_ptr log_buffer; #ifdef FUZZ_SERIALIZED log_buffer.reset(new SerializedLogBuffer(&reader_list, &tags, &stats)); diff --git a/logd/main.cpp b/logd/main.cpp index e1ec52bc2..350642b8a 100644 --- a/logd/main.cpp +++ b/logd/main.cpp @@ -259,7 +259,7 @@ int main(int argc, char* argv[]) { bool enable_full_log_statistics = __android_logger_property_get_bool( "logd.statistics", BOOL_DEFAULT_TRUE | BOOL_DEFAULT_FLAG_PERSIST | BOOL_DEFAULT_FLAG_ENG | BOOL_DEFAULT_FLAG_SVELTE); - LogStatistics log_statistics(enable_full_log_statistics); + LogStatistics log_statistics(enable_full_log_statistics, false); // Serves the purpose of managing the last logs times read on a // socket connection, and as a reader lock on a range of log