Merge "logd: record and replay log messages"

Author: Tom Cherry

logd/Android.bp

@@ -180,3 +180,23 @@ cc_test {
         "vts10",
     ],
 }
+
+cc_binary {
+    name: "replay_messages",
+    defaults: ["logd_defaults"],
+    host_supported: true,
+
+    srcs: [
+        "ReplayMessages.cpp",
+    ],
+
+    static_libs: [
+        "libbase",
+        "libcutils",
+        "liblog",
+        "liblogd",
+        "libselinux",
+        "libz",
+        "libzstd",
+    ],
+}

logd/LogStatistics.cpp

@@ -26,8 +26,10 @@
 #include <unistd.h>
 
 #include <list>
+#include <vector>
 
 #include <android-base/logging.h>
+#include <android-base/strings.h>
 #include <private/android_logger.h>
 
 #include "LogBufferElement.h"
@@ -61,7 +63,8 @@ static std::string TagNameKey(const LogStatisticsElement& element) {
     return std::string(msg, len);
 }
 
-LogStatistics::LogStatistics(bool enable_statistics, bool track_total_size)
+LogStatistics::LogStatistics(bool enable_statistics, bool track_total_size,
+                             std::optional<log_time> start_time)
     : enable(enable_statistics), track_total_size_(track_total_size) {
     log_time now(CLOCK_REALTIME);
     log_id_for_each(id) {
@@ -70,8 +73,13 @@ LogStatistics::LogStatistics(bool enable_statistics, bool track_total_size)
         mDroppedElements[id] = 0;
         mSizesTotal[id] = 0;
         mElementsTotal[id] = 0;
-        mOldest[id] = now;
-        mNewest[id] = now;
+        if (start_time) {
+            mOldest[id] = *start_time;
+            mNewest[id] = *start_time;
+        } else {
+            mOldest[id] = now;
+            mNewest[id] = now;
+        }
         mNewestDropped[id] = now;
     }
 }
@@ -784,6 +792,31 @@ std::string LogStatistics::FormatTable(const LogHashtable<TKey, TEntry>& table,
     return output;
 }
 
