StatsLogProcessor.cpp revision aab45c1d09d3191a1289fb9d0408bfc2cfe7cf98 
1/*
2 * Copyright (C) 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
17#define DEBUG true  // STOPSHIP if true
18#include "Log.h"
19#include "statslog.h"
20
21#include <android-base/file.h>
22#include <dirent.h>
23#include "StatsLogProcessor.h"
24#include "android-base/stringprintf.h"
25#include "guardrail/StatsdStats.h"
26#include "metrics/CountMetricProducer.h"
27#include "external/StatsPullerManager.h"
28#include "stats_util.h"
29#include "storage/StorageManager.h"
30
31#include <log/log_event_list.h>
32#include <utils/Errors.h>
33#include <utils/SystemClock.h>
34
35using namespace android;
36using android::base::StringPrintf;
37using android::util::FIELD_COUNT_REPEATED;
38using android::util::FIELD_TYPE_BOOL;
39using android::util::FIELD_TYPE_FLOAT;
40using android::util::FIELD_TYPE_INT32;
41using android::util::FIELD_TYPE_INT64;
42using android::util::FIELD_TYPE_MESSAGE;
43using android::util::FIELD_TYPE_STRING;
44using android::util::ProtoOutputStream;
45using std::make_unique;
46using std::unique_ptr;
47using std::vector;
48
49namespace android {
50namespace os {
51namespace statsd {
52
53// for ConfigMetricsReportList
54const int FIELD_ID_CONFIG_KEY = 1;
55const int FIELD_ID_REPORTS = 2;
56// for ConfigKey
57const int FIELD_ID_UID = 1;
58const int FIELD_ID_ID = 2;
59// for ConfigMetricsReport
60const int FIELD_ID_METRICS = 1;
61const int FIELD_ID_UID_MAP = 2;
62const int FIELD_ID_LAST_REPORT_NANOS = 3;
63const int FIELD_ID_CURRENT_REPORT_NANOS = 4;
64
65#define STATS_DATA_DIR "/data/misc/stats-data"
66
67StatsLogProcessor::StatsLogProcessor(const sp<UidMap>& uidMap,
68                                     const sp<AnomalyMonitor>& anomalyMonitor,
69                                     const long timeBaseSec,
70                                     const std::function<void(const ConfigKey&)>& sendBroadcast)
71    : mUidMap(uidMap),
72      mAnomalyMonitor(anomalyMonitor),
73      mSendBroadcast(sendBroadcast),
74      mTimeBaseSec(timeBaseSec) {
75    StatsPullerManager statsPullerManager;
76    statsPullerManager.SetTimeBaseSec(mTimeBaseSec);
77}
78
79StatsLogProcessor::~StatsLogProcessor() {
80}
81
82void StatsLogProcessor::onAnomalyAlarmFired(
83        const uint64_t timestampNs,
84        unordered_set<sp<const AnomalyAlarm>, SpHash<AnomalyAlarm>> anomalySet) {
85    std::lock_guard<std::mutex> lock(mMetricsMutex);
86    for (const auto& itr : mMetricsManagers) {
87        itr.second->onAnomalyAlarmFired(timestampNs, anomalySet);
88    }
89}
90
91void updateUid(Value* value, int hostUid) {
92    int uid = value->int_value;
93    if (uid != hostUid) {
94        value->setInt(hostUid);
95    }
96}
97
98void StatsLogProcessor::mapIsolatedUidToHostUidIfNecessaryLocked(LogEvent* event) const {
99    if (android::util::kAtomsWithAttributionChain.find(event->GetTagId()) !=
100        android::util::kAtomsWithAttributionChain.end()) {
101        for (auto& value : *(event->getMutableValues())) {
102            if (value.mField.getPosAtDepth(0) > kAttributionField) {
103                break;
104            }
105            if (isAttributionUidField(value)) {
106                const int hostUid = mUidMap->getHostUidOrSelf(value.mValue.int_value);
107                updateUid(&value.mValue, hostUid);
108            }
109        }
110    } else if (android::util::kAtomsWithUidField.find(event->GetTagId()) !=
111                       android::util::kAtomsWithUidField.end() &&
112               event->getValues().size() > 0 && (event->getValues())[0].mValue.getType() == INT) {
113        Value& value = (*event->getMutableValues())[0].mValue;
114        const int hostUid = mUidMap->getHostUidOrSelf(value.int_value);
115        updateUid(&value, hostUid);
116    }
117}
118
119void StatsLogProcessor::onIsolatedUidChangedEventLocked(const LogEvent& event) {
120    status_t err = NO_ERROR, err2 = NO_ERROR, err3 = NO_ERROR;
121    bool is_create = event.GetBool(3, &err);
122    auto parent_uid = int(event.GetLong(1, &err2));
123    auto isolated_uid = int(event.GetLong(2, &err3));
124    if (err == NO_ERROR && err2 == NO_ERROR && err3 == NO_ERROR) {
125        if (is_create) {
126            mUidMap->assignIsolatedUid(isolated_uid, parent_uid);
127        } else {
128            mUidMap->removeIsolatedUid(isolated_uid, parent_uid);
129        }
130    } else {
131        ALOGE("Failed to parse uid in the isolated uid change event.");
132    }
133}
134
135// TODO: what if statsd service restarts? How do we know what logs are already processed before?
136void StatsLogProcessor::OnLogEvent(LogEvent* event) {
137    std::lock_guard<std::mutex> lock(mMetricsMutex);
138    StatsdStats::getInstance().noteAtomLogged(
139        event->GetTagId(), event->GetTimestampNs() / NS_PER_SEC);
140
141    // Hard-coded logic to update the isolated uid's in the uid-map.
142    // The field numbers need to be currently updated by hand with atoms.proto
143    if (event->GetTagId() == android::util::ISOLATED_UID_CHANGED) {
144        onIsolatedUidChangedEventLocked(*event);
145    }
146
147    if (mMetricsManagers.empty()) {
148        return;
149    }
150
151    long curTime = time(nullptr);
152    if (curTime - mLastPullerCacheClearTimeSec > StatsdStats::kPullerCacheClearIntervalSec) {
153        mStatsPullerManager.ClearPullerCacheIfNecessary(curTime);
154        mLastPullerCacheClearTimeSec = curTime;
155    }
156
157    if (event->GetTagId() != android::util::ISOLATED_UID_CHANGED) {
158        // Map the isolated uid to host uid if necessary.
159        mapIsolatedUidToHostUidIfNecessaryLocked(event);
160    }
161
162    // pass the event to metrics managers.
163    for (auto& pair : mMetricsManagers) {
164        pair.second->onLogEvent(*event);
165        flushIfNecessaryLocked(event->GetTimestampNs(), pair.first, *(pair.second));
166    }
167}
168
169void StatsLogProcessor::OnConfigUpdated(const ConfigKey& key, const StatsdConfig& config) {
170    std::lock_guard<std::mutex> lock(mMetricsMutex);
171    VLOG("Updated configuration for key %s", key.ToString().c_str());
172    sp<MetricsManager> newMetricsManager = new MetricsManager(key, config, mTimeBaseSec, mUidMap);
173    auto it = mMetricsManagers.find(key);
174    if (it == mMetricsManagers.end() && mMetricsManagers.size() > StatsdStats::kMaxConfigCount) {
175        ALOGE("Can't accept more configs!");
176        return;
177    }
178
179    if (newMetricsManager->isConfigValid()) {
180        mUidMap->OnConfigUpdated(key);
181        newMetricsManager->setAnomalyMonitor(mAnomalyMonitor);
182        if (newMetricsManager->shouldAddUidMapListener()) {
183            // We have to add listener after the MetricsManager is constructed because it's
184            // not safe to create wp or sp from this pointer inside its constructor.
185            mUidMap->addListener(newMetricsManager.get());
186        }
187        mMetricsManagers[key] = newMetricsManager;
188        // Why doesn't this work? mMetricsManagers.insert({key, std::move(newMetricsManager)});
189        VLOG("StatsdConfig valid");
190    } else {
191        // If there is any error in the config, don't use it.
192        ALOGE("StatsdConfig NOT valid");
193    }
194}
195
196size_t StatsLogProcessor::GetMetricsSize(const ConfigKey& key) const {
197    std::lock_guard<std::mutex> lock(mMetricsMutex);
198    auto it = mMetricsManagers.find(key);
199    if (it == mMetricsManagers.end()) {
200        ALOGW("Config source %s does not exist", key.ToString().c_str());
201        return 0;
202    }
203    return it->second->byteSize();
204}
205
206void StatsLogProcessor::dumpStates(FILE* out, bool verbose) {
207    std::lock_guard<std::mutex> lock(mMetricsMutex);
208    fprintf(out, "MetricsManager count: %lu\n", (unsigned long)mMetricsManagers.size());
209    for (auto metricsManager : mMetricsManagers) {
210        metricsManager.second->dumpStates(out, verbose);
211    }
212}
213
214void StatsLogProcessor::onDumpReport(const ConfigKey& key, const uint64_t dumpTimeStampNs,
215                                     vector<uint8_t>* outData) {
216    std::lock_guard<std::mutex> lock(mMetricsMutex);
217    onDumpReportLocked(key, dumpTimeStampNs, outData);
218}
219
220void StatsLogProcessor::onDumpReportLocked(const ConfigKey& key, const uint64_t dumpTimeStampNs,
221                                           vector<uint8_t>* outData) {
222    auto it = mMetricsManagers.find(key);
223    if (it == mMetricsManagers.end()) {
224        ALOGW("Config source %s does not exist", key.ToString().c_str());
225        return;
226    }
227
228    // This allows another broadcast to be sent within the rate-limit period if we get close to
229    // filling the buffer again soon.
230    mLastBroadcastTimes.erase(key);
231
232    ProtoOutputStream proto;
233
234    // Start of ConfigKey.
235    long long configKeyToken = proto.start(FIELD_TYPE_MESSAGE | FIELD_ID_CONFIG_KEY);
236    proto.write(FIELD_TYPE_INT32 | FIELD_ID_UID, key.GetUid());
237    proto.write(FIELD_TYPE_INT64 | FIELD_ID_ID, (long long)key.GetId());
238    proto.end(configKeyToken);
239    // End of ConfigKey.
240
241    // Start of ConfigMetricsReport (reports).
242    long long reportsToken =
243            proto.start(FIELD_TYPE_MESSAGE | FIELD_COUNT_REPEATED | FIELD_ID_REPORTS);
244
245    // First, fill in ConfigMetricsReport using current data on memory, which
246    // starts from filling in StatsLogReport's.
247    it->second->onDumpReport(dumpTimeStampNs, &proto);
248
249    // Fill in UidMap.
250    auto uidMap = mUidMap->getOutput(key);
251    const int uidMapSize = uidMap.ByteSize();
252    char uidMapBuffer[uidMapSize];
253    uidMap.SerializeToArray(&uidMapBuffer[0], uidMapSize);
254    proto.write(FIELD_TYPE_MESSAGE | FIELD_ID_UID_MAP, uidMapBuffer, uidMapSize);
255
256    // Fill in the timestamps.
257    proto.write(FIELD_TYPE_INT64 | FIELD_ID_LAST_REPORT_NANOS,
258                (long long)it->second->getLastReportTimeNs());
259    proto.write(FIELD_TYPE_INT64 | FIELD_ID_CURRENT_REPORT_NANOS,
260                (long long)::android::elapsedRealtimeNano());
261
262    // End of ConfigMetricsReport (reports).
263    proto.end(reportsToken);
264
265    // Then, check stats-data directory to see there's any file containing
266    // ConfigMetricsReport from previous shutdowns to concatenate to reports.
267    StorageManager::appendConfigMetricsReport(proto);
268
269    if (outData != nullptr) {
270        outData->clear();
271        outData->resize(proto.size());
272        size_t pos = 0;
273        auto iter = proto.data();
274        while (iter.readBuffer() != NULL) {
275            size_t toRead = iter.currentToRead();
276            std::memcpy(&((*outData)[pos]), iter.readBuffer(), toRead);
277            pos += toRead;
278            iter.rp()->move(toRead);
279        }
280    }
281
282    StatsdStats::getInstance().noteMetricsReportSent(key);
283}
284
285void StatsLogProcessor::OnConfigRemoved(const ConfigKey& key) {
286    std::lock_guard<std::mutex> lock(mMetricsMutex);
287    auto it = mMetricsManagers.find(key);
288    if (it != mMetricsManagers.end()) {
289        mMetricsManagers.erase(it);
290        mUidMap->OnConfigRemoved(key);
291    }
292    StatsdStats::getInstance().noteConfigRemoved(key);
293
294    mLastBroadcastTimes.erase(key);
295
296    if (mMetricsManagers.empty()) {
297        mStatsPullerManager.ForceClearPullerCache();
298    }
299}
300
301void StatsLogProcessor::flushIfNecessaryLocked(
302    uint64_t timestampNs, const ConfigKey& key, MetricsManager& metricsManager) {
303    auto lastCheckTime = mLastByteSizeTimes.find(key);
304    if (lastCheckTime != mLastByteSizeTimes.end()) {
305        if (timestampNs - lastCheckTime->second < StatsdStats::kMinByteSizeCheckPeriodNs) {
306            return;
307        }
308    }
309
310    // We suspect that the byteSize() computation is expensive, so we set a rate limit.
311    size_t totalBytes = metricsManager.byteSize();
312    mLastByteSizeTimes[key] = timestampNs;
313    if (totalBytes >
314        StatsdStats::kMaxMetricsBytesPerConfig) {  // Too late. We need to start clearing data.
315        // TODO(b/70571383): By 12/15/2017 add API to drop data directly
316        ProtoOutputStream proto;
317        metricsManager.onDumpReport(time(nullptr) * NS_PER_SEC, &proto);
318        StatsdStats::getInstance().noteDataDropped(key);
319        VLOG("StatsD had to toss out metrics for %s", key.ToString().c_str());
320    } else if (totalBytes > .9 * StatsdStats::kMaxMetricsBytesPerConfig) {
321        // Send broadcast so that receivers can pull data.
322        auto lastBroadcastTime = mLastBroadcastTimes.find(key);
323        if (lastBroadcastTime != mLastBroadcastTimes.end()) {
324            if (timestampNs - lastBroadcastTime->second < StatsdStats::kMinBroadcastPeriodNs) {
325                VLOG("StatsD would've sent a broadcast but the rate limit stopped us.");
326                return;
327            }
328        }
329        mLastBroadcastTimes[key] = timestampNs;
330        VLOG("StatsD requesting broadcast for %s", key.ToString().c_str());
331        mSendBroadcast(key);
332        StatsdStats::getInstance().noteBroadcastSent(key);
333    }
334}
335
336void StatsLogProcessor::WriteDataToDisk() {
337    std::lock_guard<std::mutex> lock(mMetricsMutex);
338    for (auto& pair : mMetricsManagers) {
339        const ConfigKey& key = pair.first;
340        vector<uint8_t> data;
341        onDumpReportLocked(key, time(nullptr) * NS_PER_SEC, &data);
342        // TODO: Add a guardrail to prevent accumulation of file on disk.
343        string file_name = StringPrintf("%s/%ld_%d_%lld", STATS_DATA_DIR, time(nullptr),
344                                        key.GetUid(), (long long)key.GetId());
345        StorageManager::writeFile(file_name.c_str(), &data[0], data.size());
346    }
347}
348
349}  // namespace statsd
350}  // namespace os
351}  // namespace android
352