Merge "record atom pull time"

6 files changed, 122 insertions, 9 deletions

diff --git a/cmds/statsd/src/external/StatsPuller.cpp b/cmds/statsd/src/external/StatsPuller.cpp
index 436a8801896f..e3f251a5263d 100644
--- a/cmds/statsd/src/external/StatsPuller.cpp
+++ b/cmds/statsd/src/external/StatsPuller.cpp
@@ -46,6 +46,7 @@ bool StatsPuller::Pull(const int64_t elapsedTimeNs, std::vector<std::shared_ptr<
     if (elapsedTimeNs - mLastPullTimeNs < mCoolDownNs) {
         (*data) = mCachedData;
         StatsdStats::getInstance().notePullFromCache(mTagId);
+        StatsdStats::getInstance().notePullDelay(mTagId, getElapsedRealtimeNs() - elapsedTimeNs);
         return true;
     }
     if (mMinPullIntervalNs > elapsedTimeNs - mLastPullTimeNs) {
@@ -55,7 +56,9 @@ bool StatsPuller::Pull(const int64_t elapsedTimeNs, std::vector<std::shared_ptr<
     }
     mCachedData.clear();
     mLastPullTimeNs = elapsedTimeNs;
+    int64_t pullStartTimeNs = getElapsedRealtimeNs();
     bool ret = PullInternal(&mCachedData);
+    StatsdStats::getInstance().notePullTime(mTagId, getElapsedRealtimeNs() - pullStartTimeNs);
     for (const shared_ptr<LogEvent>& data : mCachedData) {
         data->setElapsedTimestampNs(elapsedTimeNs);
         data->setLogdWallClockTimestampNs(wallClockTimeNs);
@@ -64,6 +67,7 @@ bool StatsPuller::Pull(const int64_t elapsedTimeNs, std::vector<std::shared_ptr<
       mergeIsolatedUidsToHostUid(mCachedData, mUidMap, mTagId);
       (*data) = mCachedData;
     }
+    StatsdStats::getInstance().notePullDelay(mTagId, getElapsedRealtimeNs() - elapsedTimeNs);
     return ret;
 }
 
diff --git a/cmds/statsd/src/guardrail/StatsdStats.cpp b/cmds/statsd/src/guardrail/StatsdStats.cpp
index 023d835a8429..d2919c51a65e 100644
--- a/cmds/statsd/src/guardrail/StatsdStats.cpp
+++ b/cmds/statsd/src/guardrail/StatsdStats.cpp
@@ -335,7 +335,8 @@ void StatsdStats::noteRegisteredPeriodicAlarmChanged() {
 
 void StatsdStats::updateMinPullIntervalSec(int pullAtomId, long intervalSec) {
     lock_guard<std::mutex> lock(mLock);
-    mPulledAtomStats[pullAtomId].minPullIntervalSec = intervalSec;
+    mPulledAtomStats[pullAtomId].minPullIntervalSec =
+            std::min(mPulledAtomStats[pullAtomId].minPullIntervalSec, intervalSec);
 }
 
 void StatsdStats::notePull(int pullAtomId) {
@@ -348,6 +349,24 @@ void StatsdStats::notePullFromCache(int pullAtomId) {
     mPulledAtomStats[pullAtomId].totalPullFromCache++;
 }
 
+void StatsdStats::notePullTime(int pullAtomId, int64_t pullTimeNs) {
+    lock_guard<std::mutex> lock(mLock);
+    auto& pullStats = mPulledAtomStats[pullAtomId];
+    pullStats.maxPullTimeNs = std::max(pullStats.maxPullTimeNs, pullTimeNs);
+    pullStats.avgPullTimeNs = (pullStats.avgPullTimeNs * pullStats.numPullTime + pullTimeNs) /
+                              (pullStats.numPullTime + 1);
+    pullStats.numPullTime += 1;
+}
+
+void StatsdStats::notePullDelay(int pullAtomId, int64_t pullDelayNs) {
+    lock_guard<std::mutex> lock(mLock);
+    auto& pullStats = mPulledAtomStats[pullAtomId];
+    pullStats.maxPullDelayNs = std::max(pullStats.maxPullDelayNs, pullDelayNs);
+    pullStats.avgPullDelayNs = (pullStats.avgPullDelayNs * pullStats.numPullDelay + pullDelayNs) /
+                               (pullStats.numPullDelay + 1);
+    pullStats.numPullDelay += 1;
+}
+
 void StatsdStats::noteAtomLogged(int atomId, int32_t timeSec) {
     lock_guard<std::mutex> lock(mLock);
 
@@ -394,6 +413,16 @@ void StatsdStats::resetInternalLocked() {
         config.second->metric_dimension_in_condition_stats.clear();
         config.second->alert_stats.clear();
     }
+    for (auto& pullStats : mPulledAtomStats) {
+        pullStats.second.totalPull = 0;
+        pullStats.second.totalPullFromCache = 0;
+        pullStats.second.avgPullTimeNs = 0;
+        pullStats.second.maxPullTimeNs = 0;
+        pullStats.second.numPullTime = 0;
+        pullStats.second.avgPullDelayNs = 0;
+        pullStats.second.maxPullDelayNs = 0;
+        pullStats.second.numPullDelay = 0;
+    }
 }
 
 string buildTimeString(int64_t timeSec) {
@@ -498,8 +527,14 @@ void StatsdStats::dumpStats(int out) const {
 
     dprintf(out, "********Pulled Atom stats***********\n");
     for (const auto& pair : mPulledAtomStats) {
-        dprintf(out, "Atom %d->%ld, %ld, %ld\n", (int)pair.first, (long)pair.second.totalPull,
-                (long)pair.second.totalPullFromCache, (long)pair.second.minPullIntervalSec);
+        dprintf(out,
+                "Atom %d->(total pull)%ld, (pull from cache)%ld, (min pull interval)%ld, (average "
+                "pull time nanos)%lld, (max pull time nanos)%lld, (average pull delay nanos)%lld, "
+                "(max pull delay nanos)%lld\n",
+                (int)pair.first, (long)pair.second.totalPull, (long)pair.second.totalPullFromCache,
+                (long)pair.second.minPullIntervalSec, (long long)pair.second.avgPullTimeNs,
+                (long long)pair.second.maxPullTimeNs, (long long)pair.second.avgPullDelayNs,
+                (long long)pair.second.maxPullDelayNs);
     }
 
     if (mAnomalyAlarmRegisteredStats > 0) {
diff --git a/cmds/statsd/src/guardrail/StatsdStats.h b/cmds/statsd/src/guardrail/StatsdStats.h
index 7d95b54cc574..777d8652d2b6 100644
--- a/cmds/statsd/src/guardrail/StatsdStats.h
+++ b/cmds/statsd/src/guardrail/StatsdStats.h
@@ -263,16 +263,34 @@ public:
     void setUidMapChanges(int changes);
     void setCurrentUidMapMemory(int bytes);
 
-    // Update minimum interval between pulls for an pulled atom
+    /*
+     * Updates minimum interval between pulls for an pulled atom.
+     */
     void updateMinPullIntervalSec(int pullAtomId, long intervalSec);
 
-    // Notify pull request for an atom
+    /*
+     * Notes an atom is pulled.
+     */
     void notePull(int pullAtomId);
 
-    // Notify pull request for an atom served from cached data
+    /*
+     * Notes an atom is served from puller cache.
+     */
     void notePullFromCache(int pullAtomId);
 
     /*
+     * Records time for actual pulling, not including those served from cache and not including
+     * statsd processing delays.
+     */
+    void notePullTime(int pullAtomId, int64_t pullTimeNs);
+
+    /*
+     * Records pull delay for a pulled atom, including those served from cache and including statsd
+     * processing delays.
+     */
+    void notePullDelay(int pullAtomId, int64_t pullDelayNs);
+
+    /*
      * Records when system server restarts.
      */
     void noteSystemServerRestart(int32_t timeSec);
@@ -302,9 +320,15 @@ public:
     void dumpStats(int outFd) const;
 
     typedef struct {
-        long totalPull;
-        long totalPullFromCache;
-        long minPullIntervalSec;
+        long totalPull = 0;
+        long totalPullFromCache = 0;
+        long minPullIntervalSec = LONG_MAX;
+        int64_t avgPullTimeNs = 0;
+        int64_t maxPullTimeNs = 0;
+        long numPullTime = 0;
+        int64_t avgPullDelayNs = 0;
+        int64_t maxPullDelayNs = 0;
+        long numPullDelay = 0;
     } PulledAtomStats;
 
 private:
@@ -368,6 +392,7 @@ private:
     FRIEND_TEST(StatsdStatsTest, TestTimestampThreshold);
     FRIEND_TEST(StatsdStatsTest, TestAnomalyMonitor);
     FRIEND_TEST(StatsdStatsTest, TestSystemServerCrash);
+    FRIEND_TEST(StatsdStatsTest, TestPullAtomStats);
 };
 
 }  // namespace statsd
diff --git a/cmds/statsd/src/stats_log.proto b/cmds/statsd/src/stats_log.proto
index e8f74d3008e4..8bfa36059e9a 100644
--- a/cmds/statsd/src/stats_log.proto
+++ b/cmds/statsd/src/stats_log.proto
@@ -370,6 +370,10 @@ message StatsdStatsReport {
         optional int64 total_pull = 2;
         optional int64 total_pull_from_cache = 3;
         optional int64 min_pull_interval_sec = 4;
+        optional int64 average_pull_time_nanos = 5;
+        optional int64 max_pull_time_nanos = 6;
+        optional int64 average_pull_delay_nanos = 7;
+        optional int64 max_pull_delay_nanos = 8;
     }
     repeated PulledAtomStats pulled_atom_stats = 10;
 
diff --git a/cmds/statsd/src/stats_log_util.cpp b/cmds/statsd/src/stats_log_util.cpp
index 2498d9f32d06..44fa72e77a0d 100644
--- a/cmds/statsd/src/stats_log_util.cpp
+++ b/cmds/statsd/src/stats_log_util.cpp
@@ -59,6 +59,10 @@ const int FIELD_ID_PULL_ATOM_ID = 1;
 const int FIELD_ID_TOTAL_PULL = 2;
 const int FIELD_ID_TOTAL_PULL_FROM_CACHE = 3;
 const int FIELD_ID_MIN_PULL_INTERVAL_SEC = 4;
+const int FIELD_ID_AVERAGE_PULL_TIME_NANOS = 5;
+const int FIELD_ID_MAX_PULL_TIME_NANOS = 6;
+const int FIELD_ID_AVERAGE_PULL_DELAY_NANOS = 7;
+const int FIELD_ID_MAX_PULL_DELAY_NANOS = 8;
 
 namespace {
 
@@ -434,6 +438,14 @@ void writePullerStatsToStream(const std::pair<int, StatsdStats::PulledAtomStats>
                        (long long)pair.second.totalPullFromCache);
     protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_MIN_PULL_INTERVAL_SEC,
                        (long long)pair.second.minPullIntervalSec);
+    protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_AVERAGE_PULL_TIME_NANOS,
+                       (long long)pair.second.avgPullTimeNs);
+    protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_MAX_PULL_TIME_NANOS,
+                       (long long)pair.second.maxPullTimeNs);
+    protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_AVERAGE_PULL_DELAY_NANOS,
+                       (long long)pair.second.avgPullDelayNs);
+    protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_MAX_PULL_DELAY_NANOS,
+                       (long long)pair.second.maxPullDelayNs);
     protoOutput->end(token);
 }
 
