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

Commit 16ca28fc authored by Tej Singh's avatar Tej Singh
Browse files

StatsdStats: improve activation time logging 

Add logging to record whenever the 10 second guardrail for sending
active configs changed broadcast is met, so that we know when the
broadcast would not have been sent.
Add activation time for configs that are active when the device boots.
This will help determine whether or not statsd thinks configs are active
and will help debug issues like b/133809948

Bug: 133809948
Test: bit statsd_test:*
Test: manually rebooted to make sure activation time was logged
Change-Id: Ifa72202bc52485e4953e49d78dffea685cc3d1e7
parent 2c824e3a

cmds/statsd/src/StatsLogProcessor.cpp

+1 −0
Original line number Diff line number Diff line
@@ -269,6 +269,7 @@ void StatsLogProcessor::OnLogEvent(LogEvent* event) { 
        if (lastBroadcastTime != mLastActivationBroadcastTimes.end()) {

            if (currentTimestampNs - lastBroadcastTime->second <

                    StatsdStats::kMinActivationBroadcastPeriodNs) {

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

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

                return;

            }

cmds/statsd/src/guardrail/StatsdStats.cpp

+43 −0
Original line number Diff line number Diff line
@@ -51,6 +51,7 @@ const int FIELD_ID_PERIODIC_ALARM_STATS = 12; 
const int FIELD_ID_SYSTEM_SERVER_RESTART = 15;

const int FIELD_ID_LOGGER_ERROR_STATS = 16;

const int FIELD_ID_OVERFLOW = 18;

const int FIELD_ID_ACTIVATION_BROADCAST_GUARDRAIL = 19;



const int FIELD_ID_ATOM_STATS_TAG = 1;

const int FIELD_ID_ATOM_STATS_COUNT = 2;
@@ -109,6 +110,9 @@ const int FIELD_ID_UID_MAP_BYTES_USED = 2; 
const int FIELD_ID_UID_MAP_DROPPED_CHANGES = 3;

const int FIELD_ID_UID_MAP_DELETED_APPS = 4;



const int FIELD_ID_ACTIVATION_BROADCAST_GUARDRAIL_UID = 1;

const int FIELD_ID_ACTIVATION_BROADCAST_GUARDRAIL_TIME = 2;



const std::map<int, std::pair<size_t, size_t>> StatsdStats::kAtomDimensionKeySizeLimitMap = {

        {android::util::BINDER_CALLS, {6000, 10000}},

        {android::util::LOOPER_STATS, {1500, 2500}},
@@ -236,6 +240,19 @@ void StatsdStats::noteActiveStatusChanged(const ConfigKey& key, bool activated, 
    vec.push_back(timeSec);

}



void StatsdStats::noteActivationBroadcastGuardrailHit(const int uid) {

    noteActivationBroadcastGuardrailHit(uid, getWallClockSec());

}



void StatsdStats::noteActivationBroadcastGuardrailHit(const int uid, const int32_t timeSec) {

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

    auto& guardrailTimes = mActivationBroadcastGuardrailStats[uid];

    if (guardrailTimes.size() == kMaxTimestampCount) {

        guardrailTimes.pop_front();

    }

    guardrailTimes.push_back(timeSec);

}



void StatsdStats::noteDataDropped(const ConfigKey& key, const size_t totalBytes) {

    noteDataDropped(key, totalBytes, getWallClockSec());

}
@@ -590,6 +607,7 @@ void StatsdStats::resetInternalLocked() { 
        pullStats.second.unregisteredCount = 0;

    }

    mAtomMetricStats.clear();

    mActivationBroadcastGuardrailStats.clear();

}



string buildTimeString(int64_t timeSec) {
@@ -758,6 +776,17 @@ void StatsdStats::dumpStats(int out) const { 


    dprintf(out, "Event queue overflow: %d; MaxHistoryNs: %lld; MinHistoryNs: %lld\n",

            mOverflowCount, (long long)mMaxQueueHistoryNs, (long long)mMinQueueHistoryNs);



    if (mActivationBroadcastGuardrailStats.size() > 0) {

        dprintf(out, "********mActivationBroadcastGuardrail stats***********\n");

        for (const auto& pair: mActivationBroadcastGuardrailStats) {

            dprintf(out, "Uid %d: Times: ", pair.first);

            for (const auto& guardrailHitTime : pair.second) {

                dprintf(out, "%d ", guardrailHitTime);

            }

        }

        dprintf(out, "\n");

    }

}



void addConfigStatsToProto(const ConfigStats& configStats, ProtoOutputStream* proto) {
@@ -959,6 +988,20 @@ void StatsdStats::dumpStats(std::vector<uint8_t>* output, bool reset) { 
                    restart);

    }



    for (const auto& pair: mActivationBroadcastGuardrailStats) {

        uint64_t token = proto.start(FIELD_TYPE_MESSAGE |

                                     FIELD_ID_ACTIVATION_BROADCAST_GUARDRAIL |

                                     FIELD_COUNT_REPEATED);

        proto.write(FIELD_TYPE_INT32 | FIELD_ID_ACTIVATION_BROADCAST_GUARDRAIL_UID,

                    (int32_t) pair.first);

        for (const auto& guardrailHitTime : pair.second) {

            proto.write(FIELD_TYPE_INT32 | FIELD_ID_ACTIVATION_BROADCAST_GUARDRAIL_TIME |

                            FIELD_COUNT_REPEATED,

                        guardrailHitTime);

        }

        proto.end(token);

    }



    output->clear();

    size_t bufferSize = proto.size();

    output->resize(bufferSize);

cmds/statsd/src/guardrail/StatsdStats.h

+13 −0
Original line number Diff line number Diff line
@@ -444,6 +444,12 @@ public: 
     * the queue */

    void noteEventQueueOverflow(int64_t oldestEventTimestampNs);



    /**

     * Reports that the activation broadcast guardrail was hit for this uid. Namely, the broadcast

     * should have been sent, but instead was skipped due to hitting the guardrail.

     */

     void noteActivationBroadcastGuardrailHit(const int uid);



    /**

     * Reset the historical stats. Including all stats in icebox, and the tracked stats about

     * metrics, matchers, and atoms. The active configs will be kept and StatsdStats will continue
@@ -532,6 +538,10 @@ private: 
    // Maps metric ID to its stats. The size is capped by the number of metrics.

    std::map<int64_t, AtomMetricStats> mAtomMetricStats;



    // Maps uids to times when the activation changed broadcast not sent due to hitting the

    // guardrail. The size is capped by the number of configs, and up to 20 times per uid.

    std::map<int, std::list<int32_t>> mActivationBroadcastGuardrailStats;



    struct LogLossStats {

        LogLossStats(int32_t sec, int32_t count, int32_t error, int32_t tag, int32_t uid,

                     int32_t pid)
@@ -588,6 +598,8 @@ private: 


    void noteActiveStatusChanged(const ConfigKey& key, bool activate, int32_t timeSec);



    void noteActivationBroadcastGuardrailHit(const int uid, int32_t timeSec);



    void addToIceBoxLocked(std::shared_ptr<ConfigStats>& stats);



    /**
@@ -607,6 +619,7 @@ private: 
    FRIEND_TEST(StatsdStatsTest, TestSystemServerCrash);

    FRIEND_TEST(StatsdStatsTest, TestPullAtomStats);

    FRIEND_TEST(StatsdStatsTest, TestAtomMetricsStats);

    FRIEND_TEST(StatsdStatsTest, TestActivationBroadcastGuardrailHit);

};



}  // namespace statsd

cmds/statsd/src/metrics/MetricsManager.cpp

+4 −0
Original line number Diff line number Diff line
@@ -521,6 +521,10 @@ void MetricsManager::loadActiveConfig(const ActiveConfig& config, int64_t curren 
            if (metric->getMetricId() == activeMetric.id()) {

                VLOG("Setting active metric: %lld", (long long)metric->getMetricId());

                metric->loadActiveMetric(activeMetric, currentTimeNs);

                if (!mIsActive && metric->isActive()) {

                    StatsdStats::getInstance().noteActiveStatusChanged(mConfigKey,

                                                                       /*activate=*/ true);

                }

                mIsActive |= metric->isActive();

            }

        }

cmds/statsd/src/stats_log.proto

+7 −0
Original line number Diff line number Diff line
@@ -470,6 +470,13 @@ message StatsdStatsReport { 
    }



    optional EventQueueOverflow queue_overflow = 18;



    message ActivationBroadcastGuardrail {

        optional int32 uid = 1;

        repeated int32 guardrail_met_sec = 2;

    }



    repeated ActivationBroadcastGuardrail activation_guardrail_stats = 19;

}



message AlertTriggerDetails {