diff options
5 files changed, 60 insertions, 61 deletions
diff --git a/cmds/statsd/src/metrics/DurationMetricProducer.cpp b/cmds/statsd/src/metrics/DurationMetricProducer.cpp index 0ee7dcdf3c2e..c8e6ccec07cd 100644 --- a/cmds/statsd/src/metrics/DurationMetricProducer.cpp +++ b/cmds/statsd/src/metrics/DurationMetricProducer.cpp @@ -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) { diff --git a/cmds/statsd/src/metrics/duration_helper/MaxDurationTracker.cpp b/cmds/statsd/src/metrics/duration_helper/MaxDurationTracker.cpp index 06e743daa090..e4b3693fb24d 100644 --- a/cmds/statsd/src/metrics/duration_helper/MaxDurationTracker.cpp +++ b/cmds/statsd/src/metrics/duration_helper/MaxDurationTracker.cpp @@ -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()) { diff --git a/cmds/statsd/src/metrics/duration_helper/OringDurationTracker.cpp b/cmds/statsd/src/metrics/duration_helper/OringDurationTracker.cpp index 29b6c8965ee6..76f8514178f8 100644 --- a/cmds/statsd/src/metrics/duration_helper/OringDurationTracker.cpp +++ b/cmds/statsd/src/metrics/duration_helper/OringDurationTracker.cpp @@ -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); diff --git a/cmds/statsd/tests/metrics/MaxDurationTracker_test.cpp b/cmds/statsd/tests/metrics/MaxDurationTracker_test.cpp index 9e169bbf10ef..d82ccfe6b43e 100644 --- a/cmds/statsd/tests/metrics/MaxDurationTracker_test.cpp +++ b/cmds/statsd/tests/metrics/MaxDurationTracker_test.cpp @@ -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.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.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(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, diff --git a/cmds/statsd/tests/metrics/OringDurationTracker_test.cpp b/cmds/statsd/tests/metrics/OringDurationTracker_test.cpp index f4edffd1af1e..54618b5fb588 100644 --- a/cmds/statsd/tests/metrics/OringDurationTracker_test.cpp +++ b/cmds/statsd/tests/metrics/OringDurationTracker_test.cpp @@ -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), |