| /* |
| * Copyright (C) 2017 The Android Open Source Project |
| * |
| * Licensed under the Apache License, Version 2.0 (the "License"); |
| * you may not use this file except in compliance with the License. |
| * You may obtain a copy of the License at |
| * |
| * http://www.apache.org/licenses/LICENSE-2.0 |
| * |
| * Unless required by applicable law or agreed to in writing, software |
| * distributed under the License is distributed on an "AS IS" BASIS, |
| * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| * See the License for the specific language governing permissions and |
| * limitations under the License. |
| */ |
| |
| #define DEBUG false // STOPSHIP if true |
| #include "Log.h" |
| |
| #include "StatsLogProcessor.h" |
| |
| #include <android-base/file.h> |
| #include <cutils/multiuser.h> |
| #include <frameworks/base/cmds/statsd/src/active_config_list.pb.h> |
| #include <frameworks/base/cmds/statsd/src/experiment_ids.pb.h> |
| |
| #include "android-base/stringprintf.h" |
| #include "atoms_info.h" |
| #include "external/StatsPullerManager.h" |
| #include "guardrail/StatsdStats.h" |
| #include "logd/LogEvent.h" |
| #include "metrics/CountMetricProducer.h" |
| #include "StatsService.h" |
| #include "state/StateManager.h" |
| #include "stats_log_util.h" |
| #include "stats_util.h" |
| #include "statslog.h" |
| #include "storage/StorageManager.h" |
| |
| using namespace android; |
| using android::base::StringPrintf; |
| using android::util::FIELD_COUNT_REPEATED; |
| using android::util::FIELD_TYPE_BOOL; |
| using android::util::FIELD_TYPE_FLOAT; |
| using android::util::FIELD_TYPE_INT32; |
| using android::util::FIELD_TYPE_INT64; |
| using android::util::FIELD_TYPE_MESSAGE; |
| using android::util::FIELD_TYPE_STRING; |
| using android::util::ProtoOutputStream; |
| using std::vector; |
| |
| namespace android { |
| namespace os { |
| namespace statsd { |
| |
| // for ConfigMetricsReportList |
| const int FIELD_ID_CONFIG_KEY = 1; |
| const int FIELD_ID_REPORTS = 2; |
| // for ConfigKey |
| const int FIELD_ID_UID = 1; |
| const int FIELD_ID_ID = 2; |
| // for ConfigMetricsReport |
| // const int FIELD_ID_METRICS = 1; // written in MetricsManager.cpp |
| const int FIELD_ID_UID_MAP = 2; |
| const int FIELD_ID_LAST_REPORT_ELAPSED_NANOS = 3; |
| const int FIELD_ID_CURRENT_REPORT_ELAPSED_NANOS = 4; |
| const int FIELD_ID_LAST_REPORT_WALL_CLOCK_NANOS = 5; |
| const int FIELD_ID_CURRENT_REPORT_WALL_CLOCK_NANOS = 6; |
| const int FIELD_ID_DUMP_REPORT_REASON = 8; |
| const int FIELD_ID_STRINGS = 9; |
| |
| // for ActiveConfigList |
| const int FIELD_ID_ACTIVE_CONFIG_LIST_CONFIG = 1; |
| |
| // for permissions checks |
| constexpr const char* kPermissionDump = "android.permission.DUMP"; |
| constexpr const char* kPermissionUsage = "android.permission.PACKAGE_USAGE_STATS"; |
| |
| #define NS_PER_HOUR 3600 * NS_PER_SEC |
| |
| #define STATS_ACTIVE_METRIC_DIR "/data/misc/stats-active-metric" |
| |
| // Cool down period for writing data to disk to avoid overwriting files. |
| #define WRITE_DATA_COOL_DOWN_SEC 5 |
| |
| StatsLogProcessor::StatsLogProcessor(const sp<UidMap>& uidMap, |
| const sp<StatsPullerManager>& pullerManager, |
| const sp<AlarmMonitor>& anomalyAlarmMonitor, |
| const sp<AlarmMonitor>& periodicAlarmMonitor, |
| const int64_t timeBaseNs, |
| const std::function<bool(const ConfigKey&)>& sendBroadcast, |
| const std::function<bool( |
| const int&, const vector<int64_t>&)>& activateBroadcast) |
| : mUidMap(uidMap), |
| mPullerManager(pullerManager), |
| mAnomalyAlarmMonitor(anomalyAlarmMonitor), |
| mPeriodicAlarmMonitor(periodicAlarmMonitor), |
| mSendBroadcast(sendBroadcast), |
| mSendActivationBroadcast(activateBroadcast), |
| mTimeBaseNs(timeBaseNs), |
| mLargestTimestampSeen(0), |
| mLastTimestampSeen(0) { |
| mPullerManager->ForceClearPullerCache(); |
| } |
| |
| StatsLogProcessor::~StatsLogProcessor() { |
| } |
| |
| static void flushProtoToBuffer(ProtoOutputStream& proto, vector<uint8_t>* outData) { |
| outData->clear(); |
| outData->resize(proto.size()); |
| size_t pos = 0; |
| sp<android::util::ProtoReader> reader = proto.data(); |
| while (reader->readBuffer() != NULL) { |
| size_t toRead = reader->currentToRead(); |
| std::memcpy(&((*outData)[pos]), reader->readBuffer(), toRead); |
| pos += toRead; |
| reader->move(toRead); |
| } |
| } |
| |
| void StatsLogProcessor::onAnomalyAlarmFired( |
| const int64_t& timestampNs, |
| unordered_set<sp<const InternalAlarm>, SpHash<InternalAlarm>> alarmSet) { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| for (const auto& itr : mMetricsManagers) { |
| itr.second->onAnomalyAlarmFired(timestampNs, alarmSet); |
| } |
| } |
| void StatsLogProcessor::onPeriodicAlarmFired( |
| const int64_t& timestampNs, |
| unordered_set<sp<const InternalAlarm>, SpHash<InternalAlarm>> alarmSet) { |
| |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| for (const auto& itr : mMetricsManagers) { |
| itr.second->onPeriodicAlarmFired(timestampNs, alarmSet); |
| } |
| } |
| |
| void updateUid(Value* value, int hostUid) { |
| int uid = value->int_value; |
| if (uid != hostUid) { |
| value->setInt(hostUid); |
| } |
| } |
| |
| void StatsLogProcessor::mapIsolatedUidToHostUidIfNecessaryLocked(LogEvent* event) const { |
| if (android::util::AtomsInfo::kAtomsWithAttributionChain.find(event->GetTagId()) != |
| android::util::AtomsInfo::kAtomsWithAttributionChain.end()) { |
| for (auto& value : *(event->getMutableValues())) { |
| if (value.mField.getPosAtDepth(0) > kAttributionField) { |
| break; |
| } |
| if (isAttributionUidField(value)) { |
| const int hostUid = mUidMap->getHostUidOrSelf(value.mValue.int_value); |
| updateUid(&value.mValue, hostUid); |
| } |
| } |
| } else { |
| auto it = android::util::AtomsInfo::kAtomsWithUidField.find(event->GetTagId()); |
| if (it != android::util::AtomsInfo::kAtomsWithUidField.end()) { |
| int uidField = it->second; // uidField is the field number in proto, |
| // starting from 1 |
| if (uidField > 0 && (int)event->getValues().size() >= uidField && |
| (event->getValues())[uidField - 1].mValue.getType() == INT) { |
| Value& value = (*event->getMutableValues())[uidField - 1].mValue; |
| const int hostUid = mUidMap->getHostUidOrSelf(value.int_value); |
| updateUid(&value, hostUid); |
| } else { |
| ALOGE("Malformed log, uid not found. %s", event->ToString().c_str()); |
| } |
| } |
| } |
| } |
| |
| void StatsLogProcessor::onIsolatedUidChangedEventLocked(const LogEvent& event) { |
| status_t err = NO_ERROR, err2 = NO_ERROR, err3 = NO_ERROR; |
| bool is_create = event.GetBool(3, &err); |
| auto parent_uid = int(event.GetLong(1, &err2)); |
| auto isolated_uid = int(event.GetLong(2, &err3)); |
| if (err == NO_ERROR && err2 == NO_ERROR && err3 == NO_ERROR) { |
| if (is_create) { |
| mUidMap->assignIsolatedUid(isolated_uid, parent_uid); |
| } else { |
| mUidMap->removeIsolatedUid(isolated_uid); |
| } |
| } else { |
| ALOGE("Failed to parse uid in the isolated uid change event."); |
| } |
| } |
| |
| void StatsLogProcessor::onBinaryPushStateChangedEventLocked(LogEvent* event) { |
| pid_t pid = event->GetPid(); |
| uid_t uid = event->GetUid(); |
| if (!checkPermissionForIds(kPermissionDump, pid, uid) || |
| !checkPermissionForIds(kPermissionUsage, pid, uid)) { |
| return; |
| } |
| // The Get* functions don't modify the status on success, they only write in |
| // failure statuses, so we can use one status variable for all calls then |
| // check if it is no longer NO_ERROR. |
| status_t err = NO_ERROR; |
| InstallTrainInfo trainInfo; |
| trainInfo.trainName = string(event->GetString(1 /*train name field id*/, &err)); |
| trainInfo.trainVersionCode = event->GetLong(2 /*train version field id*/, &err); |
| trainInfo.requiresStaging = event->GetBool(3 /*requires staging field id*/, &err); |
| trainInfo.rollbackEnabled = event->GetBool(4 /*rollback enabled field id*/, &err); |
| trainInfo.requiresLowLatencyMonitor = |
| event->GetBool(5 /*requires low latency monitor field id*/, &err); |
| trainInfo.status = int32_t(event->GetLong(6 /*state field id*/, &err)); |
| #ifdef NEW_ENCODING_SCHEME |
| std::vector<uint8_t> trainExperimentIdBytes = |
| event->GetStorage(7 /*experiment ids field id*/, &err); |
| #else |
| string trainExperimentIdString = event->GetString(7 /*experiment ids field id*/, &err); |
| #endif |
| bool is_rollback = event->GetBool(10 /*is rollback field id*/, &err); |
| |
| if (err != NO_ERROR) { |
| ALOGE("Failed to parse fields in binary push state changed log event"); |
| return; |
| } |
| ExperimentIds trainExperimentIds; |
| #ifdef NEW_ENCODING_SCHEME |
| if (!trainExperimentIds.ParseFromArray(trainExperimentIdBytes.data(), |
| trainExperimentIdBytes.size())) { |
| #else |
| if (!trainExperimentIds.ParseFromString(trainExperimentIdString)) { |
| #endif |
| ALOGE("Failed to parse experimentids in binary push state changed."); |
| return; |
| } |
| trainInfo.experimentIds = {trainExperimentIds.experiment_id().begin(), |
| trainExperimentIds.experiment_id().end()}; |
| |
| // Update the train info on disk and get any data the logevent is missing. |
| getAndUpdateTrainInfoOnDisk(is_rollback, &trainInfo); |
| |
| std::vector<uint8_t> trainExperimentIdProto; |
| writeExperimentIdsToProto(trainInfo.experimentIds, &trainExperimentIdProto); |
| int32_t userId = multiuser_get_user_id(uid); |
| |
| event->updateValue(2 /*train version field id*/, trainInfo.trainVersionCode, LONG); |
| #ifdef NEW_ENCODING_SCHEME |
| event->updateValue(7 /*experiment ids field id*/, trainExperimentIdProto, STORAGE); |
| #else |
| event->updateValue(7 /*experiment ids field id*/, trainExperimentIdProto, STRING); |
| #endif |
| event->updateValue(8 /*user id field id*/, userId, INT); |
| |
| if (is_rollback) { |
| int bit = trainInfo.requiresStaging ? 1 : 0; |
| event->updateValue(3 /*requires staging field id*/, bit, INT); |
| bit = trainInfo.rollbackEnabled ? 1 : 0; |
| event->updateValue(4 /*rollback enabled field id*/, bit, INT); |
| bit = trainInfo.requiresLowLatencyMonitor ? 1 : 0; |
| event->updateValue(5 /*requires low latency monitor field id*/, bit, INT); |
| } |
| } |
| |
| void StatsLogProcessor::getAndUpdateTrainInfoOnDisk(bool is_rollback, |
| InstallTrainInfo* trainInfo) { |
| // If the train name is empty, we don't know which train to attribute the |
| // event to, so return early. |
| if (trainInfo->trainName.empty()) { |
| return; |
| } |
| bool readTrainInfoSuccess = false; |
| InstallTrainInfo trainInfoOnDisk; |
| readTrainInfoSuccess = StorageManager::readTrainInfo(trainInfo->trainName, trainInfoOnDisk); |
| |
| bool resetExperimentIds = false; |
| if (readTrainInfoSuccess) { |
| // Keep the old train version if we received an empty version. |
| if (trainInfo->trainVersionCode == -1) { |
| trainInfo->trainVersionCode = trainInfoOnDisk.trainVersionCode; |
| } else if (trainInfo->trainVersionCode != trainInfoOnDisk.trainVersionCode) { |
| // Reset experiment ids if we receive a new non-empty train version. |
| resetExperimentIds = true; |
| } |
| |
| // Reset if we received a different experiment id. |
| if (!trainInfo->experimentIds.empty() && |
| (trainInfoOnDisk.experimentIds.empty() || |
| trainInfo->experimentIds.at(0) != trainInfoOnDisk.experimentIds[0])) { |
| resetExperimentIds = true; |
| } |
| } |
| |
| // Find the right experiment IDs |
| if ((!resetExperimentIds || is_rollback) && readTrainInfoSuccess) { |
| trainInfo->experimentIds = trainInfoOnDisk.experimentIds; |
| } |
| |
| if (!trainInfo->experimentIds.empty()) { |
| int64_t firstId = trainInfo->experimentIds.at(0); |
| switch (trainInfo->status) { |
| case android::util::BINARY_PUSH_STATE_CHANGED__STATE__INSTALL_SUCCESS: |
| trainInfo->experimentIds.push_back(firstId + 1); |
| break; |
| case android::util::BINARY_PUSH_STATE_CHANGED__STATE__INSTALLER_ROLLBACK_INITIATED: |
| trainInfo->experimentIds.push_back(firstId + 2); |
| break; |
| case android::util::BINARY_PUSH_STATE_CHANGED__STATE__INSTALLER_ROLLBACK_SUCCESS: |
| trainInfo->experimentIds.push_back(firstId + 3); |
| break; |
| } |
| } |
| |
| if (is_rollback) { |
| trainInfo->requiresStaging = trainInfoOnDisk.requiresStaging; |
| trainInfo->rollbackEnabled = trainInfoOnDisk.rollbackEnabled; |
| trainInfo->requiresLowLatencyMonitor = trainInfoOnDisk.requiresLowLatencyMonitor; |
| } |
| |
| StorageManager::writeTrainInfo(*trainInfo); |
| } |
| |
| void StatsLogProcessor::onWatchdogRollbackOccurredLocked(LogEvent* event) { |
| pid_t pid = event->GetPid(); |
| uid_t uid = event->GetUid(); |
| if (!checkPermissionForIds(kPermissionDump, pid, uid) || |
| !checkPermissionForIds(kPermissionUsage, pid, uid)) { |
| return; |
| } |
| // The Get* functions don't modify the status on success, they only write in |
| // failure statuses, so we can use one status variable for all calls then |
| // check if it is no longer NO_ERROR. |
| status_t err = NO_ERROR; |
| int32_t rollbackType = int32_t(event->GetInt(1 /*rollback type field id*/, &err)); |
| string packageName = string(event->GetString(2 /*package name field id*/, &err)); |
| |
| if (err != NO_ERROR) { |
| ALOGE("Failed to parse fields in watchdog rollback occurred log event"); |
| return; |
| } |
| |
| vector<int64_t> experimentIds = |
| processWatchdogRollbackOccurred(rollbackType, packageName); |
| vector<uint8_t> experimentIdProto; |
| writeExperimentIdsToProto(experimentIds, &experimentIdProto); |
| |
| #ifdef NEW_ENCODING_SCHEME |
| event->updateValue(6 /*experiment ids field id*/, experimentIdProto, STORAGE); |
| #else |
| event->updateValue(6 /*experiment ids field id*/, experimentIdProto, STRING); |
| #endif |
| } |
| |
| vector<int64_t> StatsLogProcessor::processWatchdogRollbackOccurred(const int32_t rollbackTypeIn, |
| const string& packageNameIn) { |
| // If the package name is empty, we can't attribute it to any train, so |
| // return early. |
| if (packageNameIn.empty()) { |
| return vector<int64_t>(); |
| } |
| bool readTrainInfoSuccess = false; |
| InstallTrainInfo trainInfoOnDisk; |
| readTrainInfoSuccess = StorageManager::readTrainInfo(packageNameIn, trainInfoOnDisk); |
| |
| if (!readTrainInfoSuccess) { |
| return vector<int64_t>(); |
| } |
| |
| if (trainInfoOnDisk.experimentIds.empty()) { |
| return vector<int64_t>(); |
| } |
| switch (rollbackTypeIn) { |
| case android::util::WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_INITIATE: |
| trainInfoOnDisk.experimentIds.push_back(trainInfoOnDisk.experimentIds[0] + 4); |
| StorageManager::writeTrainInfo(trainInfoOnDisk); |
| break; |
| case android::util::WATCHDOG_ROLLBACK_OCCURRED__ROLLBACK_TYPE__ROLLBACK_SUCCESS: |
| trainInfoOnDisk.experimentIds.push_back(trainInfoOnDisk.experimentIds[0] + 5); |
| StorageManager::writeTrainInfo(trainInfoOnDisk); |
| break; |
| } |
| |
| return trainInfoOnDisk.experimentIds; |
| } |
| |
| void StatsLogProcessor::resetConfigs() { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| resetConfigsLocked(getElapsedRealtimeNs()); |
| } |
| |
| void StatsLogProcessor::resetConfigsLocked(const int64_t timestampNs) { |
| std::vector<ConfigKey> configKeys; |
| for (auto it = mMetricsManagers.begin(); it != mMetricsManagers.end(); it++) { |
| configKeys.push_back(it->first); |
| } |
| resetConfigsLocked(timestampNs, configKeys); |
| } |
| |
| void StatsLogProcessor::OnLogEvent(LogEvent* event) { |
| OnLogEvent(event, getElapsedRealtimeNs()); |
| } |
| |
| void StatsLogProcessor::OnLogEvent(LogEvent* event, int64_t elapsedRealtimeNs) { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| |
| // Hard-coded logic to update train info on disk and fill in any information |
| // this log event may be missing. |
| if (event->GetTagId() == android::util::BINARY_PUSH_STATE_CHANGED) { |
| onBinaryPushStateChangedEventLocked(event); |
| } |
| |
| // Hard-coded logic to update experiment ids on disk for certain rollback |
| // types and fill the rollback atom with experiment ids |
| if (event->GetTagId() == android::util::WATCHDOG_ROLLBACK_OCCURRED) { |
| onWatchdogRollbackOccurredLocked(event); |
| } |
| |
| #ifdef VERY_VERBOSE_PRINTING |
| if (mPrintAllLogs) { |
| ALOGI("%s", event->ToString().c_str()); |
| } |
| #endif |
| const int64_t eventElapsedTimeNs = event->GetElapsedTimestampNs(); |
| |
| resetIfConfigTtlExpiredLocked(eventElapsedTimeNs); |
| |
| StatsdStats::getInstance().noteAtomLogged( |
| event->GetTagId(), event->GetElapsedTimestampNs() / NS_PER_SEC); |
| |
| // Hard-coded logic to update the isolated uid's in the uid-map. |
| // The field numbers need to be currently updated by hand with atoms.proto |
| if (event->GetTagId() == android::util::ISOLATED_UID_CHANGED) { |
| onIsolatedUidChangedEventLocked(*event); |
| } |
| |
| StateManager::getInstance().onLogEvent(*event); |
| |
| if (mMetricsManagers.empty()) { |
| return; |
| } |
| |
| int64_t curTimeSec = getElapsedRealtimeSec(); |
| if (curTimeSec - mLastPullerCacheClearTimeSec > StatsdStats::kPullerCacheClearIntervalSec) { |
| mPullerManager->ClearPullerCacheIfNecessary(curTimeSec * NS_PER_SEC); |
| mLastPullerCacheClearTimeSec = curTimeSec; |
| } |
| |
| |
| if (event->GetTagId() != android::util::ISOLATED_UID_CHANGED) { |
| // Map the isolated uid to host uid if necessary. |
| mapIsolatedUidToHostUidIfNecessaryLocked(event); |
| } |
| |
| std::unordered_set<int> uidsWithActiveConfigsChanged; |
| std::unordered_map<int, std::vector<int64_t>> activeConfigsPerUid; |
| // pass the event to metrics managers. |
| for (auto& pair : mMetricsManagers) { |
| int uid = pair.first.GetUid(); |
| int64_t configId = pair.first.GetId(); |
| bool isPrevActive = pair.second->isActive(); |
| pair.second->onLogEvent(*event); |
| bool isCurActive = pair.second->isActive(); |
| // Map all active configs by uid. |
| if (isCurActive) { |
| auto activeConfigs = activeConfigsPerUid.find(uid); |
| if (activeConfigs != activeConfigsPerUid.end()) { |
| activeConfigs->second.push_back(configId); |
| } else { |
| vector<int64_t> newActiveConfigs; |
| newActiveConfigs.push_back(configId); |
| activeConfigsPerUid[uid] = newActiveConfigs; |
| } |
| } |
| // The activation state of this config changed. |
| if (isPrevActive != isCurActive) { |
| VLOG("Active status changed for uid %d", uid); |
| uidsWithActiveConfigsChanged.insert(uid); |
| StatsdStats::getInstance().noteActiveStatusChanged(pair.first, isCurActive); |
| } |
| 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 (elapsedRealtimeNs - lastBroadcastTime->second < |
| StatsdStats::kMinActivationBroadcastPeriodNs) { |
| StatsdStats::getInstance().noteActivationBroadcastGuardrailHit(uid); |
| VLOG("StatsD would've sent an activation broadcast but the rate limit stopped us."); |
| return; |
| } |
| } |
| auto activeConfigs = activeConfigsPerUid.find(uid); |
| if (activeConfigs != activeConfigsPerUid.end()) { |
| if (mSendActivationBroadcast(uid, activeConfigs->second)) { |
| VLOG("StatsD sent activation notice for uid %d", uid); |
| 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] = elapsedRealtimeNs; |
| } |
| } |
| } |
| } |
| |
| void StatsLogProcessor::GetActiveConfigs(const int uid, vector<int64_t>& outActiveConfigs) { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| GetActiveConfigsLocked(uid, outActiveConfigs); |
| } |
| |
| void StatsLogProcessor::GetActiveConfigsLocked(const int uid, vector<int64_t>& outActiveConfigs) { |
| outActiveConfigs.clear(); |
| for (auto& pair : mMetricsManagers) { |
| if (pair.first.GetUid() == uid && pair.second->isActive()) { |
| outActiveConfigs.push_back(pair.first.GetId()); |
| } |
| } |
| } |
| |
| void StatsLogProcessor::OnConfigUpdated(const int64_t timestampNs, const ConfigKey& key, |
| const StatsdConfig& config) { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| WriteDataToDiskLocked(key, timestampNs, CONFIG_UPDATED, NO_TIME_CONSTRAINTS); |
| OnConfigUpdatedLocked(timestampNs, key, config); |
| } |
| |
| void StatsLogProcessor::OnConfigUpdatedLocked( |
| const int64_t timestampNs, const ConfigKey& key, const StatsdConfig& config) { |
| VLOG("Updated configuration for key %s", key.ToString().c_str()); |
| sp<MetricsManager> newMetricsManager = |
| new MetricsManager(key, config, mTimeBaseNs, timestampNs, mUidMap, mPullerManager, |
| mAnomalyAlarmMonitor, mPeriodicAlarmMonitor); |
| if (newMetricsManager->isConfigValid()) { |
| mUidMap->OnConfigUpdated(key); |
| newMetricsManager->refreshTtl(timestampNs); |
| mMetricsManagers[key] = newMetricsManager; |
| VLOG("StatsdConfig valid"); |
| } else { |
| // If there is any error in the config, don't use it. |
| ALOGE("StatsdConfig NOT valid"); |
| } |
| } |
| |
| size_t StatsLogProcessor::GetMetricsSize(const ConfigKey& key) const { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| auto it = mMetricsManagers.find(key); |
| if (it == mMetricsManagers.end()) { |
| ALOGW("Config source %s does not exist", key.ToString().c_str()); |
| return 0; |
| } |
| return it->second->byteSize(); |
| } |
| |
| void StatsLogProcessor::dumpStates(int out, bool verbose) { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| FILE* fout = fdopen(out, "w"); |
| if (fout == NULL) { |
| return; |
| } |
| fprintf(fout, "MetricsManager count: %lu\n", (unsigned long)mMetricsManagers.size()); |
| for (auto metricsManager : mMetricsManagers) { |
| metricsManager.second->dumpStates(fout, verbose); |
| } |
| |
| fclose(fout); |
| } |
| |
| /* |
| * onDumpReport dumps serialized ConfigMetricsReportList into proto. |
| */ |
| void StatsLogProcessor::onDumpReport(const ConfigKey& key, const int64_t dumpTimeStampNs, |
| const bool include_current_partial_bucket, |
| const bool erase_data, |
| const DumpReportReason dumpReportReason, |
| const DumpLatency dumpLatency, |
| ProtoOutputStream* proto) { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| |
| // Start of ConfigKey. |
| uint64_t configKeyToken = proto->start(FIELD_TYPE_MESSAGE | FIELD_ID_CONFIG_KEY); |
| proto->write(FIELD_TYPE_INT32 | FIELD_ID_UID, key.GetUid()); |
| proto->write(FIELD_TYPE_INT64 | FIELD_ID_ID, (long long)key.GetId()); |
| proto->end(configKeyToken); |
| // End of ConfigKey. |
| |
| bool keepFile = false; |
| auto it = mMetricsManagers.find(key); |
| if (it != mMetricsManagers.end() && it->second->shouldPersistLocalHistory()) { |
| keepFile = true; |
| } |
| |
| // Then, check stats-data directory to see there's any file containing |
| // ConfigMetricsReport from previous shutdowns to concatenate to reports. |
| StorageManager::appendConfigMetricsReport( |
| key, proto, erase_data && !keepFile /* should remove file after appending it */, |
| dumpReportReason == ADB_DUMP /*if caller is adb*/); |
| |
| if (it != mMetricsManagers.end()) { |
| // This allows another broadcast to be sent within the rate-limit period if we get close to |
| // filling the buffer again soon. |
| mLastBroadcastTimes.erase(key); |
| |
| vector<uint8_t> buffer; |
| onConfigMetricsReportLocked(key, dumpTimeStampNs, include_current_partial_bucket, |
| erase_data, dumpReportReason, dumpLatency, |
| false /* is this data going to be saved on disk */, &buffer); |
| proto->write(FIELD_TYPE_MESSAGE | FIELD_COUNT_REPEATED | FIELD_ID_REPORTS, |
| reinterpret_cast<char*>(buffer.data()), buffer.size()); |
| } else { |
| ALOGW("Config source %s does not exist", key.ToString().c_str()); |
| } |
| } |
| |
| /* |
| * onDumpReport dumps serialized ConfigMetricsReportList into outData. |
| */ |
| void StatsLogProcessor::onDumpReport(const ConfigKey& key, const int64_t dumpTimeStampNs, |
| const bool include_current_partial_bucket, |
| const bool erase_data, |
| const DumpReportReason dumpReportReason, |
| const DumpLatency dumpLatency, |
| vector<uint8_t>* outData) { |
| ProtoOutputStream proto; |
| onDumpReport(key, dumpTimeStampNs, include_current_partial_bucket, erase_data, |
| dumpReportReason, dumpLatency, &proto); |
| |
| if (outData != nullptr) { |
| flushProtoToBuffer(proto, outData); |
| VLOG("output data size %zu", outData->size()); |
| } |
| |
| StatsdStats::getInstance().noteMetricsReportSent(key, proto.size()); |
| } |
| |
| /* |
| * onConfigMetricsReportLocked dumps serialized ConfigMetricsReport into outData. |
| */ |
| void StatsLogProcessor::onConfigMetricsReportLocked( |
| const ConfigKey& key, const int64_t dumpTimeStampNs, |
| const bool include_current_partial_bucket, const bool erase_data, |
| const DumpReportReason dumpReportReason, const DumpLatency dumpLatency, |
| const bool dataSavedOnDisk, vector<uint8_t>* buffer) { |
| // We already checked whether key exists in mMetricsManagers in |
| // WriteDataToDisk. |
| auto it = mMetricsManagers.find(key); |
| if (it == mMetricsManagers.end()) { |
| return; |
| } |
| int64_t lastReportTimeNs = it->second->getLastReportTimeNs(); |
| int64_t lastReportWallClockNs = it->second->getLastReportWallClockNs(); |
| |
| std::set<string> str_set; |
| |
| ProtoOutputStream tempProto; |
| // First, fill in ConfigMetricsReport using current data on memory, which |
| // starts from filling in StatsLogReport's. |
| it->second->onDumpReport(dumpTimeStampNs, include_current_partial_bucket, erase_data, |
| dumpLatency, &str_set, &tempProto); |
| |
| // Fill in UidMap if there is at least one metric to report. |
| // This skips the uid map if it's an empty config. |
| if (it->second->getNumMetrics() > 0) { |
| uint64_t uidMapToken = tempProto.start(FIELD_TYPE_MESSAGE | FIELD_ID_UID_MAP); |
| mUidMap->appendUidMap( |
| dumpTimeStampNs, key, it->second->hashStringInReport() ? &str_set : nullptr, |
| it->second->versionStringsInReport(), it->second->installerInReport(), &tempProto); |
| tempProto.end(uidMapToken); |
| } |
| |
| // Fill in the timestamps. |
| tempProto.write(FIELD_TYPE_INT64 | FIELD_ID_LAST_REPORT_ELAPSED_NANOS, |
| (long long)lastReportTimeNs); |
| tempProto.write(FIELD_TYPE_INT64 | FIELD_ID_CURRENT_REPORT_ELAPSED_NANOS, |
| (long long)dumpTimeStampNs); |
| tempProto.write(FIELD_TYPE_INT64 | FIELD_ID_LAST_REPORT_WALL_CLOCK_NANOS, |
| (long long)lastReportWallClockNs); |
| tempProto.write(FIELD_TYPE_INT64 | FIELD_ID_CURRENT_REPORT_WALL_CLOCK_NANOS, |
| (long long)getWallClockNs()); |
| // Dump report reason |
| tempProto.write(FIELD_TYPE_INT32 | FIELD_ID_DUMP_REPORT_REASON, dumpReportReason); |
| |
| for (const auto& str : str_set) { |
| tempProto.write(FIELD_TYPE_STRING | FIELD_COUNT_REPEATED | FIELD_ID_STRINGS, str); |
| } |
| |
| flushProtoToBuffer(tempProto, buffer); |
| |
| // save buffer to disk if needed |
| if (erase_data && !dataSavedOnDisk && it->second->shouldPersistLocalHistory()) { |
| VLOG("save history to disk"); |
| string file_name = StorageManager::getDataHistoryFileName((long)getWallClockSec(), |
| key.GetUid(), key.GetId()); |
| StorageManager::writeFile(file_name.c_str(), buffer->data(), buffer->size()); |
| } |
| } |
| |
| void StatsLogProcessor::resetConfigsLocked(const int64_t timestampNs, |
| const std::vector<ConfigKey>& configs) { |
| for (const auto& key : configs) { |
| StatsdConfig config; |
| if (StorageManager::readConfigFromDisk(key, &config)) { |
| OnConfigUpdatedLocked(timestampNs, key, config); |
| StatsdStats::getInstance().noteConfigReset(key); |
| } else { |
| ALOGE("Failed to read backup config from disk for : %s", key.ToString().c_str()); |
| auto it = mMetricsManagers.find(key); |
| if (it != mMetricsManagers.end()) { |
| it->second->refreshTtl(timestampNs); |
| } |
| } |
| } |
| } |
| |
| void StatsLogProcessor::resetIfConfigTtlExpiredLocked(const int64_t timestampNs) { |
| std::vector<ConfigKey> configKeysTtlExpired; |
| for (auto it = mMetricsManagers.begin(); it != mMetricsManagers.end(); it++) { |
| if (it->second != nullptr && !it->second->isInTtl(timestampNs)) { |
| configKeysTtlExpired.push_back(it->first); |
| } |
| } |
| if (configKeysTtlExpired.size() > 0) { |
| WriteDataToDiskLocked(CONFIG_RESET, NO_TIME_CONSTRAINTS); |
| resetConfigsLocked(timestampNs, configKeysTtlExpired); |
| } |
| } |
| |
| void StatsLogProcessor::OnConfigRemoved(const ConfigKey& key) { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| auto it = mMetricsManagers.find(key); |
| if (it != mMetricsManagers.end()) { |
| WriteDataToDiskLocked(key, getElapsedRealtimeNs(), CONFIG_REMOVED, |
| NO_TIME_CONSTRAINTS); |
| mMetricsManagers.erase(it); |
| mUidMap->OnConfigRemoved(key); |
| } |
| StatsdStats::getInstance().noteConfigRemoved(key); |
| |
| mLastBroadcastTimes.erase(key); |
| |
| int uid = key.GetUid(); |
| bool lastConfigForUid = true; |
| for (auto it : mMetricsManagers) { |
| if (it.first.GetUid() == uid) { |
| lastConfigForUid = false; |
| break; |
| } |
| } |
| if (lastConfigForUid) { |
| mLastActivationBroadcastTimes.erase(uid); |
| } |
| |
| if (mMetricsManagers.empty()) { |
| mPullerManager->ForceClearPullerCache(); |
| } |
| } |
| |
| void StatsLogProcessor::flushIfNecessaryLocked(const ConfigKey& key, |
| MetricsManager& metricsManager) { |
| int64_t elapsedRealtimeNs = getElapsedRealtimeNs(); |
| auto lastCheckTime = mLastByteSizeTimes.find(key); |
| if (lastCheckTime != mLastByteSizeTimes.end()) { |
| 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] = elapsedRealtimeNs; |
| bool requestDump = false; |
| 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) || |
| (mOnDiskDataConfigs.find(key) != mOnDiskDataConfigs.end())) { |
| // Request to send a broadcast if: |
| // 1. in memory data > threshold OR |
| // 2. config has old data report on disk. |
| requestDump = true; |
| } |
| |
| if (requestDump) { |
| // Send broadcast so that receivers can pull data. |
| auto lastBroadcastTime = mLastBroadcastTimes.find(key); |
| if (lastBroadcastTime != mLastBroadcastTimes.end()) { |
| if (elapsedRealtimeNs - lastBroadcastTime->second < |
| StatsdStats::kMinBroadcastPeriodNs) { |
| VLOG("StatsD would've sent a broadcast but the rate limit stopped us."); |
| return; |
| } |
| } |
| if (mSendBroadcast(key)) { |
| mOnDiskDataConfigs.erase(key); |
| VLOG("StatsD triggered data fetch for %s", key.ToString().c_str()); |
| mLastBroadcastTimes[key] = elapsedRealtimeNs; |
| StatsdStats::getInstance().noteBroadcastSent(key); |
| } |
| } |
| } |
| |
| void StatsLogProcessor::WriteDataToDiskLocked(const ConfigKey& key, |
| const int64_t timestampNs, |
| const DumpReportReason dumpReportReason, |
| const DumpLatency dumpLatency) { |
| if (mMetricsManagers.find(key) == mMetricsManagers.end() || |
| !mMetricsManagers.find(key)->second->shouldWriteToDisk()) { |
| return; |
| } |
| vector<uint8_t> buffer; |
| onConfigMetricsReportLocked(key, timestampNs, true /* include_current_partial_bucket*/, |
| true /* erase_data */, dumpReportReason, dumpLatency, true, |
| &buffer); |
| string file_name = |
| StorageManager::getDataFileName((long)getWallClockSec(), key.GetUid(), key.GetId()); |
| StorageManager::writeFile(file_name.c_str(), buffer.data(), buffer.size()); |
| |
| // We were able to write the ConfigMetricsReport to disk, so we should trigger collection ASAP. |
| mOnDiskDataConfigs.insert(key); |
| } |
| |
| void StatsLogProcessor::SaveActiveConfigsToDisk(int64_t currentTimeNs) { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| const int64_t timeNs = getElapsedRealtimeNs(); |
| // Do not write to disk if we already have in the last few seconds. |
| if (static_cast<unsigned long long> (timeNs) < |
| mLastActiveMetricsWriteNs + WRITE_DATA_COOL_DOWN_SEC * NS_PER_SEC) { |
| ALOGI("Statsd skipping writing active metrics to disk. Already wrote data in last %d seconds", |
| WRITE_DATA_COOL_DOWN_SEC); |
| return; |
| } |
| mLastActiveMetricsWriteNs = timeNs; |
| |
| ProtoOutputStream proto; |
| WriteActiveConfigsToProtoOutputStreamLocked(currentTimeNs, DEVICE_SHUTDOWN, &proto); |
| |
| string file_name = StringPrintf("%s/active_metrics", STATS_ACTIVE_METRIC_DIR); |
| StorageManager::deleteFile(file_name.c_str()); |
| android::base::unique_fd fd( |
| open(file_name.c_str(), O_WRONLY | O_CREAT | O_CLOEXEC, S_IRUSR | S_IWUSR)); |
| if (fd == -1) { |
| ALOGE("Attempt to write %s but failed", file_name.c_str()); |
| return; |
| } |
| proto.flush(fd.get()); |
| } |
| |
| void StatsLogProcessor::WriteActiveConfigsToProtoOutputStream( |
| int64_t currentTimeNs, const DumpReportReason reason, ProtoOutputStream* proto) { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| WriteActiveConfigsToProtoOutputStreamLocked(currentTimeNs, reason, proto); |
| } |
| |
| void StatsLogProcessor::WriteActiveConfigsToProtoOutputStreamLocked( |
| int64_t currentTimeNs, const DumpReportReason reason, ProtoOutputStream* proto) { |
| for (const auto& pair : mMetricsManagers) { |
| const sp<MetricsManager>& metricsManager = pair.second; |
| uint64_t configToken = proto->start(FIELD_TYPE_MESSAGE | FIELD_COUNT_REPEATED | |
| FIELD_ID_ACTIVE_CONFIG_LIST_CONFIG); |
| metricsManager->writeActiveConfigToProtoOutputStream(currentTimeNs, reason, proto); |
| proto->end(configToken); |
| } |
| } |
| void StatsLogProcessor::LoadActiveConfigsFromDisk() { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| string file_name = StringPrintf("%s/active_metrics", STATS_ACTIVE_METRIC_DIR); |
| int fd = open(file_name.c_str(), O_RDONLY | O_CLOEXEC); |
| if (-1 == fd) { |
| VLOG("Attempt to read %s but failed", file_name.c_str()); |
| StorageManager::deleteFile(file_name.c_str()); |
| return; |
| } |
| string content; |
| if (!android::base::ReadFdToString(fd, &content)) { |
| ALOGE("Attempt to read %s but failed", file_name.c_str()); |
| close(fd); |
| StorageManager::deleteFile(file_name.c_str()); |
| return; |
| } |
| |
| close(fd); |
| |
| ActiveConfigList activeConfigList; |
| if (!activeConfigList.ParseFromString(content)) { |
| ALOGE("Attempt to read %s but failed; failed to load active configs", file_name.c_str()); |
| StorageManager::deleteFile(file_name.c_str()); |
| return; |
| } |
| // Passing in mTimeBaseNs only works as long as we only load from disk is when statsd starts. |
| SetConfigsActiveStateLocked(activeConfigList, mTimeBaseNs); |
| StorageManager::deleteFile(file_name.c_str()); |
| } |
| |
| void StatsLogProcessor::SetConfigsActiveState(const ActiveConfigList& activeConfigList, |
| int64_t currentTimeNs) { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| SetConfigsActiveStateLocked(activeConfigList, currentTimeNs); |
| } |
| |
| void StatsLogProcessor::SetConfigsActiveStateLocked(const ActiveConfigList& activeConfigList, |
| int64_t currentTimeNs) { |
| for (int i = 0; i < activeConfigList.config_size(); i++) { |
| const auto& config = activeConfigList.config(i); |
| ConfigKey key(config.uid(), config.id()); |
| auto it = mMetricsManagers.find(key); |
| if (it == mMetricsManagers.end()) { |
| ALOGE("No config found for config %s", key.ToString().c_str()); |
| continue; |
| } |
| VLOG("Setting active config %s", key.ToString().c_str()); |
| it->second->loadActiveConfig(config, currentTimeNs); |
| } |
| VLOG("Successfully loaded %d active configs.", activeConfigList.config_size()); |
| } |
| |
| void StatsLogProcessor::WriteDataToDiskLocked(const DumpReportReason dumpReportReason, |
| const DumpLatency dumpLatency) { |
| const int64_t timeNs = getElapsedRealtimeNs(); |
| // Do not write to disk if we already have in the last few seconds. |
| // This is to avoid overwriting files that would have the same name if we |
| // write twice in the same second. |
| if (static_cast<unsigned long long> (timeNs) < |
| mLastWriteTimeNs + WRITE_DATA_COOL_DOWN_SEC * NS_PER_SEC) { |
| ALOGI("Statsd skipping writing data to disk. Already wrote data in last %d seconds", |
| WRITE_DATA_COOL_DOWN_SEC); |
| return; |
| } |
| mLastWriteTimeNs = timeNs; |
| for (auto& pair : mMetricsManagers) { |
| WriteDataToDiskLocked(pair.first, timeNs, dumpReportReason, dumpLatency); |
| } |
| } |
| |
| void StatsLogProcessor::WriteDataToDisk(const DumpReportReason dumpReportReason, |
| const DumpLatency dumpLatency) { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| WriteDataToDiskLocked(dumpReportReason, dumpLatency); |
| } |
| |
| void StatsLogProcessor::informPullAlarmFired(const int64_t timestampNs) { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| mPullerManager->OnAlarmFired(timestampNs); |
| } |
| |
| int64_t StatsLogProcessor::getLastReportTimeNs(const ConfigKey& key) { |
| auto it = mMetricsManagers.find(key); |
| if (it == mMetricsManagers.end()) { |
| return 0; |
| } else { |
| return it->second->getLastReportTimeNs(); |
| } |
| } |
| |
| void StatsLogProcessor::notifyAppUpgrade(const int64_t& eventTimeNs, const string& apk, |
| const int uid, const int64_t version) { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| ALOGW("Received app upgrade"); |
| for (auto it : mMetricsManagers) { |
| it.second->notifyAppUpgrade(eventTimeNs, apk, uid, version); |
| } |
| } |
| |
| void StatsLogProcessor::notifyAppRemoved(const int64_t& eventTimeNs, const string& apk, |
| const int uid) { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| ALOGW("Received app removed"); |
| for (auto it : mMetricsManagers) { |
| it.second->notifyAppRemoved(eventTimeNs, apk, uid); |
| } |
| } |
| |
| void StatsLogProcessor::onUidMapReceived(const int64_t& eventTimeNs) { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| ALOGW("Received uid map"); |
| for (auto it : mMetricsManagers) { |
| it.second->onUidMapReceived(eventTimeNs); |
| } |
| } |
| |
| void StatsLogProcessor::noteOnDiskData(const ConfigKey& key) { |
| std::lock_guard<std::mutex> lock(mMetricsMutex); |
| mOnDiskDataConfigs.insert(key); |
| } |
| |
| } // namespace statsd |
| } // namespace os |
| } // namespace android |