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
diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp
index dd779f9..26affa8 100644
--- a/logd/LogBufferElement.cpp
+++ b/logd/LogBufferElement.cpp
@@ -99,6 +99,10 @@
}
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 @@
.msg_len = msg_len(),
.dropped_count = dropped_count(),
.log_id = log_id(),
+ .total_len = static_cast<uint16_t>(element_in_list_size + msg_len()),
};
}
diff --git a/logd/LogBufferTest.h b/logd/LogBufferTest.h
index 5d57ad1..1fd22c2 100644
--- a/logd/LogBufferTest.h
+++ b/logd/LogBufferTest.h
@@ -87,6 +87,6 @@
LogReaderList reader_list_;
LogTags tags_;
PruneList prune_;
- LogStatistics stats_{false};
+ LogStatistics stats_{false, true};
std::unique_ptr<LogBuffer> log_buffer_;
};
diff --git a/logd/LogStatistics.cpp b/logd/LogStatistics.cpp
index 3cd8fde..1705d48 100644
--- a/logd/LogStatistics.cpp
+++ b/logd/LogStatistics.cpp
@@ -27,6 +27,7 @@
#include <list>
+#include <android-base/logging.h>
#include <private/android_logger.h>
#include "LogBufferElement.h"
@@ -60,7 +61,8 @@
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 @@
++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::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 @@
// 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 @@
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 @@
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<LogBufferElement*>);
- 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 5f55802..d440a8c 100644
--- a/logd/LogStatistics.h
+++ b/logd/LogStatistics.h
@@ -57,6 +57,7 @@
uint16_t msg_len;
uint16_t dropped_count;
log_id_t log_id;
+ uint16_t total_len;
};
template <typename TKey, typename TEntry>
@@ -172,6 +173,13 @@
}
}
+ 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 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 @@
}
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 @@
}
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 @@
// 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 @@
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 <typename TKey, typename TEntry>
void WorstTwoWithThreshold(const LogHashtable<TKey, TEntry>& table, size_t threshold,
@@ -559,4 +580,7 @@
const char* UidToNameLocked(uid_t uid) const REQUIRES(lock_);
mutable std::mutex lock_;
+ bool track_total_size_;
+
+ std::optional<size_t> overhead_[LOG_ID_MAX] GUARDED_BY(lock_);
};
diff --git a/logd/SerializedLogBuffer.cpp b/logd/SerializedLogBuffer.cpp
index 0f30794..aec24c3 100644
--- a/logd/SerializedLogBuffer.cpp
+++ b/logd/SerializedLogBuffer.cpp
@@ -109,19 +109,16 @@
}
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 @@
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 @@
}
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 421d419..2b2559f 100644
--- a/logd/SerializedLogBuffer.h
+++ b/logd/SerializedLogBuffer.h
@@ -61,6 +61,7 @@
REQUIRES_SHARED(lock_);
void NotifyReadersOfPrune(log_id_t log_id, const std::list<SerializedLogChunk>::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 65a1e86..50bae63 100644
--- a/logd/SerializedLogChunk.h
+++ b/logd/SerializedLogChunk.h
@@ -44,7 +44,9 @@
// 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 f599abe..2f2c244 100644
--- a/logd/SerializedLogEntry.h
+++ b/logd/SerializedLogEntry.h
@@ -59,6 +59,7 @@
.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 1dc996c..8309f95 100644
--- a/logd/fuzz/log_buffer_log_fuzzer.cpp
+++ b/logd/fuzz/log_buffer_log_fuzzer.cpp
@@ -114,7 +114,7 @@
LogReaderList reader_list;
LogTags tags;
PruneList prune_list;
- LogStatistics stats(true);
+ LogStatistics stats(true, true);
std::unique_ptr<LogBuffer> 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 e1ec52b..350642b 100644
--- a/logd/main.cpp
+++ b/logd/main.cpp
@@ -259,7 +259,7 @@
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