thermal: add power rail log

Add rate limited power rail log which print only when any sensor
throttled and time gap between logging is greater than configured
duration (1 min by default).

Bug: 274567039
Test: Local build and use burn8
Change-Id: Iff8b7cd5a539589f54f812af3bf84065753240fe

4 files changed, 87 insertions, 20 deletions

diff --git a/thermal/thermal-helper.cpp b/thermal/thermal-helper.cpp
index a50839fd..d7981f89 100644
--- a/thermal/thermal-helper.cpp
+++ b/thermal/thermal-helper.cpp
@@ -1128,6 +1128,12 @@ std::chrono::milliseconds ThermalHelper::thermalWatcherCallbackFunc(
         LOG(ERROR) << "Failed to report " << count_failed_reporting << " thermal stats";
     }
 
+    const auto since_last_power_log_ms = std::chrono::duration_cast<std::chrono::milliseconds>(
+            now - power_files_.GetPrevPowerLogTime());
+    if (since_last_power_log_ms >= kPowerLogIntervalMs) {
+        power_files_.logPowerStatus(now);
+    }
+
     return min_sleep_ms;
 }
 
diff --git a/thermal/utils/power_files.cpp b/thermal/utils/power_files.cpp
index 50cc5b62..767f434b 100644
--- a/thermal/utils/power_files.cpp
+++ b/thermal/utils/power_files.cpp
@@ -39,6 +39,28 @@ constexpr std::string_view kEnergyValueNode("energy_value");
 using ::android::base::ReadFileToString;
 using ::android::base::StringPrintf;
 
+namespace {
+bool calculateAvgPower(std::string_view power_rail, const PowerSample &last_sample,
+                       const PowerSample &curr_sample, float *avg_power) {
+    *avg_power = NAN;
+    const auto duration = curr_sample.duration - last_sample.duration;
+    const auto deltaEnergy = curr_sample.energy_counter - last_sample.energy_counter;
+    if (!last_sample.duration) {
+        LOG(VERBOSE) << "Power rail " << power_rail.data()
+                     << ": all power samples have not been collected yet";
+    } else if (duration <= 0 || deltaEnergy < 0) {
+        LOG(ERROR) << "Power rail " << power_rail.data() << " is invalid: duration = " << duration
+                   << ", deltaEnergy = " << deltaEnergy;
+        return false;
+    } else {
+        *avg_power = static_cast<float>(deltaEnergy) / static_cast<float>(duration);
+        LOG(VERBOSE) << "Power rail " << power_rail.data() << ", avg power = " << *avg_power
+                     << ", duration = " << duration << ", deltaEnergy = " << deltaEnergy;
+    }
+    return true;
+}
+}  // namespace
+
 bool PowerFiles::registerPowerRailsToWatch(const Json::Value &config) {
     if (!ParsePowerRailInfo(config, &power_rail_info_map_)) {
         LOG(ERROR) << "Failed to parse power rail info config";
@@ -113,6 +135,9 @@ bool PowerFiles::registerPowerRailsToWatch(const Json::Value &config) {
         }
         LOG(INFO) << "Successfully to register power rail " << power_rail_info_pair.first;
     }
+
+    power_status_log_ = {.prev_log_time = boot_clock::now(),
+                         .prev_energy_info_map = energy_info_map_};
     return true;
 }
 
