[gegl] Bring back gegl_instrument timers

[Daniel Sabo <daniels src gnome org>]

commit 5c50de7278b165a19299da20909f243548a4359b
Author: Daniel Sabo <DanielSabo gmail com>
Date:   Fri Jun 7 01:14:05 2013 -0700

    Bring back gegl_instrument timers
    
    This was broken by the graph rewrite, the new version
    is fully conditional so it imposes no overhead when
    GEGL_DEBUG_TIME is not set.

 gegl/gegl-init.c                    |   18 +++++-------------
 gegl/gegl-instrument.c              |    2 +-
 gegl/gegl-instrument.h              |   10 ++++++++++
 gegl/gegl-xml.c                     |    6 +++---
 gegl/process/gegl-eval-manager.c    |    7 +++++++
 gegl/process/gegl-graph-traversal.c |    5 +++++
 6 files changed, 31 insertions(+), 17 deletions(-)
---
diff --git a/gegl/gegl-init.c b/gegl/gegl-init.c
index fd976cc..921cf26 100644
--- a/gegl/gegl-init.c
+++ b/gegl/gegl-init.c
@@ -385,15 +385,13 @@ static void swap_clean (void)
 void
 gegl_exit (void)
 {
-  glong timing;
-
   if (!config)
     {
       g_warning("gegl_exit() called without matching call to gegl_init()");
       return;
     }
 
-  timing = gegl_ticks ();
+  GEGL_INSTRUMENT_START()
 
   gegl_tile_cache_destroy ();
   gegl_operation_gtype_cleanup ();
@@ -408,8 +406,7 @@ gegl_exit (void)
 
   babl_exit ();
 
-  timing = gegl_ticks () - timing;
-  gegl_instrument ("gegl", "gegl_exit", timing);
+  GEGL_INSTRUMENT_END ("gegl", "gegl_exit")
 
   /* used when tracking buffer and tile leaks */
   if (g_getenv ("GEGL_DEBUG_BUFS") != NULL)
@@ -506,8 +503,6 @@ gegl_post_parse_hook (GOptionContext *context,
                       gpointer        data,
                       GError        **error)
 {
-  glong time;
-
   g_assert (global_time == 0);
   global_time = gegl_ticks ();
   g_type_init ();
@@ -562,11 +557,8 @@ gegl_post_parse_hook (GOptionContext *context,
     g_object_set (config, "queue-limit", cmd_gegl_queue_limit, NULL);
 
 
-  time = gegl_ticks ();
-
-  gegl_instrument ("gegl_init", "babl_init", gegl_ticks () - time);
+  GEGL_INSTRUMENT_START();
 
-  time = gegl_ticks ();
   if (!module_db)
     {
       const gchar *gegl_path = g_getenv ("GEGL_PATH");
@@ -617,10 +609,10 @@ gegl_post_parse_hook (GOptionContext *context,
           gegl_module_db_load (module_db, module_path);
           g_free (module_path);
         }
-
-      gegl_instrument ("gegl_init", "load modules", gegl_ticks () - time);
     }
 
+  GEGL_INSTRUMENT_END ("gegl_init", "load modules");
+
   gegl_instrument ("gegl", "gegl_init", gegl_ticks () - global_time);
 
   if (g_getenv ("GEGL_SWAP"))
diff --git a/gegl/gegl-instrument.c b/gegl/gegl-instrument.c
index 290f93e..e165899 100644
--- a/gegl/gegl-instrument.c
+++ b/gegl/gegl-instrument.c
@@ -120,7 +120,7 @@ real_gegl_instrument (const gchar *parent_name,
   parent = timing_find (root, parent_name);
   if (!parent)
     {
-      gegl_instrument (root->name, parent_name, 0);
+      real_gegl_instrument (root->name, parent_name, 0);
       parent = timing_find (root, parent_name);
     }
   g_assert (parent);
diff --git a/gegl/gegl-instrument.h b/gegl/gegl-instrument.h
index a888b99..7dd6cb5 100644
--- a/gegl/gegl-instrument.h
+++ b/gegl/gegl-instrument.h
@@ -26,6 +26,16 @@ long gegl_ticks               (void);
 /* start tracking times with gegl_instrument */
 void gegl_instrument_enable   (void);
 
+#define GEGL_INSTRUMENT_START() \
+  { long _gegl_instrument_ticks = 0; \
+    if (gegl_instrument_enabled) { _gegl_instrument_ticks = gegl_ticks (); }
+
+#define GEGL_INSTRUMENT_END(parent, scale) \
+    if (gegl_instrument_enabled) { \
+      real_gegl_instrument (parent, scale, gegl_ticks () - _gegl_instrument_ticks); \
+                                 } \
+  }
+
 /* store a timing instrumentation (parent is expected to exist,
  * and to keep it's own record of the time-slice reported) */
 #define gegl_instrument(parent, scale, usecs) \
diff --git a/gegl/gegl-xml.c b/gegl/gegl-xml.c
index a6ae802..dd035a5 100644
--- a/gegl/gegl-xml.c
+++ b/gegl/gegl-xml.c
@@ -521,13 +521,14 @@ static void each_ref (gpointer value,
 GeglNode *gegl_node_new_from_xml (const gchar *xmldata,
                                   const gchar *path_root)
 {
-  glong                time = gegl_ticks ();
   ParseData            pd   = { 0, };
   GMarkupParseContext *context;
   gboolean             success = FALSE;
 
   g_return_val_if_fail (xmldata != NULL, NULL);
 
+  GEGL_INSTRUMENT_START();
+
   pd.ids       = g_hash_table_new_full (g_str_hash, g_str_equal, g_free, NULL);
   pd.refs      = NULL;
   pd.path_root = path_root;
@@ -557,8 +558,7 @@ GeglNode *gegl_node_new_from_xml (const gchar *xmldata,
   g_markup_parse_context_free (context);
   g_hash_table_destroy (pd.ids);
 
-  time = gegl_ticks () - time;
-  gegl_instrument ("gegl", "gegl_parse_xml", time);
+  GEGL_INSTRUMENT_END ("gegl", "gegl_parse_xml");
 
   return success ? GEGL_NODE (pd.gegl) : NULL;
 }
diff --git a/gegl/process/gegl-eval-manager.c b/gegl/process/gegl-eval-manager.c
index 8fa799c..04a1a70 100644
--- a/gegl/process/gegl-eval-manager.c
+++ b/gegl/process/gegl-eval-manager.c
@@ -124,10 +124,17 @@ gegl_eval_manager_apply (GeglEvalManager     *self,
   if (roi->width <= 0 || roi->height <= 0)
     return NULL;
 
+  GEGL_INSTRUMENT_START();
   gegl_eval_manager_prepare (self);
+  GEGL_INSTRUMENT_END ("gegl", "prepare-graph");
 
+  GEGL_INSTRUMENT_START();
   gegl_graph_prepare_request (self->traversal, roi);
+  GEGL_INSTRUMENT_END ("gegl", "prepare-request");
+
+  GEGL_INSTRUMENT_START();
   object = gegl_graph_process (self->traversal);
+  GEGL_INSTRUMENT_END ("gegl", "process");
 
   return object;
 }
diff --git a/gegl/process/gegl-graph-traversal.c b/gegl/process/gegl-graph-traversal.c
index 0ce9da0..4a3e16f 100644
--- a/gegl/process/gegl-graph-traversal.c
+++ b/gegl/process/gegl-graph-traversal.c
@@ -24,6 +24,7 @@
 #include "gegl.h"
 #include "gegl-utils.h"
 #include "gegl-debug.h"
+#include "gegl-instrument.h"
 
 #include "buffer/gegl-region.h"
 
@@ -376,6 +377,8 @@ gegl_graph_process (GeglGraphTraversal *path)
       g_return_val_if_fail (node, NULL);
       g_return_val_if_fail (operation, NULL);
       
+      GEGL_INSTRUMENT_START();
+
       if (last_context)
         gegl_operation_context_purge (last_context);
       
@@ -439,6 +442,8 @@ gegl_graph_process (GeglGraphTraversal *path)
         }
       
       last_context = context;
+
+      GEGL_INSTRUMENT_END ("process", gegl_node_get_operation (node));
     }
   
   if (last_context)