openkylin
/
platform_system_core
mirror of https://gitee.com/openkylin/platform_system_core.git
9
0
Fork 0
Code Issues Projects Releases Wiki Activity

Merge "logd: move leading_dropped logic into FlushTo()" am: a8b8d108e5 am: a9b4222196 

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

Change-Id: I7ef591e802e260a1c61db34330845321092ac884
This commit is contained in:
Tom Cherry 2020-06-02 22:01:36 +00:00 committed by Automerger Merge Worker
parent f8edf1fc16 a9b4222196
commit ff3bd58b97
8 changed files with 165 additions and 50 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

130
logd/ChattyLogBufferTest.cpp
View File

@ -202,4 +202,134 @@ TEST_P(ChattyLogBufferTest, deduplication_liblog) {
CompareLogMessages(expected_log_messages, read_log_messages);
};
TEST_P(ChattyLogBufferTest, no_leading_chatty_simple) {
auto make_message = [&](uint32_t sec, int32_t pid, uint32_t uid, uint32_t lid, const char* tag,
const char* msg, bool regex = false) -> LogMessage {
logger_entry entry = {.pid = pid, .tid = 1, .sec = sec, .nsec = 1, .lid = lid, .uid = uid};
std::string message;
message.push_back(ANDROID_LOG_INFO);
message.append(tag);
message.push_back('\0');
message.append(msg);
message.push_back('\0');
return {entry, message, regex};
};
// clang-format off
std::vector<LogMessage> log_messages = {
make_message(1, 1, 1, LOG_ID_MAIN, "test_tag", "duplicate1"),
make_message(2, 2, 2, LOG_ID_SYSTEM, "test_tag", "duplicate2"),
make_message(3, 2, 2, LOG_ID_SYSTEM, "test_tag", "duplicate2"),
make_message(4, 2, 2, LOG_ID_SYSTEM, "test_tag", "duplicate2"),
make_message(6, 2, 2, LOG_ID_SYSTEM, "test_tag", "not duplicate2"),
make_message(7, 1, 1, LOG_ID_MAIN, "test_tag", "duplicate1"),
make_message(8, 1, 1, LOG_ID_MAIN, "test_tag", "duplicate1"),
make_message(9, 1, 1, LOG_ID_MAIN, "test_tag", "duplicate1"),
make_message(10, 1, 1, LOG_ID_MAIN, "test_tag", "not duplicate1"),
};
// clang-format on
FixupMessages(&log_messages);
LogMessages(log_messages);
// After logging log_messages, the below is what should be in the buffer:
// PID=1, LOG_ID_MAIN duplicate1
// [1] PID=2, LOG_ID_SYSTEM duplicate2
// PID=2, LOG_ID_SYSTEM chatty drop
// PID=2, LOG_ID_SYSTEM duplicate2
// PID=2, LOG_ID_SYSTEM not duplicate2
// [2] PID=1, LOG_ID_MAIN chatty drop
// [3] PID=1, LOG_ID_MAIN duplicate1
// PID=1, LOG_ID_MAIN not duplicate1
// We then read from the 2nd sequence number, starting from log message [1], but filtering out
// everything but PID=1, which results in us starting with log message [2], which is a chatty
// drop. Code prior to this test case would erroneously print it. The intended behavior that
// this test checks prints logs starting from log message [3].
// clang-format off
std::vector<LogMessage> expected_log_messages = {
make_message(9, 1, 1, LOG_ID_MAIN, "test_tag", "duplicate1"),
make_message(10, 1, 1, LOG_ID_MAIN, "test_tag", "not duplicate1"),
};
FixupMessages(&expected_log_messages);
// clang-format on
std::vector<LogMessage> read_log_messages;
bool released = false;
{
auto lock = std::unique_lock{reader_list_.reader_threads_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, ~0, 1, {}, 2, {}));
reader_list_.reader_threads().emplace_back(std::move(log_reader));
}
while (!released) {
usleep(5000);
}
CompareLogMessages(expected_log_messages, read_log_messages);
}
TEST_P(ChattyLogBufferTest, no_leading_chatty_tail) {
auto make_message = [&](uint32_t sec, const char* tag, const char* msg,
bool regex = false) -> LogMessage {
logger_entry entry = {
.pid = 1, .tid = 1, .sec = sec, .nsec = 1, .lid = LOG_ID_MAIN, .uid = 0};
std::string message;
message.push_back(ANDROID_LOG_INFO);
message.append(tag);
message.push_back('\0');
message.append(msg);
message.push_back('\0');
return {entry, message, regex};
};
// clang-format off
std::vector<LogMessage> log_messages = {
make_message(1, "test_tag", "duplicate"),
make_message(2, "test_tag", "duplicate"),
make_message(3, "test_tag", "duplicate"),
make_message(4, "test_tag", "not_duplicate"),
};
// clang-format on
FixupMessages(&log_messages);
LogMessages(log_messages);
// After logging log_messages, the below is what should be in the buffer:
// "duplicate"
// chatty
// "duplicate"
// "not duplicate"
// We then read the tail 3 messages expecting there to not be a chatty message, meaning that we
// should only see the last two messages.
// clang-format off
std::vector<LogMessage> expected_log_messages = {
make_message(3, "test_tag", "duplicate"),
make_message(4, "test_tag", "not_duplicate"),
};
FixupMessages(&expected_log_messages);
// clang-format on
std::vector<LogMessage> read_log_messages;
bool released = false;
{
auto lock = std::unique_lock{reader_list_.reader_threads_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,
3, ~0, 0, {}, 1, {}));
reader_list_.reader_threads().emplace_back(std::move(log_reader));
}
while (!released) {
usleep(5000);
}
CompareLogMessages(expected_log_messages, read_log_messages);
}
INSTANTIATE_TEST_CASE_P(ChattyLogBufferTests, ChattyLogBufferTest, testing::Values("chatty"));

