From 873e91a1174b3d44a2f5978b256fffeef37241a8 Mon Sep 17 00:00:00 2001 From: Tej Singh Date: Tue, 28 Apr 2020 00:33:11 -0700 Subject: [PATCH] Improve statsdstats logging for pulled atoms 1. remove old statscompanion counters 2. add outgoing binder call fail counts 3. Add additional pull failure cases a. No pull uid provider (If a config doesn't register properly) b. Puller not found - either because it was not registered or because the client did not specify the correct uids 4. Make metrics own logging pull delays - these were getting overcounted since both the PullerManager and ValueMetricProducer were logging pull delays. 5. Move noteEmptyPull to StatsPuller for more uniform logging, instead of it just being logged in value metric producer. Test: m statsd Bug: 154056912 Change-Id: Ia373003905ee44d3b7b37b2bfa1e1d6268250070 --- .../src/external/StatsCallbackPuller.cpp | 1 + cmds/statsd/src/external/StatsPuller.cpp | 5 ++++ .../src/external/StatsPullerManager.cpp | 8 +++--- cmds/statsd/src/guardrail/StatsdStats.cpp | 24 ++++++++++++---- cmds/statsd/src/guardrail/StatsdStats.h | 28 +++++++++++++------ .../src/metrics/GaugeMetricProducer.cpp | 10 +++++-- .../src/metrics/ValueMetricProducer.cpp | 5 ---- cmds/statsd/src/stats_log.proto | 7 +++-- cmds/statsd/src/stats_log_util.cpp | 15 ++++++---- .../tests/guardrail/StatsdStats_test.cpp | 8 +++++- 10 files changed, 76 insertions(+), 35 deletions(-) diff --git a/cmds/statsd/src/external/StatsCallbackPuller.cpp b/cmds/statsd/src/external/StatsCallbackPuller.cpp index 3618bb0dd08ba..78e6f094db7e3 100644 --- a/cmds/statsd/src/external/StatsCallbackPuller.cpp +++ b/cmds/statsd/src/external/StatsCallbackPuller.cpp @@ -86,6 +86,7 @@ bool StatsCallbackPuller::PullInternal(vector>* data) { // in unit tests. In process calls are not oneway. Status status = mCallback->onPullAtom(mTagId, resultReceiver); if (!status.isOk()) { + StatsdStats::getInstance().notePullBinderCallFailed(mTagId); return false; } diff --git a/cmds/statsd/src/external/StatsPuller.cpp b/cmds/statsd/src/external/StatsPuller.cpp index 5192ddf301e10..829a60345ba70 100644 --- a/cmds/statsd/src/external/StatsPuller.cpp +++ b/cmds/statsd/src/external/StatsPuller.cpp @@ -82,6 +82,11 @@ bool StatsPuller::Pull(std::vector>* data) { mapAndMergeIsolatedUidsToHostUid(mCachedData, mUidMap, mTagId, mAdditiveFields); } + if (mCachedData.empty()) { + VLOG("Data pulled is empty"); + StatsdStats::getInstance().noteEmptyData(mTagId); + } + (*data) = mCachedData; return mHasGoodData; } diff --git a/cmds/statsd/src/external/StatsPullerManager.cpp b/cmds/statsd/src/external/StatsPullerManager.cpp index cfd5d14b0d3be..4320793598a89 100644 --- a/cmds/statsd/src/external/StatsPullerManager.cpp +++ b/cmds/statsd/src/external/StatsPullerManager.cpp @@ -111,12 +111,14 @@ bool StatsPullerManager::PullLocked(int tagId, const ConfigKey& configKey, if (uidProviderIt == mPullUidProviders.end()) { ALOGE("Error pulling tag %d. No pull uid provider for config key %s", tagId, configKey.ToString().c_str()); + StatsdStats::getInstance().notePullUidProviderNotFound(tagId); return false; } sp pullUidProvider = uidProviderIt->second.promote(); if (pullUidProvider == nullptr) { ALOGE("Error pulling tag %d, pull uid provider for config %s is gone.", tagId, configKey.ToString().c_str()); + StatsdStats::getInstance().notePullUidProviderNotFound(tagId); return false; } uids = pullUidProvider->getPullAtomUids(tagId); @@ -140,6 +142,7 @@ bool StatsPullerManager::PullLocked(int tagId, const vector& uids, return ret; } } + StatsdStats::getInstance().notePullerNotFound(tagId); ALOGW("StatsPullerManager: Unknown tagId %d", tagId); return false; // Return early since we don't know what to pull. } else { @@ -288,10 +291,7 @@ void StatsPullerManager::OnAlarmFired(int64_t elapsedTimeNs) { for (const auto& pullInfo : needToPull) { vector> data; bool pullSuccess = PullLocked(pullInfo.first->atomTag, pullInfo.first->configKey, &data); - if (pullSuccess) { - StatsdStats::getInstance().notePullDelay(pullInfo.first->atomTag, - getElapsedRealtimeNs() - elapsedTimeNs); - } else { + if (!pullSuccess) { VLOG("pull failed at %lld, will try again later", (long long)elapsedTimeNs); } diff --git a/cmds/statsd/src/guardrail/StatsdStats.cpp b/cmds/statsd/src/guardrail/StatsdStats.cpp index 46f5dbda5521c..c027fffd20a0e 100644 --- a/cmds/statsd/src/guardrail/StatsdStats.cpp +++ b/cmds/statsd/src/guardrail/StatsdStats.cpp @@ -472,14 +472,19 @@ void StatsdStats::notePullFailed(int atomId) { mPulledAtomStats[atomId].pullFailed++; } -void StatsdStats::noteStatsCompanionPullFailed(int atomId) { +void StatsdStats::notePullUidProviderNotFound(int atomId) { lock_guard lock(mLock); - mPulledAtomStats[atomId].statsCompanionPullFailed++; + mPulledAtomStats[atomId].pullUidProviderNotFound++; } -void StatsdStats::noteStatsCompanionPullBinderTransactionFailed(int atomId) { +void StatsdStats::notePullerNotFound(int atomId) { lock_guard lock(mLock); - mPulledAtomStats[atomId].statsCompanionPullBinderTransactionFailed++; + mPulledAtomStats[atomId].pullerNotFound++; +} + +void StatsdStats::notePullBinderCallFailed(int atomId) { + lock_guard lock(mLock); + mPulledAtomStats[atomId].binderCallFailCount++; } void StatsdStats::noteEmptyData(int atomId) { @@ -608,6 +613,7 @@ void StatsdStats::resetInternalLocked() { for (auto& pullStats : mPulledAtomStats) { pullStats.second.totalPull = 0; pullStats.second.totalPullFromCache = 0; + pullStats.second.minPullIntervalSec = LONG_MAX; pullStats.second.avgPullTimeNs = 0; pullStats.second.maxPullTimeNs = 0; pullStats.second.numPullTime = 0; @@ -617,9 +623,13 @@ void StatsdStats::resetInternalLocked() { pullStats.second.dataError = 0; pullStats.second.pullTimeout = 0; pullStats.second.pullExceedMaxDelay = 0; + pullStats.second.pullFailed = 0; + pullStats.second.pullUidProviderNotFound = 0; + pullStats.second.pullerNotFound = 0; pullStats.second.registeredCount = 0; pullStats.second.unregisteredCount = 0; pullStats.second.atomErrorCount = 0; + pullStats.second.binderCallFailCount = 0; } mAtomMetricStats.clear(); mActivationBroadcastGuardrailStats.clear(); @@ -764,14 +774,16 @@ void StatsdStats::dumpStats(int out) const { " (average pull time nanos)%lld, (max pull time nanos)%lld, (average pull delay " "nanos)%lld, " " (max pull delay nanos)%lld, (data error)%ld\n" - " (pull timeout)%ld, (pull exceed max delay)%ld\n" - " (registered count) %ld, (unregistered count) %ld\n" + " (pull timeout)%ld, (pull exceed max delay)%ld" + " (no uid provider count)%ld, (no puller found count)%ld\n" + " (registered count) %ld, (unregistered count) %ld" " (atom error count) %d\n", (int)pair.first, (long)pair.second.totalPull, (long)pair.second.totalPullFromCache, (long)pair.second.pullFailed, (long)pair.second.minPullIntervalSec, (long long)pair.second.avgPullTimeNs, (long long)pair.second.maxPullTimeNs, (long long)pair.second.avgPullDelayNs, (long long)pair.second.maxPullDelayNs, pair.second.dataError, pair.second.pullTimeout, pair.second.pullExceedMaxDelay, + pair.second.pullUidProviderNotFound, pair.second.pullerNotFound, pair.second.registeredCount, pair.second.unregisteredCount, pair.second.atomErrorCount); } diff --git a/cmds/statsd/src/guardrail/StatsdStats.h b/cmds/statsd/src/guardrail/StatsdStats.h index 805281ccd2d2d..3d0eeb840064a 100644 --- a/cmds/statsd/src/guardrail/StatsdStats.h +++ b/cmds/statsd/src/guardrail/StatsdStats.h @@ -371,21 +371,30 @@ public: int32_t lastAtomTag, int32_t uid, int32_t pid); /** - * Records that the pull of an atom has failed + * Records that the pull of an atom has failed. Eg, if the client indicated the pull failed, if + * the pull timed out, or if the outgoing binder call failed. + * This count will only increment if the puller was actually invoked. + * + * It does not include a pull not occurring due to not finding the appropriate + * puller. These cases are covered in other counts. */ void notePullFailed(int atomId); /** - * Records that the pull of StatsCompanionService atom has failed + * Records that the pull of an atom has failed due to not having a uid provider. */ - void noteStatsCompanionPullFailed(int atomId); + void notePullUidProviderNotFound(int atomId); /** - * Records that the pull of a StatsCompanionService atom has failed due to a failed binder - * transaction. This can happen when StatsCompanionService returns too - * much data (the max Binder parcel size is 1MB) + * Records that the pull of an atom has failed due not finding a puller registered by a + * trusted uid. */ - void noteStatsCompanionPullBinderTransactionFailed(int atomId); + void notePullerNotFound(int atomId); + + /** + * Records that the pull has failed due to the outgoing binder call failing. + */ + void notePullBinderCallFailed(int atomId); /** * A pull with no data occurred @@ -503,12 +512,13 @@ public: long pullTimeout = 0; long pullExceedMaxDelay = 0; long pullFailed = 0; - long statsCompanionPullFailed = 0; - long statsCompanionPullBinderTransactionFailed = 0; + long pullUidProviderNotFound = 0; + long pullerNotFound = 0; long emptyData = 0; long registeredCount = 0; long unregisteredCount = 0; int32_t atomErrorCount = 0; + long binderCallFailCount = 0; } PulledAtomStats; typedef struct { diff --git a/cmds/statsd/src/metrics/GaugeMetricProducer.cpp b/cmds/statsd/src/metrics/GaugeMetricProducer.cpp index c4bd0549465ac..cc4c56537c4c6 100644 --- a/cmds/statsd/src/metrics/GaugeMetricProducer.cpp +++ b/cmds/statsd/src/metrics/GaugeMetricProducer.cpp @@ -326,13 +326,12 @@ void GaugeMetricProducer::pullAndMatchEventsLocked(const int64_t timestampNs) { return; } const int64_t pullDelayNs = getElapsedRealtimeNs() - timestampNs; + StatsdStats::getInstance().notePullDelay(mPullTagId, pullDelayNs); if (pullDelayNs > mMaxPullDelayNs) { ALOGE("Pull finish too late for atom %d", mPullTagId); StatsdStats::getInstance().notePullExceedMaxDelay(mPullTagId); - StatsdStats::getInstance().notePullDelay(mPullTagId, pullDelayNs); return; } - StatsdStats::getInstance().notePullDelay(mPullTagId, pullDelayNs); for (const auto& data : allData) { LogEvent localCopy = data->makeCopy(); localCopy.setElapsedTimestampNs(timestampNs); @@ -415,6 +414,13 @@ void GaugeMetricProducer::onDataPulled(const std::vector mMaxPullDelayNs) { + ALOGE("Pull finish too late for atom %d", mPullTagId); + StatsdStats::getInstance().notePullExceedMaxDelay(mPullTagId); + return; + } for (const auto& data : allData) { if (mEventMatcherWizard->matchLogEvent( *data, mWhatMatcherIndex) == MatchingState::kMatched) { diff --git a/cmds/statsd/src/metrics/ValueMetricProducer.cpp b/cmds/statsd/src/metrics/ValueMetricProducer.cpp index f34423a27affc..e5ec72e3d0f50 100644 --- a/cmds/statsd/src/metrics/ValueMetricProducer.cpp +++ b/cmds/statsd/src/metrics/ValueMetricProducer.cpp @@ -584,11 +584,6 @@ void ValueMetricProducer::accumulateEvents(const std::vectormakeCopy(); diff --git a/cmds/statsd/src/stats_log.proto b/cmds/statsd/src/stats_log.proto index 868247bc9d643..1121392f1db0a 100644 --- a/cmds/statsd/src/stats_log.proto +++ b/cmds/statsd/src/stats_log.proto @@ -456,12 +456,15 @@ message StatsdStatsReport { optional int64 pull_timeout = 10; optional int64 pull_exceed_max_delay = 11; optional int64 pull_failed = 12; - optional int64 stats_companion_pull_failed = 13; - optional int64 stats_companion_pull_binder_transaction_failed = 14; + optional int64 stats_companion_pull_failed = 13 [deprecated = true]; + optional int64 stats_companion_pull_binder_transaction_failed = 14 [deprecated = true]; optional int64 empty_data = 15; optional int64 registered_count = 16; optional int64 unregistered_count = 17; optional int32 atom_error_count = 18; + optional int64 binder_call_failed = 19; + optional int64 failed_uid_provider_not_found = 20; + optional int64 puller_not_found = 21; } 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 2acffee0f4433..bafdfcba59b23 100644 --- a/cmds/statsd/src/stats_log_util.cpp +++ b/cmds/statsd/src/stats_log_util.cpp @@ -74,12 +74,13 @@ const int FIELD_ID_DATA_ERROR = 9; const int FIELD_ID_PULL_TIMEOUT = 10; const int FIELD_ID_PULL_EXCEED_MAX_DELAY = 11; const int FIELD_ID_PULL_FAILED = 12; -const int FIELD_ID_STATS_COMPANION_FAILED = 13; -const int FIELD_ID_STATS_COMPANION_BINDER_TRANSACTION_FAILED = 14; const int FIELD_ID_EMPTY_DATA = 15; const int FIELD_ID_PULL_REGISTERED_COUNT = 16; const int FIELD_ID_PULL_UNREGISTERED_COUNT = 17; const int FIELD_ID_ATOM_ERROR_COUNT = 18; +const int FIELD_ID_BINDER_CALL_FAIL_COUNT = 19; +const int FIELD_ID_PULL_UID_PROVIDER_NOT_FOUND = 20; +const int FIELD_ID_PULLER_NOT_FOUND = 21; // for AtomMetricStats proto const int FIELD_ID_ATOM_METRIC_STATS = 17; @@ -483,10 +484,6 @@ void writePullerStatsToStream(const std::pair (long long)pair.second.pullExceedMaxDelay); protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_PULL_FAILED, (long long)pair.second.pullFailed); - protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_STATS_COMPANION_FAILED, - (long long)pair.second.statsCompanionPullFailed); - protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_STATS_COMPANION_BINDER_TRANSACTION_FAILED, - (long long)pair.second.statsCompanionPullBinderTransactionFailed); protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_EMPTY_DATA, (long long)pair.second.emptyData); protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_PULL_REGISTERED_COUNT, @@ -494,6 +491,12 @@ void writePullerStatsToStream(const std::pair protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_PULL_UNREGISTERED_COUNT, (long long) pair.second.unregisteredCount); protoOutput->write(FIELD_TYPE_INT32 | FIELD_ID_ATOM_ERROR_COUNT, pair.second.atomErrorCount); + protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_BINDER_CALL_FAIL_COUNT, + (long long)pair.second.binderCallFailCount); + protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_PULL_UID_PROVIDER_NOT_FOUND, + (long long)pair.second.pullUidProviderNotFound); + protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_PULLER_NOT_FOUND, + (long long)pair.second.pullerNotFound); protoOutput->end(token); } diff --git a/cmds/statsd/tests/guardrail/StatsdStats_test.cpp b/cmds/statsd/tests/guardrail/StatsdStats_test.cpp index cdde603f4c0b5..948d587069714 100644 --- a/cmds/statsd/tests/guardrail/StatsdStats_test.cpp +++ b/cmds/statsd/tests/guardrail/StatsdStats_test.cpp @@ -302,7 +302,10 @@ TEST(StatsdStatsTest, TestPullAtomStats) { stats.notePullerCallbackRegistrationChanged(util::DISK_SPACE, true); stats.notePullerCallbackRegistrationChanged(util::DISK_SPACE, false); stats.notePullerCallbackRegistrationChanged(util::DISK_SPACE, true); - + stats.notePullBinderCallFailed(util::DISK_SPACE); + stats.notePullUidProviderNotFound(util::DISK_SPACE); + stats.notePullerNotFound(util::DISK_SPACE); + stats.notePullerNotFound(util::DISK_SPACE); vector output; stats.dumpStats(&output, false); @@ -322,6 +325,9 @@ TEST(StatsdStatsTest, TestPullAtomStats) { EXPECT_EQ(3335L, report.pulled_atom_stats(0).max_pull_delay_nanos()); EXPECT_EQ(2L, report.pulled_atom_stats(0).registered_count()); EXPECT_EQ(1L, report.pulled_atom_stats(0).unregistered_count()); + EXPECT_EQ(1L, report.pulled_atom_stats(0).binder_call_failed()); + EXPECT_EQ(1L, report.pulled_atom_stats(0).failed_uid_provider_not_found()); + EXPECT_EQ(2L, report.pulled_atom_stats(0).puller_not_found()); } TEST(StatsdStatsTest, TestAtomMetricsStats) {