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

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

logd: record and replay log messages 

To profile different log buffer types and configuration, this change
adds the ability to record log messages and adds a tool that will
replay those log messages through different log buffer implementations
and collect stats about the execution.

Test: log messages replay correctly
Change-Id: I0dc6c545b782fa7732e325dde109c496b137d0dd
parent 1270608d

logd/Android.bp

+20 −0
Original line number Diff line number Diff line
@@ -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

+36 −3
Original line number Diff line number Diff line
@@ -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;

        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

+3 −1
Original line number Diff line number Diff line
@@ -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 → 100644
+46 −0
Original line number Diff line number Diff line 
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 → 100644
+30 −0
Original line number Diff line number Diff line 
/*

 * 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;

};