Merge "StatsdStats: improve activation time logging" into qt-dev

cmds/statsd/src/StatsLogProcessor.cpp

@@ -269,6 +269,7 @@ void StatsLogProcessor::OnLogEvent(LogEvent* event) {
         if (lastBroadcastTime != mLastActivationBroadcastTimes.end()) {
             if (currentTimestampNs - lastBroadcastTime->second <
                     StatsdStats::kMinActivationBroadcastPeriodNs) {
+                StatsdStats::getInstance().noteActivationBroadcastGuardrailHit(uid);
                 VLOG("StatsD would've sent an activation broadcast but the rate limit stopped us.");
                 return;
             }

cmds/statsd/src/guardrail/StatsdStats.cpp

@@ -51,6 +51,7 @@ const int FIELD_ID_PERIODIC_ALARM_STATS = 12;
 const int FIELD_ID_SYSTEM_SERVER_RESTART = 15;
 const int FIELD_ID_LOGGER_ERROR_STATS = 16;
 const int FIELD_ID_OVERFLOW = 18;
+const int FIELD_ID_ACTIVATION_BROADCAST_GUARDRAIL = 19;
 
 const int FIELD_ID_ATOM_STATS_TAG = 1;
 const int FIELD_ID_ATOM_STATS_COUNT = 2;
@@ -109,6 +110,9 @@ const int FIELD_ID_UID_MAP_BYTES_USED = 2;
 const int FIELD_ID_UID_MAP_DROPPED_CHANGES = 3;
 const int FIELD_ID_UID_MAP_DELETED_APPS = 4;
 
+const int FIELD_ID_ACTIVATION_BROADCAST_GUARDRAIL_UID = 1;
+const int FIELD_ID_ACTIVATION_BROADCAST_GUARDRAIL_TIME = 2;
+
 const std::map<int, std::pair<size_t, size_t>> StatsdStats::kAtomDimensionKeySizeLimitMap = {
         {android::util::BINDER_CALLS, {6000, 10000}},
         {android::util::LOOPER_STATS, {1500, 2500}},
@@ -236,6 +240,19 @@ void StatsdStats::noteActiveStatusChanged(const ConfigKey& key, bool activated,
     vec.push_back(timeSec);
 }
 
+void StatsdStats::noteActivationBroadcastGuardrailHit(const int uid) {
+    noteActivationBroadcastGuardrailHit(uid, getWallClockSec());
+}
+
+void StatsdStats::noteActivationBroadcastGuardrailHit(const int uid, const int32_t timeSec) {
+    lock_guard<std::mutex> lock(mLock);
+    auto& guardrailTimes = mActivationBroadcastGuardrailStats[uid];
+    if (guardrailTimes.size() == kMaxTimestampCount) {
+        guardrailTimes.pop_front();
+    }
+    guardrailTimes.push_back(timeSec);
+}
+
 void StatsdStats::noteDataDropped(const ConfigKey& key, const size_t totalBytes) {
     noteDataDropped(key, totalBytes, getWallClockSec());
 }
@@ -590,6 +607,7 @@ void StatsdStats::resetInternalLocked() {
         pullStats.second.unregisteredCount = 0;
     }
     mAtomMetricStats.clear();
+    mActivationBroadcastGuardrailStats.clear();
 }
 
 string buildTimeString(int64_t timeSec) {
@@ -758,6 +776,17 @@ void StatsdStats::dumpStats(int out) const {
 
     dprintf(out, "Event queue overflow: %d; MaxHistoryNs: %lld; MinHistoryNs: %lld\n",
             mOverflowCount, (long long)mMaxQueueHistoryNs, (long long)mMinQueueHistoryNs);
+
+    if (mActivationBroadcastGuardrailStats.size() > 0) {
+        dprintf(out, "********mActivationBroadcastGuardrail stats***********\n");
+        for (const auto& pair: mActivationBroadcastGuardrailStats) {
+            dprintf(out, "Uid %d: Times: ", pair.first);
+            for (const auto& guardrailHitTime : pair.second) {
+                dprintf(out, "%d ", guardrailHitTime);
+            }
+        }
+        dprintf(out, "\n");
+    }
 }
 
 void addConfigStatsToProto(const ConfigStats& configStats, ProtoOutputStream* proto) {
@@ -959,6 +988,20 @@ void StatsdStats::dumpStats(std::vector<uint8_t>* output, bool reset) {
                     restart);
     }
 
+    for (const auto& pair: mActivationBroadcastGuardrailStats) {
+        uint64_t token = proto.start(FIELD_TYPE_MESSAGE |
+                                     FIELD_ID_ACTIVATION_BROADCAST_GUARDRAIL |
+                                     FIELD_COUNT_REPEATED);
+        proto.write(FIELD_TYPE_INT32 | FIELD_ID_ACTIVATION_BROADCAST_GUARDRAIL_UID,
+                    (int32_t) pair.first);
+        for (const auto& guardrailHitTime : pair.second) {
+            proto.write(FIELD_TYPE_INT32 | FIELD_ID_ACTIVATION_BROADCAST_GUARDRAIL_TIME |
+                            FIELD_COUNT_REPEATED,
+                        guardrailHitTime);
+        }
+        proto.end(token);
+    }
+
     output->clear();
     size_t bufferSize = proto.size();
     output->resize(bufferSize);

cmds/statsd/src/guardrail/StatsdStats.h

@@ -444,6 +444,12 @@ public:
      * the queue */
     void noteEventQueueOverflow(int64_t oldestEventTimestampNs);
 
+    /**
+     * Reports that the activation broadcast guardrail was hit for this uid. Namely, the broadcast
+     * should have been sent, but instead was skipped due to hitting the guardrail.
+     */
+     void noteActivationBroadcastGuardrailHit(const int uid);
+
     /**
      * Reset the historical stats. Including all stats in icebox, and the tracked stats about
      * metrics, matchers, and atoms. The active configs will be kept and StatsdStats will continue
@@ -532,6 +538,10 @@ private:
     // Maps metric ID to its stats. The size is capped by the number of metrics.
     std::map<int64_t, AtomMetricStats> mAtomMetricStats;
 
+    // Maps uids to times when the activation changed broadcast not sent due to hitting the
+    // guardrail. The size is capped by the number of configs, and up to 20 times per uid.
+    std::map<int, std::list<int32_t>> mActivationBroadcastGuardrailStats;
+
     struct LogLossStats {
         LogLossStats(int32_t sec, int32_t count, int32_t error, int32_t tag, int32_t uid,
                      int32_t pid)
@@ -588,6 +598,8 @@ private:
 
     void noteActiveStatusChanged(const ConfigKey& key, bool activate, int32_t timeSec);
 
+    void noteActivationBroadcastGuardrailHit(const int uid, int32_t timeSec);
+
     void addToIceBoxLocked(std::shared_ptr<ConfigStats>& stats);
 
     /**
@@ -607,6 +619,7 @@ private:
     FRIEND_TEST(StatsdStatsTest, TestSystemServerCrash);
     FRIEND_TEST(StatsdStatsTest, TestPullAtomStats);
     FRIEND_TEST(StatsdStatsTest, TestAtomMetricsStats);
+    FRIEND_TEST(StatsdStatsTest, TestActivationBroadcastGuardrailHit);
 };
 
 }  // namespace statsd

cmds/statsd/src/metrics/MetricsManager.cpp

@@ -521,6 +521,10 @@ void MetricsManager::loadActiveConfig(const ActiveConfig& config, int64_t curren
             if (metric->getMetricId() == activeMetric.id()) {
                 VLOG("Setting active metric: %lld", (long long)metric->getMetricId());
                 metric->loadActiveMetric(activeMetric, currentTimeNs);
+                if (!mIsActive && metric->isActive()) {
+                    StatsdStats::getInstance().noteActiveStatusChanged(mConfigKey,
+                                                                       /*activate=*/ true);
+                }
                 mIsActive |= metric->isActive();
             }
         }

