Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Improve statsdstats logging for pulled atoms

Browse Source 
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
This commit is contained in:
Tej Singh
2020-04-28 00:33:11 -07:00
parent 5a61909275
commit 873e91a117
10 changed files with 76 additions and 35 deletions
Download Patch File Download Diff File Expand all files Collapse all files

1
cmds/statsd/src/external/StatsCallbackPuller.cpp vendored
View File

@@ -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;
}

5
cmds/statsd/src/external/StatsPuller.cpp vendored
View File

@@ -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;
}

8
cmds/statsd/src/external/StatsPullerManager.cpp vendored
View File

@@ -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) {
StatsdStats::getInstance().notePullDelay(pullInfo.first->atomTag,
getElapsedRealtimeNs() - elapsedTimeNs);
} else {
if (!pullSuccess) {
VLOG("pull failed at %lld, will try again later", (long long)elapsedTimeNs);
}

24
cmds/statsd/src/guardrail/StatsdStats.cpp
View File

@@ -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"
" (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);
}

28
cmds/statsd/src/guardrail/StatsdStats.h
View File

@@ -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 {

10
cmds/statsd/src/metrics/GaugeMetricProducer.cpp
View File

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

5
cmds/statsd/src/metrics/ValueMetricProducer.cpp
View File

@@ -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();

7
cmds/statsd/src/stats_log.proto
View File

@@ -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;

15
cmds/statsd/src/stats_log_util.cpp
View File

@@ -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);
}

8
cmds/statsd/tests/guardrail/StatsdStats_test.cpp
View File

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