diff --git a/cmds/statsd/tests/guardrail/StatsdStats_test.cpp b/cmds/statsd/tests/guardrail/StatsdStats_test.cpp
index f37f908532ca..6069516e9666 100644
--- a/cmds/statsd/tests/guardrail/StatsdStats_test.cpp
+++ b/cmds/statsd/tests/guardrail/StatsdStats_test.cpp
@@ -244,6 +244,39 @@ TEST(StatsdStatsTest, TestAtomLog) {
     EXPECT_TRUE(sensorAtomGood);
 }
 
+TEST(StatsdStatsTest, TestPullAtomStats) {
+    StatsdStats stats;
+
+    stats.updateMinPullIntervalSec(android::util::DISK_SPACE, 3333L);
+    stats.updateMinPullIntervalSec(android::util::DISK_SPACE, 2222L);
+    stats.updateMinPullIntervalSec(android::util::DISK_SPACE, 4444L);
+
+    stats.notePull(android::util::DISK_SPACE);
+    stats.notePullTime(android::util::DISK_SPACE, 1111L);
+    stats.notePullDelay(android::util::DISK_SPACE, 1111L);
+    stats.notePull(android::util::DISK_SPACE);
+    stats.notePullTime(android::util::DISK_SPACE, 3333L);
+    stats.notePullDelay(android::util::DISK_SPACE, 3335L);
+    stats.notePull(android::util::DISK_SPACE);
+    stats.notePullFromCache(android::util::DISK_SPACE);
+
+    vector<uint8_t> output;
+    stats.dumpStats(&output, false);
+    StatsdStatsReport report;
+    bool good = report.ParseFromArray(&output[0], output.size());
+    EXPECT_TRUE(good);
+
+    EXPECT_EQ(1, report.pulled_atom_stats_size());
+
+    EXPECT_EQ(android::util::DISK_SPACE, report.pulled_atom_stats(0).atom_id());
+    EXPECT_EQ(3, report.pulled_atom_stats(0).total_pull());
+    EXPECT_EQ(1, report.pulled_atom_stats(0).total_pull_from_cache());
+    EXPECT_EQ(2222L, report.pulled_atom_stats(0).min_pull_interval_sec());
+    EXPECT_EQ(2222L, report.pulled_atom_stats(0).average_pull_time_nanos());
+    EXPECT_EQ(3333L, report.pulled_atom_stats(0).max_pull_time_nanos());
+    EXPECT_EQ(2223L, report.pulled_atom_stats(0).average_pull_delay_nanos());
+    EXPECT_EQ(3335L, report.pulled_atom_stats(0).max_pull_delay_nanos());
+}
 
 TEST(StatsdStatsTest, TestAnomalyMonitor) {
     StatsdStats stats;