From 756541526a8cbeb058e4ceb79436bf8fd11a5ddf Mon Sep 17 00:00:00 2001 From: Tej Singh Date: Fri, 12 Jun 2020 18:46:27 -0700 Subject: [PATCH] Mark bucket as condition_unknown properly Previously, if the condition was unknown for the entire bucket, the bucket would be annotated with a NO_DATA rather than being dropped because CONDITION_UNKNOWN. This updates all the buckets to be dropped due to CONDITION_UNKNOWN. Note that this will make the condition unknown problem appear worse, when in reality it is making our bucket drop reasons more correct and should not have any impact on the true CONDITION_UNKNOWN. Also fix an issue where a test was failing due to a previous test leaving data persisted to disk. This fix is a hack for now, and should be properly fixed later. Bug: 158897179 Test: atest statsd_test Change-Id: Ic703600d37aa1873ec67cb1a279dcf349d48fc9f --- .../src/metrics/ValueMetricProducer.cpp | 1 + cmds/statsd/tests/StatsLogProcessor_test.cpp | 18 ++-- .../metrics/ValueMetricProducer_test.cpp | 98 ++++++++++++++++++- 3 files changed, 107 insertions(+), 10 deletions(-) diff --git a/cmds/statsd/src/metrics/ValueMetricProducer.cpp b/cmds/statsd/src/metrics/ValueMetricProducer.cpp index 8203f38de393a..0a0bdb3baa1ba 100644 --- a/cmds/statsd/src/metrics/ValueMetricProducer.cpp +++ b/cmds/statsd/src/metrics/ValueMetricProducer.cpp @@ -951,6 +951,7 @@ void ValueMetricProducer::flushCurrentBucketLocked(const int64_t& eventTimeNs, const int64_t& nextBucketStartTimeNs) { if (mCondition == ConditionState::kUnknown) { StatsdStats::getInstance().noteBucketUnknownCondition(mMetricId); + invalidateCurrentBucketWithoutResetBase(eventTimeNs, BucketDropReason::CONDITION_UNKNOWN); } VLOG("finalizing bucket for %ld, dumping %d slices", (long)mCurrentBucketStartTimeNs, diff --git a/cmds/statsd/tests/StatsLogProcessor_test.cpp b/cmds/statsd/tests/StatsLogProcessor_test.cpp index 13d977fa2563e..1e6680c475671 100644 --- a/cmds/statsd/tests/StatsLogProcessor_test.cpp +++ b/cmds/statsd/tests/StatsLogProcessor_test.cpp @@ -13,6 +13,11 @@ // limitations under the License. #include "StatsLogProcessor.h" + +#include +#include +#include + #include "StatsService.h" #include "config/ConfigKey.h" #include "frameworks/base/cmds/statsd/src/stats_log.pb.h" @@ -20,16 +25,10 @@ #include "guardrail/StatsdStats.h" #include "logd/LogEvent.h" #include "packages/UidMap.h" -#include "storage/StorageManager.h" #include "statslog_statsdtest.h" - -#include -#include - +#include "storage/StorageManager.h" #include "tests/statsd_test_util.h" -#include - using namespace android; using namespace testing; using ::ndk::SharedRefBase; @@ -1836,6 +1835,11 @@ TEST(StatsLogProcessorTest, TestDumpReportWithoutErasingDataDoesNotUpdateTimesta int isolatedUid = 30; sp mockUidMap = makeMockUidMapForOneHost(hostUid, {isolatedUid}); ConfigKey key(3, 4); + + // TODO: All tests should not persist state on disk. This removes any reports that were present. + ProtoOutputStream proto; + StorageManager::appendConfigMetricsReport(key, &proto, /*erase data=*/true, /*isAdb=*/false); + StatsdConfig config = MakeConfig(false); sp processor = CreateStatsLogProcessor(1, 1, config, key, nullptr, 0, mockUidMap); diff --git a/cmds/statsd/tests/metrics/ValueMetricProducer_test.cpp b/cmds/statsd/tests/metrics/ValueMetricProducer_test.cpp index f0419964e892f..5666501d7d510 100644 --- a/cmds/statsd/tests/metrics/ValueMetricProducer_test.cpp +++ b/cmds/statsd/tests/metrics/ValueMetricProducer_test.cpp @@ -3295,11 +3295,15 @@ TEST(ValueMetricProducerTest_BucketDrop, TestInvalidBucketWhenConditionEventWron report.value_metrics().skipped(0).start_bucket_elapsed_millis()); EXPECT_EQ(NanoToMillis(bucket2StartTimeNs + 100), report.value_metrics().skipped(0).end_bucket_elapsed_millis()); - ASSERT_EQ(1, report.value_metrics().skipped(0).drop_event_size()); + ASSERT_EQ(2, report.value_metrics().skipped(0).drop_event_size()); auto dropEvent = report.value_metrics().skipped(0).drop_event(0); EXPECT_EQ(BucketDropReason::EVENT_IN_WRONG_BUCKET, dropEvent.drop_reason()); EXPECT_EQ(NanoToMillis(bucket2StartTimeNs - 100), dropEvent.drop_time_millis()); + + dropEvent = report.value_metrics().skipped(0).drop_event(1); + EXPECT_EQ(BucketDropReason::CONDITION_UNKNOWN, dropEvent.drop_reason()); + EXPECT_EQ(NanoToMillis(bucket2StartTimeNs + 100), dropEvent.drop_time_millis()); } /* @@ -3615,7 +3619,7 @@ TEST(ValueMetricProducerTest_BucketDrop, TestBucketDropWhenDataUnavailable) { sp valueProducer = ValueMetricProducerTestHelper::createValueProducerWithCondition( - pullerManager, metric, ConditionState::kUnknown); + pullerManager, metric, ConditionState::kFalse); // Check dump report. ProtoOutputStream output; @@ -3640,6 +3644,94 @@ TEST(ValueMetricProducerTest_BucketDrop, TestBucketDropWhenDataUnavailable) { EXPECT_EQ(NanoToMillis(dumpReportTimeNs), dropEvent.drop_time_millis()); } +/* + * Test that all buckets are dropped due to condition unknown until the first onConditionChanged. + */ +TEST(ValueMetricProducerTest_BucketDrop, TestConditionUnknownMultipleBuckets) { + ValueMetric metric = ValueMetricProducerTestHelper::createMetricWithCondition(); + + sp pullerManager = new StrictMock(); + EXPECT_CALL(*pullerManager, Pull(tagId, kConfigKey, _, _, _)) + // Condition change to true. + .WillOnce(Invoke([](int tagId, const ConfigKey&, const int64_t eventTimeNs, + vector>* data, bool) { + EXPECT_EQ(eventTimeNs, bucket2StartTimeNs + 10 * NS_PER_SEC); + data->clear(); + data->push_back(CreateRepeatedValueLogEvent( + tagId, bucket2StartTimeNs + 10 * NS_PER_SEC, 10)); + return true; + })) + // Dump report requested. + .WillOnce(Invoke([](int tagId, const ConfigKey&, const int64_t eventTimeNs, + vector>* data, bool) { + EXPECT_EQ(eventTimeNs, bucket2StartTimeNs + 15 * NS_PER_SEC); + data->clear(); + data->push_back(CreateRepeatedValueLogEvent( + tagId, bucket2StartTimeNs + 15 * NS_PER_SEC, 15)); + return true; + })); + + sp valueProducer = + ValueMetricProducerTestHelper::createValueProducerWithCondition( + pullerManager, metric, ConditionState::kUnknown); + + // Bucket should be dropped because of condition unknown. + int64_t appUpgradeTimeNs = bucketStartTimeNs + 5 * NS_PER_SEC; + valueProducer->notifyAppUpgrade(appUpgradeTimeNs); + + // Bucket also dropped due to condition unknown + vector> allData; + allData.clear(); + allData.push_back(CreateRepeatedValueLogEvent(tagId, bucket2StartTimeNs + 1, 3)); + valueProducer->onDataPulled(allData, /** succeed */ true, bucket2StartTimeNs); + + // This bucket is also dropped due to condition unknown. + int64_t conditionChangeTimeNs = bucket2StartTimeNs + 10 * NS_PER_SEC; + valueProducer->onConditionChanged(true, conditionChangeTimeNs); + + // Check dump report. + ProtoOutputStream output; + std::set strSet; + int64_t dumpReportTimeNs = bucket2StartTimeNs + 15 * NS_PER_SEC; // 15 seconds + valueProducer->onDumpReport(dumpReportTimeNs, true /* include current bucket */, true, + NO_TIME_CONSTRAINTS /* dumpLatency */, &strSet, &output); + + StatsLogReport report = outputStreamToProto(&output); + EXPECT_TRUE(report.has_value_metrics()); + ASSERT_EQ(0, report.value_metrics().data_size()); + ASSERT_EQ(3, report.value_metrics().skipped_size()); + + EXPECT_EQ(NanoToMillis(bucketStartTimeNs), + report.value_metrics().skipped(0).start_bucket_elapsed_millis()); + EXPECT_EQ(NanoToMillis(appUpgradeTimeNs), + report.value_metrics().skipped(0).end_bucket_elapsed_millis()); + ASSERT_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(appUpgradeTimeNs), dropEvent.drop_time_millis()); + + EXPECT_EQ(NanoToMillis(appUpgradeTimeNs), + report.value_metrics().skipped(1).start_bucket_elapsed_millis()); + EXPECT_EQ(NanoToMillis(bucket2StartTimeNs), + report.value_metrics().skipped(1).end_bucket_elapsed_millis()); + ASSERT_EQ(1, report.value_metrics().skipped(1).drop_event_size()); + + dropEvent = report.value_metrics().skipped(1).drop_event(0); + EXPECT_EQ(BucketDropReason::CONDITION_UNKNOWN, dropEvent.drop_reason()); + EXPECT_EQ(NanoToMillis(bucket2StartTimeNs), dropEvent.drop_time_millis()); + + EXPECT_EQ(NanoToMillis(bucket2StartTimeNs), + report.value_metrics().skipped(2).start_bucket_elapsed_millis()); + EXPECT_EQ(NanoToMillis(dumpReportTimeNs), + report.value_metrics().skipped(2).end_bucket_elapsed_millis()); + ASSERT_EQ(1, report.value_metrics().skipped(2).drop_event_size()); + + dropEvent = report.value_metrics().skipped(2).drop_event(0); + EXPECT_EQ(BucketDropReason::CONDITION_UNKNOWN, dropEvent.drop_reason()); + EXPECT_EQ(NanoToMillis(conditionChangeTimeNs), dropEvent.drop_time_millis()); +} + /* * Test that a skipped bucket is logged when a forced bucket split occurs when the previous bucket * was not flushed in time. @@ -4957,7 +5049,7 @@ TEST(ValueMetricProducerTest, TestForcedBucketSplitWhenConditionUnknownSkipsBuck ASSERT_EQ(1, report.value_metrics().skipped(0).drop_event_size()); auto dropEvent = report.value_metrics().skipped(0).drop_event(0); - EXPECT_EQ(BucketDropReason::NO_DATA, dropEvent.drop_reason()); + EXPECT_EQ(BucketDropReason::CONDITION_UNKNOWN, dropEvent.drop_reason()); EXPECT_EQ(NanoToMillis(appUpdateTimeNs), dropEvent.drop_time_millis()); }