(woah, replying to mails on lists I'm not subscribed to should be a lot
easier, I hope this works)
> For example, in the Boot column, the Clearlooks mean slowdown ranges
> from as bad as 1.57 to as good as 0.57.
>
> Similarly, in the Expose column, the Lighthouse Blue mean slowdown
> is 2.04 in the -2 run but only 1.46 in the -3 run. Drilling down into
> the results show the following anomalous timings for GtkFrame
>
> Lighthouse blue expose timings
> 2.6 2.10
> GtkFrame-2 0.07 0.40
> GtkFrame-3 0.38 0.09
>
> http://cairographics.org/~cworth/gtk2.6_vs_2.10/20060815-2/LighthouseBlue/expose.html
> http://cairographics.org/~cworth/gtk2.6_vs_2.10/20060815-3/LighthouseBlue/expose.html
>
> So something very funny is happening there. I don't know where the
> non-determinism is coming from, but a result like the above makes the
> "Expose" numbers seem very un-useful.
You can thank Federico for that, his blog got me interested in this. I've
attached a patch to your current git repo that I hope fixes most of the
variations.
The changes I did are described in that patch, but I'll repeat them here,
they seem interesting:
The first thing I wanted to know is how big the deviations are, so I
hacked up torturer.c to print that out (the huge print statement to do
it is currently #if 0'ed out - you might want to enable it to check that
there's no huge deviations). When doing this I noticed that benchmark
times can differ by as much as 500 times, which makes the whole benchmark
kinda useless.
Then I noticed (or actually Benjamin Berg on IRC did) that the test is
creating a GtkWindow. And then metacity is painting a border around that,
the tasklist is showing the window in its list and whatnot. So I made the
GtkWindow a GTK_WINDOW_POPUP. That reduced the total expose times by a
factor of >20. (19.0 to 0.8 seconds for 84 GtkEntry exposes.)
Then I did the usual statistic stuff and didn't include the slowest and
fastest 10% of the results. After that the times that got still
included differed by around 15%, depending on run and test.
I then tried to exclude top and bottom 20% which reduced the maximum
time difference to around 10%, which I liked even more, so I left it at
that.
So with my patch above the code discards the top and bottom 16 results and
calculates the average of the resulting 52 runs.
The third thing I did was trying to reduce the influences from
other running processes. First I tried grabbing the display with
gdk_x11_display_(un)grab. This didn't seem to improve the results, but
didn't make it worse either. I just decided to let it in.
Then I decided to g_usleep (0) after a benchmark has finished. I once
learned that sleep (0) makes the kernel schedule other tasks immediately,
a kind of cooperative multitasking. ;)
It seems to have worked somehow since adding it reduced the time
difference from ~10% to ~7%.
I haven't run the benchmark since I don't have different gtk versions
installed and am too lazy to do so, but I hope this stuff helps.
Benjamin
From 1617286989a538190491ebbe4e7cf05d982f38a4 Mon Sep 17 00:00:00 2001
From: Benjamin Otte <[EMAIL PROTECTED]>
Date: Thu, 17 Aug 2006 12:34:57 +0200
Subject: [PATCH] - use GTK_WINDOW_POPUP instead of GTK_WINDOW_TOPLEVEL to get
metacity, tasklist etc out of this benchmark (this change alone reduces runtime
to 15%)
- discard bottom 20% and top 20% of the results (reduces difference between
best and worst case from ~300% to ~10%) - discarding only bottom/top 10% would
give 15-20% difference
- use gdk_x11_display_(un)grab when benchmarking (no real change)
- use g_usleep after each benchmark to yield to other processes (slight
improvement to ~7% between best and worst result)
---
gtk-theme-torturer/gtkwidgetprofiler.c | 63 ++++++++++--------
gtk-theme-torturer/torturer.c | 112 +++++++++++++++++++++++---------
2 files changed, 116 insertions(+), 59 deletions(-)
diff --git a/gtk-theme-torturer/gtkwidgetprofiler.c
b/gtk-theme-torturer/gtkwidgetprofiler.c
index 7b8a07f..421d3ec 100644
--- a/gtk-theme-torturer/gtkwidgetprofiler.c
+++ b/gtk-theme-torturer/gtkwidgetprofiler.c
@@ -1,4 +1,7 @@
#include <gdk/gdk.h>
+#ifdef GDK_WINDOWING_X11
+# include <gdk/gdkx.h>
+#endif
#include <string.h>
#include "gtkwidgetprofiler.h"
#include "marshalers.h"
@@ -149,15 +152,29 @@ gtk_widget_profiler_set_num_iterations (
}
static void
-report (GtkWidgetProfiler *profiler,
- GtkWidgetProfilerReport report,
- gdouble elapsed)
+gtk_widget_profiler_start (GtkWidgetProfiler *profiler)
{
- GtkWidgetProfilerPrivate *priv;
-
- priv = profiler->priv;
+#ifdef GDK_WINDOWING_X11
+ /* grab display, so we really only benchmark this program */
+ gdk_x11_display_grab (gdk_display_get_default ());
+#endif
+ g_timer_reset (profiler->priv->timer);
+}
+static void
+gtk_widget_profiler_stop (GtkWidgetProfiler *profiler,
+ GtkWidgetProfilerReport report)
+{
+ GtkWidgetProfilerPrivate *priv = profiler->priv;
+ gdouble elapsed = g_timer_elapsed (priv->timer, NULL);
+#ifdef GDK_WINDOWING_X11
+ /* ungrab previously grabbed display */
+ gdk_x11_display_ungrab (gdk_display_get_default ());
+#endif
+ /* signal report */
g_signal_emit (profiler, signals[REPORT], 0, report, priv->profiled_widget,
elapsed);
+ /* make sure other apps can do their stuff, so they don't mess up the next
measurement */
+ g_usleep (0);
}
static GtkWidget *
@@ -181,7 +198,6 @@ toplevel_property_notify_event_cb (GtkWi
{
GtkWidgetProfiler *profiler;
GtkWidgetProfilerPrivate *priv;
- gdouble elapsed;
profiler = GTK_WIDGET_PROFILER (data);
priv = profiler->priv;
@@ -190,9 +206,7 @@ toplevel_property_notify_event_cb (GtkWi
return FALSE;
/* Finish timing map/expose */
-
- elapsed = g_timer_elapsed (priv->timer, NULL);
- report (profiler, GTK_WIDGET_PROFILER_REPORT_EXPOSE, elapsed);
+ gtk_widget_profiler_stop (profiler, GTK_WIDGET_PROFILER_REPORT_EXPOSE);
gtk_main_quit (); /* This will get us back to the end of
profile_map_expose() */
return TRUE;
@@ -265,7 +279,7 @@ ensure_and_get_toplevel (GtkWidgetProfil
g_assert (toplevel == widget); /* we don't want extraneous ancestors */
- window = gtk_window_new (GTK_WINDOW_TOPLEVEL);
+ window = gtk_window_new (GTK_WINDOW_POPUP);
/* Small hack so that the toplevel still gets expose events even when
* the child occupies the whole surface
@@ -320,21 +334,18 @@ static void
profile_map_expose (GtkWidgetProfiler *profiler)
{
GtkWidgetProfilerPrivate *priv;
- gdouble elapsed;
priv = profiler->priv;
g_assert (priv->state == STATE_INSTRUMENTED_NOT_MAPPED);
- g_timer_reset (priv->timer);
+ gtk_widget_profiler_start (profiler);
map_widget (profiler);
- elapsed = g_timer_elapsed (priv->timer, NULL);
-
- report (profiler, GTK_WIDGET_PROFILER_REPORT_MAP, elapsed);
+ gtk_widget_profiler_stop (profiler, GTK_WIDGET_PROFILER_REPORT_MAP);
/* Time expose; this gets recorded in toplevel_property_notify_event_cb() */
- g_timer_reset (priv->timer);
+ gtk_widget_profiler_start (profiler);
gtk_main ();
}
@@ -342,17 +353,14 @@ static void
profile_destroy (GtkWidgetProfiler *profiler)
{
GtkWidgetProfilerPrivate *priv;
- gdouble elapsed;
priv = profiler->priv;
g_assert (priv->state != STATE_NOT_CREATED);
- g_timer_reset (priv->timer);
+ gtk_widget_profiler_start (profiler);
reset_state (profiler);
- elapsed = g_timer_elapsed (priv->timer, NULL);
-
- report (profiler, GTK_WIDGET_PROFILER_REPORT_DESTROY, elapsed);
+ gtk_widget_profiler_stop (profiler, GTK_WIDGET_PROFILER_REPORT_DESTROY);
}
static void
@@ -384,7 +392,6 @@ static void
profile_boot (GtkWidgetProfiler *profiler)
{
GtkWidgetProfilerPrivate *priv;
- gdouble elapsed;
priv = profiler->priv;
@@ -392,11 +399,9 @@ profile_boot (GtkWidgetProfiler *profile
/* Time creation */
- g_timer_reset (priv->timer);
+ gtk_widget_profiler_start (profiler);
create_widget (profiler);
- elapsed = g_timer_elapsed (priv->timer, NULL);
-
- report (profiler, GTK_WIDGET_PROFILER_REPORT_CREATE, elapsed);
+ gtk_widget_profiler_stop (profiler, GTK_WIDGET_PROFILER_REPORT_CREATE);
/* Start timing map/expose */
@@ -444,7 +449,7 @@ profile_expose (GtkWidgetProfiler *profi
/* Time expose; this gets recorded in toplevel_property_notify_event_cb() */
- g_timer_reset (priv->timer);
+ gtk_widget_profiler_start (profiler);
gtk_main ();
}
@@ -484,7 +489,7 @@ profile_expose_with_size (GtkWidgetProfi
/* Time expose; this gets recorded in toplevel_property_notify_event_cb() */
- g_timer_reset (priv->timer);
+ gtk_widget_profiler_start (profiler);
gtk_main ();
}
diff --git a/gtk-theme-torturer/torturer.c b/gtk-theme-torturer/torturer.c
index 00b01f3..7afd23d 100644
--- a/gtk-theme-torturer/torturer.c
+++ b/gtk-theme-torturer/torturer.c
@@ -7,6 +7,11 @@ #include "torturer.h"
#include "paint.h"
#include "gtkwidgetprofiler.h"
+typedef struct {
+ GtkWidgetProfilerReport type;
+ double elapsed;
+} StoredReport;
+
GType *types;
gchar **function_name;
GtkWidget *crash_test_label;
@@ -67,13 +72,6 @@ initialize_functions (void) {
function_name[GTK_PAINT_RESIZE_GRIPS] = g_strdup_printf ("Resize grips");
}
-
-
-static void
-reset_total_expose_timer (void) {
- total_expose = 0.;
-}
-
static GtkWidget *
create_widget (void) {
const char *torture_string = "Aaaah! Please stop this!";
@@ -123,29 +121,74 @@ profiler_create_widget_cb (GtkWidgetProf
}
static void
-profiler_report_cb (GtkWidgetProfiler *profiler, GtkWidgetProfilerReport
report, GtkWidget *widget, gdouble elapsed, gpointer data)
+profiler_report_cb (GtkWidgetProfiler *profiler, GtkWidgetProfilerReport type,
GtkWidget *widget, gdouble elapsed, gpointer data)
{
+ StoredReport report = { type, elapsed };
- switch (report) {
- case GTK_WIDGET_PROFILER_REPORT_CREATE:
- total_create += elapsed;
- break;
-
- case GTK_WIDGET_PROFILER_REPORT_MAP:
- total_map += elapsed;
- break;
+ g_array_append_val (data, report);
+}
- case GTK_WIDGET_PROFILER_REPORT_EXPOSE:
- total_expose += elapsed;
- break;
+gint
+sort_report_entry (gconstpointer _a, gconstpointer _b)
+{
+ const StoredReport *a = _a;
+ const StoredReport *b = _b;
- case GTK_WIDGET_PROFILER_REPORT_DESTROY:
- total_destroy += elapsed;
- break;
+ if (a->type < b->type)
+ return -1;
+ if (a->type > b->type)
+ return 1;
+ if (a->elapsed < b->elapsed)
+ return -1;
+ if (a->elapsed > b->elapsed)
+ return 1;
+ return 0;
+}
- default:
- g_assert_not_reached ();
+/* reports must be sorted when calling this function */
+static gdouble
+calculate_average (GArray *reports, GtkWidgetProfilerReport type)
+{
+ guint i, first, last, discard;
+ double sum, average;
+/* percentage of results discarded at top and bottom each */
+#define DISCARD_PERCENTAGE 20
+
+ first = last = reports->len;
+ for (i = 0; i < reports->len; i++) {
+ if (g_array_index (reports, StoredReport, i).type == type) {
+ first = i;
+ break;
+ }
+ }
+ if (first >= reports->len) /* none found */
+ return 0.0;
+ for (i = first; i < reports->len; i++) {
+ if (g_array_index (reports, StoredReport, i).type != type) {
+ last = i;
+ break;
+ }
+ }
+ sum = 0;
+ discard = (last - first) * DISCARD_PERCENTAGE / 100;
+ g_assert (discard * 2 < last - first);
+ for (i = first + discard; i < last - discard; i++) {
+ sum += g_array_index (reports, StoredReport, i).elapsed;
}
+ average = sum / (last - first - 2 * discard);
+#if 0
+ g_print ("%g (from %g to %g - %d%%) (full times from %g to %g - %d excluded)
for %d reports\n",
+ average,
+ g_array_index (reports, StoredReport, first + discard).elapsed,
+ g_array_index (reports, StoredReport, last - 1 - discard).elapsed,
+ (int) (g_array_index (reports, StoredReport, last - 1 - discard).elapsed
* 100 /
+ g_array_index (reports, StoredReport, first + discard).elapsed),
+ g_array_index (reports, StoredReport, first).elapsed,
+ g_array_index (reports, StoredReport, last - 1).elapsed,
+ discard,
+ last - first);
+#endif
+ return average;
}
static void
@@ -153,6 +196,7 @@ torture_widget (GtkWidget *not_useful, g
int i, n_iter; //width, height;
GtkWidgetProfiler *profiler;
gdouble total_expose_in_boot, total_expose_in_expose, total_expose_in_resize;
+ GArray *reports;
i = GPOINTER_TO_INT (data);
current_widget_type = i;
@@ -160,27 +204,35 @@ torture_widget (GtkWidget *not_useful, g
/* Profiler init */
profiler = gtk_widget_profiler_new ();
+ reports = g_array_new (FALSE, FALSE, sizeof (StoredReport));
g_signal_connect (profiler, "create-widget",
G_CALLBACK (profiler_create_widget_cb), NULL);
g_signal_connect (profiler, "report",
- G_CALLBACK (profiler_report_cb), NULL);
+ G_CALLBACK (profiler_report_cb), reports);
gtk_widget_profiler_set_num_iterations (profiler, n_iter);
/* Boot */
gtk_widget_profiler_profile_boot (profiler);
- total_expose_in_boot = total_expose;
+ g_array_sort (reports, sort_report_entry);
+ total_expose_in_boot = calculate_average (reports,
GTK_WIDGET_PROFILER_REPORT_EXPOSE);
+ total_create = calculate_average (reports,
GTK_WIDGET_PROFILER_REPORT_CREATE);
+ total_map = calculate_average (reports, GTK_WIDGET_PROFILER_REPORT_MAP);
+ total_destroy = calculate_average (reports,
GTK_WIDGET_PROFILER_REPORT_DESTROY);
/* Expose */
- reset_total_expose_timer ();
+ g_array_set_size (reports, 0);
gtk_widget_profiler_profile_expose (profiler);
- total_expose_in_expose = total_expose;
+ g_array_sort (reports, sort_report_entry);
+ total_expose_in_expose = calculate_average (reports,
GTK_WIDGET_PROFILER_REPORT_EXPOSE);
/* Expose and resize */
- reset_total_expose_timer ();
+ g_array_set_size (reports, 0);
gtk_widget_profiler_profile_expose_with_resize (profiler, 0.1, 0.5);
- total_expose_in_resize = total_expose;
+ g_array_sort (reports, sort_report_entry);
+ total_expose_in_resize = calculate_average (reports,
GTK_WIDGET_PROFILER_REPORT_EXPOSE);
+ g_array_free (reports, TRUE);
if (!xml_output) {
printf ("%s\t%g\t%g\t%g\t%g\t%g\t%g\n",
g_type_name (types[current_widget_type]),
--
1.4.1
_______________________________________________
Performance-list mailing list
Performance-list@gnome.org
http://mail.gnome.org/mailman/listinfo/performance-list
