Add a "reason" argument to sleep_ms().

sleep_ms() should generally be avoided when possible. This can be used to try
to track down unnecessary sleeps by adding some logging.

This commit on its own doesn't actually add any logging.
This commit is contained in:
Henrik Rydgård 2024-11-21 15:25:02 +01:00
parent 489db6b92c
commit 59a56d66c7
27 changed files with 53 additions and 55 deletions

View File

@ -235,7 +235,7 @@ bool PathBrowser::GetListing(std::vector<File::FileInfo> &fileInfo, const char *
while (!IsListingReady() && (!cancel || !*cancel)) {
// In case cancel changes, just sleep. TODO: Replace with condition variable.
guard.unlock();
sleep_ms(50);
sleep_ms(50, "pathbrowser-poll");
guard.lock();
}

View File

@ -279,7 +279,7 @@ public:
void CreateMultiPipelinesTask::WaitForAll() {
while (tasksInFlight_.load() > 0) {
sleep_ms(2);
sleep_ms(2, "create-multi-pipelines-wait");
}
}
@ -522,7 +522,7 @@ void VulkanRenderManager::CompileThreadFunc() {
}
// Hold off just a bit before we check again, to allow bunches of pipelines to collect.
sleep_ms(1);
sleep_ms(1, "pipeline-collect");
}
std::unique_lock<std::mutex> lock(compileQueueMutex_);
@ -579,7 +579,7 @@ void VulkanRenderManager::PresentWaitThreadFunc() {
waitedId++;
} else {
// We caught up somehow, which is a bad sign (we should have blocked, right?). Maybe we should break out of the loop?
sleep_ms(1);
sleep_ms(1, "present-wait-problem");
frameTimeHistory_[waitedId].waitCount++;
}
_dbg_assert_(waitedId <= frameIdGen_);

View File

@ -211,7 +211,7 @@ bool Connection::Connect(int maxTries, double timeout, bool *cancelConnect) {
break;
}
sleep_ms(1);
sleep_ms(1, "connect");
}
// Nothing connected, unfortunately.

View File

