Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit c581886e authored by Tom Cherry's avatar Tom Cherry
Browse files

logd: single std::mutex for locking log buffers and tracking readers

There are only three places where the log buffer lock is not already
held when the reader lock is taken:
1) In LogReader, when a new reader connects
2) In LogReader, when a misbehaving reader disconnects
3) LogReaderThread::ThreadFunction()

1) and 2) happen sufficiently rarely that there's no impact if they
additionally held a global lock.
3) is refactored in this CL.  Previously, it would do the below in a loop
  1) Lock the reader lock then wait on a condition variable
  2) Unlock the reader lock
  3) Lock the log buffer lock in LogBuffer::FlushTo()
  4) In each iteration in the LogBuffer::FlushTo() loop
    1) Lock then unlock the reader lock in FilterSecondPass()
    2) Unlock the log buffer lock to send the message, then re-lock it
  5) Unlock the log buffer lock when leaving LogBuffer::FlushTo()
If these locks are collapsed into a single lock, then this simplifies to:
  1) Lock the single lock then wait on a condition variable
  2) In each iteration in the LogBuffer::FlushTo() loop
    1) Unlock the single lock to send the message, then re-lock it

Collapsing both these locks into a single lock simplifes the code and
removes the overhead of acquiring the second lock, in the majority of
use cases where the first lock is already held.

Secondly, this lock will be a plain std::mutex instead of a RwLock.
RwLock's are appropriate when there is a substantial imbalance between
readers and writers and high contention, neither are true for logd.

