On Tuesday 23 November 2010, Simon Farnsworth <[email protected]>
wrote:
> So, I looked at this a bit; started by using:
> ./perf record -e sched:sched_wakeup -e sched:sched_switch -e
> i915:i915_flip_request -e i915:i915_flip_complete -e
> i915:i915_gem_request_wait_begin -a
>
> to record traces, and viewed them with perf trace, to check that I was on
> the right sort of track. I then tried perf timechart, just to see what the
> output looks like, but found that 8GB RAM and 10GB swap isn't enough space
> for Inkspace, Google Chrome or Firefox to examine the resulting SVG.
>
> I'm therefore just using perf trace to look at deadline misses; the record
> command above gives you enough data to see who's pushed you off the CPU and
> thus determine why you couldn't make your deadline, albeit not nicely
> presented.
>
And I've just found the perf trace hooks to let a python script help print
traces - I knew the kernel guys were normally a few steps ahead of me. Run the
attached script via:
perf trace -s /path/to/i915-crisis.py
It changes the printed timings to be relative to the most recent flip_complete;
you can thus see what's running when within your crisis period, and how close
you get to running out of time. Using it, I've seen that I'm taking 10-12
milliseconds to draw after a flip, and thus usually only seeing 30 frames a
second on a 60Hz refresh display.
--
Simon Farnsworth
Software Engineer
ONELAN Limited
http://www.onelan.com/
# perf trace event handlers, generated by perf trace -g python
# Licensed under the terms of the GNU GPL License version 2
# The common_* event handler fields are the most useful fields common to
# all events. They don't necessarily correspond to the 'common_*' fields
# in the format files. Those fields not available as handler params can
# be retrieved using Python functions of the form common_*(context).
# See the perf-trace-python Documentation for the list of available functions.
import os
import sys
sys.path.append(os.environ['PERF_EXEC_PATH'] + \
'/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
from perf_trace_context import *
from Core import *
last_flip_complete = None
def trace_begin():
global last_flip_complete
last_flip_complete = None
print "in trace_begin"
def trace_end():
print "in trace_end"
def sched__sched_switch(event_name, context, common_cpu,
common_secs, common_nsecs, common_pid, common_comm,
prev_comm, prev_pid, prev_prio, prev_state,
next_comm, next_pid, next_prio):
print_header(event_name, common_cpu, common_secs, common_nsecs,
common_pid, common_comm)
print "prev_comm=%s, prev_pid=%d, prev_prio=%d, " \
"prev_state=%s, next_comm=%s, next_pid=%d, " \
"next_prio=%d\n" % \
(prev_comm, prev_pid, prev_prio,
flag_str("sched__sched_switch", "prev_state", prev_state),
next_comm, next_pid, next_prio),
def sched__sched_wakeup(event_name, context, common_cpu,
common_secs, common_nsecs, common_pid, common_comm,
comm, pid, prio, success,
target_cpu):
print_header(event_name, common_cpu, common_secs, common_nsecs,
common_pid, common_comm)
print "comm=%s, pid=%d, prio=%d, " \
"success=%d, target_cpu=%d\n" % \
(comm, pid, prio, success,
target_cpu),
def i915__i915_flip_complete(event_name, context, common_cpu,
common_secs, common_nsecs, common_pid, common_comm,
plane, obj):
print_header(event_name, common_cpu, common_secs, common_nsecs,
common_pid, common_comm, flip=True)
print "plane=%d, obj=%u\n" % \
(plane, obj),
def i915__i915_flip_request(event_name, context, common_cpu,
common_secs, common_nsecs, common_pid, common_comm,
plane, obj):
print_header(event_name, common_cpu, common_secs, common_nsecs,
common_pid, common_comm)
print "plane=%d, obj=%u\n" % \
(plane, obj),
def i915__i915_gem_request_wait_begin(event_name, context, common_cpu,
common_secs, common_nsecs, common_pid, common_comm,
dev, seqno):
print_header(event_name, common_cpu, common_secs, common_nsecs,
common_pid, common_comm)
print "dev=%u, seqno=%u\n" % \
(dev, seqno),
def trace_unhandled(event_name, context, event_fields_dict):
print ' '.join(['%s=%s'%(k,str(v))for k,v in sorted(event_fields_dict.items())])
def print_header(event_name, cpu, secs, nsecs, pid, comm, flip=False):
global last_flip_complete
if last_flip_complete is None:
offset_secs = secs
offset_nsecs = nsecs
else:
offset_secs = secs - last_flip_complete[0]
offset_nsecs = nsecs - last_flip_complete[1]
if flip:
last_flip_complete = (secs, nsecs,)
print "%-20s %5u %05u.%09u %8u %-20s " % \
(event_name, cpu, offset_secs, offset_nsecs, pid, comm),
_______________________________________________
Intel-gfx mailing list
[email protected]
http://lists.freedesktop.org/mailman/listinfo/intel-gfx
