Merge pull request #10872 from shuffle2/timer

Timer improvements

6 files changed, 86 insertions, 230 deletions

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 <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)
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<LogContainer, LAST_LOG_TYPE> m_log{};
   std::array<LogListener*, LogListener::NUMBER_OF_LISTENERS> 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<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;
 
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 <chrono>
-#include <string>
 
 #ifdef _WIN32
-#include <cwchar>
-
-#include <windows.h>
-#include <mmsystem.h>
-#include <sys/timeb.h>
+#include <Windows.h>
+#include <timeapi.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 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<Duration>(Clock::now()).time_since_epoch().count();
 }
 
-#ifdef _WIN32
-double GetFreq()
+template <typename Duration>
+static auto steady_time_now()
 {
-  LARGE_INTEGER freq;
-  QueryPerformanceFrequency(&freq);
-  return 1000000.0 / double(freq.QuadPart);
+  return time_now<std::chrono::steady_clock, Duration>();
 }
-#endif
 
-u64 Timer::GetTimeUs()
+u64 Timer::NowUs()
 {
-#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 steady_time_now<std::chrono::microseconds>();
 }
 
-// --------------------------------------------
-// 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::NowMs()
 {
-  Update();
+  return steady_time_now<std::chrono::milliseconds>();
 }
 
-// Write the starting time
 void Timer::Start()
 {
-  m_StartTime = GetTimeMs();
-  m_Running = true;
-}
-
-// Stop the timer
-void Timer::Stop()
-{
-  // Write the final time
-  m_LastTime = GetTimeMs();
-  m_Running = false;
-}
-
-// Update the last time variable
-void Timer::Update()
-{
-  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);
+  m_start_ms = NowMs();
+  m_end_ms = 0;
+  m_running = true;
 }
 
-// Get current time
-void Timer::IncreaseResolution()
+void Timer::StartWithOffset(u64 offset)
 {
-#ifdef _WIN32
-  timeBeginPeriod(1);
-#endif
+  Start();
+  m_start_ms -= offset;
 }
 
-void Timer::RestoreResolution()
+void Timer::Stop()
 {
-#ifdef _WIN32
-  timeEndPeriod(1);
-#endif
+  m_end_ms = NowMs();
+  m_running = false;
 }
 
-// Get the number of seconds since January 1 1970
-u64 Timer::GetTimeSinceJan1970()
+u64 Timer::ElapsedMs() const
 {
-  time_t ltime;
-  time(&ltime);
-  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::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);
+#endif
 }
 
-// Return the current time formatted as Minutes:Seconds:Milliseconds
-// in the form 00:00:000.
-std::string Timer::GetTimeFormatted()
+void Timer::IncreaseResolution()
 {
-  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);
+  // 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));
+
+  // Not actually sure how useful this is these days.. :')
+  timeBeginPeriod(1);
 #endif
 }
 
-// Returns a timestamp with decimals for precise time comparisons
-double Timer::GetDoubleTime()
-{
-  // 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();
-}
-
-// 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 <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
-  // 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