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