| /* |
| * Copyright (C) 2017 The Android Open Source Project |
| * |
| * Licensed under the Apache License, Version 2.0 (the "License"); |
| * you may not use this file except in compliance with the License. |
| * You may obtain a copy of the License at |
| * |
| * http://www.apache.org/licenses/LICENSE-2.0 |
| * |
| * Unless required by applicable law or agreed to in writing, software |
| * distributed under the License is distributed on an "AS IS" BASIS, |
| * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| * See the License for the specific language governing permissions and |
| * limitations under the License. |
| */ |
| |
| #define DEBUG false // STOPSHIP if true |
| #include "Log.h" |
| |
| #include "ValueMetricProducer.h" |
| #include "../guardrail/StatsdStats.h" |
| #include "../stats_log_util.h" |
| |
| #include <cutils/log.h> |
| #include <limits.h> |
| #include <stdlib.h> |
| |
| using android::util::FIELD_COUNT_REPEATED; |
| using android::util::FIELD_TYPE_BOOL; |
| using android::util::FIELD_TYPE_DOUBLE; |
| using android::util::FIELD_TYPE_INT32; |
| using android::util::FIELD_TYPE_INT64; |
| using android::util::FIELD_TYPE_MESSAGE; |
| using android::util::FIELD_TYPE_STRING; |
| using android::util::ProtoOutputStream; |
| using std::list; |
| using std::make_pair; |
| using std::make_shared; |
| using std::map; |
| using std::shared_ptr; |
| using std::unique_ptr; |
| using std::unordered_map; |
| |
| namespace android { |
| namespace os { |
| namespace statsd { |
| |
| // for StatsLogReport |
| const int FIELD_ID_ID = 1; |
| const int FIELD_ID_VALUE_METRICS = 7; |
| const int FIELD_ID_TIME_BASE = 9; |
| const int FIELD_ID_BUCKET_SIZE = 10; |
| const int FIELD_ID_DIMENSION_PATH_IN_WHAT = 11; |
| const int FIELD_ID_DIMENSION_PATH_IN_CONDITION = 12; |
| const int FIELD_ID_IS_ACTIVE = 14; |
| // for ValueMetricDataWrapper |
| const int FIELD_ID_DATA = 1; |
| const int FIELD_ID_SKIPPED = 2; |
| const int FIELD_ID_SKIPPED_START_MILLIS = 3; |
| const int FIELD_ID_SKIPPED_END_MILLIS = 4; |
| // for ValueMetricData |
| const int FIELD_ID_DIMENSION_IN_WHAT = 1; |
| const int FIELD_ID_DIMENSION_IN_CONDITION = 2; |
| const int FIELD_ID_BUCKET_INFO = 3; |
| const int FIELD_ID_DIMENSION_LEAF_IN_WHAT = 4; |
| const int FIELD_ID_DIMENSION_LEAF_IN_CONDITION = 5; |
| // for ValueBucketInfo |
| const int FIELD_ID_VALUE_INDEX = 1; |
| const int FIELD_ID_VALUE_LONG = 2; |
| const int FIELD_ID_VALUE_DOUBLE = 3; |
| const int FIELD_ID_VALUES = 9; |
| const int FIELD_ID_BUCKET_NUM = 4; |
| const int FIELD_ID_START_BUCKET_ELAPSED_MILLIS = 5; |
| const int FIELD_ID_END_BUCKET_ELAPSED_MILLIS = 6; |
| const int FIELD_ID_CONDITION_TRUE_NS = 10; |
| |
| const Value ZERO_LONG((int64_t)0); |
| const Value ZERO_DOUBLE((int64_t)0); |
| |
| // ValueMetric has a minimum bucket size of 10min so that we don't pull too frequently |
| ValueMetricProducer::ValueMetricProducer( |
| const ConfigKey& key, const ValueMetric& metric, const int conditionIndex, |
| const sp<ConditionWizard>& conditionWizard, const int whatMatcherIndex, |
| const sp<EventMatcherWizard>& matcherWizard, const int pullTagId, const int64_t timeBaseNs, |
| const int64_t startTimeNs, const sp<StatsPullerManager>& pullerManager) |
| : MetricProducer(metric.id(), key, timeBaseNs, conditionIndex, conditionWizard), |
| mWhatMatcherIndex(whatMatcherIndex), |
| mEventMatcherWizard(matcherWizard), |
| mPullerManager(pullerManager), |
| mPullTagId(pullTagId), |
| mIsPulled(pullTagId != -1), |
| mMinBucketSizeNs(metric.min_bucket_size_nanos()), |
| mDimensionSoftLimit(StatsdStats::kAtomDimensionKeySizeLimitMap.find(pullTagId) != |
| StatsdStats::kAtomDimensionKeySizeLimitMap.end() |
| ? StatsdStats::kAtomDimensionKeySizeLimitMap.at(pullTagId).first |
| : StatsdStats::kDimensionKeySizeSoftLimit), |
| mDimensionHardLimit(StatsdStats::kAtomDimensionKeySizeLimitMap.find(pullTagId) != |
| StatsdStats::kAtomDimensionKeySizeLimitMap.end() |
| ? StatsdStats::kAtomDimensionKeySizeLimitMap.at(pullTagId).second |
| : StatsdStats::kDimensionKeySizeHardLimit), |
| mUseAbsoluteValueOnReset(metric.use_absolute_value_on_reset()), |
| mAggregationType(metric.aggregation_type()), |
| mUseDiff(metric.has_use_diff() ? metric.use_diff() : (mIsPulled ? true : false)), |
| mValueDirection(metric.value_direction()), |
| mSkipZeroDiffOutput(metric.skip_zero_diff_output()), |
| mUseZeroDefaultBase(metric.use_zero_default_base()), |
| mHasGlobalBase(false), |
| mCurrentBucketIsInvalid(false), |
| mMaxPullDelayNs(metric.max_pull_delay_sec() > 0 ? metric.max_pull_delay_sec() * NS_PER_SEC |
| : StatsdStats::kPullMaxDelayNs), |
| mSplitBucketForAppUpgrade(metric.split_bucket_for_app_upgrade()), |
| // Condition timer will be set in prepareFirstBucketLocked. |
| mConditionTimer(false, timeBaseNs) { |
| int64_t bucketSizeMills = 0; |
| if (metric.has_bucket()) { |
| bucketSizeMills = TimeUnitToBucketSizeInMillisGuardrailed(key.GetUid(), metric.bucket()); |
| } else { |
| bucketSizeMills = TimeUnitToBucketSizeInMillis(ONE_HOUR); |
| } |
| |
| mBucketSizeNs = bucketSizeMills * 1000000; |
| |
| translateFieldMatcher(metric.value_field(), &mFieldMatchers); |
| |
| if (metric.has_dimensions_in_what()) { |
| translateFieldMatcher(metric.dimensions_in_what(), &mDimensionsInWhat); |
| mContainANYPositionInDimensionsInWhat = HasPositionANY(metric.dimensions_in_what()); |
| } |
| |
| if (metric.has_dimensions_in_condition()) { |
| translateFieldMatcher(metric.dimensions_in_condition(), &mDimensionsInCondition); |
| } |
| |
| if (metric.links().size() > 0) { |
| for (const auto& link : metric.links()) { |
| Metric2Condition mc; |
| mc.conditionId = link.condition(); |
| translateFieldMatcher(link.fields_in_what(), &mc.metricFields); |
| translateFieldMatcher(link.fields_in_condition(), &mc.conditionFields); |
| mMetric2ConditionLinks.push_back(mc); |
| } |
| } |
| |
| mConditionSliced = (metric.links().size() > 0) || (mDimensionsInCondition.size() > 0); |
| mSliceByPositionALL = HasPositionALL(metric.dimensions_in_what()) || |
| HasPositionALL(metric.dimensions_in_condition()); |
| |
| int64_t numBucketsForward = calcBucketsForwardCount(startTimeNs); |
| mCurrentBucketNum += numBucketsForward; |
| |
| flushIfNeededLocked(startTimeNs); |
| |
| if (mIsPulled) { |
| mPullerManager->RegisterReceiver(mPullTagId, this, getCurrentBucketEndTimeNs(), |
| mBucketSizeNs); |
| } |
| |
| // Only do this for partial buckets like first bucket. All other buckets should use |
| // flushIfNeeded to adjust start and end to bucket boundaries. |
| // Adjust start for partial bucket |
| mCurrentBucketStartTimeNs = startTimeNs; |
| mConditionTimer.newBucketStart(mCurrentBucketStartTimeNs); |
| VLOG("value metric %lld created. bucket size %lld start_time: %lld", (long long)metric.id(), |
| (long long)mBucketSizeNs, (long long)mTimeBaseNs); |
| } |
| |
| ValueMetricProducer::~ValueMetricProducer() { |
| VLOG("~ValueMetricProducer() called"); |
| if (mIsPulled) { |
| mPullerManager->UnRegisterReceiver(mPullTagId, this); |
| } |
| } |
| |
| void ValueMetricProducer::prepareFirstBucketLocked() { |
| // Kicks off the puller immediately if condition is true and diff based. |
| if (mIsActive && mIsPulled && mCondition == ConditionState::kTrue && mUseDiff) { |
| pullAndMatchEventsLocked(mCurrentBucketStartTimeNs, mCondition); |
| } |
| // Now that activations are processed, start the condition timer if needed. |
| mConditionTimer.onConditionChanged(mIsActive && mCondition == ConditionState::kTrue, |
| mCurrentBucketStartTimeNs); |
| } |
| |
| void ValueMetricProducer::onSlicedConditionMayChangeLocked(bool overallCondition, |
| const int64_t eventTime) { |
| VLOG("Metric %lld onSlicedConditionMayChange", (long long)mMetricId); |
| } |
| |
| void ValueMetricProducer::dropDataLocked(const int64_t dropTimeNs) { |
| StatsdStats::getInstance().noteBucketDropped(mMetricId); |
| // We are going to flush the data without doing a pull first so we need to invalidte the data. |
| bool pullNeeded = mIsPulled && mCondition == ConditionState::kTrue; |
| if (pullNeeded) { |
| invalidateCurrentBucket(); |
| } |
| flushIfNeededLocked(dropTimeNs); |
| clearPastBucketsLocked(dropTimeNs); |
| } |
| |
| void ValueMetricProducer::clearPastBucketsLocked(const int64_t dumpTimeNs) { |
| mPastBuckets.clear(); |
| mSkippedBuckets.clear(); |
| } |
| |
| void ValueMetricProducer::onDumpReportLocked(const int64_t dumpTimeNs, |
| const bool include_current_partial_bucket, |
| const bool erase_data, |
| const DumpLatency dumpLatency, |
| std::set<string> *str_set, |
| ProtoOutputStream* protoOutput) { |
| VLOG("metric %lld dump report now...", (long long)mMetricId); |
| if (include_current_partial_bucket) { |
| // For pull metrics, we need to do a pull at bucket boundaries. If we do not do that the |
| // current bucket will have incomplete data and the next will have the wrong snapshot to do |
| // a diff against. If the condition is false, we are fine since the base data is reset and |
| // we are not tracking anything. |
| bool pullNeeded = mIsPulled && mCondition == ConditionState::kTrue; |
| if (pullNeeded) { |
| switch (dumpLatency) { |
| case FAST: |
| invalidateCurrentBucket(); |
| break; |
| case NO_TIME_CONSTRAINTS: |
| pullAndMatchEventsLocked(dumpTimeNs, mCondition); |
| break; |
| } |
| } |
| flushCurrentBucketLocked(dumpTimeNs, dumpTimeNs); |
| } |
| protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_ID, (long long)mMetricId); |
| protoOutput->write(FIELD_TYPE_BOOL | FIELD_ID_IS_ACTIVE, isActiveLocked()); |
| |
| if (mPastBuckets.empty() && mSkippedBuckets.empty()) { |
| return; |
| } |
| protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_TIME_BASE, (long long)mTimeBaseNs); |
| protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_BUCKET_SIZE, (long long)mBucketSizeNs); |
| // Fills the dimension path if not slicing by ALL. |
| if (!mSliceByPositionALL) { |
| if (!mDimensionsInWhat.empty()) { |
| uint64_t dimenPathToken = |
| protoOutput->start(FIELD_TYPE_MESSAGE | FIELD_ID_DIMENSION_PATH_IN_WHAT); |
| writeDimensionPathToProto(mDimensionsInWhat, protoOutput); |
| protoOutput->end(dimenPathToken); |
| } |
| if (!mDimensionsInCondition.empty()) { |
| uint64_t dimenPathToken = |
| protoOutput->start(FIELD_TYPE_MESSAGE | FIELD_ID_DIMENSION_PATH_IN_CONDITION); |
| writeDimensionPathToProto(mDimensionsInCondition, protoOutput); |
| protoOutput->end(dimenPathToken); |
| } |
| } |
| |
| uint64_t protoToken = protoOutput->start(FIELD_TYPE_MESSAGE | FIELD_ID_VALUE_METRICS); |
| |
| for (const auto& pair : mSkippedBuckets) { |
| uint64_t wrapperToken = |
| protoOutput->start(FIELD_TYPE_MESSAGE | FIELD_COUNT_REPEATED | FIELD_ID_SKIPPED); |
| protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_SKIPPED_START_MILLIS, |
| (long long)(NanoToMillis(pair.first))); |
| protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_SKIPPED_END_MILLIS, |
| (long long)(NanoToMillis(pair.second))); |
| protoOutput->end(wrapperToken); |
| } |
| |
| for (const auto& pair : mPastBuckets) { |
| const MetricDimensionKey& dimensionKey = pair.first; |
| VLOG(" dimension key %s", dimensionKey.toString().c_str()); |
| uint64_t wrapperToken = |
| protoOutput->start(FIELD_TYPE_MESSAGE | FIELD_COUNT_REPEATED | FIELD_ID_DATA); |
| |
| // First fill dimension. |
| if (mSliceByPositionALL) { |
| uint64_t dimensionToken = |
| protoOutput->start(FIELD_TYPE_MESSAGE | FIELD_ID_DIMENSION_IN_WHAT); |
| writeDimensionToProto(dimensionKey.getDimensionKeyInWhat(), str_set, protoOutput); |
| protoOutput->end(dimensionToken); |
| if (dimensionKey.hasDimensionKeyInCondition()) { |
| uint64_t dimensionInConditionToken = |
| protoOutput->start(FIELD_TYPE_MESSAGE | FIELD_ID_DIMENSION_IN_CONDITION); |
| writeDimensionToProto(dimensionKey.getDimensionKeyInCondition(), str_set, |
| protoOutput); |
| protoOutput->end(dimensionInConditionToken); |
| } |
| } else { |
| writeDimensionLeafNodesToProto(dimensionKey.getDimensionKeyInWhat(), |
| FIELD_ID_DIMENSION_LEAF_IN_WHAT, str_set, protoOutput); |
| if (dimensionKey.hasDimensionKeyInCondition()) { |
| writeDimensionLeafNodesToProto(dimensionKey.getDimensionKeyInCondition(), |
| FIELD_ID_DIMENSION_LEAF_IN_CONDITION, str_set, |
| protoOutput); |
| } |
| } |
| |
| // Then fill bucket_info (ValueBucketInfo). |
| for (const auto& bucket : pair.second) { |
| uint64_t bucketInfoToken = protoOutput->start( |
| FIELD_TYPE_MESSAGE | FIELD_COUNT_REPEATED | FIELD_ID_BUCKET_INFO); |
| |
| if (bucket.mBucketEndNs - bucket.mBucketStartNs != mBucketSizeNs) { |
| protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_START_BUCKET_ELAPSED_MILLIS, |
| (long long)NanoToMillis(bucket.mBucketStartNs)); |
| protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_END_BUCKET_ELAPSED_MILLIS, |
| (long long)NanoToMillis(bucket.mBucketEndNs)); |
| } else { |
| protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_BUCKET_NUM, |
| (long long)(getBucketNumFromEndTimeNs(bucket.mBucketEndNs))); |
| } |
| // only write the condition timer value if the metric has a condition. |
| if (mConditionTrackerIndex >= 0) { |
| protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_CONDITION_TRUE_NS, |
| (long long)bucket.mConditionTrueNs); |
| } |
| for (int i = 0; i < (int)bucket.valueIndex.size(); i ++) { |
| int index = bucket.valueIndex[i]; |
| const Value& value = bucket.values[i]; |
| uint64_t valueToken = protoOutput->start( |
| FIELD_TYPE_MESSAGE | FIELD_COUNT_REPEATED | FIELD_ID_VALUES); |
| protoOutput->write(FIELD_TYPE_INT32 | FIELD_ID_VALUE_INDEX, |
| index); |
| if (value.getType() == LONG) { |
| protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_VALUE_LONG, |
| (long long)value.long_value); |
| VLOG("\t bucket [%lld - %lld] value %d: %lld", (long long)bucket.mBucketStartNs, |
| (long long)bucket.mBucketEndNs, index, (long long)value.long_value); |
| } else if (value.getType() == DOUBLE) { |
| protoOutput->write(FIELD_TYPE_DOUBLE | FIELD_ID_VALUE_DOUBLE, |
| value.double_value); |
| VLOG("\t bucket [%lld - %lld] value %d: %.2f", (long long)bucket.mBucketStartNs, |
| (long long)bucket.mBucketEndNs, index, value.double_value); |
| } else { |
| VLOG("Wrong value type for ValueMetric output: %d", value.getType()); |
| } |
| protoOutput->end(valueToken); |
| } |
| protoOutput->end(bucketInfoToken); |
| } |
| protoOutput->end(wrapperToken); |
| } |
| protoOutput->end(protoToken); |
| |
| VLOG("metric %lld dump report now...", (long long)mMetricId); |
| if (erase_data) { |
| mPastBuckets.clear(); |
| mSkippedBuckets.clear(); |
| } |
| } |
| |
| void ValueMetricProducer::invalidateCurrentBucketWithoutResetBase() { |
| if (!mCurrentBucketIsInvalid) { |
| // Only report once per invalid bucket. |
| StatsdStats::getInstance().noteInvalidatedBucket(mMetricId); |
| } |
| mCurrentBucketIsInvalid = true; |
| } |
| |
| void ValueMetricProducer::invalidateCurrentBucket() { |
| invalidateCurrentBucketWithoutResetBase(); |
| resetBase(); |
| } |
| |
| void ValueMetricProducer::resetBase() { |
| for (auto& slice : mCurrentSlicedBucket) { |
| for (auto& interval : slice.second) { |
| interval.hasBase = false; |
| } |
| } |
| mHasGlobalBase = false; |
| } |
| |
| // Handle active state change. Active state change is treated like a condition change: |
| // - drop bucket if active state change event arrives too late |
| // - if condition is true, pull data on active state changes |
| // - ConditionTimer tracks changes based on AND of condition and active state. |
| void ValueMetricProducer::onActiveStateChangedLocked(const int64_t& eventTimeNs) { |
| bool isEventTooLate = eventTimeNs < mCurrentBucketStartTimeNs; |
| if (ConditionState::kTrue == mCondition && isEventTooLate) { |
| // Drop bucket because event arrived too late, ie. we are missing data for this bucket. |
| invalidateCurrentBucket(); |
| } |
| |
| // Call parent method once we've verified the validity of current bucket. |
| MetricProducer::onActiveStateChangedLocked(eventTimeNs); |
| |
| if (ConditionState::kTrue != mCondition) { |
| return; |
| } |
| |
| // Pull on active state changes. |
| if (!isEventTooLate) { |
| if (mIsPulled) { |
| pullAndMatchEventsLocked(eventTimeNs, mCondition); |
| } |
| // When active state changes from true to false, clear diff base but don't |
| // reset other counters as we may accumulate more value in the bucket. |
| if (mUseDiff && !mIsActive) { |
| resetBase(); |
| } |
| } |
| |
| flushIfNeededLocked(eventTimeNs); |
| |
| // Let condition timer know of new active state. |
| mConditionTimer.onConditionChanged(mIsActive, eventTimeNs); |
| } |
| |
| void ValueMetricProducer::onConditionChangedLocked(const bool condition, |
| const int64_t eventTimeNs) { |
| ConditionState newCondition = condition ? ConditionState::kTrue : ConditionState::kFalse; |
| bool isEventTooLate = eventTimeNs < mCurrentBucketStartTimeNs; |
| |
| if (mIsActive) { |
| if (isEventTooLate) { |
| VLOG("Skip event due to late arrival: %lld vs %lld", (long long)eventTimeNs, |
| (long long)mCurrentBucketStartTimeNs); |
| StatsdStats::getInstance().noteConditionChangeInNextBucket(mMetricId); |
| invalidateCurrentBucket(); |
| } else { |
| if (mCondition == ConditionState::kUnknown) { |
| // If the condition was unknown, we mark the bucket as invalid since the bucket will |
| // contain partial data. For instance, the condition change might happen close to |
| // the end of the bucket and we might miss lots of data. |
| // |
| // We still want to pull to set the base. |
| invalidateCurrentBucket(); |
| } |
| |
| // Pull on condition changes. |
| bool conditionChanged = |
| (mCondition == ConditionState::kTrue && newCondition == ConditionState::kFalse) |
| || (mCondition == ConditionState::kFalse && |
| newCondition == ConditionState::kTrue); |
| // We do not need to pull when we go from unknown to false. |
| // |
| // We also pull if the condition was already true in order to be able to flush the |
| // bucket at the end if needed. |
| // |
| // onConditionChangedLocked might happen on bucket boundaries if this is called before |
| // #onDataPulled. |
| if (mIsPulled && (conditionChanged || condition)) { |
| pullAndMatchEventsLocked(eventTimeNs, newCondition); |
| } |
| |
| // When condition change from true to false, clear diff base but don't |
| // reset other counters as we may accumulate more value in the bucket. |
| if (mUseDiff && mCondition == ConditionState::kTrue |
| && newCondition == ConditionState::kFalse) { |
| resetBase(); |
| } |
| } |
| } |
| |
| mCondition = isEventTooLate ? initialCondition(mConditionTrackerIndex) : newCondition; |
| |
| if (mIsActive) { |
| flushIfNeededLocked(eventTimeNs); |
| mConditionTimer.onConditionChanged(mCondition, eventTimeNs); |
| } |
| } |
| |
| void ValueMetricProducer::pullAndMatchEventsLocked(const int64_t timestampNs, |
| ConditionState condition) { |
| vector<std::shared_ptr<LogEvent>> allData; |
| if (!mPullerManager->Pull(mPullTagId, &allData)) { |
| ALOGE("Stats puller failed for tag: %d at %lld", mPullTagId, (long long)timestampNs); |
| invalidateCurrentBucket(); |
| return; |
| } |
| |
| accumulateEvents(allData, timestampNs, timestampNs, condition); |
| } |
| |
| int64_t ValueMetricProducer::calcPreviousBucketEndTime(const int64_t currentTimeNs) { |
| return mTimeBaseNs + ((currentTimeNs - mTimeBaseNs) / mBucketSizeNs) * mBucketSizeNs; |
| } |
| |
| // By design, statsd pulls data at bucket boundaries using AlarmManager. These pulls are likely |
| // to be delayed. Other events like condition changes or app upgrade which are not based on |
| // AlarmManager might have arrived earlier and close the bucket. |
| void ValueMetricProducer::onDataPulled(const std::vector<std::shared_ptr<LogEvent>>& allData, |
| bool pullSuccess, int64_t originalPullTimeNs) { |
| std::lock_guard<std::mutex> lock(mMutex); |
| if (mCondition == ConditionState::kTrue) { |
| // If the pull failed, we won't be able to compute a diff. |
| if (!pullSuccess) { |
| invalidateCurrentBucket(); |
| } else { |
| bool isEventLate = originalPullTimeNs < getCurrentBucketEndTimeNs(); |
| if (isEventLate) { |
| // If the event is late, we are in the middle of a bucket. Just |
| // process the data without trying to snap the data to the nearest bucket. |
| accumulateEvents(allData, originalPullTimeNs, originalPullTimeNs, mCondition); |
| } else { |
| // For scheduled pulled data, the effective event time is snap to the nearest |
| // bucket end. In the case of waking up from a deep sleep state, we will |
| // attribute to the previous bucket end. If the sleep was long but not very |
| // long, we will be in the immediate next bucket. Previous bucket may get a |
| // larger number as we pull at a later time than real bucket end. |
| // |
| // If the sleep was very long, we skip more than one bucket before sleep. In |
| // this case, if the diff base will be cleared and this new data will serve as |
| // new diff base. |
| int64_t bucketEndTime = calcPreviousBucketEndTime(originalPullTimeNs) - 1; |
| StatsdStats::getInstance().noteBucketBoundaryDelayNs( |
| mMetricId, originalPullTimeNs - bucketEndTime); |
| accumulateEvents(allData, originalPullTimeNs, bucketEndTime, mCondition); |
| } |
| } |
| } |
| |
| // We can probably flush the bucket. Since we used bucketEndTime when calling |
| // #onMatchedLogEventInternalLocked, the current bucket will not have been flushed. |
| flushIfNeededLocked(originalPullTimeNs); |
| } |
| |
| void ValueMetricProducer::accumulateEvents(const std::vector<std::shared_ptr<LogEvent>>& allData, |
| int64_t originalPullTimeNs, int64_t eventElapsedTimeNs, |
| ConditionState condition) { |
| bool isEventLate = eventElapsedTimeNs < mCurrentBucketStartTimeNs; |
| if (isEventLate) { |
| VLOG("Skip bucket end pull due to late arrival: %lld vs %lld", |
| (long long)eventElapsedTimeNs, (long long)mCurrentBucketStartTimeNs); |
| StatsdStats::getInstance().noteLateLogEventSkipped(mMetricId); |
| invalidateCurrentBucket(); |
| return; |
| } |
| |
| const int64_t pullDelayNs = getElapsedRealtimeNs() - originalPullTimeNs; |
| StatsdStats::getInstance().notePullDelay(mPullTagId, pullDelayNs); |
| if (pullDelayNs > mMaxPullDelayNs) { |
| ALOGE("Pull finish too late for atom %d, longer than %lld", mPullTagId, |
| (long long)mMaxPullDelayNs); |
| StatsdStats::getInstance().notePullExceedMaxDelay(mPullTagId); |
| // We are missing one pull from the bucket which means we will not have a complete view of |
| // what's going on. |
| invalidateCurrentBucket(); |
| 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(); |
| if (mEventMatcherWizard->matchLogEvent(localCopy, mWhatMatcherIndex) == |
| MatchingState::kMatched) { |
| localCopy.setElapsedTimestampNs(eventElapsedTimeNs); |
| onMatchedLogEventLocked(mWhatMatcherIndex, localCopy); |
| } |
| } |
| // If the new pulled data does not contains some keys we track in our intervals, we need to |
| // reset the base. |
| for (auto& slice : mCurrentSlicedBucket) { |
| bool presentInPulledData = mMatchedMetricDimensionKeys.find(slice.first) |
| != mMatchedMetricDimensionKeys.end(); |
| if (!presentInPulledData) { |
| for (auto& interval : slice.second) { |
| interval.hasBase = false; |
| } |
| } |
| } |
| mMatchedMetricDimensionKeys.clear(); |
| mHasGlobalBase = true; |
| |
| // If we reach the guardrail, we might have dropped some data which means the bucket is |
| // incomplete. |
| // |
| // The base also needs to be reset. If we do not have the full data, we might |
| // incorrectly compute the diff when mUseZeroDefaultBase is true since an existing key |
| // might be missing from mCurrentSlicedBucket. |
| if (hasReachedGuardRailLimit()) { |
| invalidateCurrentBucket(); |
| mCurrentSlicedBucket.clear(); |
| } |
| } |
| |
| void ValueMetricProducer::dumpStatesLocked(FILE* out, bool verbose) const { |
| if (mCurrentSlicedBucket.size() == 0) { |
| return; |
| } |
| |
| fprintf(out, "ValueMetric %lld dimension size %lu\n", (long long)mMetricId, |
| (unsigned long)mCurrentSlicedBucket.size()); |
| if (verbose) { |
| for (const auto& it : mCurrentSlicedBucket) { |
| for (const auto& interval : it.second) { |
| fprintf(out, "\t(what)%s\t(condition)%s (value)%s\n", |
| it.first.getDimensionKeyInWhat().toString().c_str(), |
| it.first.getDimensionKeyInCondition().toString().c_str(), |
| interval.value.toString().c_str()); |
| } |
| } |
| } |
| } |
| |
| bool ValueMetricProducer::hasReachedGuardRailLimit() const { |
| return mCurrentSlicedBucket.size() >= mDimensionHardLimit; |
| } |
| |
| bool ValueMetricProducer::hitGuardRailLocked(const MetricDimensionKey& newKey) { |
| // ===========GuardRail============== |
| // 1. Report the tuple count if the tuple count > soft limit |
| if (mCurrentSlicedBucket.find(newKey) != mCurrentSlicedBucket.end()) { |
| return false; |
| } |
| if (mCurrentSlicedBucket.size() > mDimensionSoftLimit - 1) { |
| size_t newTupleCount = mCurrentSlicedBucket.size() + 1; |
| StatsdStats::getInstance().noteMetricDimensionSize(mConfigKey, mMetricId, newTupleCount); |
| // 2. Don't add more tuples, we are above the allowed threshold. Drop the data. |
| if (hasReachedGuardRailLimit()) { |
| ALOGE("ValueMetric %lld dropping data for dimension key %s", (long long)mMetricId, |
| newKey.toString().c_str()); |
| StatsdStats::getInstance().noteHardDimensionLimitReached(mMetricId); |
| return true; |
| } |
| } |
| |
| return false; |
| } |
| |
| bool ValueMetricProducer::hitFullBucketGuardRailLocked(const MetricDimensionKey& newKey) { |
| // ===========GuardRail============== |
| // 1. Report the tuple count if the tuple count > soft limit |
| if (mCurrentFullBucket.find(newKey) != mCurrentFullBucket.end()) { |
| return false; |
| } |
| if (mCurrentFullBucket.size() > mDimensionSoftLimit - 1) { |
| size_t newTupleCount = mCurrentFullBucket.size() + 1; |
| // 2. Don't add more tuples, we are above the allowed threshold. Drop the data. |
| if (newTupleCount > mDimensionHardLimit) { |
| ALOGE("ValueMetric %lld dropping data for full bucket dimension key %s", |
| (long long)mMetricId, |
| newKey.toString().c_str()); |
| return true; |
| } |
| } |
| |
| return false; |
| } |
| |
| bool getDoubleOrLong(const LogEvent& event, const Matcher& matcher, Value& ret) { |
| for (const FieldValue& value : event.getValues()) { |
| if (value.mField.matches(matcher)) { |
| switch (value.mValue.type) { |
| case INT: |
| ret.setLong(value.mValue.int_value); |
| break; |
| case LONG: |
| ret.setLong(value.mValue.long_value); |
| break; |
| case FLOAT: |
| ret.setDouble(value.mValue.float_value); |
| break; |
| case DOUBLE: |
| ret.setDouble(value.mValue.double_value); |
| break; |
| default: |
| break; |
| } |
| return true; |
| } |
| } |
| return false; |
| } |
| |
| void ValueMetricProducer::onMatchedLogEventInternalLocked(const size_t matcherIndex, |
| const MetricDimensionKey& eventKey, |
| const ConditionKey& conditionKey, |
| bool condition, const LogEvent& event) { |
| int64_t eventTimeNs = event.GetElapsedTimestampNs(); |
| if (eventTimeNs < mCurrentBucketStartTimeNs) { |
| VLOG("Skip event due to late arrival: %lld vs %lld", (long long)eventTimeNs, |
| (long long)mCurrentBucketStartTimeNs); |
| return; |
| } |
| mMatchedMetricDimensionKeys.insert(eventKey); |
| |
| if (!mIsPulled) { |
| // We cannot flush without doing a pull first. |
| flushIfNeededLocked(eventTimeNs); |
| } |
| |
| // We should not accumulate the data for pushed metrics when the condition is false. |
| bool shouldSkipForPushMetric = !mIsPulled && !condition; |
| // For pulled metrics, there are two cases: |
| // - to compute diffs, we need to process all the state changes |
| // - for non-diffs metrics, we should ignore the data if the condition wasn't true. If we have a |
| // state change from |
| // + True -> True: we should process the data, it might be a bucket boundary |
| // + True -> False: we als need to process the data. |
| bool shouldSkipForPulledMetric = mIsPulled && !mUseDiff |
| && mCondition != ConditionState::kTrue; |
| if (shouldSkipForPushMetric || shouldSkipForPulledMetric) { |
| VLOG("ValueMetric skip event because condition is false"); |
| return; |
| } |
| |
| if (hitGuardRailLocked(eventKey)) { |
| return; |
| } |
| vector<Interval>& multiIntervals = mCurrentSlicedBucket[eventKey]; |
| if (multiIntervals.size() < mFieldMatchers.size()) { |
| VLOG("Resizing number of intervals to %d", (int)mFieldMatchers.size()); |
| multiIntervals.resize(mFieldMatchers.size()); |
| } |
| |
| // We only use anomaly detection under certain cases. |
| // N.B.: The anomaly detection cases were modified in order to fix an issue with value metrics |
| // containing multiple values. We tried to retain all previous behaviour, but we are unsure the |
| // previous behaviour was correct. At the time of the fix, anomaly detection had no owner. |
| // Whoever next works on it should look into the cases where it is triggered in this function. |
| // Discussion here: http://ag/6124370. |
| bool useAnomalyDetection = true; |
| |
| for (int i = 0; i < (int)mFieldMatchers.size(); i++) { |
| const Matcher& matcher = mFieldMatchers[i]; |
| Interval& interval = multiIntervals[i]; |
| interval.valueIndex = i; |
| Value value; |
| if (!getDoubleOrLong(event, matcher, value)) { |
| VLOG("Failed to get value %d from event %s", i, event.ToString().c_str()); |
| StatsdStats::getInstance().noteBadValueType(mMetricId); |
| return; |
| } |
| interval.seenNewData = true; |
| |
| if (mUseDiff) { |
| if (!interval.hasBase) { |
| if (mHasGlobalBase && mUseZeroDefaultBase) { |
| // The bucket has global base. This key does not. |
| // Optionally use zero as base. |
| interval.base = (value.type == LONG ? ZERO_LONG : ZERO_DOUBLE); |
| interval.hasBase = true; |
| } else { |
| // no base. just update base and return. |
| interval.base = value; |
| interval.hasBase = true; |
| // If we're missing a base, do not use anomaly detection on incomplete data |
| useAnomalyDetection = false; |
| // Continue (instead of return) here in order to set interval.base and |
| // interval.hasBase for other intervals |
| continue; |
| } |
| } |
| Value diff; |
| switch (mValueDirection) { |
| case ValueMetric::INCREASING: |
| if (value >= interval.base) { |
| diff = value - interval.base; |
| } else if (mUseAbsoluteValueOnReset) { |
| diff = value; |
| } else { |
| VLOG("Unexpected decreasing value"); |
| StatsdStats::getInstance().notePullDataError(mPullTagId); |
| interval.base = value; |
| // If we've got bad data, do not use anomaly detection |
| useAnomalyDetection = false; |
| continue; |
| } |
| break; |
| case ValueMetric::DECREASING: |
| if (interval.base >= value) { |
| diff = interval.base - value; |
| } else if (mUseAbsoluteValueOnReset) { |
| diff = value; |
| } else { |
| VLOG("Unexpected increasing value"); |
| StatsdStats::getInstance().notePullDataError(mPullTagId); |
| interval.base = value; |
| // If we've got bad data, do not use anomaly detection |
| useAnomalyDetection = false; |
| continue; |
| } |
| break; |
| case ValueMetric::ANY: |
| diff = value - interval.base; |
| break; |
| default: |
| break; |
| } |
| interval.base = value; |
| value = diff; |
| } |
| |
| if (interval.hasValue) { |
| switch (mAggregationType) { |
| case ValueMetric::SUM: |
| // for AVG, we add up and take average when flushing the bucket |
| case ValueMetric::AVG: |
| interval.value += value; |
| break; |
| case ValueMetric::MIN: |
| interval.value = std::min(value, interval.value); |
| break; |
| case ValueMetric::MAX: |
| interval.value = std::max(value, interval.value); |
| break; |
| default: |
| break; |
| } |
| } else { |
| interval.value = value; |
| interval.hasValue = true; |
| } |
| interval.sampleSize += 1; |
| } |
| |
| // Only trigger the tracker if all intervals are correct |
| if (useAnomalyDetection) { |
| // TODO: propgate proper values down stream when anomaly support doubles |
| long wholeBucketVal = multiIntervals[0].value.long_value; |
| auto prev = mCurrentFullBucket.find(eventKey); |
| if (prev != mCurrentFullBucket.end()) { |
| wholeBucketVal += prev->second; |
| } |
| for (auto& tracker : mAnomalyTrackers) { |
| tracker->detectAndDeclareAnomaly(eventTimeNs, mCurrentBucketNum, mMetricId, eventKey, |
| wholeBucketVal); |
| } |
| } |
| } |
| |
| // For pulled metrics, we always need to make sure we do a pull before flushing the bucket |
| // if mCondition is true! |
| void ValueMetricProducer::flushIfNeededLocked(const int64_t& eventTimeNs) { |
| int64_t currentBucketEndTimeNs = getCurrentBucketEndTimeNs(); |
| if (eventTimeNs < currentBucketEndTimeNs) { |
| VLOG("eventTime is %lld, less than next bucket start time %lld", (long long)eventTimeNs, |
| (long long)(currentBucketEndTimeNs)); |
| return; |
| } |
| int64_t numBucketsForward = calcBucketsForwardCount(eventTimeNs); |
| int64_t nextBucketStartTimeNs = currentBucketEndTimeNs + (numBucketsForward - 1) * mBucketSizeNs; |
| flushCurrentBucketLocked(eventTimeNs, nextBucketStartTimeNs); |
| } |
| |
| int64_t ValueMetricProducer::calcBucketsForwardCount(const int64_t& eventTimeNs) const { |
| int64_t currentBucketEndTimeNs = getCurrentBucketEndTimeNs(); |
| if (eventTimeNs < currentBucketEndTimeNs) { |
| return 0; |
| } |
| return 1 + (eventTimeNs - currentBucketEndTimeNs) / mBucketSizeNs; |
| } |
| |
| void ValueMetricProducer::flushCurrentBucketLocked(const int64_t& eventTimeNs, |
| const int64_t& nextBucketStartTimeNs) { |
| if (mCondition == ConditionState::kUnknown) { |
| StatsdStats::getInstance().noteBucketUnknownCondition(mMetricId); |
| } |
| |
| int64_t numBucketsForward = calcBucketsForwardCount(eventTimeNs); |
| if (numBucketsForward > 1) { |
| VLOG("Skipping forward %lld buckets", (long long)numBucketsForward); |
| StatsdStats::getInstance().noteSkippedForwardBuckets(mMetricId); |
| // Something went wrong. Maybe the device was sleeping for a long time. It is better |
| // to mark the current bucket as invalid. The last pull might have been successful through. |
| invalidateCurrentBucketWithoutResetBase(); |
| } |
| |
| VLOG("finalizing bucket for %ld, dumping %d slices", (long)mCurrentBucketStartTimeNs, |
| (int)mCurrentSlicedBucket.size()); |
| int64_t fullBucketEndTimeNs = getCurrentBucketEndTimeNs(); |
| int64_t bucketEndTime = eventTimeNs < fullBucketEndTimeNs ? eventTimeNs : fullBucketEndTimeNs; |
| // Close the current bucket. |
| int64_t conditionTrueDuration = mConditionTimer.newBucketStart(bucketEndTime); |
| bool isBucketLargeEnough = bucketEndTime - mCurrentBucketStartTimeNs >= mMinBucketSizeNs; |
| if (isBucketLargeEnough && !mCurrentBucketIsInvalid) { |
| // The current bucket is large enough to keep. |
| for (const auto& slice : mCurrentSlicedBucket) { |
| ValueBucket bucket = buildPartialBucket(bucketEndTime, slice.second); |
| bucket.mConditionTrueNs = conditionTrueDuration; |
| // it will auto create new vector of ValuebucketInfo if the key is not found. |
| if (bucket.valueIndex.size() > 0) { |
| auto& bucketList = mPastBuckets[slice.first]; |
| bucketList.push_back(bucket); |
| } |
| } |
| } else { |
| mSkippedBuckets.emplace_back(mCurrentBucketStartTimeNs, bucketEndTime); |
| } |
| |
| appendToFullBucket(eventTimeNs, fullBucketEndTimeNs); |
| initCurrentSlicedBucket(nextBucketStartTimeNs); |
| // Update the condition timer again, in case we skipped buckets. |
| mConditionTimer.newBucketStart(nextBucketStartTimeNs); |
| mCurrentBucketNum += numBucketsForward; |
| } |
| |
| ValueBucket ValueMetricProducer::buildPartialBucket(int64_t bucketEndTime, |
| const std::vector<Interval>& intervals) { |
| ValueBucket bucket; |
| bucket.mBucketStartNs = mCurrentBucketStartTimeNs; |
| bucket.mBucketEndNs = bucketEndTime; |
| for (const auto& interval : intervals) { |
| if (interval.hasValue) { |
| // skip the output if the diff is zero |
| if (mSkipZeroDiffOutput && mUseDiff && interval.value.isZero()) { |
| continue; |
| } |
| bucket.valueIndex.push_back(interval.valueIndex); |
| if (mAggregationType != ValueMetric::AVG) { |
| bucket.values.push_back(interval.value); |
| } else { |
| double sum = interval.value.type == LONG ? (double)interval.value.long_value |
| : interval.value.double_value; |
| bucket.values.push_back(Value((double)sum / interval.sampleSize)); |
| } |
| } |
| } |
| return bucket; |
| } |
| |
| void ValueMetricProducer::initCurrentSlicedBucket(int64_t nextBucketStartTimeNs) { |
| StatsdStats::getInstance().noteBucketCount(mMetricId); |
| // Cleanup data structure to aggregate values. |
| for (auto it = mCurrentSlicedBucket.begin(); it != mCurrentSlicedBucket.end();) { |
| bool obsolete = true; |
| for (auto& interval : it->second) { |
| interval.hasValue = false; |
| interval.sampleSize = 0; |
| if (interval.seenNewData) { |
| obsolete = false; |
| } |
| interval.seenNewData = false; |
| } |
| |
| if (obsolete) { |
| it = mCurrentSlicedBucket.erase(it); |
| } else { |
| it++; |
| } |
| } |
| |
| mCurrentBucketIsInvalid = false; |
| // If we do not have a global base when the condition is true, |
| // we will have incomplete bucket for the next bucket. |
| if (mUseDiff && !mHasGlobalBase && mCondition) { |
| mCurrentBucketIsInvalid = false; |
| } |
| mCurrentBucketStartTimeNs = nextBucketStartTimeNs; |
| VLOG("metric %lld: new bucket start time: %lld", (long long)mMetricId, |
| (long long)mCurrentBucketStartTimeNs); |
| } |
| |
| void ValueMetricProducer::appendToFullBucket(int64_t eventTimeNs, int64_t fullBucketEndTimeNs) { |
| bool isFullBucketReached = eventTimeNs > fullBucketEndTimeNs; |
| if (mCurrentBucketIsInvalid) { |
| if (isFullBucketReached) { |
| // If the bucket is invalid, we ignore the full bucket since it contains invalid data. |
| mCurrentFullBucket.clear(); |
| } |
| // Current bucket is invalid, we do not add it to the full bucket. |
| return; |
| } |
| |
| if (isFullBucketReached) { // If full bucket, send to anomaly tracker. |
| // Accumulate partial buckets with current value and then send to anomaly tracker. |
| if (mCurrentFullBucket.size() > 0) { |
| for (const auto& slice : mCurrentSlicedBucket) { |
| if (hitFullBucketGuardRailLocked(slice.first)) { |
| continue; |
| } |
| // TODO: fix this when anomaly can accept double values |
| auto& interval = slice.second[0]; |
| if (interval.hasValue) { |
| mCurrentFullBucket[slice.first] += interval.value.long_value; |
| } |
| } |
| for (const auto& slice : mCurrentFullBucket) { |
| for (auto& tracker : mAnomalyTrackers) { |
| if (tracker != nullptr) { |
| tracker->addPastBucket(slice.first, slice.second, mCurrentBucketNum); |
| } |
| } |
| } |
| mCurrentFullBucket.clear(); |
| } else { |
| // Skip aggregating the partial buckets since there's no previous partial bucket. |
| for (const auto& slice : mCurrentSlicedBucket) { |
| for (auto& tracker : mAnomalyTrackers) { |
| if (tracker != nullptr) { |
| // TODO: fix this when anomaly can accept double values |
| auto& interval = slice.second[0]; |
| if (interval.hasValue) { |
| tracker->addPastBucket(slice.first, interval.value.long_value, |
| mCurrentBucketNum); |
| } |
| } |
| } |
| } |
| } |
| } else { |
| // Accumulate partial bucket. |
| for (const auto& slice : mCurrentSlicedBucket) { |
| // TODO: fix this when anomaly can accept double values |
| auto& interval = slice.second[0]; |
| if (interval.hasValue) { |
| mCurrentFullBucket[slice.first] += interval.value.long_value; |
| } |
| } |
| } |
| } |
| |
| size_t ValueMetricProducer::byteSizeLocked() const { |
| size_t totalSize = 0; |
| for (const auto& pair : mPastBuckets) { |
| totalSize += pair.second.size() * kBucketSize; |
| } |
| return totalSize; |
| } |
| |
| } // namespace statsd |
| } // namespace os |
| } // namespace android |
