perf: Print a summary of each operation for a trace (using '-s')

In order for this to be effective on small system we also need to
disable the recording of the long traces which exhaust all memory...

Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
This commit is contained in:
Chris Wilson 2011-08-25 18:43:02 +01:00
parent 7ae2708fc8
commit 6b1daace57
4 changed files with 273 additions and 84 deletions

View file

@ -473,7 +473,9 @@ cairo_perf_trace (cairo_perf_t *perf,
CAIRO_BOILERPLATE_MODE_PERF,
0,
&args.closure);
args.surface = cairo_surface_create_observer (real);
args.surface =
cairo_surface_create_observer (real,
CAIRO_SURFACE_OBSERVER_RECORD_OPERATIONS);
cairo_surface_destroy (real);
if (cairo_surface_status (args.surface)) {
fprintf (stderr,

View file

@ -594,7 +594,7 @@ cairo_perf_trace (cairo_perf_t *perf,
{
static cairo_bool_t first_run = TRUE;
unsigned int i;
cairo_perf_ticks_t *times;
cairo_perf_ticks_t *times, *paint, *mask, *fill, *stroke, *glyphs;
cairo_stats_t stats = {0.0, 0.0};
struct trace args = { target };
int low_std_dev_count;
@ -627,15 +627,28 @@ cairo_perf_trace (cairo_perf_t *perf,
}
if (perf->summary) {
fprintf (perf->summary,
"[ # ] %8s %28s %8s %5s %5s %s\n",
"backend", "test", "min(s)", "median(s)",
"stddev.", "count");
if (perf->observe) {
fprintf (perf->summary,
"[ # ] %8s %28s %9s %9s %9s %9s %9s %9s %5s\n",
"backend", "test",
"total(s)", "paint(s)", "mask(s)", "fill(s)", "stroke(s)", "glyphs(s)",
"count");
} else {
fprintf (perf->summary,
"[ # ] %8s %28s %8s %5s %5s %s\n",
"backend", "test", "min(s)", "median(s)",
"stddev.", "count");
}
}
first_run = FALSE;
}
times = perf->times;
paint = times + perf->iterations;
mask = paint + perf->iterations;
stroke = mask + perf->iterations;
fill = stroke + perf->iterations;
glyphs = fill + perf->iterations;
low_std_dev_count = 0;
for (i = 0; i < perf->iterations && ! user_interrupt; i++) {
@ -652,7 +665,8 @@ cairo_perf_trace (cairo_perf_t *perf,
&args.closure);
if (perf->observe) {
cairo_surface_t *obs;
obs = cairo_surface_create_observer (args.surface);
obs = cairo_surface_create_observer (args.surface,
CAIRO_SURFACE_OBSERVER_NORMAL);
cairo_surface_destroy (args.surface);
args.surface = obs;
}
@ -677,7 +691,6 @@ cairo_perf_trace (cairo_perf_t *perf,
}
}
csi = cairo_script_interpreter_create ();
cairo_script_interpreter_install_hooks (csi, &hooks);
@ -689,7 +702,13 @@ cairo_perf_trace (cairo_perf_t *perf,
cairo_script_interpreter_run (csi, trace);
if (perf->observe) {
times[i] = cairo_device_observer_elapsed (cairo_surface_get_device (args.surface)) * (1e-9 * cairo_perf_ticks_per_second ());
cairo_device_t *observer = cairo_surface_get_device (args.surface);
times[i] = cairo_device_observer_elapsed (observer) * (1e-9 * cairo_perf_ticks_per_second ());
paint[i] = cairo_device_observer_paint_elapsed (observer) * (1e-9 * cairo_perf_ticks_per_second ());
mask[i] = cairo_device_observer_mask_elapsed (observer) * (1e-9 * cairo_perf_ticks_per_second ());
stroke[i] = cairo_device_observer_stroke_elapsed (observer) * (1e-9 * cairo_perf_ticks_per_second ());
fill[i] = cairo_device_observer_fill_elapsed (observer) * (1e-9 * cairo_perf_ticks_per_second ());
glyphs[i] = cairo_device_observer_glyphs_elapsed (observer) * (1e-9 * cairo_perf_ticks_per_second ());
} else {
clear_surface (args.surface); /* queue a write to the sync'ed surface */
cairo_perf_timer_stop ();
@ -747,12 +766,40 @@ cairo_perf_trace (cairo_perf_t *perf,
perf->test_number,
perf->target->name,
name);
fprintf (perf->summary,
"%#8.3f %#8.3f %#6.2f%% %4d/%d",
(double) stats.min_ticks / cairo_perf_ticks_per_second (),
(double) stats.median_ticks / cairo_perf_ticks_per_second (),
stats.std_dev * 100.0,
stats.iterations, i+1);
if (perf->observe) {
fprintf (perf->summary,
" %#9.3f", (double) stats.median_ticks / cairo_perf_ticks_per_second ());
_cairo_stats_compute (&stats, paint, i+1);
fprintf (perf->summary,
" %#9.3f", (double) stats.median_ticks / cairo_perf_ticks_per_second ());
_cairo_stats_compute (&stats, mask, i+1);
fprintf (perf->summary,
" %#9.3f", (double) stats.median_ticks / cairo_perf_ticks_per_second ());
_cairo_stats_compute (&stats, fill, i+1);
fprintf (perf->summary,
" %#9.3f", (double) stats.median_ticks / cairo_perf_ticks_per_second ());
_cairo_stats_compute (&stats, stroke, i+1);
fprintf (perf->summary,
" %#9.3f", (double) stats.median_ticks / cairo_perf_ticks_per_second ());
_cairo_stats_compute (&stats, glyphs, i+1);
fprintf (perf->summary,
" %#9.3f", (double) stats.median_ticks / cairo_perf_ticks_per_second ());
fprintf (perf->summary,
" %5d", i+1);
} else {
fprintf (perf->summary,
"%#8.3f %#8.3f %#6.2f%% %4d/%d",
(double) stats.min_ticks / cairo_perf_ticks_per_second (),
(double) stats.median_ticks / cairo_perf_ticks_per_second (),
stats.std_dev * 100.0,
stats.iterations, i+1);
}
fflush (perf->summary);
}
}
@ -767,12 +814,40 @@ cairo_perf_trace (cairo_perf_t *perf,
perf->target->name,
name);
}
fprintf (perf->summary,
"%#8.3f %#8.3f %#6.2f%% %4d/%d\n",
(double) stats.min_ticks / cairo_perf_ticks_per_second (),
(double) stats.median_ticks / cairo_perf_ticks_per_second (),
stats.std_dev * 100.0,
stats.iterations, i);
if (perf->observe) {
fprintf (perf->summary,
" %#9.3f", (double) stats.median_ticks / cairo_perf_ticks_per_second ());
_cairo_stats_compute (&stats, paint, i+1);
fprintf (perf->summary,
" %#9.3f", (double) stats.median_ticks / cairo_perf_ticks_per_second ());
_cairo_stats_compute (&stats, mask, i+1);
fprintf (perf->summary,
" %#9.3f", (double) stats.median_ticks / cairo_perf_ticks_per_second ());
_cairo_stats_compute (&stats, fill, i+1);
fprintf (perf->summary,
" %#9.3f", (double) stats.median_ticks / cairo_perf_ticks_per_second ());
_cairo_stats_compute (&stats, stroke, i+1);
fprintf (perf->summary,
" %#9.3f", (double) stats.median_ticks / cairo_perf_ticks_per_second ());
_cairo_stats_compute (&stats, glyphs, i+1);
fprintf (perf->summary,
" %#9.3f", (double) stats.median_ticks / cairo_perf_ticks_per_second ());
fprintf (perf->summary,
" %5d\n", i+1);
} else {
fprintf (perf->summary,
"%#8.3f %#8.3f %#6.2f%% %4d/%d\n",
(double) stats.min_ticks / cairo_perf_ticks_per_second (),
(double) stats.median_ticks / cairo_perf_ticks_per_second (),
stats.std_dev * 100.0,
stats.iterations, i);
}
fflush (perf->summary);
}
@ -877,7 +952,7 @@ main (int argc,
trace_dir = getenv ("CAIRO_TRACE_DIR");
perf.targets = cairo_boilerplate_get_targets (&perf.num_targets, NULL);
perf.times = xmalloc (perf.iterations * sizeof (cairo_perf_ticks_t));
perf.times = xmalloc (6 * perf.iterations * sizeof (cairo_perf_ticks_t));
/* do we have a list of filenames? */
perf.exact_names = have_trace_filenames (&perf);

View file

@ -114,7 +114,8 @@ static void init_glyphs (struct glyphs *g)
}
static cairo_status_t
log_init (cairo_observation_t *log)
log_init (cairo_observation_t *log,
cairo_bool_t record)
{
memset (log, 0, sizeof(*log));
@ -126,12 +127,14 @@ log_init (cairo_observation_t *log)
_cairo_array_init (&log->timings, sizeof (cairo_observation_record_t));
log->record = (cairo_recording_surface_t *)
if (record) {
log->record = (cairo_recording_surface_t *)
cairo_recording_surface_create (CAIRO_CONTENT_COLOR_ALPHA, NULL);
if (unlikely (log->record->base.status))
return log->record->base.status;
if (unlikely (log->record->base.status))
return log->record->base.status;
log->record->optimize_clears = FALSE;
log->record->optimize_clears = FALSE;
}
return CAIRO_STATUS_SUCCESS;
}
@ -326,7 +329,8 @@ static const cairo_device_backend_t _cairo_device_observer_backend = {
};
static cairo_device_t *
_cairo_device_create_observer_internal (cairo_device_t *target)
_cairo_device_create_observer_internal (cairo_device_t *target,
cairo_bool_t record)
{
cairo_device_observer_t *device;
cairo_status_t status;
@ -336,7 +340,7 @@ _cairo_device_create_observer_internal (cairo_device_t *target)
return _cairo_device_create_in_error (_cairo_error (CAIRO_STATUS_NO_MEMORY));
_cairo_device_init (&device->base, &_cairo_device_observer_backend);
status = log_init (&device->log);
status = log_init (&device->log, record);
if (unlikely (status)) {
free (device);
return _cairo_device_create_in_error (status);
@ -370,7 +374,8 @@ _cairo_surface_create_observer_internal (cairo_device_t *device,
&_cairo_surface_observer_backend, device,
target->content);
status = log_init (&surface->log);
status = log_init (&surface->log,
((cairo_device_observer_t *)device)->log.record != NULL);
if (unlikely (status)) {
free (surface);
return _cairo_surface_create_in_error (status);
@ -612,12 +617,11 @@ record_glyphs (cairo_observation_record_t *r,
static void
add_record (cairo_observation_t *log,
cairo_observation_record_t *r,
unsigned long index)
cairo_observation_record_t *r)
{
cairo_int_status_t status;
r->index = index;
r->index = log->record ? log->record->commands.num_elements : 0;
status = _cairo_array_append (&log->timings, r);
assert (status == CAIRO_INT_STATUS_SUCCESS);
@ -676,17 +680,17 @@ add_record_paint (cairo_observation_t *log,
cairo_int_status_t status;
add_record (log,
record_paint (&record, target, op, source, clip, elapsed),
log->record->commands.num_elements);
record_paint (&record, target, op, source, clip, elapsed));
/* We have to bypass the high-level surface layer in case it tries to be
* too smart and discard operations; we need to record exactly what just
* happened on the target.
*/
status = log->record->base.backend->paint (&log->record->base,
op, source, clip);
assert (status == CAIRO_INT_STATUS_SUCCESS);
assert (log->record->commands.num_elements == record.index + 1);
if (log->record) {
status = log->record->base.backend->paint (&log->record->base,
op, source, clip);
assert (status == CAIRO_INT_STATUS_SUCCESS);
}
if (elapsed > log->paint.slowest.elapsed)
log->paint.slowest = record;
@ -766,12 +770,13 @@ add_record_mask (cairo_observation_t *log,
cairo_int_status_t status;
add_record (log,
record_mask (&record, target, op, source, mask, clip, elapsed),
log->record->commands.num_elements);
record_mask (&record, target, op, source, mask, clip, elapsed));
status = log->record->base.backend->mask (&log->record->base,
op, source, mask, clip);
assert (status == CAIRO_INT_STATUS_SUCCESS);
if (log->record) {
status = log->record->base.backend->mask (&log->record->base,
op, source, mask, clip);
assert (status == CAIRO_INT_STATUS_SUCCESS);
}
if (elapsed > log->mask.slowest.elapsed)
log->mask.slowest = record;
@ -862,15 +867,16 @@ add_record_fill (cairo_observation_t *log,
record_fill (&record,
target, op, source,
path, fill_rule, tolerance, antialias,
clip, elapsed),
log->record->commands.num_elements);
clip, elapsed));
status = log->record->base.backend->fill (&log->record->base,
op, source,
path, fill_rule,
tolerance, antialias,
clip);
assert (status == CAIRO_INT_STATUS_SUCCESS);
if (log->record) {
status = log->record->base.backend->fill (&log->record->base,
op, source,
path, fill_rule,
tolerance, antialias,
clip);
assert (status == CAIRO_INT_STATUS_SUCCESS);
}
if (elapsed > log->fill.slowest.elapsed)
log->fill.slowest = record;
@ -975,15 +981,16 @@ add_record_stroke (cairo_observation_t *log,
target, op, source,
path, style, ctm,ctm_inverse,
tolerance, antialias,
clip, elapsed),
log->record->commands.num_elements);
clip, elapsed));
status = log->record->base.backend->stroke (&log->record->base,
op, source,
path, style, ctm,ctm_inverse,
tolerance, antialias,
clip);
assert (status == CAIRO_INT_STATUS_SUCCESS);
if (log->record) {
status = log->record->base.backend->stroke (&log->record->base,
op, source,
path, style, ctm,ctm_inverse,
tolerance, antialias,
clip);
assert (status == CAIRO_INT_STATUS_SUCCESS);
}
if (elapsed > log->stroke.slowest.elapsed)
log->stroke.slowest = record;
@ -1092,17 +1099,18 @@ add_record_glyphs (cairo_observation_t *log,
record_glyphs (&record,
target, op, source,
glyphs, num_glyphs, scaled_font,
clip, elapsed),
log->record->commands.num_elements);
clip, elapsed));
status = log->record->base.backend->show_text_glyphs (&log->record->base,
op, source,
NULL, 0,
glyphs, num_glyphs,
NULL, 0, 0,
scaled_font,
clip);
assert (status == CAIRO_INT_STATUS_SUCCESS);
if (log->record) {
status = log->record->base.backend->show_text_glyphs (&log->record->base,
op, source,
NULL, 0,
glyphs, num_glyphs,
NULL, 0, 0,
scaled_font,
clip);
assert (status == CAIRO_INT_STATUS_SUCCESS);
}
if (elapsed > log->glyphs.slowest.elapsed)
log->glyphs.slowest = record;
@ -1378,17 +1386,20 @@ static const cairo_surface_backend_t _cairo_surface_observer_backend = {
* Since: 1.12
**/
cairo_surface_t *
cairo_surface_create_observer (cairo_surface_t *target)
cairo_surface_create_observer (cairo_surface_t *target,
cairo_surface_observer_mode_t mode)
{
cairo_device_t *device;
cairo_surface_t *surface;
cairo_bool_t record;
if (unlikely (target->status))
return _cairo_surface_create_in_error (target->status);
if (unlikely (target->finished))
return _cairo_surface_create_in_error (_cairo_error (CAIRO_STATUS_SURFACE_FINISHED));
device = _cairo_device_create_observer_internal (target->device);
record = mode & CAIRO_SURFACE_OBSERVER_RECORD_OPERATIONS;
device = _cairo_device_create_observer_internal (target->device, record);
if (unlikely (device->status))
return _cairo_surface_create_in_error (device->status);
@ -1615,7 +1626,7 @@ static double percent (double a, double b)
return round (a*1000 / b) / 10;
}
static void
static cairo_bool_t
replay_record (cairo_observation_t *log,
cairo_observation_record_t *r,
cairo_device_t *script)
@ -1623,6 +1634,9 @@ replay_record (cairo_observation_t *log,
cairo_surface_t *surface;
cairo_int_status_t status;
if (log->record == NULL)
return FALSE;
surface = cairo_script_surface_create (script,
r->target_content,
r->target_width,
@ -1632,6 +1646,8 @@ replay_record (cairo_observation_t *log,
cairo_surface_destroy (surface);
assert (status == CAIRO_INT_STATUS_SUCCESS);
return TRUE;
}
static double
@ -1684,8 +1700,8 @@ _cairo_observation_print (cairo_output_stream_t *stream,
print_record (stream, &log->paint.slowest);
_cairo_output_stream_printf (stream, "\n");
replay_record (log, &log->paint.slowest, script);
_cairo_output_stream_printf (stream, "\n\n");
if (replay_record (log, &log->paint.slowest, script))
_cairo_output_stream_printf (stream, "\n\n");
}
_cairo_output_stream_printf (stream, "mask: count %d [no-op %d], elapsed %f [%f%%]\n",
@ -1705,8 +1721,8 @@ _cairo_observation_print (cairo_output_stream_t *stream,
print_record (stream, &log->mask.slowest);
_cairo_output_stream_printf (stream, "\n");
replay_record (log, &log->mask.slowest, script);
_cairo_output_stream_printf (stream, "\n\n");
if (replay_record (log, &log->mask.slowest, script))
_cairo_output_stream_printf (stream, "\n\n");
}
_cairo_output_stream_printf (stream, "fill: count %d [no-op %d], elaspsed %f [%f%%]\n",
@ -1728,8 +1744,8 @@ _cairo_observation_print (cairo_output_stream_t *stream,
print_record (stream, &log->fill.slowest);
_cairo_output_stream_printf (stream, "\n");
replay_record (log, &log->fill.slowest, script);
_cairo_output_stream_printf (stream, "\n\n");
if (replay_record (log, &log->fill.slowest, script))
_cairo_output_stream_printf (stream, "\n\n");
}
_cairo_output_stream_printf (stream, "stroke: count %d [no-op %d], elapsed %f [%f%%]\n",
@ -1752,8 +1768,8 @@ _cairo_observation_print (cairo_output_stream_t *stream,
print_record (stream, &log->stroke.slowest);
_cairo_output_stream_printf (stream, "\n");
replay_record (log, &log->stroke.slowest, script);
_cairo_output_stream_printf (stream, "\n\n");
if (replay_record (log, &log->stroke.slowest, script))
_cairo_output_stream_printf (stream, "\n\n");
}
_cairo_output_stream_printf (stream, "glyphs: count %d [no-op %d], elasped %f [%f%%]\n",
@ -1772,8 +1788,8 @@ _cairo_observation_print (cairo_output_stream_t *stream,
print_record (stream, &log->glyphs.slowest);
_cairo_output_stream_printf (stream, "\n");
replay_record (log, &log->glyphs.slowest, script);
_cairo_output_stream_printf (stream, "\n\n");
if (replay_record (log, &log->glyphs.slowest, script))
_cairo_output_stream_printf (stream, "\n\n");
}
cairo_device_destroy (script);
@ -1850,3 +1866,78 @@ cairo_device_observer_elapsed (cairo_device_t *abstract_device)
device = (cairo_device_observer_t *) abstract_device;
return _cairo_observation_total_elapsed_ns (&device->log);
}
double
cairo_device_observer_paint_elapsed (cairo_device_t *abstract_device)
{
cairo_device_observer_t *device;
if (unlikely (CAIRO_REFERENCE_COUNT_IS_INVALID (&abstract_device->ref_count)))
return -1;
if (! _cairo_device_is_observer (abstract_device))
return -1;
device = (cairo_device_observer_t *) abstract_device;
return device->log.paint.elapsed;
}
double
cairo_device_observer_mask_elapsed (cairo_device_t *abstract_device)
{
cairo_device_observer_t *device;
if (unlikely (CAIRO_REFERENCE_COUNT_IS_INVALID (&abstract_device->ref_count)))
return -1;
if (! _cairo_device_is_observer (abstract_device))
return -1;
device = (cairo_device_observer_t *) abstract_device;
return device->log.mask.elapsed;
}
double
cairo_device_observer_fill_elapsed (cairo_device_t *abstract_device)
{
cairo_device_observer_t *device;
if (unlikely (CAIRO_REFERENCE_COUNT_IS_INVALID (&abstract_device->ref_count)))
return -1;
if (! _cairo_device_is_observer (abstract_device))
return -1;
device = (cairo_device_observer_t *) abstract_device;
return device->log.fill.elapsed;
}
double
cairo_device_observer_stroke_elapsed (cairo_device_t *abstract_device)
{
cairo_device_observer_t *device;
if (unlikely (CAIRO_REFERENCE_COUNT_IS_INVALID (&abstract_device->ref_count)))
return -1;
if (! _cairo_device_is_observer (abstract_device))
return -1;
device = (cairo_device_observer_t *) abstract_device;
return device->log.stroke.elapsed;
}
double
cairo_device_observer_glyphs_elapsed (cairo_device_t *abstract_device)
{
cairo_device_observer_t *device;
if (unlikely (CAIRO_REFERENCE_COUNT_IS_INVALID (&abstract_device->ref_count)))
return -1;
if (! _cairo_device_is_observer (abstract_device))
return -1;
device = (cairo_device_observer_t *) abstract_device;
return device->log.glyphs.elapsed;
}

View file

@ -2113,8 +2113,14 @@ cairo_surface_create_for_rectangle (cairo_surface_t *target,
double width,
double height);
typedef enum {
CAIRO_SURFACE_OBSERVER_NORMAL = 0,
CAIRO_SURFACE_OBSERVER_RECORD_OPERATIONS = 0x1,
} cairo_surface_observer_mode_t;
cairo_public cairo_surface_t *
cairo_surface_create_observer (cairo_surface_t *target);
cairo_surface_create_observer (cairo_surface_t *target,
cairo_surface_observer_mode_t mode);
cairo_public void
cairo_surface_observer_print (cairo_surface_t *surface,
@ -2131,6 +2137,21 @@ cairo_device_observer_print (cairo_device_t *device,
cairo_public double
cairo_device_observer_elapsed (cairo_device_t *device);
cairo_public double
cairo_device_observer_paint_elapsed (cairo_device_t *device);
cairo_public double
cairo_device_observer_mask_elapsed (cairo_device_t *device);
cairo_public double
cairo_device_observer_fill_elapsed (cairo_device_t *device);
cairo_public double
cairo_device_observer_stroke_elapsed (cairo_device_t *device);
cairo_public double
cairo_device_observer_glyphs_elapsed (cairo_device_t *device);
cairo_public cairo_surface_t *
cairo_surface_reference (cairo_surface_t *surface);