Re: GtkPerf data for GTK+ 2.6 vs GTK+ 2.10 vs Maemo-GTK+ 2.6

[Benjamin Otte <in7y118 public uni-hamburg de>]

(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 <otte gnome org>
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