From 16ca28fc8ebc47a7863dc3c3e6c7048a4be04ba8 Mon Sep 17 00:00:00 2001 From: Tej Singh Date: Mon, 24 Jun 2019 11:58:23 -0700 Subject: [PATCH] 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 --- cmds/statsd/src/StatsLogProcessor.cpp | 1 + cmds/statsd/src/guardrail/StatsdStats.cpp | 43 +++++++++++++++++++ cmds/statsd/src/guardrail/StatsdStats.h | 13 ++++++ cmds/statsd/src/metrics/MetricsManager.cpp | 4 ++ cmds/statsd/src/stats_log.proto | 7 +++ .../tests/guardrail/StatsdStats_test.cpp | 41 ++++++++++++++++++ 6 files changed, 109 insertions(+) diff --git a/cmds/statsd/src/StatsLogProcessor.cpp b/cmds/statsd/src/StatsLogProcessor.cpp index 4e0a8ebdf380e..ff7416c4b9e0f 100644 --- a/cmds/statsd/src/StatsLogProcessor.cpp +++ b/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; } diff --git a/cmds/statsd/src/guardrail/StatsdStats.cpp b/cmds/statsd/src/guardrail/StatsdStats.cpp index ce0e561f291b4..a836bd14c012d 100644 --- a/cmds/statsd/src/guardrail/StatsdStats.cpp +++ b/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> 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 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* 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); diff --git a/cmds/statsd/src/guardrail/StatsdStats.h b/cmds/statsd/src/guardrail/StatsdStats.h index 42d9e96c8cab4..23d2aceb4fc33 100644 --- a/cmds/statsd/src/guardrail/StatsdStats.h +++ b/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 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> 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& stats); /** @@ -607,6 +619,7 @@ private: 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 207a7dd872151..963205ee56f47 100644 --- a/cmds/statsd/src/metrics/MetricsManager.cpp +++ b/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(); } } diff --git a/cmds/statsd/src/stats_log.proto b/cmds/statsd/src/stats_log.proto index 54ca757f5f611..b87547056ad3c 100644 --- a/cmds/statsd/src/stats_log.proto +++ b/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 { diff --git a/cmds/statsd/tests/guardrail/StatsdStats_test.cpp b/cmds/statsd/tests/guardrail/StatsdStats_test.cpp index 1b8a3b543a490..2a43d9ba39844 100644 --- a/cmds/statsd/tests/guardrail/StatsdStats_test.cpp +++ b/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 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