/* * Copyright (C) 2019 The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ #include "WakeLockEntryList.h" #include #include #include #include #include #include #include using android::base::ParseInt; using android::base::ReadFdToString; using android::base::Readlink; using android::base::StringPrintf; using suspend_service::flags::fast_kernel_wakelock_reporting; using ISCSI = ::android::system::suspend::internal::ISuspendControlServiceInternal; namespace android { namespace system { namespace suspend { namespace V1_0 { namespace { struct BitAndFilename { int32_t bit; std::string filename; }; const BitAndFilename FIELDS[] = { {-1, "name"}, {ISCSI::WAKE_LOCK_INFO_ACTIVE_COUNT, "active_count"}, {ISCSI::WAKE_LOCK_INFO_LAST_CHANGE, "last_change_ms"}, {ISCSI::WAKE_LOCK_INFO_MAX_TIME, "max_time_ms"}, {ISCSI::WAKE_LOCK_INFO_TOTAL_TIME, "total_time_ms"}, {ISCSI::WAKE_LOCK_INFO_ACTIVE_TIME, "active_time_ms"}, {ISCSI::WAKE_LOCK_INFO_EVENT_COUNT, "event_count"}, {ISCSI::WAKE_LOCK_INFO_EXPIRE_COUNT, "expire_count"}, {ISCSI::WAKE_LOCK_INFO_PREVENT_SUSPEND_TIME, "prevent_suspend_time_ms"}, {ISCSI::WAKE_LOCK_INFO_WAKEUP_COUNT, "wakeup_count"}, }; } // namespace static std::ostream& operator<<(std::ostream& out, const WakeLockInfo& entry) { const char* sep = " | "; const char* notApplicable = "---"; bool kernelWakelock = entry.isKernelWakelock; // clang-format off out << sep << std::left << std::setw(30) << entry.name << sep << std::right << std::setw(6) << ((kernelWakelock) ? notApplicable : std::to_string(entry.pid)) << sep << std::left << std::setw(6) << ((kernelWakelock) ? "Kernel" : "Native") << sep << std::left << std::setw(8) << ((entry.isActive) ? "Active" : "Inactive") << sep << std::right << std::setw(12) << entry.activeCount << sep << std::right << std::setw(12) << std::to_string(entry.totalTime) + "ms" << sep << std::right << std::setw(12) << std::to_string(entry.maxTime) + "ms" << sep << std::right << std::setw(12) << ((kernelWakelock) ? std::to_string(entry.eventCount) : notApplicable) << sep << std::right << std::setw(12) << ((kernelWakelock) ? std::to_string(entry.wakeupCount) : notApplicable) << sep << std::right << std::setw(12) << ((kernelWakelock) ? std::to_string(entry.expireCount) : notApplicable) << sep << std::right << std::setw(20) << ((kernelWakelock) ? std::to_string(entry.preventSuspendTime) + "ms" : notApplicable) << sep << std::right << std::setw(16) << std::to_string(entry.lastChange) + "ms" << sep; // clang-format on return out; } std::ostream& operator<<(std::ostream& out, const WakeLockEntryList& list) { std::vector wlStats; list.getWakeLockStats(ISCSI::WAKE_LOCK_INFO_ALL_FIELDS, &wlStats); int width = 194; const char* sep = " | "; std::stringstream ss; ss << " " << std::setfill('-') << std::setw(width) << "\n"; std::string div = ss.str(); out << div; std::stringstream header; header << sep << std::right << std::setw(((width - 14) / 2) + 14) << "WAKELOCK STATS" << std::right << std::setw((width - 14) / 2) << sep << "\n"; out << header.str(); out << div; // Col names // clang-format off out << sep << std::left << std::setw(30) << "NAME" << sep << std::left << std::setw(6) << "PID" << sep << std::left << std::setw(6) << "TYPE" << sep << std::left << std::setw(8) << "STATUS" << sep << std::left << std::setw(12) << "ACTIVE COUNT" << sep << std::left << std::setw(12) << "TOTAL TIME" << sep << std::left << std::setw(12) << "MAX TIME" << sep << std::left << std::setw(12) << "EVENT COUNT" << sep << std::left << std::setw(12) << "WAKEUP COUNT" << sep << std::left << std::setw(12) << "EXPIRE COUNT" << sep << std::left << std::setw(20) << "PREVENT SUSPEND TIME" << sep << std::left << std::setw(16) << "LAST CHANGE" << sep << "\n"; // clang-format on out << div; // Rows for (const WakeLockInfo& entry : wlStats) { out << entry << "\n"; } out << div; return out; } /** * Returns the monotonic time in milliseconds. */ TimestampType getTimeNow() { timespec monotime; clock_gettime(CLOCK_MONOTONIC, &monotime); return std::chrono::duration_cast( std::chrono::nanoseconds{monotime.tv_nsec}) .count() + std::chrono::duration_cast( std::chrono::seconds{monotime.tv_sec}) .count(); } WakeLockEntryList::WakeLockEntryList(size_t capacity, unique_fd kernelWakelockStatsFd) : mCapacity(capacity), mKernelWakelockStatsFd(std::move(kernelWakelockStatsFd)) {} /** * Evicts LRU from back of list if stats is at capacity. */ void WakeLockEntryList::evictIfFull() { static std::chrono::steady_clock::time_point lastWarningTime{}; static std::chrono::steady_clock::time_point lastEvictionTime{}; static long evictionCountSinceLastLog = 0; if (mStats.size() == mCapacity) { auto evictIt = mStats.end(); std::advance(evictIt, -1); auto evictKey = std::make_pair(evictIt->name, evictIt->pid); mLookupTable.erase(evictKey); mStats.erase(evictIt); std::chrono::steady_clock::time_point now = std::chrono::steady_clock::now(); long long secondsSinceLastLog = std::chrono::duration_cast(now - lastWarningTime).count(); evictionCountSinceLastLog++; if (secondsSinceLastLog >= 5) { long long secondsSinceLastEvict = std::chrono::duration_cast(now - lastEvictionTime).count(); LOG(WARNING) << "WakeLock Stats: Stats capacity met " << evictionCountSinceLastLog << " time(s) since last warning (" << secondsSinceLastLog << " seconds ago). An eviction is occurring now, with the previous" << " eviction occurring " << secondsSinceLastEvict << " seconds ago. Consider adjusting capacity to avoid stats eviction."; lastWarningTime = now; evictionCountSinceLastLog = 0; // Reset the count } lastEvictionTime = now; } } /** * Inserts entry as MRU. */ void WakeLockEntryList::insertEntry(WakeLockInfo entry) { auto key = std::make_pair(entry.name, entry.pid); mStats.emplace_front(std::move(entry)); mLookupTable[key] = mStats.begin(); } /** * Removes entry from the stats list. */ void WakeLockEntryList::deleteEntry(std::list::iterator entry) { auto key = std::make_pair(entry->name, entry->pid); mLookupTable.erase(key); mStats.erase(entry); } /** * Creates and returns a native wakelock entry. */ WakeLockInfo WakeLockEntryList::createNativeEntry(const std::string& name, int pid, TimestampType timeNow) const { WakeLockInfo info; info.name = name; // It only makes sense to create a new entry on initial activation of the lock. info.activeCount = 1; info.lastChange = timeNow; info.maxTime = 0; info.totalTime = 0; info.isActive = true; info.activeTime = 0; info.isKernelWakelock = false; info.pid = pid; info.eventCount = 0; info.expireCount = 0; info.preventSuspendTime = 0; info.wakeupCount = 0; return info; } /* * Checks whether a given directory entry is a stat file we're interested in. */ static bool isStatFile(const struct dirent* de) { const char* statName = de->d_name; if (!strcmp(statName, ".") || !strcmp(statName, "..") || !strcmp(statName, "device") || !strcmp(statName, "power") || !strcmp(statName, "subsystem") || !strcmp(statName, "uevent")) { return false; } return true; } /* * Creates and returns a kernel wakelock entry with data read from mKernelWakelockStatsFd */ WakeLockInfo WakeLockEntryList::createKernelEntry(const std::string& kwlId) const { WakeLockInfo info; info.activeCount = 0; info.lastChange = 0; info.maxTime = 0; info.totalTime = 0; info.isActive = false; info.activeTime = 0; info.isKernelWakelock = true; info.pid = -1; // N/A info.eventCount = 0; info.expireCount = 0; info.preventSuspendTime = 0; info.wakeupCount = 0; unique_fd wakelockFd{TEMP_FAILURE_RETRY( openat(mKernelWakelockStatsFd, kwlId.c_str(), O_DIRECTORY | O_CLOEXEC | O_RDONLY))}; if (wakelockFd < 0) { char buf[PATH_MAX]; ssize_t data_length = readlinkat(mKernelWakelockStatsFd, kwlId.c_str(), buf, sizeof(buf) - 1); if (data_length <= 0 || strncmp(kwlId.c_str(), buf, kwlId.length()) == 0) { buf[0] = '\0'; } PLOG(ERROR) << "Error opening kernel wakelock stats for: " << kwlId << " (" << buf << ")"; } std::unique_ptr wakelockDp(fdopendir(dup(wakelockFd.get())), &closedir); if (wakelockDp) { struct dirent* de; while ((de = readdir(wakelockDp.get()))) { if (!isStatFile(de)) { continue; } std::string statName(de->d_name); unique_fd statFd{ TEMP_FAILURE_RETRY(openat(wakelockFd, statName.c_str(), O_CLOEXEC | O_RDONLY))}; if (statFd < 0) { PLOG(ERROR) << "Error opening " << statName << " for " << kwlId; continue; } std::string valStr; if (!ReadFdToString(statFd.get(), &valStr)) { PLOG(ERROR) << "Error reading " << statName << " for " << kwlId; continue; } // Trim newline valStr.erase(std::remove(valStr.begin(), valStr.end(), '\n'), valStr.end()); if (statName == "name") { info.name = valStr; continue; } int64_t statVal; if (!ParseInt(valStr, &statVal)) { std::string path; if (Readlink(StringPrintf("/proc/self/fd/%d", statFd.get()), &path)) { LOG(ERROR) << "Unexpected format for wakelock stat value (" << valStr << ") from file: " << path; } else { LOG(ERROR) << "Unexpected format for wakelock stat value (" << valStr << ")"; } continue; } if (statName == "active_count") { info.activeCount = statVal; } else if (statName == "active_time_ms") { info.activeTime = statVal; } else if (statName == "event_count") { info.eventCount = statVal; } else if (statName == "expire_count") { info.expireCount = statVal; } else if (statName == "last_change_ms") { info.lastChange = statVal; } else if (statName == "max_time_ms") { info.maxTime = statVal; } else if (statName == "prevent_suspend_time_ms") { info.preventSuspendTime = statVal; } else if (statName == "total_time_ms") { info.totalTime = statVal; } else if (statName == "wakeup_count") { info.wakeupCount = statVal; } } } // Derived stats info.isActive = info.activeTime > 0; return info; } /* * Creates and returns a kernel wakelock entry with data read from mKernelWakelockStatsFd. * Has been micro-optimized to reduce CPU time and wall time. */ WakeLockInfo WakeLockEntryList::createKernelEntry(ScratchSpace* ss, int wakeLockInfoFieldBitMask, const std::string& kwlId) const { WakeLockInfo info; info.activeCount = 0; info.lastChange = 0; info.maxTime = 0; info.totalTime = 0; info.isActive = false; info.activeTime = 0; info.isKernelWakelock = true; info.pid = -1; // N/A info.eventCount = 0; info.expireCount = 0; info.preventSuspendTime = 0; info.wakeupCount = 0; for (const auto& field : FIELDS) { const bool isNameField = field.bit == -1; if (!isNameField && (wakeLockInfoFieldBitMask & field.bit) == 0) { continue; } ss->statName = kwlId + "/" + field.filename; int statFd = -1; { std::lock_guard lock(mLock); // Check if we have a valid cached file descriptor. auto it = mFdCache.find(ss->statName); if (it != mFdCache.end() && it->second >= 0) { auto result = lseek(it->second, 0, SEEK_SET); if (result < 0) { PLOG(ERROR) << "Could not seek to start of FD for " << ss->statName; mFdCache.erase(it); PLOG(ERROR) << "Closed the FD."; } else { statFd = it->second; } } if (statFd == -1) { unique_fd tmpFd(TEMP_FAILURE_RETRY( openat(mKernelWakelockStatsFd, ss->statName.c_str(), O_CLOEXEC | O_RDONLY))); if (tmpFd < 0) { PLOG(ERROR) << "Error opening " << ss->statName << " for " << kwlId; continue; } statFd = tmpFd; mFdCache.insert(it, {ss->statName, std::move(tmpFd)}); } } // mLock is released here ss->valStr.clear(); ssize_t n; while ((n = TEMP_FAILURE_RETRY(read(statFd, &ss->readBuff[0], sizeof(ss->readBuff)))) > 0) { ss->valStr.append(ss->readBuff, n); } if (n < 0) { PLOG(ERROR) << "Error reading " << ss->statName; { std::lock_guard lock(mLock); mFdCache.erase(ss->statName); PLOG(ERROR) << "Closed the FD."; } continue; } // Trim newline ss->valStr.erase(std::remove(ss->valStr.begin(), ss->valStr.end(), '\n'), ss->valStr.end()); if (isNameField) { info.name = ss->valStr; continue; } int64_t statVal; if (!ParseInt(ss->valStr, &statVal)) { std::string path; if (Readlink(StringPrintf("/proc/self/fd/%d", statFd), &path)) { LOG(ERROR) << "Unexpected format for wakelock stat value (" << ss->valStr << ") from file: " << path; } else { LOG(ERROR) << "Unexpected format for wakelock stat value (" << ss->valStr << ")"; } continue; } if (field.filename == "active_count") { info.activeCount = statVal; } else if (field.filename == "active_time_ms") { info.activeTime = statVal; } else if (field.filename == "event_count") { info.eventCount = statVal; } else if (field.filename == "expire_count") { info.expireCount = statVal; } else if (field.filename == "last_change_ms") { info.lastChange = statVal; } else if (field.filename == "max_time_ms") { info.maxTime = statVal; } else if (field.filename == "prevent_suspend_time_ms") { info.preventSuspendTime = statVal; } else if (field.filename == "total_time_ms") { info.totalTime = statVal; } else if (field.filename == "wakeup_count") { info.wakeupCount = statVal; } } // Derived stats info.isActive = info.activeTime > 0; return info; } void WakeLockEntryList::getKernelWakelockStats(int wakeLockInfoFieldBitMask, std::vector* aidl_return) const { std::unique_ptr dp(fdopendir(dup(mKernelWakelockStatsFd.get())), &closedir); if (dp) { // rewinddir, else subsequent calls will not get any kernel wakelocks. rewinddir(dp.get()); ScratchSpace ss; struct dirent* de; while ((de = readdir(dp.get()))) { std::string kwlId(de->d_name); if ((kwlId == ".") || (kwlId == "..")) { continue; } WakeLockInfo entry = fast_kernel_wakelock_reporting() ? createKernelEntry(&ss, wakeLockInfoFieldBitMask, kwlId) : createKernelEntry(kwlId); aidl_return->emplace_back(std::move(entry)); } } } void WakeLockEntryList::updateOnAcquire(const std::string& name, int pid) { TimestampType timeNow = getTimeNow(); std::lock_guard lock(mLock); auto key = std::make_pair(name, pid); auto it = mLookupTable.find(key); if (it == mLookupTable.end()) { evictIfFull(); WakeLockInfo newEntry = createNativeEntry(name, pid, timeNow); insertEntry(newEntry); } else { auto staleEntry = it->second; WakeLockInfo updatedEntry = *staleEntry; // Update entry updatedEntry.isActive = true; updatedEntry.activeTime = 0; updatedEntry.activeCount++; updatedEntry.lastChange = timeNow; deleteEntry(staleEntry); insertEntry(std::move(updatedEntry)); } } void WakeLockEntryList::updateOnRelease(const std::string& name, int pid) { TimestampType timeNow = getTimeNow(); std::lock_guard lock(mLock); auto key = std::make_pair(name, pid); auto it = mLookupTable.find(key); if (it == mLookupTable.end()) { LOG(INFO) << "WakeLock Stats: A stats entry for, \"" << name << "\" was not found. This is most likely due to it being evicted."; } else { auto staleEntry = it->second; WakeLockInfo updatedEntry = *staleEntry; // Update entry TimestampType timeDelta = timeNow - updatedEntry.lastChange; if (updatedEntry.activeCount > 0) { updatedEntry.activeCount--; } else { LOG(ERROR) << "WakeLock Stats: Active count attempted to go below zero for " << "wakelock \"" << name << "\". This is unexpected."; } updatedEntry.isActive = (updatedEntry.activeCount > 0); updatedEntry.activeTime += timeDelta; updatedEntry.maxTime = std::max(updatedEntry.maxTime, updatedEntry.activeTime); updatedEntry.activeTime = updatedEntry.isActive ? updatedEntry.activeTime : 0; updatedEntry.totalTime += timeDelta; updatedEntry.lastChange = timeNow; deleteEntry(staleEntry); insertEntry(std::move(updatedEntry)); } } /** * Updates the native wakelock stats based on the current time. */ void WakeLockEntryList::updateNow() { std::lock_guard lock(mLock); TimestampType timeNow = getTimeNow(); for (std::list::iterator it = mStats.begin(); it != mStats.end(); ++it) { if (it->isActive) { TimestampType timeDelta = timeNow - it->lastChange; it->activeTime += timeDelta; it->maxTime = std::max(it->maxTime, it->activeTime); it->totalTime += timeDelta; it->lastChange = timeNow; } } } void WakeLockEntryList::getWakeLockStats(int wakeLockInfoFieldBitMask, std::vector* aidl_return) const { // Under no circumstances should the lock be held while getting kernel wakelock stats { std::lock_guard lock(mLock); for (const WakeLockInfo& entry : mStats) { aidl_return->emplace_back(entry); } } getKernelWakelockStats(wakeLockInfoFieldBitMask, aidl_return); } } // namespace V1_0 } // namespace suspend } // namespace system } // namespace android