Merge pull request #10872 from shuffle2/timer

Timer improvements

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;
 }
 

Source/Core/Common/Logging/LogManager.cpp

@@ -4,6 +4,7 @@
 #include "Common/Logging/LogManager.h"
 
 #include <algorithm>
+#include <chrono>
 #include <cstdarg>
 #include <cstring>
 #include <locale>
@@ -11,6 +12,7 @@
 #include <ostream>
 #include <string>
 
+#include <fmt/chrono.h>
 #include <fmt/format.h>
 
 #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<std::chrono::seconds>(now);
+  const auto now_ms = std::chrono::floor<std::chrono::milliseconds>(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<int>(level)], GetShortName(type), message);
 
   for (const auto listener_id : m_listener_ids)

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<LogContainer, LAST_LOG_TYPE> m_log{};
   std::array<LogListener*, LogListener::NUMBER_OF_LISTENERS> m_listeners{};

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<u32>(s_max_length, u32(m_name.length()));
 
   std::lock_guard<std::mutex> 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;
 

Source/Core/Common/Timer.cpp

@@ -4,180 +4,75 @@
 #include "Common/Timer.h"
 
 #include <chrono>
-#include <string>
 
 #ifdef _WIN32
-#include <cwchar>
+#include <Windows.h>
-
+#include <timeapi.h>
-#include <windows.h>
-#include <mmsystem.h>
-#include <sys/timeb.h>
 #else
 #include <sys/time.h>
 #endif
 
-#include <fmt/format.h>
-
 #include "Common/CommonTypes.h"