+std::string LogStatistics::ReportInteresting() const {
+    auto lock = std::lock_guard{lock_};
+
+    std::vector<std::string> items;
+
+    log_id_for_each(i) { items.emplace_back(std::to_string(mElements[i])); }
+
+    log_id_for_each(i) { items.emplace_back(std::to_string(mSizes[i])); }
+
+    log_id_for_each(i) {
+        items.emplace_back(std::to_string(overhead_[i] ? *overhead_[i] : mSizes[i]));
+    }
+
+    log_id_for_each(i) {
+        uint64_t oldest = mOldest[i].msec() / 1000;
+        uint64_t newest = mNewest[i].msec() / 1000;
+
+        int span = newest - oldest;
+
+        items.emplace_back(std::to_string(span));
+    }
+
+    return android::base::Join(items, ",");
+}
+
 std::string LogStatistics::Format(uid_t uid, pid_t pid, unsigned int logMask) const {
     auto lock = std::lock_guard{lock_};
 

logd/LogStatistics.h

@@ -515,7 +515,8 @@ class LogStatistics {
     }
 
   public:
-    LogStatistics(bool enable_statistics, bool track_total_size);
+    LogStatistics(bool enable_statistics, bool track_total_size,
+                  std::optional<log_time> start_time = {});
 
     void AddTotal(log_id_t log_id, uint16_t size) EXCLUDES(lock_);
 
@@ -556,6 +557,7 @@ class LogStatistics {
         return SizesTotal;
     }
 
+    std::string ReportInteresting() const EXCLUDES(lock_);
     std::string Format(uid_t uid, pid_t pid, unsigned int logMask) const EXCLUDES(lock_);
 
     const char* PidToName(pid_t pid) const EXCLUDES(lock_);

logd/README.replay.md

@@ -0,0 +1,46 @@
+logd can record and replay log messages for offline analysis.
+
+Recording Messages
+------------------
+
+logd has a `RecordingLogBuffer` buffer that records messages to /data/misc/logd/recorded-messages.
+It stores messages in memory until that file is accessible, in order to capture all messages since
+the beginning of boot.  It is only meant for logging developers to use and must be manually enabled
+in by adding `RecordingLogBuffer.cpp` to `Android.bp` and setting
+`log_buffer = new SimpleLogBuffer(&reader_list, &log_tags, &log_statistics);` in `main.cpp`.
+
+Recording messages may delay the Log() function from completing and it is highly recommended to make
+the logd socket in `liblog` blocking, by removing `SOCK_NONBLOCK` from the `socket()` call in
+`liblog/logd_writer.cpp`.
+
+Replaying Messages
+------------------
+
+Recorded messages can be replayed offline with the `replay_messages` tool.  It runs on host and
+device and supports the following options:
+
+1. `interesting` - this prints 'interesting' statistics for each of the log buffer types (simple,
+   chatty, serialized).  The statistics are:
+    1. Log Entry Count
+    2. Size (the uncompressed size of the log messages in bytes)
+    3. Overhead (the total cost of the log messages in memory in bytes)
+    4. Range (the range of time that the logs cover in seconds)
+2. `memory_usage BUFFER_TYPE` - this prints the memory usage (sum of private dirty pages of the
+  `replay_messages` process).  Note that the input file is mmap()'ed as RO/Shared so it does not
+  appear in these dirty pages, and a baseline is taken before allocating the log buffers, so only
+  their contributions are measured.  The tool outputs the memory usage every 100,000 messages.
+3. `latency BUFFER_TYPE` - this prints statistics of the latency of the Log() function for the given
+  buffer type.  It specifically prints the 1st, 2nd, and 3rd quartiles; the 95th, 99th, and 99.99th
+  percentiles; and the maximum latency.
+4. `print_logs BUFFER_TYPE [buffers] [print_point]` - this prints the logs as processed by the given
+  buffer_type from the buffers specified by `buffers` starting after the number of logs specified by
+  `print_point` have been logged.  This acts as if a user called `logcat` immediately after the
+  specified logs have been logged, which is particularly useful since it will show the chatty
+  pruning messages at that point.  It additionally prints the statistics from `logcat -S` after the
+  logs.
+  `buffers` is a comma separated list of the numeric buffer id values from `<android/log.h>`.  For
+  example, `0,1,3` represents the main, radio, and system buffers.  It can can also be `all`.
+  `print_point` is an positive integer.  If it is unspecified, logs are printed after the entire
+  input file is consumed.
+5. `nothing BUFFER_TYPE` - this does nothing other than read the input file and call Log() for the
+  given buffer type.  This is used for profiling CPU usage of strictly the log buffer.

logd/RecordedLogMessage.h

@@ -0,0 +1,30 @@
+/*
+ * 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.
+ */
+
+#pragma once
+
+#include <inttypes.h>
+
+#include <log/log_time.h>
+
+struct __attribute__((packed)) RecordedLogMessage {
+    uint32_t uid;
+    uint32_t pid;
+    uint32_t tid;
+    log_time realtime;
+    uint16_t msg_len;
+    uint8_t log_id;
+};

logd/RecordingLogBuffer.cpp

@@ -0,0 +1,62 @@
+/*
+ * 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 "RecordingLogBuffer.h"
+
+#include <android-base/file.h>
+
+static void WriteLogMessage(int fd, const RecordedLogMessage& meta, const std::string& msg) {
+    android::base::WriteFully(fd, &meta, sizeof(meta));
+    android::base::WriteFully(fd, msg.c_str(), meta.msg_len);
+}
+
+void RecordingLogBuffer::RecordLogMessage(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid,
+                                          pid_t tid, const char* msg, uint16_t len) {
+    auto lock = std::lock_guard{lock_};
+    if (len > LOGGER_ENTRY_MAX_PAYLOAD) {
+        len = LOGGER_ENTRY_MAX_PAYLOAD;
+    }
+
+    RecordedLogMessage recorded_log_message = {
+            .uid = uid,
+            .pid = static_cast<uint32_t>(pid),
+            .tid = static_cast<uint32_t>(tid),
+            .realtime = realtime,
+            .msg_len = len,
+            .log_id = static_cast<uint8_t>(log_id),
+    };
+
+    if (!fd_.ok()) {
+        fd_.reset(open("/data/misc/logd/recorded-messages",
+                       O_WRONLY | O_CREAT | O_APPEND | O_CLOEXEC, 0666));
+        if (!fd_.ok()) {
+            since_boot_messages_.emplace_back(recorded_log_message, std::string(msg, len));
+            return;
+        } else {
+            for (const auto& [meta, msg] : since_boot_messages_) {
+                WriteLogMessage(fd_.get(), meta, msg);
+            }
+        }
+    }
+
+    WriteLogMessage(fd_.get(), recorded_log_message, std::string(msg, len));
+}
+
+int RecordingLogBuffer::Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid,
+                            const char* msg, uint16_t len) {
+    RecordLogMessage(log_id, realtime, uid, pid, tid, msg, len);
+    return SimpleLogBuffer::Log(log_id, realtime, uid, pid, tid, msg, len);
+}

logd/RecordingLogBuffer.h

@@ -0,0 +1,43 @@
+/*
+ * 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.
+ */
+
+#pragma once
+
+#include "SimpleLogBuffer.h"
+
+#include <string>
+#include <tuple>
+#include <vector>
+
+#include <android-base/unique_fd.h>
+
+#include "RecordedLogMessage.h"
+
+class RecordingLogBuffer : public SimpleLogBuffer {
+  public:
+    RecordingLogBuffer(LogReaderList* reader_list, LogTags* tags, LogStatistics* stats)
+        : SimpleLogBuffer(reader_list, tags, stats) {}
+
+    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) override;
+
+  private:
+    void RecordLogMessage(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid,
+                          const char* msg, uint16_t len);
+
+    std::vector<std::pair<RecordedLogMessage, std::string>> since_boot_messages_;
+    android::base::unique_fd fd_;
+};