diff --git a/Source/Core/Common/Image.cpp b/Source/Core/Common/Image.cpp index adca8c1aa7..94e65b9619 100644 --- a/Source/Core/Common/Image.cpp +++ b/Source/Core/Common/Image.cpp @@ -116,7 +116,7 @@ bool SavePNG(const std::string& path, const u8* input, ImageByteFormat format, u size_t image_len = 0; spng_decoded_image_size(ctx.get(), SPNG_FMT_PNG, &image_len); INFO_LOG_FMT(FRAMEDUMP, "{} byte {} by {} image saved to {} at level {} in {}", image_len, width, - height, path, level, timer.GetTimeElapsedFormatted()); + height, path, level, timer.ElapsedMs()); return true; } diff --git a/Source/Core/Common/Logging/LogManager.cpp b/Source/Core/Common/Logging/LogManager.cpp index 2fa86a11b2..80e7db895e 100644 --- a/Source/Core/Common/Logging/LogManager.cpp +++ b/Source/Core/Common/Logging/LogManager.cpp @@ -4,6 +4,7 @@ #include "Common/Logging/LogManager.h" #include +#include #include #include #include @@ -11,6 +12,7 @@ #include #include +#include #include #include "Common/CommonPaths.h" @@ -19,7 +21,6 @@ #include "Common/Logging/ConsoleListener.h" #include "Common/Logging/Log.h" #include "Common/StringUtil.h" -#include "Common/Timer.h" namespace Common::Log { @@ -204,11 +205,23 @@ void LogManager::Log(LogLevel level, LogType type, const char* file, int line, c LogWithFullPath(level, type, file + m_path_cutoff_point, line, message); } +std::string LogManager::GetTimestamp() +{ + // NOTE: the Qt LogWidget hardcodes the expected length of the timestamp portion of the log line, + // so ensure they stay in sync + + // We want milliseconds *and not hours*, so can't directly use STL formatters + const auto now = std::chrono::system_clock::now(); + const auto now_s = std::chrono::floor(now); + const auto now_ms = std::chrono::floor(now); + return fmt::format("{:%M:%S}:{:03}", now_s, (now_ms - now_s).count()); +} + void LogManager::LogWithFullPath(LogLevel level, LogType type, const char* file, int line, const char* message) { const std::string msg = - fmt::format("{} {}:{} {}[{}]: {}\n", Common::Timer::GetTimeFormatted(), file, line, + fmt::format("{} {}:{} {}[{}]: {}\n", GetTimestamp(), file, line, LOG_LEVEL_TO_CHAR[static_cast(level)], GetShortName(type), message); for (const auto listener_id : m_listener_ids) diff --git a/Source/Core/Common/Logging/LogManager.h b/Source/Core/Common/Logging/LogManager.h index 070edd82b4..093d31e01d 100644 --- a/Source/Core/Common/Logging/LogManager.h +++ b/Source/Core/Common/Logging/LogManager.h @@ -75,6 +75,8 @@ private: LogManager(LogManager&&) = delete; LogManager& operator=(LogManager&&) = delete; + static std::string GetTimestamp(); + LogLevel m_level; EnumMap m_log{}; std::array m_listeners{}; diff --git a/Source/Core/Common/Profiler.cpp b/Source/Core/Common/Profiler.cpp index 6e35318668..f3903629e6 100644 --- a/Source/Core/Common/Profiler.cpp +++ b/Source/Core/Common/Profiler.cpp @@ -32,7 +32,7 @@ Profiler::Profiler(const std::string& name) : m_name(name), m_usecs(0), m_usecs_min(UINT64_MAX), m_usecs_max(0), m_usecs_quad(0), m_calls(0), m_depth(0) { - m_time = Common::Timer::GetTimeUs(); + m_time = Common::Timer::NowUs(); s_max_length = std::max(s_max_length, u32(m_name.length())); std::lock_guard lk(s_mutex); @@ -64,7 +64,7 @@ std::string Profiler::ToString() if (s_all_profilers.empty()) return ""; - u64 end = Common::Timer::GetTimeUs(); + u64 end = Common::Timer::NowUs(); s_usecs_frame = end - s_frame_time; s_frame_time = end; @@ -101,7 +101,7 @@ void Profiler::Start() { if (!m_depth++) { - m_time = Common::Timer::GetTimeUs(); + m_time = Common::Timer::NowUs(); } } @@ -109,7 +109,7 @@ void Profiler::Stop() { if (!--m_depth) { - u64 end = Common::Timer::GetTimeUs(); + u64 end = Common::Timer::NowUs(); u64 diff = end - m_time; diff --git a/Source/Core/Common/Timer.cpp b/Source/Core/Common/Timer.cpp index f6d4c983cb..fb81164390 100644 --- a/Source/Core/Common/Timer.cpp +++ b/Source/Core/Common/Timer.cpp @@ -4,180 +4,75 @@ #include "Common/Timer.h" #include -#include #ifdef _WIN32 -#include - -#include -#include -#include +#include +#include #else #include #endif -#include - #include "Common/CommonTypes.h" -#include "Common/StringUtil.h" namespace Common { -u32 Timer::GetTimeMs() +template +static typename Clock::rep time_now() { -#ifdef _WIN32 - return timeGetTime(); -#elif defined __APPLE__ - struct timeval t; - (void)gettimeofday(&t, nullptr); - return ((u32)(t.tv_sec * 1000 + t.tv_usec / 1000)); -#else - struct timespec t; - (void)clock_gettime(CLOCK_MONOTONIC, &t); - return ((u32)(t.tv_sec * 1000 + t.tv_nsec / 1000000)); -#endif + return std::chrono::time_point_cast(Clock::now()).time_since_epoch().count(); } -#ifdef _WIN32 -double GetFreq() +template +static auto steady_time_now() { - LARGE_INTEGER freq; - QueryPerformanceFrequency(&freq); - return 1000000.0 / double(freq.QuadPart); -} -#endif - -u64 Timer::GetTimeUs() -{ -#ifdef _WIN32 - LARGE_INTEGER time; - static double freq = GetFreq(); - QueryPerformanceCounter(&time); - return u64(double(time.QuadPart) * freq); -#elif defined __APPLE__ - struct timeval t; - (void)gettimeofday(&t, nullptr); - return ((u64)(t.tv_sec * 1000000 + t.tv_usec)); -#else - struct timespec t; - (void)clock_gettime(CLOCK_MONOTONIC, &t); - return ((u64)(t.tv_sec * 1000000 + t.tv_nsec / 1000)); -#endif + return time_now(); } -// -------------------------------------------- -// Initiate, Start, Stop, and Update the time -// -------------------------------------------- - -// Set initial values for the class -Timer::Timer() : m_LastTime(0), m_StartTime(0), m_Running(false) +u64 Timer::NowUs() { - Update(); + return steady_time_now(); +} + +u64 Timer::NowMs() +{ + return steady_time_now(); } -// Write the starting time void Timer::Start() { - m_StartTime = GetTimeMs(); - m_Running = true; + m_start_ms = NowMs(); + m_end_ms = 0; + m_running = true; +} + +void Timer::StartWithOffset(u64 offset) +{ + Start(); + m_start_ms -= offset; } -// Stop the timer void Timer::Stop() { - // Write the final time - m_LastTime = GetTimeMs(); - m_Running = false; + m_end_ms = NowMs(); + m_running = false; } -// Update the last time variable -void Timer::Update() +u64 Timer::ElapsedMs() const { - m_LastTime = GetTimeMs(); - // TODO(ector) - QPF -} - -// ------------------------------------- -// Get time difference and elapsed time -// ------------------------------------- - -// Get the number of milliseconds since the last Update() -u64 Timer::GetTimeDifference() -{ - return GetTimeMs() - m_LastTime; -} - -// Add the time difference since the last Update() to the starting time. -// This is used to compensate for a paused game. -void Timer::AddTimeDifference() -{ - m_StartTime += GetTimeDifference(); -} - -// Get the time elapsed since the Start() -u64 Timer::GetTimeElapsed() -{ - // If we have not started yet, return zero - if (m_StartTime == 0) - return 0; - - // Return the final timer time if the timer is stopped - if (!m_Running) - return (m_LastTime - m_StartTime); - - return (GetTimeMs() - m_StartTime); -} - -// Get the formatted time elapsed since the Start() -std::string Timer::GetTimeElapsedFormatted() const -{ - // If we have not started yet, return zero - if (m_StartTime == 0) - return "00:00:00:000"; - - // The number of milliseconds since the start. - // Use a different value if the timer is stopped. - u64 Milliseconds; - if (m_Running) - Milliseconds = GetTimeMs() - m_StartTime; - else - Milliseconds = m_LastTime - m_StartTime; - // Seconds - u32 Seconds = (u32)(Milliseconds / 1000); - // Minutes - u32 Minutes = Seconds / 60; - // Hours - u32 Hours = Minutes / 60; - - return fmt::format("{:02}:{:02}:{:02}:{:03}", Hours, Minutes % 60, Seconds % 60, - Milliseconds % 1000); -} - -// Get current time -void Timer::IncreaseResolution() -{ -#ifdef _WIN32 - timeBeginPeriod(1); -#endif -} - -void Timer::RestoreResolution() -{ -#ifdef _WIN32 - timeEndPeriod(1); -#endif -} - -// Get the number of seconds since January 1 1970 -u64 Timer::GetTimeSinceJan1970() -{ - time_t ltime; - time(<ime); - return ((u64)ltime); + const u64 end = m_running ? NowMs() : m_end_ms; + // Can handle up to 1 rollover event (underflow produces correct result) + // If Start() has never been called, will return 0 + return end - m_start_ms; } u64 Timer::GetLocalTimeSinceJan1970() { +#ifdef _MSC_VER + std::chrono::zoned_seconds seconds( + std::chrono::current_zone(), + std::chrono::time_point_cast(std::chrono::system_clock::now())); + return seconds.get_local_time().time_since_epoch().count(); +#else time_t sysTime, tzDiff, tzDST; time(&sysTime); tm* gmTime = localtime(&sysTime); @@ -193,72 +88,36 @@ u64 Timer::GetLocalTimeSinceJan1970() tzDiff = sysTime - mktime(gmTime); return static_cast(sysTime + tzDiff + tzDST); -} - -// Return the current time formatted as Minutes:Seconds:Milliseconds -// in the form 00:00:000. -std::string Timer::GetTimeFormatted() -{ - time_t sysTime; - time(&sysTime); - - struct tm* gmTime = localtime(&sysTime); - -#ifdef _WIN32 - wchar_t tmp[13]; - wcsftime(tmp, 6, L"%M:%S", gmTime); -#else - char tmp[13]; - strftime(tmp, 6, "%M:%S", gmTime); -#endif - -// Now tack on the milliseconds -#ifdef _WIN32 - struct timeb tp; - (void)::ftime(&tp); - return WStringToUTF8(tmp) + fmt::format(":{:03}", tp.millitm); -#elif defined __APPLE__ - struct timeval t; - (void)gettimeofday(&t, nullptr); - return fmt::format("{}:{:03}", tmp, t.tv_usec / 1000); -#else - struct timespec t; - (void)clock_gettime(CLOCK_MONOTONIC, &t); - return fmt::format("{}:{:03}", tmp, t.tv_nsec / 1000000); #endif } -// Returns a timestamp with decimals for precise time comparisons -double Timer::GetDoubleTime() +void Timer::IncreaseResolution() { - // FYI: std::chrono::system_clock epoch is not required to be 1970 until c++20. - // We will however assume time_t IS unix time. - using Clock = std::chrono::system_clock; +#ifdef _WIN32 + // Disable execution speed and timer resolution throttling process-wide. + // This mainly will keep Dolphin marked as high performance if it's in the background. The OS + // should make it high performance if it's in the foreground anyway (or for some specific + // threads e.g. audio). + // This is best-effort (i.e. the call may fail on older versions of Windows, where such throttling + // doesn't exist, anyway), and we don't bother reverting once set. + // This adjusts behavior on CPUs with "performance" and "efficiency" cores + PROCESS_POWER_THROTTLING_STATE PowerThrottling{}; + PowerThrottling.Version = PROCESS_POWER_THROTTLING_CURRENT_VERSION; + PowerThrottling.ControlMask = + PROCESS_POWER_THROTTLING_EXECUTION_SPEED | PROCESS_POWER_THROTTLING_IGNORE_TIMER_RESOLUTION; + PowerThrottling.StateMask = 0; + SetProcessInformation(GetCurrentProcess(), ProcessPowerThrottling, &PowerThrottling, + sizeof(PowerThrottling)); - // TODO: Use this on switch to c++20: - // const auto since_epoch = Clock::now().time_since_epoch(); - const auto unix_epoch = Clock::from_time_t({}); - const auto since_epoch = Clock::now() - unix_epoch; - - const auto since_double_time_epoch = since_epoch - std::chrono::seconds(DOUBLE_TIME_OFFSET); - return std::chrono::duration_cast>(since_double_time_epoch).count(); + // Not actually sure how useful this is these days.. :') + timeBeginPeriod(1); +#endif } -// Formats a timestamp from GetDoubleTime() into a date and time string -std::string Timer::GetDateTimeFormatted(double time) +void Timer::RestoreResolution() { - // revert adjustments from GetDoubleTime() to get a normal Unix timestamp again - time_t seconds = (time_t)time + DOUBLE_TIME_OFFSET; - tm* localTime = localtime(&seconds); - #ifdef _WIN32 - wchar_t tmp[32] = {}; - wcsftime(tmp, std::size(tmp), L"%x %X", localTime); - return WStringToUTF8(tmp); -#else - char tmp[32] = {}; - strftime(tmp, sizeof(tmp), "%x %X", localTime); - return tmp; + timeEndPeriod(1); #endif } diff --git a/Source/Core/Common/Timer.h b/Source/Core/Common/Timer.h index 614e7b3dfe..7298f4a368 100644 --- a/Source/Core/Common/Timer.h +++ b/Source/Core/Common/Timer.h @@ -3,7 +3,6 @@ #pragma once -#include #include "Common/CommonTypes.h" namespace Common @@ -11,43 +10,26 @@ namespace Common class Timer { public: - Timer(); + static u64 NowUs(); + static u64 NowMs(); void Start(); + // Start(), then decrement start time by the offset. + // Effectively "resumes" a timer + void StartWithOffset(u64 offset); void Stop(); - void Update(); + u64 ElapsedMs() const; - // The time difference is always returned in milliseconds, regardless of alternative internal - // representation - u64 GetTimeDifference(); - void AddTimeDifference(); - - bool IsRunning() const { return m_Running; } + // The rest of these functions probably belong somewhere else + static u64 GetLocalTimeSinceJan1970(); static void IncreaseResolution(); static void RestoreResolution(); - static u64 GetTimeSinceJan1970(); - static u64 GetLocalTimeSinceJan1970(); - // Returns a timestamp with decimals for precise time comparisons - static double GetDoubleTime(); - - static std::string GetTimeFormatted(); - // Formats a timestamp from GetDoubleTime() into a date and time string - static std::string GetDateTimeFormatted(double time); - std::string GetTimeElapsedFormatted() const; - u64 GetTimeElapsed(); - - static u32 GetTimeMs(); - static u64 GetTimeUs(); - - // Arbitrarily chosen value (38 years) that is subtracted in GetDoubleTime() - // to increase sub-second precision of the resulting double timestamp - static constexpr int DOUBLE_TIME_OFFSET = (38 * 365 * 24 * 60 * 60); private: - u64 m_LastTime; - u64 m_StartTime; - bool m_Running; + u64 m_start_ms{0}; + u64 m_end_ms{0}; + bool m_running{false}; }; } // Namespace Common diff --git a/Source/Core/Core/Core.cpp b/Source/Core/Core/Core.cpp index e445749d8d..26fe5444ba 100644 --- a/Source/Core/Core/Core.cpp +++ b/Source/Core/Core/Core.cpp @@ -99,6 +99,7 @@ static bool s_wants_determinism; // Declarations and definitions static Common::Timer s_timer; +static u64 s_timer_offset; static std::atomic s_drawn_frame; static std::atomic s_drawn_video; @@ -271,8 +272,6 @@ void Stop() // - Hammertime! s_is_stopping = true; - s_timer.Stop(); - CallOnStateChangedCallbacks(State::Stopping); // Dump left over jobs @@ -662,21 +661,18 @@ void SetState(State state) CPU::EnableStepping(true); // Break Wiimote::Pause(); ResetRumble(); - s_timer.Update(); + s_timer_offset = s_timer.ElapsedMs(); break; case State::Running: + { CPU::EnableStepping(false); Wiimote::Resume(); - if (!s_timer.IsRunning()) - { - s_timer.Start(); - } - else - { - // Add time difference from the last pause - s_timer.AddTimeDifference(); - } + // Restart timer, accounting for time that had elapsed between previous s_timer.Start() and + // emulator pause + s_timer.StartWithOffset(s_timer_offset); + s_timer_offset = 0; break; + } default: PanicAlertFmt("Invalid state"); break; @@ -848,12 +844,12 @@ void RunOnCPUThread(std::function function, bool wait_for_completion) void VideoThrottle() { // Update info per second - u32 ElapseTime = (u32)s_timer.GetTimeElapsed(); - if ((ElapseTime >= 1000 && s_drawn_video.load() > 0) || s_frame_step) + u64 elapsed_ms = s_timer.ElapsedMs(); + if ((elapsed_ms >= 1000 && s_drawn_video.load() > 0) || s_frame_step) { s_timer.Start(); - UpdateTitle(ElapseTime); + UpdateTitle(elapsed_ms); s_drawn_frame.store(0); s_drawn_video.store(0); @@ -895,15 +891,15 @@ void Callback_NewField() } } -void UpdateTitle(u32 ElapseTime) +void UpdateTitle(u64 elapsed_ms) { - if (ElapseTime == 0) - ElapseTime = 1; + if (elapsed_ms == 0) + elapsed_ms = 1; - float FPS = (float)(s_drawn_frame.load() * 1000.0 / ElapseTime); - float VPS = (float)(s_drawn_video.load() * 1000.0 / ElapseTime); + float FPS = (float)(s_drawn_frame.load() * 1000.0 / elapsed_ms); + float VPS = (float)(s_drawn_video.load() * 1000.0 / elapsed_ms); float Speed = (float)(s_drawn_video.load() * (100 * 1000.0) / - (VideoInterface::GetTargetRefreshRate() * ElapseTime)); + (VideoInterface::GetTargetRefreshRate() * elapsed_ms)); // Settings are shown the same for both extended and summary info const std::string SSettings = fmt::format( diff --git a/Source/Core/Core/Core.h b/Source/Core/Core/Core.h index 1e6e240682..54c7692e39 100644 --- a/Source/Core/Core/Core.h +++ b/Source/Core/Core/Core.h @@ -126,7 +126,7 @@ void OnFrameEnd(); void VideoThrottle(); -void UpdateTitle(u32 ElapseTime); +void UpdateTitle(u64 elapsed_ms); // Run a function as the CPU thread. // diff --git a/Source/Core/Core/DolphinAnalytics.cpp b/Source/Core/Core/DolphinAnalytics.cpp index cd481cd426..5c4c420168 100644 --- a/Source/Core/Core/DolphinAnalytics.cpp +++ b/Source/Core/Core/DolphinAnalytics.cpp @@ -231,18 +231,18 @@ void DolphinAnalytics::InitializePerformanceSampling() u64 wait_us = PERFORMANCE_SAMPLING_INITIAL_WAIT_TIME_SECS * 1000000 + Common::Random::GenerateValue() % (PERFORMANCE_SAMPLING_WAIT_TIME_JITTER_SECS * 1000000); - m_sampling_next_start_us = Common::Timer::GetTimeUs() + wait_us; + m_sampling_next_start_us = Common::Timer::NowUs() + wait_us; } bool DolphinAnalytics::ShouldStartPerformanceSampling() { - if (Common::Timer::GetTimeUs() < m_sampling_next_start_us) + if (Common::Timer::NowUs() < m_sampling_next_start_us) return false; u64 wait_us = PERFORMANCE_SAMPLING_INTERVAL_SECS * 1000000 + Common::Random::GenerateValue() % (PERFORMANCE_SAMPLING_WAIT_TIME_JITTER_SECS * 1000000); - m_sampling_next_start_us = Common::Timer::GetTimeUs() + wait_us; + m_sampling_next_start_us = Common::Timer::NowUs() + wait_us; return true; } diff --git a/Source/Core/Core/HW/DVD/DVDThread.cpp b/Source/Core/Core/HW/DVD/DVDThread.cpp index b06fcd19e2..4d37f823ec 100644 --- a/Source/Core/Core/HW/DVD/DVDThread.cpp +++ b/Source/Core/Core/HW/DVD/DVDThread.cpp @@ -286,7 +286,7 @@ static void StartReadInternal(bool copy_to_ram, u32 output_address, u64 dvd_offs request.id = id; request.time_started_ticks = CoreTiming::GetTicks(); - request.realtime_started_us = Common::Timer::GetTimeUs(); + request.realtime_started_us = Common::Timer::NowUs(); s_request_queue.Push(std::move(request)); s_request_queue_expanded.Set(); @@ -336,7 +336,7 @@ static void FinishRead(u64 id, s64 cycles_late) "Real time including delay: {} us. " "Emulated time including delay: {} us.", request.realtime_done_us - request.realtime_started_us, - Common::Timer::GetTimeUs() - request.realtime_started_us, + Common::Timer::NowUs() - request.realtime_started_us, (CoreTiming::GetTicks() - request.time_started_ticks) / (SystemTimers::GetTicksPerSecond() / 1000000)); @@ -381,7 +381,7 @@ static void DVDThread() if (!s_disc->Read(request.dvd_offset, request.length, buffer.data(), request.partition)) buffer.resize(0); - request.realtime_done_us = Common::Timer::GetTimeUs(); + request.realtime_done_us = Common::Timer::NowUs(); s_result_queue.Push(ReadResult(std::move(request), std::move(buffer))); s_result_queue_expanded.Set(); diff --git a/Source/Core/Core/HW/SystemTimers.cpp b/Source/Core/Core/HW/SystemTimers.cpp index 00a1fb9f36..6a41362b82 100644 --- a/Source/Core/Core/HW/SystemTimers.cpp +++ b/Source/Core/Core/HW/SystemTimers.cpp @@ -167,16 +167,19 @@ void PatchEngineCallback(u64 userdata, s64 cycles_late) CoreTiming::ScheduleEvent(next_schedule, et_PatchEngine, cycles_pruned); } -void ThrottleCallback(u64 last_time, s64 cyclesLate) +void ThrottleCallback(u64 deadline, s64 cyclesLate) { // Allow the GPU thread to sleep. Setting this flag here limits the wakeups to 1 kHz. Fifo::GpuMaySleep(); - u64 time = Common::Timer::GetTimeUs(); + const u64 time = Common::Timer::NowUs(); - s64 diff = last_time - time; + if (deadline == 0) + deadline = time; + + const s64 diff = deadline - time; const float emulation_speed = Config::Get(Config::MAIN_EMULATION_SPEED); - bool frame_limiter = emulation_speed > 0.0f && !Core::GetIsThrottlerTempDisabled(); + const bool frame_limiter = emulation_speed > 0.0f && !Core::GetIsThrottlerTempDisabled(); u32 next_event = GetTicksPerSecond() / 1000; { @@ -193,17 +196,19 @@ void ThrottleCallback(u64 last_time, s64 cyclesLate) const s64 max_fallback = Config::Get(Config::MAIN_TIMING_VARIANCE) * 1000; if (std::abs(diff) > max_fallback) { - DEBUG_LOG_FMT(COMMON, "system too {}, {} ms skipped", diff < 0 ? "slow" : "fast", + DEBUG_LOG_FMT(COMMON, "system too {}, {} us skipped", diff < 0 ? "slow" : "fast", std::abs(diff) - max_fallback); - last_time = time - max_fallback; + deadline = time - max_fallback; } else if (diff > 1000) { Common::SleepCurrentThread(diff / 1000); - s_time_spent_sleeping += Common::Timer::GetTimeUs() - time; + s_time_spent_sleeping += Common::Timer::NowUs() - time; } } - CoreTiming::ScheduleEvent(next_event - cyclesLate, et_Throttle, last_time + 1000); + // reschedule 1ms (possibly scaled by emulation_speed) into future on ppc + // add 1ms to the deadline + CoreTiming::ScheduleEvent(next_event - cyclesLate, et_Throttle, deadline + 1000); } } // namespace @@ -330,7 +335,7 @@ void Init() CoreTiming::ScheduleEvent(VideoInterface::GetTicksPerHalfLine(), et_VI); CoreTiming::ScheduleEvent(0, et_DSP); CoreTiming::ScheduleEvent(GetAudioDMACallbackPeriod(), et_AudioDMA); - CoreTiming::ScheduleEvent(0, et_Throttle, Common::Timer::GetTimeUs()); + CoreTiming::ScheduleEvent(0, et_Throttle, 0); CoreTiming::ScheduleEvent(VideoInterface::GetTicksPerField(), et_PatchEngine); diff --git a/Source/Core/Core/IOS/DolphinDevice.cpp b/Source/Core/Core/IOS/DolphinDevice.cpp index db399c97a9..8048e40d25 100644 --- a/Source/Core/Core/IOS/DolphinDevice.cpp +++ b/Source/Core/Core/IOS/DolphinDevice.cpp @@ -33,24 +33,6 @@ enum }; -IPCReply GetSystemTime(const IOCtlVRequest& request) -{ - if (!request.HasNumberOfValidVectors(0, 1)) - { - return IPCReply(IPC_EINVAL); - } - - if (request.io_vectors[0].size != 4) - { - return IPCReply(IPC_EINVAL); - } - - const u32 milliseconds = Common::Timer::GetTimeMs(); - - Memory::Write_U32(milliseconds, request.io_vectors[0].address); - return IPCReply(IPC_SUCCESS); -} - IPCReply GetVersion(const IOCtlVRequest& request) { if (!request.HasNumberOfValidVectors(0, 1)) @@ -159,6 +141,32 @@ IPCReply GetRealProductCode(const IOCtlVRequest& request) } // namespace +IPCReply DolphinDevice::GetSystemTime(const IOCtlVRequest& request) const +{ + if (!request.HasNumberOfValidVectors(0, 1)) + { + return IPCReply(IPC_EINVAL); + } + + if (request.io_vectors[0].size != 4) + { + return IPCReply(IPC_EINVAL); + } + + // This ioctl is used by emulated software to judge if emulation is running too fast or slow. + // By using Common::Timer, the same clock Dolphin uses internally for the same task is exposed. + // Return elapsed time instead of current timestamp to make buggy emulated code less likely to + // have issuses. + const u32 milliseconds = static_cast(m_timer.ElapsedMs()); + Memory::Write_U32(milliseconds, request.io_vectors[0].address); + return IPCReply(IPC_SUCCESS); +} + +DolphinDevice::DolphinDevice(Kernel& ios, const std::string& device_name) : Device(ios, device_name) +{ + m_timer.Start(); +} + std::optional DolphinDevice::IOCtlV(const IOCtlVRequest& request) { if (Core::WantsDeterminism()) diff --git a/Source/Core/Core/IOS/DolphinDevice.h b/Source/Core/Core/IOS/DolphinDevice.h index baa5809fee..0da464f373 100644 --- a/Source/Core/Core/IOS/DolphinDevice.h +++ b/Source/Core/Core/IOS/DolphinDevice.h @@ -3,6 +3,7 @@ #pragma once +#include "Common/Timer.h" #include "Core/IOS/Device.h" namespace IOS::HLE @@ -10,8 +11,12 @@ namespace IOS::HLE class DolphinDevice final : public Device { public: - // Inherit the constructor from the Device class, since we don't need to do anything special. - using Device::Device; + DolphinDevice(Kernel& ios, const std::string& device_name); std::optional IOCtlV(const IOCtlVRequest& request) override; + +private: + IPCReply GetSystemTime(const IOCtlVRequest& request) const; + + Common::Timer m_timer; }; } // namespace IOS::HLE diff --git a/Source/Core/Core/IOS/IOS.cpp b/Source/Core/Core/IOS/IOS.cpp index 42fb3632d3..de4cdc5d17 100644 --- a/Source/Core/Core/IOS/IOS.cpp +++ b/Source/Core/Core/IOS/IOS.cpp @@ -657,7 +657,7 @@ std::optional Kernel::HandleIPCCommand(const Request& request) return IPCReply{IPC_EINVAL, 550_tbticks}; std::optional ret; - const u64 wall_time_before = Common::Timer::GetTimeUs(); + const u64 wall_time_before = Common::Timer::NowUs(); switch (request.command) { @@ -686,7 +686,7 @@ std::optional Kernel::HandleIPCCommand(const Request& request) break; } - const u64 wall_time_after = Common::Timer::GetTimeUs(); + const u64 wall_time_after = Common::Timer::NowUs(); constexpr u64 BLOCKING_IPC_COMMAND_THRESHOLD_US = 2000; if (wall_time_after - wall_time_before > BLOCKING_IPC_COMMAND_THRESHOLD_US) { diff --git a/Source/Core/Core/IOS/USB/Bluetooth/BTReal.cpp b/Source/Core/Core/IOS/USB/Bluetooth/BTReal.cpp index b093add42d..08323d4b4c 100644 --- a/Source/Core/Core/IOS/USB/Bluetooth/BTReal.cpp +++ b/Source/Core/Core/IOS/USB/Bluetooth/BTReal.cpp @@ -371,12 +371,12 @@ void BluetoothRealDevice::UpdateSyncButtonState(const bool is_held) { if (m_sync_button_state == SyncButtonState::Unpressed && is_held) { - m_sync_button_held_timer.Update(); + m_sync_button_held_timer.Start(); m_sync_button_state = SyncButtonState::Held; } if (m_sync_button_state == SyncButtonState::Held && is_held && - m_sync_button_held_timer.GetTimeDifference() > SYNC_BUTTON_HOLD_MS_TO_RESET) + m_sync_button_held_timer.ElapsedMs() > SYNC_BUTTON_HOLD_MS_TO_RESET) m_sync_button_state = SyncButtonState::LongPressed; else if (m_sync_button_state == SyncButtonState::Held && !is_held) m_sync_button_state = SyncButtonState::Pressed; diff --git a/Source/Core/Core/IOS/USB/Bluetooth/BTReal.h b/Source/Core/Core/IOS/USB/Bluetooth/BTReal.h index 6fd419beba..9b5c36635b 100644 --- a/Source/Core/Core/IOS/USB/Bluetooth/BTReal.h +++ b/Source/Core/Core/IOS/USB/Bluetooth/BTReal.h @@ -62,8 +62,8 @@ private: // Arbitrarily chosen value that allows emulated software to send commands often enough // so that the sync button event is triggered at least every 200ms. // Ideally this should be equal to 0, so we don't trigger unnecessary libusb transfers. - static constexpr int TIMEOUT = 200; - static constexpr int SYNC_BUTTON_HOLD_MS_TO_RESET = 10000; + static constexpr u32 TIMEOUT = 200; + static constexpr u32 SYNC_BUTTON_HOLD_MS_TO_RESET = 10000; std::atomic m_sync_button_state{SyncButtonState::Unpressed}; Common::Timer m_sync_button_held_timer; diff --git a/Source/Core/Core/NetPlayClient.cpp b/Source/Core/Core/NetPlayClient.cpp index d4e8e5fa35..9c01f7a080 100644 --- a/Source/Core/Core/NetPlayClient.cpp +++ b/Source/Core/Core/NetPlayClient.cpp @@ -224,7 +224,7 @@ NetPlayClient::NetPlayClient(const std::string& address, const u16 port, NetPlay break; } } - if (connect_timer.GetTimeElapsed() > 5000) + if (connect_timer.ElapsedMs() > 5000) break; } m_dialog->OnConnectionError(_trans("Could not communicate with host.")); diff --git a/Source/Core/Core/NetPlayServer.cpp b/Source/Core/Core/NetPlayServer.cpp index 0ed2290b0d..ddc62d4561 100644 --- a/Source/Core/Core/NetPlayServer.cpp +++ b/Source/Core/Core/NetPlayServer.cpp @@ -240,9 +240,10 @@ void NetPlayServer::ThreadFunc() while (m_do_loop) { // update pings every so many seconds - if ((m_ping_timer.GetTimeElapsed() > 1000) || m_update_pings) + if ((m_ping_timer.ElapsedMs() > 1000) || m_update_pings) { - m_ping_key = Common::Timer::GetTimeMs(); + // only used as an identifier, not time value, so truncation is fine + m_ping_key = static_cast(Common::Timer::NowMs()); sf::Packet spac; spac << MessageID::Ping; @@ -951,7 +952,8 @@ unsigned int NetPlayServer::OnData(sf::Packet& packet, Client& player) case MessageID::Pong: { - const u32 ping = (u32)m_ping_timer.GetTimeElapsed(); + // truncation (> ~49 days elapsed) should never happen here + const u32 ping = static_cast(m_ping_timer.ElapsedMs()); u32 ping_key = 0; packet >> ping_key; @@ -1459,7 +1461,8 @@ bool NetPlayServer::StartGame() m_timebase_by_frame.clear(); m_desync_detected = false; std::lock_guard lkg(m_crit.game); - m_current_game = Common::Timer::GetTimeMs(); + // only used as an identifier, not time value, so truncation is fine + m_current_game = static_cast(Common::Timer::NowMs()); // no change, just update with clients if (!m_host_input_authority) diff --git a/Source/Core/Core/State.cpp b/Source/Core/Core/State.cpp index 9457ea259a..c7c2aee8dd 100644 --- a/Source/Core/Core/State.cpp +++ b/Source/Core/Core/State.cpp @@ -270,6 +270,42 @@ static int GetEmptySlot(std::map m) return -1; } +// Arbitrarily chosen value (38 years) that is subtracted in GetSystemTimeAsDouble() +// to increase sub-second precision of the resulting double timestamp +static constexpr int DOUBLE_TIME_OFFSET = (38 * 365 * 24 * 60 * 60); + +static double GetSystemTimeAsDouble() +{ + // FYI: std::chrono::system_clock epoch is not required to be 1970 until c++20. + // We will however assume time_t IS unix time. + using Clock = std::chrono::system_clock; + + // TODO: Use this on switch to c++20: + // const auto since_epoch = Clock::now().time_since_epoch(); + const auto unix_epoch = Clock::from_time_t({}); + const auto since_epoch = Clock::now() - unix_epoch; + + const auto since_double_time_epoch = since_epoch - std::chrono::seconds(DOUBLE_TIME_OFFSET); + return std::chrono::duration_cast>(since_double_time_epoch).count(); +} + +static std::string SystemTimeAsDoubleToString(double time) +{ + // revert adjustments from GetSystemTimeAsDouble() to get a normal Unix timestamp again + time_t seconds = (time_t)time + DOUBLE_TIME_OFFSET; + tm* localTime = localtime(&seconds); + +#ifdef _WIN32 + wchar_t tmp[32] = {}; + wcsftime(tmp, std::size(tmp), L"%x %X", localTime); + return WStringToUTF8(tmp); +#else + char tmp[32] = {}; + strftime(tmp, sizeof(tmp), "%x %X", localTime); + return tmp; +#endif +} + static std::string MakeStateFilename(int number); // read state timestamps @@ -284,7 +320,7 @@ static std::map GetSavedStates() { if (ReadHeader(filename, header)) { - double d = Common::Timer::GetDoubleTime() - header.time; + double d = GetSystemTimeAsDouble() - header.time; // increase time until unique value is obtained while (m.find(d) != m.end()) @@ -359,7 +395,7 @@ static void CompressAndDumpState(CompressAndDumpState_args save_args) StateHeader header{}; SConfig::GetInstance().GetGameID().copy(header.gameID, std::size(header.gameID)); header.size = s_use_compression ? (u32)buffer_size : 0; - header.time = Common::Timer::GetDoubleTime(); + header.time = GetSystemTimeAsDouble(); f.WriteArray(&header, 1); @@ -471,7 +507,7 @@ std::string GetInfoStringOfSlot(int slot, bool translate) if (!ReadHeader(filename, header)) return translate ? Common::GetStringT("Unknown") : "Unknown"; - return Common::Timer::GetDateTimeFormatted(header.time); + return SystemTimeAsDoubleToString(header.time); } u64 GetUnixTimeOfSlot(int slot) @@ -481,8 +517,7 @@ u64 GetUnixTimeOfSlot(int slot) return 0; constexpr u64 MS_PER_SEC = 1000; - return static_cast(header.time * MS_PER_SEC) + - (Common::Timer::DOUBLE_TIME_OFFSET * MS_PER_SEC); + return static_cast(header.time * MS_PER_SEC) + (DOUBLE_TIME_OFFSET * MS_PER_SEC); } static void LoadFileStateData(const std::string& filename, std::vector& ret_data) diff --git a/Source/Core/VideoCommon/FPSCounter.cpp b/Source/Core/VideoCommon/FPSCounter.cpp index 459856d1ef..e38305eb7f 100644 --- a/Source/Core/VideoCommon/FPSCounter.cpp +++ b/Source/Core/VideoCommon/FPSCounter.cpp @@ -16,7 +16,7 @@ static constexpr u64 FPS_REFRESH_INTERVAL_US = 250000; FPSCounter::FPSCounter() { - m_last_time = Common::Timer::GetTimeUs(); + m_last_time = Common::Timer::NowUs(); m_on_state_changed_handle = Core::AddOnStateChangedCallback([this](Core::State state) { if (state == Core::State::Paused) @@ -44,7 +44,7 @@ void FPSCounter::LogRenderTimeToFile(u64 val) void FPSCounter::Update() { - const u64 time = Common::Timer::GetTimeUs(); + const u64 time = Common::Timer::NowUs(); const u64 diff = time - m_last_time; m_time_diff_secs = static_cast(diff / 1000000.0); if (g_ActiveConfig.bLogRenderTimeToFile) @@ -66,11 +66,11 @@ void FPSCounter::SetPaused(bool paused) { if (paused) { - m_last_time_pause = Common::Timer::GetTimeUs(); + m_last_time_pause = Common::Timer::NowUs(); } else { - const u64 time = Common::Timer::GetTimeUs(); + const u64 time = Common::Timer::NowUs(); const u64 diff = time - m_last_time_pause; m_last_time += diff; } diff --git a/Source/Core/VideoCommon/HiresTextures.cpp b/Source/Core/VideoCommon/HiresTextures.cpp index 9636bfe651..f3d6d77373 100644 --- a/Source/Core/VideoCommon/HiresTextures.cpp +++ b/Source/Core/VideoCommon/HiresTextures.cpp @@ -159,7 +159,8 @@ void HiresTexture::Prefetch() const size_t max_mem = (sys_mem / 2 < recommended_min_mem) ? (sys_mem / 2) : (sys_mem - recommended_min_mem); - const u32 start_time = Common::Timer::GetTimeMs(); + Common::Timer timer; + timer.Start(); for (const auto& entry : s_textureMap) { const std::string& base_filename = entry.first; @@ -207,9 +208,8 @@ void HiresTexture::Prefetch() } } - const u32 stop_time = Common::Timer::GetTimeMs(); OSD::AddMessage(fmt::format("Custom Textures loaded, {:.1f} MB in {:.1f}s", - size_sum / (1024.0 * 1024.0), (stop_time - start_time) / 1000.0), + size_sum / (1024.0 * 1024.0), timer.ElapsedMs() / 1000.0), 10000); } diff --git a/Source/Core/VideoCommon/OnScreenDisplay.cpp b/Source/Core/VideoCommon/OnScreenDisplay.cpp index 4bc7cd9494..e860c53ec0 100644 --- a/Source/Core/VideoCommon/OnScreenDisplay.cpp +++ b/Source/Core/VideoCommon/OnScreenDisplay.cpp @@ -32,12 +32,14 @@ static std::atomic s_obscured_pixels_top = 0; struct Message { Message() = default; - Message(std::string text_, u32 timestamp_, u32 duration_, u32 color_) - : text(std::move(text_)), timestamp(timestamp_), duration(duration_), color(color_) + Message(std::string text_, u32 duration_, u32 color_) + : text(std::move(text_)), duration(duration_), color(color_) { + timer.Start(); } + s64 TimeRemaining() const { return duration - timer.ElapsedMs(); } std::string text; - u32 timestamp = 0; + Common::Timer timer; u32 duration = 0; bool ever_drawn = false; u32 color = 0; @@ -93,20 +95,18 @@ void AddTypedMessage(MessageType type, std::string message, u32 ms, u32 argb) { std::lock_guard lock{s_messages_mutex}; s_messages.erase(type); - s_messages.emplace(type, Message(std::move(message), Common::Timer::GetTimeMs() + ms, ms, argb)); + s_messages.emplace(type, Message(std::move(message), ms, argb)); } void AddMessage(std::string message, u32 ms, u32 argb) { std::lock_guard lock{s_messages_mutex}; - s_messages.emplace(MessageType::Typeless, - Message(std::move(message), Common::Timer::GetTimeMs() + ms, ms, argb)); + s_messages.emplace(MessageType::Typeless, Message(std::move(message), ms, argb)); } void DrawMessages() { const bool draw_messages = Config::Get(Config::MAIN_OSD_MESSAGES); - const u32 now = Common::Timer::GetTimeMs(); const float current_x = LEFT_MARGIN * ImGui::GetIO().DisplayFramebufferScale.x + s_obscured_pixels_left; float current_y = TOP_MARGIN * ImGui::GetIO().DisplayFramebufferScale.y + s_obscured_pixels_top; @@ -117,7 +117,7 @@ void DrawMessages() for (auto it = s_messages.begin(); it != s_messages.end();) { Message& msg = it->second; - const int time_left = static_cast(msg.timestamp - now); + const s64 time_left = msg.TimeRemaining(); // Make sure we draw them at least once if they were printed with 0ms, // unless enough time has expired, in that case, we drop them diff --git a/Source/Core/VideoCommon/PostProcessing.cpp b/Source/Core/VideoCommon/PostProcessing.cpp index 72ee15a776..69e4327bdd 100644 --- a/Source/Core/VideoCommon/PostProcessing.cpp +++ b/Source/Core/VideoCommon/PostProcessing.cpp @@ -640,7 +640,7 @@ void PostProcessing::FillUniformBuffer(const MathUtil::Rectangle& src, static_cast(src.GetWidth()) * rcp_src_width, static_cast(src.GetHeight()) * rcp_src_height}, static_cast(src_layer), - static_cast(m_timer.GetTimeElapsed()), + static_cast(m_timer.ElapsedMs()), }; u8* buf = m_uniform_staging_buffer.data(); diff --git a/Source/Core/VideoCommon/RenderBase.cpp b/Source/Core/VideoCommon/RenderBase.cpp index 412461d409..e51307fa15 100644 --- a/Source/Core/VideoCommon/RenderBase.cpp +++ b/Source/Core/VideoCommon/RenderBase.cpp @@ -1066,7 +1066,7 @@ bool Renderer::InitializeImGui() if (!RecompileImGuiPipeline()) return false; - m_imgui_last_frame_time = Common::Timer::GetTimeUs(); + m_imgui_last_frame_time = Common::Timer::NowUs(); BeginImGuiFrame(); return true; } @@ -1139,7 +1139,7 @@ void Renderer::BeginImGuiFrame() { std::unique_lock imgui_lock(m_imgui_mutex); - const u64 current_time_us = Common::Timer::GetTimeUs(); + const u64 current_time_us = Common::Timer::NowUs(); const u64 time_diff_us = current_time_us - m_imgui_last_frame_time; const float time_diff_secs = static_cast(time_diff_us / 1000000.0); m_imgui_last_frame_time = current_time_us;