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
diff --git a/cmds/statsd/src/external/StatsCallbackPuller.cpp b/cmds/statsd/src/external/StatsCallbackPuller.cpp
index 3618bb0..78e6f09 100644
--- a/cmds/statsd/src/external/StatsCallbackPuller.cpp
+++ b/cmds/statsd/src/external/StatsCallbackPuller.cpp
@@ -86,6 +86,7 @@
     // 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 5192ddf..829a603 100644
--- a/cmds/statsd/src/external/StatsPuller.cpp
+++ b/cmds/statsd/src/external/StatsPuller.cpp
@@ -82,6 +82,11 @@
         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 cfd5d14..4320793 100644
--- a/cmds/statsd/src/external/StatsPullerManager.cpp
+++ b/cmds/statsd/src/external/StatsPullerManager.cpp
@@ -111,12 +111,14 @@
         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 @@
                 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 @@
     for (const auto& pullInfo : needToPull) {
         vector<shared_ptr<LogEvent>> 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 46f5dbd..c027fff 100644
--- a/cmds/statsd/src/guardrail/StatsdStats.cpp
+++ b/cmds/statsd/src/guardrail/StatsdStats.cpp
@@ -472,14 +472,19 @@
     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 @@
     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 @@
         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 @@
                 "  (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 805281c..3d0eeb8 100644
--- a/cmds/statsd/src/guardrail/StatsdStats.h
+++ b/cmds/statsd/src/guardrail/StatsdStats.h
@@ -371,21 +371,30 @@
                      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 @@
         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 c4bd054..cc4c565 100644
--- a/cmds/statsd/src/metrics/GaugeMetricProducer.cpp
+++ b/cmds/statsd/src/metrics/GaugeMetricProducer.cpp
@@ -326,13 +326,12 @@
         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 @@
     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) {
diff --git a/cmds/statsd/src/metrics/ValueMetricProducer.cpp b/cmds/statsd/src/metrics/ValueMetricProducer.cpp
index f34423a..e5ec72e 100644
--- a/cmds/statsd/src/metrics/ValueMetricProducer.cpp
+++ b/cmds/statsd/src/metrics/ValueMetricProducer.cpp
@@ -584,11 +584,6 @@
         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();
diff --git a/cmds/statsd/src/stats_log.proto b/cmds/statsd/src/stats_log.proto
index 868247b..1121392 100644
--- a/cmds/statsd/src/stats_log.proto
+++ b/cmds/statsd/src/stats_log.proto
@@ -456,12 +456,15 @@
         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 2acffee..bafdfcb 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_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 @@
                        (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 @@
     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 cdde603..948d587 100644
--- a/cmds/statsd/tests/guardrail/StatsdStats_test.cpp
+++ b/cmds/statsd/tests/guardrail/StatsdStats_test.cpp
@@ -302,7 +302,10 @@
     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 @@
     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) {