From 0b01ff0f39cfecae21cf11b213a36e2c0e504d09 Mon Sep 17 00:00:00 2001 From: Tom Cherry Date: Thu, 21 May 2020 10:37:22 -0700 Subject: [PATCH 1/3] logd: use RAII locks and thread annotations Test: unit tests Change-Id: I38623130a96f17a47ed79753e24b25efa9e38279 --- logd/ChattyLogBuffer.cpp | 45 +++++++++++--------------------- logd/ChattyLogBuffer.h | 33 ++++++++++++----------- logd/rwlock.h | 56 ++++++++++++++++++++++++++++++++++++++++ 3 files changed, 87 insertions(+), 47 deletions(-) create mode 100644 logd/rwlock.h diff --git a/logd/ChattyLogBuffer.cpp b/logd/ChattyLogBuffer.cpp index f1305a5b4..369587ac3 100644 --- a/logd/ChattyLogBuffer.cpp +++ b/logd/ChattyLogBuffer.cpp @@ -59,8 +59,6 @@ void ChattyLogBuffer::Init() { ChattyLogBuffer::ChattyLogBuffer(LogReaderList* reader_list, LogTags* tags, PruneList* prune, LogStatistics* stats) : reader_list_(reader_list), tags_(tags), prune_(prune), stats_(stats) { - pthread_rwlock_init(&mLogElementsLock, nullptr); - log_id_for_each(i) { lastLoggedElements[i] = nullptr; droppedElements[i] = nullptr; @@ -162,10 +160,8 @@ int ChattyLogBuffer::Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pi // b/137093665: don't coalesce security messages. if (log_id == LOG_ID_SECURITY) { - wrlock(); + auto lock = std::lock_guard{lock_}; log(elem); - unlock(); - return len; } @@ -189,7 +185,7 @@ int ChattyLogBuffer::Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pi return -EACCES; } - wrlock(); + auto lock = std::lock_guard{lock_}; LogBufferElement* currentLast = lastLoggedElements[log_id]; if (currentLast) { LogBufferElement* dropped = droppedElements[log_id]; @@ -289,14 +285,12 @@ int ChattyLogBuffer::Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pi // check for overflow if (total >= std::numeric_limits::max()) { log(currentLast); - unlock(); return len; } stats_->AddTotal(currentLast); delete currentLast; swab = total; event->payload.data = htole32(swab); - unlock(); return len; } if (count == USHRT_MAX) { @@ -313,7 +307,6 @@ int ChattyLogBuffer::Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pi } droppedElements[log_id] = currentLast; lastLoggedElements[log_id] = elem; - unlock(); return len; } if (dropped) { // State 1 or 2 @@ -331,12 +324,9 @@ int ChattyLogBuffer::Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pi lastLoggedElements[log_id] = new LogBufferElement(*elem); log(elem); - unlock(); - return len; } -// assumes ChattyLogBuffer::wrlock() held, owns elem, look after garbage collection void ChattyLogBuffer::log(LogBufferElement* elem) { mLogElements.push_back(elem); stats_->Add(elem); @@ -344,7 +334,6 @@ void ChattyLogBuffer::log(LogBufferElement* elem) { reader_list_->NotifyNewLog(1 << elem->getLogId()); } -// ChattyLogBuffer::wrlock() must be held when this function is called. void ChattyLogBuffer::maybePrune(log_id_t id) { unsigned long prune_rows; if (stats_->ShouldPrune(id, log_buffer_size(id), &prune_rows)) { @@ -540,8 +529,6 @@ void ChattyLogBuffer::kickMe(LogReaderThread* me, log_id_t id, unsigned long pru // The third thread is optional, and only gets hit if there was a whitelist // and more needs to be pruned against the backstop of the region lock. // -// ChattyLogBuffer::wrlock() must be held when this function is called. -// bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { LogReaderThread* oldest = nullptr; bool busy = false; @@ -846,9 +833,10 @@ bool ChattyLogBuffer::Clear(log_id_t id, uid_t uid) { // one entry, not another clear run, so we are looking for // the quick side effect of the return value to tell us if // we have a _blocked_ reader. - wrlock(); - busy = prune(id, 1, uid); - unlock(); + { + auto lock = std::lock_guard{lock_}; + busy = prune(id, 1, uid); + } // It is still busy, blocked reader(s), lets kill them all! // otherwise, lets be a good citizen and preserve the slow // readers and let the clear run (below) deal with determining @@ -865,9 +853,10 @@ bool ChattyLogBuffer::Clear(log_id_t id, uid_t uid) { } } } - wrlock(); - busy = prune(id, ULONG_MAX, uid); - unlock(); + { + auto lock = std::lock_guard{lock_}; + busy = prune(id, ULONG_MAX, uid); + } if (!busy || !--retry) { break; } @@ -882,17 +871,15 @@ int ChattyLogBuffer::SetSize(log_id_t id, unsigned long size) { if (!__android_logger_valid_buffer_size(size)) { return -1; } - wrlock(); + auto lock = std::lock_guard{lock_}; log_buffer_size(id) = size; - unlock(); return 0; } // get the total space allocated to "id" unsigned long ChattyLogBuffer::GetSize(log_id_t id) { - rdlock(); + auto shared_lock = SharedLock{lock_}; size_t retval = log_buffer_size(id); - unlock(); return retval; } @@ -902,7 +889,7 @@ uint64_t ChattyLogBuffer::FlushTo( LogBufferElementCollection::iterator it; uid_t uid = writer->uid(); - rdlock(); + auto shared_lock = SharedLock{lock_}; if (start <= 1) { // client wants to start from the beginning @@ -957,7 +944,7 @@ uint64_t ChattyLogBuffer::FlushTo( (element->getDropped() && !sameTid) ? 0 : element->getTid(); } - unlock(); + shared_lock.unlock(); curr = element->getSequence(); // range locking in LastLogTimes looks after us @@ -965,9 +952,7 @@ uint64_t ChattyLogBuffer::FlushTo( return FLUSH_ERROR; } - rdlock(); + shared_lock.lock_shared(); } - unlock(); - return curr; } diff --git a/logd/ChattyLogBuffer.h b/logd/ChattyLogBuffer.h index 29a421d62..42cdeec81 100644 --- a/logd/ChattyLogBuffer.h +++ b/logd/ChattyLogBuffer.h @@ -22,6 +22,7 @@ #include #include +#include #include #include #include @@ -34,25 +35,25 @@ #include "LogTags.h" #include "LogWhiteBlackList.h" #include "LogWriter.h" +#include "rwlock.h" typedef std::list LogBufferElementCollection; class ChattyLogBuffer : public LogBuffer { - LogBufferElementCollection mLogElements; - pthread_rwlock_t mLogElementsLock; + LogBufferElementCollection mLogElements GUARDED_BY(lock_); // watermark of any worst/chatty uid processing typedef std::unordered_map LogBufferIteratorMap; - LogBufferIteratorMap mLastWorst[LOG_ID_MAX]; + LogBufferIteratorMap mLastWorst[LOG_ID_MAX] GUARDED_BY(lock_); // watermark of any worst/chatty pid of system processing typedef std::unordered_map LogBufferPidIteratorMap; - LogBufferPidIteratorMap mLastWorstPidOfSystem[LOG_ID_MAX]; + LogBufferPidIteratorMap mLastWorstPidOfSystem[LOG_ID_MAX] GUARDED_BY(lock_); - unsigned long mMaxSize[LOG_ID_MAX]; + unsigned long mMaxSize[LOG_ID_MAX] GUARDED_BY(lock_); - LogBufferElement* lastLoggedElements[LOG_ID_MAX]; - LogBufferElement* droppedElements[LOG_ID_MAX]; - void log(LogBufferElement* elem); + LogBufferElement* lastLoggedElements[LOG_ID_MAX] GUARDED_BY(lock_); + LogBufferElement* droppedElements[LOG_ID_MAX] GUARDED_BY(lock_); + void log(LogBufferElement* elem) REQUIRES(lock_); public: ChattyLogBuffer(LogReaderList* reader_list, LogTags* tags, PruneList* prune, @@ -71,20 +72,16 @@ class ChattyLogBuffer : public LogBuffer { int SetSize(log_id_t id, unsigned long size) override; private: - void wrlock() { pthread_rwlock_wrlock(&mLogElementsLock); } - void rdlock() { pthread_rwlock_rdlock(&mLogElementsLock); } - void unlock() { pthread_rwlock_unlock(&mLogElementsLock); } + void maybePrune(log_id_t id) REQUIRES(lock_); + void kickMe(LogReaderThread* me, log_id_t id, unsigned long pruneRows) REQUIRES_SHARED(lock_); - void maybePrune(log_id_t id); - void kickMe(LogReaderThread* me, log_id_t id, unsigned long pruneRows); - - bool prune(log_id_t id, unsigned long pruneRows, uid_t uid = AID_ROOT); + bool prune(log_id_t id, unsigned long pruneRows, uid_t uid = AID_ROOT) REQUIRES(lock_); LogBufferElementCollection::iterator erase(LogBufferElementCollection::iterator it, - bool coalesce = false); + bool coalesce = false) REQUIRES(lock_); // Returns an iterator to the oldest element for a given log type, or mLogElements.end() if // there are no logs for the given log type. Requires mLogElementsLock to be held. - LogBufferElementCollection::iterator GetOldest(log_id_t log_id); + LogBufferElementCollection::iterator GetOldest(log_id_t log_id) REQUIRES(lock_); LogReaderList* reader_list_; LogTags* tags_; @@ -94,4 +91,6 @@ class ChattyLogBuffer : public LogBuffer { // Keeps track of the iterator to the oldest log message of a given log type, as an // optimization when pruning logs. Use GetOldest() to retrieve. std::optional oldest_[LOG_ID_MAX]; + + RwLock lock_; }; diff --git a/logd/rwlock.h b/logd/rwlock.h new file mode 100644 index 000000000..2b27ff1a4 --- /dev/null +++ b/logd/rwlock.h @@ -0,0 +1,56 @@ +/* + * Copyright (C) 2020 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#pragma once + +#include + +#include +#include + +// As of the end of May 2020, std::shared_mutex is *not* simply a pthread_rwlock, but rather a +// combination of std::mutex and std::condition variable, which is obviously less efficient. This +// immitates what std::shared_mutex should be doing and is compatible with RAII thread wrappers. + +class SHARED_CAPABILITY("mutex") RwLock { + public: + RwLock() {} + ~RwLock() {} + + void lock() ACQUIRE() { pthread_rwlock_wrlock(&rwlock_); } + void lock_shared() ACQUIRE_SHARED() { pthread_rwlock_rdlock(&rwlock_); } + + void unlock() RELEASE() { pthread_rwlock_unlock(&rwlock_); } + + private: + pthread_rwlock_t rwlock_ = PTHREAD_RWLOCK_INITIALIZER; +}; + +// std::shared_lock does not have thread annotations, so we need our own. + +class SCOPED_CAPABILITY SharedLock { + public: + SharedLock(RwLock& lock) ACQUIRE_SHARED(lock) : lock_(lock) { lock_.lock_shared(); } + ~SharedLock() RELEASE() { lock_.unlock(); } + + void lock_shared() ACQUIRE_SHARED() { lock_.lock_shared(); } + void unlock() RELEASE() { lock_.unlock(); } + + DISALLOW_IMPLICIT_CONSTRUCTORS(SharedLock); + + private: + RwLock& lock_; +}; From a26f7dffe5e3169b2c93545d4231c5d1129c7e2d Mon Sep 17 00:00:00 2001 From: Tom Cherry Date: Tue, 19 May 2020 17:48:42 -0700 Subject: [PATCH 2/3] logd: refactor chatty deduplication logging This code and comment is hard to follow, despite the operation being simple, so refactor the code to be easier to follow. Also, use std::unique_ptr instead of raw pointers as appropriate. Test: logging unit tests Change-Id: Id1f29f4deeca730d1e3b6856e1581d0b840f883e --- logd/ChattyLogBuffer.cpp | 270 +++++++++++++++------------------------ logd/ChattyLogBuffer.h | 12 +- logd/LogStatistics.cpp | 5 +- logd/LogStatistics.h | 2 +- 4 files changed, 110 insertions(+), 179 deletions(-) diff --git a/logd/ChattyLogBuffer.cpp b/logd/ChattyLogBuffer.cpp index 369587ac3..26584584a 100644 --- a/logd/ChattyLogBuffer.cpp +++ b/logd/ChattyLogBuffer.cpp @@ -59,20 +59,10 @@ void ChattyLogBuffer::Init() { ChattyLogBuffer::ChattyLogBuffer(LogReaderList* reader_list, LogTags* tags, PruneList* prune, LogStatistics* stats) : reader_list_(reader_list), tags_(tags), prune_(prune), stats_(stats) { - log_id_for_each(i) { - lastLoggedElements[i] = nullptr; - droppedElements[i] = nullptr; - } - Init(); } -ChattyLogBuffer::~ChattyLogBuffer() { - log_id_for_each(i) { - delete lastLoggedElements[i]; - delete droppedElements[i]; - } -} +ChattyLogBuffer::~ChattyLogBuffer() {} LogBufferElementCollection::iterator ChattyLogBuffer::GetOldest(log_id_t log_id) { auto it = mLogElements.begin(); @@ -145,31 +135,20 @@ static enum match_type identical(LogBufferElement* elem, LogBufferElement* last) return SAME; } -int ChattyLogBuffer::Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid, - const char* msg, uint16_t len) { - if (log_id >= LOG_ID_MAX) { - return -EINVAL; - } - - // Slip the time by 1 nsec if the incoming lands on xxxxxx000 ns. - // This prevents any chance that an outside source can request an - // exact entry with time specified in ms or us precision. - if ((realtime.tv_nsec % 1000) == 0) ++realtime.tv_nsec; - - LogBufferElement* elem = new LogBufferElement(log_id, realtime, uid, pid, tid, msg, len); - - // b/137093665: don't coalesce security messages. +bool ChattyLogBuffer::ShouldLog(log_id_t log_id, const char* msg, uint16_t len) { if (log_id == LOG_ID_SECURITY) { - auto lock = std::lock_guard{lock_}; - log(elem); - return len; + return true; } int prio = ANDROID_LOG_INFO; const char* tag = nullptr; size_t tag_len = 0; if (log_id == LOG_ID_EVENTS || log_id == LOG_ID_STATS) { - tag = tags_->tagToName(elem->getTag()); + if (len < sizeof(android_event_header_t)) { + return false; + } + int32_t numeric_tag = reinterpret_cast(msg)->tag; + tag = tags_->tagToName(numeric_tag); if (tag) { tag_len = strlen(tag); } @@ -178,160 +157,111 @@ int ChattyLogBuffer::Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pi tag = msg + 1; tag_len = strnlen(tag, len - 1); } - if (!__android_log_is_loggable_len(prio, tag, tag_len, ANDROID_LOG_VERBOSE)) { + return __android_log_is_loggable_len(prio, tag, tag_len, ANDROID_LOG_VERBOSE); +} + +int ChattyLogBuffer::Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid, + const char* msg, uint16_t len) { + if (log_id >= LOG_ID_MAX) { + return -EINVAL; + } + + if (!ShouldLog(log_id, msg, len)) { // Log traffic received to total - stats_->AddTotal(elem); - delete elem; + stats_->AddTotal(log_id, len); return -EACCES; } - auto lock = std::lock_guard{lock_}; - LogBufferElement* currentLast = lastLoggedElements[log_id]; - if (currentLast) { - LogBufferElement* dropped = droppedElements[log_id]; - uint16_t count = dropped ? dropped->getDropped() : 0; - // - // State Init - // incoming: - // dropped = nullptr - // currentLast = nullptr; - // elem = incoming message - // outgoing: - // dropped = nullptr -> State 0 - // currentLast = copy of elem - // log elem - // State 0 - // incoming: - // count = 0 - // dropped = nullptr - // currentLast = copy of last message - // elem = incoming message - // outgoing: if match != DIFFERENT - // dropped = copy of first identical message -> State 1 - // currentLast = reference to elem - // break: if match == DIFFERENT - // dropped = nullptr -> State 0 - // delete copy of last message (incoming currentLast) - // currentLast = copy of elem - // log elem - // State 1 - // incoming: - // count = 0 - // dropped = copy of first identical message - // currentLast = reference to last held-back incoming - // message - // elem = incoming message - // outgoing: if match == SAME - // delete copy of first identical message (dropped) - // dropped = reference to last held-back incoming - // message set to chatty count of 1 -> State 2 - // currentLast = reference to elem - // outgoing: if match == SAME_LIBLOG - // dropped = copy of first identical message -> State 1 - // take sum of currentLast and elem - // if sum overflows: - // log currentLast - // currentLast = reference to elem - // else - // delete currentLast - // currentLast = reference to elem, sum liblog. - // break: if match == DIFFERENT - // delete dropped - // dropped = nullptr -> State 0 - // log reference to last held-back (currentLast) - // currentLast = copy of elem - // log elem - // State 2 - // incoming: - // count = chatty count - // dropped = chatty message holding count - // currentLast = reference to last held-back incoming - // message. - // dropped = chatty message holding count - // elem = incoming message - // outgoing: if match != DIFFERENT - // delete chatty message holding count - // dropped = reference to last held-back incoming - // message, set to chatty count + 1 - // currentLast = reference to elem - // break: if match == DIFFERENT - // log dropped (chatty message) - // dropped = nullptr -> State 0 - // log reference to last held-back (currentLast) - // currentLast = copy of elem - // log elem - // - enum match_type match = identical(elem, currentLast); - if (match != DIFFERENT) { - if (dropped) { - // Sum up liblog tag messages? - if ((count == 0) /* at Pass 1 */ && (match == SAME_LIBLOG)) { - android_log_event_int_t* event = reinterpret_cast( - const_cast(currentLast->getMsg())); - // - // To unit test, differentiate with something like: - // event->header.tag = htole32(CHATTY_LOG_TAG); - // here, then instead of delete currentLast below, - // log(currentLast) to see the incremental sums form. - // - uint32_t swab = event->payload.data; - unsigned long long total = htole32(swab); - event = reinterpret_cast( - const_cast(elem->getMsg())); - swab = event->payload.data; + // Slip the time by 1 nsec if the incoming lands on xxxxxx000 ns. + // This prevents any chance that an outside source can request an + // exact entry with time specified in ms or us precision. + if ((realtime.tv_nsec % 1000) == 0) ++realtime.tv_nsec; - lastLoggedElements[LOG_ID_EVENTS] = elem; - total += htole32(swab); - // check for overflow - if (total >= std::numeric_limits::max()) { - log(currentLast); - return len; - } - stats_->AddTotal(currentLast); - delete currentLast; - swab = total; - event->payload.data = htole32(swab); - return len; - } - if (count == USHRT_MAX) { - log(dropped); - count = 1; - } else { - delete dropped; - ++count; - } + std::unique_ptr elem( + new LogBufferElement(log_id, realtime, uid, pid, tid, msg, len)); + + // b/137093665: don't coalesce security messages. + if (log_id == LOG_ID_SECURITY) { + auto lock = std::lock_guard{lock_}; + Log(std::move(elem)); + return len; + } + + auto lock = std::lock_guard{lock_}; + // Initialize last_logged_elements_ to a copy of elem if logging the first element for a log_id. + if (!last_logged_elements_[log_id]) { + last_logged_elements_[log_id].reset(new LogBufferElement(*elem)); + Log(std::move(elem)); + return len; + } + + std::unique_ptr current_last = std::move(last_logged_elements_[log_id]); + enum match_type match = identical(elem.get(), current_last.get()); + + if (match == DIFFERENT) { + if (duplicate_elements_[log_id]) { + auto dropped_element = std::move(duplicate_elements_[log_id]); + // If we previously had 3+ identical messages, log the chatty message. + if (dropped_element && dropped_element->getDropped() > 0) { + Log(std::move(dropped_element)); } - if (count) { - stats_->AddTotal(currentLast); - currentLast->setDropped(count); - } - droppedElements[log_id] = currentLast; - lastLoggedElements[log_id] = elem; + // Log the saved copy of the last identical message seen. + Log(std::move(current_last)); + } + last_logged_elements_[log_id].reset(new LogBufferElement(*elem)); + Log(std::move(elem)); + return len; + } + + // 2 identical message: set duplicate_elements_ appropriately. + if (!duplicate_elements_[log_id]) { + duplicate_elements_[log_id] = std::move(current_last); + last_logged_elements_[log_id] = std::move(elem); + return len; + } + + // 3+ identical LIBLOG event messages: coalesce them into last_logged_elements_. + if (match == SAME_LIBLOG) { + const android_log_event_int_t* current_last_event = + reinterpret_cast(current_last->getMsg()); + int64_t current_last_count = current_last_event->payload.data; + android_log_event_int_t* elem_event = + reinterpret_cast(const_cast(elem->getMsg())); + int64_t elem_count = elem_event->payload.data; + + int64_t total = current_last_count + elem_count; + if (total > std::numeric_limits::max()) { + last_logged_elements_[log_id] = std::move(elem); + Log(std::move(current_last)); return len; } - if (dropped) { // State 1 or 2 - if (count) { // State 2 - log(dropped); // report chatty - } else { // State 1 - delete dropped; - } - droppedElements[log_id] = nullptr; - log(currentLast); // report last message in the series - } else { // State 0 - delete currentLast; - } + stats_->AddTotal(current_last->getLogId(), current_last->getMsgLen()); + elem_event->payload.data = total; + last_logged_elements_[log_id] = std::move(elem); + return len; } - lastLoggedElements[log_id] = new LogBufferElement(*elem); - log(elem); + // 3+ identical messages (not LIBLOG) messages: increase the drop count. + uint16_t dropped_count = duplicate_elements_[log_id]->getDropped(); + if (dropped_count == std::numeric_limits::max()) { + Log(std::move(duplicate_elements_[log_id])); + dropped_count = 0; + } + // We're dropping the current_last log so add its stats to the total. + stats_->AddTotal(current_last->getLogId(), current_last->getMsgLen()); + // Use current_last for tracking the dropped count to always use the latest timestamp. + current_last->setDropped(dropped_count + 1); + duplicate_elements_[log_id] = std::move(current_last); + last_logged_elements_[log_id] = std::move(elem); return len; } -void ChattyLogBuffer::log(LogBufferElement* elem) { - mLogElements.push_back(elem); - stats_->Add(elem); - maybePrune(elem->getLogId()); - reader_list_->NotifyNewLog(1 << elem->getLogId()); +void ChattyLogBuffer::Log(std::unique_ptr elem) { + log_id_t log_id = elem->getLogId(); + mLogElements.push_back(elem.release()); + stats_->Add(mLogElements.back()); + maybePrune(log_id); + reader_list_->NotifyNewLog(1 << log_id); } void ChattyLogBuffer::maybePrune(log_id_t id) { diff --git a/logd/ChattyLogBuffer.h b/logd/ChattyLogBuffer.h index 42cdeec81..d307a5e08 100644 --- a/logd/ChattyLogBuffer.h +++ b/logd/ChattyLogBuffer.h @@ -51,10 +51,6 @@ class ChattyLogBuffer : public LogBuffer { unsigned long mMaxSize[LOG_ID_MAX] GUARDED_BY(lock_); - LogBufferElement* lastLoggedElements[LOG_ID_MAX] GUARDED_BY(lock_); - LogBufferElement* droppedElements[LOG_ID_MAX] GUARDED_BY(lock_); - void log(LogBufferElement* elem) REQUIRES(lock_); - public: ChattyLogBuffer(LogReaderList* reader_list, LogTags* tags, PruneList* prune, LogStatistics* stats); @@ -78,6 +74,8 @@ class ChattyLogBuffer : public LogBuffer { bool prune(log_id_t id, unsigned long pruneRows, uid_t uid = AID_ROOT) REQUIRES(lock_); LogBufferElementCollection::iterator erase(LogBufferElementCollection::iterator it, bool coalesce = false) REQUIRES(lock_); + bool ShouldLog(log_id_t log_id, const char* msg, uint16_t len); + void Log(std::unique_ptr elem) REQUIRES(lock_); // Returns an iterator to the oldest element for a given log type, or mLogElements.end() if // there are no logs for the given log type. Requires mLogElementsLock to be held. @@ -93,4 +91,10 @@ class ChattyLogBuffer : public LogBuffer { std::optional oldest_[LOG_ID_MAX]; RwLock lock_; + + // This always contains a copy of the last message logged, for deduplication. + std::unique_ptr last_logged_elements_[LOG_ID_MAX] GUARDED_BY(lock_); + // This contains an element if duplicate messages are seen. + // Its `dropped` count is `duplicates seen - 1`. + std::unique_ptr duplicate_elements_[LOG_ID_MAX] GUARDED_BY(lock_); }; diff --git a/logd/LogStatistics.cpp b/logd/LogStatistics.cpp index 14bcb6395..bb7621d2f 100644 --- a/logd/LogStatistics.cpp +++ b/logd/LogStatistics.cpp @@ -79,12 +79,9 @@ char* pidToName(pid_t pid) { } } -void LogStatistics::AddTotal(LogBufferElement* element) { +void LogStatistics::AddTotal(log_id_t log_id, uint16_t size) { auto lock = std::lock_guard{lock_}; - if (element->getDropped()) return; - log_id_t log_id = element->getLogId(); - uint16_t size = element->getMsgLen(); mSizesTotal[log_id] += size; SizesTotal += size; ++mElementsTotal[log_id]; diff --git a/logd/LogStatistics.h b/logd/LogStatistics.h index 53c9bb667..7d13ff757 100644 --- a/logd/LogStatistics.h +++ b/logd/LogStatistics.h @@ -666,7 +666,7 @@ class LogStatistics { public: LogStatistics(bool enable_statistics); - void AddTotal(LogBufferElement* entry) EXCLUDES(lock_); + void AddTotal(log_id_t log_id, uint16_t size) EXCLUDES(lock_); void Add(LogBufferElement* entry) EXCLUDES(lock_); void Subtract(LogBufferElement* entry) EXCLUDES(lock_); // entry->setDropped(1) must follow this call From 1322472ad04773bba1525553407632318e59841e Mon Sep 17 00:00:00 2001 From: Tom Cherry Date: Tue, 19 May 2020 18:02:00 -0700 Subject: [PATCH 3/3] logd: use a std::list<> of values not pointers This saves 4 or 8 bytes off of each log message for 32 bit or 64 bit devices respectively. In practice, this actually saves more, due to avoiding heap fragmentation. Averaging over 5 runs of the LogBufferTest.random_messages unit test (32 bit), this change results in 8k less memory used when 1000 logs are logged and results in 260k less memory used when 10000 logs are logged. Test: check memory usage during LogBufferTest.random_messages Test: logging unit tests Change-Id: Ia7953e3c4cb19631ef43bab1deb91bb336bc2520 --- logd/ChattyLogBuffer.cpp | 162 +++++++++++++++++++------------------- logd/ChattyLogBuffer.h | 8 +- logd/LogBufferElement.cpp | 17 ++++ logd/LogBufferElement.h | 1 + 4 files changed, 102 insertions(+), 86 deletions(-) diff --git a/logd/ChattyLogBuffer.cpp b/logd/ChattyLogBuffer.cpp index 26584584a..fd2c23691 100644 --- a/logd/ChattyLogBuffer.cpp +++ b/logd/ChattyLogBuffer.cpp @@ -69,7 +69,7 @@ LogBufferElementCollection::iterator ChattyLogBuffer::GetOldest(log_id_t log_id) if (oldest_[log_id]) { it = *oldest_[log_id]; } - while (it != mLogElements.end() && (*it)->getLogId() != log_id) { + while (it != mLogElements.end() && it->getLogId() != log_id) { it++; } if (it != mLogElements.end()) { @@ -177,8 +177,7 @@ int ChattyLogBuffer::Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pi // exact entry with time specified in ms or us precision. if ((realtime.tv_nsec % 1000) == 0) ++realtime.tv_nsec; - std::unique_ptr elem( - new LogBufferElement(log_id, realtime, uid, pid, tid, msg, len)); + LogBufferElement elem(log_id, realtime, uid, pid, tid, msg, len); // b/137093665: don't coalesce security messages. if (log_id == LOG_ID_SECURITY) { @@ -190,76 +189,76 @@ int ChattyLogBuffer::Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pi auto lock = std::lock_guard{lock_}; // Initialize last_logged_elements_ to a copy of elem if logging the first element for a log_id. if (!last_logged_elements_[log_id]) { - last_logged_elements_[log_id].reset(new LogBufferElement(*elem)); + last_logged_elements_[log_id].emplace(elem); Log(std::move(elem)); return len; } - std::unique_ptr current_last = std::move(last_logged_elements_[log_id]); - enum match_type match = identical(elem.get(), current_last.get()); + LogBufferElement& current_last = *last_logged_elements_[log_id]; + enum match_type match = identical(&elem, ¤t_last); if (match == DIFFERENT) { if (duplicate_elements_[log_id]) { - auto dropped_element = std::move(duplicate_elements_[log_id]); // If we previously had 3+ identical messages, log the chatty message. - if (dropped_element && dropped_element->getDropped() > 0) { - Log(std::move(dropped_element)); + if (duplicate_elements_[log_id]->getDropped() > 0) { + Log(std::move(*duplicate_elements_[log_id])); } + duplicate_elements_[log_id].reset(); // Log the saved copy of the last identical message seen. Log(std::move(current_last)); } - last_logged_elements_[log_id].reset(new LogBufferElement(*elem)); + last_logged_elements_[log_id].emplace(elem); Log(std::move(elem)); return len; } // 2 identical message: set duplicate_elements_ appropriately. if (!duplicate_elements_[log_id]) { - duplicate_elements_[log_id] = std::move(current_last); - last_logged_elements_[log_id] = std::move(elem); + duplicate_elements_[log_id].emplace(std::move(current_last)); + last_logged_elements_[log_id].emplace(std::move(elem)); return len; } // 3+ identical LIBLOG event messages: coalesce them into last_logged_elements_. if (match == SAME_LIBLOG) { const android_log_event_int_t* current_last_event = - reinterpret_cast(current_last->getMsg()); + reinterpret_cast(current_last.getMsg()); int64_t current_last_count = current_last_event->payload.data; android_log_event_int_t* elem_event = - reinterpret_cast(const_cast(elem->getMsg())); + reinterpret_cast(const_cast(elem.getMsg())); int64_t elem_count = elem_event->payload.data; int64_t total = current_last_count + elem_count; if (total > std::numeric_limits::max()) { - last_logged_elements_[log_id] = std::move(elem); Log(std::move(current_last)); + last_logged_elements_[log_id].emplace(std::move(elem)); return len; } - stats_->AddTotal(current_last->getLogId(), current_last->getMsgLen()); + stats_->AddTotal(current_last.getLogId(), current_last.getMsgLen()); elem_event->payload.data = total; - last_logged_elements_[log_id] = std::move(elem); + last_logged_elements_[log_id].emplace(std::move(elem)); return len; } // 3+ identical messages (not LIBLOG) messages: increase the drop count. uint16_t dropped_count = duplicate_elements_[log_id]->getDropped(); if (dropped_count == std::numeric_limits::max()) { - Log(std::move(duplicate_elements_[log_id])); + Log(std::move(*duplicate_elements_[log_id])); dropped_count = 0; } // We're dropping the current_last log so add its stats to the total. - stats_->AddTotal(current_last->getLogId(), current_last->getMsgLen()); + stats_->AddTotal(current_last.getLogId(), current_last.getMsgLen()); // Use current_last for tracking the dropped count to always use the latest timestamp. - current_last->setDropped(dropped_count + 1); - duplicate_elements_[log_id] = std::move(current_last); - last_logged_elements_[log_id] = std::move(elem); + current_last.setDropped(dropped_count + 1); + duplicate_elements_[log_id].emplace(std::move(current_last)); + last_logged_elements_[log_id].emplace(std::move(elem)); return len; } -void ChattyLogBuffer::Log(std::unique_ptr elem) { - log_id_t log_id = elem->getLogId(); - mLogElements.push_back(elem.release()); - stats_->Add(mLogElements.back()); +void ChattyLogBuffer::Log(LogBufferElement&& elem) { + log_id_t log_id = elem.getLogId(); + mLogElements.push_back(std::move(elem)); + stats_->Add(&mLogElements.back()); maybePrune(log_id); reader_list_->NotifyNewLog(1 << log_id); } @@ -273,15 +272,15 @@ void ChattyLogBuffer::maybePrune(log_id_t id) { LogBufferElementCollection::iterator ChattyLogBuffer::erase(LogBufferElementCollection::iterator it, bool coalesce) { - LogBufferElement* element = *it; - log_id_t id = element->getLogId(); + LogBufferElement& element = *it; + log_id_t id = element.getLogId(); // Remove iterator references in the various lists that will become stale // after the element is erased from the main logging list. { // start of scope for found iterator - int key = (id == LOG_ID_EVENTS || id == LOG_ID_SECURITY) ? element->getTag() - : element->getUid(); + int key = (id == LOG_ID_EVENTS || id == LOG_ID_SECURITY) ? element.getTag() + : element.getUid(); LogBufferIteratorMap::iterator found = mLastWorst[id].find(key); if ((found != mLastWorst[id].end()) && (it == found->second)) { mLastWorst[id].erase(found); @@ -292,7 +291,7 @@ LogBufferElementCollection::iterator ChattyLogBuffer::erase(LogBufferElementColl // element->getUid() may not be AID_SYSTEM for next-best-watermark. // will not assume id != LOG_ID_EVENTS or LOG_ID_SECURITY for KISS and // long term code stability, find() check should be fast for those ids. - LogBufferPidIteratorMap::iterator found = mLastWorstPidOfSystem[id].find(element->getPid()); + LogBufferPidIteratorMap::iterator found = mLastWorstPidOfSystem[id].find(element.getPid()); if (found != mLastWorstPidOfSystem[id].end() && it == found->second) { mLastWorstPidOfSystem[id].erase(found); } @@ -306,7 +305,15 @@ LogBufferElementCollection::iterator ChattyLogBuffer::erase(LogBufferElementColl int key = (id == LOG_ID_EVENTS || id == LOG_ID_SECURITY) ? element->getTag() : element->getUid(); #endif + + if (coalesce) { + stats_->Erase(&element); + } else { + stats_->Subtract(&element); + } + it = mLogElements.erase(it); + if (doSetLast) { log_id_for_each(i) { if (setLast[i]) { @@ -333,13 +340,6 @@ LogBufferElementCollection::iterator ChattyLogBuffer::erase(LogBufferElementColl } } #endif - if (coalesce) { - stats_->Erase(element); - } else { - stats_->Subtract(element); - } - delete element; - return it; } @@ -485,14 +485,14 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u // filter logistics is not required. it = GetOldest(id); while (it != mLogElements.end()) { - LogBufferElement* element = *it; + LogBufferElement& element = *it; - if (element->getLogId() != id || element->getUid() != caller_uid) { + if (element.getLogId() != id || element.getUid() != caller_uid) { ++it; continue; } - if (oldest && oldest->start() <= element->getSequence()) { + if (oldest && oldest->start() <= element.getSequence()) { busy = true; kickMe(oldest, id, pruneRows); break; @@ -572,21 +572,21 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u --lastt; LogBufferElementLast last; while (it != mLogElements.end()) { - LogBufferElement* element = *it; + LogBufferElement& element = *it; - if (oldest && oldest->start() <= element->getSequence()) { + if (oldest && oldest->start() <= element.getSequence()) { busy = true; // Do not let chatty eliding trigger any reader mitigation break; } - if (element->getLogId() != id) { + if (element.getLogId() != id) { ++it; continue; } // below this point element->getLogId() == id - uint16_t dropped = element->getDropped(); + uint16_t dropped = element.getDropped(); // remove any leading drops if (leading && dropped) { @@ -594,16 +594,16 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u continue; } - if (dropped && last.coalesce(element, dropped)) { + if (dropped && last.coalesce(&element, dropped)) { it = erase(it, true); continue; } - int key = (id == LOG_ID_EVENTS || id == LOG_ID_SECURITY) ? element->getTag() - : element->getUid(); + int key = (id == LOG_ID_EVENTS || id == LOG_ID_SECURITY) ? element.getTag() + : element.getUid(); - if (hasBlacklist && prune_->naughty(element)) { - last.clear(element); + if (hasBlacklist && prune_->naughty(&element)) { + last.clear(&element); it = erase(it); if (dropped) { continue; @@ -619,25 +619,25 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u if (worst_sizes < second_worst_sizes) { break; } - worst_sizes -= element->getMsgLen(); + worst_sizes -= element.getMsgLen(); } continue; } - if ((element->getRealTime() < ((*lastt)->getRealTime() - too_old)) || - (element->getRealTime() > (*lastt)->getRealTime())) { + if (element.getRealTime() < (lastt->getRealTime() - too_old) || + element.getRealTime() > lastt->getRealTime()) { break; } if (dropped) { - last.add(element); - if (worstPid && ((!gc && element->getPid() == worstPid) || - mLastWorstPidOfSystem[id].find(element->getPid()) == + last.add(&element); + if (worstPid && ((!gc && element.getPid() == worstPid) || + mLastWorstPidOfSystem[id].find(element.getPid()) == mLastWorstPidOfSystem[id].end())) { // element->getUid() may not be AID_SYSTEM, next best // watermark if current one empty. id is not LOG_ID_EVENTS // or LOG_ID_SECURITY because of worstPid check. - mLastWorstPidOfSystem[id][element->getPid()] = it; + mLastWorstPidOfSystem[id][element.getPid()] = it; } if ((!gc && !worstPid && (key == worst)) || (mLastWorst[id].find(key) == mLastWorst[id].end())) { @@ -647,9 +647,9 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u continue; } - if (key != worst || (worstPid && element->getPid() != worstPid)) { + if (key != worst || (worstPid && element.getPid() != worstPid)) { leading = false; - last.clear(element); + last.clear(&element); ++it; continue; } @@ -663,18 +663,18 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u kick = true; - uint16_t len = element->getMsgLen(); + uint16_t len = element.getMsgLen(); // do not create any leading drops if (leading) { it = erase(it); } else { - stats_->Drop(element); - element->setDropped(1); - if (last.coalesce(element, 1)) { + stats_->Drop(&element); + element.setDropped(1); + if (last.coalesce(&element, 1)) { it = erase(it, true); } else { - last.add(element); + last.add(&element); if (worstPid && (!gc || mLastWorstPidOfSystem[id].find(worstPid) == mLastWorstPidOfSystem[id].end())) { // element->getUid() may not be AID_SYSTEM, next best @@ -704,20 +704,20 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u bool hasWhitelist = (id != LOG_ID_SECURITY) && prune_->nice() && !clearAll; it = GetOldest(id); while ((pruneRows > 0) && (it != mLogElements.end())) { - LogBufferElement* element = *it; + LogBufferElement& element = *it; - if (element->getLogId() != id) { + if (element.getLogId() != id) { it++; continue; } - if (oldest && oldest->start() <= element->getSequence()) { + if (oldest && oldest->start() <= element.getSequence()) { busy = true; if (!whitelist) kickMe(oldest, id, pruneRows); break; } - if (hasWhitelist && !element->getDropped() && prune_->nice(element)) { + if (hasWhitelist && !element.getDropped() && prune_->nice(&element)) { // WhiteListed whitelist = true; it++; @@ -732,14 +732,14 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u if (whitelist && (pruneRows > 0)) { it = GetOldest(id); while ((it != mLogElements.end()) && (pruneRows > 0)) { - LogBufferElement* element = *it; + LogBufferElement& element = *it; - if (element->getLogId() != id) { + if (element.getLogId() != id) { ++it; continue; } - if (oldest && oldest->start() <= element->getSequence()) { + if (oldest && oldest->start() <= element.getSequence()) { busy = true; kickMe(oldest, id, pruneRows); break; @@ -830,8 +830,7 @@ uint64_t ChattyLogBuffer::FlushTo( for (it = mLogElements.end(); it != mLogElements.begin(); /* do nothing */) { --it; - LogBufferElement* element = *it; - if (element->getSequence() <= start) { + if (it->getSequence() <= start) { it++; break; } @@ -841,19 +840,19 @@ uint64_t ChattyLogBuffer::FlushTo( uint64_t curr = start; for (; it != mLogElements.end(); ++it) { - LogBufferElement* element = *it; + LogBufferElement& element = *it; - if (!writer->privileged() && element->getUid() != uid) { + if (!writer->privileged() && element.getUid() != uid) { continue; } - if (!writer->can_read_security_logs() && element->getLogId() == LOG_ID_SECURITY) { + if (!writer->can_read_security_logs() && element.getLogId() == LOG_ID_SECURITY) { continue; } // NB: calling out to another object with wrlock() held (safe) if (filter) { - FlushToResult ret = filter(element); + FlushToResult ret = filter(&element); if (ret == FlushToResult::kSkip) { continue; } @@ -864,21 +863,20 @@ uint64_t ChattyLogBuffer::FlushTo( bool sameTid = false; if (lastTid) { - sameTid = lastTid[element->getLogId()] == element->getTid(); + sameTid = lastTid[element.getLogId()] == element.getTid(); // Dropped (chatty) immediately following a valid log from the // same source in the same log buffer indicates we have a // multiple identical squash. chatty that differs source // is due to spam filter. chatty to chatty of different // source is also due to spam filter. - lastTid[element->getLogId()] = - (element->getDropped() && !sameTid) ? 0 : element->getTid(); + lastTid[element.getLogId()] = (element.getDropped() && !sameTid) ? 0 : element.getTid(); } shared_lock.unlock(); - curr = element->getSequence(); + curr = element.getSequence(); // range locking in LastLogTimes looks after us - if (!element->FlushTo(writer, stats_, sameTid)) { + if (!element.FlushTo(writer, stats_, sameTid)) { return FLUSH_ERROR; } diff --git a/logd/ChattyLogBuffer.h b/logd/ChattyLogBuffer.h index d307a5e08..08c4bffe4 100644 --- a/logd/ChattyLogBuffer.h +++ b/logd/ChattyLogBuffer.h @@ -37,7 +37,7 @@ #include "LogWriter.h" #include "rwlock.h" -typedef std::list LogBufferElementCollection; +typedef std::list LogBufferElementCollection; class ChattyLogBuffer : public LogBuffer { LogBufferElementCollection mLogElements GUARDED_BY(lock_); @@ -75,7 +75,7 @@ class ChattyLogBuffer : public LogBuffer { LogBufferElementCollection::iterator erase(LogBufferElementCollection::iterator it, bool coalesce = false) REQUIRES(lock_); bool ShouldLog(log_id_t log_id, const char* msg, uint16_t len); - void Log(std::unique_ptr elem) REQUIRES(lock_); + void Log(LogBufferElement&& elem) REQUIRES(lock_); // Returns an iterator to the oldest element for a given log type, or mLogElements.end() if // there are no logs for the given log type. Requires mLogElementsLock to be held. @@ -93,8 +93,8 @@ class ChattyLogBuffer : public LogBuffer { RwLock lock_; // This always contains a copy of the last message logged, for deduplication. - std::unique_ptr last_logged_elements_[LOG_ID_MAX] GUARDED_BY(lock_); + std::optional last_logged_elements_[LOG_ID_MAX] GUARDED_BY(lock_); // This contains an element if duplicate messages are seen. // Its `dropped` count is `duplicates seen - 1`. - std::unique_ptr duplicate_elements_[LOG_ID_MAX] GUARDED_BY(lock_); + std::optional duplicate_elements_[LOG_ID_MAX] GUARDED_BY(lock_); }; diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp index 4f5cabd1d..3bcf11deb 100644 --- a/logd/LogBufferElement.cpp +++ b/logd/LogBufferElement.cpp @@ -63,6 +63,23 @@ LogBufferElement::LogBufferElement(const LogBufferElement& elem) } } +LogBufferElement::LogBufferElement(LogBufferElement&& elem) + : mUid(elem.mUid), + mPid(elem.mPid), + mTid(elem.mTid), + mSequence(elem.mSequence), + mRealTime(elem.mRealTime), + mMsgLen(elem.mMsgLen), + mLogId(elem.mLogId), + mDropped(elem.mDropped) { + if (mDropped) { + mTag = elem.getTag(); + } else { + mMsg = elem.mMsg; + elem.mMsg = nullptr; + } +} + LogBufferElement::~LogBufferElement() { if (!mDropped) { delete[] mMsg; diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h index 2f2d70d3a..a777970d4 100644 --- a/logd/LogBufferElement.h +++ b/logd/LogBufferElement.h @@ -60,6 +60,7 @@ class __attribute__((packed)) LogBufferElement { LogBufferElement(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid, const char* msg, uint16_t len); LogBufferElement(const LogBufferElement& elem); + LogBufferElement(LogBufferElement&& elem); ~LogBufferElement(); bool isBinary(void) const {