Fix skipped bucket end times
Previously, skipped bucket were assigned the full bucket end time by
default. This caused partial buckets that were skipped to have the
wrong end time. The end time is now logged when the bucket is being
flushed so that the actual bucket end time is captured.
Bug: 148692479
Test: bit statsd_test:*
Change-Id: Ie9cc57d1bac5f6522e5794b4a49b99d1208f44ea
diff --git a/cmds/statsd/src/metrics/GaugeMetricProducer.cpp b/cmds/statsd/src/metrics/GaugeMetricProducer.cpp
index 4ab6fd4..641031b 100644
--- a/cmds/statsd/src/metrics/GaugeMetricProducer.cpp
+++ b/cmds/statsd/src/metrics/GaugeMetricProducer.cpp
@@ -549,14 +549,11 @@
void GaugeMetricProducer::flushCurrentBucketLocked(const int64_t& eventTimeNs,
const int64_t& nextBucketStartTimeNs) {
int64_t fullBucketEndTimeNs = getCurrentBucketEndTimeNs();
+ int64_t bucketEndTime = eventTimeNs < fullBucketEndTimeNs ? eventTimeNs : fullBucketEndTimeNs;
GaugeBucket info;
info.mBucketStartNs = mCurrentBucketStartTimeNs;
- if (eventTimeNs < fullBucketEndTimeNs) {
- info.mBucketEndNs = eventTimeNs;
- } else {
- info.mBucketEndNs = fullBucketEndTimeNs;
- }
+ info.mBucketEndNs = bucketEndTime;
// Add bucket to mPastBuckets if bucket is large enough.
// Otherwise, drop the bucket data and add bucket metadata to mSkippedBuckets.
@@ -571,7 +568,7 @@
}
} else {
mCurrentSkippedBucket.bucketStartTimeNs = mCurrentBucketStartTimeNs;
- mCurrentSkippedBucket.bucketEndTimeNs = eventTimeNs;
+ mCurrentSkippedBucket.bucketEndTimeNs = bucketEndTime;
if (!maxDropEventsReached()) {
mCurrentSkippedBucket.dropEvents.emplace_back(
buildDropEvent(eventTimeNs, BucketDropReason::BUCKET_TOO_SMALL));
diff --git a/cmds/statsd/src/metrics/ValueMetricProducer.cpp b/cmds/statsd/src/metrics/ValueMetricProducer.cpp
index d2db6e9..04857da 100644
--- a/cmds/statsd/src/metrics/ValueMetricProducer.cpp
+++ b/cmds/statsd/src/metrics/ValueMetricProducer.cpp
@@ -384,9 +384,6 @@
if (!mCurrentBucketIsInvalid) {
// Only report to StatsdStats once per invalid bucket.
StatsdStats::getInstance().noteInvalidatedBucket(mMetricId);
-
- mCurrentSkippedBucket.bucketStartTimeNs = mCurrentBucketStartTimeNs;
- mCurrentSkippedBucket.bucketEndTimeNs = getCurrentBucketEndTimeNs();
}
if (!maxDropEventsReached()) {
@@ -960,12 +957,6 @@
int64_t conditionTrueDuration = mConditionTimer.newBucketStart(bucketEndTime);
bool isBucketLargeEnough = bucketEndTime - mCurrentBucketStartTimeNs >= mMinBucketSizeNs;
if (!isBucketLargeEnough) {
- // If the bucket is valid, this is the only drop reason and we need to
- // set the skipped bucket start and end times.
- if (!mCurrentBucketIsInvalid) {
- mCurrentSkippedBucket.bucketStartTimeNs = mCurrentBucketStartTimeNs;
- mCurrentSkippedBucket.bucketEndTimeNs = bucketEndTime;
- }
if (!maxDropEventsReached()) {
mCurrentSkippedBucket.dropEvents.emplace_back(
buildDropEvent(eventTimeNs, BucketDropReason::BUCKET_TOO_SMALL));
@@ -983,6 +974,8 @@
}
}
} else {
+ mCurrentSkippedBucket.bucketStartTimeNs = mCurrentBucketStartTimeNs;
+ mCurrentSkippedBucket.bucketEndTimeNs = bucketEndTime;
mSkippedBuckets.emplace_back(mCurrentSkippedBucket);
}
diff --git a/cmds/statsd/tests/metrics/ValueMetricProducer_test.cpp b/cmds/statsd/tests/metrics/ValueMetricProducer_test.cpp
index 92e8241..f6245ac 100644
--- a/cmds/statsd/tests/metrics/ValueMetricProducer_test.cpp
+++ b/cmds/statsd/tests/metrics/ValueMetricProducer_test.cpp
@@ -3333,7 +3333,7 @@
EXPECT_EQ(NanoToMillis(bucketStartTimeNs),
report.value_metrics().skipped(0).start_bucket_elapsed_millis());
- EXPECT_EQ(NanoToMillis(bucket2StartTimeNs),
+ EXPECT_EQ(NanoToMillis(bucketStartTimeNs + 40),
report.value_metrics().skipped(0).end_bucket_elapsed_millis());
EXPECT_EQ(1, report.value_metrics().skipped(0).drop_event_size());
@@ -3393,7 +3393,7 @@
EXPECT_EQ(NanoToMillis(bucket2StartTimeNs),
report.value_metrics().skipped(0).start_bucket_elapsed_millis());
- EXPECT_EQ(NanoToMillis(bucket3StartTimeNs),
+ EXPECT_EQ(NanoToMillis(bucket2StartTimeNs + 100),
report.value_metrics().skipped(0).end_bucket_elapsed_millis());
EXPECT_EQ(1, report.value_metrics().skipped(0).drop_event_size());
@@ -3470,7 +3470,7 @@
EXPECT_EQ(NanoToMillis(bucket2StartTimeNs),
report.value_metrics().skipped(0).start_bucket_elapsed_millis());
- EXPECT_EQ(NanoToMillis(bucket3StartTimeNs),
+ EXPECT_EQ(NanoToMillis(bucket2StartTimeNs + 100),
report.value_metrics().skipped(0).end_bucket_elapsed_millis());
EXPECT_EQ(1, report.value_metrics().skipped(0).drop_event_size());
@@ -3519,7 +3519,8 @@
// Check dump report.
ProtoOutputStream output;
std::set<string> strSet;
- valueProducer->onDumpReport(bucketStartTimeNs + 100, true /* include recent buckets */, true,
+ int64_t dumpReportTimeNs = bucketStartTimeNs + 10000;
+ valueProducer->onDumpReport(dumpReportTimeNs, true /* include recent buckets */, true,
NO_TIME_CONSTRAINTS /* dumpLatency */, &strSet, &output);
StatsLogReport report = outputStreamToProto(&output);
@@ -3529,13 +3530,13 @@
EXPECT_EQ(NanoToMillis(bucketStartTimeNs),
report.value_metrics().skipped(0).start_bucket_elapsed_millis());
- EXPECT_EQ(NanoToMillis(bucket2StartTimeNs),
+ EXPECT_EQ(NanoToMillis(dumpReportTimeNs),
report.value_metrics().skipped(0).end_bucket_elapsed_millis());
EXPECT_EQ(1, report.value_metrics().skipped(0).drop_event_size());
auto dropEvent = report.value_metrics().skipped(0).drop_event(0);
EXPECT_EQ(BucketDropReason::CONDITION_UNKNOWN, dropEvent.drop_reason());
- EXPECT_EQ(NanoToMillis(bucketStartTimeNs + 100), dropEvent.drop_time_millis());
+ EXPECT_EQ(NanoToMillis(dumpReportTimeNs), dropEvent.drop_time_millis());
}
/*
@@ -3569,7 +3570,8 @@
// Check dump report.
ProtoOutputStream output;
std::set<string> strSet;
- valueProducer->onDumpReport(bucketStartTimeNs + 100, true /* include recent buckets */, true,
+ int64_t dumpReportTimeNs = bucketStartTimeNs + 10000;
+ valueProducer->onDumpReport(dumpReportTimeNs, true /* include recent buckets */, true,
NO_TIME_CONSTRAINTS /* dumpLatency */, &strSet, &output);
StatsLogReport report = outputStreamToProto(&output);
@@ -3579,13 +3581,13 @@
EXPECT_EQ(NanoToMillis(bucketStartTimeNs),
report.value_metrics().skipped(0).start_bucket_elapsed_millis());
- EXPECT_EQ(NanoToMillis(bucket2StartTimeNs),
+ EXPECT_EQ(NanoToMillis(dumpReportTimeNs),
report.value_metrics().skipped(0).end_bucket_elapsed_millis());
EXPECT_EQ(1, report.value_metrics().skipped(0).drop_event_size());
auto dropEvent = report.value_metrics().skipped(0).drop_event(0);
EXPECT_EQ(BucketDropReason::PULL_FAILED, dropEvent.drop_reason());
- EXPECT_EQ(NanoToMillis(bucketStartTimeNs + 100), dropEvent.drop_time_millis());
+ EXPECT_EQ(NanoToMillis(dumpReportTimeNs), dropEvent.drop_time_millis());
}
/*
@@ -3691,8 +3693,9 @@
// Check dump report.
ProtoOutputStream output;
std::set<string> strSet;
- valueProducer->onDumpReport(bucketStartTimeNs + 9000000, true /* include recent buckets */,
- true, NO_TIME_CONSTRAINTS /* dumpLatency */, &strSet, &output);
+ int64_t dumpReportTimeNs = bucketStartTimeNs + 9000000;
+ valueProducer->onDumpReport(dumpReportTimeNs, true /* include recent buckets */, true,
+ NO_TIME_CONSTRAINTS /* dumpLatency */, &strSet, &output);
StatsLogReport report = outputStreamToProto(&output);
EXPECT_TRUE(report.has_value_metrics());
@@ -3701,13 +3704,13 @@
EXPECT_EQ(NanoToMillis(bucketStartTimeNs),
report.value_metrics().skipped(0).start_bucket_elapsed_millis());
- EXPECT_EQ(NanoToMillis(bucketStartTimeNs + 9000000),
+ EXPECT_EQ(NanoToMillis(dumpReportTimeNs),
report.value_metrics().skipped(0).end_bucket_elapsed_millis());
EXPECT_EQ(1, report.value_metrics().skipped(0).drop_event_size());
auto dropEvent = report.value_metrics().skipped(0).drop_event(0);
EXPECT_EQ(BucketDropReason::BUCKET_TOO_SMALL, dropEvent.drop_reason());
- EXPECT_EQ(NanoToMillis(bucketStartTimeNs + 9000000), dropEvent.drop_time_millis());
+ EXPECT_EQ(NanoToMillis(dumpReportTimeNs), dropEvent.drop_time_millis());
}
/*
@@ -3739,7 +3742,8 @@
// Check dump report.
ProtoOutputStream output;
std::set<string> strSet;
- valueProducer->onDumpReport(bucketStartTimeNs + 1000, true /* include recent buckets */, true,
+ int64_t dumpReportTimeNs = bucketStartTimeNs + 1000;
+ valueProducer->onDumpReport(dumpReportTimeNs, true /* include recent buckets */, true,
FAST /* dumpLatency */, &strSet, &output);
StatsLogReport report = outputStreamToProto(&output);
@@ -3749,7 +3753,7 @@
EXPECT_EQ(NanoToMillis(bucketStartTimeNs),
report.value_metrics().skipped(0).start_bucket_elapsed_millis());
- EXPECT_EQ(NanoToMillis(bucket2StartTimeNs),
+ EXPECT_EQ(NanoToMillis(dumpReportTimeNs),
report.value_metrics().skipped(0).end_bucket_elapsed_millis());
EXPECT_EQ(2, report.value_metrics().skipped(0).drop_event_size());
@@ -3759,7 +3763,7 @@
dropEvent = report.value_metrics().skipped(0).drop_event(1);
EXPECT_EQ(BucketDropReason::DUMP_REPORT_REQUESTED, dropEvent.drop_reason());
- EXPECT_EQ(NanoToMillis(bucketStartTimeNs + 1000), dropEvent.drop_time_millis());
+ EXPECT_EQ(NanoToMillis(dumpReportTimeNs), dropEvent.drop_time_millis());
}
/*
@@ -3826,6 +3830,7 @@
// Check dump report.
ProtoOutputStream output;
std::set<string> strSet;
+ int64_t dumpReportTimeNs = bucketStartTimeNs + 1000;
// Because we already have 10 dump events in the current bucket,
// this case should not be added to the list of dump events.
valueProducer->onDumpReport(bucketStartTimeNs + 1000, true /* include recent buckets */, true,
@@ -3838,7 +3843,7 @@
EXPECT_EQ(NanoToMillis(bucketStartTimeNs),
report.value_metrics().skipped(0).start_bucket_elapsed_millis());
- EXPECT_EQ(NanoToMillis(bucket2StartTimeNs),
+ EXPECT_EQ(NanoToMillis(dumpReportTimeNs),
report.value_metrics().skipped(0).end_bucket_elapsed_millis());
EXPECT_EQ(10, report.value_metrics().skipped(0).drop_event_size());