From: Tri Vo Date: Fri, 9 Nov 2018 02:24:52 +0000 (-0800) Subject: system suspend: more information about wake locks X-Git-Url: http://git.osdn.net/view?a=commitdiff_plain;h=ba81fb29c4998647baf5fe0fa313a14d87b92eff;p=android-x86%2Fsystem-hardware-interfaces.git system suspend: more information about wake locks /sys/power/{wake_lock wake_unlock} can give a list of all currently active and inactive wake lock names. Bring system suspend debug functionality up to par by keeping track of all used wake lock names, client pids, current state and last used timestamp. To prevent collected stats from growing unboundedly we evict least recently used stats entry after a given threshold. Bug: 78888165 Test: SystemSuspendV1_0UnitTest Change-Id: I26eb94e61d4656ec1bba45b4a70a0715fae15d05 --- diff --git a/suspend/1.0/default/SystemSuspend.cpp b/suspend/1.0/default/SystemSuspend.cpp index eae240a..d0f5944 100644 --- a/suspend/1.0/default/SystemSuspend.cpp +++ b/suspend/1.0/default/SystemSuspend.cpp @@ -27,6 +27,7 @@ #include #include +#include #include #include @@ -57,7 +58,18 @@ static inline int getCallingPid() { return IPCThreadState::self()->getCallingPid(); } -WakeLock::WakeLock(SystemSuspend* systemSuspend) : mReleased(), mSystemSuspend(systemSuspend) { +static inline WakeLockIdType getWakeLockId(int pid, const string& name) { + // Doesn't guarantee unique ids, but for debuging purposes this is adequate. + return std::to_string(pid) + "/" + name; +} + +TimestampType getEpochTimeNow() { + auto timeSinceEpoch = std::chrono::system_clock::now().time_since_epoch(); + return std::chrono::duration_cast(timeSinceEpoch).count(); +} + +WakeLock::WakeLock(SystemSuspend* systemSuspend, const WakeLockIdType& id) + : mReleased(), mSystemSuspend(systemSuspend), mId(id) { mSystemSuspend->incSuspendCounter(); } @@ -73,15 +85,16 @@ Return WakeLock::release() { void WakeLock::releaseOnce() { std::call_once(mReleased, [this]() { mSystemSuspend->decSuspendCounter(); - mSystemSuspend->deleteWakeLockStatsEntry(reinterpret_cast(this)); + mSystemSuspend->deleteWakeLockStatsEntry(mId); }); } -SystemSuspend::SystemSuspend(unique_fd wakeupCountFd, unique_fd stateFd, +SystemSuspend::SystemSuspend(unique_fd wakeupCountFd, unique_fd stateFd, size_t maxStatsEntries, std::chrono::milliseconds baseSleepTime) : mSuspendCounter(0), mWakeupCountFd(std::move(wakeupCountFd)), mStateFd(std::move(stateFd)), + mMaxStatsEntries(maxStatsEntries), mBaseSleepTime(baseSleepTime), mSleepTime(baseSleepTime) {} @@ -99,14 +112,28 @@ Return SystemSuspend::enableAutosuspend() { Return> SystemSuspend::acquireWakeLock(WakeLockType /* type */, const hidl_string& name) { - IWakeLock* wl = new WakeLock{this}; + auto pid = getCallingPid(); + auto wlId = getWakeLockId(pid, name); + IWakeLock* wl = new WakeLock{this, wlId}; { auto l = std::lock_guard(mStatsLock); - WakeLockStats wlStats{}; - wlStats.set_name(name); - wlStats.set_pid(getCallingPid()); - // Use WakeLock's address as a unique identifier. - (*mStats.mutable_wake_lock_stats())[reinterpret_cast(wl)] = wlStats; + + auto& wlStatsEntry = (*mStats.mutable_wl_stats())[wlId]; + auto lastUpdated = wlStatsEntry.last_updated(); + auto timeNow = getEpochTimeNow(); + mLruWakeLockId.erase(lastUpdated); + mLruWakeLockId[timeNow] = wlId; + + wlStatsEntry.set_name(name); + wlStatsEntry.set_pid(pid); + wlStatsEntry.set_active(true); + wlStatsEntry.set_last_updated(timeNow); + + if (mStats.wl_stats().size() > mMaxStatsEntries) { + auto lruWakeLockId = mLruWakeLockId.begin()->second; + mLruWakeLockId.erase(mLruWakeLockId.begin()); + mStats.mutable_wl_stats()->erase(lruWakeLockId); + } } return wl; } @@ -164,7 +191,16 @@ void SystemSuspend::decSuspendCounter() { void SystemSuspend::deleteWakeLockStatsEntry(WakeLockIdType id) { auto l = std::lock_guard(mStatsLock); - mStats.mutable_wake_lock_stats()->erase(id); + auto* wlStats = mStats.mutable_wl_stats(); + if (wlStats->find(id) != wlStats->end()) { + auto& wlStatsEntry = (*wlStats)[id]; + auto timeNow = getEpochTimeNow(); + auto lastUpdated = wlStatsEntry.last_updated(); + wlStatsEntry.set_active(false); + wlStatsEntry.set_last_updated(timeNow); + mLruWakeLockId.erase(lastUpdated); + mLruWakeLockId[timeNow] = id; + } } void SystemSuspend::initAutosuspend() { diff --git a/suspend/1.0/default/SystemSuspend.h b/suspend/1.0/default/SystemSuspend.h index 1e83b2c..9817b97 100644 --- a/suspend/1.0/default/SystemSuspend.h +++ b/suspend/1.0/default/SystemSuspend.h @@ -40,17 +40,19 @@ using ::android::hardware::hidl_vec; using ::android::hardware::interfacesEqual; using ::android::hardware::Return; -using WakeLockIdType = uint64_t; +using TimestampType = uint64_t; +using WakeLockIdType = std::string; using namespace std::chrono_literals; class SystemSuspend; std::string readFd(int fd); +TimestampType getEpochTimeNow(); class WakeLock : public IWakeLock { public: - WakeLock(SystemSuspend* systemSuspend); + WakeLock(SystemSuspend* systemSuspend, const WakeLockIdType& id); ~WakeLock(); Return release(); @@ -60,11 +62,12 @@ class WakeLock : public IWakeLock { std::once_flag mReleased; SystemSuspend* mSystemSuspend; + WakeLockIdType mId; }; class SystemSuspend : public ISystemSuspend, public hidl_death_recipient { public: - SystemSuspend(unique_fd wakeupCountFd, unique_fd stateFd, + SystemSuspend(unique_fd wakeupCountFd, unique_fd stateFd, size_t maxStatsEntries, std::chrono::milliseconds baseSleepTime); Return enableAutosuspend() override; Return> acquireWakeLock(WakeLockType type, const hidl_string& name) override; @@ -88,6 +91,12 @@ class SystemSuspend : public ISystemSuspend, public hidl_death_recipient { // protect these. However, since mStats is only for debugging we prioritize performance. // Never hold both locks at the same time to avoid deadlock. std::mutex mStatsLock; + // We don't want mStats to grow unboundedly in memory. This constant limits amount of + // information mStats can collect on the device. + size_t mMaxStatsEntries; + // Used to evict the least recently used wake lock stats entry in case mMaxStatsEntries is + // reached. + std::map mLruWakeLockId; SystemSuspendStats mStats; using CbType = sp; diff --git a/suspend/1.0/default/SystemSuspendStats.proto b/suspend/1.0/default/SystemSuspendStats.proto index 76d6c0b..4be6bc2 100644 --- a/suspend/1.0/default/SystemSuspendStats.proto +++ b/suspend/1.0/default/SystemSuspendStats.proto @@ -14,13 +14,15 @@ syntax = "proto3"; -// Collects information about individual WakeLock instances. +// Collects information about an individual live WakeLock instances. message WakeLockStats { string name = 1; int32 pid = 2; + bool active = 3; + uint64 last_updated = 4; } message SystemSuspendStats { // Maps a unique id of a WakeLock instance to the corresponding WakeLockStats message. - map wake_lock_stats = 1; + map wl_stats = 1; } diff --git a/suspend/1.0/default/SystemSuspendUnitTest.cpp b/suspend/1.0/default/SystemSuspendUnitTest.cpp index 6d08ec4..90c0266 100644 --- a/suspend/1.0/default/SystemSuspendUnitTest.cpp +++ b/suspend/1.0/default/SystemSuspendUnitTest.cpp @@ -44,6 +44,7 @@ using android::hardware::configureRpcThreadpool; using android::hardware::joinRpcThreadpool; using android::hardware::Return; using android::hardware::Void; +using android::system::suspend::V1_0::getEpochTimeNow; using android::system::suspend::V1_0::ISystemSuspend; using android::system::suspend::V1_0::ISystemSuspendCallback; using android::system::suspend::V1_0::IWakeLock; @@ -80,8 +81,9 @@ class SystemSuspendTestEnvironment : public ::testing::Environment { void registerTestService() { std::thread testService([this] { configureRpcThreadpool(1, true /* callerWillJoin */); - sp suspend = new SystemSuspend( - std::move(wakeupCountFds[1]), std::move(stateFds[1]), 0ms /* baseSleepTime */); + sp suspend = + new SystemSuspend(std::move(wakeupCountFds[1]), std::move(stateFds[1]), + 1 /* maxStatsEntries */, 0ms /* baseSleepTime */); status_t status = suspend->registerAsService(kServiceName); if (android::OK != status) { LOG(FATAL) << "Unable to register service: " << status; @@ -155,7 +157,10 @@ class SystemSuspendTest : public ::testing::Test { return stats; } - size_t getWakeLockCount() { return getDebugDump().wake_lock_stats().size(); } + size_t getActiveWakeLockCount() { + const auto& wlStats = getDebugDump().wl_stats(); + return count_if(wlStats.begin(), wlStats.end(), [](auto x) { return x.second.active(); }); + } void checkLoop(int numIter) { for (int i = 0; i < numIter; i++) { @@ -248,15 +253,43 @@ TEST_F(SystemSuspendTest, CleanupOnAbort) { ASSERT_FALSE(isSystemSuspendBlocked()); } -// Test that debug dump has correct information about acquired WakeLocks. -TEST_F(SystemSuspendTest, DebugDump) { +// Test that debug dump has correct information about WakeLocks. +TEST_F(SystemSuspendTest, DebugDumpWakeLocks) { + uint64_t timeNow = getEpochTimeNow(); { sp wl = acquireWakeLock(); - SystemSuspendStats debugDump = getDebugDump(); - ASSERT_EQ(debugDump.wake_lock_stats().size(), 1); - ASSERT_EQ(debugDump.wake_lock_stats().begin()->second.name(), "TestLock"); + auto wlStats = getDebugDump().wl_stats(); + ASSERT_EQ(wlStats.size(), 1); + ASSERT_EQ(wlStats.begin()->second.name(), "TestLock"); + ASSERT_EQ(wlStats.begin()->second.pid(), getpid()); + ASSERT_EQ(wlStats.begin()->second.active(), true); + ASSERT_GT(wlStats.begin()->second.last_updated(), timeNow); + // We sleep so that the wake lock stats entry get updated with a different timestamp. + std::this_thread::sleep_for(1s); } - ASSERT_EQ(getWakeLockCount(), 0); + auto wlStats = getDebugDump().wl_stats(); + ASSERT_EQ(wlStats.size(), 1); + ASSERT_EQ(wlStats.begin()->second.name(), "TestLock"); + ASSERT_EQ(wlStats.begin()->second.pid(), getpid()); + ASSERT_EQ(wlStats.begin()->second.active(), false); + // The updated timestamp is not deterministic. However, all SystemSuspend HAL calls run in the + // order of microseconds, so in practice the updated timestamp should be 1 second newer than the + // old one. + ASSERT_GT(wlStats.begin()->second.last_updated(), timeNow + 1000000); +} + +// Test that the least recently used wake stats entry is evicted after a given threshold. +TEST_F(SystemSuspendTest, LruWakeLockStatsEviction) { + suspendService->acquireWakeLock(WakeLockType::PARTIAL, "foo"); + suspendService->acquireWakeLock(WakeLockType::PARTIAL, "bar"); + suspendService->acquireWakeLock(WakeLockType::PARTIAL, "bar"); + suspendService->acquireWakeLock(WakeLockType::PARTIAL, "baz"); + + auto wlStats = getDebugDump().wl_stats(); + // Max number of stats entries was set to 1 in SystemSuspend constructor. + ASSERT_EQ(wlStats.size(), 1); + ASSERT_EQ(wlStats.begin()->second.name(), "baz"); + ASSERT_EQ(wlStats.begin()->second.active(), false); } // Stress test acquiring/releasing WakeLocks. @@ -268,7 +301,7 @@ TEST_F(SystemSuspendTest, WakeLockStressTest) { for (int i = 0; i < numThreads; i++) { tds[i] = std::thread([this] { - for (int i = 0; i < numLocks; i++) { + for (int j = 0; j < numLocks; j++) { sp wl1 = acquireWakeLock(); sp wl2 = acquireWakeLock(); wl2->release(); @@ -278,7 +311,7 @@ TEST_F(SystemSuspendTest, WakeLockStressTest) { for (int i = 0; i < numThreads; i++) { tds[i].join(); } - ASSERT_EQ(getWakeLockCount(), 0); + ASSERT_EQ(getActiveWakeLockCount(), 0); } // Callbacks are passed around as sp<>. However, mock expectations are verified when mock objects diff --git a/suspend/1.0/default/main.cpp b/suspend/1.0/default/main.cpp index 2dce6fd..9f4bea1 100644 --- a/suspend/1.0/default/main.cpp +++ b/suspend/1.0/default/main.cpp @@ -36,7 +36,8 @@ int main() { configureRpcThreadpool(1, true /* callerWillJoin */); sp suspend = - new SystemSuspend(std::move(wakeupCountFd), std::move(stateFd), 100ms /* baseSleepTime */); + new SystemSuspend(std::move(wakeupCountFd), std::move(stateFd), 100 /* maxStatsEntries */, + 100ms /* baseSleepTime */); status_t status = suspend->registerAsService(); if (android::OK != status) { LOG(FATAL) << "Unable to register service: " << status;