Merge "logd: optionally track the full size of log buffers" am: 478d93846d

Original change: https://android-review.googlesource.com/c/platform/system/core/+/1353171

Change-Id: I4f1b942079a9ac2a6ef5e99a1720baf9b1acc57f
This commit is contained in:
Tom Cherry 2020-07-13 19:50:41 +00:00 committed by Automerger Merge Worker
commit a7aaf84b4e
10 changed files with 142 additions and 50 deletions

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()),
};
}

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_;
};

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;

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_);
};

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

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

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;

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(),
};
}

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

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