/* -*- Mode: C; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 4 -*- */ /* This Source Code Form is subject to the terms of the Mozilla Public * License, v. 2.0. If a copy of the MPL was not distributed with this * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ #include "mozilla/CondVar.h" #include "mozilla/Mutex.h" #include "mozilla/ThreadSafety.h" #include "mozilla/TimeStamp.h" #include "nsIThread.h" #include "nsThreadPool.h" #include "nsThreadUtils.h" #include "pratom.h" #include "prinrval.h" #include "prmon.h" #include "prthread.h" #include "mozilla/Assertions.h" #include "mozilla/Logging.h" #include "mozilla/gtest/MozAssertions.h" #include "gtest/gtest.h" using namespace mozilla; #define NUMBER_OF_MAX_THREADS ((uint32_t)6) #define NUMBER_OF_IDLE_THREADS ((uint32_t)3) #define IDLE_THREAD_GRACE_TIMEOUT 250 #define IDLE_THREAD_MAX_TIMEOUT 1000 namespace TestThreadPoolIdleTimeout { // Given that this test wants to check if timeouts happen when they should, // and given that timeouts can be unreliable depending on the execution // environment, while running the timeout test we run in parallel some // extra timeouts of known duration in order to check for their deviation. // This allows us to skip test conditions if the deviation is getting // significant. This is not perfect because this is run on different threads // but there is no significant workload on the tested threads, neither, so // hopefully we capture most cases with this. template class ScopedTimingChecker { Mutex mMutex{"ScopedTimingCheckMutex"}; CondVar mWaitForTimer MOZ_GUARDED_BY(mMutex); nsCOMPtr mTarget MOZ_GUARDED_BY(mMutex); TimeStamp mLastStart MOZ_GUARDED_BY(mMutex); nsCOMPtr mTimer MOZ_GUARDED_BY(mMutex); AutoTArray mEffectiveMS MOZ_GUARDED_BY(mMutex); double& mDeviationPerc; void TimerFn() { MutexAutoLock lock(mMutex); TimeDuration delta = TimeStamp::Now() - mLastStart; mEffectiveMS.AppendElement(delta); if (mEffectiveMS.Length() < repeats) { mLastStart = TimeStamp::Now(); auto ret = NS_NewTimerWithCallback( [self = this](nsITimer* t) { self->TimerFn(); }, TimeDuration::FromMilliseconds(ms), nsITimer::TYPE_ONE_SHOT, "TimingChecker", mTarget); MOZ_ASSERT(ret.isOk()); mTimer = ret.unwrap(); } else { mWaitForTimer.Notify(); } }; public: ScopedTimingChecker(nsCOMPtr aTarget, double& aDeviationPerc) : mWaitForTimer(mMutex, "WaitForPeak"), mTarget(std::move(aTarget)), mDeviationPerc(aDeviationPerc) { MutexAutoLock lock(mMutex); mLastStart = TimeStamp::Now(); auto ret = NS_NewTimerWithCallback( [self = this](nsITimer* t) { self->TimerFn(); }, TimeDuration::FromMilliseconds(ms), nsITimer::TYPE_ONE_SHOT, "TimingChecker", mTarget); MOZ_ASSERT(ret.isOk()); mTimer = ret.unwrap(); } ~ScopedTimingChecker() { MutexAutoLock lock(mMutex); if (mEffectiveMS.Length() < repeats) { mWaitForTimer.Wait(); } double maxDeviation = 0.0; for (size_t i = 0; i < repeats; i++) { maxDeviation = std::max(maxDeviation, std::abs(mEffectiveMS[i].ToMilliseconds() - ms)); } mDeviationPerc = 100.0 * (maxDeviation / ms); printf("ScopedTimingChecker calculated %.2f %% deviation.\n", mDeviationPerc); } }; class Listener final : public nsIThreadPoolListener { ~Listener() = default; TimeStamp mExecStart; Atomic& mNumberOfThreadsCurrent; Atomic& mNumberOfThreadsCreated; Mutex& mWaitMutex; CondVar& mWaitForIdleLimit; CondVar& mWaitForNoThreadsAlive; public: NS_DECL_THREADSAFE_ISUPPORTS NS_DECL_NSITHREADPOOLLISTENER Listener(TimeStamp aStart, Atomic& aNumberOfThreadsCurrent, Atomic& aNumberOfThreadsCreated, Mutex& aWaitMutex, CondVar& aWaitForGrace, CondVar& aWaitForMaximum) : mExecStart(aStart), mNumberOfThreadsCurrent(aNumberOfThreadsCurrent), mNumberOfThreadsCreated(aNumberOfThreadsCreated), mWaitMutex(aWaitMutex), mWaitForIdleLimit(aWaitForGrace), mWaitForNoThreadsAlive(aWaitForMaximum) {} }; NS_IMPL_ISUPPORTS(Listener, nsIThreadPoolListener) NS_IMETHODIMP Listener::OnThreadCreated() { // We cannot lock gWaitMutex here, we would deadlock, thus // the Atomic above. ++mNumberOfThreadsCurrent; ++mNumberOfThreadsCreated; printf("%u Start new thread. %u alive, %u ever created.\n", (uint32_t)(TimeStamp::Now() - mExecStart).ToMilliseconds(), (uint32_t)mNumberOfThreadsCurrent, (uint32_t)mNumberOfThreadsCreated); return NS_OK; } NS_IMETHODIMP Listener::OnThreadShuttingDown() { MutexAutoLock lock(mWaitMutex); --mNumberOfThreadsCurrent; if (mNumberOfThreadsCurrent == NUMBER_OF_IDLE_THREADS) { mWaitForIdleLimit.Notify(); } if (mNumberOfThreadsCurrent == 0) { mWaitForNoThreadsAlive.Notify(); } printf("%u Shutdown thread. %u alive, %u ever created.\n", (uint32_t)(TimeStamp::Now() - mExecStart).ToMilliseconds(), (uint32_t)mNumberOfThreadsCurrent, (uint32_t)mNumberOfThreadsCreated); return NS_OK; } // We want to see how the thread pool behaves under different loads // in terms of creating and/or timing out threads as expected. TEST(ThreadPoolIdleTimeout, Test) { nsresult rv; // Setup pool and environment. Mutex waitMutex("WaitMutex"); CondVar waitForPeak(waitMutex, "WaitForPeak"); CondVar waitForIdleAfterPeak(waitMutex, "WaitForIdleAfterPeak"); CondVar waitForGrace(waitMutex, "WaitForGrace"); CondVar waitForMaximum(waitMutex, "WaitForMaximum"); TimeStamp execStart = TimeStamp::Now(); Atomic numberOfThreads(0); Atomic numberOfThreadsCreated(0); Atomic numberOfActiviationRunnables(0); nsCOMPtr pool = new nsThreadPool(); rv = pool->SetThreadLimit(NUMBER_OF_MAX_THREADS); ASSERT_NS_SUCCEEDED(rv); rv = pool->SetIdleThreadLimit(NUMBER_OF_IDLE_THREADS); ASSERT_NS_SUCCEEDED(rv); rv = pool->SetIdleThreadGraceTimeout(IDLE_THREAD_GRACE_TIMEOUT); ASSERT_NS_SUCCEEDED(rv); rv = pool->SetIdleThreadMaximumTimeout(IDLE_THREAD_MAX_TIMEOUT); ASSERT_NS_SUCCEEDED(rv); pool->SetName("IdleTest"_ns); nsCOMPtr listener = new Listener(execStart, numberOfThreads, numberOfThreadsCreated, waitMutex, waitForGrace, waitForMaximum); ASSERT_TRUE(listener); rv = pool->SetListener(listener); ASSERT_NS_SUCCEEDED(rv); nsCOMPtr timer; nsCOMPtr helperTarget; rv = NS_CreateBackgroundTaskQueue("Helper", getter_AddRefs(helperTarget)); ASSERT_NS_SUCCEEDED(rv); auto activateThreads = [&](uint32_t aNumThreads) MOZ_REQUIRES(waitMutex) { // Ramp up to have all 4 threads running. // The pool must be completely idle before calling this! MOZ_ASSERT(!numberOfActiviationRunnables); printf("%u Activate %u threads.\n", (uint32_t)(TimeStamp::Now() - execStart).ToMilliseconds(), (uint32_t)aNumThreads); // We dispatch a runnable per thread that will wait for us unless we are // the last to run. for (uint32_t i = 0; i < aNumThreads; i++) { nsCOMPtr runnable = NS_NewRunnableFunction("TestRunnable", [&]() { MutexAutoLock lock(waitMutex); numberOfActiviationRunnables++; if (numberOfActiviationRunnables >= aNumThreads) { waitForPeak.NotifyAll(); } else { // Block this thread until we reach our max. waitForPeak.Wait(); } numberOfActiviationRunnables--; if (numberOfActiviationRunnables == 0) { waitForIdleAfterPeak.NotifyAll(); } }); ASSERT_TRUE(runnable); rv = pool->Dispatch(runnable, NS_DISPATCH_NORMAL); ASSERT_NS_SUCCEEDED(rv); } // Ensure all runnables were executed. Should be immediate. waitForPeak.Wait(); if (numberOfActiviationRunnables > 0) { waitForIdleAfterPeak.Wait(); } }; // 1st Test: Ramp up once to maximum threads and see how the threads are // timing out. { double deviationPerc = 0.0; TimeStamp start; TimeDuration graceTime; { ScopedTimingChecker checker( helperTarget, deviationPerc); { MutexAutoLock lock(waitMutex); activateThreads(NUMBER_OF_MAX_THREADS); } printf("%u Found %u threads alive.\n", (uint32_t)(TimeStamp::Now() - execStart).ToMilliseconds(), (uint32_t)numberOfThreads); EXPECT_EQ(numberOfThreads, (uint32_t)NUMBER_OF_MAX_THREADS); start = TimeStamp::Now(); // We expect the excess idle threads to terminate after // IDLE_THREAD_GRACE_TIMEOUT. printf("%u Wait for grace timeout...\n", (uint32_t)(TimeStamp::Now() - execStart).ToMilliseconds()); { MutexAutoLock lock(waitMutex); waitForGrace.Wait(); } printf("%u Found %u threads alive.\n", (uint32_t)(TimeStamp::Now() - execStart).ToMilliseconds(), (uint32_t)numberOfThreads); graceTime = TimeStamp::Now() - start; } EXPECT_EQ(numberOfThreads, (uint32_t)NUMBER_OF_IDLE_THREADS); if (deviationPerc < 10) { EXPECT_GE(graceTime, TimeDuration::FromMilliseconds(IDLE_THREAD_GRACE_TIMEOUT * .9)); EXPECT_LE(graceTime, TimeDuration::FromMilliseconds( IDLE_THREAD_GRACE_TIMEOUT * 1.5)); } else { printf( "Encountered flaky timers (deviation=%.2f), skipping grace timeout " "check.\n", deviationPerc); } TimeDuration maxTime; { ScopedTimingChecker< (IDLE_THREAD_MAX_TIMEOUT - IDLE_THREAD_GRACE_TIMEOUT) / 5, 5> checker(helperTarget, deviationPerc); printf("%u Wait for maximum timeout...\n", (uint32_t)(TimeStamp::Now() - execStart).ToMilliseconds()); { MutexAutoLock lock(waitMutex); waitForMaximum.Wait(); } } printf("%u Found %u threads alive.\n", (uint32_t)(TimeStamp::Now() - execStart).ToMilliseconds(), (uint32_t)numberOfThreads); maxTime = TimeStamp::Now() - start; EXPECT_EQ(numberOfThreads, (uint32_t)0); if (deviationPerc < 10) { EXPECT_GE(maxTime, TimeDuration::FromMilliseconds(IDLE_THREAD_MAX_TIMEOUT * .9)); EXPECT_LE(maxTime, TimeDuration::FromMilliseconds(IDLE_THREAD_MAX_TIMEOUT * 1.5)); } else { printf( "Encountered flaky timers (deviation=%.2f), skipping max timeout " "check.\n", deviationPerc); } } // 2nd Test: Have several bursts that ramp up to maximum threads interleaved // with short pauses and see how many threads are created and/or shutdown. TimeStamp started = TimeStamp::Now(); CondVar waitForRepeats(waitMutex, "WaitForRepeats"); { numberOfThreadsCreated = 0; // Cause a burst every 50ms for 500ms auto res = NS_NewTimerWithCallback( [&](nsITimer* t) { MutexAutoLock lock(waitMutex); activateThreads(NUMBER_OF_MAX_THREADS); if (TimeStamp::Now() - started > TimeDuration::FromMilliseconds(2.0 * IDLE_THREAD_GRACE_TIMEOUT)) { waitForRepeats.Notify(); } }, 50, nsITimer::TYPE_REPEATING_PRECISE_CAN_SKIP, "Background Bursts", helperTarget); ASSERT_TRUE(res.isOk()); timer = res.unwrap(); printf("%u Wait for repeated bursts...\n", (uint32_t)(TimeStamp::Now() - execStart).ToMilliseconds()); { MutexAutoLock lock(waitMutex); waitForRepeats.Wait(); timer->Cancel(); } // We expect only 6 initial threads to be created and kept alive by the // grace timeout. printf("%u Found %u threads created.\n", (uint32_t)(TimeStamp::Now() - execStart).ToMilliseconds(), (uint32_t)numberOfThreadsCreated); EXPECT_EQ(NUMBER_OF_MAX_THREADS, (uint32_t)numberOfThreadsCreated); } // 3rd Test: After an initial burst, see how low noise of repeated single // events keeps alive threads. { // Reset the timeouts of all threads. { MutexAutoLock lock(waitMutex); activateThreads(NUMBER_OF_MAX_THREADS); } printf("%u Found %u threads alive.\n", (uint32_t)(TimeStamp::Now() - execStart).ToMilliseconds(), (uint32_t)numberOfThreads); EXPECT_EQ(numberOfThreads, (uint32_t)NUMBER_OF_MAX_THREADS); double deviationPerc = 0.0; { ScopedTimingChecker checker( helperTarget, deviationPerc); // Create some low level noise that should need only 1 idle thread at // a time (1 runnable every 50ms for 625ms). numberOfActiviationRunnables = 0; started = TimeStamp::Now(); CondVar waitForRepeatExecutions(waitMutex, "waitForRepeatExecutions"); Atomic numberOfNoiseRunnables(0); auto res = NS_NewTimerWithCallback( [&](nsITimer* t) { MutexAutoLock lock(waitMutex); if (TimeStamp::Now() - started > TimeDuration::FromMilliseconds(2.5 * IDLE_THREAD_GRACE_TIMEOUT)) { waitForRepeats.Notify(); } else { // Decouple the dispatch to the tested pool from the timer // execution. If there is still a runnable in flight for slow // execution, skip. if (numberOfNoiseRunnables == 0) { nsCOMPtr runnable = NS_NewRunnableFunction("EmptyRunnable", [&]() { MutexAutoLock lock(waitMutex); printf("%u Execute empty runnable, num %u.\n", (uint32_t)(TimeStamp::Now() - execStart) .ToMilliseconds(), (uint32_t)numberOfNoiseRunnables); numberOfNoiseRunnables--; if (numberOfNoiseRunnables == 0) { waitForRepeatExecutions.Notify(); } }); ASSERT_TRUE(runnable); numberOfNoiseRunnables++; printf( "%u Dispatch empty runnable, num %u.\n", (uint32_t)(TimeStamp::Now() - execStart).ToMilliseconds(), (uint32_t)numberOfNoiseRunnables); rv = pool->Dispatch(runnable, NS_DISPATCH_NORMAL); ASSERT_NS_SUCCEEDED(rv); } } }, 50, nsITimer::TYPE_REPEATING_PRECISE_CAN_SKIP, "Background Noise", helperTarget); ASSERT_TRUE(res.isOk()); timer = res.unwrap(); printf("%u Wait for repeated low noise...\n", (uint32_t)(TimeStamp::Now() - execStart).ToMilliseconds()); { MutexAutoLock lock(waitMutex); waitForRepeats.Wait(); timer->Cancel(); if (numberOfNoiseRunnables) { printf("%u Runnables in flight after cancel: %u, wait...\n", (uint32_t)(TimeStamp::Now() - execStart).ToMilliseconds(), (uint32_t)numberOfNoiseRunnables); waitForRepeatExecutions.Wait(); } } } if (deviationPerc < 10) { // We would expect the idle threads to have gone back to // NUMBER_OF_IDLE_THREADS. // But due to the same MRU thread being used all the time we can // find NUMBER_OF_IDLE_THREADS + 1 if none of the other threads waiting // with IDLE_THREAD_MAX_TIMEOUT expired, yet. printf("%u End of low noise, found %u threads alive.\n", (uint32_t)(TimeStamp::Now() - execStart).ToMilliseconds(), (uint32_t)numberOfThreads); EXPECT_LE(NUMBER_OF_IDLE_THREADS, (uint32_t)numberOfThreads); EXPECT_GE(NUMBER_OF_IDLE_THREADS + 1, (uint32_t)numberOfThreads); } else { printf( "Encountered flaky timers (deviation=%.2f), skipping low noise " "timeout check.\n", deviationPerc); } } // Teardown. rv = pool->Shutdown(); ASSERT_NS_SUCCEEDED(rv); } } // namespace TestThreadPoolIdleTimeout