cmds/statsd/src/stats_log.proto

@@ -470,6 +470,13 @@ message StatsdStatsReport {
     }
 
     optional EventQueueOverflow queue_overflow = 18;
+
+    message ActivationBroadcastGuardrail {
+        optional int32 uid = 1;
+        repeated int32 guardrail_met_sec = 2;
+    }
+
+    repeated ActivationBroadcastGuardrail activation_guardrail_stats = 19;
 }
 
 message AlertTriggerDetails {

cmds/statsd/tests/guardrail/StatsdStats_test.cpp

@@ -445,6 +445,47 @@ TEST(StatsdStatsTest, TestSystemServerCrash) {
     EXPECT_EQ(StatsdStats::kMaxSystemServerRestarts + 1, report.system_restart_sec(maxCount - 1));
 }
 
+TEST(StatsdStatsTest, TestActivationBroadcastGuardrailHit) {
+    StatsdStats stats;
+    int uid1 = 1;
+    int uid2 = 2;
+    stats.noteActivationBroadcastGuardrailHit(uid1, 10);
+    stats.noteActivationBroadcastGuardrailHit(uid1, 20);
+
+    // Test that we only keep 20 timestamps.
+    for (int i = 0; i < 100; i++) {
+        stats.noteActivationBroadcastGuardrailHit(uid2, i);
+    }
+
+    vector<uint8_t> output;
+    stats.dumpStats(&output, false);
+    StatsdStatsReport report;
+    EXPECT_TRUE(report.ParseFromArray(&output[0], output.size()));
+
+    EXPECT_EQ(2, report.activation_guardrail_stats_size());
+    bool uid1Good = false;
+    bool uid2Good = false;
+    for (const auto& guardrailTimes : report.activation_guardrail_stats()) {
+        if (uid1 == guardrailTimes.uid()) {
+            uid1Good = true;
+            EXPECT_EQ(2, guardrailTimes.guardrail_met_sec_size());
+            EXPECT_EQ(10, guardrailTimes.guardrail_met_sec(0));
+            EXPECT_EQ(20, guardrailTimes.guardrail_met_sec(1));
+        } else if (uid2 == guardrailTimes.uid()) {
+            int maxCount = StatsdStats::kMaxTimestampCount;
+            uid2Good = true;
+            EXPECT_EQ(maxCount, guardrailTimes.guardrail_met_sec_size());
+            for (int i = 0; i < maxCount; i++) {
+                EXPECT_EQ(100 - maxCount + i, guardrailTimes.guardrail_met_sec(i));
+            }
+        } else {
+            FAIL() << "Unexpected uid.";
+        }
+    }
+    EXPECT_TRUE(uid1Good);
+    EXPECT_TRUE(uid2Good);
+}
+
 }  // namespace statsd
 }  // namespace os
 }  // namespace android