ACPR/android_system_core
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

logd: optionally track the full size of log buffers

Browse source 
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
This commit is contained in:
Tom Cherry 2020-06-19 12:21:21 -07:00
parent c3f17840ae
commit f74503dd46
10 changed files with 142 additions and 50 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

5
logd/LogBufferElement.cpp
View file

@ -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<uint16_t>(element_in_list_size + msg_len()),
};
}

2
logd/LogBufferTest.h
View file

@ -87,6 +87,6 @@ class LogBufferTest : public testing::TestWithParam<std::string> {
LogReaderList reader_list_;
LogTags tags_;
PruneList prune_;
LogStatistics stats_{false};
LogStatistics stats_{false, true};
std::unique_ptr<LogBuffer> log_buffer_;
};

83
logd/LogStatistics.cpp
View file

@ -27,6 +27,7 @@
#include <list>
#include <android-base/logging.h>
#include <private/android_logger.h>
#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<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;

60
logd/LogStatistics.h
View file

@ -57,6 +57,7 @@ struct LogStatisticsElement {
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 @@ 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 <typename TKey, typename TEntry>
void WorstTwoWithThreshold(const LogHashtable<TKey, TEntry>& 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<size_t> overhead_[LOG_ID_MAX] GUARDED_BY(lock_);
};

32
logd/SerializedLogBuffer.cpp
View file

@ -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);

1
logd/SerializedLogBuffer.h
View file

@ -61,6 +61,7 @@ class SerializedLogBuffer final : public LogBuffer {
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();

4
logd/SerializedLogChunk.h
View file

@ -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;

1
logd/SerializedLogEntry.h
View file

@ -59,6 +59,7 @@ class __attribute__((packed)) SerializedLogEntry {
.msg_len = msg_len(),
.dropped_count = 0,
.log_id = log_id,
.total_len = total_len(),
};
}

2
logd/fuzz/log_buffer_log_fuzzer.cpp
View file

@ -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<LogBuffer> log_buffer;
#ifdef FUZZ_SERIALIZED
log_buffer.reset(new SerializedLogBuffer(&reader_list, &tags, &stats));

2
logd/main.cpp
View file

@ -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