StatsdStats: improve activation time logging
Add logging to record whenever the 10 second guardrail for sending
active configs changed broadcast is met, so that we know when the
broadcast would not have been sent.
Add activation time for configs that are active when the device boots.
This will help determine whether or not statsd thinks configs are active
and will help debug issues like b/133809948
Bug: 133809948
Test: bit statsd_test:*
Test: manually rebooted to make sure activation time was logged
Change-Id: Ifa72202bc52485e4953e49d78dffea685cc3d1e7
diff --git a/cmds/statsd/src/StatsLogProcessor.cpp b/cmds/statsd/src/StatsLogProcessor.cpp
index 4e0a8eb..ff7416c 100644
--- a/cmds/statsd/src/StatsLogProcessor.cpp
+++ b/cmds/statsd/src/StatsLogProcessor.cpp
@@ -269,6 +269,7 @@
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;
}
diff --git a/cmds/statsd/src/guardrail/StatsdStats.cpp b/cmds/statsd/src/guardrail/StatsdStats.cpp
index ce0e561..a836bd1 100644
--- a/cmds/statsd/src/guardrail/StatsdStats.cpp
+++ b/cmds/statsd/src/guardrail/StatsdStats.cpp
@@ -51,6 +51,7 @@
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_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 @@
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 @@
pullStats.second.unregisteredCount = 0;
}
mAtomMetricStats.clear();
+ mActivationBroadcastGuardrailStats.clear();
}
string buildTimeString(int64_t timeSec) {
@@ -758,6 +776,17 @@
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 @@
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);
diff --git a/cmds/statsd/src/guardrail/StatsdStats.h b/cmds/statsd/src/guardrail/StatsdStats.h
index 42d9e96..23d2ace 100644
--- a/cmds/statsd/src/guardrail/StatsdStats.h
+++ b/cmds/statsd/src/guardrail/StatsdStats.h
@@ -445,6 +445,12 @@
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
* to collect stats after reset() has been called.
@@ -532,6 +538,10 @@
// 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 @@
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 @@
FRIEND_TEST(StatsdStatsTest, TestSystemServerCrash);
FRIEND_TEST(StatsdStatsTest, TestPullAtomStats);
FRIEND_TEST(StatsdStatsTest, TestAtomMetricsStats);
+ FRIEND_TEST(StatsdStatsTest, TestActivationBroadcastGuardrailHit);
};
} // namespace statsd
diff --git a/cmds/statsd/src/metrics/MetricsManager.cpp b/cmds/statsd/src/metrics/MetricsManager.cpp
index 207a7dd..963205e 100644
--- a/cmds/statsd/src/metrics/MetricsManager.cpp
+++ b/cmds/statsd/src/metrics/MetricsManager.cpp
@@ -521,6 +521,10 @@
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();
}
}
diff --git a/cmds/statsd/src/stats_log.proto b/cmds/statsd/src/stats_log.proto
index 54ca757..b875470 100644
--- a/cmds/statsd/src/stats_log.proto
+++ b/cmds/statsd/src/stats_log.proto
@@ -470,6 +470,13 @@
}
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 {
diff --git a/cmds/statsd/tests/guardrail/StatsdStats_test.cpp b/cmds/statsd/tests/guardrail/StatsdStats_test.cpp
index 1b8a3b5..2a43d9b 100644
--- a/cmds/statsd/tests/guardrail/StatsdStats_test.cpp
+++ b/cmds/statsd/tests/guardrail/StatsdStats_test.cpp
@@ -445,6 +445,47 @@
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