8
logd/LogBuffer.h
View File

@ -62,10 +62,10 @@ class LogBuffer {
const char* msg, uint16_t len) = 0;
virtual std::unique_ptr<FlushToState> CreateFlushToState(uint64_t start, LogMask log_mask) = 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,
uint16_t dropped_count)>& filter) = 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;
virtual bool Clear(log_id_t id, uid_t uid) = 0;
virtual unsigned long GetSize(log_id_t id) = 0;

2
logd/LogBufferTest.cpp
View File

@ -119,7 +119,7 @@ static std::string CompareMessages(const std::string& expected, const std::strin
}
}
if (diff_index < 10) {
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(),

2
logd/LogReader.cpp
View File

@ -172,7 +172,7 @@ bool LogReader::onDataAvailable(SocketClient* cli) {
uint64_t last = sequence;
auto log_find_start = [pid, start, &sequence, &start_time_set, &last](
log_id_t, pid_t element_pid, uint64_t element_sequence,
log_time element_realtime, uint16_t) -> FilterResult {
log_time element_realtime) -> FilterResult {
if (pid && pid != element_pid) {
return FilterResult::kSkip;
}

41
logd/LogReaderThread.cpp
View File

@ -35,7 +35,6 @@ LogReaderThread::LogReaderThread(LogBuffer* log_buffer, LogReaderList* reader_li
: log_buffer_(log_buffer),
reader_list_(reader_list),
writer_(std::move(writer)),
leading_dropped_(false),
pid_(pid),
tail_(tail),
count_(0),
@ -52,8 +51,6 @@ LogReaderThread::LogReaderThread(LogBuffer* log_buffer, LogReaderList* reader_li
void LogReaderThread::ThreadFunction() {
prctl(PR_SET_NAME, "logd.reader.per");
leading_dropped_ = true;
auto lock = std::unique_lock{reader_list_->reader_threads_lock()};
while (!release_) {
@ -72,21 +69,16 @@ void LogReaderThread::ThreadFunction() {
if (tail_) {
auto first_pass_state = log_buffer_->CreateFlushToState(flush_to_state_->start(),
flush_to_state_->log_mask());
log_buffer_->FlushTo(writer_.get(), *first_pass_state,
[this](log_id_t log_id, pid_t pid, uint64_t sequence,
log_time realtime, uint16_t dropped_count) {
return FilterFirstPass(log_id, pid, sequence, realtime,
dropped_count);
});
leading_dropped_ =
true; // TODO: Likely a bug, if leading_dropped_ was not true before calling
// flushTo(), then it should not be reset to true after.
log_buffer_->FlushTo(
writer_.get(), *first_pass_state,
[this](log_id_t log_id, pid_t pid, uint64_t sequence, log_time realtime) {
return FilterFirstPass(log_id, pid, sequence, realtime);
});
}
bool flush_success = log_buffer_->FlushTo(
writer_.get(), *flush_to_state_,
[this](log_id_t log_id, pid_t pid, uint64_t sequence, log_time realtime,
uint16_t dropped_count) {
return FilterSecondPass(log_id, pid, sequence, realtime, dropped_count);
[this](log_id_t log_id, pid_t pid, uint64_t sequence, log_time realtime) {
return FilterSecondPass(log_id, pid, sequence, realtime);
});
// We only ignore entries before the original start time for the first flushTo(), if we
@ -127,17 +119,9 @@ void LogReaderThread::ThreadFunction() {
}
// A first pass to count the number of elements
FilterResult LogReaderThread::FilterFirstPass(log_id_t, pid_t pid, uint64_t, log_time realtime,
uint16_t dropped_count) {
FilterResult LogReaderThread::FilterFirstPass(log_id_t, pid_t pid, uint64_t, log_time realtime) {
auto lock = std::lock_guard{reader_list_->reader_threads_lock()};
if (leading_dropped_) {
if (dropped_count) {
return FilterResult::kSkip;
}
leading_dropped_ = false;
}
if ((!pid_ || pid_ == pid) && (start_time_ == log_time::EPOCH || start_time_ <= realtime)) {
++count_;
}
@ -147,7 +131,7 @@ FilterResult LogReaderThread::FilterFirstPass(log_id_t, pid_t pid, uint64_t, log
// A second pass to send the selected elements
FilterResult LogReaderThread::FilterSecondPass(log_id_t log_id, pid_t pid, uint64_t,
log_time realtime, uint16_t dropped_count) {
log_time realtime) {
auto lock = std::lock_guard{reader_list_->reader_threads_lock()};
if (skip_ahead_[log_id]) {
@ -155,13 +139,6 @@ FilterResult LogReaderThread::FilterSecondPass(log_id_t log_id, pid_t pid, uint6
return FilterResult::kSkip;
}
if (leading_dropped_) {
if (dropped_count) {
return FilterResult::kSkip;
}
leading_dropped_ = false;
}
// Truncate to close race between first and second pass
if (non_block_ && tail_ && index_ >= count_) {
return FilterResult::kStop;

9
logd/LogReaderThread.h
View File

@ -64,10 +64,8 @@ class LogReaderThread {
private:
void ThreadFunction();
// flushTo filter callbacks
FilterResult FilterFirstPass(log_id_t log_id, pid_t pid, uint64_t sequence, log_time realtime,
uint16_t dropped_count);
FilterResult FilterSecondPass(log_id_t log_id, pid_t pid, uint64_t sequence, log_time realtime,
uint16_t dropped_count);
FilterResult FilterFirstPass(log_id_t log_id, pid_t pid, uint64_t sequence, log_time realtime);
FilterResult FilterSecondPass(log_id_t log_id, pid_t pid, uint64_t sequence, log_time realtime);
std::condition_variable thread_triggered_condition_;
LogBuffer* log_buffer_;
@ -76,9 +74,6 @@ class LogReaderThread {
// Set to true to cause the thread to end and the LogReaderThread to delete itself.
bool release_ = false;
// Indicates whether or not 'leading' (first logs seen starting from start_) 'dropped' (chatty)
// messages should be ignored.
bool leading_dropped_;
// If set to non-zero, only pids equal to this are read by the reader.
const pid_t pid_;

20
logd/SimpleLogBuffer.cpp
View File

@ -119,8 +119,12 @@ class ChattyFlushToState : public FlushToState {
pid_t* last_tid() { return last_tid_; }
bool drop_chatty_messages() const { return drop_chatty_messages_; }
void set_drop_chatty_messages(bool value) { drop_chatty_messages_ = value; }
private:
pid_t last_tid_[LOG_ID_MAX] = {};
bool drop_chatty_messages_ = true;
};
std::unique_ptr<FlushToState> SimpleLogBuffer::CreateFlushToState(uint64_t start,
@ -131,7 +135,7 @@ std::unique_ptr<FlushToState> SimpleLogBuffer::CreateFlushToState(uint64_t start
bool SimpleLogBuffer::FlushTo(
LogWriter* writer, FlushToState& abstract_state,
const std::function<FilterResult(log_id_t log_id, pid_t pid, uint64_t sequence,
log_time realtime, uint16_t dropped_count)>& filter) {
log_time realtime)>& filter) {
auto shared_lock = SharedLock{lock_};
auto& state = reinterpret_cast<ChattyFlushToState&>(abstract_state);
@ -169,8 +173,8 @@ bool SimpleLogBuffer::FlushTo(
}
if (filter) {
FilterResult ret = filter(element.log_id(), element.pid(), element.sequence(),
element.realtime(), element.dropped_count());
FilterResult ret =
filter(element.log_id(), element.pid(), element.sequence(), element.realtime());
if (ret == FilterResult::kSkip) {
continue;
}
@ -179,6 +183,16 @@ bool SimpleLogBuffer::FlushTo(
}
}
// drop_chatty_messages is initialized to true, so if the first message that we attempt to
// flush is a chatty message, we drop it. Once we see a non-chatty message it gets set to
// false to let further chatty messages be printed.
if (state.drop_chatty_messages()) {
if (element.dropped_count() != 0) {
continue;
}
state.set_drop_chatty_messages(false);
}
bool same_tid = state.last_tid()[element.log_id()] == element.tid();
// 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

3
logd/SimpleLogBuffer.h
View File

@ -38,8 +38,7 @@ class SimpleLogBuffer : public LogBuffer {
std::unique_ptr<FlushToState> CreateFlushToState(uint64_t start, LogMask log_mask) override;
bool FlushTo(LogWriter* writer, FlushToState& state,
const std::function<FilterResult(log_id_t log_id, pid_t pid, uint64_t sequence,
log_time realtime, uint16_t dropped_count)>&
filter) override;
log_time realtime)>& filter) override;
bool Clear(log_id_t id, uid_t uid) override;
unsigned long GetSize(log_id_t id) override;