@@ -212,33 +237,16 @@ bool PowerFiles::updateEnergyValues(void) {
 float PowerFiles::updateAveragePower(std::string_view power_rail,
                                      std::queue<PowerSample> *power_history) {
     float avg_power = NAN;
-
     if (!energy_info_map_.count(power_rail.data())) {
         LOG(ERROR) << " Could not find power rail " << power_rail.data();
         return avg_power;
     }
     const auto last_sample = power_history->front();
     const auto curr_sample = energy_info_map_.at(power_rail.data());
-    const auto duration = curr_sample.duration - last_sample.duration;
-    const auto deltaEnergy = curr_sample.energy_counter - last_sample.energy_counter;
-
-    if (!last_sample.duration) {
-        LOG(VERBOSE) << "Power rail " << power_rail.data()
-                     << ": all power samples have not been collected yet";
-    } else if (duration <= 0 || deltaEnergy < 0) {
-        LOG(ERROR) << "Power rail " << power_rail.data() << " is invalid: duration = " << duration
-                   << ", deltaEnergy = " << deltaEnergy;
-
-        return avg_power;
-    } else {
-        avg_power = static_cast<float>(deltaEnergy) / static_cast<float>(duration);
-        LOG(VERBOSE) << "Power rail " << power_rail.data() << ", avg power = " << avg_power
-                     << ", duration = " << duration << ", deltaEnergy = " << deltaEnergy;
+    if (calculateAvgPower(power_rail, last_sample, curr_sample, &avg_power)) {
+        power_history->pop();
+        power_history->push(curr_sample);
     }
-
-    power_history->pop();
-    power_history->push(curr_sample);
-
     return avg_power;
 }
 
@@ -335,6 +343,43 @@ bool PowerFiles::refreshPowerStatus(void) {
     return true;
 }
 
+void PowerFiles::logPowerStatus(const boot_clock::time_point &now) {
+    // calculate energy and print
+    uint8_t power_rail_log_cnt = 0;
+    uint64_t max_duration = 0;
+    float tot_power = 0.0;
+    std::string out;
+    for (const auto &energy_info_pair : energy_info_map_) {
+        const auto &rail = energy_info_pair.first;
+        if (!power_status_log_.prev_energy_info_map.count(rail)) {
+            continue;
+        }
+        const auto &last_sample = power_status_log_.prev_energy_info_map.at(rail);
+        const auto &curr_sample = energy_info_pair.second;
+        float avg_power = NAN;
+        if (calculateAvgPower(rail, last_sample, curr_sample, &avg_power) && avg_power != NAN) {
+            // start of new line
+            if (power_rail_log_cnt % kMaxPowerLogPerLine == 0) {
+                if (power_rail_log_cnt != 0) {
+                    out.append("\n");
+                }
+                out.append("Power rails ");
+            }
+            out.append(StringPrintf("[%s: %0.2f mW] ", rail.c_str(), avg_power));
+            power_rail_log_cnt++;
+            tot_power += avg_power;
+            max_duration = std::max(max_duration, curr_sample.duration - last_sample.duration);
+        }
+    }
+
+    if (power_rail_log_cnt) {
+        LOG(INFO) << StringPrintf("Power rails total power: %0.2f mW for %" PRId64 " ms", tot_power,
+                                  max_duration);
+        LOG(INFO) << out;
+    }
+    power_status_log_ = {.prev_log_time = now, .prev_energy_info_map = energy_info_map_};
+}
+
 }  // namespace implementation
 }  // namespace thermal
 }  // namespace hardware
diff --git a/thermal/utils/power_files.h b/thermal/utils/power_files.h
index bcf8e820..0b00604f 100644
--- a/thermal/utils/power_files.h
+++ b/thermal/utils/power_files.h
@@ -47,6 +47,12 @@ struct PowerStatus {
     float last_updated_avg_power;
 };
 
+struct PowerStatusLog {
+    boot_clock::time_point prev_log_time;
+    // energy sample at last logging
+    std::unordered_map<std::string, PowerSample> prev_energy_info_map;
+};
+
 // A helper class for monitoring power rails.
 class PowerFiles {
   public:
@@ -58,6 +64,12 @@ class PowerFiles {
     bool registerPowerRailsToWatch(const Json::Value &config);
     // Update the power data from ODPM sysfs
     bool refreshPowerStatus(void);
+    // Log the power data for the duration
+    void logPowerStatus(const boot_clock::time_point &now);
+    // Get previous power log time_point
+    const boot_clock::time_point &GetPrevPowerLogTime() const {
+        return power_status_log_.prev_log_time;
+    }
     // Get power status map
     const std::unordered_map<std::string, PowerStatus> &GetPowerStatusMap() const {
         std::shared_lock<std::shared_mutex> _lock(power_status_map_mutex_);
@@ -86,6 +98,7 @@ class PowerFiles {
     std::unordered_map<std::string, PowerRailInfo> power_rail_info_map_;
     // The set to store the energy source paths
     std::unordered_set<std::string> energy_path_set_;
+    PowerStatusLog power_status_log_;
 };
 
 }  // namespace implementation
diff --git a/thermal/utils/thermal_info.h b/thermal/utils/thermal_info.h
index a3454da1..ecd2ee8f 100644
--- a/thermal/utils/thermal_info.h
+++ b/thermal/utils/thermal_info.h
@@ -40,6 +40,9 @@ using ThrottlingArray = std::array<float, static_cast<size_t>(kThrottlingSeverit
 using CdevArray = std::array<int, static_cast<size_t>(kThrottlingSeverityCount)>;
 constexpr std::chrono::milliseconds kMinPollIntervalMs = std::chrono::milliseconds(2000);
 constexpr std::chrono::milliseconds kUeventPollTimeoutMs = std::chrono::milliseconds(300000);
+// TODO(b/292044404): Add debug config to make them easily configurable
+constexpr std::chrono::milliseconds kPowerLogIntervalMs = std::chrono::milliseconds(60000);
+constexpr int kMaxPowerLogPerLine = 6;
 // Max number of time_in_state buckets is 20 in atoms
 // VendorSensorCoolingDeviceStats, VendorTempResidencyStats
 constexpr int kMaxStatsResidencyCount = 20;