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

Commit 48ed1cc7 authored by Chenjie Yu's avatar Chenjie Yu
Browse files

record atom pull time 

output looks like this:
********Pulled Atom stats***********
Atom 10003->(total pull)2, (pull from cache)0, (min pull interval)0,
(average pull time nanos)528047, (max pull time nanos)568386, (average
pull delay nanos)4222422, (max pull delay nanos)4498125
Atom 10019->(total pull)2, (pull from cache)0, (min pull interval)0,
(average pull time nanos)4455885, (max pull time nanos)6245938, (average
pull delay nanos)12153985, (max pull delay nanos)13518387
Atom 10020->(total pull)2, (pull from cache)0, (min pull interval)0,
(average pull time nanos)3092005, (max pull time nanos)3223594, (average
pull delay nanos)18301668, (max pull delay nanos)19805783
Atom 10021->(total pull)3, (pull from cache)0, (min pull interval)0,
(average pull time nanos)3151944, (max pull time nanos)4931719, (average
pull delay nanos)17319897, (max pull delay nanos)24455211

Bug: 118757386
Test: unit test
Change-Id: Idbe0e4cc822d75813d2e4511be5e7593fff370d4
parent f06f3720

cmds/statsd/src/external/StatsPuller.cpp

+4 −0
Original line number Diff line number Diff line
@@ -46,6 +46,7 @@ bool StatsPuller::Pull(const int64_t elapsedTimeNs, std::vector<std::shared_ptr< 
    if (elapsedTimeNs - mLastPullTimeNs < mCoolDownNs) {

        (*data) = mCachedData;

        StatsdStats::getInstance().notePullFromCache(mTagId);

        StatsdStats::getInstance().notePullDelay(mTagId, getElapsedRealtimeNs() - elapsedTimeNs);

        return true;

    }

    if (mMinPullIntervalNs > elapsedTimeNs - mLastPullTimeNs) {
@@ -55,7 +56,9 @@ bool StatsPuller::Pull(const int64_t elapsedTimeNs, std::vector<std::shared_ptr< 
    }

    mCachedData.clear();

    mLastPullTimeNs = elapsedTimeNs;

    int64_t pullStartTimeNs = getElapsedRealtimeNs();

    bool ret = PullInternal(&mCachedData);

    StatsdStats::getInstance().notePullTime(mTagId, getElapsedRealtimeNs() - pullStartTimeNs);

    for (const shared_ptr<LogEvent>& data : mCachedData) {

        data->setElapsedTimestampNs(elapsedTimeNs);

        data->setLogdWallClockTimestampNs(wallClockTimeNs);
@@ -64,6 +67,7 @@ bool StatsPuller::Pull(const int64_t elapsedTimeNs, std::vector<std::shared_ptr< 
      mergeIsolatedUidsToHostUid(mCachedData, mUidMap, mTagId);

      (*data) = mCachedData;

    }

    StatsdStats::getInstance().notePullDelay(mTagId, getElapsedRealtimeNs() - elapsedTimeNs);

    return ret;

}

cmds/statsd/src/guardrail/StatsdStats.cpp

+38 −3
Original line number Diff line number Diff line
@@ -335,7 +335,8 @@ void StatsdStats::noteRegisteredPeriodicAlarmChanged() { 


void StatsdStats::updateMinPullIntervalSec(int pullAtomId, long intervalSec) {

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

    mPulledAtomStats[pullAtomId].minPullIntervalSec = intervalSec;

    mPulledAtomStats[pullAtomId].minPullIntervalSec =

            std::min(mPulledAtomStats[pullAtomId].minPullIntervalSec, intervalSec);

}



void StatsdStats::notePull(int pullAtomId) {
@@ -348,6 +349,24 @@ void StatsdStats::notePullFromCache(int pullAtomId) { 
    mPulledAtomStats[pullAtomId].totalPullFromCache++;

}



void StatsdStats::notePullTime(int pullAtomId, int64_t pullTimeNs) {

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

    auto& pullStats = mPulledAtomStats[pullAtomId];

    pullStats.maxPullTimeNs = std::max(pullStats.maxPullTimeNs, pullTimeNs);

    pullStats.avgPullTimeNs = (pullStats.avgPullTimeNs * pullStats.numPullTime + pullTimeNs) /

                              (pullStats.numPullTime + 1);

    pullStats.numPullTime += 1;

}



void StatsdStats::notePullDelay(int pullAtomId, int64_t pullDelayNs) {

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

    auto& pullStats = mPulledAtomStats[pullAtomId];

    pullStats.maxPullDelayNs = std::max(pullStats.maxPullDelayNs, pullDelayNs);

    pullStats.avgPullDelayNs = (pullStats.avgPullDelayNs * pullStats.numPullDelay + pullDelayNs) /

                               (pullStats.numPullDelay + 1);

    pullStats.numPullDelay += 1;

}



void StatsdStats::noteAtomLogged(int atomId, int32_t timeSec) {

    lock_guard<std::mutex> lock(mLock);
@@ -394,6 +413,16 @@ void StatsdStats::resetInternalLocked() { 
        config.second->metric_dimension_in_condition_stats.clear();

        config.second->alert_stats.clear();

    }

    for (auto& pullStats : mPulledAtomStats) {

        pullStats.second.totalPull = 0;

        pullStats.second.totalPullFromCache = 0;

        pullStats.second.avgPullTimeNs = 0;

        pullStats.second.maxPullTimeNs = 0;

        pullStats.second.numPullTime = 0;

        pullStats.second.avgPullDelayNs = 0;

        pullStats.second.maxPullDelayNs = 0;

        pullStats.second.numPullDelay = 0;

    }

}



string buildTimeString(int64_t timeSec) {
@@ -498,8 +527,14 @@ void StatsdStats::dumpStats(int out) const { 


    dprintf(out, "********Pulled Atom stats***********\n");

    for (const auto& pair : mPulledAtomStats) {

        dprintf(out, "Atom %d->%ld, %ld, %ld\n", (int)pair.first, (long)pair.second.totalPull,

                (long)pair.second.totalPullFromCache, (long)pair.second.minPullIntervalSec);

        dprintf(out,

                "Atom %d->(total pull)%ld, (pull from cache)%ld, (min pull interval)%ld, (average "

                "pull time nanos)%lld, (max pull time nanos)%lld, (average pull delay nanos)%lld, "

                "(max pull delay nanos)%lld\n",

                (int)pair.first, (long)pair.second.totalPull, (long)pair.second.totalPullFromCache,

                (long)pair.second.minPullIntervalSec, (long long)pair.second.avgPullTimeNs,

                (long long)pair.second.maxPullTimeNs, (long long)pair.second.avgPullDelayNs,

                (long long)pair.second.maxPullDelayNs);

    }



    if (mAnomalyAlarmRegisteredStats > 0) {

cmds/statsd/src/guardrail/StatsdStats.h

+31 −6
Original line number Diff line number Diff line
@@ -263,15 +263,33 @@ public: 
    void setUidMapChanges(int changes);

    void setCurrentUidMapMemory(int bytes);



    // Update minimum interval between pulls for an pulled atom

    /*

     * Updates minimum interval between pulls for an pulled atom.

     */

    void updateMinPullIntervalSec(int pullAtomId, long intervalSec);



    // Notify pull request for an atom

    /*

     * Notes an atom is pulled.

     */

    void notePull(int pullAtomId);



    // Notify pull request for an atom served from cached data

    /*

     * Notes an atom is served from puller cache.

     */

    void notePullFromCache(int pullAtomId);



    /*

     * Records time for actual pulling, not including those served from cache and not including

     * statsd processing delays.

     */

    void notePullTime(int pullAtomId, int64_t pullTimeNs);



    /*

     * Records pull delay for a pulled atom, including those served from cache and including statsd

     * processing delays.

     */

    void notePullDelay(int pullAtomId, int64_t pullDelayNs);



    /*

     * Records when system server restarts.

     */
@@ -302,9 +320,15 @@ public: 
    void dumpStats(int outFd) const;



    typedef struct {

        long totalPull;

        long totalPullFromCache;

        long minPullIntervalSec;

        long totalPull = 0;

        long totalPullFromCache = 0;

        long minPullIntervalSec = LONG_MAX;

        int64_t avgPullTimeNs = 0;

        int64_t maxPullTimeNs = 0;

        long numPullTime = 0;

        int64_t avgPullDelayNs = 0;

        int64_t maxPullDelayNs = 0;

        long numPullDelay = 0;

    } PulledAtomStats;



private:
@@ -368,6 +392,7 @@ private: 
    FRIEND_TEST(StatsdStatsTest, TestTimestampThreshold);

    FRIEND_TEST(StatsdStatsTest, TestAnomalyMonitor);

    FRIEND_TEST(StatsdStatsTest, TestSystemServerCrash);

    FRIEND_TEST(StatsdStatsTest, TestPullAtomStats);

};



}  // namespace statsd

cmds/statsd/src/stats_log.proto

+4 −0
Original line number Diff line number Diff line
@@ -370,6 +370,10 @@ message StatsdStatsReport { 
        optional int64 total_pull = 2;

        optional int64 total_pull_from_cache = 3;

        optional int64 min_pull_interval_sec = 4;

        optional int64 average_pull_time_nanos = 5;

        optional int64 max_pull_time_nanos = 6;

        optional int64 average_pull_delay_nanos = 7;

        optional int64 max_pull_delay_nanos = 8;

    }

    repeated PulledAtomStats pulled_atom_stats = 10;

cmds/statsd/src/stats_log_util.cpp

+12 −0
Original line number Diff line number Diff line
@@ -59,6 +59,10 @@ const int FIELD_ID_PULL_ATOM_ID = 1; 
const int FIELD_ID_TOTAL_PULL = 2;

const int FIELD_ID_TOTAL_PULL_FROM_CACHE = 3;

const int FIELD_ID_MIN_PULL_INTERVAL_SEC = 4;

const int FIELD_ID_AVERAGE_PULL_TIME_NANOS = 5;

const int FIELD_ID_MAX_PULL_TIME_NANOS = 6;

const int FIELD_ID_AVERAGE_PULL_DELAY_NANOS = 7;

const int FIELD_ID_MAX_PULL_DELAY_NANOS = 8;



namespace {
@@ -434,6 +438,14 @@ void writePullerStatsToStream(const std::pair<int, StatsdStats::PulledAtomStats> 
                       (long long)pair.second.totalPullFromCache);

    protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_MIN_PULL_INTERVAL_SEC,

                       (long long)pair.second.minPullIntervalSec);

    protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_AVERAGE_PULL_TIME_NANOS,

                       (long long)pair.second.avgPullTimeNs);

    protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_MAX_PULL_TIME_NANOS,

                       (long long)pair.second.maxPullTimeNs);

    protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_AVERAGE_PULL_DELAY_NANOS,

                       (long long)pair.second.avgPullDelayNs);

    protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_MAX_PULL_DELAY_NANOS,

                       (long long)pair.second.maxPullDelayNs);

    protoOutput->end(token);

}