Bug: 169736426
Test: logging unit tests
Change-Id: Ia511506f2d0935a5321c1b2f65569066f91ecb06
parent 8401907a
Loading
Loading
Loading
Loading
+3 −1
Original line number Diff line number Diff line
@@ -58,12 +58,13 @@ cc_library_static {
    srcs: [
        "ChattyLogBuffer.cpp",
        "CompressionEngine.cpp",
        "LogBufferElement.cpp",
        "LogReaderList.cpp",
        "LogReaderThread.cpp",
        "LogBufferElement.cpp",
        "LogSize.cpp",
        "LogStatistics.cpp",
        "LogTags.cpp",
        "LogdLock.cpp",
        "PruneList.cpp",
        "SerializedFlushToState.cpp",
        "SerializedLogBuffer.cpp",
@@ -138,6 +139,7 @@ cc_defaults {
        "-fstack-protector-all",
        "-g",
        "-Wall",
        "-Wthread-safety",
        "-Wextra",
        "-Werror",
        "-fno-builtin",
+0 −2
Original line number Diff line number Diff line
@@ -333,8 +333,6 @@ bool ChattyLogBuffer::Prune(log_id_t id, unsigned long pruneRows, uid_t caller_u
    LogReaderThread* oldest = nullptr;
    bool clearAll = pruneRows == ULONG_MAX;

    auto reader_threads_lock = std::lock_guard{reader_list()->reader_threads_lock()};

    // Region locked?
    for (const auto& reader_thread : reader_list()->reader_threads()) {
        if (!reader_thread->IsWatching(id)) {
+8 −8
Original line number Diff line number Diff line
@@ -33,19 +33,19 @@
#include "LogStatistics.h"
#include "LogTags.h"
#include "LogWriter.h"
#include "LogdLock.h"
#include "PruneList.h"
#include "SimpleLogBuffer.h"
#include "rwlock.h"

typedef std::list<LogBufferElement> LogBufferElementCollection;

class ChattyLogBuffer : public SimpleLogBuffer {
    // watermark of any worst/chatty uid processing
    typedef std::unordered_map<uid_t, LogBufferElementCollection::iterator> LogBufferIteratorMap;
    LogBufferIteratorMap mLastWorst[LOG_ID_MAX] GUARDED_BY(lock_);
    LogBufferIteratorMap mLastWorst[LOG_ID_MAX] GUARDED_BY(logd_lock);
    // watermark of any worst/chatty pid of system processing
    typedef std::unordered_map<pid_t, LogBufferElementCollection::iterator> LogBufferPidIteratorMap;
    LogBufferPidIteratorMap mLastWorstPidOfSystem[LOG_ID_MAX] GUARDED_BY(lock_);
    LogBufferPidIteratorMap mLastWorstPidOfSystem[LOG_ID_MAX] GUARDED_BY(logd_lock);

  public:
    ChattyLogBuffer(LogReaderList* reader_list, LogTags* tags, PruneList* prune,
@@ -53,18 +53,18 @@ class ChattyLogBuffer : public SimpleLogBuffer {
    ~ChattyLogBuffer();

  protected:
    bool Prune(log_id_t id, unsigned long pruneRows, uid_t uid) REQUIRES(lock_) override;
    void LogInternal(LogBufferElement&& elem) REQUIRES(lock_) override;
    bool Prune(log_id_t id, unsigned long pruneRows, uid_t uid) REQUIRES(logd_lock) override;
    void LogInternal(LogBufferElement&& elem) REQUIRES(logd_lock) override;

  private:
    LogBufferElementCollection::iterator Erase(LogBufferElementCollection::iterator it,
                                               bool coalesce = false) REQUIRES(lock_);
                                               bool coalesce = false) REQUIRES(logd_lock);

    PruneList* prune_;

    // This always contains a copy of the last message logged, for deduplication.
    std::optional<LogBufferElement> last_logged_elements_[LOG_ID_MAX] GUARDED_BY(lock_);
    std::optional<LogBufferElement> last_logged_elements_[LOG_ID_MAX] GUARDED_BY(logd_lock);
    // This contains an element if duplicate messages are seen.
    // Its `dropped` count is `duplicates seen - 1`.
    std::optional<LogBufferElement> duplicate_elements_[LOG_ID_MAX] GUARDED_BY(lock_);
    std::optional<LogBufferElement> duplicate_elements_[LOG_ID_MAX] GUARDED_BY(logd_lock);
};
+24 −11
Original line number Diff line number Diff line
@@ -60,9 +60,14 @@ TEST_P(ChattyLogBufferTest, deduplication_simple) {
    LogMessages(log_messages);

    std::vector<LogMessage> read_log_messages;
    {
        auto lock = std::lock_guard{logd_lock};
        std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, nullptr));
    std::unique_ptr<FlushToState> flush_to_state = log_buffer_->CreateFlushToState(1, kLogMaskAll);

        std::unique_ptr<FlushToState> flush_to_state =
                log_buffer_->CreateFlushToState(1, kLogMaskAll);
        EXPECT_TRUE(log_buffer_->FlushTo(test_writer.get(), *flush_to_state, nullptr));
    }

    std::vector<LogMessage> expected_log_messages = {
            make_message(0, "test_tag", "duplicate"),
@@ -117,9 +122,13 @@ TEST_P(ChattyLogBufferTest, deduplication_overflow) {
    LogMessages(log_messages);

    std::vector<LogMessage> read_log_messages;
    {
        auto lock = std::lock_guard{logd_lock};
        std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, nullptr));
    std::unique_ptr<FlushToState> flush_to_state = log_buffer_->CreateFlushToState(1, kLogMaskAll);
        std::unique_ptr<FlushToState> flush_to_state =
                log_buffer_->CreateFlushToState(1, kLogMaskAll);
        EXPECT_TRUE(log_buffer_->FlushTo(test_writer.get(), *flush_to_state, nullptr));
    }

    std::vector<LogMessage> expected_log_messages = {
            make_message(0, "test_tag", "normal"),
@@ -173,9 +182,13 @@ TEST_P(ChattyLogBufferTest, deduplication_liblog) {
    LogMessages(log_messages);

    std::vector<LogMessage> read_log_messages;
    {
        auto lock = std::lock_guard{logd_lock};
        std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, nullptr));
    std::unique_ptr<FlushToState> flush_to_state = log_buffer_->CreateFlushToState(1, kLogMaskAll);
        std::unique_ptr<FlushToState> flush_to_state =
                log_buffer_->CreateFlushToState(1, kLogMaskAll);
        EXPECT_TRUE(log_buffer_->FlushTo(test_writer.get(), *flush_to_state, nullptr));
    }

    std::vector<LogMessage> expected_log_messages = {
            make_message(0, 1234, 1),
@@ -257,7 +270,7 @@ TEST_P(ChattyLogBufferTest, no_leading_chatty_simple) {
    std::vector<LogMessage> read_log_messages;
    bool released = false;
    {
        auto lock = std::unique_lock{reader_list_.reader_threads_lock()};
        auto lock = std::lock_guard{logd_lock};
        std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, &released));
        std::unique_ptr<LogReaderThread> log_reader(
                new LogReaderThread(log_buffer_.get(), &reader_list_, std::move(test_writer), true,
@@ -317,7 +330,7 @@ TEST_P(ChattyLogBufferTest, no_leading_chatty_tail) {
    std::vector<LogMessage> read_log_messages;
    bool released = false;
    {
        auto lock = std::unique_lock{reader_list_.reader_threads_lock()};
        auto lock = std::lock_guard{logd_lock};
        std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, &released));
        std::unique_ptr<LogReaderThread> log_reader(
                new LogReaderThread(log_buffer_.get(), &reader_list_, std::move(test_writer), true,
+5 −3
Original line number Diff line number Diff line
@@ -21,10 +21,12 @@
#include <functional>
#include <memory>

#include <android-base/thread_annotations.h>
#include <log/log.h>
#include <log/log_read.h>

#include "LogWriter.h"
#include "LogdLock.h"

// A mask to represent which log buffers a reader is watching, values are (1 << LOG_ID_MAIN), etc.
using LogMask = uint32_t;
@@ -62,12 +64,12 @@ class LogBuffer {
    virtual int Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid,
                    const char* msg, uint16_t len) = 0;

    virtual std::unique_ptr<FlushToState> CreateFlushToState(uint64_t start, LogMask log_mask) = 0;
    virtual void DeleteFlushToState(std::unique_ptr<FlushToState>) {}
    virtual std::unique_ptr<FlushToState> CreateFlushToState(uint64_t start, LogMask log_mask)
            REQUIRES(logd_lock) = 0;
    virtual bool FlushTo(
            LogWriter* writer, FlushToState& state,
            const std::function<FilterResult(log_id_t log_id, pid_t pid, uint64_t sequence,
                                             log_time realtime)>& filter) = 0;
                                             log_time realtime)>& filter) REQUIRES(logd_lock) = 0;

    virtual bool Clear(log_id_t id, uid_t uid) = 0;
    virtual size_t GetSize(log_id_t id) = 0;
Loading