Merge "Improve statsdstats logging for pulled atoms" into rvc-dev

cmds/statsd/src/external/StatsCallbackPuller.cpp

@@ -86,6 +86,7 @@ bool StatsCallbackPuller::PullInternal(vector<shared_ptr<LogEvent>>* 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;
     }
 

cmds/statsd/src/external/StatsPuller.cpp

@@ -82,6 +82,11 @@ bool StatsPuller::Pull(std::vector<std::shared_ptr<LogEvent>>* data) {
         mapAndMergeIsolatedUidsToHostUid(mCachedData, mUidMap, mTagId, mAdditiveFields);
     }
 
+    if (mCachedData.empty()) {
+        VLOG("Data pulled is empty");
+        StatsdStats::getInstance().noteEmptyData(mTagId);
+    }
+
     (*data) = mCachedData;
     return mHasGoodData;
 }

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> 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<int32_t>& 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<shared_ptr<LogEvent>> data;
         bool pullSuccess = PullLocked(pullInfo.first->atomTag, pullInfo.first->configKey, &data);
-        if (pullSuccess) {
+        if (!pullSuccess) {
-            StatsdStats::getInstance().notePullDelay(pullInfo.first->atomTag,
-                                                     getElapsedRealtimeNs() - elapsedTimeNs);
-        } else {
             VLOG("pull failed at %lld, will try again later", (long long)elapsedTimeNs);
         }
 

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<std::mutex> lock(mLock);
-    mPulledAtomStats[atomId].statsCompanionPullFailed++;
+    mPulledAtomStats[atomId].pullUidProviderNotFound++;
 }
 
-void StatsdStats::noteStatsCompanionPullBinderTransactionFailed(int atomId) {
+void StatsdStats::notePullerNotFound(int atomId) {
     lock_guard<std::mutex> lock(mLock);
-    mPulledAtomStats[atomId].statsCompanionPullBinderTransactionFailed++;
+    mPulledAtomStats[atomId].pullerNotFound++;
+}
+
+void StatsdStats::notePullBinderCallFailed(int atomId) {
+    lock_guard<std::mutex> 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"
+                "  (pull timeout)%ld, (pull exceed max delay)%ld"
-                "  (registered count) %ld, (unregistered count) %ld\n"
+                "  (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);
     }

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
+     * Records that the pull of an atom has failed due not finding a puller registered by a
-     * transaction. This can happen when StatsCompanionService returns too
+     * trusted uid.
-     * much data (the max Binder parcel size is 1MB)
      */
-    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 pullUidProviderNotFound = 0;
-        long statsCompanionPullBinderTransactionFailed = 0;
+        long pullerNotFound = 0;
         long emptyData = 0;
         long registeredCount = 0;
         long unregisteredCount = 0;
         int32_t atomErrorCount = 0;
+        long binderCallFailCount = 0;
     } PulledAtomStats;
 
     typedef struct {

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<std::shared_ptr<LogEven
     if (!pullSuccess || allData.size() == 0) {
         return;
     }
+    const int64_t pullDelayNs = getElapsedRealtimeNs() - originalPullTimeNs;
+    StatsdStats::getInstance().notePullDelay(mPullTagId, pullDelayNs);
+    if (pullDelayNs > 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) {

cmds/statsd/src/metrics/ValueMetricProducer.cpp

@@ -584,11 +584,6 @@ void ValueMetricProducer::accumulateEvents(const std::vector<std::shared_ptr<Log
         return;
     }
 
-    if (allData.size() == 0) {
-        VLOG("Data pulled is empty");
-        StatsdStats::getInstance().noteEmptyData(mPullTagId);
-    }
-
     mMatchedMetricDimensionKeys.clear();
     for (const auto& data : allData) {
         LogEvent localCopy = data->makeCopy();

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_failed = 13 [deprecated = true];
-        optional int64 stats_companion_pull_binder_transaction_failed = 14;
+        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;
 

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<int, StatsdStats::PulledAtomStats>
                        (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<int, StatsdStats::PulledAtomStats>
     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);
 }
 

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<uint8_t> 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) {