From cd1fbfcf1b70e365d81480ec0f56db19ed02454f Mon Sep 17 00:00:00 2001 From: Yuri Kunde Schlesner Date: Thu, 5 Feb 2015 14:53:25 -0200 Subject: Add profiling infrastructure and widget --- src/common/CMakeLists.txt | 4 + src/common/profiler.cpp | 159 ++++++++++++++++++++++++++++++++++++++ src/common/profiler.h | 134 ++++++++++++++++++++++++++++++++ src/common/profiler_reporting.h | 108 ++++++++++++++++++++++++++ src/common/synchronized_wrapper.h | 69 +++++++++++++++++ src/common/thread.h | 19 +++++ 6 files changed, 493 insertions(+) create mode 100644 src/common/profiler.cpp create mode 100644 src/common/profiler.h create mode 100644 src/common/profiler_reporting.h create mode 100644 src/common/synchronized_wrapper.h (limited to 'src/common') diff --git a/src/common/CMakeLists.txt b/src/common/CMakeLists.txt index b05c35546..daa2d59de 100644 --- a/src/common/CMakeLists.txt +++ b/src/common/CMakeLists.txt @@ -14,6 +14,7 @@ set(SRCS mem_arena.cpp memory_util.cpp misc.cpp + profiler.cpp scm_rev.cpp string_util.cpp symbols.cpp @@ -48,11 +49,14 @@ set(HEADERS mem_arena.h memory_util.h platform.h + profiler.h + profiler_reporting.h scm_rev.h scope_exit.h string_util.h swap.h symbols.h + synchronized_wrapper.h thread.h thread_queue_list.h thunk.h diff --git a/src/common/profiler.cpp b/src/common/profiler.cpp new file mode 100644 index 000000000..c37546af0 --- /dev/null +++ b/src/common/profiler.cpp @@ -0,0 +1,159 @@ +// Copyright 2015 Citra Emulator Project +// Licensed under GPLv2 or any later version +// Refer to the license.txt file included. + +#include "common/profiler.h" +#include "common/profiler_reporting.h" +#include "common/assert.h" + +namespace Common { +namespace Profiling { + +#if ENABLE_PROFILING +thread_local Timer* Timer::current_timer = nullptr; +#endif + +TimingCategory::TimingCategory(const char* name, TimingCategory* parent) + : accumulated_duration(0) { + + ProfilingManager& manager = GetProfilingManager(); + category_id = manager.RegisterTimingCategory(this, name); + if (parent != nullptr) + manager.SetTimingCategoryParent(category_id, parent->category_id); +} + +ProfilingManager::ProfilingManager() + : last_frame_end(Clock::now()), this_frame_start(Clock::now()) { +} + +unsigned int ProfilingManager::RegisterTimingCategory(TimingCategory* category, const char* name) { + TimingCategoryInfo info; + info.category = category; + info.name = name; + info.parent = TimingCategoryInfo::NO_PARENT; + + unsigned int id = (unsigned int)timing_categories.size(); + timing_categories.push_back(std::move(info)); + + return id; +} + +void ProfilingManager::SetTimingCategoryParent(unsigned int category, unsigned int parent) { + ASSERT(category < timing_categories.size()); + ASSERT(parent < timing_categories.size()); + + timing_categories[category].parent = parent; +} + +void ProfilingManager::BeginFrame() { + this_frame_start = Clock::now(); +} + +void ProfilingManager::FinishFrame() { + Clock::time_point now = Clock::now(); + + results.interframe_time = now - last_frame_end; + results.frame_time = now - this_frame_start; + + results.time_per_category.resize(timing_categories.size()); + for (size_t i = 0; i < timing_categories.size(); ++i) { + results.time_per_category[i] = timing_categories[i].category->GetAccumulatedTime(); + } + + last_frame_end = now; +} + +TimingResultsAggregator::TimingResultsAggregator(size_t window_size) + : max_window_size(window_size), window_size(0) { + interframe_times.resize(window_size, Duration::zero()); + frame_times.resize(window_size, Duration::zero()); +} + +void TimingResultsAggregator::Clear() { + window_size = cursor = 0; +} + +void TimingResultsAggregator::SetNumberOfCategories(size_t n) { + size_t old_size = times_per_category.size(); + if (n == old_size) + return; + + times_per_category.resize(n); + + for (size_t i = old_size; i < n; ++i) { + times_per_category[i].resize(max_window_size, Duration::zero()); + } +} + +void TimingResultsAggregator::AddFrame(const ProfilingFrameResult& frame_result) { + SetNumberOfCategories(frame_result.time_per_category.size()); + + interframe_times[cursor] = frame_result.interframe_time; + frame_times[cursor] = frame_result.frame_time; + for (size_t i = 0; i < frame_result.time_per_category.size(); ++i) { + times_per_category[i][cursor] = frame_result.time_per_category[i]; + } + + ++cursor; + if (cursor == max_window_size) + cursor = 0; + if (window_size < max_window_size) + ++window_size; +} + +static AggregatedDuration AggregateField(const std::vector& v, size_t len) { + AggregatedDuration result; + result.avg = Duration::zero(); + + result.min = result.max = (len == 0 ? Duration::zero() : v[0]); + + for (size_t i = 1; i < len; ++i) { + Duration value = v[i]; + result.avg += value; + result.min = std::min(result.min, value); + result.max = std::max(result.max, value); + } + if (len != 0) + result.avg /= len; + + return result; +} + +static float tof(Common::Profiling::Duration dur) { + using FloatMs = std::chrono::duration; + return std::chrono::duration_cast(dur).count(); +} + +AggregatedFrameResult TimingResultsAggregator::GetAggregatedResults() const { + AggregatedFrameResult result; + + result.interframe_time = AggregateField(interframe_times, window_size); + result.frame_time = AggregateField(frame_times, window_size); + + if (result.interframe_time.avg != Duration::zero()) { + result.fps = 1000.0f / tof(result.interframe_time.avg); + } else { + result.fps = 0.0f; + } + + result.time_per_category.resize(times_per_category.size()); + for (size_t i = 0; i < times_per_category.size(); ++i) { + result.time_per_category[i] = AggregateField(times_per_category[i], window_size); + } + + return result; +} + +ProfilingManager& GetProfilingManager() { + // Takes advantage of "magic" static initialization for race-free initialization. + static ProfilingManager manager; + return manager; +} + +SynchronizedRef GetTimingResultsAggregator() { + static SynchronizedWrapper aggregator(30); + return SynchronizedRef(aggregator); +} + +} // namespace Profiling +} // namespace Common diff --git a/src/common/profiler.h b/src/common/profiler.h new file mode 100644 index 000000000..53c4f6eaf --- /dev/null +++ b/src/common/profiler.h @@ -0,0 +1,134 @@ +// Copyright 2015 Citra Emulator Project +// Licensed under GPLv2 or any later version +// Refer to the license.txt file included. + +#pragma once + +#include +#include + +#include "common/assert.h" +#include "common/thread.h" + +namespace Common { +namespace Profiling { + +// If this is defined to 0, it turns all Timers into no-ops. +#ifndef ENABLE_PROFILING +#define ENABLE_PROFILING 1 +#endif + +using Duration = std::chrono::nanoseconds; +using Clock = std::chrono::high_resolution_clock; + +/** + * Represents a timing category that measured time can be accounted towards. Should be declared as a + * global variable and passed to Timers. + */ +class TimingCategory final { +public: + TimingCategory(const char* name, TimingCategory* parent = nullptr); + + unsigned int GetCategoryId() const { + return category_id; + } + + /// Adds some time to this category. Can safely be called from multiple threads at the same time. + void AddTime(Duration amount) { + std::atomic_fetch_add_explicit( + &accumulated_duration, amount.count(), + std::memory_order_relaxed); + } + + /** + * Atomically retrieves the accumulated measured time for this category and resets the counter + * to zero. Can be safely called concurrently with AddTime. + */ + Duration GetAccumulatedTime() { + return Duration(std::atomic_exchange_explicit( + &accumulated_duration, (Duration::rep)0, + std::memory_order_relaxed)); + } + +private: + unsigned int category_id; + std::atomic accumulated_duration; +}; + +/** + * Measures time elapsed between a call to Start and a call to Stop and attributes it to the given + * TimingCategory. Start/Stop can be called multiple times on the same timer, but each call must be + * appropriately paired. + * + * When a Timer is started, it automatically pauses a previously running timer on the same thread, + * which is resumed when it is stopped. As such, no special action needs to be taken to avoid + * double-accounting of time on two categories. + */ +class Timer { +public: + Timer(TimingCategory& category) : category(category) { + } + + void Start() { +#if ENABLE_PROFILING + ASSERT(!running); + previous_timer = current_timer; + current_timer = this; + if (previous_timer != nullptr) + previous_timer->StopTiming(); + + StartTiming(); +#endif + } + + void Stop() { +#if ENABLE_PROFILING + ASSERT(running); + StopTiming(); + + if (previous_timer != nullptr) + previous_timer->StartTiming(); + current_timer = previous_timer; +#endif + } + +private: +#if ENABLE_PROFILING + void StartTiming() { + start = Clock::now(); + running = true; + } + + void StopTiming() { + auto duration = Clock::now() - start; + running = false; + category.AddTime(std::chrono::duration_cast(duration)); + } + + Clock::time_point start; + bool running = false; + + Timer* previous_timer; + static thread_local Timer* current_timer; +#endif + + TimingCategory& category; +}; + +/** + * A Timer that automatically starts timing when created and stops at the end of the scope. Should + * be used in the majority of cases. + */ +class ScopeTimer : public Timer { +public: + ScopeTimer(TimingCategory& category) : Timer(category) { + Start(); + } + + ~ScopeTimer() { + Stop(); + } +}; + +} // namespace Profiling +} // namespace Common diff --git a/src/common/profiler_reporting.h b/src/common/profiler_reporting.h new file mode 100644 index 000000000..3abb73315 --- /dev/null +++ b/src/common/profiler_reporting.h @@ -0,0 +1,108 @@ +// Copyright 2015 Citra Emulator Project +// Licensed under GPLv2 or any later version +// Refer to the license.txt file included. + +#pragma once + +#include +#include +#include +#include +#include + +#include "common/profiler.h" +#include "common/synchronized_wrapper.h" + +namespace Common { +namespace Profiling { + +struct TimingCategoryInfo { + static const unsigned int NO_PARENT = -1; + + TimingCategory* category; + const char* name; + unsigned int parent; +}; + +struct ProfilingFrameResult { + /// Time since the last delivered frame + Duration interframe_time; + + /// Time spent processing a frame, excluding VSync + Duration frame_time; + + /// Total amount of time spent inside each category in this frame. Indexed by the category id + std::vector time_per_category; +}; + +class ProfilingManager final { +public: + ProfilingManager(); + + unsigned int RegisterTimingCategory(TimingCategory* category, const char* name); + void SetTimingCategoryParent(unsigned int category, unsigned int parent); + + const std::vector& GetTimingCategoriesInfo() const { + return timing_categories; + } + + /// This should be called after swapping screen buffers. + void BeginFrame(); + /// This should be called before swapping screen buffers. + void FinishFrame(); + + /// Get the timing results from the previous frame. This is updated when you call FinishFrame(). + const ProfilingFrameResult& GetPreviousFrameResults() const { + return results; + } + +private: + std::vector timing_categories; + Clock::time_point last_frame_end; + Clock::time_point this_frame_start; + + ProfilingFrameResult results; +}; + +struct AggregatedDuration { + Duration avg, min, max; +}; + +struct AggregatedFrameResult { + /// Time since the last delivered frame + AggregatedDuration interframe_time; + + /// Time spent processing a frame, excluding VSync + AggregatedDuration frame_time; + + float fps; + + /// Total amount of time spent inside each category in this frame. Indexed by the category id + std::vector time_per_category; +}; + +class TimingResultsAggregator final { +public: + TimingResultsAggregator(size_t window_size); + + void Clear(); + void SetNumberOfCategories(size_t n); + + void AddFrame(const ProfilingFrameResult& frame_result); + + AggregatedFrameResult GetAggregatedResults() const; + + size_t max_window_size; + size_t window_size; + size_t cursor; + + std::vector interframe_times; + std::vector frame_times; + std::vector> times_per_category; +}; + +ProfilingManager& GetProfilingManager(); +SynchronizedRef GetTimingResultsAggregator(); + +} // namespace Profiling +} // namespace Common diff --git a/src/common/synchronized_wrapper.h b/src/common/synchronized_wrapper.h new file mode 100644 index 000000000..946252b8c --- /dev/null +++ b/src/common/synchronized_wrapper.h @@ -0,0 +1,69 @@ +// Copyright 2015 Citra Emulator Project +// Licensed under GPLv2 or any later version +// Refer to the license.txt file included. + +#pragma once + +#include + +namespace Common { + +/** + * Wraps an object, only allowing access to it via a locking reference wrapper. Good to ensure no + * one forgets to lock a mutex before acessing an object. To access the wrapped object construct a + * SyncronizedRef on this wrapper. Inspired by Rust's Mutex type (http://doc.rust-lang.org/std/sync/struct.Mutex.html). + */ +template +class SynchronizedWrapper { +public: + template + SynchronizedWrapper(Args&&... args) : + data(std::forward(args)...) { + } + +private: + template + friend class SynchronizedRef; + + std::mutex mutex; + T data; +}; + +/** + * Synchronized reference, that keeps a SynchronizedWrapper's mutex locked during its lifetime. This + * greatly reduces the chance that someone will access the wrapped resource without locking the + * mutex. + */ +template +class SynchronizedRef { +public: + SynchronizedRef(SynchronizedWrapper& wrapper) : wrapper(&wrapper) { + wrapper.mutex.lock(); + } + + SynchronizedRef(SynchronizedRef&) = delete; + SynchronizedRef(SynchronizedRef&& o) : wrapper(o.wrapper) { + o.wrapper = nullptr; + } + + ~SynchronizedRef() { + if (wrapper) + wrapper->mutex.unlock(); + } + + SynchronizedRef& operator=(SynchronizedRef&) = delete; + SynchronizedRef& operator=(SynchronizedRef&& o) { + std::swap(wrapper, o.wrapper); + } + + T& operator*() { return wrapper->data; } + const T& operator*() const { return wrapper->data; } + + T* operator->() { return &wrapper->data; } + const T* operator->() const { return &wrapper->data; } + +private: + SynchronizedWrapper* wrapper; +}; + +} // namespace Common diff --git a/src/common/thread.h b/src/common/thread.h index eaf1ba00c..a45728e1e 100644 --- a/src/common/thread.h +++ b/src/common/thread.h @@ -24,6 +24,25 @@ #include #endif +// Support for C++11's thread_local keyword was surprisingly spotty in compilers until very +// recently. Fortunately, thread local variables have been well supported for compilers for a while, +// but with semantics supporting only POD types, so we can use a few defines to get some amount of +// backwards compat support. +// WARNING: This only works correctly with POD types. +#if defined(__clang__) +# if !__has_feature(cxx_thread_local) +# define thread_local __thread +# endif +#elif defined(__GNUC__) +# if __GNUC__ < 4 || (__GNUC__ == 4 && __GNUC_MINOR__ < 8) +# define thread_local __thread +# endif +#elif defined(_MSC_VER) +# if _MSC_VER < 1900 +# define thread_local __declspec(thread) +# endif +#endif + namespace Common { -- cgit v1.2.3 From dc8a3f8bc842df1b3eeeb5a283556ac644ab3183 Mon Sep 17 00:00:00 2001 From: Yuri Kunde Schlesner Date: Sun, 15 Feb 2015 15:49:27 -0200 Subject: Profiler: Implement QPCClock to get better precision on Win32 MSVC 2013 (at least) doesn't use QueryPerformanceCounter to implement std::chrono::high_resolution_clock, so it has bad precision. Manually implementing our own clock type using it works around this for now. --- src/common/profiler.cpp | 23 +++++++++++++++++++++++ src/common/profiler.h | 20 +++++++++++++++++++- 2 files changed, 42 insertions(+), 1 deletion(-) (limited to 'src/common') diff --git a/src/common/profiler.cpp b/src/common/profiler.cpp index c37546af0..65c3df167 100644 --- a/src/common/profiler.cpp +++ b/src/common/profiler.cpp @@ -6,6 +6,12 @@ #include "common/profiler_reporting.h" #include "common/assert.h" +#if defined(_MSC_VER) && _MSC_VER <= 1800 // MSVC 2013. +#define NOMINMAX +#define WIN32_LEAN_AND_MEAN +#include // For QueryPerformanceCounter/Frequency +#endif + namespace Common { namespace Profiling { @@ -13,6 +19,23 @@ namespace Profiling { thread_local Timer* Timer::current_timer = nullptr; #endif +#if defined(_MSC_VER) && _MSC_VER <= 1800 // MSVC 2013 +QPCClock::time_point QPCClock::now() { + static LARGE_INTEGER freq; + // Use this dummy local static to ensure this gets initialized once. + static BOOL dummy = QueryPerformanceFrequency(&freq); + + LARGE_INTEGER ticks; + QueryPerformanceCounter(&ticks); + + // This is prone to overflow when multiplying, which is why I'm using micro instead of nano. The + // correct way to approach this would be to just return ticks as a time_point and then subtract + // and do this conversion when creating a duration from two time_points, however, as far as I + // could tell the C++ requirements for these types are incompatible with this approach. + return time_point(duration(ticks.QuadPart * std::micro::den / freq.QuadPart)); +} +#endif + TimingCategory::TimingCategory(const char* name, TimingCategory* parent) : accumulated_duration(0) { diff --git a/src/common/profiler.h b/src/common/profiler.h index 53c4f6eaf..3e967b4bc 100644 --- a/src/common/profiler.h +++ b/src/common/profiler.h @@ -18,8 +18,26 @@ namespace Profiling { #define ENABLE_PROFILING 1 #endif -using Duration = std::chrono::nanoseconds; +#if defined(_MSC_VER) && _MSC_VER <= 1800 // MSVC 2013 +// MSVC up to 2013 doesn't use QueryPerformanceCounter for high_resolution_clock, so it has bad +// precision. We manually implement a clock based on QPC to get good results. + +struct QPCClock { + using duration = std::chrono::microseconds; + using time_point = std::chrono::time_point; + using rep = duration::rep; + using period = duration::period; + static const bool is_steady = false; + + static time_point now(); +}; + +using Clock = QPCClock; +#else using Clock = std::chrono::high_resolution_clock; +#endif + +using Duration = Clock::duration; /** * Represents a timing category that measured time can be accounted towards. Should be declared as a -- cgit v1.2.3