Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 09294efe authored by Yao Chen's avatar Yao Chen
Browse files

Fix some bugs in duration tracker. 

There are some bugs in the previous big anomaly detection cl, which I didn't catch.

Test: statsd_test
Change-Id: I2ca22e0f112e5cff8fb204c0c94141188659fdba
parent 7250622b

cmds/statsd/src/metrics/DurationMetricProducer.cpp

+2 −0
Original line number Diff line number Diff line
@@ -130,6 +130,7 @@ void DurationMetricProducer::finish() { 


void DurationMetricProducer::onSlicedConditionMayChange(const uint64_t eventTime) {

    VLOG("Metric %s onSlicedConditionMayChange", mMetric.name().c_str());

    flushIfNeeded(eventTime);

    // Now for each of the on-going event, check if the condition has changed for them.

    for (auto& pair : mCurrentSlicedDuration) {

        pair.second->onSlicedConditionMayChange(eventTime);
@@ -139,6 +140,7 @@ void DurationMetricProducer::onSlicedConditionMayChange(const uint64_t eventTime 
void DurationMetricProducer::onConditionChanged(const bool conditionMet, const uint64_t eventTime) {

    VLOG("Metric %s onConditionChanged", mMetric.name().c_str());

    mCondition = conditionMet;

    flushIfNeeded(eventTime);

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

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

+0 −4
Original line number Diff line number Diff line
@@ -34,7 +34,6 @@ MaxDurationTracker::MaxDurationTracker(const HashableDimensionKey& eventKey, 


void MaxDurationTracker::noteStart(const HashableDimensionKey& key, bool condition,

                                   const uint64_t eventTime, const ConditionKey& conditionKey) {

    flushIfNeeded(eventTime);

    // this will construct a new DurationInfo if this key didn't exist.

    DurationInfo& duration = mInfos[key];

    duration.conditionKeys = conditionKey;
@@ -63,7 +62,6 @@ void MaxDurationTracker::noteStart(const HashableDimensionKey& key, bool conditi 


void MaxDurationTracker::noteStop(const HashableDimensionKey& key, const uint64_t eventTime,

                                  bool forceStop) {

    flushIfNeeded(eventTime);

    declareAnomalyIfAlarmExpired(eventTime);

    VLOG("MaxDuration: key %s stop", key.c_str());

    if (mInfos.find(key) == mInfos.end()) {
@@ -85,7 +83,6 @@ void MaxDurationTracker::noteStop(const HashableDimensionKey& key, const uint64_ 
                     (long long)duration.lastStartTime, (long long)eventTime,

                     (long long)durationTime);

                duration.lastDuration = duration.lastDuration + durationTime;

                duration.lastStartTime = -1;

                VLOG("  record duration: %lld ", (long long)duration.lastDuration);

            }

            break;
@@ -223,7 +220,6 @@ void MaxDurationTracker::onConditionChanged(bool condition, const uint64_t times 


void MaxDurationTracker::noteConditionChanged(const HashableDimensionKey& key, bool conditionMet,

                                              const uint64_t timestamp) {

    flushIfNeeded(timestamp);

    declareAnomalyIfAlarmExpired(timestamp);

    auto it = mInfos.find(key);

    if (it == mInfos.end()) {

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

+4 −16
Original line number Diff line number Diff line
@@ -38,7 +38,6 @@ OringDurationTracker::OringDurationTracker(const HashableDimensionKey& eventKey, 


void OringDurationTracker::noteStart(const HashableDimensionKey& key, bool condition,

                                     const uint64_t eventTime, const ConditionKey& conditionKey) {

    flushIfNeeded(eventTime);

    if (condition) {

        if (mStarted.size() == 0) {

            mLastStartTime = eventTime;
@@ -59,7 +58,6 @@ void OringDurationTracker::noteStart(const HashableDimensionKey& key, bool condi 


void OringDurationTracker::noteStop(const HashableDimensionKey& key, const uint64_t timestamp,

                                    const bool stopAll) {

    flushIfNeeded(timestamp);

    declareAnomalyIfAlarmExpired(timestamp);

    VLOG("Oring: %s stop", key.c_str());

    auto it = mStarted.find(key);
@@ -72,7 +70,6 @@ void OringDurationTracker::noteStop(const HashableDimensionKey& key, const uint6 
        if (mStarted.empty()) {

            mDuration += (timestamp - mLastStartTime);

            detectAndDeclareAnomaly(timestamp, mCurrentBucketNum, mDuration);

            mLastStartTime = -1;

            VLOG("record duration %lld, total %lld ", (long long)timestamp - mLastStartTime,

                 (long long)mDuration);

        }
@@ -92,7 +89,6 @@ void OringDurationTracker::noteStop(const HashableDimensionKey& key, const uint6 
}



void OringDurationTracker::noteStopAll(const uint64_t timestamp) {

    flushIfNeeded(timestamp);

    declareAnomalyIfAlarmExpired(timestamp);

    if (!mStarted.empty()) {

        mDuration += (timestamp - mLastStartTime);
@@ -105,7 +101,6 @@ void OringDurationTracker::noteStopAll(const uint64_t timestamp) { 
    mStarted.clear();

    mPaused.clear();

    mConditionKeyMap.clear();

    mLastStartTime = -1;

}



bool OringDurationTracker::flushIfNeeded(uint64_t eventTime) {
@@ -122,7 +117,6 @@ bool OringDurationTracker::flushIfNeeded(uint64_t eventTime) { 
    // Process the current bucket.

    if (mStarted.size() > 0) {

        mDuration += (current_info.mBucketEndNs - mLastStartTime);

        mLastStartTime = current_info.mBucketEndNs;

    }

    if (mDuration > 0) {

        current_info.mDuration = mDuration;
@@ -138,17 +132,15 @@ bool OringDurationTracker::flushIfNeeded(uint64_t eventTime) { 
            info.mBucketEndNs = info.mBucketStartNs + mBucketSizeNs;

            info.mBucketNum = mCurrentBucketNum + i;

            info.mDuration = mBucketSizeNs;

            mLastStartTime = info.mBucketEndNs;

            if (info.mDuration > 0) {

                mBucket.push_back(info);

                addPastBucketToAnomalyTrackers(info.mDuration, info.mBucketNum);

                VLOG("  add filling bucket with duration %lld", (long long)info.mDuration);

        }

    }

    }

    mCurrentBucketStartTimeNs += numBucketsForward * mBucketSizeNs;

    mCurrentBucketNum += numBucketsForward;



    mLastStartTime = mCurrentBucketStartTimeNs;

    mDuration = 0;



    // if all stopped, then tell owner it's safe to remove this tracker.
@@ -156,7 +148,6 @@ bool OringDurationTracker::flushIfNeeded(uint64_t eventTime) { 
}



void OringDurationTracker::onSlicedConditionMayChange(const uint64_t timestamp) {

    flushIfNeeded(timestamp);

    declareAnomalyIfAlarmExpired(timestamp);

    vector<pair<HashableDimensionKey, int>> startedToPaused;

    vector<pair<HashableDimensionKey, int>> pausedToStarted;
@@ -179,8 +170,7 @@ void OringDurationTracker::onSlicedConditionMayChange(const uint64_t timestamp) 
        }



        if (mStarted.empty()) {

            mDuration = (timestamp - mLastStartTime);

            mLastStartTime = -1;

            mDuration += (timestamp - mLastStartTime);

            VLOG("Duration add %lld , to %lld ", (long long)(timestamp - mLastStartTime),

                 (long long)mDuration);

            detectAndDeclareAnomaly(timestamp, mCurrentBucketNum, mDuration);
@@ -222,13 +212,12 @@ void OringDurationTracker::onSlicedConditionMayChange(const uint64_t timestamp) 
}



void OringDurationTracker::onConditionChanged(bool condition, const uint64_t timestamp) {

    flushIfNeeded(timestamp);

    declareAnomalyIfAlarmExpired(timestamp);

    if (condition) {

        if (!mPaused.empty()) {

            VLOG("Condition true, all started");

            if (mStarted.empty()) {

                mLastStartTime = -1;

                mLastStartTime = timestamp;

            }

            if (mStarted.empty() && !mPaused.empty()) {

                startAnomalyAlarm(timestamp);
@@ -239,8 +228,7 @@ void OringDurationTracker::onConditionChanged(bool condition, const uint64_t tim 
    } else {

        if (!mStarted.empty()) {

            VLOG("Condition false, all paused");

            mDuration = (timestamp - mLastStartTime);

            mLastStartTime = -1;

            mDuration += (timestamp - mLastStartTime);

            mPaused.insert(mStarted.begin(), mStarted.end());

            mStarted.clear();

            detectAndDeclareAnomaly(timestamp, mCurrentBucketNum, mDuration);

cmds/statsd/tests/metrics/MaxDurationTracker_test.cpp

+10 −33
Original line number Diff line number Diff line
@@ -79,6 +79,7 @@ TEST(MaxDurationTrackerTest, TestStopAll) { 


    // Another event starts in this bucket.

    tracker.noteStart("2", true, bucketStartTimeNs + 20, key1);

    tracker.flushIfNeeded(bucketStartTimeNs + bucketSizeNs + 40);

    tracker.noteStopAll(bucketStartTimeNs + bucketSizeNs + 40);

    EXPECT_TRUE(tracker.mInfos.empty());

    EXPECT_EQ(1u, buckets.size());
@@ -108,20 +109,9 @@ TEST(MaxDurationTrackerTest, TestCrossBucketBoundary) { 
    // Starts again. Does not change anything.

    tracker.noteStart("", true, bucketStartTimeNs + bucketSizeNs + 1, key1);



    // Flushes at early 2nd bucket. The event still does not stop yet.

    tracker.flushIfNeeded(bucketStartTimeNs + bucketSizeNs + 1);

    EXPECT_EQ(1u, buckets.size());

    EXPECT_EQ((unsigned long long)(bucketSizeNs - 1), buckets[0].mDuration);



    // Flushes at the end of the 2nd bucket. The event still does not stop yet.

    tracker.flushIfNeeded(bucketStartTimeNs + (2 * bucketSizeNs));

    EXPECT_EQ(2u, buckets.size());

    EXPECT_EQ((unsigned long long)(bucketSizeNs - 1), buckets[0].mDuration);

    EXPECT_EQ((unsigned long long)bucketSizeNs, buckets[1].mDuration);



    // The event stops at early 4th bucket.

    tracker.flushIfNeeded(bucketStartTimeNs + (3 * bucketSizeNs) + 20);

    tracker.noteStop("", bucketStartTimeNs + (3 * bucketSizeNs) + 20, false /*stop all*/);

    tracker.flushIfNeeded(bucketStartTimeNs + (3 * bucketSizeNs) + 21);

    EXPECT_EQ(3u, buckets.size());

    EXPECT_EQ((unsigned long long)(bucketSizeNs - 1), buckets[0].mDuration);

    EXPECT_EQ((unsigned long long)bucketSizeNs, buckets[1].mDuration);
@@ -183,28 +173,14 @@ TEST(MaxDurationTrackerTest, TestMaxDurationWithCondition) { 
    EXPECT_TRUE(tracker.mAnomalyTrackers.empty());



    tracker.noteStart("2:maps", true, eventStartTimeNs, key1);

    tracker.onSlicedConditionMayChange(eventStartTimeNs + 2 * bucketSizeNs + 5);

    EXPECT_EQ(2u, buckets.size());

    EXPECT_EQ(bucketSizeNs - 1, buckets[0].mDuration);

    EXPECT_EQ(bucketSizeNs, buckets[1].mDuration);



    tracker.noteStop("2:maps", eventStartTimeNs + 2 * bucketSizeNs + durationTimeNs, false);

    EXPECT_EQ(2u, buckets.size());

    EXPECT_EQ(bucketSizeNs - 1, buckets[0].mDuration);

    EXPECT_EQ(bucketSizeNs, buckets[1].mDuration);

    EXPECT_TRUE(tracker.mInfos.empty());

    EXPECT_EQ(6LL, tracker.mDuration);

    tracker.onSlicedConditionMayChange(eventStartTimeNs + 5);



    tracker.noteStart("2:maps", false, eventStartTimeNs + 3 * bucketSizeNs + 10, key1);

    EXPECT_EQ(1u, tracker.mInfos.size());

    for (const auto& itr : tracker.mInfos) {

        EXPECT_EQ(DurationState::kPaused, itr.second.state);

        EXPECT_EQ(0LL, itr.second.lastDuration);

    }

    EXPECT_EQ(3u, buckets.size());

    EXPECT_EQ(bucketSizeNs - 1, buckets[0].mDuration);

    EXPECT_EQ(bucketSizeNs, buckets[1].mDuration);

    EXPECT_EQ(6ULL, buckets[2].mDuration);

    tracker.noteStop("2:maps", eventStartTimeNs + durationTimeNs, false);



    tracker.flushIfNeeded(bucketStartTimeNs + bucketSizeNs + 1);

    EXPECT_EQ(1u, buckets.size());

    EXPECT_EQ(5ULL, buckets[0].mDuration);

}



TEST(MaxDurationTrackerTest, TestAnomalyDetection) {
@@ -233,6 +209,7 @@ TEST(MaxDurationTrackerTest, TestAnomalyDetection) { 
    EXPECT_EQ(10LL, tracker.mDuration);



    tracker.noteStart("2", true, eventStartTimeNs + 20, key1);

    tracker.flushIfNeeded(eventStartTimeNs + 2 * bucketSizeNs + 3 * NS_PER_SEC);

    tracker.noteStop("2", eventStartTimeNs + 2 * bucketSizeNs + 3 * NS_PER_SEC, false);

    EXPECT_EQ((long long)(4 * NS_PER_SEC + 1LL), tracker.mDuration);

    EXPECT_EQ(anomalyTracker->mLastAlarmTimestampNs,

cmds/statsd/tests/metrics/OringDurationTracker_test.cpp

+44 −8
Original line number Diff line number Diff line
@@ -130,10 +130,10 @@ TEST(OringDurationTrackerTest, TestCrossBucketBoundary) { 


    tracker.noteStart("2:maps", true, eventStartTimeNs, key1);

    EXPECT_EQ((long long)eventStartTimeNs, tracker.mLastStartTime);

    tracker.flushIfNeeded(eventStartTimeNs + 2 * bucketSizeNs);

    tracker.noteStart("2:maps", true, eventStartTimeNs + 2 * bucketSizeNs, key1);

    EXPECT_EQ((long long)(bucketStartTimeNs + 2 * bucketSizeNs), tracker.mLastStartTime);



    tracker.flushIfNeeded(eventStartTimeNs + 2 * bucketSizeNs);

    EXPECT_EQ(2u, buckets.size());

    EXPECT_EQ(bucketSizeNs - 1, buckets[0].mDuration);

    EXPECT_EQ(bucketSizeNs, buckets[1].mDuration);
@@ -167,12 +167,47 @@ TEST(OringDurationTrackerTest, TestDurationConditionChange) { 


    tracker.noteStart("2:maps", true, eventStartTimeNs, key1);



    tracker.onSlicedConditionMayChange(eventStartTimeNs + 2 * bucketSizeNs + 5);

    tracker.noteStop("2:maps", eventStartTimeNs + 2 * bucketSizeNs + durationTimeNs, false);

    tracker.flushIfNeeded(bucketStartTimeNs + 2 * bucketSizeNs + durationTimeNs);

    EXPECT_EQ(2u, buckets.size());

    EXPECT_EQ(bucketSizeNs - 1, buckets[0].mDuration);

    EXPECT_EQ(bucketSizeNs, buckets[1].mDuration);

    tracker.onSlicedConditionMayChange(eventStartTimeNs + 5);



    tracker.noteStop("2:maps", eventStartTimeNs + durationTimeNs, false);



    tracker.flushIfNeeded(bucketStartTimeNs + bucketSizeNs + 1);

    EXPECT_EQ(1u, buckets.size());

    EXPECT_EQ(5ULL, buckets[0].mDuration);

}



TEST(OringDurationTrackerTest, TestDurationConditionChange2) {

    sp<MockConditionWizard> wizard = new NaggyMock<MockConditionWizard>();



    ConditionKey key1;

    key1["APP_BACKGROUND"] = "1:maps|";



    EXPECT_CALL(*wizard, query(_, key1))

            .Times(2)

            .WillOnce(Return(ConditionState::kFalse))

            .WillOnce(Return(ConditionState::kTrue));



    vector<DurationBucket> buckets;



    uint64_t bucketStartTimeNs = 10000000000;

    uint64_t eventStartTimeNs = bucketStartTimeNs + 1;

    uint64_t bucketSizeNs = 30 * 1000 * 1000 * 1000LL;

    uint64_t durationTimeNs = 2 * 1000;



    OringDurationTracker tracker("event", wizard, 1, false, bucketStartTimeNs, bucketSizeNs, {},

                                 buckets);



    tracker.noteStart("2:maps", true, eventStartTimeNs, key1);

    // condition to false; record duration 5n

    tracker.onSlicedConditionMayChange(eventStartTimeNs + 5);

    // condition to true.

    tracker.onSlicedConditionMayChange(eventStartTimeNs + 1000);

    // 2nd duration: 1000ns

    tracker.noteStop("2:maps", eventStartTimeNs + durationTimeNs, false);



    tracker.flushIfNeeded(bucketStartTimeNs + bucketSizeNs + 1);

    EXPECT_EQ(1u, buckets.size());

    EXPECT_EQ(1005ULL, buckets[0].mDuration);

}



TEST(OringDurationTrackerTest, TestDurationConditionChangeNested) {
@@ -242,6 +277,7 @@ TEST(OringDurationTrackerTest, TestPredictAnomalyTimestamp) { 
              tracker.predictAnomalyTimestampNs(*anomalyTracker, event1StartTimeNs));



    uint64_t event1StopTimeNs = eventStartTimeNs + bucketSizeNs + 10;

    tracker.flushIfNeeded(event1StopTimeNs);

    tracker.noteStop("1", event1StopTimeNs, false);

    EXPECT_EQ(1u, buckets.size());

    EXPECT_EQ(3ULL + bucketStartTimeNs + bucketSizeNs - eventStartTimeNs - 10,
@@ -290,7 +326,6 @@ TEST(OringDurationTrackerTest, TestAnomalyDetection) { 
    tracker.noteStop("", eventStartTimeNs + 10, false);

    EXPECT_EQ(anomalyTracker->mLastAlarmTimestampNs, -1);

    EXPECT_TRUE(tracker.mStarted.empty());

    EXPECT_EQ(-1LL, tracker.mLastStartTime);

    EXPECT_EQ(10LL, tracker.mDuration);



    EXPECT_EQ(0u, tracker.mStarted.size());
@@ -299,6 +334,7 @@ TEST(OringDurationTrackerTest, TestAnomalyDetection) { 
    EXPECT_EQ(1u, anomalyTracker->mAlarms.size());

    EXPECT_EQ((long long)(51ULL * NS_PER_SEC),

              (long long)(anomalyTracker->mAlarms.begin()->second->timestampSec * NS_PER_SEC));

    tracker.flushIfNeeded(eventStartTimeNs + 2 * bucketSizeNs + 25);

    tracker.noteStop("", eventStartTimeNs + 2 * bucketSizeNs + 25, false);

    EXPECT_EQ(anomalyTracker->getSumOverPastBuckets("event"), (long long)(bucketSizeNs));

    EXPECT_EQ((long long)(eventStartTimeNs + 2 * bucketSizeNs + 25),