@ -130,14 +130,6 @@ restart:
}
}
void RequestManager::WaitForAll() {
// TODO: Should lock? Though, OK if called from main thread, where Update() is called from.
while (!downloads_.empty()) {
Update();
sleep_ms(10);
}
}
void RequestManager::CancelAll() {
for (size_t i = 0; i < downloads_.size(); i++) {
downloads_[i]->Cancel();

View File

@ -108,7 +108,6 @@ public:
void Update();
void CancelAll();
void WaitForAll();
void SetUserAgent(const std::string &userAgent) {
userAgent_ = userAgent;
}

View File

@ -105,7 +105,7 @@ bool DNSResolve(const std::string &host, const std::string &service, addrinfo **
int result = getaddrinfo(host.c_str(), servicep, &hints, res);
if (result == EAI_AGAIN) {
// Temporary failure. Since this already blocks, let's just try once more.
sleep_ms(1);
sleep_ms(1, "dns-resolve-poll");
result = getaddrinfo(host.c_str(), servicep, &hints, res);
}

View File

@ -251,7 +251,7 @@ double Instant::ElapsedSeconds() const {
#endif
void sleep_ms(int ms) {
void sleep_ms(int ms, const char *reason) {
#ifdef _WIN32
Sleep(ms);
#elif defined(HAVE_LIBNX)

View File

@ -18,7 +18,9 @@ double from_time_raw_relative(uint64_t raw_time);
double time_now_unix_utc();
// Sleep. Does not necessarily have millisecond granularity, especially on Windows.
void sleep_ms(int ms);
// Requires a "reason" since sleeping generally should be very sparingly used. This
// can be logged if desired to figure out where we're wasting time.
void sleep_ms(int ms, const char *reason);
// Precise sleep. Can consume a little bit of CPU on Windows at least.
void sleep_precise(double seconds);

View File

@ -222,7 +222,7 @@ bool UpdateScreenScale(int width, int height) {
void UpdateRunLoop(GraphicsContext *ctx) {
NativeFrame(ctx);
if (windowHidden && g_Config.bPauseWhenMinimized) {
sleep_ms(16);
sleep_ms(16, "window-hidden");
return;
}
}
@ -230,7 +230,7 @@ void UpdateRunLoop(GraphicsContext *ctx) {
// Note: not used on Android.
void Core_RunLoop(GraphicsContext *ctx) {
if (windowHidden && g_Config.bPauseWhenMinimized) {
sleep_ms(16);
sleep_ms(16, "window-hidden");
return;
}

View File

@ -110,7 +110,7 @@ void CachingFileLoader::ShutdownCache() {
// We can't delete while the thread is running, so have to wait.
// This should only happen from the menu.
while (aheadThreadRunning_) {
sleep_ms(1);
sleep_ms(1, "shutdown-cache-poll");
}
if (aheadThread_.joinable())
aheadThread_.join();

View File

@ -106,7 +106,7 @@ void RamCachingFileLoader::ShutdownCache() {
// We can't delete while the thread is running, so have to wait.
// This should only happen from the menu.
while (aheadThreadRunning_) {
sleep_ms(1);
sleep_ms(1, "shutdown-ram-cache-poll");
}
if (aheadThread_.joinable())
aheadThread_.join();

View File

@ -35,7 +35,7 @@ FrameTiming g_frameTiming;
void WaitUntil(double now, double timestamp) {
#ifdef _WIN32
while (time_now_d() < timestamp) {
sleep_ms(1); // Sleep for 1ms on this thread
sleep_ms(1, "wait-until"); // Sleep for 1ms on this thread
}
#else
const double left = timestamp - now;

View File

@ -1780,10 +1780,11 @@ int friendFinder(){
}
}
// This delay time should be 100ms when there is an event otherwise 500ms ?
sleep_ms(10); // Using 1ms for faster response just like AdhocServer?
sleep_ms(10, "pro-adhoc-poll-2"); // Using 1ms for faster response just like AdhocServer?
// Don't do anything if it's paused, otherwise the log will be flooded
while (Core_IsStepping() && coreState != CORE_POWERDOWN && friendFinderRunning) sleep_ms(10);
while (Core_IsStepping() && coreState != CORE_POWERDOWN && friendFinderRunning)
sleep_ms(10, "pro-adhoc-paused-poll-2");
}
// Groups/Networks should be deallocated isn't?
@ -2257,7 +2258,7 @@ int initNetwork(SceNetAdhocctlAdhocId *adhoc_id){
errorcode = ETIMEDOUT;
break;
}
sleep_ms(10);
sleep_ms(10, "pro-adhoc-socket-poll");
}
if (!done) {
ERROR_LOG(Log::sceNet, "Socket error (%i) when connecting to AdhocServer [%s/%s:%u]", errorcode, g_Config.proAdhocServer.c_str(), ip2str(g_adhocServerIP.in.sin_addr).c_str(), ntohs(g_adhocServerIP.in.sin_port));

View File

@ -2081,10 +2081,12 @@ int server_loop(int server)
}
// Prevent needless CPU Overload (1ms Sleep)
sleep_ms(10);
// !!!! COMMENT NOT REFLECTING REALITY
sleep_ms(10, "pro-adhoc-poll");
// Don't do anything if it's paused, otherwise the log will be flooded
while (adhocServerRunning && Core_IsStepping() && coreState != CORE_POWERDOWN) sleep_ms(10);
while (adhocServerRunning && Core_IsStepping() && coreState != CORE_POWERDOWN)
sleep_ms(10, "pro-adhot-paused-poll");
}
// Free User Database Memory

View File

@ -483,7 +483,7 @@ static void DoFrameIdleTiming() {
double cur_time;
while ((cur_time = time_now_d()) < goal) {
#ifdef _WIN32
sleep_ms(1);
sleep_ms(1, "frame-idle");
#else
const double left = goal - cur_time;
if (left > 0.0f && left < 1.0f) { // Sanity check

View File

@ -7577,10 +7577,11 @@ int matchingEventThread(int matchingId)
}
// Share CPU Time
sleep_ms(10); //1 //sceKernelDelayThread(10000);
sleep_ms(10, "pro-adhoc-poll-3"); //1 //sceKernelDelayThread(10000);
// Don't do anything if it's paused, otherwise the log will be flooded
while (Core_IsStepping() && coreState != CORE_POWERDOWN && contexts != NULL && context->eventRunning) sleep_ms(10);
while (Core_IsStepping() && coreState != CORE_POWERDOWN && contexts != NULL && context->eventRunning)
sleep_ms(10, "pro-adhoc-event-poll-3");
}
// Process Last Messages
@ -7847,10 +7848,11 @@ int matchingInputThread(int matchingId) // TODO: The MatchingInput thread is usi
break;
}
// Share CPU Time
sleep_ms(10); //1 //sceKernelDelayThread(10000);
sleep_ms(10, "pro-adhoc-4"); //1 //sceKernelDelayThread(10000);
// Don't do anything if it's paused, otherwise the log will be flooded
while (Core_IsStepping() && coreState != CORE_POWERDOWN && contexts != NULL && context->inputRunning) sleep_ms(10);
while (Core_IsStepping() && coreState != CORE_POWERDOWN && contexts != NULL && context->inputRunning)
sleep_ms(10, "pro-adhoc-input-4");
}
if (contexts != NULL) {

View File

@ -536,7 +536,7 @@ bool PSP_Init(const CoreParameter &coreParam, std::string *error_string) {
return false;
while (!PSP_InitUpdate(error_string))
sleep_ms(10);
sleep_ms(10, "psp-init-poll");
return pspIsInited;
}

View File

@ -478,7 +478,7 @@ int upnpService(const unsigned int timeout)
// Service Loop
while (upnpServiceRunning && coreState != CORE_POWERDOWN) {
// Sleep for 1ms for faster response if active, otherwise sleep longer (TODO: Improve on this).
sleep_ms(g_Config.bEnableUPnP ? 1 : 100);
sleep_ms(g_Config.bEnableUPnP ? 1 : 100, "upnp-poll");
// Attempts to reconnect if not connected yet or got disconnected
if (g_Config.bEnableUPnP && g_PortManager.GetInitState() == UPNP_INITSTATE_NONE) {

View File

@ -935,7 +935,7 @@ void GameInfoCache::PurgeType(IdentifiedFileType fileType) {
}
}
sleep_ms(10);
sleep_ms(10, "game-info-cache-purge-poll");
} while (retry);
}

View File

@ -1165,7 +1165,7 @@ void NativeFrame(GraphicsContext *graphicsContext) {
double diffTime = time_now_d() - startTime;
int sleepTime = (int)(1000.0 / refreshRate) - (int)(diffTime * 1000.0);
if (sleepTime > 0)
sleep_ms(sleepTime);
sleep_ms(sleepTime, "fallback-throttle");
}
}

View File

@ -457,7 +457,7 @@ RemoteISOConnectScreen::~RemoteISOConnectScreen() {
int maxWait = 5000;
scanCancelled = true;
while (GetStatus() == ScanStatus::SCANNING || GetStatus() == ScanStatus::LOADING) {
sleep_ms(1);
sleep_ms(1, "remote-iso-scan");
if (--maxWait < 0) {
// If it does ever wake up, it may crash... but better than hanging?
scanAborted = true;

View File

@ -316,7 +316,7 @@ static void EmuThreadFunc() {
// Wait for render loop to get started.
INFO_LOG(Log::System, "Runloop: Waiting for displayInit...");
while (!graphicsContext || graphicsContext->GetState() == GraphicsContextState::PENDING) {
sleep_ms(5);
sleep_ms(5, "graphics-poll");
}
// Check the state of the graphics context before we try to feed it into NativeInitGraphics.
@ -1700,7 +1700,7 @@ extern "C" jstring Java_org_ppsspp_ppsspp_ShortcutActivity_queryGameName(JNIEnv
if (info) {
INFO_LOG(Log::System, "GetInfo successful, waiting");
while (!info->Ready(GameInfoFlags::PARAM_SFO)) {
sleep_ms(1);
sleep_ms(1, "info-poll");
}
INFO_LOG(Log::System, "Done waiting");
if (info->fileType != IdentifiedFileType::UNKNOWN) {
@ -1754,7 +1754,7 @@ Java_org_ppsspp_ppsspp_ShortcutActivity_queryGameIcon(JNIEnv * env, jclass clazz
INFO_LOG(Log::System, "GetInfo successful, waiting");
int attempts = 1000;
while (!info->Ready(GameInfoFlags::ICON)) {
sleep_ms(1);
sleep_ms(1, "icon-poll");
attempts--;
if (!attempts) {
break;

View File

@ -222,7 +222,7 @@ bool RunAutoTest(HeadlessHost *headlessHost, CoreParameter &coreParameter, const
headlessHost->SetComparisonScreenshot(ExpectedScreenshotFromFilename(coreParameter.fileToStart), opt.maxScreenshotError);
while (!PSP_InitUpdate(&error_string))
sleep_ms(1);
sleep_ms(1, "auto-test");
if (!PSP_IsInited()) {
TeamCityPrint("testFailed name='%s' message='Startup failed'", currentTestName.c_str());
TeamCityPrint("testFinished name='%s'", currentTestName.c_str());

View File

@ -175,7 +175,7 @@ bool SDLHeadlessHost::InitGraphics(std::string *error_message, GraphicsContext *
std::thread th([&]{
while (threadState_ == RenderThreadState::IDLE)
sleep_ms(1);
sleep_ms(1, "sdl-idle-poll");
threadState_ = RenderThreadState::STARTING;
std::string err;
@ -201,7 +201,7 @@ bool SDLHeadlessHost::InitGraphics(std::string *error_message, GraphicsContext *
threadState_ = RenderThreadState::START_REQUESTED;
while (threadState_ == RenderThreadState::START_REQUESTED || threadState_ == RenderThreadState::STARTING)
sleep_ms(1);
sleep_ms(1, "sdl-start-poll");
return threadState_ == RenderThreadState::STARTED;
}
@ -209,7 +209,7 @@ bool SDLHeadlessHost::InitGraphics(std::string *error_message, GraphicsContext *
void SDLHeadlessHost::ShutdownGraphics() {
gfx_->StopThread();
while (threadState_ != RenderThreadState::STOPPED && threadState_ != RenderThreadState::START_FAILED)
sleep_ms(1);
sleep_ms(1, "sdl-stop-poll");
gfx_->Shutdown();
delete gfx_;

View File

@ -117,7 +117,7 @@ bool WindowsHeadlessHost::InitGraphics(std::string *error_message, GraphicsConte
if (needRenderThread) {
std::thread th([&]{
while (threadState_ == RenderThreadState::IDLE)
sleep_ms(1);
sleep_ms(1, "render-thread-idle-poll");
threadState_ = RenderThreadState::STARTING;
std::string err;
@ -145,7 +145,7 @@ bool WindowsHeadlessHost::InitGraphics(std::string *error_message, GraphicsConte
if (needRenderThread) {
threadState_ = RenderThreadState::START_REQUESTED;
while (threadState_ == RenderThreadState::START_REQUESTED || threadState_ == RenderThreadState::STARTING)
sleep_ms(1);
sleep_ms(1, "render-thread-start-poll");
return threadState_ == RenderThreadState::STARTED;
}
@ -156,7 +156,7 @@ bool WindowsHeadlessHost::InitGraphics(std::string *error_message, GraphicsConte
void WindowsHeadlessHost::ShutdownGraphics() {
gfx_->StopThread();
while (threadState_ != RenderThreadState::STOPPED && threadState_ != RenderThreadState::IDLE)
sleep_ms(1);
sleep_ms(1, "render-thread-stop-poll");
gfx_->Shutdown();
delete gfx_;

View File

@ -1383,7 +1383,7 @@ namespace Libretro
emuThreadState = EmuThreadState::PAUSED;
/* fallthrough */
case EmuThreadState::PAUSED:
sleep_ms(1);
sleep_ms(1, "libretro-paused");
break;
default:
case EmuThreadState::QUIT_REQUESTED:
@ -1432,7 +1432,7 @@ namespace Libretro
ctx->ThreadFrame(); // Eat 1 frame
while (emuThreadState != EmuThreadState::PAUSED)
sleep_ms(1);
sleep_ms(1, "libretro-pause-poll");
}
} // namespace Libretro
@ -1644,7 +1644,7 @@ void retro_run(void)
{
std::string error_string;
while (!PSP_InitUpdate(&error_string))
sleep_ms(4);
sleep_ms(4, "libretro-init-poll");
if (!PSP_IsInited())
{
@ -1736,7 +1736,7 @@ bool retro_serialize(void *data, size_t size)
if (useEmuThread)
{
EmuThreadStart();
sleep_ms(4);
sleep_ms(4, "libretro-serialize");
}
return retVal;
@ -1759,7 +1759,7 @@ bool retro_unserialize(const void *data, size_t size)
if (useEmuThread)
{
EmuThreadStart();
sleep_ms(4);
sleep_ms(4, "libretro-unserialize");
}
return retVal;

View File

@ -19,7 +19,7 @@ struct ResultObject {
};
ResultObject *ResultProducer() {
sleep_ms(250);
sleep_ms(250, "test-result");
printf("result produced: thread %d\n", GetCurrentThreadIdForDebug());
return new ResultObject{ true };
}
@ -36,7 +36,7 @@ bool TestMailbox() {
}
void rangeFunc(int lower, int upper) {
sleep_ms(30);
sleep_ms(30, "test-range");
printf(" - range %d-%d (thread %d)\n", lower, upper, GetCurrentThreadIdForDebug());
}
@ -135,7 +135,7 @@ bool TestThreadManager() {
if (!TestParallelLoop(&manager)) {
return false;
}
sleep_ms(100);
sleep_ms(100, "test-threadman");
ResultObject *result = object->BlockUntilReady();
if (result) {