From d168b8e533526026f680f79935462a85a160b2c1 Mon Sep 17 00:00:00 2001 From: Heinrich Date: Fri, 9 Aug 2019 17:53:47 +0200 Subject: [PATCH 1/4] trace-read: parse high-precision timestamp from drm_vblank_event When reading drm_vblank_event events, parse the following optional fields: - 'time': a possibly more accurate timestamp better representing the actual HW vblank timestamp - 'high_prec': true if 'time' is a high-precision HW timestamp from a drm driver with this particular capability Fields are only parsed if the ftrace clock was set to `mono`, otherwise the timestamps can't be aligned in a meaningful way. With ftrace, the tracing clock can be set to `mono like this: `echo mono > /sys/kernel/tracing/trace_clock` Also add helper functions to retrieve the high-precision timestamp. --- src/trace-cmd/trace-read.cpp | 28 ++++++++++++++++++++++++++++ src/trace-cmd/trace-read.h | 35 +++++++++++++++++++---------------- 2 files changed, 47 insertions(+), 16 deletions(-) diff --git a/src/trace-cmd/trace-read.cpp b/src/trace-cmd/trace-read.cpp index f90db6dc..2c5d61d1 100644 --- a/src/trace-cmd/trace-read.cpp +++ b/src/trace-cmd/trace-read.cpp @@ -1582,6 +1582,8 @@ class trace_data_t ftrace_function_str = strpool.getstr( "ftrace-function" ); drm_vblank_event_str = strpool.getstr( "drm_vblank_event" ); sched_switch_str = strpool.getstr( "sched_switch" ); + time_str = strpool.getstr( "time" ); + high_prec_str = strpool.getstr( "high_prec" ); } public: @@ -1600,6 +1602,8 @@ class trace_data_t const char *ftrace_function_str; const char *drm_vblank_event_str; const char *sched_switch_str; + const char *time_str; + const char *high_prec_str; }; static void init_event_flags( trace_data_t &trace_data, trace_event_t &event ) @@ -1734,6 +1738,30 @@ static int trace_enum_events( trace_data_t &trace_data, tracecmd_input_t *handle trace_event.crtc = val; } + else if ( trace_event.name == trace_data.drm_vblank_event_str && + format_name == trace_data.time_str && + !strcmp(handle->pevent->trace_clock, "mono")) + { + // for drm_vblank_event, if "time" field is available, + // and the trace-clock is monotonic, store the timestamp + // passed along with the vblank event + unsigned long long val = pevent_read_number( pevent, + ( char * )record->data + format->offset, format->size ); + + trace_event.vblank_ts = val - trace_data.trace_info.min_file_ts; + } + else if ( trace_event.name == trace_data.drm_vblank_event_str && + format_name == trace_data.high_prec_str && + !strcmp(handle->pevent->trace_clock, "mono")) + { + // for drm_vblank_event, if "high_prec" field is available, + // and the trace-lock is monotonic, store the field whether or not + // the passed timestamp is actually from a high-precision source + unsigned long long val = pevent_read_number( pevent, + ( char * )record->data + format->offset, format->size ); + + trace_event.vblank_ts_high_prec = val != 0; + } else if ( is_ftrace_function ) { bool is_ip = ( format_name == trace_data.ip_str ); diff --git a/src/trace-cmd/trace-read.h b/src/trace-cmd/trace-read.h index 7d3ffb17..b60161b0 100644 --- a/src/trace-cmd/trace-read.h +++ b/src/trace-cmd/trace-read.h @@ -177,16 +177,18 @@ struct trace_event_t public: bool is_filtered_out = false; - int pid; // event process id - uint32_t id; // event id - uint32_t cpu; // cpu this event was hit on - int64_t ts; // timestamp - - uint32_t flags = 0; // TRACE_FLAGS_IRQS_OFF, TRACE_FLAG_HARDIRQ, TRACE_FLAG_SOFTIRQ - uint32_t seqno = 0; // event seqno (from fields) - uint32_t id_start = INVALID_ID; // start event if this is a graph sequence event (ie amdgpu_sched_run_job, fence_signaled) + int pid; // event process id + uint32_t id; // event id + uint32_t cpu; // cpu this event was hit on + int64_t ts; // timestamp + + uint32_t flags = 0; // TRACE_FLAGS_IRQS_OFF, TRACE_FLAG_HARDIRQ, TRACE_FLAG_SOFTIRQ + uint32_t seqno = 0; // event seqno (from fields) + uint32_t id_start = INVALID_ID; // start event if this is a graph sequence event (ie amdgpu_sched_run_job, fence_signaled) uint32_t graph_row_id = 0; - int crtc = -1; // drm_vblank_event crtc (or -1) + int crtc = -1; // drm_vblank_event crtc (or -1) + int64_t vblank_ts = INT64_MAX; // time-stamp that is passed with the drm_event_vblank event + bool vblank_ts_high_prec = false; // denotes whether or not the hardware timestamp is high-precision uint32_t color = 0; // color of the event (or 0 for default) @@ -206,13 +208,14 @@ struct trace_event_t event_field_t *fields = nullptr; public: - bool is_fence_signaled() const { return !!( flags & TRACE_FLAG_FENCE_SIGNALED ); } - bool is_ftrace_print() const { return !!( flags & TRACE_FLAG_FTRACE_PRINT ); } - bool is_vblank() const { return !!( flags & TRACE_FLAG_VBLANK ); } - bool is_timeline() const { return !!( flags & TRACE_FLAG_TIMELINE ); } - bool is_sched_switch() const { return !!( flags & TRACE_FLAG_SCHED_SWITCH ); } - - bool has_duration() const { return duration != INT64_MAX; } + bool is_fence_signaled() const { return !!( flags & TRACE_FLAG_FENCE_SIGNALED ); } + bool is_ftrace_print() const { return !!( flags & TRACE_FLAG_FTRACE_PRINT ); } + bool is_vblank() const { return !!( flags & TRACE_FLAG_VBLANK ); } + bool is_timeline() const { return !!( flags & TRACE_FLAG_TIMELINE ); } + bool is_sched_switch() const { return !!( flags & TRACE_FLAG_SCHED_SWITCH ); } + + bool has_duration() const { return duration != INT64_MAX; } + int64_t get_vblank_ts(bool want_high_prec) const { return want_high_prec && (vblank_ts != INT64_MAX) && vblank_ts_high_prec ? vblank_ts : ts; } const char *get_timeline_name( const char *def = NULL ) const { From c0d1949dcb82cabe445410e7f3822e6d4b1d849c Mon Sep 17 00:00:00 2001 From: Heinrich Date: Fri, 9 Aug 2019 18:01:06 +0200 Subject: [PATCH 2/4] Opts: Add option to use high-prec vblank timestamps Disabled by default --- src/gpuvis.cpp | 3 +++ src/gpuvis.h | 1 + 2 files changed, 4 insertions(+) diff --git a/src/gpuvis.cpp b/src/gpuvis.cpp index 293b9e66..f75d3ddb 100644 --- a/src/gpuvis.cpp +++ b/src/gpuvis.cpp @@ -300,6 +300,9 @@ void Opts::init() init_opt_bool( i, desc.c_str(), inikey.c_str(), true ); } + + init_opt_bool( OPT_VBlankHighPrecTimestamps, "Use high-precision HW vblank timestamps (if available)", "vblank_high_prec_timestamps", false ); + init_opt_bool( OPT_RenderFrameMarkers, "Show render frame markers", "render_framemarkers", true ); // Set up action mappings so we can display hotkeys in render_imgui_opt(). diff --git a/src/gpuvis.h b/src/gpuvis.h index c3b4735d..799a342f 100644 --- a/src/gpuvis.h +++ b/src/gpuvis.h @@ -945,6 +945,7 @@ enum : uint32_t OPT_RenderCrtc7, OPT_RenderCrtc8, OPT_RenderCrtc9, + OPT_VBlankHighPrecTimestamps, OPT_RenderFrameMarkers, OPT_GraphHeight, OPT_GraphHeightZoomed, From 271a50c15218feed212fb1a7394b6f35c5b71587 Mon Sep 17 00:00:00 2001 From: Heinrich Date: Fri, 9 Aug 2019 18:02:39 +0200 Subject: [PATCH 3/4] opts: Use Ctrl-Shift-K to toggle high-prec vblank timestamps --- src/gpuvis.cpp | 3 +++ src/gpuvis_utils.cpp | 1 + src/gpuvis_utils.h | 1 + 3 files changed, 5 insertions(+) diff --git a/src/gpuvis.cpp b/src/gpuvis.cpp index f75d3ddb..d885566a 100644 --- a/src/gpuvis.cpp +++ b/src/gpuvis.cpp @@ -308,6 +308,7 @@ void Opts::init() // Set up action mappings so we can display hotkeys in render_imgui_opt(). m_options[ OPT_RenderCrtc0 ].action = action_toggle_vblank0; m_options[ OPT_RenderCrtc1 ].action = action_toggle_vblank1; + m_options[ OPT_VBlankHighPrecTimestamps].action = action_toggle_vblank_hardware_timestamps; m_options[ OPT_RenderFrameMarkers ].action = action_toggle_framemarkers; add_opt_graph_rowsize( "gfx", 8 ); @@ -4608,6 +4609,8 @@ void MainApp::handle_hotkeys() s_opts().setb( OPT_RenderCrtc0, !s_opts().getb( OPT_RenderCrtc0 ) ); if ( s_actions().get( action_toggle_vblank1 ) ) s_opts().setb( OPT_RenderCrtc1, !s_opts().getb( OPT_RenderCrtc1 ) ); + if ( s_actions().get( action_toggle_vblank_hardware_timestamps ) ) + s_opts().setb( OPT_VBlankHighPrecTimestamps, !s_opts().getb( OPT_VBlankHighPrecTimestamps ) ); if ( s_actions().get( action_toggle_framemarkers ) ) s_opts().setb( OPT_RenderFrameMarkers, !s_opts().getb( OPT_RenderFrameMarkers ) ); diff --git a/src/gpuvis_utils.cpp b/src/gpuvis_utils.cpp index dd7cda6e..7d90ed2d 100644 --- a/src/gpuvis_utils.cpp +++ b/src/gpuvis_utils.cpp @@ -1449,6 +1449,7 @@ void Actions::init() m_actionmap.push_back( { action_toggle_vblank0, KMOD_CTRL | KMOD_SHIFT, SDLK_m, "Graph: Toggle showing vblank 0 markers" } ); m_actionmap.push_back( { action_toggle_vblank1, KMOD_CTRL | KMOD_SHIFT, SDLK_n, "Graph: Toggle showing vblank 1 markers" } ); + m_actionmap.push_back( { action_toggle_vblank_hardware_timestamps, KMOD_CTRL | KMOD_SHIFT, SDLK_k, "Graph: Toggle showing hardware vblank timestamps" } ); m_actionmap.push_back( { action_toggle_framemarkers, KMOD_CTRL | KMOD_SHIFT, SDLK_f, "Graph: Toggle showing Frame Markers" } ); m_actionmap.push_back( { action_toggle_frame_filters, KMOD_CTRL | KMOD_SHIFT, SDLK_r, "Graph: Toggle Frame Filters" } ); diff --git a/src/gpuvis_utils.h b/src/gpuvis_utils.h index 33bc0c99..af5b29a6 100644 --- a/src/gpuvis_utils.h +++ b/src/gpuvis_utils.h @@ -415,6 +415,7 @@ enum action_t action_toggle_vblank0, action_toggle_vblank1, + action_toggle_vblank_hardware_timestamps, action_toggle_framemarkers, action_toggle_frame_filters, From 1a9eb5df6303ee44f7290c23305b963c12f8aff6 Mon Sep 17 00:00:00 2001 From: Heinrich Date: Fri, 9 Aug 2019 18:03:31 +0200 Subject: [PATCH 4/4] vblanks: use high-prec timestamps if available and toggled --- src/gpuvis.cpp | 6 +++--- src/gpuvis_graph.cpp | 14 +++++++------- 2 files changed, 10 insertions(+), 10 deletions(-) diff --git a/src/gpuvis.cpp b/src/gpuvis.cpp index d885566a..1c06c63a 100644 --- a/src/gpuvis.cpp +++ b/src/gpuvis.cpp @@ -1941,7 +1941,7 @@ void TraceEvents::init_new_event_vblank( trace_event_t &event ) trace_event_t &event_vblank_queued = m_events[ *vblank_queued_id ]; // If so, set the vblank queued time - event_vblank_queued.duration = event.ts - event_vblank_queued.ts; + event_vblank_queued.duration = event.get_vblank_ts( s_opts().getb( OPT_VBlankHighPrecTimestamps ) ) - event_vblank_queued.ts; } m_tdopexpr_locs.add_location_str( "$name=drm_vblank_event", event.id ); @@ -1951,7 +1951,7 @@ void TraceEvents::init_new_event_vblank( trace_event_t &event ) */ if ( m_vblank_info[ event.crtc ].last_vblank_ts ) { - int64_t diff = event.ts - m_vblank_info[ event.crtc ].last_vblank_ts; + int64_t diff = event.get_vblank_ts( s_opts().getb( OPT_VBlankHighPrecTimestamps ) ) - m_vblank_info[ event.crtc ].last_vblank_ts; // Normalize ts diff to known frequencies diff = normalize_vblank_diff( diff ); @@ -1961,7 +1961,7 @@ void TraceEvents::init_new_event_vblank( trace_event_t &event ) m_vblank_info[ event.crtc ].count++; } - m_vblank_info[ event.crtc ].last_vblank_ts = event.ts; + m_vblank_info[ event.crtc ].last_vblank_ts = event.get_vblank_ts( s_opts().getb( OPT_VBlankHighPrecTimestamps ) ); } // new_event_cb adds all events to array, this function initializes them. diff --git a/src/gpuvis_graph.cpp b/src/gpuvis_graph.cpp index ac3758b9..6561b608 100644 --- a/src/gpuvis_graph.cpp +++ b/src/gpuvis_graph.cpp @@ -2548,7 +2548,7 @@ static float get_vblank_xdiffs( TraceWin &win, graph_info_t &gi, const std::vect if ( s_opts().getcrtc( event.crtc ) ) { - float x = gi.ts_to_screenx( event.ts ); + float x = gi.ts_to_screenx( event.get_vblank_ts( s_opts().getb( OPT_VBlankHighPrecTimestamps ) ) ); if ( xlast ) xdiff = std::max< float >( xdiff, x - xlast ); @@ -2595,7 +2595,7 @@ void TraceWin::graph_render_vblanks( graph_info_t &gi ) { // Handle drm_vblank_event0 .. drm_vblank_event2 uint32_t col = Clamp< uint32_t >( col_VBlank0 + event.crtc, col_VBlank0, col_VBlank2 ); - float x = gi.ts_to_screenx( event.ts ); + float x = gi.ts_to_screenx( event.get_vblank_ts( s_opts().getb( OPT_VBlankHighPrecTimestamps ) ) ); imgui_drawrect_filled( x, gi.rc.y, imgui_scale( 1.0f ), gi.rc.h, s_clrs().get( col, alpha ) ); @@ -4077,13 +4077,13 @@ void TraceWin::graph_mouse_tooltip_vblanks( std::string &ttip, graph_info_t &gi, { if ( event.ts < mouse_ts ) { - if ( mouse_ts - event.ts < prev_vblank_ts ) - prev_vblank_ts = mouse_ts - event.ts; + if ( mouse_ts - event.get_vblank_ts( s_opts().getb( OPT_VBlankHighPrecTimestamps ) ) < prev_vblank_ts ) + prev_vblank_ts = mouse_ts - event.get_vblank_ts( s_opts().getb( OPT_VBlankHighPrecTimestamps ) ); } - if ( event.ts > mouse_ts ) + if ( event.get_vblank_ts( s_opts().getb( OPT_VBlankHighPrecTimestamps ) ) > mouse_ts ) { - if ( event.ts - mouse_ts < next_vblank_ts ) - next_vblank_ts = event.ts - mouse_ts; + if ( event.get_vblank_ts( s_opts().getb( OPT_VBlankHighPrecTimestamps ) ) - mouse_ts < next_vblank_ts ) + next_vblank_ts = event.get_vblank_ts( s_opts().getb( OPT_VBlankHighPrecTimestamps ) ) - mouse_ts; } } }