From a871eabcedffb4f817033b393e25ce373d977b1a Mon Sep 17 00:00:00 2001 From: Russell Greene Date: Tue, 22 Oct 2024 00:37:23 -0600 Subject: [PATCH] wsi/wayland/perfetto: supply presentation clock to perfetto Perfetto is allowed to choose it's own default clock, and before this we just assumed the presentation times reported by the compositor are the same as perfetto's internal clock, which is not always the case. I got a nasty trace where all the wayland presents were in the wrong location. This fixes that by asking the compositor which clock it uses, then passing that along to perfetto. A workaround for my compositor was setting use_monotonic_clock=true in the perfetto config, as my compositor (and I suspect most others) use the monotonic clock for presentation timestamps. However, asking the compositor is definitely the most correct solution. I added a clock param to `MESA_TRACE_TIMESTAMP_{BEGIN,END}`, as it's only use that I could see was in wsi_common_wayland, and in general it seems good to be careful about which clock tracing timestamps come from. Part-of: --- src/util/perf/cpu_trace.h | 32 ++++++++++++++--------------- src/util/perf/u_perfetto.cc | 30 +++++++++++++++++++++++---- src/util/perf/u_perfetto.h | 17 +++++++++++---- src/vulkan/wsi/wsi_common_wayland.c | 20 ++++++++++++++++-- 4 files changed, 73 insertions(+), 26 deletions(-) diff --git a/src/util/perf/cpu_trace.h b/src/util/perf/cpu_trace.h index b72218d55a5..c495dd5295a 100644 --- a/src/util/perf/cpu_trace.h +++ b/src/util/perf/cpu_trace.h @@ -41,16 +41,16 @@ util_perfetto_counter_set(name, value); \ } while (0) -#define _MESA_TRACE_TIMESTAMP_BEGIN(name, track_id, flow_id, timestamp) \ - do { \ - if (unlikely(util_perfetto_is_tracing_enabled())) \ - util_perfetto_trace_full_begin(name, track_id, flow_id, timestamp); \ +#define _MESA_TRACE_TIMESTAMP_BEGIN(name, track_id, flow_id, clock, timestamp) \ + do { \ + if (unlikely(util_perfetto_is_tracing_enabled())) \ + util_perfetto_trace_full_begin(name, track_id, flow_id, clock, timestamp); \ } while (0) -#define _MESA_TRACE_TIMESTAMP_END(name, track_id, timestamp) \ - do { \ - if (unlikely(util_perfetto_is_tracing_enabled())) \ - util_perfetto_trace_full_end(name, track_id, timestamp); \ +#define _MESA_TRACE_TIMESTAMP_END(name, track_id, clock, timestamp) \ + do { \ + if (unlikely(util_perfetto_is_tracing_enabled())) \ + util_perfetto_trace_full_end(name, track_id, clock, timestamp); \ } while (0) /* NOTE: for now disable atrace for C++ to workaround a ndk bug with ordering @@ -68,16 +68,16 @@ #define _MESA_TRACE_FLOW_BEGIN(name, id) \ atrace_begin(ATRACE_TAG_GRAPHICS, name) #define _MESA_TRACE_SET_COUNTER(name, value) -#define _MESA_TRACE_TIMESTAMP_BEGIN(name, track_id, flow_id, timestamp) -#define _MESA_TRACE_TIMESTAMP_END(name, track_id, timestamp) +#define _MESA_TRACE_TIMESTAMP_BEGIN(name, track_id, flow_id, clock, timestamp) +#define _MESA_TRACE_TIMESTAMP_END(name, track_id, clock, timestamp) #else #define _MESA_TRACE_BEGIN(name) #define _MESA_TRACE_END() #define _MESA_TRACE_FLOW_BEGIN(name, id) #define _MESA_TRACE_SET_COUNTER(name, value) -#define _MESA_TRACE_TIMESTAMP_BEGIN(name, track_id, flow_id, timestamp) -#define _MESA_TRACE_TIMESTAMP_END(name, track_id, timestamp) +#define _MESA_TRACE_TIMESTAMP_BEGIN(name, track_id, flow_id, clock, timestamp) +#define _MESA_TRACE_TIMESTAMP_END(name, track_id, clock, timestamp) #endif /* HAVE_PERFETTO */ @@ -152,10 +152,10 @@ _mesa_trace_scope_end(UNUSED int *scope) #define MESA_TRACE_FUNC() _MESA_TRACE_SCOPE(__func__) #define MESA_TRACE_FUNC_FLOW(id) _MESA_TRACE_SCOPE_FLOW(__func__, id) #define MESA_TRACE_SET_COUNTER(name, value) _MESA_TRACE_SET_COUNTER(name, value) -#define MESA_TRACE_TIMESTAMP_BEGIN(name, track_id, flow_id, timestamp) \ - _MESA_TRACE_TIMESTAMP_BEGIN(name, track_id, flow_id, timestamp) -#define MESA_TRACE_TIMESTAMP_END(name, track_id, timestamp) \ - _MESA_TRACE_TIMESTAMP_END(name, track_id, timestamp) +#define MESA_TRACE_TIMESTAMP_BEGIN(name, track_id, flow_id, clock, timestamp) \ + _MESA_TRACE_TIMESTAMP_BEGIN(name, track_id, flow_id, clock, timestamp) +#define MESA_TRACE_TIMESTAMP_END(name, track_id, clock, timestamp) \ + _MESA_TRACE_TIMESTAMP_END(name, track_id, clock, timestamp) static inline void util_cpu_trace_init() diff --git a/src/util/perf/u_perfetto.cc b/src/util/perf/u_perfetto.cc index 7cb4a923201..5b91011ff26 100644 --- a/src/util/perf/u_perfetto.cc +++ b/src/util/perf/u_perfetto.cc @@ -41,6 +41,24 @@ int util_perfetto_tracing_state; static uint64_t util_perfetto_unique_id = 1; +static uint32_t +clockid_to_perfetto_clock(UNUSED perfetto_clock_id clock) +{ +#ifndef _WIN32 + switch (clock) { + case CLOCK_REALTIME: return perfetto::protos::pbzero::BUILTIN_CLOCK_REALTIME; + case CLOCK_REALTIME_COARSE: return perfetto::protos::pbzero::BUILTIN_CLOCK_REALTIME_COARSE; + case CLOCK_MONOTONIC: return perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC; + case CLOCK_MONOTONIC_COARSE: return perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC_COARSE; + case CLOCK_MONOTONIC_RAW: return perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC_RAW; + case CLOCK_BOOTTIME: return perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME; + } + return perfetto::protos::pbzero::BUILTIN_CLOCK_UNKNOWN; +#else + return perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC; // perfetto always uses QueryPerformanceCounter & marks this as CLOCK_MONOTONIC on Windows +#endif +} + static void util_perfetto_update_tracing_state(void) { @@ -73,11 +91,12 @@ util_perfetto_trace_begin_flow(const char *fname, uint64_t id) } void -util_perfetto_trace_full_begin(const char *fname, uint64_t track_id, uint64_t id, uint64_t timestamp) +util_perfetto_trace_full_begin(const char *fname, uint64_t track_id, uint64_t id, perfetto_clock_id clock, uint64_t timestamp) { TRACE_EVENT_BEGIN( UTIL_PERFETTO_CATEGORY_DEFAULT_STR, nullptr, perfetto::Track(track_id), - timestamp, perfetto::Flow::ProcessScoped(id), + perfetto::TraceTimestamp{clockid_to_perfetto_clock(clock), timestamp}, + perfetto::Flow::ProcessScoped(id), [&](perfetto::EventContext ctx) { ctx.event()->set_name(fname); }); } @@ -93,9 +112,12 @@ util_perfetto_new_track(const char *name) } void -util_perfetto_trace_full_end(const char *name, uint64_t track_id, uint64_t timestamp) +util_perfetto_trace_full_end(const char *name, uint64_t track_id, perfetto_clock_id clock, uint64_t timestamp) { - TRACE_EVENT_END(UTIL_PERFETTO_CATEGORY_DEFAULT_STR, perfetto::Track(track_id), timestamp); + TRACE_EVENT_END( + UTIL_PERFETTO_CATEGORY_DEFAULT_STR, + perfetto::Track(track_id), + perfetto::TraceTimestamp{clockid_to_perfetto_clock(clock), timestamp}); util_perfetto_update_tracing_state(); } diff --git a/src/util/perf/u_perfetto.h b/src/util/perf/u_perfetto.h index 25db962c864..5d8d8e4f3b6 100644 --- a/src/util/perf/u_perfetto.h +++ b/src/util/perf/u_perfetto.h @@ -26,6 +26,15 @@ #include "util/u_atomic.h" +// On Unix, pass a clockid_t to designate which clock was used to gather the timestamp +// On Windows, this paramter is ignored, and it's expected that `timestamp` comes from QueryPerformanceCounter +#ifndef _WIN32 +#include +typedef clockid_t perfetto_clock_id; +#else +typedef int32_t perfetto_clock_id; +#endif + #ifdef __cplusplus extern "C" { #endif @@ -50,9 +59,9 @@ void util_perfetto_trace_begin_flow(const char *fname, uint64_t id); void util_perfetto_counter_set(const char *name, double value); -void util_perfetto_trace_full_begin(const char *name, uint64_t track_id, uint64_t id, uint64_t timestamp); +void util_perfetto_trace_full_begin(const char *name, uint64_t track_id, uint64_t id, perfetto_clock_id clock, uint64_t timestamp); -void util_perfetto_trace_full_end(const char *name, uint64_t track_id, uint64_t timestamp); +void util_perfetto_trace_full_end(const char *name, uint64_t track_id, perfetto_clock_id clock, uint64_t timestamp); uint64_t util_perfetto_next_id(void); @@ -86,12 +95,12 @@ static inline void util_perfetto_trace_begin_flow(const char *fname, uint64_t id } static inline void -util_perfetto_trace_full_begin(const char *name, uint64_t track_id, uint64_t id, uint64_t timestamp) +util_perfetto_trace_full_begin(const char *name, uint64_t track_id, uint64_t id, perfetto_clock_id clock, uint64_t timestamp) { } static inline void -util_perfetto_trace_full_end(const char *name, uint64_t track_id) +util_perfetto_trace_full_end(const char *name, uint64_t track_id, perfetto_clock_id clock, uint64_t timestamp) { } diff --git a/src/vulkan/wsi/wsi_common_wayland.c b/src/vulkan/wsi/wsi_common_wayland.c index fc208057298..453746c8156 100644 --- a/src/vulkan/wsi/wsi_common_wayland.c +++ b/src/vulkan/wsi/wsi_common_wayland.c @@ -122,6 +122,8 @@ struct wsi_wl_display { dev_t main_device; bool same_gpu; + + clockid_t presentation_clock_id; }; struct wsi_wayland { @@ -814,6 +816,18 @@ static const struct wl_shm_listener shm_listener = { .format = shm_handle_format }; +static void +presentation_handle_clock_id(void* data, struct wp_presentation *wp_presentation, uint32_t clk_id) +{ + struct wsi_wl_display *display = data; + + display->presentation_clock_id = clk_id; +} + +static const struct wp_presentation_listener presentation_listener = { + presentation_handle_clock_id, +}; + static void registry_handle_global(void *data, struct wl_registry *registry, uint32_t name, const char *interface, uint32_t version) @@ -841,6 +855,7 @@ registry_handle_global(void *data, struct wl_registry *registry, if (strcmp(interface, wp_presentation_interface.name) == 0) { display->wp_presentation_notwrapped = wl_registry_bind(registry, name, &wp_presentation_interface, 1); + wp_presentation_add_listener(display->wp_presentation_notwrapped, &presentation_listener, display); } else if (strcmp(interface, wp_tearing_control_manager_v1_interface.name) == 0) { display->tearing_control_manager = wl_registry_bind(registry, name, &wp_tearing_control_manager_v1_interface, 1); @@ -893,6 +908,7 @@ wsi_wl_display_init(struct wsi_wayland *wsi_wl, if (!u_vector_init(&display->formats, 8, sizeof(struct wsi_wl_format))) return VK_ERROR_OUT_OF_HOST_MEMORY; + display->presentation_clock_id = -1; // 0 is a valid clock ID display->wsi_wl = wsi_wl; display->wl_display = wl_display; display->sw = sw; @@ -1998,7 +2014,7 @@ trace_present(const struct wsi_wl_present_id *id, buffer_name = stringify_wayland_id(surface->analytics.presenting); MESA_TRACE_TIMESTAMP_END(buffer_name ? buffer_name : "Wayland buffer", surface->analytics.presentation_track_id, - presentation_time); + chain->wsi_wl_surface->display->presentation_clock_id, presentation_time); free(buffer_name); } @@ -2009,7 +2025,7 @@ trace_present(const struct wsi_wl_present_id *id, MESA_TRACE_TIMESTAMP_BEGIN(buffer_name ? buffer_name : "Wayland buffer", surface->analytics.presentation_track_id, id->flow_id, - presentation_time); + chain->wsi_wl_surface->display->presentation_clock_id, presentation_time); free(buffer_name); } }