From b1c9430229f92b46bc91aa8fca5486a54c3be24c Mon Sep 17 00:00:00 2001 From: Heinrich Date: Fri, 9 Aug 2019 17:53:47 +0200 Subject: [PATCH] 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 9be6754e..1cb43722 100644 --- a/src/trace-cmd/trace-read.cpp +++ b/src/trace-cmd/trace-read.cpp @@ -1575,6 +1575,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: @@ -1593,6 +1595,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 ) @@ -1727,6 +1731,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 a07a3780..3f6cdeb6 100644 --- a/src/trace-cmd/trace-read.h +++ b/src/trace-cmd/trace-read.h @@ -178,16 +178,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) @@ -207,13 +209,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 {