diff options
41 files changed, 406 insertions, 249 deletions
diff --git a/cmds/statsd/src/StatsLogProcessor.cpp b/cmds/statsd/src/StatsLogProcessor.cpp index 3a20b12500ae..afb2c4782fac 100644 --- a/cmds/statsd/src/StatsLogProcessor.cpp +++ b/cmds/statsd/src/StatsLogProcessor.cpp @@ -21,6 +21,7 @@ #include <android-base/file.h> #include <dirent.h> #include "StatsLogProcessor.h" +#include "stats_log_util.h" #include "android-base/stringprintf.h" #include "guardrail/StatsdStats.h" #include "metrics/CountMetricProducer.h" @@ -59,8 +60,8 @@ const int FIELD_ID_ID = 2; // for ConfigMetricsReport const int FIELD_ID_METRICS = 1; const int FIELD_ID_UID_MAP = 2; -const int FIELD_ID_LAST_REPORT_NANOS = 3; -const int FIELD_ID_CURRENT_REPORT_NANOS = 4; +const int FIELD_ID_LAST_REPORT_ELAPSED_NANOS = 3; +const int FIELD_ID_CURRENT_REPORT_ELAPSED_NANOS = 4; #define STATS_DATA_DIR "/data/misc/stats-data" @@ -136,7 +137,7 @@ void StatsLogProcessor::onIsolatedUidChangedEventLocked(const LogEvent& event) { void StatsLogProcessor::OnLogEvent(LogEvent* event) { std::lock_guard<std::mutex> lock(mMetricsMutex); StatsdStats::getInstance().noteAtomLogged( - event->GetTagId(), event->GetTimestampNs() / NS_PER_SEC); + 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 @@ -148,10 +149,10 @@ void StatsLogProcessor::OnLogEvent(LogEvent* event) { return; } - long curTime = time(nullptr); - if (curTime - mLastPullerCacheClearTimeSec > StatsdStats::kPullerCacheClearIntervalSec) { - mStatsPullerManager.ClearPullerCacheIfNecessary(curTime); - mLastPullerCacheClearTimeSec = curTime; + uint64_t curTimeSec = getElapsedRealtimeSec(); + if (curTimeSec - mLastPullerCacheClearTimeSec > StatsdStats::kPullerCacheClearIntervalSec) { + mStatsPullerManager.ClearPullerCacheIfNecessary(curTimeSec); + mLastPullerCacheClearTimeSec = curTimeSec; } if (event->GetTagId() != android::util::ISOLATED_UID_CHANGED) { @@ -162,7 +163,7 @@ void StatsLogProcessor::OnLogEvent(LogEvent* event) { // pass the event to metrics managers. for (auto& pair : mMetricsManagers) { pair.second->onLogEvent(*event); - flushIfNecessaryLocked(event->GetTimestampNs(), pair.first, *(pair.second)); + flushIfNecessaryLocked(event->GetElapsedTimestampNs(), pair.first, *(pair.second)); } } @@ -242,6 +243,7 @@ void StatsLogProcessor::onDumpReportLocked(const ConfigKey& key, const uint64_t long long reportsToken = proto.start(FIELD_TYPE_MESSAGE | FIELD_COUNT_REPEATED | FIELD_ID_REPORTS); + int64_t lastReportTimeNs = it->second->getLastReportTimeNs(); // First, fill in ConfigMetricsReport using current data on memory, which // starts from filling in StatsLogReport's. it->second->onDumpReport(dumpTimeStampNs, &proto); @@ -254,10 +256,10 @@ void StatsLogProcessor::onDumpReportLocked(const ConfigKey& key, const uint64_t proto.write(FIELD_TYPE_MESSAGE | FIELD_ID_UID_MAP, uidMapBuffer, uidMapSize); // Fill in the timestamps. - proto.write(FIELD_TYPE_INT64 | FIELD_ID_LAST_REPORT_NANOS, - (long long)it->second->getLastReportTimeNs()); - proto.write(FIELD_TYPE_INT64 | FIELD_ID_CURRENT_REPORT_NANOS, - (long long)::android::elapsedRealtimeNano()); + proto.write(FIELD_TYPE_INT64 | FIELD_ID_LAST_REPORT_ELAPSED_NANOS, + (long long)lastReportTimeNs); + proto.write(FIELD_TYPE_INT64 | FIELD_ID_CURRENT_REPORT_ELAPSED_NANOS, + (long long)dumpTimeStampNs); // End of ConfigMetricsReport (reports). proto.end(reportsToken); @@ -340,8 +342,8 @@ void StatsLogProcessor::WriteDataToDisk() { vector<uint8_t> data; onDumpReportLocked(key, time(nullptr) * NS_PER_SEC, &data); // TODO: Add a guardrail to prevent accumulation of file on disk. - string file_name = StringPrintf("%s/%ld_%d_%lld", STATS_DATA_DIR, time(nullptr), - key.GetUid(), (long long)key.GetId()); + string file_name = StringPrintf("%s/%ld_%d_%lld", STATS_DATA_DIR, + (long)getWallClockSec(), key.GetUid(), (long long)key.GetId()); StorageManager::writeFile(file_name.c_str(), &data[0], data.size()); } } diff --git a/cmds/statsd/src/StatsService.cpp b/cmds/statsd/src/StatsService.cpp index ee38667b0df9..bb47653f03b0 100644 --- a/cmds/statsd/src/StatsService.cpp +++ b/cmds/statsd/src/StatsService.cpp @@ -18,6 +18,7 @@ #include "Log.h" #include "StatsService.h" +#include "stats_log_util.h" #include "android-base/stringprintf.h" #include "config/ConfigKey.h" #include "config/ConfigManager.h" @@ -79,18 +80,20 @@ StatsService::StatsService(const sp<Looper>& handlerLooper) mUidMap = new UidMap(); StatsPuller::SetUidMap(mUidMap); mConfigManager = new ConfigManager(); - mProcessor = new StatsLogProcessor(mUidMap, mAnomalyMonitor, time(nullptr), [this](const ConfigKey& key) { - sp<IStatsCompanionService> sc = getStatsCompanionService(); - auto receiver = mConfigManager->GetConfigReceiver(key); - if (sc == nullptr) { - VLOG("Could not find StatsCompanionService"); - } else if (receiver == nullptr) { - VLOG("Statscompanion could not find a broadcast receiver for %s", - key.ToString().c_str()); - } else { - sc->sendDataBroadcast(receiver); + mProcessor = new StatsLogProcessor(mUidMap, mAnomalyMonitor, getElapsedRealtimeSec(), + [this](const ConfigKey& key) { + sp<IStatsCompanionService> sc = getStatsCompanionService(); + auto receiver = mConfigManager->GetConfigReceiver(key); + if (sc == nullptr) { + VLOG("Could not find StatsCompanionService"); + } else if (receiver == nullptr) { + VLOG("Statscompanion could not find a broadcast receiver for %s", + key.ToString().c_str()); + } else { + sc->sendDataBroadcast(receiver); + } } - }); + ); mConfigManager->AddListener(mProcessor); @@ -668,11 +671,7 @@ Status StatsService::informAnomalyAlarmFired() { return Status::fromExceptionCode(Status::EX_SECURITY, "Only system uid can call informAnomalyAlarmFired"); } - - // TODO: This may be a bug. time(nullptr) can be off (wrt AlarmManager's time) and cause us to - // miss the alarm! Eventually we will switch to using elapsedRealTime everywhere, - // which may hopefully fix the problem, so we'll leave this alone for now. - uint64_t currentTimeSec = time(nullptr); + uint64_t currentTimeSec = getElapsedRealtimeSec(); std::unordered_set<sp<const AnomalyAlarm>, SpHash<AnomalyAlarm>> anomalySet = mAnomalyMonitor->popSoonerThan(static_cast<uint32_t>(currentTimeSec)); if (anomalySet.size() > 0) { diff --git a/cmds/statsd/src/external/CpuTimePerUidFreqPuller.cpp b/cmds/statsd/src/external/CpuTimePerUidFreqPuller.cpp index d0d2f938cf0c..d1d9d3778267 100644 --- a/cmds/statsd/src/external/CpuTimePerUidFreqPuller.cpp +++ b/cmds/statsd/src/external/CpuTimePerUidFreqPuller.cpp @@ -25,6 +25,7 @@ #include "guardrail/StatsdStats.h" #include "logd/LogEvent.h" #include "statslog.h" +#include "stats_log_util.h" using std::make_shared; using std::shared_ptr; @@ -62,7 +63,9 @@ bool CpuTimePerUidFreqPuller::PullInternal(vector<shared_ptr<LogEvent>>* data) { return false; } - uint64_t timestamp = time(nullptr) * NS_PER_SEC; + int64_t wallClockTimestampNs = getWallClockNs(); + int64_t elapsedTimestampNs = getElapsedRealtimeNs(); + char buf[kLineBufferSize]; // first line prints the format and frequencies fin.getline(buf, kLineBufferSize); @@ -77,7 +80,8 @@ bool CpuTimePerUidFreqPuller::PullInternal(vector<shared_ptr<LogEvent>>* data) { int idx = 0; do { timeMs = std::stoull(pch); - auto ptr = make_shared<LogEvent>(android::util::CPU_TIME_PER_UID_FREQ, timestamp); + auto ptr = make_shared<LogEvent>(android::util::CPU_TIME_PER_UID_FREQ, + wallClockTimestampNs, elapsedTimestampNs); ptr->write(uid); ptr->write(idx); ptr->write(timeMs); diff --git a/cmds/statsd/src/external/CpuTimePerUidPuller.cpp b/cmds/statsd/src/external/CpuTimePerUidPuller.cpp index d9aeb4656bfe..568b8f0c0c53 100644 --- a/cmds/statsd/src/external/CpuTimePerUidPuller.cpp +++ b/cmds/statsd/src/external/CpuTimePerUidPuller.cpp @@ -24,6 +24,7 @@ #include "guardrail/StatsdStats.h" #include "logd/LogEvent.h" #include "statslog.h" +#include "stats_log_util.h" using std::make_shared; using std::shared_ptr; @@ -57,7 +58,8 @@ bool CpuTimePerUidPuller::PullInternal(vector<shared_ptr<LogEvent>>* data) { return false; } - uint64_t timestamp = time(nullptr) * NS_PER_SEC; + int64_t wallClockTimestampNs = getWallClockNs(); + int64_t elapsedTimestampNs = getElapsedRealtimeNs(); char buf[kLineBufferSize]; char* pch; while (!fin.eof()) { @@ -70,7 +72,8 @@ bool CpuTimePerUidPuller::PullInternal(vector<shared_ptr<LogEvent>>* data) { pch = strtok(buf, " "); uint64_t sysTimeMs = std::stoull(pch); - auto ptr = make_shared<LogEvent>(android::util::CPU_TIME_PER_UID, timestamp); + auto ptr = make_shared<LogEvent>(android::util::CPU_TIME_PER_UID, + wallClockTimestampNs, elapsedTimestampNs); ptr->write(uid); ptr->write(userTimeMs); ptr->write(sysTimeMs); diff --git a/cmds/statsd/src/external/KernelUidCpuActiveTimeReader.cpp b/cmds/statsd/src/external/KernelUidCpuActiveTimeReader.cpp index 0e126e7a4b44..0b545ccb3658 100644 --- a/cmds/statsd/src/external/KernelUidCpuActiveTimeReader.cpp +++ b/cmds/statsd/src/external/KernelUidCpuActiveTimeReader.cpp @@ -23,6 +23,7 @@ #include "guardrail/StatsdStats.h" #include "logd/LogEvent.h" #include "statslog.h" +#include "stats_log_util.h" using std::make_shared; using std::shared_ptr; @@ -57,7 +58,9 @@ bool KernelUidCpuActiveTimeReader::PullInternal(vector<shared_ptr<LogEvent>>* da return false; } - uint64_t timestamp = time(nullptr) * NS_PER_SEC; + int64_t wallClockTimestampNs = getWallClockNs(); + int64_t elapsedTimestampNs = getElapsedRealtimeNs(); + char buf[kLineBufferSize]; char* pch; while (!fin.eof()) { @@ -70,7 +73,7 @@ bool KernelUidCpuActiveTimeReader::PullInternal(vector<shared_ptr<LogEvent>>* da int idx = 0; do { timeMs = std::stoull(pch); - auto ptr = make_shared<LogEvent>(mTagId, timestamp); + auto ptr = make_shared<LogEvent>(mTagId, wallClockTimestampNs, elapsedTimestampNs); ptr->write(uid); ptr->write(idx); ptr->write(timeMs); diff --git a/cmds/statsd/src/external/KernelUidCpuClusterTimeReader.cpp b/cmds/statsd/src/external/KernelUidCpuClusterTimeReader.cpp index 7684ed4eb44b..cc80204b105e 100644 --- a/cmds/statsd/src/external/KernelUidCpuClusterTimeReader.cpp +++ b/cmds/statsd/src/external/KernelUidCpuClusterTimeReader.cpp @@ -22,6 +22,7 @@ #include "guardrail/StatsdStats.h" #include "logd/LogEvent.h" #include "statslog.h" +#include "stats_log_util.h" using std::make_shared; using std::shared_ptr; @@ -56,7 +57,8 @@ bool KernelUidCpuClusterTimeReader::PullInternal(vector<shared_ptr<LogEvent>>* d return false; } - uint64_t timestamp = time(nullptr) * NS_PER_SEC; + int64_t wallClockTimestampNs = getWallClockNs(); + int64_t elapsedTimestampNs = getElapsedRealtimeNs(); char buf[kLineBufferSize]; char* pch; while (!fin.eof()) { @@ -69,7 +71,7 @@ bool KernelUidCpuClusterTimeReader::PullInternal(vector<shared_ptr<LogEvent>>* d int idx = 0; do { timeMs = std::stoull(pch); - auto ptr = make_shared<LogEvent>(mTagId, timestamp); + auto ptr = make_shared<LogEvent>(mTagId, wallClockTimestampNs, elapsedTimestampNs); ptr->write(uid); ptr->write(idx); ptr->write(timeMs); diff --git a/cmds/statsd/src/external/ResourceHealthManagerPuller.cpp b/cmds/statsd/src/external/ResourceHealthManagerPuller.cpp index 72fb5ffd4b90..261cb4332dd6 100644 --- a/cmds/statsd/src/external/ResourceHealthManagerPuller.cpp +++ b/cmds/statsd/src/external/ResourceHealthManagerPuller.cpp @@ -25,6 +25,7 @@ #include "ResourceHealthManagerPuller.h" #include "logd/LogEvent.h" #include "statslog.h" +#include "stats_log_util.h" using android::hardware::hidl_vec; using android::hardware::health::V2_0::get_health_service; @@ -61,7 +62,8 @@ bool ResourceHealthManagerPuller::PullInternal(vector<shared_ptr<LogEvent>>* dat return false; } - uint64_t timestamp = time(nullptr) * NS_PER_SEC; + int64_t wallClockTimestampNs = getWallClockNs(); + int64_t elapsedTimestampNs = getElapsedRealtimeNs(); data->clear(); bool result_success = true; @@ -72,12 +74,14 @@ bool ResourceHealthManagerPuller::PullInternal(vector<shared_ptr<LogEvent>>* dat return; } if (mTagId == android::util::REMAINING_BATTERY_CAPACITY) { - auto ptr = make_shared<LogEvent>(android::util::REMAINING_BATTERY_CAPACITY, timestamp); + auto ptr = make_shared<LogEvent>(android::util::REMAINING_BATTERY_CAPACITY, + wallClockTimestampNs, elapsedTimestampNs); ptr->write(v.legacy.batteryChargeCounter); ptr->init(); data->push_back(ptr); } else if (mTagId == android::util::FULL_BATTERY_CAPACITY) { - auto ptr = make_shared<LogEvent>(android::util::FULL_BATTERY_CAPACITY, timestamp); + auto ptr = make_shared<LogEvent>(android::util::FULL_BATTERY_CAPACITY, + wallClockTimestampNs, elapsedTimestampNs); ptr->write(v.legacy.batteryFullCharge); ptr->init(); data->push_back(ptr); diff --git a/cmds/statsd/src/external/StatsCompanionServicePuller.cpp b/cmds/statsd/src/external/StatsCompanionServicePuller.cpp index 8210c8dcd63d..bd859fd79a09 100644 --- a/cmds/statsd/src/external/StatsCompanionServicePuller.cpp +++ b/cmds/statsd/src/external/StatsCompanionServicePuller.cpp @@ -22,6 +22,7 @@ #include <private/android_filesystem_config.h> #include "StatsCompanionServicePuller.h" #include "StatsService.h" +#include "stats_log_util.h" #include "guardrail/StatsdStats.h" using namespace android; @@ -53,13 +54,13 @@ bool StatsCompanionServicePuller::PullInternal(vector<shared_ptr<LogEvent> >* da return false; } data->clear(); - int timestamp = time(nullptr); + int32_t timestampSec = getWallClockSec(); for (const StatsLogEventWrapper& it : returned_value) { log_msg tmp; tmp.entry_v1.len = it.bytes.size(); // Manually set the header size to 28 bytes to match the pushed log events. tmp.entry.hdr_size = kLogMsgHeaderSize; - tmp.entry_v1.sec = timestamp; + tmp.entry_v1.sec = timestampSec; // And set the received bytes starting after the 28 bytes reserved for header. std::copy(it.bytes.begin(), it.bytes.end(), tmp.buf + kLogMsgHeaderSize); data->push_back(make_shared<LogEvent>(tmp)); diff --git a/cmds/statsd/src/external/StatsPuller.cpp b/cmds/statsd/src/external/StatsPuller.cpp index fc0ad7c5c3fc..9513cc521af7 100644 --- a/cmds/statsd/src/external/StatsPuller.cpp +++ b/cmds/statsd/src/external/StatsPuller.cpp @@ -20,6 +20,7 @@ #include "StatsPuller.h" #include "guardrail/StatsdStats.h" #include "puller_util.h" +#include "stats_log_util.h" namespace android { namespace os { @@ -44,7 +45,7 @@ StatsPuller::StatsPuller(const int tagId) bool StatsPuller::Pull(std::vector<std::shared_ptr<LogEvent>>* data) { lock_guard<std::mutex> lock(mLock); StatsdStats::getInstance().notePull(mTagId); - long curTime = time(nullptr); + long curTime = getElapsedRealtimeSec(); if (curTime - mLastPullTimeSec < mCoolDownSec) { (*data) = mCachedData; StatsdStats::getInstance().notePullFromCache(mTagId); diff --git a/cmds/statsd/src/external/StatsPullerManagerImpl.cpp b/cmds/statsd/src/external/StatsPullerManagerImpl.cpp index 4c676a70363f..08c59cfed518 100644 --- a/cmds/statsd/src/external/StatsPullerManagerImpl.cpp +++ b/cmds/statsd/src/external/StatsPullerManagerImpl.cpp @@ -33,6 +33,7 @@ #include "SubsystemSleepStatePuller.h" #include "logd/LogEvent.h" #include "statslog.h" +#include "stats_log_util.h" #include <iostream> @@ -165,8 +166,9 @@ void StatsPullerManagerImpl::RegisterReceiver(int tagId, wp<PullDataReceiver> re if (roundedIntervalMs < mCurrentPullingInterval) { VLOG("Updating pulling interval %ld", intervalMs); mCurrentPullingInterval = roundedIntervalMs; - long currentTimeMs = time(nullptr) * 1000; - long nextAlarmTimeMs = currentTimeMs + mCurrentPullingInterval - (currentTimeMs - mTimeBaseSec * 1000) % mCurrentPullingInterval; + long currentTimeMs = getElapsedRealtimeMillis(); + long nextAlarmTimeMs = currentTimeMs + mCurrentPullingInterval - + (currentTimeMs - mTimeBaseSec * 1000) % mCurrentPullingInterval; if (mStatsCompanionService != nullptr) { mStatsCompanionService->setPullingAlarms(nextAlarmTimeMs, mCurrentPullingInterval); } else { @@ -195,7 +197,7 @@ void StatsPullerManagerImpl::UnRegisterReceiver(int tagId, wp<PullDataReceiver> void StatsPullerManagerImpl::OnAlarmFired() { AutoMutex _l(mReceiversLock); - uint64_t currentTimeMs = time(nullptr) /60 * 60 * 1000; + uint64_t currentTimeMs = getElapsedRealtimeMillis(); vector<pair<int, vector<ReceiverInfo*>>> needToPull = vector<pair<int, vector<ReceiverInfo*>>>(); diff --git a/cmds/statsd/src/external/SubsystemSleepStatePuller.cpp b/cmds/statsd/src/external/SubsystemSleepStatePuller.cpp index 65a1df0eda20..4501b64ad47e 100644 --- a/cmds/statsd/src/external/SubsystemSleepStatePuller.cpp +++ b/cmds/statsd/src/external/SubsystemSleepStatePuller.cpp @@ -36,6 +36,7 @@ #include "SubsystemSleepStatePuller.h" #include "logd/LogEvent.h" #include "statslog.h" +#include "stats_log_util.h" using android::hardware::hidl_vec; using android::hardware::power::V1_0::IPower; @@ -84,20 +85,22 @@ bool SubsystemSleepStatePuller::PullInternal(vector<shared_ptr<LogEvent>>* data) return false; } - uint64_t timestamp = time(nullptr) * NS_PER_SEC; + int64_t wallClockTimestampNs = getWallClockNs(); + int64_t elapsedTimestampNs = getElapsedRealtimeNs(); data->clear(); Return<void> ret; ret = gPowerHalV1_0->getPlatformLowPowerStats( - [&data, timestamp](hidl_vec<PowerStatePlatformSleepState> states, Status status) { + [&data, wallClockTimestampNs, elapsedTimestampNs](hidl_vec<PowerStatePlatformSleepState> states, Status status) { if (status != Status::SUCCESS) return; for (size_t i = 0; i < states.size(); i++) { const PowerStatePlatformSleepState& state = states[i]; - auto statePtr = make_shared<LogEvent>(android::util::SUBSYSTEM_SLEEP_STATE, - timestamp); + auto statePtr = make_shared<LogEvent>( + android::util::SUBSYSTEM_SLEEP_STATE, + wallClockTimestampNs, elapsedTimestampNs); statePtr->write(state.name); statePtr->write(""); statePtr->write(state.totalTransitions); @@ -109,8 +112,9 @@ bool SubsystemSleepStatePuller::PullInternal(vector<shared_ptr<LogEvent>>* data) (long long)state.totalTransitions, state.supportedOnlyInSuspend ? 1 : 0); for (auto voter : state.voters) { - auto voterPtr = make_shared<LogEvent>(android::util::SUBSYSTEM_SLEEP_STATE, - timestamp); + auto voterPtr = make_shared<LogEvent>( + android::util::SUBSYSTEM_SLEEP_STATE, + wallClockTimestampNs, elapsedTimestampNs); voterPtr->write(state.name); voterPtr->write(voter.name); voterPtr->write(voter.totalNumberOfTimesVotedSinceBoot); @@ -135,7 +139,7 @@ bool SubsystemSleepStatePuller::PullInternal(vector<shared_ptr<LogEvent>>* data) android::hardware::power::V1_1::IPower::castFrom(gPowerHalV1_0); if (gPowerHal_1_1 != nullptr) { ret = gPowerHal_1_1->getSubsystemLowPowerStats( - [&data, timestamp](hidl_vec<PowerStateSubsystem> subsystems, Status status) { + [&data, wallClockTimestampNs, elapsedTimestampNs](hidl_vec<PowerStateSubsystem> subsystems, Status status) { if (status != Status::SUCCESS) return; if (subsystems.size() > 0) { @@ -145,7 +149,8 @@ bool SubsystemSleepStatePuller::PullInternal(vector<shared_ptr<LogEvent>>* data) const PowerStateSubsystemSleepState& state = subsystem.states[j]; auto subsystemStatePtr = make_shared<LogEvent>( - android::util::SUBSYSTEM_SLEEP_STATE, timestamp); + android::util::SUBSYSTEM_SLEEP_STATE, + wallClockTimestampNs, elapsedTimestampNs); subsystemStatePtr->write(subsystem.name); subsystemStatePtr->write(state.name); subsystemStatePtr->write(state.totalTransitions); diff --git a/cmds/statsd/src/guardrail/StatsdStats.cpp b/cmds/statsd/src/guardrail/StatsdStats.cpp index 06c5b0049a3b..e2e94263ed8f 100644 --- a/cmds/statsd/src/guardrail/StatsdStats.cpp +++ b/cmds/statsd/src/guardrail/StatsdStats.cpp @@ -80,7 +80,7 @@ std::map<int, long> StatsdStats::kPullerCooldownMap = { // TODO: add stats for pulled atoms. StatsdStats::StatsdStats() { mPushedAtomStats.resize(android::util::kMaxPushedAtomId + 1); - mStartTimeSec = time(nullptr); + mStartTimeSec = getWallClockSec(); } StatsdStats& StatsdStats::getInstance() { @@ -99,7 +99,7 @@ void StatsdStats::addToIceBoxLocked(const StatsdStatsReport_ConfigStats& stats) void StatsdStats::noteConfigReceived(const ConfigKey& key, int metricsCount, int conditionsCount, int matchersCount, int alertsCount, bool isValid) { lock_guard<std::mutex> lock(mLock); - int32_t nowTimeSec = time(nullptr); + int32_t nowTimeSec = getWallClockSec(); // If there is an existing config for the same key, icebox the old config. noteConfigRemovedInternalLocked(key); @@ -125,7 +125,7 @@ void StatsdStats::noteConfigReceived(const ConfigKey& key, int metricsCount, int void StatsdStats::noteConfigRemovedInternalLocked(const ConfigKey& key) { auto it = mConfigStats.find(key); if (it != mConfigStats.end()) { - int32_t nowTimeSec = time(nullptr); + int32_t nowTimeSec = getWallClockSec(); it->second.set_deletion_time_sec(nowTimeSec); // Add condition stats, metrics stats, matcher stats, alert stats addSubStatsToConfigLocked(key, it->second); @@ -145,7 +145,7 @@ void StatsdStats::noteConfigRemoved(const ConfigKey& key) { } void StatsdStats::noteBroadcastSent(const ConfigKey& key) { - noteBroadcastSent(key, time(nullptr)); + noteBroadcastSent(key, getWallClockSec()); } void StatsdStats::noteBroadcastSent(const ConfigKey& key, int32_t timeSec) { @@ -164,7 +164,7 @@ void StatsdStats::noteBroadcastSent(const ConfigKey& key, int32_t timeSec) { } void StatsdStats::noteDataDropped(const ConfigKey& key) { - noteDataDropped(key, time(nullptr)); + noteDataDropped(key, getWallClockSec()); } void StatsdStats::noteDataDropped(const ConfigKey& key, int32_t timeSec) { @@ -183,7 +183,7 @@ void StatsdStats::noteDataDropped(const ConfigKey& key, int32_t timeSec) { } void StatsdStats::noteMetricsReportSent(const ConfigKey& key) { - noteMetricsReportSent(key, time(nullptr)); + noteMetricsReportSent(key, getWallClockSec()); } void StatsdStats::noteMetricsReportSent(const ConfigKey& key, int32_t timeSec) { @@ -275,10 +275,6 @@ void StatsdStats::notePullFromCache(int pullAtomId) { void StatsdStats::noteAtomLogged(int atomId, int32_t timeSec) { lock_guard<std::mutex> lock(mLock); - if (timeSec < mStartTimeSec) { - return; - } - if (atomId > android::util::kMaxPushedAtomId) { ALOGW("not interested in atom %d", atomId); return; @@ -293,7 +289,7 @@ void StatsdStats::noteLoggerError(int error) { if (mLoggerErrors.size() == kMaxLoggerErrors) { mLoggerErrors.pop_front(); } - mLoggerErrors.push_back(std::make_pair(time(nullptr), error)); + mLoggerErrors.push_back(std::make_pair(getWallClockSec(), error)); } void StatsdStats::reset() { @@ -303,7 +299,7 @@ void StatsdStats::reset() { void StatsdStats::resetInternalLocked() { // Reset the historical data, but keep the active ConfigStats - mStartTimeSec = time(nullptr); + mStartTimeSec = getWallClockSec(); mIceBox.clear(); mConditionStats.clear(); mMetricsStats.clear(); @@ -495,7 +491,7 @@ void StatsdStats::dumpStats(std::vector<uint8_t>* output, bool reset) { ProtoOutputStream proto; proto.write(FIELD_TYPE_INT32 | FIELD_ID_BEGIN_TIME, mStartTimeSec); - proto.write(FIELD_TYPE_INT32 | FIELD_ID_END_TIME, (int32_t)time(nullptr)); + proto.write(FIELD_TYPE_INT32 | FIELD_ID_END_TIME, (int32_t)getWallClockSec()); for (const auto& configStats : mIceBox) { const int numBytes = configStats.ByteSize(); diff --git a/cmds/statsd/src/logd/LogEvent.cpp b/cmds/statsd/src/logd/LogEvent.cpp index 45fb5da3b67b..7489d9b72e94 100644 --- a/cmds/statsd/src/logd/LogEvent.cpp +++ b/cmds/statsd/src/logd/LogEvent.cpp @@ -33,7 +33,7 @@ using android::util::ProtoOutputStream; LogEvent::LogEvent(log_msg& msg) { mContext = create_android_log_parser(msg.msg() + sizeof(uint32_t), msg.len() - sizeof(uint32_t)); - mTimestampNs = msg.entry_v1.sec * NS_PER_SEC + msg.entry_v1.nsec; + mLogdTimestampNs = msg.entry_v1.sec * NS_PER_SEC + msg.entry_v1.nsec; mLogUid = msg.entry_v4.uid; init(mContext); if (mContext) { @@ -42,12 +42,24 @@ LogEvent::LogEvent(log_msg& msg) { } } -LogEvent::LogEvent(int32_t tagId, uint64_t timestampNs) { - mTimestampNs = timestampNs; +LogEvent::LogEvent(int32_t tagId, int64_t wallClockTimestampNs, int64_t elapsedTimestampNs) { + mLogdTimestampNs = wallClockTimestampNs; mTagId = tagId; mLogUid = 0; mContext = create_android_logger(1937006964); // the event tag shared by all stats logs if (mContext) { + android_log_write_int64(mContext, elapsedTimestampNs); + android_log_write_int32(mContext, tagId); + } +} + +LogEvent::LogEvent(int32_t tagId, int64_t timestampNs) { + mLogdTimestampNs = timestampNs; + mTagId = tagId; + mLogUid = 0; + mContext = create_android_logger(1937006964); // the event tag shared by all stats logs + if (mContext) { + android_log_write_int64(mContext, timestampNs); android_log_write_int32(mContext, tagId); } } @@ -176,8 +188,8 @@ void LogEvent::init(android_log_context context) { elem = android_log_read_next(context); switch ((int)elem.type) { case EVENT_TYPE_INT: - // elem at [0] is EVENT_TYPE_LIST, [1] is the tag id. - if (i == 1) { + // elem at [0] is EVENT_TYPE_LIST, [1] is the timestamp, [2] is tag id. + if (i == 2) { mTagId = elem.data.int32; } else { if (depth < 0 || depth > 2) { @@ -214,15 +226,18 @@ void LogEvent::init(android_log_context context) { } break; case EVENT_TYPE_LONG: { - if (depth < 0 || depth > 2) { - ALOGE("Depth > 2. Not supported!"); - return; - } - mValues.push_back( - FieldValue(Field(mTagId, pos, depth), Value((int64_t)elem.data.int64))); - - pos[depth]++; + if (i == 1) { + mElapsedTimestampNs = elem.data.int64; + } else { + if (depth < 0 || depth > 2) { + ALOGE("Depth > 2. Not supported!"); + return; + } + mValues.push_back( + FieldValue(Field(mTagId, pos, depth), Value((int64_t)elem.data.int64))); + pos[depth]++; + } } break; case EVENT_TYPE_LIST: depth++; @@ -370,7 +385,7 @@ float LogEvent::GetFloat(size_t key, status_t* err) const { string LogEvent::ToString() const { ostringstream result; - result << "{ " << mTimestampNs << " (" << mTagId << ")"; + result << "{ " << mLogdTimestampNs << " " << mElapsedTimestampNs << " (" << mTagId << ")"; for (const auto& value : mValues) { result << StringPrintf("%#x", value.mField.getField()); result << "->"; diff --git a/cmds/statsd/src/logd/LogEvent.h b/cmds/statsd/src/logd/LogEvent.h index 0895daa49ad3..b3084d54d848 100644 --- a/cmds/statsd/src/logd/LogEvent.h +++ b/cmds/statsd/src/logd/LogEvent.h @@ -47,14 +47,18 @@ public: /** * Constructs a LogEvent with synthetic data for testing. Must call init() before reading. */ - explicit LogEvent(int32_t tagId, uint64_t timestampNs); + explicit LogEvent(int32_t tagId, int64_t wallClockTimestampNs, int64_t elapsedTimestampNs); + + // For testing. The timestamp is used as both elapsed real time and logd timestamp. + explicit LogEvent(int32_t tagId, int64_t timestampNs); ~LogEvent(); /** * Get the timestamp associated with this event. */ - inline uint64_t GetTimestampNs() const { return mTimestampNs; } + inline int64_t GetLogdTimestampNs() const { return mLogdTimestampNs; } + inline int64_t GetElapsedTimestampNs() const { return mElapsedTimestampNs; } /** * Get the tag for this event. @@ -107,9 +111,18 @@ public: void init(); /** - * Set timestamp if the original timestamp is missing. + * Set elapsed timestamp if the original timestamp is missing. */ - void setTimestampNs(uint64_t timestampNs) {mTimestampNs = timestampNs;} + void setElapsedTimestampNs(int64_t timestampNs) { + mElapsedTimestampNs = timestampNs; + } + + /** + * Set the timestamp if the original logd timestamp is missing. + */ + void setLogdWallClockTimestampNs(int64_t timestampNs) { + mLogdTimestampNs = timestampNs; + } inline int size() const { return mValues.size(); @@ -144,7 +157,11 @@ private: // When the log event is created from log msg, this field is never initiated. android_log_context mContext = NULL; - uint64_t mTimestampNs; + // The timestamp set by the logd. + int64_t mLogdTimestampNs; + + // The elapsed timestamp set by statsd log writer. + int64_t mElapsedTimestampNs; int mTagId; diff --git a/cmds/statsd/src/metrics/CountMetricProducer.cpp b/cmds/statsd/src/metrics/CountMetricProducer.cpp index bd2674b86a46..178db1ae5e5f 100644 --- a/cmds/statsd/src/metrics/CountMetricProducer.cpp +++ b/cmds/statsd/src/metrics/CountMetricProducer.cpp @@ -52,8 +52,8 @@ const int FIELD_ID_DIMENSION_IN_WHAT = 1; const int FIELD_ID_DIMENSION_IN_CONDITION = 2; const int FIELD_ID_BUCKET_INFO = 3; // for CountBucketInfo -const int FIELD_ID_START_BUCKET_NANOS = 1; -const int FIELD_ID_END_BUCKET_NANOS = 2; +const int FIELD_ID_START_BUCKET_ELAPSED_NANOS = 1; +const int FIELD_ID_END_BUCKET_ELAPSED_NANOS = 2; const int FIELD_ID_COUNT = 3; CountMetricProducer::CountMetricProducer(const ConfigKey& key, const CountMetric& metric, @@ -107,7 +107,6 @@ void CountMetricProducer::onDumpReportLocked(const uint64_t dumpTimeNs, if (mPastBuckets.empty()) { return; } - protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_ID, (long long)mMetricId); long long protoToken = protoOutput->start(FIELD_TYPE_MESSAGE | FIELD_ID_COUNT_METRICS); @@ -132,12 +131,13 @@ void CountMetricProducer::onDumpReportLocked(const uint64_t dumpTimeNs, } // Then fill bucket_info (CountBucketInfo). + for (const auto& bucket : counter.second) { long long bucketInfoToken = protoOutput->start( FIELD_TYPE_MESSAGE | FIELD_COUNT_REPEATED | FIELD_ID_BUCKET_INFO); - protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_START_BUCKET_NANOS, + protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_START_BUCKET_ELAPSED_NANOS, (long long)bucket.mBucketStartNs); - protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_END_BUCKET_NANOS, + protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_END_BUCKET_ELAPSED_NANOS, (long long)bucket.mBucketEndNs); protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_COUNT, (long long)bucket.mCount); protoOutput->end(bucketInfoToken); @@ -184,7 +184,7 @@ void CountMetricProducer::onMatchedLogEventInternalLocked( const size_t matcherIndex, const MetricDimensionKey& eventKey, const ConditionKey& conditionKey, bool condition, const LogEvent& event) { - uint64_t eventTimeNs = event.GetTimestampNs(); + uint64_t eventTimeNs = event.GetElapsedTimestampNs(); flushIfNeededLocked(eventTimeNs); if (condition == false) { diff --git a/cmds/statsd/src/metrics/DurationMetricProducer.cpp b/cmds/statsd/src/metrics/DurationMetricProducer.cpp index 6b321e11edcf..af22578cc758 100644 --- a/cmds/statsd/src/metrics/DurationMetricProducer.cpp +++ b/cmds/statsd/src/metrics/DurationMetricProducer.cpp @@ -51,8 +51,8 @@ const int FIELD_ID_DIMENSION_IN_WHAT = 1; const int FIELD_ID_DIMENSION_IN_CONDITION = 2; const int FIELD_ID_BUCKET_INFO = 3; // for DurationBucketInfo -const int FIELD_ID_START_BUCKET_NANOS = 1; -const int FIELD_ID_END_BUCKET_NANOS = 2; +const int FIELD_ID_START_BUCKET_ELAPSED_NANOS = 1; +const int FIELD_ID_END_BUCKET_ELAPSED_NANOS = 2; const int FIELD_ID_DURATION = 3; DurationMetricProducer::DurationMetricProducer(const ConfigKey& key, const DurationMetric& metric, @@ -221,9 +221,9 @@ void DurationMetricProducer::onDumpReportLocked(const uint64_t dumpTimeNs, for (const auto& bucket : pair.second) { long long bucketInfoToken = protoOutput->start( FIELD_TYPE_MESSAGE | FIELD_COUNT_REPEATED | FIELD_ID_BUCKET_INFO); - protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_START_BUCKET_NANOS, + protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_START_BUCKET_ELAPSED_NANOS, (long long)bucket.mBucketStartNs); - protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_END_BUCKET_NANOS, + protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_END_BUCKET_ELAPSED_NANOS, (long long)bucket.mBucketEndNs); protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_DURATION, (long long)bucket.mDuration); protoOutput->end(bucketInfoToken); @@ -310,11 +310,11 @@ void DurationMetricProducer::onMatchedLogEventInternalLocked( const size_t matcherIndex, const MetricDimensionKey& eventKey, const ConditionKey& conditionKeys, bool condition, const LogEvent& event) { - flushIfNeededLocked(event.GetTimestampNs()); + flushIfNeededLocked(event.GetElapsedTimestampNs()); if (matcherIndex == mStopAllIndex) { for (auto& pair : mCurrentSlicedDurationTrackerMap) { - pair.second->noteStopAll(event.GetTimestampNs()); + pair.second->noteStopAll(event.GetElapsedTimestampNs()); } return; } @@ -333,16 +333,16 @@ void DurationMetricProducer::onMatchedLogEventInternalLocked( if (values.empty()) { if (matcherIndex == mStartIndex) { it->second->noteStart(DEFAULT_DIMENSION_KEY, condition, - event.GetTimestampNs(), conditionKeys); + event.GetElapsedTimestampNs(), conditionKeys); } else if (matcherIndex == mStopIndex) { - it->second->noteStop(DEFAULT_DIMENSION_KEY, event.GetTimestampNs(), false); + it->second->noteStop(DEFAULT_DIMENSION_KEY, event.GetElapsedTimestampNs(), false); } } else { for (const auto& value : values) { if (matcherIndex == mStartIndex) { - it->second->noteStart(value, condition, event.GetTimestampNs(), conditionKeys); + it->second->noteStart(value, condition, event.GetElapsedTimestampNs(), conditionKeys); } else if (matcherIndex == mStopIndex) { - it->second->noteStop(value, event.GetTimestampNs(), false); + it->second->noteStop(value, event.GetElapsedTimestampNs(), false); } } } diff --git a/cmds/statsd/src/metrics/EventMetricProducer.cpp b/cmds/statsd/src/metrics/EventMetricProducer.cpp index ed7e44de09c0..2585aa3bdbff 100644 --- a/cmds/statsd/src/metrics/EventMetricProducer.cpp +++ b/cmds/statsd/src/metrics/EventMetricProducer.cpp @@ -19,6 +19,7 @@ #include "EventMetricProducer.h" #include "stats_util.h" +#include "stats_log_util.h" #include <limits.h> #include <stdlib.h> @@ -46,8 +47,9 @@ const int FIELD_ID_EVENT_METRICS = 4; // for EventMetricDataWrapper const int FIELD_ID_DATA = 1; // for EventMetricData -const int FIELD_ID_TIMESTAMP_NANOS = 1; +const int FIELD_ID_ELAPSED_TIMESTAMP_NANOS = 1; const int FIELD_ID_ATOMS = 2; +const int FIELD_ID_WALL_CLOCK_TIMESTAMP_NANOS = 3; EventMetricProducer::EventMetricProducer(const ConfigKey& key, const EventMetric& metric, const int conditionIndex, @@ -127,9 +129,12 @@ void EventMetricProducer::onMatchedLogEventInternalLocked( long long wrapperToken = mProto->start(FIELD_TYPE_MESSAGE | FIELD_COUNT_REPEATED | FIELD_ID_DATA); - mProto->write(FIELD_TYPE_INT64 | FIELD_ID_TIMESTAMP_NANOS, (long long)event.GetTimestampNs()); + mProto->write(FIELD_TYPE_INT64 | FIELD_ID_ELAPSED_TIMESTAMP_NANOS, + (long long)event.GetElapsedTimestampNs()); long long eventToken = mProto->start(FIELD_TYPE_MESSAGE | FIELD_ID_ATOMS); event.ToProto(*mProto); + mProto->write(FIELD_TYPE_INT64 | FIELD_ID_WALL_CLOCK_TIMESTAMP_NANOS, + (long long)getWallClockNs()); mProto->end(eventToken); mProto->end(wrapperToken); } diff --git a/cmds/statsd/src/metrics/GaugeMetricProducer.cpp b/cmds/statsd/src/metrics/GaugeMetricProducer.cpp index da0cafeca427..af3b4c5a648a 100644 --- a/cmds/statsd/src/metrics/GaugeMetricProducer.cpp +++ b/cmds/statsd/src/metrics/GaugeMetricProducer.cpp @@ -52,10 +52,10 @@ const int FIELD_ID_DIMENSION_IN_WHAT = 1; const int FIELD_ID_DIMENSION_IN_CONDITION = 2; const int FIELD_ID_BUCKET_INFO = 3; // for GaugeBucketInfo -const int FIELD_ID_START_BUCKET_NANOS = 1; -const int FIELD_ID_END_BUCKET_NANOS = 2; +const int FIELD_ID_START_BUCKET_ELAPSED_NANOS = 1; +const int FIELD_ID_END_BUCKET_ELAPSED_NANOS = 2; const int FIELD_ID_ATOM = 3; -const int FIELD_ID_TIMESTAMP = 4; +const int FIELD_ID_ELAPSED_ATOM_TIMESTAMP = 4; GaugeMetricProducer::GaugeMetricProducer(const ConfigKey& key, const GaugeMetric& metric, const int conditionIndex, @@ -161,9 +161,9 @@ void GaugeMetricProducer::onDumpReportLocked(const uint64_t dumpTimeNs, for (const auto& bucket : pair.second) { long long bucketInfoToken = protoOutput->start( FIELD_TYPE_MESSAGE | FIELD_COUNT_REPEATED | FIELD_ID_BUCKET_INFO); - protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_START_BUCKET_NANOS, + protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_START_BUCKET_ELAPSED_NANOS, (long long)bucket.mBucketStartNs); - protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_END_BUCKET_NANOS, + protoOutput->write(FIELD_TYPE_INT64 | FIELD_ID_END_BUCKET_ELAPSED_NANOS, (long long)bucket.mBucketEndNs); if (!bucket.mGaugeAtoms.empty()) { @@ -175,8 +175,9 @@ void GaugeMetricProducer::onDumpReportLocked(const uint64_t dumpTimeNs, protoOutput->end(atomsToken); for (const auto& atom : bucket.mGaugeAtoms) { - protoOutput->write(FIELD_TYPE_INT64 | FIELD_COUNT_REPEATED | FIELD_ID_TIMESTAMP, - (long long)atom.mTimestamps); + protoOutput->write( + FIELD_TYPE_INT64 | FIELD_COUNT_REPEATED | FIELD_ID_ELAPSED_ATOM_TIMESTAMP, + (long long)atom.mTimestamps); } } protoOutput->end(bucketInfoToken); @@ -293,7 +294,7 @@ void GaugeMetricProducer::onMatchedLogEventInternalLocked( if (condition == false) { return; } - uint64_t eventTimeNs = event.GetTimestampNs(); + uint64_t eventTimeNs = event.GetElapsedTimestampNs(); mTagId = event.GetTagId(); if (eventTimeNs < mCurrentBucketStartTimeNs) { VLOG("Skip event due to late arrival: %lld vs %lld", (long long)eventTimeNs, diff --git a/cmds/statsd/src/metrics/MetricProducer.cpp b/cmds/statsd/src/metrics/MetricProducer.cpp index beb90155f183..f3307dc1d1e3 100644 --- a/cmds/statsd/src/metrics/MetricProducer.cpp +++ b/cmds/statsd/src/metrics/MetricProducer.cpp @@ -25,7 +25,7 @@ namespace statsd { using std::map; void MetricProducer::onMatchedLogEventLocked(const size_t matcherIndex, const LogEvent& event) { - uint64_t eventTimeNs = event.GetTimestampNs(); + uint64_t eventTimeNs = event.GetElapsedTimestampNs(); // this is old event, maybe statsd restarted? if (eventTimeNs < mStartTimeNs) { return; diff --git a/cmds/statsd/src/metrics/MetricsManager.cpp b/cmds/statsd/src/metrics/MetricsManager.cpp index dd6735b6faca..ae48c522363a 100644 --- a/cmds/statsd/src/metrics/MetricsManager.cpp +++ b/cmds/statsd/src/metrics/MetricsManager.cpp @@ -26,6 +26,7 @@ #include "matchers/SimpleLogMatchingTracker.h" #include "metrics_manager_util.h" #include "stats_util.h" +#include "stats_log_util.h" #include <log/logprint.h> #include <private/android_filesystem_config.h> @@ -49,9 +50,10 @@ const int FIELD_ID_METRICS = 1; MetricsManager::MetricsManager(const ConfigKey& key, const StatsdConfig& config, const long timeBaseSec, sp<UidMap> uidMap) - : mConfigKey(key), mUidMap(uidMap), mLastReportTimeNs(0) { + : mConfigKey(key), mUidMap(uidMap), mLastReportTimeNs(timeBaseSec * NS_PER_SEC) { mConfigValid = - initStatsdConfig(key, config, *uidMap, timeBaseSec, mTagIds, mAllAtomMatchers, mAllConditionTrackers, + initStatsdConfig(key, config, *uidMap, timeBaseSec, mTagIds, mAllAtomMatchers, + mAllConditionTrackers, mAllMetricProducers, mAllAnomalyTrackers, mConditionToMetricMap, mTrackerToMetricMap, mTrackerToConditionMap, mNoReportMetricIds); @@ -176,7 +178,7 @@ void MetricsManager::onDumpReport(const uint64_t dumpTimeStampNs, ProtoOutputStr protoOutput->end(token); } } - mLastReportTimeNs = ::android::elapsedRealtimeNano(); + mLastReportTimeNs = dumpTimeStampNs; VLOG("=========================Metric Reports End=========================="); } @@ -230,7 +232,7 @@ void MetricsManager::onLogEvent(const LogEvent& event) { } int tagId = event.GetTagId(); - uint64_t eventTime = event.GetTimestampNs(); + uint64_t eventTime = event.GetElapsedTimestampNs(); if (mTagIds.find(tagId) == mTagIds.end()) { // not interesting... return; diff --git a/cmds/statsd/src/metrics/ValueMetricProducer.cpp b/cmds/statsd/src/metrics/ValueMetricProducer.cpp index 45b4ac0cd43a..cbca884ae6f3 100644 --- a/cmds/statsd/src/metrics/ValueMetricProducer.cpp +++ b/cmds/statsd/src/metrics/ValueMetricProducer.cpp @@ -219,19 +219,19 @@ void ValueMetricProducer::onDataPulled(const std::vector<std::shared_ptr<LogEven } // For scheduled pulled data, the effective event time is snap to the nearest // bucket boundary to make bucket finalize. - uint64_t realEventTime = allData.at(0)->GetTimestampNs(); + uint64_t realEventTime = allData.at(0)->GetElapsedTimestampNs(); uint64_t eventTime = mStartTimeNs + - ((realEventTime - mStartTimeNs)/mBucketSizeNs) * mBucketSizeNs; + ((realEventTime - mStartTimeNs) / mBucketSizeNs) * mBucketSizeNs; mCondition = false; for (const auto& data : allData) { - data->setTimestampNs(eventTime-1); + data->setElapsedTimestampNs(eventTime - 1); onMatchedLogEventLocked(0, *data); } mCondition = true; for (const auto& data : allData) { - data->setTimestampNs(eventTime); + data->setElapsedTimestampNs(eventTime); onMatchedLogEventLocked(0, *data); } } @@ -261,7 +261,7 @@ void ValueMetricProducer::onMatchedLogEventInternalLocked( const size_t matcherIndex, const MetricDimensionKey& eventKey, const ConditionKey& conditionKey, bool condition, const LogEvent& event) { - uint64_t eventTimeNs = event.GetTimestampNs(); + uint64_t eventTimeNs = event.GetElapsedTimestampNs(); if (eventTimeNs < mCurrentBucketStartTimeNs) { VLOG("Skip event due to late arrival: %lld vs %lld", (long long)eventTimeNs, (long long)mCurrentBucketStartTimeNs); diff --git a/cmds/statsd/src/metrics/ValueMetricProducer.h b/cmds/statsd/src/metrics/ValueMetricProducer.h index 6701a46acde1..b518f2f841cf 100644 --- a/cmds/statsd/src/metrics/ValueMetricProducer.h +++ b/cmds/statsd/src/metrics/ValueMetricProducer.h @@ -62,7 +62,7 @@ public: // Pretend the pulled data occurs right before the app upgrade event. mCondition = false; for (const auto& data : allData) { - data->setTimestampNs(eventTimeNs - 1); + data->setElapsedTimestampNs(eventTimeNs - 1); onMatchedLogEventLocked(0, *data); } @@ -71,7 +71,7 @@ public: mCondition = true; for (const auto& data : allData) { - data->setTimestampNs(eventTimeNs); + data->setElapsedTimestampNs(eventTimeNs); onMatchedLogEventLocked(0, *data); } } else { // For pushed value metric, we simply flush and reset the current bucket start. diff --git a/cmds/statsd/src/packages/UidMap.cpp b/cmds/statsd/src/packages/UidMap.cpp index 691423e054b2..e322ca4bb1ac 100644 --- a/cmds/statsd/src/packages/UidMap.cpp +++ b/cmds/statsd/src/packages/UidMap.cpp @@ -16,6 +16,7 @@ #define DEBUG true // STOPSHIP if true #include "Log.h" +#include "stats_log_util.h" #include "guardrail/StatsdStats.h" #include "packages/UidMap.h" @@ -82,7 +83,7 @@ int64_t UidMap::getAppVersion(int uid, const string& packageName) const { void UidMap::updateMap(const vector<int32_t>& uid, const vector<int64_t>& versionCode, const vector<String16>& packageName) { - updateMap(time(nullptr) * NS_PER_SEC, uid, versionCode, packageName); + updateMap(getElapsedRealtimeNs(), uid, versionCode, packageName); } void UidMap::updateMap(const int64_t& timestamp, const vector<int32_t>& uid, @@ -98,7 +99,7 @@ void UidMap::updateMap(const int64_t& timestamp, const vector<int32_t>& uid, } auto snapshot = mOutput.add_snapshots(); - snapshot->set_timestamp_nanos(timestamp); + snapshot->set_elapsed_timestamp_nanos(timestamp); for (size_t j = 0; j < uid.size(); j++) { auto t = snapshot->add_package_info(); t->set_name(string(String8(packageName[j]).string())); @@ -125,7 +126,7 @@ void UidMap::updateMap(const int64_t& timestamp, const vector<int32_t>& uid, } void UidMap::updateApp(const String16& app_16, const int32_t& uid, const int64_t& versionCode) { - updateApp(time(nullptr) * NS_PER_SEC, app_16, uid, versionCode); + updateApp(getElapsedRealtimeNs(), app_16, uid, versionCode); } void UidMap::updateApp(const int64_t& timestamp, const String16& app_16, const int32_t& uid, @@ -137,7 +138,7 @@ void UidMap::updateApp(const int64_t& timestamp, const String16& app_16, const i auto log = mOutput.add_changes(); log->set_deletion(false); - log->set_timestamp_nanos(timestamp); + log->set_elapsed_timestamp_nanos(timestamp); log->set_app(appName); log->set_uid(uid); log->set_version(versionCode); @@ -194,7 +195,7 @@ void UidMap::ensureBytesUsedBelowLimit() { } void UidMap::removeApp(const String16& app_16, const int32_t& uid) { - removeApp(time(nullptr) * NS_PER_SEC, app_16, uid); + removeApp(getElapsedRealtimeNs(), app_16, uid); } void UidMap::getListenerListCopyLocked(vector<wp<PackageInfoListener>>* output) { @@ -218,7 +219,7 @@ void UidMap::removeApp(const int64_t& timestamp, const String16& app_16, const i auto log = mOutput.add_changes(); log->set_deletion(true); - log->set_timestamp_nanos(timestamp); + log->set_elapsed_timestamp_nanos(timestamp); log->set_app(app); log->set_uid(uid); mBytesUsed += log->ByteSize(); @@ -305,7 +306,7 @@ size_t UidMap::getBytesUsed() const { } UidMapping UidMap::getOutput(const ConfigKey& key) { - return getOutput(time(nullptr) * NS_PER_SEC, key); + return getOutput(getElapsedRealtimeNs(), key); } UidMapping UidMap::getOutput(const int64_t& timestamp, const ConfigKey& key) { @@ -321,7 +322,7 @@ UidMapping UidMap::getOutput(const int64_t& timestamp, const ConfigKey& key) { auto snapshots = mOutput.mutable_snapshots(); auto it_snapshots = snapshots->cbegin(); while (it_snapshots != snapshots->cend()) { - if (it_snapshots->timestamp_nanos() < cutoff_nanos) { + if (it_snapshots->elapsed_timestamp_nanos() < cutoff_nanos) { // it_snapshots points to the following element after erasing. it_snapshots = snapshots->erase(it_snapshots); } else { @@ -331,7 +332,7 @@ UidMapping UidMap::getOutput(const int64_t& timestamp, const ConfigKey& key) { auto deltas = mOutput.mutable_changes(); auto it_deltas = deltas->cbegin(); while (it_deltas != deltas->cend()) { - if (it_deltas->timestamp_nanos() < cutoff_nanos) { + if (it_deltas->elapsed_timestamp_nanos() < cutoff_nanos) { // it_snapshots points to the following element after erasing. it_deltas = deltas->erase(it_deltas); } else { @@ -343,7 +344,7 @@ UidMapping UidMap::getOutput(const int64_t& timestamp, const ConfigKey& key) { // Produce another snapshot. This results in extra data being uploaded but helps // ensure we can re-construct the UID->app name, versionCode mapping in server. auto snapshot = mOutput.add_snapshots(); - snapshot->set_timestamp_nanos(timestamp); + snapshot->set_elapsed_timestamp_nanos(timestamp); for (auto it : mMap) { auto t = snapshot->add_package_info(); t->set_name(it.second.packageName); diff --git a/cmds/statsd/src/stats_log.proto b/cmds/statsd/src/stats_log.proto index b56cffb40806..b427485fd705 100644 --- a/cmds/statsd/src/stats_log.proto +++ b/cmds/statsd/src/stats_log.proto @@ -42,15 +42,17 @@ message DimensionsValueTuple { } message EventMetricData { - optional int64 timestamp_nanos = 1; + optional int64 elapsed_timestamp_nanos = 1; optional Atom atom = 2; + + optional int64 wall_clock_timestamp_sec = 3; } message CountBucketInfo { - optional int64 start_bucket_nanos = 1; + optional int64 start_bucket_elapsed_nanos = 1; - optional int64 end_bucket_nanos = 2; + optional int64 end_bucket_elapsed_nanos = 2; optional int64 count = 3; } @@ -64,9 +66,9 @@ message CountMetricData { } message DurationBucketInfo { - optional int64 start_bucket_nanos = 1; + optional int64 start_bucket_elapsed_nanos = 1; - optional int64 end_bucket_nanos = 2; + optional int64 end_bucket_elapsed_nanos = 2; optional int64 duration_nanos = 3; } @@ -80,9 +82,9 @@ message DurationMetricData { } message ValueBucketInfo { - optional int64 start_bucket_nanos = 1; + optional int64 start_bucket_elapsed_nanos = 1; - optional int64 end_bucket_nanos = 2; + optional int64 end_bucket_elapsed_nanos = 2; optional int64 value = 3; } @@ -102,7 +104,7 @@ message GaugeBucketInfo { repeated Atom atom = 3; - repeated int64 timestamp_nanos = 4; + repeated int64 elapsed_timestamp_nanos = 4; } message GaugeMetricData { @@ -122,7 +124,7 @@ message UidMapping { optional int32 uid = 3; } - optional int64 timestamp_nanos = 1; + optional int64 elapsed_timestamp_nanos = 1; repeated PackageInfo package_info = 2; } @@ -131,7 +133,7 @@ message UidMapping { message Change { optional bool deletion = 1; - optional int64 timestamp_nanos = 2; + optional int64 elapsed_timestamp_nanos = 2; optional string app = 3; optional int32 uid = 4; @@ -176,9 +178,9 @@ message ConfigMetricsReport { optional UidMapping uid_map = 2; - optional int64 last_report_nanos = 3; + optional int64 last_report_elapsed_nanos = 3; - optional int64 current_report_nanos = 4; + optional int64 current_report_elapsed_nanos = 4; } message ConfigMetricsReportList { diff --git a/cmds/statsd/src/stats_log_util.cpp b/cmds/statsd/src/stats_log_util.cpp index 86c258bd3dfd..e73577041f75 100644 --- a/cmds/statsd/src/stats_log_util.cpp +++ b/cmds/statsd/src/stats_log_util.cpp @@ -20,6 +20,8 @@ #include <utils/Log.h> #include <set> #include <stack> +#include <utils/Log.h> +#include <utils/SystemClock.h> using android::util::FIELD_COUNT_REPEATED; using android::util::FIELD_TYPE_BOOL; @@ -263,6 +265,30 @@ void writePullerStatsToStream(const std::pair<int, StatsdStats::PulledAtomStats> protoOutput->end(token); } +int64_t getElapsedRealtimeNs() { + return ::android::elapsedRealtimeNano(); +} + +int64_t getElapsedRealtimeSec() { + return ::android::elapsedRealtimeNano() / NS_PER_SEC; +} + +int64_t getElapsedRealtimeMillis() { + return ::android::elapsedRealtime(); +} + +int64_t getWallClockNs() { + return time(nullptr) * NS_PER_SEC; +} + +int64_t getWallClockSec() { + return time(nullptr); +} + +int64_t getWallClockMillis() { + return time(nullptr) * MS_PER_SEC; +} + } // namespace statsd } // namespace os } // namespace android
\ No newline at end of file diff --git a/cmds/statsd/src/stats_log_util.h b/cmds/statsd/src/stats_log_util.h index 6583f579648b..32fe0b8370b8 100644 --- a/cmds/statsd/src/stats_log_util.h +++ b/cmds/statsd/src/stats_log_util.h @@ -35,6 +35,24 @@ void writeDimensionToProto(const HashableDimensionKey& dimension, // Convert the TimeUnit enum to the bucket size in millis. int64_t TimeUnitToBucketSizeInMillis(TimeUnit unit); +// Gets the elapsed timestamp in ns. +int64_t getElapsedRealtimeNs(); + +// Gets the elapsed timestamp in millis. +int64_t getElapsedRealtimeMillis(); + +// Gets the elapsed timestamp in seconds. +int64_t getElapsedRealtimeSec(); + +// Gets the wall clock timestamp in ns. +int64_t getWallClockNs(); + +// Gets the wall clock timestamp in millis. +int64_t getWallClockMillis(); + +// Gets the wall clock timestamp in seconds. +int64_t getWallClockSec(); + // Helper function to write PulledAtomStats to ProtoOutputStream void writePullerStatsToStream(const std::pair<int, StatsdStats::PulledAtomStats>& pair, util::ProtoOutputStream* protoOutput); diff --git a/cmds/statsd/src/storage/StorageManager.cpp b/cmds/statsd/src/storage/StorageManager.cpp index 23bd55616be2..6a1db72b3911 100644 --- a/cmds/statsd/src/storage/StorageManager.cpp +++ b/cmds/statsd/src/storage/StorageManager.cpp @@ -20,6 +20,7 @@ #include "android-base/stringprintf.h" #include "guardrail/StatsdStats.h" #include "storage/StorageManager.h" +#include "stats_log_util.h" #include <android-base/file.h> #include <dirent.h> @@ -252,7 +253,7 @@ void StorageManager::trimToFit(const char* path) { string file_name = getFilePath(path, timestamp, uid, configID); // Check for timestamp and delete if it's too old. - long fileAge = time(nullptr) - timestamp; + long fileAge = getWallClockSec() - timestamp; if (fileAge > StatsdStats::kMaxAgeSecond) { deleteFile(file_name.c_str()); } diff --git a/cmds/statsd/tests/e2e/Attribution_e2e_test.cpp b/cmds/statsd/tests/e2e/Attribution_e2e_test.cpp index 01743ef1a45c..93cd5875c52b 100644 --- a/cmds/statsd/tests/e2e/Attribution_e2e_test.cpp +++ b/cmds/statsd/tests/e2e/Attribution_e2e_test.cpp @@ -163,11 +163,11 @@ TEST(AttributionE2eTest, TestAttributionMatchAndSlice) { "App1"); EXPECT_EQ(data.bucket_info_size(), 2); EXPECT_EQ(data.bucket_info(0).count(), 2); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); EXPECT_EQ(data.bucket_info(1).count(), 1); - EXPECT_EQ(data.bucket_info(1).start_bucket_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); - EXPECT_EQ(data.bucket_info(1).end_bucket_nanos(), bucketStartTimeNs + 3 * bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).start_bucket_elapsed_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).end_bucket_elapsed_nanos(), bucketStartTimeNs + 3 * bucketSizeNs); data = countMetrics.data(1); ValidateAttributionUidAndTagDimension( @@ -175,11 +175,11 @@ TEST(AttributionE2eTest, TestAttributionMatchAndSlice) { "GMSCoreModule1"); EXPECT_EQ(data.bucket_info_size(), 2); EXPECT_EQ(data.bucket_info(0).count(), 1); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); EXPECT_EQ(data.bucket_info(1).count(), 1); - EXPECT_EQ(data.bucket_info(1).start_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); - EXPECT_EQ(data.bucket_info(1).end_bucket_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).start_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).end_bucket_elapsed_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); data = countMetrics.data(2); ValidateAttributionUidAndTagDimension( @@ -187,8 +187,8 @@ TEST(AttributionE2eTest, TestAttributionMatchAndSlice) { "GMSCoreModule3"); EXPECT_EQ(data.bucket_info_size(), 1); EXPECT_EQ(data.bucket_info(0).count(), 1); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs + 3 * bucketSizeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + 4 * bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs + 3 * bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + 4 * bucketSizeNs); data = countMetrics.data(3); ValidateAttributionUidAndTagDimension( @@ -196,8 +196,8 @@ TEST(AttributionE2eTest, TestAttributionMatchAndSlice) { "GMSCoreModule2"); EXPECT_EQ(data.bucket_info_size(), 1); EXPECT_EQ(data.bucket_info(0).count(), 1); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + 3 * bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + 3 * bucketSizeNs); } #else diff --git a/cmds/statsd/tests/e2e/DimensionInCondition_e2e_test.cpp b/cmds/statsd/tests/e2e/DimensionInCondition_e2e_test.cpp index 275b58244e0f..293f579ac848 100644 --- a/cmds/statsd/tests/e2e/DimensionInCondition_e2e_test.cpp +++ b/cmds/statsd/tests/e2e/DimensionInCondition_e2e_test.cpp @@ -142,8 +142,8 @@ TEST(DimensionInConditionE2eTest, TestCountMetricNoLink) { auto data = countMetrics.data(0); EXPECT_EQ(data.bucket_info_size(), 1); EXPECT_EQ(data.bucket_info(0).count(), 1); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); EXPECT_EQ(data.dimensions_in_what().field(), android::util::SCREEN_BRIGHTNESS_CHANGED); EXPECT_EQ(data.dimensions_in_what().value_tuple().dimensions_value_size(), 1); EXPECT_EQ(data.dimensions_in_what().value_tuple().dimensions_value(0).field(), 1); @@ -153,8 +153,8 @@ TEST(DimensionInConditionE2eTest, TestCountMetricNoLink) { data = countMetrics.data(1); EXPECT_EQ(data.bucket_info_size(), 1); EXPECT_EQ(data.bucket_info(0).count(), 1); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); EXPECT_EQ(data.dimensions_in_what().field(), android::util::SCREEN_BRIGHTNESS_CHANGED); EXPECT_EQ(data.dimensions_in_what().value_tuple().dimensions_value_size(), 1); EXPECT_EQ(data.dimensions_in_what().value_tuple().dimensions_value(0).field(), 1); @@ -165,8 +165,8 @@ TEST(DimensionInConditionE2eTest, TestCountMetricNoLink) { data = countMetrics.data(2); EXPECT_EQ(data.bucket_info_size(), 1); EXPECT_EQ(data.bucket_info(0).count(), 3); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); EXPECT_EQ(data.dimensions_in_what().field(), android::util::SCREEN_BRIGHTNESS_CHANGED); EXPECT_EQ(data.dimensions_in_what().value_tuple().dimensions_value_size(), 1); EXPECT_EQ(data.dimensions_in_what().value_tuple().dimensions_value(0).field(), 1); @@ -177,11 +177,11 @@ TEST(DimensionInConditionE2eTest, TestCountMetricNoLink) { data = countMetrics.data(3); EXPECT_EQ(data.bucket_info_size(), 2); EXPECT_EQ(data.bucket_info(0).count(), 2); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); EXPECT_EQ(data.bucket_info(1).count(), 1); - EXPECT_EQ(data.bucket_info(1).start_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); - EXPECT_EQ(data.bucket_info(1).end_bucket_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).start_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).end_bucket_elapsed_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); EXPECT_EQ(data.dimensions_in_what().field(), android::util::SCREEN_BRIGHTNESS_CHANGED); EXPECT_EQ(data.dimensions_in_what().value_tuple().dimensions_value_size(), 1); EXPECT_EQ(data.dimensions_in_what().value_tuple().dimensions_value(0).field(), 1); @@ -192,8 +192,8 @@ TEST(DimensionInConditionE2eTest, TestCountMetricNoLink) { data = countMetrics.data(4); EXPECT_EQ(data.bucket_info_size(), 1); EXPECT_EQ(data.bucket_info(0).count(), 2); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); EXPECT_EQ(data.dimensions_in_what().field(), android::util::SCREEN_BRIGHTNESS_CHANGED); EXPECT_EQ(data.dimensions_in_what().value_tuple().dimensions_value_size(), 1); EXPECT_EQ(data.dimensions_in_what().value_tuple().dimensions_value(0).field(), 1); @@ -203,8 +203,8 @@ TEST(DimensionInConditionE2eTest, TestCountMetricNoLink) { data = countMetrics.data(5); EXPECT_EQ(data.bucket_info_size(), 1); EXPECT_EQ(data.bucket_info(0).count(), 1); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); EXPECT_EQ(data.dimensions_in_what().field(), android::util::SCREEN_BRIGHTNESS_CHANGED); EXPECT_EQ(data.dimensions_in_what().value_tuple().dimensions_value_size(), 1); EXPECT_EQ(data.dimensions_in_what().value_tuple().dimensions_value(0).field(), 1); @@ -215,8 +215,8 @@ TEST(DimensionInConditionE2eTest, TestCountMetricNoLink) { data = countMetrics.data(6); EXPECT_EQ(data.bucket_info_size(), 1); EXPECT_EQ(data.bucket_info(0).count(), 1); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); EXPECT_EQ(data.dimensions_in_what().field(), android::util::SCREEN_BRIGHTNESS_CHANGED); EXPECT_EQ(data.dimensions_in_what().value_tuple().dimensions_value_size(), 1); EXPECT_EQ(data.dimensions_in_what().value_tuple().dimensions_value(0).field(), 1); @@ -358,8 +358,8 @@ TEST(DimensionInConditionE2eTest, TestCountMetricWithLink) { EXPECT_FALSE(data.dimensions_in_condition().has_field()); EXPECT_EQ(data.bucket_info_size(), 1); EXPECT_EQ(data.bucket_info(0).count(), 1); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); data = countMetrics.data(1); EXPECT_EQ(data.dimensions_in_what().field(), android::util::PROCESS_LIFE_CYCLE_STATE_CHANGED); @@ -370,8 +370,8 @@ TEST(DimensionInConditionE2eTest, TestCountMetricWithLink) { android::util::SYNC_STATE_CHANGED, 111, "App1"); EXPECT_EQ(data.bucket_info_size(), 1); EXPECT_EQ(data.bucket_info(0).count(), 2); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); data = countMetrics.data(2); EXPECT_EQ(data.dimensions_in_what().field(), android::util::PROCESS_LIFE_CYCLE_STATE_CHANGED); @@ -381,8 +381,8 @@ TEST(DimensionInConditionE2eTest, TestCountMetricWithLink) { EXPECT_FALSE(data.dimensions_in_condition().has_field()); EXPECT_EQ(data.bucket_info_size(), 1); EXPECT_EQ(data.bucket_info(0).count(), 2); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); data = countMetrics.data(3); EXPECT_EQ(data.dimensions_in_what().field(), android::util::PROCESS_LIFE_CYCLE_STATE_CHANGED); @@ -393,11 +393,11 @@ TEST(DimensionInConditionE2eTest, TestCountMetricWithLink) { android::util::SYNC_STATE_CHANGED, 333, "App2"); EXPECT_EQ(data.bucket_info_size(), 2); EXPECT_EQ(data.bucket_info(0).count(), 1); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); EXPECT_EQ(data.bucket_info(1).count(), 1); - EXPECT_EQ(data.bucket_info(1).start_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); - EXPECT_EQ(data.bucket_info(1).end_bucket_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).start_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).end_bucket_elapsed_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); data = countMetrics.data(4); EXPECT_EQ(data.dimensions_in_what().field(), android::util::PROCESS_LIFE_CYCLE_STATE_CHANGED); @@ -407,8 +407,8 @@ TEST(DimensionInConditionE2eTest, TestCountMetricWithLink) { EXPECT_FALSE(data.dimensions_in_condition().has_field()); EXPECT_EQ(data.bucket_info_size(), 1); EXPECT_EQ(data.bucket_info(0).count(), 1); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); } namespace { @@ -531,11 +531,11 @@ TEST(DimensionInConditionE2eTest, TestDurationMetricNoLink) { EXPECT_FALSE(data.dimensions_in_condition().has_field()); EXPECT_EQ(data.bucket_info_size(), 2); EXPECT_EQ(data.bucket_info(0).duration_nanos(), 9); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); EXPECT_EQ(data.bucket_info(1).duration_nanos(), 30); - EXPECT_EQ(data.bucket_info(1).start_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); - EXPECT_EQ(data.bucket_info(1).end_bucket_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).start_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).end_bucket_elapsed_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); data = metrics.data(1); EXPECT_FALSE(data.dimensions_in_what().has_field()); @@ -543,11 +543,11 @@ TEST(DimensionInConditionE2eTest, TestDurationMetricNoLink) { android::util::SYNC_STATE_CHANGED, 111, "App1"); EXPECT_EQ(data.bucket_info_size(), 2); EXPECT_EQ(data.bucket_info(0).duration_nanos(), 500 - 201 + bucketSizeNs - 600); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); EXPECT_EQ(data.bucket_info(1).duration_nanos(), 300); - EXPECT_EQ(data.bucket_info(1).start_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); - EXPECT_EQ(data.bucket_info(1).end_bucket_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).start_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).end_bucket_elapsed_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); data = metrics.data(2); EXPECT_FALSE(data.dimensions_in_what().has_field()); @@ -555,11 +555,11 @@ TEST(DimensionInConditionE2eTest, TestDurationMetricNoLink) { android::util::SYNC_STATE_CHANGED, 333, "App2"); EXPECT_EQ(data.bucket_info_size(), 2); EXPECT_EQ(data.bucket_info(0).duration_nanos(), 500 - 401 + bucketSizeNs - 600); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); EXPECT_EQ(data.bucket_info(1).duration_nanos(), 700); - EXPECT_EQ(data.bucket_info(1).start_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); - EXPECT_EQ(data.bucket_info(1).end_bucket_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).start_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).end_bucket_elapsed_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); } } @@ -693,8 +693,8 @@ TEST(DimensionInConditionE2eTest, TestDurationMetricWithLink) { EXPECT_FALSE(data.dimensions_in_condition().has_field()); EXPECT_EQ(data.bucket_info_size(), 1); EXPECT_EQ(data.bucket_info(0).duration_nanos(), 9); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); data = metrics.data(1); EXPECT_EQ(data.dimensions_in_what().value_tuple().dimensions_value(0).field(), 1); @@ -703,11 +703,11 @@ TEST(DimensionInConditionE2eTest, TestDurationMetricWithLink) { android::util::SYNC_STATE_CHANGED, 111, "App1"); EXPECT_EQ(data.bucket_info_size(), 2); EXPECT_EQ(data.bucket_info(0).duration_nanos(), bucketSizeNs - 201); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); EXPECT_EQ(data.bucket_info(1).duration_nanos(), 100); - EXPECT_EQ(data.bucket_info(1).start_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); - EXPECT_EQ(data.bucket_info(1).end_bucket_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).start_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).end_bucket_elapsed_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); data = metrics.data(2); EXPECT_EQ(data.dimensions_in_what().value_tuple().dimensions_value(0).field(), 1); @@ -716,11 +716,11 @@ TEST(DimensionInConditionE2eTest, TestDurationMetricWithLink) { android::util::SYNC_STATE_CHANGED, 333, "App2"); EXPECT_EQ(data.bucket_info_size(), 2); EXPECT_EQ(data.bucket_info(0).duration_nanos(), bucketSizeNs - 401); - EXPECT_EQ(data.bucket_info(0).start_bucket_nanos(), bucketStartTimeNs); - EXPECT_EQ(data.bucket_info(0).end_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(0).start_bucket_elapsed_nanos(), bucketStartTimeNs); + EXPECT_EQ(data.bucket_info(0).end_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); EXPECT_EQ(data.bucket_info(1).duration_nanos(), 700); - EXPECT_EQ(data.bucket_info(1).start_bucket_nanos(), bucketStartTimeNs + bucketSizeNs); - EXPECT_EQ(data.bucket_info(1).end_bucket_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).start_bucket_elapsed_nanos(), bucketStartTimeNs + bucketSizeNs); + EXPECT_EQ(data.bucket_info(1).end_bucket_elapsed_nanos(), bucketStartTimeNs + 2 * bucketSizeNs); } } diff --git a/cmds/statsd/tests/e2e/WakelockDuration_e2e_test.cpp b/cmds/statsd/tests/e2e/WakelockDuration_e2e_test.cpp index 3b25694b6517..024fa3e23180 100644 --- a/cmds/statsd/tests/e2e/WakelockDuration_e2e_test.cpp +++ b/cmds/statsd/tests/e2e/WakelockDuration_e2e_test.cpp @@ -315,9 +315,9 @@ TEST(WakelockDurationE2eTest, TestAggregatedPredicateDimensionsForMaxDuration3) android::util::WAKELOCK_STATE_CHANGED, 111); // The last wakelock holding spans 4 buckets. EXPECT_EQ((unsigned long long)data.bucket_info(1).duration_nanos(), 3 * bucketSizeNs); - EXPECT_EQ((unsigned long long)data.bucket_info(1).start_bucket_nanos(), + EXPECT_EQ((unsigned long long)data.bucket_info(1).start_bucket_elapsed_nanos(), bucketStartTimeNs + 5 * bucketSizeNs); - EXPECT_EQ((unsigned long long)data.bucket_info(1).end_bucket_nanos(), + EXPECT_EQ((unsigned long long)data.bucket_info(1).end_bucket_elapsed_nanos(), bucketStartTimeNs + 6 * bucketSizeNs); } diff --git a/cmds/statsd/tests/guardrail/StatsdStats_test.cpp b/cmds/statsd/tests/guardrail/StatsdStats_test.cpp index a1343002405b..bd114439b83c 100644 --- a/cmds/statsd/tests/guardrail/StatsdStats_test.cpp +++ b/cmds/statsd/tests/guardrail/StatsdStats_test.cpp @@ -225,7 +225,7 @@ TEST(StatsdStatsTest, TestAtomLog) { bool dropboxAtomGood = false; for (const auto& atomStats : report.atom_stats()) { - if (atomStats.tag() == android::util::SENSOR_STATE_CHANGED && atomStats.count() == 2) { + if (atomStats.tag() == android::util::SENSOR_STATE_CHANGED && atomStats.count() == 3) { sensorAtomGood = true; } if (atomStats.tag() == android::util::DROPBOX_ERROR_CHANGED && atomStats.count() == 1) { diff --git a/cmds/statsd/tests/metrics/CountMetricProducer_test.cpp b/cmds/statsd/tests/metrics/CountMetricProducer_test.cpp index 1e71b73ca9fa..d9dbf1d7cadc 100644 --- a/cmds/statsd/tests/metrics/CountMetricProducer_test.cpp +++ b/cmds/statsd/tests/metrics/CountMetricProducer_test.cpp @@ -48,7 +48,9 @@ TEST(CountMetricProducerTest, TestNonDimensionalEvents) { metric.set_bucket(ONE_MINUTE); LogEvent event1(tagId, bucketStartTimeNs + 1); + event1.init(); LogEvent event2(tagId, bucketStartTimeNs + 2); + event2.init(); sp<MockConditionWizard> wizard = new NaggyMock<MockConditionWizard>(); @@ -76,6 +78,8 @@ TEST(CountMetricProducerTest, TestNonDimensionalEvents) { // 1 matched event happens in bucket 2. LogEvent event3(tagId, bucketStartTimeNs + bucketSizeNs + 2); + event3.init(); + countProducer.onMatchedLogEvent(1 /*log matcher index*/, event3); countProducer.flushIfNeededLocked(bucketStartTimeNs + 2 * bucketSizeNs + 1); EXPECT_EQ(1UL, countProducer.mPastBuckets.size()); @@ -106,7 +110,10 @@ TEST(CountMetricProducerTest, TestEventsWithNonSlicedCondition) { metric.set_condition(StringToId("SCREEN_ON")); LogEvent event1(1, bucketStartTimeNs + 1); + event1.init(); + LogEvent event2(1, bucketStartTimeNs + 10); + event2.init(); sp<MockConditionWizard> wizard = new NaggyMock<MockConditionWizard>(); @@ -326,12 +333,19 @@ TEST(CountMetricProducerTest, TestAnomalyDetectionUnSliced) { int tagId = 1; LogEvent event1(tagId, bucketStartTimeNs + 1); + event1.init(); LogEvent event2(tagId, bucketStartTimeNs + 2); + event2.init(); LogEvent event3(tagId, bucketStartTimeNs + 2 * bucketSizeNs + 1); + event3.init(); LogEvent event4(tagId, bucketStartTimeNs + 3 * bucketSizeNs + 1); + event4.init(); LogEvent event5(tagId, bucketStartTimeNs + 3 * bucketSizeNs + 2); + event5.init(); LogEvent event6(tagId, bucketStartTimeNs + 3 * bucketSizeNs + 3); + event6.init(); LogEvent event7(tagId, bucketStartTimeNs + 3 * bucketSizeNs + 2 * NS_PER_SEC); + event7.init(); // Two events in bucket #0. countProducer.onMatchedLogEvent(1 /*log matcher index*/, event1); @@ -355,13 +369,13 @@ TEST(CountMetricProducerTest, TestAnomalyDetectionUnSliced) { EXPECT_EQ(3L, countProducer.mCurrentSlicedCounter->begin()->second); // Anomaly at event 6 is within refractory period. The alarm is at event 5 timestamp not event 6 EXPECT_EQ(anomalyTracker->getRefractoryPeriodEndsSec(DEFAULT_METRIC_DIMENSION_KEY), - event5.GetTimestampNs() / NS_PER_SEC + refPeriodSec); + event5.GetElapsedTimestampNs() / NS_PER_SEC + refPeriodSec); countProducer.onMatchedLogEvent(1 /*log matcher index*/, event7); EXPECT_EQ(1UL, countProducer.mCurrentSlicedCounter->size()); EXPECT_EQ(4L, countProducer.mCurrentSlicedCounter->begin()->second); EXPECT_EQ(anomalyTracker->getRefractoryPeriodEndsSec(DEFAULT_METRIC_DIMENSION_KEY), - event7.GetTimestampNs() / NS_PER_SEC + refPeriodSec); + event7.GetElapsedTimestampNs() / NS_PER_SEC + refPeriodSec); } } // namespace statsd diff --git a/cmds/statsd/tests/metrics/DurationMetricProducer_test.cpp b/cmds/statsd/tests/metrics/DurationMetricProducer_test.cpp index 23e15f78a96c..57e2794c0eea 100644 --- a/cmds/statsd/tests/metrics/DurationMetricProducer_test.cpp +++ b/cmds/statsd/tests/metrics/DurationMetricProducer_test.cpp @@ -51,7 +51,9 @@ TEST(DurationMetricTrackerTest, TestNoCondition) { int tagId = 1; LogEvent event1(tagId, bucketStartTimeNs + 1); + event1.init(); LogEvent event2(tagId, bucketStartTimeNs + bucketSizeNs + 2); + event2.init(); FieldMatcher dimensions; DurationMetricProducer durationProducer( @@ -86,9 +88,13 @@ TEST(DurationMetricTrackerTest, TestNonSlicedCondition) { int tagId = 1; LogEvent event1(tagId, bucketStartTimeNs + 1); + event1.init(); LogEvent event2(tagId, bucketStartTimeNs + 2); + event2.init(); LogEvent event3(tagId, bucketStartTimeNs + bucketSizeNs + 1); + event3.init(); LogEvent event4(tagId, bucketStartTimeNs + bucketSizeNs + 3); + event4.init(); FieldMatcher dimensions; DurationMetricProducer durationProducer( @@ -144,7 +150,9 @@ TEST(DurationMetricTrackerTest, TestSumDurationWithUpgrade) { kConfigKey, metric, -1 /* no condition */, 1 /* start index */, 2 /* stop index */, 3 /* stop_all index */, false /*nesting*/, wizard, dimensions, bucketStartTimeNs); - durationProducer.onMatchedLogEvent(1 /* start index*/, LogEvent(tagId, startTimeNs)); + LogEvent start_event(tagId, startTimeNs); + start_event.init(); + durationProducer.onMatchedLogEvent(1 /* start index*/, start_event); EXPECT_EQ(0UL, durationProducer.mPastBuckets.size()); EXPECT_EQ(bucketStartTimeNs, durationProducer.mCurrentBucketStartTimeNs); @@ -158,7 +166,9 @@ TEST(DurationMetricTrackerTest, TestSumDurationWithUpgrade) { EXPECT_EQ(eventUpgradeTimeNs, durationProducer.mCurrentBucketStartTimeNs); // We skip ahead one bucket, so we fill in the first two partial buckets and one full bucket. - durationProducer.onMatchedLogEvent(2 /* stop index*/, LogEvent(tagId, endTimeNs)); + LogEvent end_event(tagId, endTimeNs); + end_event.init(); + durationProducer.onMatchedLogEvent(2 /* stop index*/, end_event); buckets = durationProducer.mPastBuckets[DEFAULT_METRIC_DIMENSION_KEY]; EXPECT_EQ(3UL, buckets.size()); EXPECT_EQ(eventUpgradeTimeNs, buckets[1].mBucketStartNs); @@ -194,7 +204,9 @@ TEST(DurationMetricTrackerTest, TestSumDurationWithUpgradeInFollowingBucket) { kConfigKey, metric, -1 /* no condition */, 1 /* start index */, 2 /* stop index */, 3 /* stop_all index */, false /*nesting*/, wizard, dimensions, bucketStartTimeNs); - durationProducer.onMatchedLogEvent(1 /* start index*/, LogEvent(tagId, startTimeNs)); + LogEvent start_event(tagId, startTimeNs); + start_event.init(); + durationProducer.onMatchedLogEvent(1 /* start index*/, start_event); EXPECT_EQ(0UL, durationProducer.mPastBuckets.size()); EXPECT_EQ(bucketStartTimeNs, durationProducer.mCurrentBucketStartTimeNs); @@ -211,7 +223,9 @@ TEST(DurationMetricTrackerTest, TestSumDurationWithUpgradeInFollowingBucket) { EXPECT_EQ(eventUpgradeTimeNs, durationProducer.mCurrentBucketStartTimeNs); // We skip ahead one bucket, so we fill in the first two partial buckets and one full bucket. - durationProducer.onMatchedLogEvent(2 /* stop index*/, LogEvent(tagId, endTimeNs)); + LogEvent end_event(tagId, endTimeNs); + end_event.init(); + durationProducer.onMatchedLogEvent(2 /* stop index*/, end_event); buckets = durationProducer.mPastBuckets[DEFAULT_METRIC_DIMENSION_KEY]; EXPECT_EQ(3UL, buckets.size()); EXPECT_EQ(eventUpgradeTimeNs, buckets[2].mBucketStartNs); @@ -245,10 +259,14 @@ TEST(DurationMetricTrackerTest, TestSumDurationAnomalyWithUpgrade) { sp<AnomalyTracker> anomalyTracker = durationProducer.addAnomalyTracker(alert); EXPECT_TRUE(anomalyTracker != nullptr); - durationProducer.onMatchedLogEvent(1 /* start index*/, LogEvent(tagId, startTimeNs)); + LogEvent start_event(tagId, startTimeNs); + start_event.init(); + durationProducer.onMatchedLogEvent(1 /* start index*/, start_event); durationProducer.notifyAppUpgrade(eventUpgradeTimeNs, "ANY.APP", 1, 1); // We skip ahead one bucket, so we fill in the first two partial buckets and one full bucket. - durationProducer.onMatchedLogEvent(2 /* stop index*/, LogEvent(tagId, endTimeNs)); + LogEvent end_event(tagId, endTimeNs); + end_event.init(); + durationProducer.onMatchedLogEvent(2 /* stop index*/, end_event); EXPECT_EQ(bucketStartTimeNs + bucketSizeNs - startTimeNs, (uint64_t)anomalyTracker->getSumOverPastBuckets(DEFAULT_METRIC_DIMENSION_KEY)); @@ -276,7 +294,9 @@ TEST(DurationMetricTrackerTest, TestMaxDurationWithUpgrade) { kConfigKey, metric, -1 /* no condition */, 1 /* start index */, 2 /* stop index */, 3 /* stop_all index */, false /*nesting*/, wizard, dimensions, bucketStartTimeNs); - durationProducer.onMatchedLogEvent(1 /* start index*/, LogEvent(tagId, startTimeNs)); + LogEvent start_event(tagId, startTimeNs); + start_event.init(); + durationProducer.onMatchedLogEvent(1 /* start index*/, start_event); EXPECT_EQ(0UL, durationProducer.mPastBuckets.size()); EXPECT_EQ(bucketStartTimeNs, durationProducer.mCurrentBucketStartTimeNs); @@ -285,7 +305,9 @@ TEST(DurationMetricTrackerTest, TestMaxDurationWithUpgrade) { EXPECT_EQ(eventUpgradeTimeNs, durationProducer.mCurrentBucketStartTimeNs); // We skip ahead one bucket, so we fill in the first two partial buckets and one full bucket. - durationProducer.onMatchedLogEvent(2 /* stop index*/, LogEvent(tagId, endTimeNs)); + LogEvent end_event(tagId, endTimeNs); + end_event.init(); + durationProducer.onMatchedLogEvent(2 /* stop index*/, end_event); EXPECT_EQ(0UL, durationProducer.mPastBuckets[DEFAULT_METRIC_DIMENSION_KEY].size()); durationProducer.flushIfNeededLocked(bucketStartTimeNs + 3 * bucketSizeNs + 1); @@ -319,7 +341,9 @@ TEST(DurationMetricTrackerTest, TestMaxDurationWithUpgradeInNextBucket) { kConfigKey, metric, -1 /* no condition */, 1 /* start index */, 2 /* stop index */, 3 /* stop_all index */, false /*nesting*/, wizard, dimensions, bucketStartTimeNs); - durationProducer.onMatchedLogEvent(1 /* start index*/, LogEvent(tagId, startTimeNs)); + LogEvent start_event(tagId, startTimeNs); + start_event.init(); + durationProducer.onMatchedLogEvent(1 /* start index*/, start_event); EXPECT_EQ(0UL, durationProducer.mPastBuckets.size()); EXPECT_EQ(bucketStartTimeNs, durationProducer.mCurrentBucketStartTimeNs); @@ -328,7 +352,9 @@ TEST(DurationMetricTrackerTest, TestMaxDurationWithUpgradeInNextBucket) { EXPECT_EQ(eventUpgradeTimeNs, durationProducer.mCurrentBucketStartTimeNs); // Stop occurs in the same partial bucket as created for the app upgrade. - durationProducer.onMatchedLogEvent(2 /* stop index*/, LogEvent(tagId, endTimeNs)); + LogEvent end_event(tagId, endTimeNs); + end_event.init(); + durationProducer.onMatchedLogEvent(2 /* stop index*/, end_event); EXPECT_EQ(0UL, durationProducer.mPastBuckets[DEFAULT_METRIC_DIMENSION_KEY].size()); EXPECT_EQ(eventUpgradeTimeNs, durationProducer.mCurrentBucketStartTimeNs); diff --git a/cmds/statsd/tests/metrics/GaugeMetricProducer_test.cpp b/cmds/statsd/tests/metrics/GaugeMetricProducer_test.cpp index 26f7c2669f15..8b4273bc7929 100644 --- a/cmds/statsd/tests/metrics/GaugeMetricProducer_test.cpp +++ b/cmds/statsd/tests/metrics/GaugeMetricProducer_test.cpp @@ -387,7 +387,7 @@ TEST(GaugeMetricProducerTest, TestAnomalyDetection) { .mFields->begin() ->mValue.int_value); EXPECT_EQ(anomalyTracker->getRefractoryPeriodEndsSec(DEFAULT_METRIC_DIMENSION_KEY), - event2->GetTimestampNs() / NS_PER_SEC + refPeriodSec); + event2->GetElapsedTimestampNs() / NS_PER_SEC + refPeriodSec); std::shared_ptr<LogEvent> event3 = std::make_shared<LogEvent>(tagId, bucketStartTimeNs + 2 * bucketSizeNs + 10); @@ -402,7 +402,7 @@ TEST(GaugeMetricProducerTest, TestAnomalyDetection) { .mFields->begin() ->mValue.int_value); EXPECT_EQ(anomalyTracker->getRefractoryPeriodEndsSec(DEFAULT_METRIC_DIMENSION_KEY), - event2->GetTimestampNs() / NS_PER_SEC + refPeriodSec); + event2->GetElapsedTimestampNs() / NS_PER_SEC + refPeriodSec); // The event4 does not have the gauge field. Thus the current bucket value is 0. std::shared_ptr<LogEvent> event4 = diff --git a/cmds/statsd/tests/metrics/ValueMetricProducer_test.cpp b/cmds/statsd/tests/metrics/ValueMetricProducer_test.cpp index 325a372d8056..6e66c6e8dcb6 100644 --- a/cmds/statsd/tests/metrics/ValueMetricProducer_test.cpp +++ b/cmds/statsd/tests/metrics/ValueMetricProducer_test.cpp @@ -406,16 +406,16 @@ TEST(ValueMetricProducerTest, TestAnomalyDetection) { valueProducer.onMatchedLogEvent(1 /*log matcher index*/, *event4); // Anomaly at event 4 since Value sum == 131 > 130! EXPECT_EQ(anomalyTracker->getRefractoryPeriodEndsSec(DEFAULT_METRIC_DIMENSION_KEY), - event4->GetTimestampNs() / NS_PER_SEC + refPeriodSec); + event4->GetElapsedTimestampNs() / NS_PER_SEC + refPeriodSec); valueProducer.onMatchedLogEvent(1 /*log matcher index*/, *event5); // Event 5 is within 3 sec refractory period. Thus last alarm timestamp is still event4. EXPECT_EQ(anomalyTracker->getRefractoryPeriodEndsSec(DEFAULT_METRIC_DIMENSION_KEY), - event4->GetTimestampNs() / NS_PER_SEC + refPeriodSec); + event4->GetElapsedTimestampNs() / NS_PER_SEC + refPeriodSec); valueProducer.onMatchedLogEvent(1 /*log matcher index*/, *event6); // Anomaly at event 6 since Value sum == 160 > 130 and after refractory period. EXPECT_EQ(anomalyTracker->getRefractoryPeriodEndsSec(DEFAULT_METRIC_DIMENSION_KEY), - event6->GetTimestampNs() / NS_PER_SEC + refPeriodSec); + event6->GetElapsedTimestampNs() / NS_PER_SEC + refPeriodSec); } } // namespace statsd diff --git a/cmds/statsd/tests/statsd_test_util.cpp b/cmds/statsd/tests/statsd_test_util.cpp index d3a89617e921..b7acef75fafb 100644 --- a/cmds/statsd/tests/statsd_test_util.cpp +++ b/cmds/statsd/tests/statsd_test_util.cpp @@ -406,7 +406,7 @@ AttributionNode CreateAttribution(const int& uid, const string& tag) { void sortLogEventsByTimestamp(std::vector<std::unique_ptr<LogEvent>> *events) { std::sort(events->begin(), events->end(), [](const std::unique_ptr<LogEvent>& a, const std::unique_ptr<LogEvent>& b) { - return a->GetTimestampNs() < b->GetTimestampNs(); + return a->GetElapsedTimestampNs() < b->GetElapsedTimestampNs(); }); } diff --git a/cmds/statsd/tools/dogfood/src/com/android/statsd/dogfood/DisplayProtoUtils.java b/cmds/statsd/tools/dogfood/src/com/android/statsd/dogfood/DisplayProtoUtils.java index 03e5fef5d717..b6b16e40a4b2 100644 --- a/cmds/statsd/tools/dogfood/src/com/android/statsd/dogfood/DisplayProtoUtils.java +++ b/cmds/statsd/tools/dogfood/src/com/android/statsd/dogfood/DisplayProtoUtils.java @@ -32,9 +32,9 @@ public class DisplayProtoUtils { for (StatsLog.ConfigMetricsReport report : reports.getReportsList()) { sb.append("StatsLogReport size: ").append(report.getMetricsCount()).append("\n"); - sb.append("Last report time:").append(getDateStr(report.getLastReportNanos())). + sb.append("Last report time:").append(getDateStr(report.getLastReportElapsedNanos())). append("\n"); - sb.append("Current report time:").append(getDateStr(report.getCurrentReportNanos())). + sb.append("Current report time:").append(getDateStr(report.getCurrentReportElapsedNanos())). append("\n"); for (StatsLog.StatsLogReport log : report.getMetricsList()) { sb.append("\n\n"); @@ -109,8 +109,8 @@ public class DisplayProtoUtils { } for (StatsLog.DurationBucketInfo info : duration.getBucketInfoList()) { - sb.append("\t[").append(getDateStr(info.getStartBucketNanos())).append("-") - .append(getDateStr(info.getEndBucketNanos())).append("] -> ") + sb.append("\t[").append(getDateStr(info.getStartBucketElapsedNanos())).append("-") + .append(getDateStr(info.getEndBucketElapsedNanos())).append("] -> ") .append(info.getDurationNanos()).append(" ns\n"); } } @@ -121,7 +121,7 @@ public class DisplayProtoUtils { StatsLog.StatsLogReport.EventMetricDataWrapper eventMetricDataWrapper = log.getEventMetrics(); for (StatsLog.EventMetricData event : eventMetricDataWrapper.getDataList()) { - sb.append(getDateStr(event.getTimestampNanos())).append(": "); + sb.append(getDateStr(event.getElapsedTimestampNanos())).append(": "); sb.append(event.getAtom().getPushedCase().toString()).append("\n"); } } @@ -141,8 +141,8 @@ public class DisplayProtoUtils { } for (StatsLog.CountBucketInfo info : count.getBucketInfoList()) { - sb.append("\t[").append(getDateStr(info.getStartBucketNanos())).append("-") - .append(getDateStr(info.getEndBucketNanos())).append("] -> ") + sb.append("\t[").append(getDateStr(info.getStartBucketElapsedNanos())).append("-") + .append(getDateStr(info.getEndBucketElapsedNanos())).append("] -> ") .append(info.getCount()).append("\n"); } } diff --git a/cmds/statsd/tools/loadtest/src/com/android/statsd/loadtest/DisplayProtoUtils.java b/cmds/statsd/tools/loadtest/src/com/android/statsd/loadtest/DisplayProtoUtils.java index 87b82c261bf1..d55f3f31fd9f 100644 --- a/cmds/statsd/tools/loadtest/src/com/android/statsd/loadtest/DisplayProtoUtils.java +++ b/cmds/statsd/tools/loadtest/src/com/android/statsd/loadtest/DisplayProtoUtils.java @@ -36,9 +36,9 @@ public class DisplayProtoUtils { int numMetrics = 0; for (StatsLog.ConfigMetricsReport report : reports.getReportsList()) { sb.append("StatsLogReport size: ").append(report.getMetricsCount()).append("\n"); - sb.append("Last report time:").append(getDateStr(report.getLastReportNanos())). + sb.append("Last report time:").append(getDateStr(report.getLastReportElapsedNanos())). append("\n"); - sb.append("Current report time:").append(getDateStr(report.getCurrentReportNanos())). + sb.append("Current report time:").append(getDateStr(report.getCurrentReportElapsedNanos())). append("\n"); for (StatsLog.StatsLogReport log : report.getMetricsList()) { numMetrics++; @@ -120,8 +120,8 @@ public class DisplayProtoUtils { } for (StatsLog.DurationBucketInfo info : duration.getBucketInfoList()) { - sb.append("\t[").append(getDateStr(info.getStartBucketNanos())).append("-") - .append(getDateStr(info.getEndBucketNanos())).append("] -> ") + sb.append("\t[").append(getDateStr(info.getStartBucketElapsedNanos())).append("-") + .append(getDateStr(info.getEndBucketElapsedNanos())).append("] -> ") .append(info.getDurationNanos()).append(" ns\n"); } } @@ -132,7 +132,7 @@ public class DisplayProtoUtils { StatsLog.StatsLogReport.EventMetricDataWrapper eventMetricDataWrapper = log.getEventMetrics(); for (StatsLog.EventMetricData event : eventMetricDataWrapper.getDataList()) { - sb.append(getDateStr(event.getTimestampNanos())).append(": "); + sb.append(getDateStr(event.getElapsedTimestampNanos())).append(": "); sb.append(event.getAtom().getPushedCase().toString()).append("\n"); } } @@ -152,8 +152,8 @@ public class DisplayProtoUtils { } for (StatsLog.CountBucketInfo info : count.getBucketInfoList()) { - sb.append("\t[").append(getDateStr(info.getStartBucketNanos())).append("-") - .append(getDateStr(info.getEndBucketNanos())).append("] -> ") + sb.append("\t[").append(getDateStr(info.getStartBucketElapsedNanos())).append("-") + .append(getDateStr(info.getEndBucketElapsedNanos())).append("] -> ") .append(info.getCount()).append("\n"); } } diff --git a/services/core/java/com/android/server/stats/StatsCompanionService.java b/services/core/java/com/android/server/stats/StatsCompanionService.java index 4bc94047b24e..9f9b1af5397e 100644 --- a/services/core/java/com/android/server/stats/StatsCompanionService.java +++ b/services/core/java/com/android/server/stats/StatsCompanionService.java @@ -361,9 +361,11 @@ public class StatsCompanionService extends IStatsCompanionService.Stub { if (DEBUG) Slog.d(TAG, "Setting anomaly alarm for " + timestampMs); final long callingToken = Binder.clearCallingIdentity(); try { - // using RTC, not RTC_WAKEUP, so if device is asleep, will only fire when it awakens. + // using ELAPSED_REALTIME, not ELAPSED_REALTIME_WAKEUP, so if device is asleep, will + // only fire when it awakens. + // This alarm is inexact, leaving its exactness completely up to the OS optimizations. // AlarmManager will automatically cancel any previous mAnomalyAlarmIntent alarm. - mAlarmManager.setExact(AlarmManager.RTC, timestampMs, mAnomalyAlarmIntent); + mAlarmManager.setExact(AlarmManager.ELAPSED_REALTIME, timestampMs, mAnomalyAlarmIntent); } finally { Binder.restoreCallingIdentity(callingToken); } @@ -388,10 +390,12 @@ public class StatsCompanionService extends IStatsCompanionService.Stub { Slog.d(TAG, "Setting pulling alarm for " + timestampMs + " every " + intervalMs + "ms"); final long callingToken = Binder.clearCallingIdentity(); try { - // using RTC, not RTC_WAKEUP, so if device is asleep, will only fire when it awakens. + // using ELAPSED_REALTIME, not ELAPSED_REALTIME_WAKEUP, so if device is asleep, will + // only fire when it awakens. // This alarm is inexact, leaving its exactness completely up to the OS optimizations. // TODO: totally inexact means that stats per bucket could be quite off. Is this okay? - mAlarmManager.setRepeating(AlarmManager.RTC, timestampMs, intervalMs, mPullingAlarmIntent); + mAlarmManager.setRepeating(AlarmManager.ELAPSED_REALTIME, timestampMs, intervalMs, + mPullingAlarmIntent); } finally { Binder.restoreCallingIdentity(callingToken); } diff --git a/tools/stats_log_api_gen/Android.bp b/tools/stats_log_api_gen/Android.bp index e301eb140fc9..dc2ed433d345 100644 --- a/tools/stats_log_api_gen/Android.bp +++ b/tools/stats_log_api_gen/Android.bp @@ -102,6 +102,7 @@ cc_library_shared { export_generated_headers: ["statslog.h"], shared_libs: [ "liblog", + "libutils", ], } diff --git a/tools/stats_log_api_gen/main.cpp b/tools/stats_log_api_gen/main.cpp index 3dbb50306cc6..a78b1a2b0731 100644 --- a/tools/stats_log_api_gen/main.cpp +++ b/tools/stats_log_api_gen/main.cpp @@ -105,6 +105,7 @@ static int write_stats_log_cpp(FILE *out, const Atoms &atoms, fprintf(out, "#include <log/log_event_list.h>\n"); fprintf(out, "#include <log/log.h>\n"); fprintf(out, "#include <statslog.h>\n"); + fprintf(out, "#include <utils/SystemClock.h>\n"); fprintf(out, "\n"); fprintf(out, "namespace android {\n"); @@ -145,6 +146,7 @@ static int write_stats_log_cpp(FILE *out, const Atoms &atoms, fprintf(out, "{\n"); argIndex = 1; fprintf(out, " android_log_event_list event(kStatsEventTag);\n"); + fprintf(out, " event << android::elapsedRealtimeNano();\n\n"); fprintf(out, " event << code;\n\n"); for (vector<java_type_t>::const_iterator arg = signature->begin(); arg != signature->end(); arg++) { |