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

Commit 480392f5 authored by Tej Singh's avatar Tej Singh
Browse files

Data/activation broadcasts use elapsed realtime 

The data and activation broadcasts were guardrailed using
elapsedRealtime of the *LogEvent*. However, it's possible to use
incorrect timestamps, and it's also possible that we could process
events that are old, which would result in the broadcast getting sent
too frequently. To fix this, we should use the current elapsedRealtime
instead of the LogEvent's elapsedRealtime.

I can remove the config activation broadcast if we think we should hold
off on it.

Test: bit statsd_test:*
Bug: 143155387
Change-Id: I4c58d2558d6ba3b4fd15a4a619d6f80a7bd7113f
parent 7bd4314e

cmds/statsd/src/StatsLogProcessor.cpp

+23 −16
Original line number Diff line number Diff line
@@ -200,6 +200,10 @@ void StatsLogProcessor::resetConfigsLocked(const int64_t timestampNs) { 
}



void StatsLogProcessor::OnLogEvent(LogEvent* event) {

    OnLogEvent(event, getElapsedRealtimeNs());

}



void StatsLogProcessor::OnLogEvent(LogEvent* event, int64_t elapsedRealtimeNs) {

    std::lock_guard<std::mutex> lock(mMetricsMutex);



#ifdef VERY_VERBOSE_PRINTING
@@ -207,9 +211,9 @@ void StatsLogProcessor::OnLogEvent(LogEvent* event) { 
        ALOGI("%s", event->ToString().c_str());

    }

#endif

    const int64_t currentTimestampNs = event->GetElapsedTimestampNs();

    const int64_t eventElapsedTimeNs = event->GetElapsedTimestampNs();



    resetIfConfigTtlExpiredLocked(currentTimestampNs);

    resetIfConfigTtlExpiredLocked(eventElapsedTimeNs);



    StatsdStats::getInstance().noteAtomLogged(

        event->GetTagId(), event->GetElapsedTimestampNs() / NS_PER_SEC);
@@ -264,14 +268,15 @@ void StatsLogProcessor::OnLogEvent(LogEvent* event) { 
            uidsWithActiveConfigsChanged.insert(uid);

            StatsdStats::getInstance().noteActiveStatusChanged(pair.first, isCurActive);

        }

        flushIfNecessaryLocked(event->GetElapsedTimestampNs(), pair.first, *(pair.second));

        flushIfNecessaryLocked(pair.first, *(pair.second));

    }



    // Don't use the event timestamp for the guardrail.

    for (int uid : uidsWithActiveConfigsChanged) {

        // Send broadcast so that receivers can pull data.

        auto lastBroadcastTime = mLastActivationBroadcastTimes.find(uid);

        if (lastBroadcastTime != mLastActivationBroadcastTimes.end()) {

            if (currentTimestampNs - lastBroadcastTime->second <

            if (elapsedRealtimeNs - lastBroadcastTime->second <

                StatsdStats::kMinActivationBroadcastPeriodNs) {

                StatsdStats::getInstance().noteActivationBroadcastGuardrailHit(uid);

                VLOG("StatsD would've sent an activation broadcast but the rate limit stopped us.");
@@ -282,13 +287,13 @@ void StatsLogProcessor::OnLogEvent(LogEvent* event) { 
        if (activeConfigs != activeConfigsPerUid.end()) {

            if (mSendActivationBroadcast(uid, activeConfigs->second)) {

                VLOG("StatsD sent activation notice for uid %d", uid);

                mLastActivationBroadcastTimes[uid] = currentTimestampNs;

                mLastActivationBroadcastTimes[uid] = elapsedRealtimeNs;

            }

        } else {

            std::vector<int64_t> emptyActiveConfigs;

            if (mSendActivationBroadcast(uid, emptyActiveConfigs)) {

                VLOG("StatsD sent EMPTY activation notice for uid %d", uid);

                mLastActivationBroadcastTimes[uid] = currentTimestampNs;

                mLastActivationBroadcastTimes[uid] = elapsedRealtimeNs;

            }

        }

    }
@@ -550,22 +555,23 @@ void StatsLogProcessor::OnConfigRemoved(const ConfigKey& key) { 
    }

}



void StatsLogProcessor::flushIfNecessaryLocked(

    int64_t timestampNs, const ConfigKey& key, MetricsManager& metricsManager) {

void StatsLogProcessor::flushIfNecessaryLocked(const ConfigKey& key,

                                               MetricsManager& metricsManager) {

    int64_t elapsedRealtimeNs = getElapsedRealtimeNs();

    auto lastCheckTime = mLastByteSizeTimes.find(key);

    if (lastCheckTime != mLastByteSizeTimes.end()) {

        if (timestampNs - lastCheckTime->second < StatsdStats::kMinByteSizeCheckPeriodNs) {

        if (elapsedRealtimeNs - lastCheckTime->second < StatsdStats::kMinByteSizeCheckPeriodNs) {

            return;

        }

    }



    // We suspect that the byteSize() computation is expensive, so we set a rate limit.

    size_t totalBytes = metricsManager.byteSize();

    mLastByteSizeTimes[key] = timestampNs;

    mLastByteSizeTimes[key] = elapsedRealtimeNs;

    bool requestDump = false;

    if (totalBytes >

        StatsdStats::kMaxMetricsBytesPerConfig) {  // Too late. We need to start clearing data.

        metricsManager.dropData(timestampNs);

    if (totalBytes > StatsdStats::kMaxMetricsBytesPerConfig) {

        // Too late. We need to start clearing data.

        metricsManager.dropData(elapsedRealtimeNs);

        StatsdStats::getInstance().noteDataDropped(key, totalBytes);

        VLOG("StatsD had to toss out metrics for %s", key.ToString().c_str());

    } else if ((totalBytes > StatsdStats::kBytesPerConfigTriggerGetData) ||
@@ -580,7 +586,8 @@ void StatsLogProcessor::flushIfNecessaryLocked( 
        // Send broadcast so that receivers can pull data.

        auto lastBroadcastTime = mLastBroadcastTimes.find(key);

        if (lastBroadcastTime != mLastBroadcastTimes.end()) {

            if (timestampNs - lastBroadcastTime->second < StatsdStats::kMinBroadcastPeriodNs) {

            if (elapsedRealtimeNs - lastBroadcastTime->second <

                    StatsdStats::kMinBroadcastPeriodNs) {

                VLOG("StatsD would've sent a broadcast but the rate limit stopped us.");

                return;

            }
@@ -588,7 +595,7 @@ void StatsLogProcessor::flushIfNecessaryLocked( 
        if (mSendBroadcast(key)) {

            mOnDiskDataConfigs.erase(key);

            VLOG("StatsD triggered data fetch for %s", key.ToString().c_str());

            mLastBroadcastTimes[key] = timestampNs;

            mLastBroadcastTimes[key] = elapsedRealtimeNs;

            StatsdStats::getInstance().noteBroadcastSent(key);

        }

    }

cmds/statsd/src/StatsLogProcessor.h

+3 −2
Original line number Diff line number Diff line
@@ -147,6 +147,8 @@ private: 


    sp<AlarmMonitor> mPeriodicAlarmMonitor;



    void OnLogEvent(LogEvent* event, int64_t elapsedRealtimeNs);



    void resetIfConfigTtlExpiredLocked(const int64_t timestampNs);



    void OnConfigUpdatedLocked(
@@ -176,8 +178,7 @@ private: 


    /* Check if we should send a broadcast if approaching memory limits and if we're over, we

     * actually delete the data. */

    void flushIfNecessaryLocked(int64_t timestampNs, const ConfigKey& key,

                                MetricsManager& metricsManager);

    void flushIfNecessaryLocked(const ConfigKey& key, MetricsManager& metricsManager);



    // Maps the isolated uid in the log event to host uid if the log event contains uid fields.

    void mapIsolatedUidToHostUidIfNecessaryLocked(LogEvent* event) const;

cmds/statsd/tests/StatsLogProcessor_test.cpp

+5 −5
Original line number Diff line number Diff line
@@ -76,9 +76,9 @@ TEST(StatsLogProcessorTest, TestRateLimitByteSize) { 
    // Expect only the first flush to trigger a check for byte size since the last two are

    // rate-limited.

    EXPECT_CALL(mockMetricsManager, byteSize()).Times(1);

    p.flushIfNecessaryLocked(99, key, mockMetricsManager);

    p.flushIfNecessaryLocked(100, key, mockMetricsManager);

    p.flushIfNecessaryLocked(101, key, mockMetricsManager);

    p.flushIfNecessaryLocked(key, mockMetricsManager);

    p.flushIfNecessaryLocked(key, mockMetricsManager);

    p.flushIfNecessaryLocked(key, mockMetricsManager);

}



TEST(StatsLogProcessorTest, TestRateLimitBroadcast) {
@@ -103,7 +103,7 @@ TEST(StatsLogProcessorTest, TestRateLimitBroadcast) { 
                    StatsdStats::kMaxMetricsBytesPerConfig * .95)));



    // Expect only one broadcast despite always returning a size that should trigger broadcast.

    p.flushIfNecessaryLocked(1, key, mockMetricsManager);

    p.flushIfNecessaryLocked(key, mockMetricsManager);

    EXPECT_EQ(1, broadcastCount);



    // b/73089712
@@ -136,7 +136,7 @@ TEST(StatsLogProcessorTest, TestDropWhenByteSizeTooLarge) { 
    EXPECT_CALL(mockMetricsManager, dropData(_)).Times(1);



    // Expect to call the onDumpReport and skip the broadcast.

    p.flushIfNecessaryLocked(1, key, mockMetricsManager);

    p.flushIfNecessaryLocked(key, mockMetricsManager);

    EXPECT_EQ(0, broadcastCount);

}

cmds/statsd/tests/e2e/DurationMetric_e2e_test.cpp

+8 −8
Original line number Diff line number Diff line
@@ -271,19 +271,19 @@ TEST(DurationMetricE2eTest, TestWithActivation) { 
    // Turn screen off.

    event = CreateScreenStateChangedEvent(

            android::view::DISPLAY_STATE_OFF, bucketStartTimeNs + 2 * NS_PER_SEC); // 0:02

    processor.OnLogEvent(event.get());

    processor.OnLogEvent(event.get(), bucketStartTimeNs + 2 * NS_PER_SEC);



    // Turn screen on.

    const int64_t durationStartNs = bucketStartTimeNs + 5 * NS_PER_SEC; // 0:05

    event = CreateScreenStateChangedEvent(android::view::DISPLAY_STATE_ON, durationStartNs);

    processor.OnLogEvent(event.get());

    processor.OnLogEvent(event.get(), durationStartNs);



    // Activate metric.

    const int64_t activationStartNs = bucketStartTimeNs + 5 * NS_PER_SEC; // 0:10

    const int64_t activationEndNs =

            activationStartNs + event_activation1->ttl_seconds() * NS_PER_SEC; // 0:40

    event = CreateAppCrashEvent(111, activationStartNs);

    processor.OnLogEvent(event.get());

    processor.OnLogEvent(event.get(), activationStartNs);

    EXPECT_TRUE(metricsManager->isActive());

    EXPECT_TRUE(metricProducer->mIsActive);

    EXPECT_EQ(broadcastCount, 1);
@@ -296,7 +296,7 @@ TEST(DurationMetricE2eTest, TestWithActivation) { 
    // Expire activation.

    const int64_t expirationNs = activationEndNs + 7 * NS_PER_SEC;

    event = CreateScreenBrightnessChangedEvent(64, expirationNs); // 0:47

    processor.OnLogEvent(event.get());

    processor.OnLogEvent(event.get(), expirationNs);

    EXPECT_FALSE(metricsManager->isActive());

    EXPECT_FALSE(metricProducer->mIsActive);

    EXPECT_EQ(broadcastCount, 2);
@@ -310,24 +310,24 @@ TEST(DurationMetricE2eTest, TestWithActivation) { 
    // Turn off screen 10 seconds after activation expiration.

    const int64_t durationEndNs = activationEndNs + 10 * NS_PER_SEC; // 0:50

    event = CreateScreenStateChangedEvent(android::view::DISPLAY_STATE_OFF, durationEndNs);

    processor.OnLogEvent(event.get());

    processor.OnLogEvent(event.get(),durationEndNs);



    // Turn screen on.

    const int64_t duration2StartNs = durationEndNs + 5 * NS_PER_SEC; // 0:55

    event = CreateScreenStateChangedEvent(android::view::DISPLAY_STATE_ON, duration2StartNs);

    processor.OnLogEvent(event.get());

    processor.OnLogEvent(event.get(), duration2StartNs);



    // Turn off screen.

    const int64_t duration2EndNs = duration2StartNs + 10 * NS_PER_SEC; // 1:05

    event = CreateScreenStateChangedEvent(android::view::DISPLAY_STATE_OFF, duration2EndNs);

    processor.OnLogEvent(event.get());

    processor.OnLogEvent(event.get(), duration2EndNs);



    // Activate metric.

    const int64_t activation2StartNs = duration2EndNs + 5 * NS_PER_SEC; // 1:10

    const int64_t activation2EndNs =

            activation2StartNs + event_activation1->ttl_seconds() * NS_PER_SEC; // 1:40

    event = CreateAppCrashEvent(211, activation2StartNs);

    processor.OnLogEvent(event.get());

    processor.OnLogEvent(event.get(), activation2StartNs);

    EXPECT_TRUE(metricsManager->isActive());

    EXPECT_TRUE(metricProducer->mIsActive);

    EXPECT_EQ(broadcastCount, 3);

cmds/statsd/tests/e2e/MetricActivation_e2e_test.cpp

+77 −77

File changed.

Preview size limit exceeded, changes collapsed.