Merge "Fix some bugs in duration tracker."
diff --git a/cmds/statsd/src/metrics/DurationMetricProducer.cpp b/cmds/statsd/src/metrics/DurationMetricProducer.cpp
index 0ee7dcd..c8e6cce 100644
--- a/cmds/statsd/src/metrics/DurationMetricProducer.cpp
+++ b/cmds/statsd/src/metrics/DurationMetricProducer.cpp
@@ -130,6 +130,7 @@
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::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 06e743d..e4b3693 100644
--- a/cmds/statsd/src/metrics/duration_helper/MaxDurationTracker.cpp
+++ b/cmds/statsd/src/metrics/duration_helper/MaxDurationTracker.cpp
@@ -34,7 +34,6 @@
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::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 @@
(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::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 29b6c89..76f8514 100644
--- a/cmds/statsd/src/metrics/duration_helper/OringDurationTracker.cpp
+++ b/cmds/statsd/src/metrics/duration_helper/OringDurationTracker.cpp
@@ -38,7 +38,6 @@
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::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 @@
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::noteStopAll(const uint64_t timestamp) {
- flushIfNeeded(timestamp);
declareAnomalyIfAlarmExpired(timestamp);
if (!mStarted.empty()) {
mDuration += (timestamp - mLastStartTime);
@@ -105,7 +101,6 @@
mStarted.clear();
mPaused.clear();
mConditionKeyMap.clear();
- mLastStartTime = -1;
}
bool OringDurationTracker::flushIfNeeded(uint64_t eventTime) {
@@ -122,7 +117,6 @@
// 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 @@
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 @@
}
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 @@
}
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::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 @@
} 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 9e169bb..d82ccfe 100644
--- a/cmds/statsd/tests/metrics/MaxDurationTracker_test.cpp
+++ b/cmds/statsd/tests/metrics/MaxDurationTracker_test.cpp
@@ -79,6 +79,7 @@
// 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 @@
// 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 @@
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 @@
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 f4edffd..54618b5 100644
--- a/cmds/statsd/tests/metrics/OringDurationTracker_test.cpp
+++ b/cmds/statsd/tests/metrics/OringDurationTracker_test.cpp
@@ -130,10 +130,10 @@
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 @@
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 @@
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 @@
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 @@
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),