cmds/statsd/src/metrics/DurationMetricProducer.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 true
#include "DurationMetricProducer.h"
#include "Log.h"
#include "stats_util.h"

#include <cutils/log.h>
#include <limits.h>
#include <stdlib.h>

using std::string;
using std::unordered_map;
using std::vector;

namespace android {
namespace os {
namespace statsd {

DurationMetricProducer::DurationMetricProducer(const DurationMetric& metric,
                                               const int conditionIndex, const size_t startIndex,
                                               const size_t stopIndex, const size_t stopAllIndex,
                                               const sp<ConditionWizard>& wizard)
    // TODO: Pass in the start time from MetricsManager, instead of calling time() here.
    : MetricProducer(time(nullptr) * NANO_SECONDS_IN_A_SECOND, conditionIndex, wizard),
      mMetric(metric),
      mStartIndex(startIndex),
      mStopIndex(stopIndex),
      mStopAllIndex(stopAllIndex) {
    // TODO: The following boiler plate code appears in all MetricProducers, but we can't abstract
    // them in the base class, because the proto generated CountMetric, and DurationMetric are
    // not related. Maybe we should add a template in the future??
    if (metric.has_bucket() && metric.bucket().has_bucket_size_millis()) {
        mBucketSizeNs = metric.bucket().bucket_size_millis() * 1000000;
    } else {
        mBucketSizeNs = LLONG_MAX;
    }

    // TODO: use UidMap if uid->pkg_name is required
    mDimension.insert(mDimension.begin(), metric.dimension().begin(), metric.dimension().end());

    if (metric.links().size() > 0) {
        mConditionLinks.insert(mConditionLinks.begin(), metric.links().begin(),
                               metric.links().end());
        mConditionSliced = true;
    }

    VLOG("metric %lld created. bucket size %lld start_time: %lld", metric.metric_id(),
         (long long)mBucketSizeNs, (long long)mStartTimeNs);
}

DurationMetricProducer::~DurationMetricProducer() {
    VLOG("~DurationMetric() called");
}

void DurationMetricProducer::finish() {
    // TODO: write the StatsLogReport to dropbox using
    // DropboxWriter.
}

void DurationMetricProducer::onSlicedConditionMayChange() {
    VLOG("Metric %lld onSlicedConditionMayChange", mMetric.metric_id());
    // Now for each of the on-going event, check if the condition has changed for them.
    for (auto& pair : mCurrentSlicedDuration) {
        VLOG("Metric %lld current %s state: %d", mMetric.metric_id(), pair.first.c_str(),
             pair.second.state);
        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, time(nullptr) * 1000000000);
    }
}

void DurationMetricProducer::onConditionChanged(const bool conditionMet) {
    VLOG("Metric %lld onConditionChanged", mMetric.metric_id());
    mCondition = conditionMet;
    // TODO: need to populate the condition change time from the event which triggers the condition
    // change, instead of using current time.
    for (auto& pair : mCurrentSlicedDuration) {
        noteConditionChanged(pair.first, conditionMet, time(nullptr) * 1000000000);
    }
}

static void addDurationBucketsToReport(StatsLogReport_DurationMetricDataWrapper& wrapper,
                                       const vector<KeyValuePair>& key,
                                       const vector<DurationBucketInfo>& buckets) {
    DurationMetricData* data = wrapper.add_data();
    for (const auto& kv : key) {
        data->add_dimension()->CopyFrom(kv);
    }
    for (const auto& bucket : buckets) {
        data->add_bucket_info()->CopyFrom(bucket);
        VLOG("\t bucket [%lld - %lld] count: %lld", bucket.start_bucket_nanos(),
             bucket.end_bucket_nanos(), bucket.duration_nanos());
    }
}

StatsLogReport DurationMetricProducer::onDumpReport() {
    VLOG("metric %lld dump report now...", mMetric.metric_id());
    StatsLogReport report;
    report.set_metric_id(mMetric.metric_id());
    report.set_start_report_nanos(mStartTimeNs);
    // Dump current bucket if it's stale.
    // If current bucket is still on-going, don't force dump current bucket.
    // In finish(), We can force dump current bucket.
    flushDurationIfNeeded(time(nullptr) * NANO_SECONDS_IN_A_SECOND);
    report.set_end_report_nanos(mCurrentBucketStartTimeNs);

    StatsLogReport_DurationMetricDataWrapper* wrapper = report.mutable_duration_metrics();
    for (const auto& pair : mPastBuckets) {
        const HashableDimensionKey& hashableKey = pair.first;
        auto it = mDimensionKeyMap.find(hashableKey);
        if (it == mDimensionKeyMap.end()) {
            ALOGW("Dimension key %s not found?!?! skip...", hashableKey.c_str());
            continue;
        }
        VLOG("  dimension key %s", hashableKey.c_str());
        addDurationBucketsToReport(*wrapper, it->second, pair.second);
    }
    return report;
};

void DurationMetricProducer::onMatchedLogEvent(const size_t matcherIndex, const LogEvent& event) {
    if (event.GetTimestampNs() < mStartTimeNs) {
        return;
    }

    flushDurationIfNeeded(event.GetTimestampNs());

    if (matcherIndex == mStopAllIndex) {
        noteStopAll(event.GetTimestampNs());
        return;
    }

    HashableDimensionKey hashableKey;
    if (mDimension.size() > 0) {
        // hook up sliced counter with AnomalyMonitor.
        vector<KeyValuePair> key = getDimensionKey(event, mDimension);
        hashableKey = getHashableKey(key);
        // Add the HashableDimensionKey->DimensionKey to the map, because StatsLogReport expects
        // vector<KeyValuePair>.
        if (mDimensionKeyMap.find(hashableKey) == mDimensionKeyMap.end()) {
            mDimensionKeyMap[hashableKey] = key;
        }
    } else {
        hashableKey = DEFAULT_DIMENSION_KEY;
    }

    if (mCurrentSlicedDuration.find(hashableKey) == mCurrentSlicedDuration.end() &&
        mConditionSliced) {
        // add the durationInfo for the current bucket.
        auto& durationInfo = mCurrentSlicedDuration[hashableKey];
        auto& conditionKeys = durationInfo.conditionKeys;
        // get and cache the keys for query condition.
        for (const auto& link : mConditionLinks) {
            HashableDimensionKey conditionKey = getDimensionKeyForCondition(event, link);
            conditionKeys[link.condition()] = conditionKey;
        }
    }

    bool conditionMet;
    if (mConditionSliced) {
        const auto& conditionKeys = mCurrentSlicedDuration[hashableKey].conditionKeys;
        conditionMet =
                mWizard->query(mConditionTrackerIndex, conditionKeys) == ConditionState::kTrue;
    } else {
        conditionMet = mCondition;
    }

    if (matcherIndex == mStartIndex) {
        VLOG("Metric %lld Key: %s Start, Condition %d", mMetric.metric_id(), hashableKey.c_str(),
             conditionMet);
        noteStart(hashableKey, conditionMet, event.GetTimestampNs());
    } else if (matcherIndex == mStopIndex) {
        VLOG("Metric %lld Key: %s Stop, Condition %d", mMetric.metric_id(), hashableKey.c_str(),
             conditionMet);
        noteStop(hashableKey, event.GetTimestampNs());
    }
}

void DurationMetricProducer::noteConditionChanged(const HashableDimensionKey& key,
                                                  const bool conditionMet,
                                                  const uint64_t eventTime) {
    flushDurationIfNeeded(eventTime);

    auto it = mCurrentSlicedDuration.find(key);
    if (it == mCurrentSlicedDuration.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 =
                        updateDuration(it->second.lastDuration,
                                       eventTime - it->second.lastStartTime, mMetric.type());
                VLOG("Metric %lld Key: %s Paused because condition is false ", mMetric.metric_id(),
                     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 = eventTime;
                VLOG("Metric %lld Key: %s Paused->Started", mMetric.metric_id(), key.c_str());
            }
            break;
    }
}

void DurationMetricProducer::noteStart(const HashableDimensionKey& key, const bool conditionMet,
                                       const uint64_t eventTime) {
    // this will add an empty bucket for this key if it didn't exist before.
    DurationInfo& duration = mCurrentSlicedDuration[key];

    switch (duration.state) {
        case kStarted:
            // It's safe to do nothing here. even if condition is not true, it means we are about
            // to receive the condition change event.
            break;
        case kPaused:
            // Safe to do nothing here. kPaused is waiting for the condition change.
            break;
        case kStopped:
            if (!conditionMet) {
                // event started, but we need to wait for the condition to become true.
                duration.state = DurationState::kPaused;
                break;
            }
            duration.state = DurationState::kStarted;
            duration.lastStartTime = eventTime;
            break;
    }
}

void DurationMetricProducer::noteStop(const HashableDimensionKey& key, const uint64_t eventTime) {
    if (mCurrentSlicedDuration.find(key) == mCurrentSlicedDuration.end()) {
        // we didn't see a start event before. do nothing.
        return;
    }
    DurationInfo& duration = mCurrentSlicedDuration[key];

    switch (duration.state) {
        case DurationState::kStopped:
            // already stopped, do nothing.
            break;
        case DurationState::kStarted: {
            duration.state = DurationState::kStopped;
            int64_t durationTime = eventTime - duration.lastStartTime;
            VLOG("Metric %lld, key %s, Stop %lld %lld %lld", mMetric.metric_id(), key.c_str(),
                 (long long)duration.lastStartTime, (long long)eventTime, (long long)durationTime);
            duration.lastDuration =
                    updateDuration(duration.lastDuration, durationTime, mMetric.type());
            VLOG("  record duration: %lld ", (long long)duration.lastDuration);
            break;
        }
        case DurationState::kPaused: {
            duration.state = DurationState::kStopped;
            break;
        }
    }
}

int64_t DurationMetricProducer::updateDuration(const int64_t lastDuration,
                                               const int64_t durationTime,
                                               const DurationMetric_AggregationType type) {
    int64_t result = lastDuration;
    switch (type) {
        case DurationMetric_AggregationType_DURATION_SUM:
            result += durationTime;
            break;
        case DurationMetric_AggregationType_DURATION_MAX_SPARSE:
            if (lastDuration < durationTime) {
                result = durationTime;
            }
            break;
        case DurationMetric_AggregationType_DURATION_MIN_SPARSE:
            if (lastDuration > durationTime) {
                result = durationTime;
            }
            break;
    }
    return result;
}

void DurationMetricProducer::noteStopAll(const uint64_t eventTime) {
    for (auto& duration : mCurrentSlicedDuration) {
        noteStop(duration.first, eventTime);
    }
}

// When a new matched event comes in, we check if event falls into the current
// bucket. If not, flush the old counter to past buckets and initialize the current buckt.
void DurationMetricProducer::flushDurationIfNeeded(const uint64_t eventTime) {
    if (mCurrentBucketStartTimeNs + mBucketSizeNs > eventTime) {
        return;
    }

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

    DurationBucketInfo info;
    uint64_t endTime = mCurrentBucketStartTimeNs + mBucketSizeNs;
    info.set_start_bucket_nanos(mCurrentBucketStartTimeNs);
    info.set_end_bucket_nanos(endTime);

    uint64_t oldBucketStartTimeNs = mCurrentBucketStartTimeNs;
    mCurrentBucketStartTimeNs += (numBucketsForward)*mBucketSizeNs;
    VLOG("Metric %lld: new bucket start time: %lld", mMetric.metric_id(),
         (long long)mCurrentBucketStartTimeNs);

    for (auto it = mCurrentSlicedDuration.begin(); it != mCurrentSlicedDuration.end(); ++it) {
        int64_t finalDuration = it->second.lastDuration;
        if (it->second.state == kStarted) {
            // the event is still on-going, duration needs to be updated.
            int64_t durationTime = endTime - it->second.lastStartTime;
            finalDuration = updateDuration(it->second.lastDuration, durationTime, mMetric.type());
        }

        VLOG("  final duration for last bucket: %lld", (long long)finalDuration);

        // Don't record empty bucket.
        if (finalDuration != 0) {
            info.set_duration_nanos(finalDuration);
            // it will auto create new vector of CountbucketInfo if the key is not found.
            auto& bucketList = mPastBuckets[it->first];
            bucketList.push_back(info);
        }

        // if the event is still on-going, add the buckets between previous bucket and now. Because
        // the event has been going on across all the buckets in between.
        // |prev_bucket|...|..|...|now_bucket|
        if (it->second.state == kStarted) {
            for (int i = 1; i < numBucketsForward; i++) {
                DurationBucketInfo info;
                info.set_start_bucket_nanos(oldBucketStartTimeNs + mBucketSizeNs * i);
                info.set_end_bucket_nanos(endTime + mBucketSizeNs * i);
                info.set_duration_nanos(mBucketSizeNs);
                auto& bucketList = mPastBuckets[it->first];
                bucketList.push_back(info);
                VLOG("  add filling bucket with duration %lld", (long long)mBucketSizeNs);
            }
        }

        if (it->second.state == DurationState::kStopped) {
            // No need to keep buckets for events that were stopped before. If the event starts
            // again, we will add it back.
            mCurrentSlicedDuration.erase(it);
        } else {
            // for kPaused, and kStarted event, we will keep the buckets, and reset the start time
            // and duration.
            it->second.lastStartTime = mCurrentBucketStartTimeNs;
            it->second.lastDuration = 0;
        }
    }
}

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