/* * 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 #include #include #include #include #include #include #include #include #include #include #include "ChattyLogBuffer.h" #include "LogBuffer.h" #include "LogStatistics.h" #include "RecordedLogMessage.h" #include "SerializedLogBuffer.h" #include "SimpleLogBuffer.h" using android::base::MappedFile; using android::base::ParseInt; using android::base::ParseUint; using android::base::Split; char* android::uidToName(uid_t) { return nullptr; } static size_t GetPrivateDirty() { // Allocate once and hope that we don't need to reallocate >40000, to prevent heap fragmentation static std::string smaps(40000, '\0'); android::base::ReadFileToString("/proc/self/smaps", &smaps); size_t result = 0; size_t base = 0; size_t found; while (true) { found = smaps.find("Private_Dirty:", base); if (found == smaps.npos) break; found += sizeof("Private_Dirty:"); result += atoi(&smaps[found]); base = found + 1; } return result; } static AndroidLogFormat* GetLogFormat() { static AndroidLogFormat* format = [] { auto* format = android_log_format_new(); android_log_setPrintFormat(format, android_log_formatFromString("threadtime")); android_log_setPrintFormat(format, android_log_formatFromString("uid")); return format; }(); return format; } static void PrintMessage(struct log_msg* buf) { bool is_binary = buf->id() == LOG_ID_EVENTS || buf->id() == LOG_ID_STATS || buf->id() == LOG_ID_SECURITY; AndroidLogEntry entry; int err; if (is_binary) { char binaryMsgBuf[1024]; err = android_log_processBinaryLogBuffer(&buf->entry, &entry, nullptr, binaryMsgBuf, sizeof(binaryMsgBuf)); } else { err = android_log_processLogBuffer(&buf->entry, &entry); } if (err < 0) { fprintf(stderr, "Error parsing log message\n"); } android_log_printLogLine(GetLogFormat(), STDOUT_FILENO, &entry); } static log_time GetFirstTimeStamp(const MappedFile& recorded_messages) { if (sizeof(RecordedLogMessage) >= recorded_messages.size()) { fprintf(stderr, "At least one log message must be present in the input\n"); exit(1); } auto* meta = reinterpret_cast(recorded_messages.data()); return meta->realtime; } static LogMask BuffersToLogMask(const char* buffers) { if (buffers == nullptr || !strcmp(buffers, "all")) { return kLogMaskAll; } auto string_ids = Split(buffers, ","); LogMask log_mask = 0; for (const auto& string_id : string_ids) { int buffer_id; if (!ParseInt(string_id, &buffer_id, 0, 7)) { fprintf(stderr, "Could not parse buffer_id '%s'\n", string_id.c_str()); exit(1); } log_mask |= 1 << buffer_id; } return log_mask; } class StdoutWriter : public LogWriter { public: StdoutWriter() : LogWriter(0, true) {} bool Write(const logger_entry& entry, const char* message) override { struct log_msg log_msg; log_msg.entry = entry; if (log_msg.entry.len > LOGGER_ENTRY_MAX_PAYLOAD) { fprintf(stderr, "payload too large %" PRIu16, log_msg.entry.len); exit(1); } memcpy(log_msg.msg(), message, log_msg.entry.len); PrintMessage(&log_msg); return true; } void Shutdown() override { fprintf(stderr, "LogWriter::Shutdown() called\n"); exit(1); } std::string name() const override { return "stdout writer"; } }; class Operation { public: virtual ~Operation() {} virtual void Begin() {} virtual void Log(const RecordedLogMessage& meta, const char* msg) = 0; virtual void End() {} }; class PrintInteresting : public Operation { public: PrintInteresting(log_time first_log_timestamp) : stats_simple_{false, false, first_log_timestamp}, stats_chatty_{false, false, first_log_timestamp}, stats_serialized_{false, true, first_log_timestamp} {} void Begin() override { printf("message_count,simple_main_lines,simple_radio_lines,simple_events_lines,simple_" "system_lines,simple_crash_lines,simple_stats_lines,simple_security_lines,simple_" "kernel_lines,simple_main_size,simple_radio_size,simple_events_size,simple_system_" "size,simple_crash_size,simple_stats_size,simple_security_size,simple_kernel_size," "simple_main_overhead,simple_radio_overhead,simple_events_overhead,simple_system_" "overhead,simple_crash_overhead,simple_stats_overhead,simple_security_overhead," "simple_kernel_overhead,simple_main_range,simple_radio_range,simple_events_range," "simple_system_range,simple_crash_range,simple_stats_range,simple_security_range," "simple_kernel_range,chatty_main_lines,chatty_radio_lines,chatty_events_lines," "chatty_system_lines,chatty_crash_lines,chatty_stats_lines,chatty_security_lines," "chatty_" "kernel_lines,chatty_main_size,chatty_radio_size,chatty_events_size,chatty_system_" "size,chatty_crash_size,chatty_stats_size,chatty_security_size,chatty_kernel_size," "chatty_main_overhead,chatty_radio_overhead,chatty_events_overhead,chatty_system_" "overhead,chatty_crash_overhead,chatty_stats_overhead,chatty_security_overhead," "chatty_kernel_overhead,chatty_main_range,chatty_radio_range,chatty_events_range," "chatty_system_range,chatty_crash_range,chatty_stats_range,chatty_security_range," "chatty_kernel_range,serialized_main_lines,serialized_radio_lines,serialized_events_" "lines,serialized_" "system_lines,serialized_crash_lines,serialized_stats_lines,serialized_security_" "lines,serialized_" "kernel_lines,serialized_main_size,serialized_radio_size,serialized_events_size," "serialized_system_" "size,serialized_crash_size,serialized_stats_size,serialized_security_size," "serialized_kernel_size," "serialized_main_overhead,serialized_radio_overhead,serialized_events_overhead," "serialized_system_" "overhead,serialized_crash_overhead,serialized_stats_overhead,serialized_security_" "overhead," "serialized_kernel_overhead,serialized_main_range,serialized_radio_range,serialized_" "events_range," "serialized_system_range,serialized_crash_range,serialized_stats_range,serialized_" "security_range," "serialized_kernel_range\n"); } void Log(const RecordedLogMessage& meta, const char* msg) override { simple_log_buffer_.Log(static_cast(meta.log_id), meta.realtime, meta.uid, meta.pid, meta.tid, msg, meta.msg_len); chatty_log_buffer_.Log(static_cast(meta.log_id), meta.realtime, meta.uid, meta.pid, meta.tid, msg, meta.msg_len); serialized_log_buffer_.Log(static_cast(meta.log_id), meta.realtime, meta.uid, meta.pid, meta.tid, msg, meta.msg_len); if (num_message_ % 10000 == 0) { printf("%" PRIu64 ",%s,%s,%s\n", num_message_, stats_simple_.ReportInteresting().c_str(), stats_chatty_.ReportInteresting().c_str(), stats_serialized_.ReportInteresting().c_str()); } num_message_++; } private: uint64_t num_message_ = 1; LogReaderList reader_list_; LogTags tags_; PruneList prune_list_; LogStatistics stats_simple_; SimpleLogBuffer simple_log_buffer_{&reader_list_, &tags_, &stats_simple_}; LogStatistics stats_chatty_; ChattyLogBuffer chatty_log_buffer_{&reader_list_, &tags_, &prune_list_, &stats_chatty_}; LogStatistics stats_serialized_; SerializedLogBuffer serialized_log_buffer_{&reader_list_, &tags_, &stats_serialized_}; }; class SingleBufferOperation : public Operation { public: SingleBufferOperation(log_time first_log_timestamp, const char* buffer) { if (!strcmp(buffer, "simple")) { stats_.reset(new LogStatistics{false, false, first_log_timestamp}); log_buffer_.reset(new SimpleLogBuffer(&reader_list_, &tags_, stats_.get())); } else if (!strcmp(buffer, "chatty")) { stats_.reset(new LogStatistics{false, false, first_log_timestamp}); log_buffer_.reset( new ChattyLogBuffer(&reader_list_, &tags_, &prune_list_, stats_.get())); } else if (!strcmp(buffer, "serialized")) { stats_.reset(new LogStatistics{false, true, first_log_timestamp}); log_buffer_.reset(new SerializedLogBuffer(&reader_list_, &tags_, stats_.get())); } else { fprintf(stderr, "invalid log buffer type '%s'\n", buffer); abort(); } } void Log(const RecordedLogMessage& meta, const char* msg) override { PreOperation(); log_buffer_->Log(static_cast(meta.log_id), meta.realtime, meta.uid, meta.pid, meta.tid, msg, meta.msg_len); Operation(); num_message_++; } virtual void PreOperation() {} virtual void Operation() {} protected: uint64_t num_message_ = 1; LogReaderList reader_list_; LogTags tags_; PruneList prune_list_; std::unique_ptr stats_; std::unique_ptr log_buffer_; }; class PrintMemory : public SingleBufferOperation { public: PrintMemory(log_time first_log_timestamp, const char* buffer) : SingleBufferOperation(first_log_timestamp, buffer) {} void Operation() override { if (num_message_ % 100000 == 0) { printf("%" PRIu64 ",%s\n", num_message_, std::to_string(GetPrivateDirty() - baseline_memory_).c_str()); } } private: size_t baseline_memory_ = GetPrivateDirty(); }; class PrintLogs : public SingleBufferOperation { public: PrintLogs(log_time first_log_timestamp, const char* buffer, const char* buffers, const char* print_point) : SingleBufferOperation(first_log_timestamp, buffer) { mask_ = BuffersToLogMask(buffers); if (print_point != nullptr) { uint64_t result = 0; if (!ParseUint(print_point, &result)) { fprintf(stderr, "Could not parse print point '%s'\n", print_point); exit(1); } print_point_ = result; } } void Operation() override { if (print_point_ && num_message_ >= *print_point_) { End(); exit(0); } } void End() override { auto lock = std::lock_guard{logd_lock}; std::unique_ptr test_writer(new StdoutWriter()); std::unique_ptr flush_to_state = log_buffer_->CreateFlushToState(1, mask_); log_buffer_->FlushTo(test_writer.get(), *flush_to_state, nullptr); auto stats_string = stats_->Format(0, 0, mask_); printf("%s\n", stats_string.c_str()); } private: LogMask mask_ = kLogMaskAll; std::optional print_point_; }; class PrintLatency : public SingleBufferOperation { public: PrintLatency(log_time first_log_timestamp, const char* buffer) : SingleBufferOperation(first_log_timestamp, buffer) {} void PreOperation() override { operation_start_ = std::chrono::steady_clock::now(); } void Operation() override { auto end = std::chrono::steady_clock::now(); auto duration = (end - operation_start_).count(); durations_.emplace_back(duration); } void End() override { std::sort(durations_.begin(), durations_.end()); auto q1 = durations_.size() / 4; auto q2 = durations_.size() / 2; auto q3 = 3 * durations_.size() / 4; auto p95 = 95 * durations_.size() / 100; auto p99 = 99 * durations_.size() / 100; auto p9999 = 9999 * durations_.size() / 10000; printf("q1: %lld q2: %lld q3: %lld p95: %lld p99: %lld p99.99: %lld max: %lld\n", durations_[q1], durations_[q2], durations_[q3], durations_[p95], durations_[p99], durations_[p9999], durations_.back()); } private: std::chrono::steady_clock::time_point operation_start_; std::vector durations_; }; class PrintAllLogs : public SingleBufferOperation { public: PrintAllLogs(log_time first_log_timestamp, const char* buffer, const char* buffers) : SingleBufferOperation(first_log_timestamp, buffer) { LogMask mask = BuffersToLogMask(buffers); auto lock = std::unique_lock{logd_lock}; std::unique_ptr stdout_writer(new StdoutWriter()); std::unique_ptr log_reader( new LogReaderThread(log_buffer_.get(), &reader_list_, std::move(stdout_writer), false, 0, mask, 0, {}, 1, {})); reader_list_.reader_threads().emplace_back(std::move(log_reader)); } void Operation() override { // If the rate of reading logs is slower than the rate of incoming logs, then the reader // thread is disconnected to not overflow log buffers, therefore we artificially slow down // the incoming log rate. usleep(100); } void End() override { // Release the reader thread. { auto lock = std::lock_guard{logd_lock}; reader_list_.reader_threads().back()->Release(); } // Wait until it has deleted itself. while (true) { usleep(500); auto lock = std::lock_guard{logd_lock}; if (reader_list_.reader_threads().size() == 0) { break; } } } }; int main(int argc, char** argv) { if (argc < 3) { fprintf(stderr, "Usage: %s FILE OPERATION [BUFFER] [OPTIONS]\n", argv[0]); return 1; } if (strcmp(argv[2], "interesting") != 0 && argc < 4) { fprintf(stderr, "Operations other than 'interesting' require a BUFFER argument\n"); return 1; } int recorded_messages_fd = open(argv[1], O_RDONLY); if (recorded_messages_fd == -1) { fprintf(stderr, "Couldn't open input file\n"); return 1; } struct stat fd_stat; if (fstat(recorded_messages_fd, &fd_stat) != 0) { fprintf(stderr, "Couldn't fstat input file\n"); return 1; } auto recorded_messages = MappedFile::FromFd(recorded_messages_fd, 0, static_cast(fd_stat.st_size), PROT_READ); if (recorded_messages == nullptr) { fprintf(stderr, "Couldn't mmap input file\n"); return 1; } // LogStatistics typically uses 'now()' to initialize its log range state, but this doesn't work // when replaying older logs, so we instead give it the timestamp from the first log. log_time first_log_timestamp = GetFirstTimeStamp(*recorded_messages); std::unique_ptr operation; if (!strcmp(argv[2], "interesting")) { operation.reset(new PrintInteresting(first_log_timestamp)); } else if (!strcmp(argv[2], "memory_usage")) { operation.reset(new PrintMemory(first_log_timestamp, argv[3])); } else if (!strcmp(argv[2], "latency")) { operation.reset(new PrintLatency(first_log_timestamp, argv[3])); } else if (!strcmp(argv[2], "print_logs")) { operation.reset(new PrintLogs(first_log_timestamp, argv[3], argc > 4 ? argv[4] : nullptr, argc > 5 ? argv[5] : nullptr)); } else if (!strcmp(argv[2], "print_all_logs")) { operation.reset( new PrintAllLogs(first_log_timestamp, argv[3], argc > 4 ? argv[4] : nullptr)); } else if (!strcmp(argv[2], "nothing")) { operation.reset(new SingleBufferOperation(first_log_timestamp, argv[3])); } else { fprintf(stderr, "unknown operation '%s'\n", argv[2]); return 1; } // LogBuffer::Log() won't log without this on host. __android_log_set_minimum_priority(ANDROID_LOG_VERBOSE); // But we still want to suppress messages <= error to not interrupt the rest of the output. __android_log_set_logger([](const struct __android_log_message* log_message) { if (log_message->priority < ANDROID_LOG_ERROR) { return; } __android_log_stderr_logger(log_message); }); operation->Begin(); uint64_t read_position = 0; while (read_position + sizeof(RecordedLogMessage) < recorded_messages->size()) { auto* meta = reinterpret_cast(recorded_messages->data() + read_position); if (read_position + sizeof(RecordedLogMessage) + meta->msg_len >= recorded_messages->size()) { break; } char* msg = recorded_messages->data() + read_position + sizeof(RecordedLogMessage); read_position += sizeof(RecordedLogMessage) + meta->msg_len; operation->Log(*meta, msg); } operation->End(); return 0; }