cmds/statsd/src/metrics/duration_helper/MaxDurationTracker.cpp

/*
 * 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

#include "Log.h"
#include "MaxDurationTracker.h"
#include "guardrail/StatsdStats.h"

namespace android {
namespace os {
namespace statsd {

MaxDurationTracker::MaxDurationTracker(const ConfigKey& key, const string& name,
                                       const HashableDimensionKey& eventKey,
                                       sp<ConditionWizard> wizard, int conditionIndex, bool nesting,
                                       uint64_t currentBucketStartNs, uint64_t bucketSizeNs,
                                       const vector<sp<DurationAnomalyTracker>>& anomalyTrackers)
    : DurationTracker(key, name, eventKey, wizard, conditionIndex, nesting, currentBucketStartNs,
                      bucketSizeNs, anomalyTrackers) {
}

bool MaxDurationTracker::hitGuardRail(const HashableDimensionKey& newKey) {
    // ===========GuardRail==============
    if (mInfos.find(newKey) != mInfos.end()) {
        // if the key existed, we are good!
        return false;
    }
    // 1. Report the tuple count if the tuple count > soft limit
    if (mInfos.size() > StatsdStats::kDimensionKeySizeSoftLimit - 1) {
        size_t newTupleCount = mInfos.size() + 1;
        StatsdStats::getInstance().noteMetricDimensionSize(mConfigKey, mName + mEventKey.toString(),
                                                           newTupleCount);
        // 2. Don't add more tuples, we are above the allowed threshold. Drop the data.
        if (newTupleCount > StatsdStats::kDimensionKeySizeHardLimit) {
            ALOGE("MaxDurTracker %s dropping data for dimension key %s", mName.c_str(),
                  newKey.c_str());
            return true;
        }
    }
    return false;
}

void MaxDurationTracker::noteStart(const HashableDimensionKey& key, bool condition,
                                   const uint64_t eventTime, const ConditionKey& conditionKey) {
    // this will construct a new DurationInfo if this key didn't exist.
    if (hitGuardRail(key)) {
        return;
    }

    DurationInfo& duration = mInfos[key];
    duration.conditionKeys = conditionKey;
    VLOG("MaxDuration: key %s start condition %d", key.c_str(), condition);

    switch (duration.state) {
        case kStarted:
            duration.startCount++;
            break;
        case kPaused:
            duration.startCount++;
            break;
        case kStopped:
            if (!condition) {
                // event started, but we need to wait for the condition to become true.
                duration.state = DurationState::kPaused;
            } else {
                duration.state = DurationState::kStarted;
                duration.lastStartTime = eventTime;
            }
            duration.startCount = 1;
            break;
    }
}


void MaxDurationTracker::noteStop(const HashableDimensionKey& key, const uint64_t eventTime,
                                  bool forceStop) {
    declareAnomalyIfAlarmExpired(eventTime);
    VLOG("MaxDuration: key %s stop", key.c_str());
    if (mInfos.find(key) == mInfos.end()) {
        // we didn't see a start event before. do nothing.
        return;
    }
    DurationInfo& duration = mInfos[key];

    switch (duration.state) {
        case DurationState::kStopped:
            // already stopped, do nothing.
            break;
        case DurationState::kStarted: {
            duration.startCount--;
            if (forceStop || !mNested || duration.startCount <= 0) {
                duration.state = DurationState::kStopped;
                int64_t durationTime = eventTime - duration.lastStartTime;
                VLOG("Max, key %s, Stop %lld %lld %lld", key.c_str(),
                     (long long)duration.lastStartTime, (long long)eventTime,
                     (long long)durationTime);
                duration.lastDuration = duration.lastDuration + durationTime;
                VLOG("  record duration: %lld ", (long long)duration.lastDuration);
            }
            break;
        }
        case DurationState::kPaused: {
            duration.startCount--;
            if (forceStop || !mNested || duration.startCount <= 0) {
                duration.state = DurationState::kStopped;
            }
            break;
        }
    }

    if (duration.lastDuration > mDuration) {
        mDuration = duration.lastDuration;
        detectAndDeclareAnomaly(eventTime, mCurrentBucketNum, mDuration);
        VLOG("Max: new max duration: %lld", (long long)mDuration);
    }
    // Once an atom duration ends, we erase it. Next time, if we see another atom event with the
    // same name, they are still considered as different atom durations.
    if (duration.state == DurationState::kStopped) {
        mInfos.erase(key);
    }
}

void MaxDurationTracker::noteStopAll(const uint64_t eventTime) {
    std::set<HashableDimensionKey> keys;
    for (const auto& pair : mInfos) {
        keys.insert(pair.first);
    }
    for (auto& key : keys) {
        noteStop(key, eventTime, true);
    }
}

bool MaxDurationTracker::flushIfNeeded(
        uint64_t eventTime, unordered_map<HashableDimensionKey, vector<DurationBucket>>* output) {
    if (mCurrentBucketStartTimeNs + mBucketSizeNs > eventTime) {
        return false;
    }

    VLOG("MaxDurationTracker flushing.....");

    // adjust the bucket start time
    int numBucketsForward = (eventTime - mCurrentBucketStartTimeNs) / mBucketSizeNs;

    uint64_t endTime = mCurrentBucketStartTimeNs + mBucketSizeNs;

    DurationBucket info;
    info.mBucketStartNs = mCurrentBucketStartTimeNs;
    info.mBucketEndNs = endTime;
    info.mBucketNum = mCurrentBucketNum;

    uint64_t oldBucketStartTimeNs = mCurrentBucketStartTimeNs;
    mCurrentBucketStartTimeNs += (numBucketsForward)*mBucketSizeNs;

    bool hasOnGoingStartedEvent = false;  // a kStarted event last across bucket boundaries.
    bool hasPendingEvent =
            false;  // has either a kStarted or kPaused event across bucket boundaries
                    // meaning we need to carry them over to the new bucket.
    for (auto it = mInfos.begin(); it != mInfos.end(); ++it) {
        int64_t finalDuration = it->second.lastDuration;
        if (it->second.state == kStarted) {
            // the event is still on-going, duration needs to be updated.
            // |..lastDurationTime_recorded...last_start -----|bucket_end. We need to record the
            // duration between lastStartTime and bucketEnd.
            int64_t durationTime = endTime - it->second.lastStartTime;

            finalDuration += durationTime;
            VLOG("  unrecorded %lld -> %lld", (long long)(durationTime), (long long)finalDuration);
            // if the event is still on-going, we need to fill the buckets between prev_bucket and
            // now_bucket. |prev_bucket|...|..|...|now_bucket|
            hasOnGoingStartedEvent = true;
        }

        if (finalDuration > mDuration) {
            mDuration = finalDuration;
        }

        if (it->second.state == DurationState::kStopped) {
            // No need to keep buckets for events that were stopped before.
            mInfos.erase(it);
        } else {
            hasPendingEvent = true;
            // for kPaused, and kStarted event, we will keep track of them, and reset the start time
            // and duration.
            it->second.lastStartTime = mCurrentBucketStartTimeNs;
            it->second.lastDuration = 0;
        }
    }

    if (mDuration != 0) {
        info.mDuration = mDuration;
        (*output)[mEventKey].push_back(info);
        addPastBucketToAnomalyTrackers(info.mDuration, info.mBucketNum);
        VLOG("  final duration for last bucket: %lld", (long long)mDuration);
    }

    mDuration = 0;
    if (hasOnGoingStartedEvent) {
        for (int i = 1; i < numBucketsForward; i++) {
            DurationBucket info;
            info.mBucketStartNs = oldBucketStartTimeNs + mBucketSizeNs * i;
            info.mBucketEndNs = endTime + mBucketSizeNs * i;
            info.mBucketNum = mCurrentBucketNum + i;
            info.mDuration = mBucketSizeNs;
            (*output)[mEventKey].push_back(info);
            addPastBucketToAnomalyTrackers(info.mDuration, info.mBucketNum);
            VLOG("  filling gap bucket with duration %lld", (long long)mBucketSizeNs);
        }
    }

    mCurrentBucketNum += numBucketsForward;
    // If this tracker has no pending events, tell owner to remove.
    return !hasPendingEvent;
}

void MaxDurationTracker::onSlicedConditionMayChange(const uint64_t timestamp) {
    // Now for each of the on-going event, check if the condition has changed for them.
    for (auto& pair : mInfos) {
        if (pair.second.state == kStopped) {
            continue;
        }
        bool conditionMet = mWizard->query(mConditionTrackerIndex, pair.second.conditionKeys) ==
                            ConditionState::kTrue;
        VLOG("key: %s, condition: %d", pair.first.c_str(), conditionMet);
        noteConditionChanged(pair.first, conditionMet, timestamp);
    }
}

void MaxDurationTracker::onConditionChanged(bool condition, const uint64_t timestamp) {
    for (auto& pair : mInfos) {
        noteConditionChanged(pair.first, condition, timestamp);
    }
}

void MaxDurationTracker::noteConditionChanged(const HashableDimensionKey& key, bool conditionMet,
                                              const uint64_t timestamp) {
    declareAnomalyIfAlarmExpired(timestamp);
    auto it = mInfos.find(key);
    if (it == mInfos.end()) {
        return;
    }

    switch (it->second.state) {
        case kStarted:
            // if condition becomes false, kStarted -> kPaused. Record the current duration.
            if (!conditionMet) {
                it->second.state = DurationState::kPaused;
                it->second.lastDuration += (timestamp - it->second.lastStartTime);
                VLOG("MaxDurationTracker Key: %s Started->Paused ", key.c_str());
            }
            break;
        case kStopped:
            // nothing to do if it's stopped.
            break;
        case kPaused:
            // if condition becomes true, kPaused -> kStarted. and the start time is the condition
            // change time.
            if (conditionMet) {
                it->second.state = DurationState::kStarted;
                it->second.lastStartTime = timestamp;
                VLOG("MaxDurationTracker Key: %s Paused->Started", key.c_str());
            }
            break;
    }
    if (it->second.lastDuration > mDuration) {
        mDuration = it->second.lastDuration;
        detectAndDeclareAnomaly(timestamp, mCurrentBucketNum, mDuration);
    }
}

int64_t MaxDurationTracker::predictAnomalyTimestampNs(const DurationAnomalyTracker& anomalyTracker,
                                                      const uint64_t currentTimestamp) const {
    ALOGE("Max duration producer does not support anomaly timestamp prediction!!!");
    return currentTimestamp;
}

}  // namespace statsd
}  // namespace os
}  // namespace android