diff --git a/logd/ChattyLogBuffer.cpp b/logd/ChattyLogBuffer.cpp index f1305a5b4..fd2c23691 100644 --- a/logd/ChattyLogBuffer.cpp +++ b/logd/ChattyLogBuffer.cpp @@ -59,29 +59,17 @@ 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; - } - 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(); 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()) { @@ -147,33 +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) { - wrlock(); - log(elem); - unlock(); - - 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); } @@ -182,169 +157,112 @@ 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; } - wrlock(); - 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); - unlock(); - return len; - } - stats_->AddTotal(currentLast); - delete currentLast; - swab = total; - event->payload.data = htole32(swab); - unlock(); - return len; - } - if (count == USHRT_MAX) { - log(dropped); - count = 1; - } else { - delete dropped; - ++count; - } + LogBufferElement elem(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].emplace(elem); + Log(std::move(elem)); + return len; + } + + LogBufferElement& current_last = *last_logged_elements_[log_id]; + enum match_type match = identical(&elem, ¤t_last); + + if (match == DIFFERENT) { + if (duplicate_elements_[log_id]) { + // If we previously had 3+ identical messages, log the chatty message. + if (duplicate_elements_[log_id]->getDropped() > 0) { + Log(std::move(*duplicate_elements_[log_id])); } - if (count) { - stats_->AddTotal(currentLast); - currentLast->setDropped(count); - } - droppedElements[log_id] = currentLast; - lastLoggedElements[log_id] = elem; - unlock(); + 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].emplace(elem); + Log(std::move(elem)); + return len; + } + + // 2 identical message: set duplicate_elements_ appropriately. + if (!duplicate_elements_[log_id]) { + 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()); + 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()) { + Log(std::move(current_last)); + last_logged_elements_[log_id].emplace(std::move(elem)); 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].emplace(std::move(elem)); + return len; } - lastLoggedElements[log_id] = new LogBufferElement(*elem); - - log(elem); - unlock(); + // 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].emplace(std::move(current_last)); + last_logged_elements_[log_id].emplace(std::move(elem)); return len; } -// assumes ChattyLogBuffer::wrlock() held, owns elem, look after garbage collection -void ChattyLogBuffer::log(LogBufferElement* elem) { - mLogElements.push_back(elem); - stats_->Add(elem); - maybePrune(elem->getLogId()); - reader_list_->NotifyNewLog(1 << elem->getLogId()); +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); } -// 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)) { @@ -354,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); @@ -373,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); } @@ -387,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]) { @@ -414,13 +340,6 @@ LogBufferElementCollection::iterator ChattyLogBuffer::erase(LogBufferElementColl } } #endif - if (coalesce) { - stats_->Erase(element); - } else { - stats_->Subtract(element); - } - delete element; - return it; } @@ -540,8 +459,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; @@ -568,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; @@ -655,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) { @@ -677,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; @@ -702,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())) { @@ -730,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; } @@ -746,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 @@ -787,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++; @@ -815,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; @@ -846,9 +763,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 +783,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 +801,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 +819,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 @@ -913,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; } @@ -924,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; } @@ -947,27 +863,24 @@ 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(); } - unlock(); + 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; } - rdlock(); + shared_lock.lock_shared(); } - unlock(); - return curr; } diff --git a/logd/ChattyLogBuffer.h b/logd/ChattyLogBuffer.h index 29a421d62..08c4bffe4 100644 --- a/logd/ChattyLogBuffer.h +++ b/logd/ChattyLogBuffer.h @@ -22,6 +22,7 @@ #include #include +#include #include #include #include @@ -34,25 +35,21 @@ #include "LogTags.h" #include "LogWhiteBlackList.h" #include "LogWriter.h" +#include "rwlock.h" -typedef std::list LogBufferElementCollection; +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]; - - LogBufferElement* lastLoggedElements[LOG_ID_MAX]; - LogBufferElement* droppedElements[LOG_ID_MAX]; - void log(LogBufferElement* elem); + unsigned long mMaxSize[LOG_ID_MAX] GUARDED_BY(lock_); public: ChattyLogBuffer(LogReaderList* reader_list, LogTags* tags, PruneList* prune, @@ -71,20 +68,18 @@ 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_); + bool ShouldLog(log_id_t log_id, const char* msg, uint16_t len); + 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. - 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 +89,12 @@ 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_; + + // This always contains a copy of the last message logged, for deduplication. + 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::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 { 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 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_; +};