-#include "Common/StringUtil.h"
 
 namespace Common
 {
-u32 Timer::GetTimeMs()
+template <typename Clock, typename Duration>
+static typename Clock::rep time_now()
 {
-#ifdef _WIN32
+  return std::chrono::time_point_cast<Duration>(Clock::now()).time_since_epoch().count();
-  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
 }
 
-#ifdef _WIN32
+template <typename Duration>
-double GetFreq()
+static auto steady_time_now()
 {
-  LARGE_INTEGER freq;
+  return time_now<std::chrono::steady_clock, Duration>();
-  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
 }
 
-// --------------------------------------------
+u64 Timer::NowUs()
-// Initiate, Start, Stop, and Update the time
-// --------------------------------------------
-
-// Set initial values for the class
-Timer::Timer() : m_LastTime(0), m_StartTime(0), m_Running(false)
 {
-  Update();
+  return steady_time_now<std::chrono::microseconds>();
+}
+
+u64 Timer::NowMs()
+{
+  return steady_time_now<std::chrono::milliseconds>();
 }
 
-// Write the starting time
 void Timer::Start()
 {
-  m_StartTime = GetTimeMs();
+  m_start_ms = NowMs();
-  m_Running = true;
+  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_end_ms = NowMs();
-  m_LastTime = GetTimeMs();
+  m_running = false;
-  m_Running = false;
 }
 
-// Update the last time variable
+u64 Timer::ElapsedMs() const
-void Timer::Update()
 {
-  m_LastTime = GetTimeMs();
+  const u64 end = m_running ? NowMs() : m_end_ms;
-  // TODO(ector) - QPF
+  // 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;
-// -------------------------------------
-// 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(&ltime);
-  return ((u64)ltime);
 }
 
 u64 Timer::GetLocalTimeSinceJan1970()
 {
+#ifdef _MSC_VER
+  std::chrono::zoned_seconds seconds(
+      std::chrono::current_zone(),
+      std::chrono::time_point_cast<std::chrono::seconds>(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<u64>(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
+void Timer::IncreaseResolution()
-double Timer::GetDoubleTime()
 {
-  // FYI: std::chrono::system_clock epoch is not required to be 1970 until c++20.
+#ifdef _WIN32
-  // We will however assume time_t IS unix time.
+  // Disable execution speed and timer resolution throttling process-wide.
-  using Clock = std::chrono::system_clock;
+  // 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:
+  // Not actually sure how useful this is these days.. :')
-  // const auto since_epoch = Clock::now().time_since_epoch();
+  timeBeginPeriod(1);
-  const auto unix_epoch = Clock::from_time_t({});
+#endif
-  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<std::chrono::duration<double>>(since_double_time_epoch).count();
 }
 
-// Formats a timestamp from GetDoubleTime() into a date and time string
+void Timer::RestoreResolution()
-std::string Timer::GetDateTimeFormatted(double time)
 {
-  // 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] = {};
+  timeEndPeriod(1);
-  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
 }
 

Source/Core/Common/Timer.h

@@ -3,7 +3,6 @@
 
 #pragma once
 
-#include <string>
 #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
+  // The rest of these functions probably belong somewhere else
-  // representation
+  static u64 GetLocalTimeSinceJan1970();
-  u64 GetTimeDifference();
-  void AddTimeDifference();
-
-  bool IsRunning() const { return m_Running; }
 
   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_start_ms{0};
-  u64 m_StartTime;
+  u64 m_end_ms{0};
-  bool m_Running;
+  bool m_running{false};
 };
 
 }  // Namespace Common

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<u32> s_drawn_frame;
 static std::atomic<u32> 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())
+    // Restart timer, accounting for time that had elapsed between previous s_timer.Start() and
-    {
+    // emulator pause
-      s_timer.Start();
+    s_timer.StartWithOffset(s_timer_offset);
-    }
+    s_timer_offset = 0;
-    else
-    {
-      // Add time difference from the last pause
-      s_timer.AddTimeDifference();
-    }
     break;
+  }
   default:
     PanicAlertFmt("Invalid state");
     break;
@@ -848,12 +844,12 @@ void RunOnCPUThread(std::function<void()> function, bool wait_for_completion)
 void VideoThrottle()
 {
   // Update info per second
-  u32 ElapseTime = (u32)s_timer.GetTimeElapsed();
+  u64 elapsed_ms = s_timer.ElapsedMs();
-  if ((ElapseTime >= 1000 && s_drawn_video.load() > 0) || s_frame_step)
+  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)
+  if (elapsed_ms == 0)
-    ElapseTime = 1;
+    elapsed_ms = 1;
 
-  float FPS = (float)(s_drawn_frame.load() * 1000.0 / ElapseTime);
+  float FPS = (float)(s_drawn_frame.load() * 1000.0 / elapsed_ms);
-  float VPS = (float)(s_drawn_video.load() * 1000.0 / ElapseTime);
+  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(

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.
 //

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<u64>() % (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<u64>() % (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;
 }
 

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();

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);
 

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<u32>(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<IPCReply> DolphinDevice::IOCtlV(const IOCtlVRequest& request)
 {
   if (Core::WantsDeterminism())

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.
+  DolphinDevice(Kernel& ios, const std::string& device_name);
-  using Device::Device;
   std::optional<IPCReply> IOCtlV(const IOCtlVRequest& request) override;
+
+private:
+  IPCReply GetSystemTime(const IOCtlVRequest& request) const;
+
+  Common::Timer m_timer;
 };
 }  // namespace IOS::HLE

Source/Core/Core/IOS/IOS.cpp

@@ -657,7 +657,7 @@ std::optional<IPCReply> Kernel::HandleIPCCommand(const Request& request)
     return IPCReply{IPC_EINVAL, 550_tbticks};
 
   std::optional<IPCReply> 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<IPCReply> 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)
   {

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;

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 u32 TIMEOUT = 200;
-  static constexpr int SYNC_BUTTON_HOLD_MS_TO_RESET = 10000;
+  static constexpr u32 SYNC_BUTTON_HOLD_MS_TO_RESET = 10000;
 
   std::atomic<SyncButtonState> m_sync_button_state{SyncButtonState::Unpressed};
   Common::Timer m_sync_button_held_timer;

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."));

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<u32>(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<u32>(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<u32>(Common::Timer::NowMs());
 
   // no change, just update with clients
   if (!m_host_input_authority)

Source/Core/Core/State.cpp

@@ -270,6 +270,42 @@ static int GetEmptySlot(std::map<double, int> 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<std::chrono::duration<double>>(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<double, int> 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<u64>(header.time * MS_PER_SEC) +
+  return static_cast<u64>(header.time * MS_PER_SEC) + (DOUBLE_TIME_OFFSET * MS_PER_SEC);
-         (Common::Timer::DOUBLE_TIME_OFFSET * MS_PER_SEC);
 }
 
 static void LoadFileStateData(const std::string& filename, std::vector<u8>& ret_data)

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<double>(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;
   }

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);
 }
 

Source/Core/VideoCommon/OnScreenDisplay.cpp

@@ -32,12 +32,14 @@ static std::atomic<int> s_obscured_pixels_top = 0;
 struct Message
 {
   Message() = default;
-  Message(std::string text_, u32 timestamp_, u32 duration_, u32 color_)
+  Message(std::string text_, u32 duration_, u32 color_)
-      : text(std::move(text_)), timestamp(timestamp_), duration(duration_), color(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,
+  s_messages.emplace(MessageType::Typeless, Message(std::move(message), ms, argb));
-                     Message(std::move(message), Common::Timer::GetTimeMs() + ms, 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<int>(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

Source/Core/VideoCommon/PostProcessing.cpp

@@ -640,7 +640,7 @@ void PostProcessing::FillUniformBuffer(const MathUtil::Rectangle<int>& src,
        static_cast<float>(src.GetWidth()) * rcp_src_width,
        static_cast<float>(src.GetHeight()) * rcp_src_height},
       static_cast<s32>(src_layer),
-      static_cast<u32>(m_timer.GetTimeElapsed()),
+      static_cast<u32>(m_timer.ElapsedMs()),
   };
 
   u8* buf = m_uniform_staging_buffer.data();

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<std::mutex> 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<float>(time_diff_us / 1000000.0);
   m_imgui_last_frame_time = current_time_us;