ACPR/android_system_core
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions
android_system_core/logd/LogBufferTest.cpp
Tom Cherry c581886eea 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
2020-10-07 15:00:49 -07:00

458 lines
17 KiB
C++
Raw Blame History

/*
* 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/LICENSE-2.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.
*/
#include "LogBufferTest.h"
#include <unistd.h>
#include <limits>
#include <memory>
#include <regex>
#include <vector>
#include <android-base/stringprintf.h>
#include <android-base/strings.h>
#include "LogBuffer.h"
#include "LogReaderThread.h"
#include "LogWriter.h"
using android::base::Join;
using android::base::Split;
using android::base::StringPrintf;
char* android::uidToName(uid_t) {
return nullptr;
}
static std::vector<std::string> CompareLoggerEntries(const logger_entry& expected,
const logger_entry& result, bool ignore_len) {
std::vector<std::string> errors;
if (!ignore_len && expected.len != result.len) {
errors.emplace_back(
StringPrintf("len: expected %" PRIu16 " vs %" PRIu16, expected.len, result.len));
}
if (expected.hdr_size != result.hdr_size) {
errors.emplace_back(StringPrintf("hdr_size: %" PRIu16 " vs %" PRIu16, expected.hdr_size,
result.hdr_size));
}
if (expected.pid != result.pid) {
errors.emplace_back(
StringPrintf("pid: expected %" PRIi32 " vs %" PRIi32, expected.pid, result.pid));
}
if (expected.tid != result.tid) {
errors.emplace_back(
StringPrintf("tid: expected %" PRIu32 " vs %" PRIu32, expected.tid, result.tid));
}
if (expected.sec != result.sec) {
errors.emplace_back(
StringPrintf("sec: expected %" PRIu32 " vs %" PRIu32, expected.sec, result.sec));
}
if (expected.nsec != result.nsec) {
errors.emplace_back(
StringPrintf("nsec: expected %" PRIu32 " vs %" PRIu32, expected.nsec, result.nsec));
}
if (expected.lid != result.lid) {
errors.emplace_back(
StringPrintf("lid: expected %" PRIu32 " vs %" PRIu32, expected.lid, result.lid));
}
if (expected.uid != result.uid) {
errors.emplace_back(
StringPrintf("uid: expected %" PRIu32 " vs %" PRIu32, expected.uid, result.uid));
}
return errors;
}
static std::string MakePrintable(std::string in) {
if (in.size() > 80) {
in = in.substr(0, 80) + "...";
}
std::string result;
for (const char c : in) {
if (isprint(c)) {
result.push_back(c);
} else {
result.append(StringPrintf("\\%02x", static_cast<int>(c) & 0xFF));
}
}
return result;
}
static std::string CompareMessages(const std::string& expected, const std::string& result) {
if (expected == result) {
return {};
}
size_t diff_index = 0;
for (; diff_index < std::min(expected.size(), result.size()); ++diff_index) {
if (expected[diff_index] != result[diff_index]) {
break;
}
}
if (diff_index < 80) {
auto expected_short = MakePrintable(expected);
auto result_short = MakePrintable(result);
return StringPrintf("msg: expected '%s' vs '%s'", expected_short.c_str(),
result_short.c_str());
}
auto expected_short = MakePrintable(expected.substr(diff_index));
auto result_short = MakePrintable(result.substr(diff_index));
return StringPrintf("msg: index %zu: expected '%s' vs '%s'", diff_index, expected_short.c_str(),
result_short.c_str());
}
static std::string CompareRegexMessages(const std::string& expected, const std::string& result) {
auto expected_pieces = Split(expected, std::string("\0", 1));
auto result_pieces = Split(result, std::string("\0", 1));
if (expected_pieces.size() != 3 || result_pieces.size() != 3) {
return StringPrintf(
"msg: should have 3 null delimited strings found %d in expected, %d in result: "
"'%s' vs '%s'",
static_cast<int>(expected_pieces.size()), static_cast<int>(result_pieces.size()),
MakePrintable(expected).c_str(), MakePrintable(result).c_str());
}
if (expected_pieces[0] != result_pieces[0]) {
return StringPrintf("msg: tag/priority mismatch expected '%s' vs '%s'",
MakePrintable(expected_pieces[0]).c_str(),
MakePrintable(result_pieces[0]).c_str());
}
std::regex expected_tag_regex(expected_pieces[1]);
if (!std::regex_search(result_pieces[1], expected_tag_regex)) {
return StringPrintf("msg: message regex mismatch expected '%s' vs '%s'",
MakePrintable(expected_pieces[1]).c_str(),
MakePrintable(result_pieces[1]).c_str());
}
if (expected_pieces[2] != result_pieces[2]) {
return StringPrintf("msg: nothing expected after final null character '%s' vs '%s'",
MakePrintable(expected_pieces[2]).c_str(),
MakePrintable(result_pieces[2]).c_str());
}
return {};
}
void CompareLogMessages(const std::vector<LogMessage>& expected,
const std::vector<LogMessage>& result) {
EXPECT_EQ(expected.size(), result.size());
size_t end = std::min(expected.size(), result.size());
size_t num_errors = 0;
for (size_t i = 0; i < end; ++i) {
auto errors =
CompareLoggerEntries(expected[i].entry, result[i].entry, expected[i].regex_compare);
auto msg_error = expected[i].regex_compare
? CompareRegexMessages(expected[i].message, result[i].message)
: CompareMessages(expected[i].message, result[i].message);
if (!msg_error.empty()) {
errors.emplace_back(msg_error);
}
if (!errors.empty()) {
GTEST_LOG_(ERROR) << "Mismatch log message " << i << "\n" << Join(errors, "\n");
++num_errors;
}
}
EXPECT_EQ(0U, num_errors);
}
void FixupMessages(std::vector<LogMessage>* messages) {
for (auto& [entry, message, _] : *messages) {
entry.hdr_size = sizeof(logger_entry);
entry.len = message.size();
}
}
TEST_P(LogBufferTest, smoke) {
std::vector<LogMessage> log_messages = {
{{
.pid = 1,
.tid = 1,
.sec = 1234,
.nsec = 323001,
.lid = LOG_ID_MAIN,
.uid = 0,
},
"smoke test"},
};
FixupMessages(&log_messages);
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);
EXPECT_TRUE(log_buffer_->FlushTo(test_writer.get(), *flush_to_state, nullptr));
EXPECT_EQ(2ULL, flush_to_state->start());
}
CompareLogMessages(log_messages, read_log_messages);
}
TEST_P(LogBufferTest, smoke_with_reader_thread) {
std::vector<LogMessage> log_messages = {
{{.pid = 1, .tid = 2, .sec = 10000, .nsec = 20001, .lid = LOG_ID_MAIN, .uid = 0},
"first"},
{{.pid = 10, .tid = 2, .sec = 10000, .nsec = 20002, .lid = LOG_ID_MAIN, .uid = 0},
"second"},
{{.pid = 100, .tid = 2, .sec = 10000, .nsec = 20003, .lid = LOG_ID_KERNEL, .uid = 0},
"third"},
{{.pid = 10, .tid = 2, .sec = 10000, .nsec = 20004, .lid = LOG_ID_MAIN, .uid = 0},
"fourth"},
{{.pid = 1, .tid = 2, .sec = 10000, .nsec = 20005, .lid = LOG_ID_RADIO, .uid = 0},
"fifth"},
{{.pid = 2, .tid = 2, .sec = 10000, .nsec = 20006, .lid = LOG_ID_RADIO, .uid = 0},
"sixth"},
{{.pid = 3, .tid = 2, .sec = 10000, .nsec = 20007, .lid = LOG_ID_RADIO, .uid = 0},
"seventh"},
{{.pid = 4, .tid = 2, .sec = 10000, .nsec = 20008, .lid = LOG_ID_MAIN, .uid = 0},
"eighth"},
{{.pid = 5, .tid = 2, .sec = 10000, .nsec = 20009, .lid = LOG_ID_CRASH, .uid = 0},
"nineth"},
{{.pid = 6, .tid = 2, .sec = 10000, .nsec = 20011, .lid = LOG_ID_MAIN, .uid = 0},
"tenth"},
};
FixupMessages(&log_messages);
LogMessages(log_messages);
std::vector<LogMessage> read_log_messages;
bool released = false;
{
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,
0, kLogMaskAll, 0, {}, 1, {}));
reader_list_.reader_threads().emplace_back(std::move(log_reader));
}
while (!released) {
usleep(5000);
}
{
auto lock = std::lock_guard{logd_lock};
EXPECT_EQ(0U, reader_list_.reader_threads().size());
}
CompareLogMessages(log_messages, read_log_messages);
}
// Generate random messages, set the 'sec' parameter explicit though, to be able to track the
// expected order of messages.
LogMessage GenerateRandomLogMessage(uint32_t sec) {
auto rand_uint32 = [](int max) -> uint32_t { return rand() % max; };
logger_entry entry = {
.hdr_size = sizeof(logger_entry),
.pid = rand() % 5000,
.tid = rand_uint32(5000),
.sec = sec,
.nsec = rand_uint32(NS_PER_SEC),
.lid = rand_uint32(LOG_ID_STATS),
.uid = rand_uint32(100000),
};
// See comment in ChattyLogBuffer::Log() for why this is disallowed.
if (entry.nsec % 1000 == 0) {
++entry.nsec;
}
if (entry.lid == LOG_ID_EVENTS) {
entry.lid = LOG_ID_KERNEL;
}
std::string message;
char priority = ANDROID_LOG_INFO + rand() % 2;
message.push_back(priority);
int tag_length = 2 + rand() % 10;
for (int i = 0; i < tag_length; ++i) {
message.push_back('a' + rand() % 26);
}
message.push_back('\0');
int msg_length = 2 + rand() % 1000;
for (int i = 0; i < msg_length; ++i) {
message.push_back('a' + rand() % 26);
}
message.push_back('\0');
entry.len = message.size();
return {entry, message};
}
TEST_P(LogBufferTest, random_messages) {
srand(1);
std::vector<LogMessage> log_messages;
for (size_t i = 0; i < 1000; ++i) {
log_messages.emplace_back(GenerateRandomLogMessage(i));
}
LogMessages(log_messages);
std::vector<LogMessage> read_log_messages;
bool released = false;
{
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,
0, kLogMaskAll, 0, {}, 1, {}));
reader_list_.reader_threads().emplace_back(std::move(log_reader));
}
while (!released) {
usleep(5000);
}
{
auto lock = std::lock_guard{logd_lock};
EXPECT_EQ(0U, reader_list_.reader_threads().size());
}
CompareLogMessages(log_messages, read_log_messages);
}
TEST_P(LogBufferTest, read_last_sequence) {
std::vector<LogMessage> log_messages = {
{{.pid = 1, .tid = 2, .sec = 10000, .nsec = 20001, .lid = LOG_ID_MAIN, .uid = 0},
"first"},
{{.pid = 10, .tid = 2, .sec = 10000, .nsec = 20002, .lid = LOG_ID_MAIN, .uid = 0},
"second"},
{{.pid = 100, .tid = 2, .sec = 10000, .nsec = 20003, .lid = LOG_ID_MAIN, .uid = 0},
"third"},
};
FixupMessages(&log_messages);
LogMessages(log_messages);
std::vector<LogMessage> read_log_messages;
bool released = false;
{
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,
0, kLogMaskAll, 0, {}, 3, {}));
reader_list_.reader_threads().emplace_back(std::move(log_reader));
}
while (!released) {
usleep(5000);
}
{
auto lock = std::lock_guard{logd_lock};
EXPECT_EQ(0U, reader_list_.reader_threads().size());
}
std::vector<LogMessage> expected_log_messages = {log_messages.back()};
CompareLogMessages(expected_log_messages, read_log_messages);
}
TEST_P(LogBufferTest, clear_logs) {
// Log 3 initial logs.
std::vector<LogMessage> log_messages = {
{{.pid = 1, .tid = 2, .sec = 10000, .nsec = 20001, .lid = LOG_ID_MAIN, .uid = 0},
"first"},
{{.pid = 10, .tid = 2, .sec = 10000, .nsec = 20002, .lid = LOG_ID_MAIN, .uid = 0},
"second"},
{{.pid = 100, .tid = 2, .sec = 10000, .nsec = 20003, .lid = LOG_ID_MAIN, .uid = 0},
"third"},
};
FixupMessages(&log_messages);
LogMessages(log_messages);
std::vector<LogMessage> read_log_messages;
bool released = false;
// Connect a blocking reader.
{
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), false,
0, kLogMaskAll, 0, {}, 1, {}));
reader_list_.reader_threads().emplace_back(std::move(log_reader));
}
// Wait up to 250ms for the reader to read the first 3 logs.
constexpr int kMaxRetryCount = 50;
int count = 0;
for (; count < kMaxRetryCount; ++count) {
usleep(5000);
auto lock = std::lock_guard{logd_lock};
if (reader_list_.reader_threads().back()->start() == 4) {
break;
}
}
ASSERT_LT(count, kMaxRetryCount);
// Clear the log buffer.
log_buffer_->Clear(LOG_ID_MAIN, 0);
// Log 3 more logs.
std::vector<LogMessage> after_clear_messages = {
{{.pid = 1, .tid = 2, .sec = 10000, .nsec = 20001, .lid = LOG_ID_MAIN, .uid = 0},
"4th"},
{{.pid = 10, .tid = 2, .sec = 10000, .nsec = 20002, .lid = LOG_ID_MAIN, .uid = 0},
"5th"},
{{.pid = 100, .tid = 2, .sec = 10000, .nsec = 20003, .lid = LOG_ID_MAIN, .uid = 0},
"6th"},
};
FixupMessages(&after_clear_messages);
LogMessages(after_clear_messages);
// Wait up to 250ms for the reader to read the 3 additional logs.
for (count = 0; count < kMaxRetryCount; ++count) {
usleep(5000);
auto lock = std::lock_guard{logd_lock};
if (reader_list_.reader_threads().back()->start() == 7) {
break;
}
}
ASSERT_LT(count, kMaxRetryCount);
// Release the reader, wait for it to get the signal then check that it has been deleted.
{
auto lock = std::lock_guard{logd_lock};
reader_list_.reader_threads().back()->Release();
}
while (!released) {
usleep(5000);
}
{
auto lock = std::lock_guard{logd_lock};
EXPECT_EQ(0U, reader_list_.reader_threads().size());
}
// Check that we have read all 6 messages.
std::vector<LogMessage> expected_log_messages = log_messages;
expected_log_messages.insert(expected_log_messages.end(), after_clear_messages.begin(),
after_clear_messages.end());
CompareLogMessages(expected_log_messages, read_log_messages);
// Finally, call FlushTo and ensure that only the 3 logs after the clear remain in the buffer.
std::vector<LogMessage> read_log_messages_after_clear;
{
auto lock = std::lock_guard{logd_lock};
std::unique_ptr<LogWriter> test_writer(
new TestWriter(&read_log_messages_after_clear, nullptr));
std::unique_ptr<FlushToState> flush_to_state =
log_buffer_->CreateFlushToState(1, kLogMaskAll);
EXPECT_TRUE(log_buffer_->FlushTo(test_writer.get(), *flush_to_state, nullptr));
EXPECT_EQ(7ULL, flush_to_state->start());
}
CompareLogMessages(after_clear_messages, read_log_messages_after_clear);
}
INSTANTIATE_TEST_CASE_P(LogBufferTests, LogBufferTest,
testing::Values("chatty", "serialized", "simple"));
Reference in a new issue View git blame Copy permalink