StatsdStats.cpp revision c8b7f2277c7d05dc0a1225dbed13ee85f18a6031 
1/*
2 * Copyright 2017, The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 *     http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16#define DEBUG true  // STOPSHIP if true
17#include "Log.h"
18
19#include "StatsdStats.h"
20
21#include <android/util/ProtoOutputStream.h>
22#include "../stats_log_util.h"
23#include "statslog.h"
24
25namespace android {
26namespace os {
27namespace statsd {
28
29using android::util::FIELD_COUNT_REPEATED;
30using android::util::FIELD_TYPE_BOOL;
31using android::util::FIELD_TYPE_FLOAT;
32using android::util::FIELD_TYPE_INT32;
33using android::util::FIELD_TYPE_INT64;
34using android::util::FIELD_TYPE_MESSAGE;
35using android::util::FIELD_TYPE_STRING;
36using android::util::ProtoOutputStream;
37using std::lock_guard;
38using std::map;
39using std::string;
40using std::vector;
41
42const int FIELD_ID_BEGIN_TIME = 1;
43const int FIELD_ID_END_TIME = 2;
44const int FIELD_ID_CONFIG_STATS = 3;
45const int FIELD_ID_ATOM_STATS = 7;
46const int FIELD_ID_UIDMAP_STATS = 8;
47const int FIELD_ID_ANOMALY_ALARM_STATS = 9;
48
49const int FIELD_ID_MATCHER_STATS_NAME = 1;
50const int FIELD_ID_MATCHER_STATS_COUNT = 2;
51
52const int FIELD_ID_CONDITION_STATS_NAME = 1;
53const int FIELD_ID_CONDITION_STATS_COUNT = 2;
54
55const int FIELD_ID_METRIC_STATS_NAME = 1;
56const int FIELD_ID_METRIC_STATS_COUNT = 2;
57
58const int FIELD_ID_ATOM_STATS_TAG = 1;
59const int FIELD_ID_ATOM_STATS_COUNT = 2;
60
61const int FIELD_ID_ANOMALY_ALARMS_REGISTERED = 1;
62
63std::map<int, long> StatsdStats::kPullerCooldownMap = {
64        {android::util::KERNEL_WAKELOCK, 1},
65        {android::util::WIFI_BYTES_TRANSFER, 1},
66        {android::util::MOBILE_BYTES_TRANSFER, 1},
67        {android::util::WIFI_BYTES_TRANSFER_BY_FG_BG, 1},
68        {android::util::MOBILE_BYTES_TRANSFER_BY_FG_BG, 1},
69        {android::util::SUBSYSTEM_SLEEP_STATE, 1},
70        {android::util::CPU_TIME_PER_FREQ, 1},
71        {android::util::CPU_TIME_PER_UID, 1},
72        {android::util::CPU_TIME_PER_UID_FREQ, 1},
73};
74
75// TODO: add stats for pulled atoms.
76StatsdStats::StatsdStats() {
77    mPushedAtomStats.resize(android::util::kMaxPushedAtomId + 1);
78    mStartTimeSec = time(nullptr);
79}
80
81StatsdStats& StatsdStats::getInstance() {
82    static StatsdStats statsInstance;
83    return statsInstance;
84}
85
86void StatsdStats::addToIceBoxLocked(const StatsdStatsReport_ConfigStats& stats) {
87    // The size of mIceBox grows strictly by one at a time. It won't be > kMaxIceBoxSize.
88    if (mIceBox.size() == kMaxIceBoxSize) {
89        mIceBox.pop_front();
90    }
91    mIceBox.push_back(stats);
92}
93
94void StatsdStats::noteConfigReceived(const ConfigKey& key, int metricsCount, int conditionsCount,
95                                     int matchersCount, int alertsCount, bool isValid) {
96    lock_guard<std::mutex> lock(mLock);
97    int32_t nowTimeSec = time(nullptr);
98
99    // If there is an existing config for the same key, icebox the old config.
100    noteConfigRemovedInternalLocked(key);
101
102    StatsdStatsReport_ConfigStats configStats;
103    configStats.set_uid(key.GetUid());
104    configStats.set_id(key.GetId());
105    configStats.set_creation_time_sec(nowTimeSec);
106    configStats.set_metric_count(metricsCount);
107    configStats.set_condition_count(conditionsCount);
108    configStats.set_matcher_count(matchersCount);
109    configStats.set_alert_count(alertsCount);
110    configStats.set_is_valid(isValid);
111
112    if (isValid) {
113        mConfigStats[key] = configStats;
114    } else {
115        configStats.set_deletion_time_sec(nowTimeSec);
116        addToIceBoxLocked(configStats);
117    }
118}
119
120void StatsdStats::noteConfigRemovedInternalLocked(const ConfigKey& key) {
121    auto it = mConfigStats.find(key);
122    if (it != mConfigStats.end()) {
123        int32_t nowTimeSec = time(nullptr);
124        it->second.set_deletion_time_sec(nowTimeSec);
125        // Add condition stats, metrics stats, matcher stats, alert stats
126        addSubStatsToConfigLocked(key, it->second);
127        // Remove them after they are added to the config stats.
128        mMatcherStats.erase(key);
129        mMetricsStats.erase(key);
130        mAlertStats.erase(key);
131        mConditionStats.erase(key);
132        addToIceBoxLocked(it->second);
133        mConfigStats.erase(it);
134    }
135}
136
137void StatsdStats::noteConfigRemoved(const ConfigKey& key) {
138    lock_guard<std::mutex> lock(mLock);
139    noteConfigRemovedInternalLocked(key);
140}
141
142void StatsdStats::noteBroadcastSent(const ConfigKey& key) {
143    noteBroadcastSent(key, time(nullptr));
144}
145
146void StatsdStats::noteBroadcastSent(const ConfigKey& key, int32_t timeSec) {
147    lock_guard<std::mutex> lock(mLock);
148    auto it = mConfigStats.find(key);
149    if (it == mConfigStats.end()) {
150        ALOGE("Config key %s not found!", key.ToString().c_str());
151        return;
152    }
153    if (it->second.broadcast_sent_time_sec_size() >= kMaxTimestampCount) {
154        auto timestampList = it->second.mutable_broadcast_sent_time_sec();
155        // This is O(N) operation. It shouldn't happen often, and N is only 20.
156        timestampList->erase(timestampList->begin());
157    }
158    it->second.add_broadcast_sent_time_sec(timeSec);
159}
160
161void StatsdStats::noteDataDropped(const ConfigKey& key) {
162    noteDataDropped(key, time(nullptr));
163}
164
165void StatsdStats::noteDataDropped(const ConfigKey& key, int32_t timeSec) {
166    lock_guard<std::mutex> lock(mLock);
167    auto it = mConfigStats.find(key);
168    if (it == mConfigStats.end()) {
169        ALOGE("Config key %s not found!", key.ToString().c_str());
170        return;
171    }
172    if (it->second.data_drop_time_sec_size() >= kMaxTimestampCount) {
173        auto timestampList = it->second.mutable_data_drop_time_sec();
174        // This is O(N) operation. It shouldn't happen often, and N is only 20.
175        timestampList->erase(timestampList->begin());
176    }
177    it->second.add_data_drop_time_sec(timeSec);
178}
179
180void StatsdStats::noteMetricsReportSent(const ConfigKey& key) {
181    noteMetricsReportSent(key, time(nullptr));
182}
183
184void StatsdStats::noteMetricsReportSent(const ConfigKey& key, int32_t timeSec) {
185    lock_guard<std::mutex> lock(mLock);
186    auto it = mConfigStats.find(key);
187    if (it == mConfigStats.end()) {
188        ALOGE("Config key %s not found!", key.ToString().c_str());
189        return;
190    }
191    if (it->second.dump_report_time_sec_size() >= kMaxTimestampCount) {
192        auto timestampList = it->second.mutable_dump_report_time_sec();
193        // This is O(N) operation. It shouldn't happen often, and N is only 20.
194        timestampList->erase(timestampList->begin());
195    }
196    it->second.add_dump_report_time_sec(timeSec);
197}
198
199void StatsdStats::noteUidMapDropped(int snapshots, int deltas) {
200    lock_guard<std::mutex> lock(mLock);
201    mUidMapStats.set_dropped_snapshots(mUidMapStats.dropped_snapshots() + snapshots);
202    mUidMapStats.set_dropped_changes(mUidMapStats.dropped_changes() + deltas);
203}
204
205void StatsdStats::setUidMapSnapshots(int snapshots) {
206    lock_guard<std::mutex> lock(mLock);
207    mUidMapStats.set_snapshots(snapshots);
208}
209
210void StatsdStats::setUidMapChanges(int changes) {
211    lock_guard<std::mutex> lock(mLock);
212    mUidMapStats.set_changes(changes);
213}
214
215void StatsdStats::setCurrentUidMapMemory(int bytes) {
216    lock_guard<std::mutex> lock(mLock);
217    mUidMapStats.set_bytes_used(bytes);
218}
219
220void StatsdStats::noteConditionDimensionSize(const ConfigKey& key, const int64_t& id, int size) {
221    lock_guard<std::mutex> lock(mLock);
222    // if name doesn't exist before, it will create the key with count 0.
223    auto& conditionSizeMap = mConditionStats[key];
224    if (size > conditionSizeMap[id]) {
225        conditionSizeMap[id] = size;
226    }
227}
228
229void StatsdStats::noteMetricDimensionSize(const ConfigKey& key, const int64_t& id, int size) {
230    lock_guard<std::mutex> lock(mLock);
231    // if name doesn't exist before, it will create the key with count 0.
232    auto& metricsDimensionMap = mMetricsStats[key];
233    if (size > metricsDimensionMap[id]) {
234        metricsDimensionMap[id] = size;
235    }
236}
237
238void StatsdStats::noteMatcherMatched(const ConfigKey& key, const int64_t& id) {
239    lock_guard<std::mutex> lock(mLock);
240    auto& matcherStats = mMatcherStats[key];
241    matcherStats[id]++;
242}
243
244void StatsdStats::noteAnomalyDeclared(const ConfigKey& key, const int64_t& id) {
245    lock_guard<std::mutex> lock(mLock);
246    auto& alertStats = mAlertStats[key];
247    alertStats[id]++;
248}
249
250void StatsdStats::noteRegisteredAnomalyAlarmChanged() {
251    lock_guard<std::mutex> lock(mLock);
252    mAnomalyAlarmRegisteredStats++;
253}
254
255void StatsdStats::updateMinPullIntervalSec(int pullAtomId, long intervalSec) {
256    lock_guard<std::mutex> lock(mLock);
257    mPulledAtomStats[pullAtomId].minPullIntervalSec = intervalSec;
258}
259
260void StatsdStats::notePull(int pullAtomId) {
261    lock_guard<std::mutex> lock(mLock);
262    mPulledAtomStats[pullAtomId].totalPull++;
263}
264
265void StatsdStats::notePullFromCache(int pullAtomId) {
266    lock_guard<std::mutex> lock(mLock);
267    mPulledAtomStats[pullAtomId].totalPullFromCache++;
268}
269
270void StatsdStats::noteAtomLogged(int atomId, int32_t timeSec) {
271    lock_guard<std::mutex> lock(mLock);
272
273    if (timeSec < mStartTimeSec) {
274        return;
275    }
276
277    if (atomId > android::util::kMaxPushedAtomId) {
278        ALOGW("not interested in atom %d", atomId);
279        return;
280    }
281
282    mPushedAtomStats[atomId]++;
283}
284
285void StatsdStats::reset() {
286    lock_guard<std::mutex> lock(mLock);
287    resetInternalLocked();
288}
289
290void StatsdStats::resetInternalLocked() {
291    // Reset the historical data, but keep the active ConfigStats
292    mStartTimeSec = time(nullptr);
293    mIceBox.clear();
294    mConditionStats.clear();
295    mMetricsStats.clear();
296    std::fill(mPushedAtomStats.begin(), mPushedAtomStats.end(), 0);
297    mAlertStats.clear();
298    mAnomalyAlarmRegisteredStats = 0;
299    mMatcherStats.clear();
300    for (auto& config : mConfigStats) {
301        config.second.clear_broadcast_sent_time_sec();
302        config.second.clear_data_drop_time_sec();
303        config.second.clear_dump_report_time_sec();
304        config.second.clear_matcher_stats();
305        config.second.clear_condition_stats();
306        config.second.clear_metric_stats();
307        config.second.clear_alert_stats();
308    }
309}
310
311void StatsdStats::addSubStatsToConfigLocked(const ConfigKey& key,
312                                      StatsdStatsReport_ConfigStats& configStats) {
313    // Add matcher stats
314    if (mMatcherStats.find(key) != mMatcherStats.end()) {
315        const auto& matcherStats = mMatcherStats[key];
316        for (const auto& stats : matcherStats) {
317            auto output = configStats.add_matcher_stats();
318            output->set_id(stats.first);
319            output->set_matched_times(stats.second);
320            VLOG("matcher %lld matched %d times",
321                (long long)stats.first, stats.second);
322        }
323    }
324    // Add condition stats
325    if (mConditionStats.find(key) != mConditionStats.end()) {
326        const auto& conditionStats = mConditionStats[key];
327        for (const auto& stats : conditionStats) {
328            auto output = configStats.add_condition_stats();
329            output->set_id(stats.first);
330            output->set_max_tuple_counts(stats.second);
331            VLOG("condition %lld max output tuple size %d",
332                (long long)stats.first, stats.second);
333        }
334    }
335    // Add metrics stats
336    if (mMetricsStats.find(key) != mMetricsStats.end()) {
337        const auto& conditionStats = mMetricsStats[key];
338        for (const auto& stats : conditionStats) {
339            auto output = configStats.add_metric_stats();
340            output->set_id(stats.first);
341            output->set_max_tuple_counts(stats.second);
342            VLOG("metrics %lld max output tuple size %d",
343                (long long)stats.first, stats.second);
344        }
345    }
346    // Add anomaly detection alert stats
347    if (mAlertStats.find(key) != mAlertStats.end()) {
348        const auto& alertStats = mAlertStats[key];
349        for (const auto& stats : alertStats) {
350            auto output = configStats.add_alert_stats();
351            output->set_id(stats.first);
352            output->set_alerted_times(stats.second);
353            VLOG("alert %lld declared %d times", (long long)stats.first, stats.second);
354        }
355    }
356}
357
358void StatsdStats::dumpStats(std::vector<uint8_t>* output, bool reset) {
359    lock_guard<std::mutex> lock(mLock);
360
361    if (DEBUG) {
362        time_t t = mStartTimeSec;
363        struct tm* tm = localtime(&t);
364        char timeBuffer[80];
365        strftime(timeBuffer, sizeof(timeBuffer), "%Y-%m-%d %I:%M%p", tm);
366        VLOG("=================StatsdStats dump begins====================");
367        VLOG("Stats collection start second: %s", timeBuffer);
368    }
369    ProtoOutputStream proto;
370    proto.write(FIELD_TYPE_INT32 | FIELD_ID_BEGIN_TIME, mStartTimeSec);
371    proto.write(FIELD_TYPE_INT32 | FIELD_ID_END_TIME, (int32_t)time(nullptr));
372
373    VLOG("%lu Config in icebox: ", (unsigned long)mIceBox.size());
374    for (const auto& configStats : mIceBox) {
375        const int numBytes = configStats.ByteSize();
376        vector<char> buffer(numBytes);
377        configStats.SerializeToArray(&buffer[0], numBytes);
378        proto.write(FIELD_TYPE_MESSAGE | FIELD_COUNT_REPEATED | FIELD_ID_CONFIG_STATS, &buffer[0],
379                    buffer.size());
380
381        // surround the whole block with DEBUG, so that compiler can strip out the code
382        // in production.
383        if (DEBUG) {
384            VLOG("*****ICEBOX*****");
385            VLOG("Config {%d-%lld}: creation=%d, deletion=%d, #metric=%d, #condition=%d, "
386                 "#matcher=%d, #alert=%d,  #valid=%d",
387                 configStats.uid(), (long long)configStats.id(), configStats.creation_time_sec(),
388                 configStats.deletion_time_sec(), configStats.metric_count(),
389                 configStats.condition_count(), configStats.matcher_count(),
390                 configStats.alert_count(), configStats.is_valid());
391
392            for (const auto& broadcastTime : configStats.broadcast_sent_time_sec()) {
393                VLOG("\tbroadcast time: %d", broadcastTime);
394            }
395
396            for (const auto& dataDropTime : configStats.data_drop_time_sec()) {
397                VLOG("\tdata drop time: %d", dataDropTime);
398            }
399        }
400    }
401
402    for (auto& pair : mConfigStats) {
403        auto& configStats = pair.second;
404        if (DEBUG) {
405            VLOG("********Active Configs***********");
406            VLOG("Config {%d-%lld}: creation=%d, deletion=%d, #metric=%d, #condition=%d, "
407                 "#matcher=%d, #alert=%d,  #valid=%d",
408                 configStats.uid(), (long long)configStats.id(), configStats.creation_time_sec(),
409                 configStats.deletion_time_sec(), configStats.metric_count(),
410                 configStats.condition_count(), configStats.matcher_count(),
411                 configStats.alert_count(), configStats.is_valid());
412            for (const auto& broadcastTime : configStats.broadcast_sent_time_sec()) {
413                VLOG("\tbroadcast time: %d", broadcastTime);
414            }
415
416            for (const auto& dataDropTime : configStats.data_drop_time_sec()) {
417                VLOG("\tdata drop time: %d", dataDropTime);
418            }
419
420            for (const auto& dumpTime : configStats.dump_report_time_sec()) {
421                VLOG("\tdump report time: %d", dumpTime);
422            }
423        }
424
425        addSubStatsToConfigLocked(pair.first, configStats);
426
427        const int numBytes = configStats.ByteSize();
428        vector<char> buffer(numBytes);
429        configStats.SerializeToArray(&buffer[0], numBytes);
430        proto.write(FIELD_TYPE_MESSAGE | FIELD_COUNT_REPEATED | FIELD_ID_CONFIG_STATS, &buffer[0],
431                    buffer.size());
432        // reset the sub stats, the source of truth is in the individual map
433        // they will be repopulated when dumpStats() is called again.
434        configStats.clear_matcher_stats();
435        configStats.clear_condition_stats();
436        configStats.clear_metric_stats();
437        configStats.clear_alert_stats();
438    }
439
440    VLOG("********Pushed Atom stats***********");
441    const size_t atomCounts = mPushedAtomStats.size();
442    for (size_t i = 2; i < atomCounts; i++) {
443        if (mPushedAtomStats[i] > 0) {
444            long long token =
445                    proto.start(FIELD_TYPE_MESSAGE | FIELD_ID_ATOM_STATS | FIELD_COUNT_REPEATED);
446            proto.write(FIELD_TYPE_INT32 | FIELD_ID_ATOM_STATS_TAG, (int32_t)i);
447            proto.write(FIELD_TYPE_INT32 | FIELD_ID_ATOM_STATS_COUNT, mPushedAtomStats[i]);
448            proto.end(token);
449
450            VLOG("Atom %lu->%d\n", (unsigned long)i, mPushedAtomStats[i]);
451        }
452    }
453
454    VLOG("********Pulled Atom stats***********");
455    for (const auto& pair : mPulledAtomStats) {
456        android::os::statsd::writePullerStatsToStream(pair, &proto);
457        VLOG("Atom %d->%ld, %ld, %ld\n", (int) pair.first, (long) pair.second.totalPull, (long) pair.second.totalPullFromCache, (long) pair.second.minPullIntervalSec);
458    }
459
460    if (mAnomalyAlarmRegisteredStats > 0) {
461        VLOG("********AnomalyAlarmStats stats***********");
462        long long token = proto.start(FIELD_TYPE_MESSAGE | FIELD_ID_ANOMALY_ALARM_STATS);
463        proto.write(FIELD_TYPE_INT32 | FIELD_ID_ANOMALY_ALARMS_REGISTERED,
464                    mAnomalyAlarmRegisteredStats);
465        proto.end(token);
466        VLOG("Anomaly alarm registrations: %d", mAnomalyAlarmRegisteredStats);
467    }
468
469    const int numBytes = mUidMapStats.ByteSize();
470    vector<char> buffer(numBytes);
471    mUidMapStats.SerializeToArray(&buffer[0], numBytes);
472    proto.write(FIELD_TYPE_MESSAGE | FIELD_ID_UIDMAP_STATS, &buffer[0], buffer.size());
473    VLOG("UID map stats: bytes=%d, snapshots=%d, changes=%d, snapshots lost=%d, changes "
474         "lost=%d",
475         mUidMapStats.bytes_used(), mUidMapStats.snapshots(), mUidMapStats.changes(),
476         mUidMapStats.dropped_snapshots(), mUidMapStats.dropped_changes());
477
478    output->clear();
479    size_t bufferSize = proto.size();
480    output->resize(bufferSize);
481
482    size_t pos = 0;
483    auto it = proto.data();
484    while (it.readBuffer() != NULL) {
485        size_t toRead = it.currentToRead();
486        std::memcpy(&((*output)[pos]), it.readBuffer(), toRead);
487        pos += toRead;
488        it.rp()->move(toRead);
489    }
490
491    if (reset) {
492        resetInternalLocked();
493    }
494
495    VLOG("reset=%d, returned proto size %lu", reset, (unsigned long)bufferSize);
496    VLOG("=================StatsdStats dump ends====================");
497}
498
499}  // namespace statsd
500}  // namespace os
501}  // namespace android