StatsLogProcessor.cpp revision e68f3a5811209eeab71976bc583c6075d9a5979a
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 "stats_log_util.h" 25#include "android-base/stringprintf.h" 26#include "guardrail/StatsdStats.h" 27#include "metrics/CountMetricProducer.h" 28#include "external/StatsPullerManager.h" 29#include "stats_util.h" 30#include "storage/StorageManager.h" 31 32#include <log/log_event_list.h> 33#include <utils/Errors.h> 34#include <utils/SystemClock.h> 35 36using namespace android; 37using android::base::StringPrintf; 38using android::util::FIELD_COUNT_REPEATED; 39using android::util::FIELD_TYPE_BOOL; 40using android::util::FIELD_TYPE_FLOAT; 41using android::util::FIELD_TYPE_INT32; 42using android::util::FIELD_TYPE_INT64; 43using android::util::FIELD_TYPE_MESSAGE; 44using android::util::FIELD_TYPE_STRING; 45using android::util::ProtoOutputStream; 46using std::make_unique; 47using std::unique_ptr; 48using std::vector; 49 50namespace android { 51namespace os { 52namespace statsd { 53 54// for ConfigMetricsReportList 55const int FIELD_ID_CONFIG_KEY = 1; 56const int FIELD_ID_REPORTS = 2; 57// for ConfigKey 58const int FIELD_ID_UID = 1; 59const int FIELD_ID_ID = 2; 60// for ConfigMetricsReport 61// const int FIELD_ID_METRICS = 1; // written in MetricsManager.cpp 62const int FIELD_ID_UID_MAP = 2; 63const int FIELD_ID_LAST_REPORT_ELAPSED_NANOS = 3; 64const int FIELD_ID_CURRENT_REPORT_ELAPSED_NANOS = 4; 65const int FIELD_ID_LAST_REPORT_WALL_CLOCK_NANOS = 5; 66const int FIELD_ID_CURRENT_REPORT_WALL_CLOCK_NANOS = 6; 67 68#define NS_PER_HOUR 3600 * NS_PER_SEC 69 70#define STATS_DATA_DIR "/data/misc/stats-data" 71 72StatsLogProcessor::StatsLogProcessor(const sp<UidMap>& uidMap, 73 const sp<AlarmMonitor>& anomalyAlarmMonitor, 74 const sp<AlarmMonitor>& periodicAlarmMonitor, 75 const long timeBaseSec, 76 const std::function<void(const ConfigKey&)>& sendBroadcast) 77 : mUidMap(uidMap), 78 mAnomalyAlarmMonitor(anomalyAlarmMonitor), 79 mPeriodicAlarmMonitor(periodicAlarmMonitor), 80 mSendBroadcast(sendBroadcast), 81 mTimeBaseSec(timeBaseSec), 82 mLastLogTimestamp(0) { 83} 84 85StatsLogProcessor::~StatsLogProcessor() { 86} 87 88void StatsLogProcessor::onAnomalyAlarmFired( 89 const int64_t& timestampNs, 90 unordered_set<sp<const InternalAlarm>, SpHash<InternalAlarm>> alarmSet) { 91 std::lock_guard<std::mutex> lock(mMetricsMutex); 92 for (const auto& itr : mMetricsManagers) { 93 itr.second->onAnomalyAlarmFired(timestampNs, alarmSet); 94 } 95} 96void StatsLogProcessor::onPeriodicAlarmFired( 97 const int64_t& timestampNs, 98 unordered_set<sp<const InternalAlarm>, SpHash<InternalAlarm>> alarmSet) { 99 100 std::lock_guard<std::mutex> lock(mMetricsMutex); 101 for (const auto& itr : mMetricsManagers) { 102 itr.second->onPeriodicAlarmFired(timestampNs, alarmSet); 103 } 104} 105 106void updateUid(Value* value, int hostUid) { 107 int uid = value->int_value; 108 if (uid != hostUid) { 109 value->setInt(hostUid); 110 } 111} 112 113void StatsLogProcessor::mapIsolatedUidToHostUidIfNecessaryLocked(LogEvent* event) const { 114 if (android::util::AtomsInfo::kAtomsWithAttributionChain.find(event->GetTagId()) != 115 android::util::AtomsInfo::kAtomsWithAttributionChain.end()) { 116 for (auto& value : *(event->getMutableValues())) { 117 if (value.mField.getPosAtDepth(0) > kAttributionField) { 118 break; 119 } 120 if (isAttributionUidField(value)) { 121 const int hostUid = mUidMap->getHostUidOrSelf(value.mValue.int_value); 122 updateUid(&value.mValue, hostUid); 123 } 124 } 125 } else { 126 auto it = android::util::AtomsInfo::kAtomsWithUidField.find(event->GetTagId()); 127 if (it != android::util::AtomsInfo::kAtomsWithUidField.end()) { 128 int uidField = it->second; // uidField is the field number in proto, 129 // starting from 1 130 if (uidField > 0 && (int)event->getValues().size() >= uidField && 131 (event->getValues())[uidField - 1].mValue.getType() == INT) { 132 Value& value = (*event->getMutableValues())[uidField - 1].mValue; 133 const int hostUid = mUidMap->getHostUidOrSelf(value.int_value); 134 updateUid(&value, hostUid); 135 } else { 136 ALOGE("Malformed log, uid not found. %s", event->ToString().c_str()); 137 } 138 } 139 } 140} 141 142void StatsLogProcessor::onIsolatedUidChangedEventLocked(const LogEvent& event) { 143 status_t err = NO_ERROR, err2 = NO_ERROR, err3 = NO_ERROR; 144 bool is_create = event.GetBool(3, &err); 145 auto parent_uid = int(event.GetLong(1, &err2)); 146 auto isolated_uid = int(event.GetLong(2, &err3)); 147 if (err == NO_ERROR && err2 == NO_ERROR && err3 == NO_ERROR) { 148 if (is_create) { 149 mUidMap->assignIsolatedUid(isolated_uid, parent_uid); 150 } else { 151 mUidMap->removeIsolatedUid(isolated_uid, parent_uid); 152 } 153 } else { 154 ALOGE("Failed to parse uid in the isolated uid change event."); 155 } 156} 157 158void StatsLogProcessor::OnLogEvent(LogEvent* event) { 159 std::lock_guard<std::mutex> lock(mMetricsMutex); 160 const int64_t currentTimestampNs = event->GetElapsedTimestampNs(); 161 162 if (currentTimestampNs < mLastLogTimestamp) { 163 StatsdStats::getInstance().noteLogEventSkipped( 164 event->GetTagId(), event->GetElapsedTimestampNs()); 165 return; 166 } 167 168 resetIfConfigTtlExpiredLocked(currentTimestampNs); 169 170 mLastLogTimestamp = currentTimestampNs; 171 StatsdStats::getInstance().noteAtomLogged( 172 event->GetTagId(), event->GetElapsedTimestampNs() / NS_PER_SEC); 173 174 // Hard-coded logic to update the isolated uid's in the uid-map. 175 // The field numbers need to be currently updated by hand with atoms.proto 176 if (event->GetTagId() == android::util::ISOLATED_UID_CHANGED) { 177 onIsolatedUidChangedEventLocked(*event); 178 } 179 180 if (mMetricsManagers.empty()) { 181 return; 182 } 183 184 int64_t curTimeSec = getElapsedRealtimeSec(); 185 if (curTimeSec - mLastPullerCacheClearTimeSec > StatsdStats::kPullerCacheClearIntervalSec) { 186 mStatsPullerManager.ClearPullerCacheIfNecessary(curTimeSec * NS_PER_SEC); 187 mLastPullerCacheClearTimeSec = curTimeSec; 188 } 189 190 191 if (event->GetTagId() != android::util::ISOLATED_UID_CHANGED) { 192 // Map the isolated uid to host uid if necessary. 193 mapIsolatedUidToHostUidIfNecessaryLocked(event); 194 } 195 196 // pass the event to metrics managers. 197 for (auto& pair : mMetricsManagers) { 198 pair.second->onLogEvent(*event); 199 flushIfNecessaryLocked(event->GetElapsedTimestampNs(), pair.first, *(pair.second)); 200 } 201} 202 203void StatsLogProcessor::OnConfigUpdated(const int64_t timestampNs, const ConfigKey& key, 204 const StatsdConfig& config) { 205 std::lock_guard<std::mutex> lock(mMetricsMutex); 206 OnConfigUpdatedLocked(timestampNs, key, config); 207} 208 209void StatsLogProcessor::OnConfigUpdatedLocked( 210 const int64_t timestampNs, const ConfigKey& key, const StatsdConfig& config) { 211 VLOG("Updated configuration for key %s", key.ToString().c_str()); 212 sp<MetricsManager> newMetricsManager = 213 new MetricsManager(key, config, mTimeBaseSec, (timestampNs - 1) / NS_PER_SEC + 1, mUidMap, 214 mAnomalyAlarmMonitor, mPeriodicAlarmMonitor); 215 auto it = mMetricsManagers.find(key); 216 if (it != mMetricsManagers.end()) { 217 WriteDataToDiskLocked(it->first); 218 } 219 if (newMetricsManager->isConfigValid()) { 220 mUidMap->OnConfigUpdated(key); 221 if (newMetricsManager->shouldAddUidMapListener()) { 222 // We have to add listener after the MetricsManager is constructed because it's 223 // not safe to create wp or sp from this pointer inside its constructor. 224 mUidMap->addListener(newMetricsManager.get()); 225 } 226 newMetricsManager->refreshTtl(timestampNs); 227 mMetricsManagers[key] = newMetricsManager; 228 VLOG("StatsdConfig valid"); 229 } else { 230 // If there is any error in the config, don't use it. 231 ALOGE("StatsdConfig NOT valid"); 232 } 233} 234 235size_t StatsLogProcessor::GetMetricsSize(const ConfigKey& key) const { 236 std::lock_guard<std::mutex> lock(mMetricsMutex); 237 auto it = mMetricsManagers.find(key); 238 if (it == mMetricsManagers.end()) { 239 ALOGW("Config source %s does not exist", key.ToString().c_str()); 240 return 0; 241 } 242 return it->second->byteSize(); 243} 244 245void StatsLogProcessor::dumpStates(FILE* out, bool verbose) { 246 std::lock_guard<std::mutex> lock(mMetricsMutex); 247 fprintf(out, "MetricsManager count: %lu\n", (unsigned long)mMetricsManagers.size()); 248 for (auto metricsManager : mMetricsManagers) { 249 metricsManager.second->dumpStates(out, verbose); 250 } 251} 252 253/* 254 * onDumpReport dumps serialized ConfigMetricsReportList into outData. 255 */ 256void StatsLogProcessor::onDumpReport(const ConfigKey& key, const int64_t dumpTimeStampNs, 257 const bool include_current_partial_bucket, 258 vector<uint8_t>* outData) { 259 std::lock_guard<std::mutex> lock(mMetricsMutex); 260 261 ProtoOutputStream proto; 262 263 // Start of ConfigKey. 264 uint64_t configKeyToken = proto.start(FIELD_TYPE_MESSAGE | FIELD_ID_CONFIG_KEY); 265 proto.write(FIELD_TYPE_INT32 | FIELD_ID_UID, key.GetUid()); 266 proto.write(FIELD_TYPE_INT64 | FIELD_ID_ID, (long long)key.GetId()); 267 proto.end(configKeyToken); 268 // End of ConfigKey. 269 270 // Then, check stats-data directory to see there's any file containing 271 // ConfigMetricsReport from previous shutdowns to concatenate to reports. 272 StorageManager::appendConfigMetricsReport(key, &proto); 273 274 auto it = mMetricsManagers.find(key); 275 if (it != mMetricsManagers.end()) { 276 // This allows another broadcast to be sent within the rate-limit period if we get close to 277 // filling the buffer again soon. 278 mLastBroadcastTimes.erase(key); 279 280 // Start of ConfigMetricsReport (reports). 281 uint64_t reportsToken = 282 proto.start(FIELD_TYPE_MESSAGE | FIELD_COUNT_REPEATED | FIELD_ID_REPORTS); 283 onConfigMetricsReportLocked(key, dumpTimeStampNs, include_current_partial_bucket, &proto); 284 proto.end(reportsToken); 285 // End of ConfigMetricsReport (reports). 286 } else { 287 ALOGW("Config source %s does not exist", key.ToString().c_str()); 288 } 289 290 if (outData != nullptr) { 291 outData->clear(); 292 outData->resize(proto.size()); 293 size_t pos = 0; 294 auto iter = proto.data(); 295 while (iter.readBuffer() != NULL) { 296 size_t toRead = iter.currentToRead(); 297 std::memcpy(&((*outData)[pos]), iter.readBuffer(), toRead); 298 pos += toRead; 299 iter.rp()->move(toRead); 300 } 301 } 302 303 StatsdStats::getInstance().noteMetricsReportSent(key, proto.size()); 304} 305 306/* 307 * onConfigMetricsReportLocked dumps serialized ConfigMetricsReport into outData. 308 */ 309void StatsLogProcessor::onConfigMetricsReportLocked(const ConfigKey& key, 310 const int64_t dumpTimeStampNs, 311 const bool include_current_partial_bucket, 312 ProtoOutputStream* proto) { 313 // We already checked whether key exists in mMetricsManagers in 314 // WriteDataToDisk. 315 auto it = mMetricsManagers.find(key); 316 if (it == mMetricsManagers.end()) { 317 return; 318 } 319 int64_t lastReportTimeNs = it->second->getLastReportTimeNs(); 320 int64_t lastReportWallClockNs = it->second->getLastReportWallClockNs(); 321 322 // First, fill in ConfigMetricsReport using current data on memory, which 323 // starts from filling in StatsLogReport's. 324 it->second->onDumpReport(dumpTimeStampNs, include_current_partial_bucket, proto); 325 326 // Fill in UidMap. 327 uint64_t uidMapToken = proto->start(FIELD_TYPE_MESSAGE | FIELD_ID_UID_MAP); 328 mUidMap->appendUidMap(dumpTimeStampNs, key, proto); 329 proto->end(uidMapToken); 330 331 // Fill in the timestamps. 332 proto->write(FIELD_TYPE_INT64 | FIELD_ID_LAST_REPORT_ELAPSED_NANOS, 333 (long long)lastReportTimeNs); 334 proto->write(FIELD_TYPE_INT64 | FIELD_ID_CURRENT_REPORT_ELAPSED_NANOS, 335 (long long)dumpTimeStampNs); 336 proto->write(FIELD_TYPE_INT64 | FIELD_ID_LAST_REPORT_WALL_CLOCK_NANOS, 337 (long long)lastReportWallClockNs); 338 proto->write(FIELD_TYPE_INT64 | FIELD_ID_CURRENT_REPORT_WALL_CLOCK_NANOS, 339 (long long)getWallClockNs()); 340} 341 342void StatsLogProcessor::resetIfConfigTtlExpiredLocked(const int64_t timestampNs) { 343 std::vector<ConfigKey> configKeysTtlExpired; 344 for (auto it = mMetricsManagers.begin(); it != mMetricsManagers.end(); it++) { 345 if (it->second != nullptr && !it->second->isInTtl(timestampNs)) { 346 configKeysTtlExpired.push_back(it->first); 347 } 348 } 349 350 for (const auto& key : configKeysTtlExpired) { 351 StatsdConfig config; 352 if (StorageManager::readConfigFromDisk(key, &config)) { 353 OnConfigUpdatedLocked(timestampNs, key, config); 354 StatsdStats::getInstance().noteConfigReset(key); 355 } else { 356 ALOGE("Failed to read backup config from disk for : %s", key.ToString().c_str()); 357 auto it = mMetricsManagers.find(key); 358 if (it != mMetricsManagers.end()) { 359 it->second->refreshTtl(timestampNs); 360 } 361 } 362 } 363} 364 365void StatsLogProcessor::OnConfigRemoved(const ConfigKey& key) { 366 std::lock_guard<std::mutex> lock(mMetricsMutex); 367 auto it = mMetricsManagers.find(key); 368 if (it != mMetricsManagers.end()) { 369 WriteDataToDiskLocked(key); 370 mMetricsManagers.erase(it); 371 mUidMap->OnConfigRemoved(key); 372 } 373 StatsdStats::getInstance().noteConfigRemoved(key); 374 375 mLastBroadcastTimes.erase(key); 376 377 if (mMetricsManagers.empty()) { 378 mStatsPullerManager.ForceClearPullerCache(); 379 } 380} 381 382void StatsLogProcessor::flushIfNecessaryLocked( 383 int64_t timestampNs, const ConfigKey& key, MetricsManager& metricsManager) { 384 auto lastCheckTime = mLastByteSizeTimes.find(key); 385 if (lastCheckTime != mLastByteSizeTimes.end()) { 386 if (timestampNs - lastCheckTime->second < StatsdStats::kMinByteSizeCheckPeriodNs) { 387 return; 388 } 389 } 390 391 // We suspect that the byteSize() computation is expensive, so we set a rate limit. 392 size_t totalBytes = metricsManager.byteSize(); 393 mLastByteSizeTimes[key] = timestampNs; 394 if (totalBytes > 395 StatsdStats::kMaxMetricsBytesPerConfig) { // Too late. We need to start clearing data. 396 metricsManager.dropData(timestampNs); 397 StatsdStats::getInstance().noteDataDropped(key); 398 VLOG("StatsD had to toss out metrics for %s", key.ToString().c_str()); 399 } else if (totalBytes > StatsdStats::kBytesPerConfigTriggerGetData) { 400 // Send broadcast so that receivers can pull data. 401 auto lastBroadcastTime = mLastBroadcastTimes.find(key); 402 if (lastBroadcastTime != mLastBroadcastTimes.end()) { 403 if (timestampNs - lastBroadcastTime->second < StatsdStats::kMinBroadcastPeriodNs) { 404 VLOG("StatsD would've sent a broadcast but the rate limit stopped us."); 405 return; 406 } 407 } 408 mLastBroadcastTimes[key] = timestampNs; 409 VLOG("StatsD requesting broadcast for %s", key.ToString().c_str()); 410 mSendBroadcast(key); 411 StatsdStats::getInstance().noteBroadcastSent(key); 412 } 413} 414 415void StatsLogProcessor::WriteDataToDiskLocked(const ConfigKey& key) { 416 ProtoOutputStream proto; 417 onConfigMetricsReportLocked(key, getElapsedRealtimeNs(), 418 true /* include_current_partial_bucket*/, &proto); 419 string file_name = StringPrintf("%s/%ld_%d_%lld", STATS_DATA_DIR, 420 (long)getWallClockSec(), key.GetUid(), (long long)key.GetId()); 421 android::base::unique_fd fd(open(file_name.c_str(), 422 O_WRONLY | O_CREAT | O_CLOEXEC, S_IRUSR | S_IWUSR)); 423 if (fd == -1) { 424 ALOGE("Attempt to write %s but failed", file_name.c_str()); 425 return; 426 } 427 proto.flush(fd.get()); 428} 429 430void StatsLogProcessor::WriteDataToDiskLocked() { 431 for (auto& pair : mMetricsManagers) { 432 WriteDataToDiskLocked(pair.first); 433 } 434} 435 436void StatsLogProcessor::WriteDataToDisk() { 437 std::lock_guard<std::mutex> lock(mMetricsMutex); 438 WriteDataToDiskLocked(); 439} 440 441} // namespace statsd 442} // namespace os 443} // namespace android 444