Skip to content

Commit

Permalink
trace-read: parse high-precision timestamp from drm_vblank_event
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
Heinrich authored and mikesart committed Sep 24, 2019
1 parent 76c688d commit b1c9430
Show file tree
Hide file tree
Showing 2 changed files with 47 additions and 16 deletions.
28 changes: 28 additions & 0 deletions src/trace-cmd/trace-read.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand All @@ -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 )
Expand Down Expand Up @@ -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 );
Expand Down
35 changes: 19 additions & 16 deletions src/trace-cmd/trace-read.h
Original file line number Diff line number Diff line change
Expand Up @@ -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)

Expand All @@ -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
{
Expand Down

0 comments on commit b1c9430

Please sign in to comment.