[gegl] Revert "remove internal profiling code"
- From: Ãyvind KolÃs <ok src gnome org>
- To: commits-list gnome org
- Cc:
- Subject: [gegl] Revert "remove internal profiling code"
- Date: Fri, 16 Mar 2012 23:00:15 +0000 (UTC)
commit 8ca39fce36fec20cae684edccafe5d3073dc273c
Author: Ãyvind KolÃs <pippin gimp org>
Date: Fri Mar 16 22:58:47 2012 +0000
Revert "remove internal profiling code"
This reverts commit 6d4456fc928a942ab519e8ce07f9187f9079c3fd.
Removing it was an experiment, the result of the experiment was that profiling
does not have a performance impact. Pushing the commit was an accident.
examples/float-lookup.c | 16 +-
gegl/Makefile.am | 2 +
gegl/gegl-init.c | 25 +++
gegl/gegl-instrument.c | 341 +++++++++++++++++++++++++++++++++++
gegl/gegl-instrument.h | 36 ++++
gegl/gegl-xml.c | 5 +
gegl/process/gegl-eval-mgr.c | 6 +
gegl/process/gegl-eval-visitor.c | 5 +
gegl/process/gegl-finish-visitor.c | 1 +
gegl/process/gegl-have-visitor.c | 6 +
gegl/process/gegl-prepare-visitor.c | 6 +
11 files changed, 440 insertions(+), 9 deletions(-)
---
diff --git a/examples/float-lookup.c b/examples/float-lookup.c
index fe1e1b8..c6f6370 100644
--- a/examples/float-lookup.c
+++ b/examples/float-lookup.c
@@ -14,7 +14,7 @@ static gfloat passthrough (gfloat in, gpointer data)
return in;
}
-glong babl_ticks (void);
+glong gegl_ticks (void);
#define ITERATIONS 10
#define SAMPLES 10000000
@@ -36,27 +36,25 @@ gint main (int argc, gchar **argv)
}
lookup = gegl_lookup_new (wrapped_sqrt, NULL);
- ticks = babl_ticks ();
+ ticks = gegl_ticks ();
for (i=0;i<ITERATIONS;i++)
for (j=0;j<SAMPLES;j++)
foo = gegl_lookup (lookup, rand[j]);
- ticks = babl_ticks ()-ticks;
+ ticks = gegl_ticks ()-ticks;
g_print ("First run: %i\n", ticks);
- if (foo)
- foo = 0;
- ticks = babl_ticks ();
+ ticks = gegl_ticks ();
for (i=0;i<ITERATIONS;i++)
for (j=0;j<SAMPLES;j++)
foo = gegl_lookup (lookup, rand[j]);
- ticks = babl_ticks ()-ticks;
+ ticks = gegl_ticks ()-ticks;
g_print ("Second run: %i\n", ticks);
- ticks = babl_ticks ();
+ ticks = gegl_ticks ();
for (i=0;i<ITERATIONS;i++)
for (j=0;j<SAMPLES;j++)
foo = sqrt (rand[j]);
- ticks = babl_ticks ()-ticks;
+ ticks = gegl_ticks ()-ticks;
g_print ("Just sqrt: %i\n", ticks);
gegl_lookup_free (lookup);
diff --git a/gegl/Makefile.am b/gegl/Makefile.am
index 4750162..02a540e 100644
--- a/gegl/Makefile.am
+++ b/gegl/Makefile.am
@@ -68,6 +68,7 @@ GEGL_introspectable_sources = \
gegl-dot-visitor.c \
gegl-enums.c \
gegl-init.c \
+ gegl-instrument.c \
gegl-utils.c \
gegl-lookup.c \
gegl-xml.c \
@@ -80,6 +81,7 @@ GEGL_introspectable_sources = \
gegl-dot.h \
gegl-dot-visitor.h \
gegl-init.h \
+ gegl-instrument.h \
gegl-plugin.h \
gegl-types-internal.h \
gegl-xml.h \
diff --git a/gegl/gegl-init.c b/gegl/gegl-init.c
index d60aa2c..dad80de 100644
--- a/gegl/gegl-init.c
+++ b/gegl/gegl-init.c
@@ -82,6 +82,7 @@ pid_is_running (gint pid)
guint gegl_debug_flags = 0;
+#include "gegl-instrument.h"
#include "gegl-init.h"
#include "module/geglmodule.h"
#include "module/geglmoduledb.h"
@@ -353,6 +354,8 @@ void gegl_tile_storage_cache_cleanup (void);
void
gegl_exit (void)
{
+ glong timing = gegl_ticks ();
+
gegl_tile_storage_cache_cleanup ();
gegl_tile_cache_destroy ();
gegl_operation_gtype_cleanup ();
@@ -366,6 +369,9 @@ gegl_exit (void)
babl_exit ();
+ timing = gegl_ticks () - timing;
+ gegl_instrument ("gegl", "gegl_exit", timing);
+
/* used when tracking buffer and tile leaks */
if (g_getenv ("GEGL_DEBUG_BUFS") != NULL)
{
@@ -374,6 +380,13 @@ gegl_exit (void)
gegl_tile_backend_file_stats ();
gegl_tile_backend_tiledir_stats ();
}
+ global_time = gegl_ticks () - global_time;
+ gegl_instrument ("gegl", "gegl", global_time);
+
+ if (g_getenv ("GEGL_DEBUG_TIME") != NULL)
+ {
+ g_printf ("\n%s", gegl_instrument_utf8 ());
+ }
if (gegl_buffer_leaks ())
g_printf (" buffer-leaks: %i\n", gegl_buffer_leaks ());
@@ -447,12 +460,16 @@ gegl_post_parse_hook (GOptionContext *context,
gpointer data,
GError **error)
{
+ glong time;
+
if (config)
return TRUE;
g_assert (global_time == 0);
+ global_time = gegl_ticks ();
g_type_init ();
+ gegl_instrument ("gegl", "gegl_init", 0);
config = (void*)gegl_config ();
@@ -492,10 +509,14 @@ gegl_post_parse_hook (GOptionContext *context,
}
#endif /* GEGL_ENABLE_DEBUG */
+ time = gegl_ticks ();
+
babl_init ();
+ gegl_instrument ("gegl_init", "babl_init", gegl_ticks () - time);
gegl_init_i18n ();
+ time = gegl_ticks ();
if (!module_db)
{
const gchar *gegl_path = g_getenv ("GEGL_PATH");
@@ -546,8 +567,12 @@ 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 ("gegl", "gegl_init", gegl_ticks () - global_time);
+
if (g_getenv ("GEGL_SWAP"))
g_object_set (config, "swap", g_getenv ("GEGL_SWAP"), NULL);
if (g_getenv ("GEGL_QUALITY"))
diff --git a/gegl/gegl-instrument.c b/gegl/gegl-instrument.c
new file mode 100644
index 0000000..a46b3ca
--- /dev/null
+++ b/gegl/gegl-instrument.c
@@ -0,0 +1,341 @@
+/* This file is part of GEGL
+ *
+ * GEGL is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation; either
+ * version 3 of the License, or (at your option) any later version.
+ *
+ * GEGL is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public
+ * License along with GEGL; if not, see <http://www.gnu.org/licenses/>.
+ *
+ * Copyright 2006 Ãyvind KolÃs
+ */
+
+#include "config.h"
+#include <glib.h>
+#include <string.h>
+#include "gegl-instrument.h"
+
+long babl_ticks (void);
+long gegl_ticks (void)
+{
+ return babl_ticks ();
+}
+
+typedef struct _Timing Timing;
+
+struct _Timing
+{
+ gchar *name;
+ long usecs;
+ Timing *parent;
+ Timing *children;
+ Timing *next;
+};
+
+static Timing *root = NULL;
+
+static Timing *iter_next (Timing *iter)
+{
+ if (iter->children)
+ {
+ iter = iter->children;
+ }
+ else if (iter->next)
+ {
+ iter = iter->next;
+ }
+ else
+ {
+ while (iter && !iter->next)
+ iter = iter->parent;
+ if (iter && iter->next)
+ iter = iter->next;
+ else
+ return NULL;
+ }
+ return iter;
+}
+
+static gint timing_depth (Timing *timing)
+{
+ Timing *iter = timing;
+ gint ret = 0;
+
+ while (iter &&
+ iter->parent)
+ {
+ ret++;
+ iter = iter->parent;
+ }
+
+ return ret;
+}
+
+static Timing *timing_find (Timing *root,
+ const gchar *name)
+{
+ Timing *iter = root;
+
+ if (!iter)
+ return NULL;
+
+ while (iter)
+ {
+ if (!strcmp (iter->name, name))
+ return iter;
+ if (timing_depth (iter_next (iter)) <= timing_depth (root))
+ return NULL;
+ iter = iter_next (iter);
+ }
+ return NULL;
+}
+
+void
+gegl_instrument (const gchar *parent_name,
+ const gchar *name,
+ long usecs)
+{
+ Timing *iter;
+ Timing *parent;
+
+ if (root == NULL)
+ {
+ root = g_slice_new0 (Timing);
+ root->name = g_strdup (parent_name);
+ }
+ parent = timing_find (root, parent_name);
+ if (!parent)
+ {
+ gegl_instrument (root->name, parent_name, 0);
+ parent = timing_find (root, parent_name);
+ }
+ g_assert (parent);
+ iter = timing_find (parent, name);
+ if (!iter)
+ {
+ iter = g_slice_new0 (Timing);
+ iter->name = g_strdup (name);
+ iter->parent = parent;
+ iter->next = parent->children;
+ parent->children = iter;
+ }
+ iter->usecs += usecs;
+}
+
+
+static glong timing_child_sum (Timing *timing)
+{
+ Timing *iter = timing->children;
+ glong sum = 0;
+
+ while (iter)
+ {
+ sum += iter->usecs;
+ iter = iter->next;
+ }
+
+ return sum;
+}
+
+static glong timing_other (Timing *timing)
+{
+ if (timing->children)
+ return timing->usecs - timing_child_sum (timing);
+ return 0;
+}
+
+static float seconds (glong usecs)
+{
+ return usecs / 1000000.0;
+}
+
+static float normalized (glong usecs)
+{
+ return 1.0 * usecs / root->usecs;
+}
+
+#include <string.h>
+
+static GString *
+tab_to (GString *string, gint position)
+{
+ gchar *p;
+ gint curcount = 0;
+ gint i;
+
+ p = strrchr (string->str, '\n');
+ if (!p)
+ {
+ p = string->str;
+ curcount++;
+ }
+ while (p && *p != '\0')
+ {
+ curcount++;
+ p++;
+ }
+
+ if (curcount > position && position != 0)
+ {
+ g_warning ("%s tab overflow %i>%i", G_STRLOC, curcount, position);
+ }
+ else
+ {
+ for (i = 0; i <= position - curcount; i++)
+ string = g_string_append (string, " ");
+ }
+ return string;
+}
+
+static gchar *eight[] = {
+ " ",
+ "â",
+ "â",
+ "â",
+ "â",
+ "â",
+ "â",
+ "â"
+};
+
+static GString *
+bar (GString *string, gint width, gfloat value)
+{
+ gboolean utf8 = TRUE;
+ gint i;
+
+ if (value < 0)
+ return string;
+ if (utf8)
+ {
+ gint blocks = width * 8 * value;
+
+ for (i = 0; i < blocks / 8; i++)
+ {
+ string = g_string_append (string, "â");
+ }
+ string = g_string_append (string, eight[blocks % 8]);
+ }
+ else
+ {
+ for (i = 0; i < width; i++)
+ {
+ if (width * value > i)
+ string = g_string_append (string, "X");
+ }
+ }
+ return string;
+}
+
+#define INDENT_SPACES 2
+#define SECONDS_COL 29
+#define BAR_COL 36
+#define BAR_WIDTH (78 - BAR_COL)
+
+static void
+sort_children (Timing *parent)
+{
+ Timing *iter;
+ Timing *prev;
+ gboolean changed = FALSE;
+
+ do
+ {
+ iter = parent->children;
+ changed = FALSE;
+ prev = NULL;
+ while (iter && iter->next)
+ {
+ Timing *next = iter->next;
+
+ if (next->usecs > iter->usecs)
+ {
+ changed = TRUE;
+ if (prev)
+ {
+ prev->next = next;
+ iter->next = next->next;
+ next->next = iter;
+ }
+ else
+ {
+ iter->next = next->next;
+ next->next = iter;
+ parent->children = next;
+ }
+ }
+ prev = iter;
+ iter = iter->next;
+ }
+ } while (changed);
+
+
+ iter = parent->children;
+ while (iter && iter->next)
+ {
+ sort_children (iter);
+ iter = iter->next;
+ }
+}
+
+gchar *
+gegl_instrument_utf8 (void)
+{
+ GString *s = g_string_new ("");
+ gchar *ret;
+ Timing *iter = root;
+
+ sort_children (root);
+
+ while (iter)
+ {
+ gchar *buf;
+
+ if (!strcmp (iter->name, root->name))
+ {
+ buf = g_strdup_printf ("Total time: %.3fs\n", seconds (iter->usecs));
+ s = g_string_append (s, buf);
+ g_free (buf);
+ }
+
+ s = tab_to (s, timing_depth (iter) * INDENT_SPACES);
+ s = g_string_append (s, iter->name);
+
+ s = tab_to (s, SECONDS_COL);
+ buf = g_strdup_printf ("%5.1f%%", iter->parent ? 100.0 * iter->usecs / iter->parent->usecs : 100.0);
+ s = g_string_append (s, buf);
+ g_free (buf);
+ s = tab_to (s, BAR_COL);
+ s = bar (s, BAR_WIDTH, normalized (iter->usecs));
+ s = g_string_append (s, "\n");
+
+ if (timing_depth (iter_next (iter)) < timing_depth (iter))
+ {
+ if (timing_other (iter->parent) > 0)
+ {
+ s = tab_to (s, timing_depth (iter) * INDENT_SPACES);
+ s = g_string_append (s, "other");
+ s = tab_to (s, SECONDS_COL);
+ buf = g_strdup_printf ("%5.1f%%", 100 * normalized (timing_other (iter->parent)));
+ s = g_string_append (s, buf);
+ g_free (buf);
+ s = tab_to (s, BAR_COL);
+ s = bar (s, BAR_WIDTH, normalized (timing_other (iter->parent)));
+ s = g_string_append (s, "\n");
+ }
+ s = g_string_append (s, "\n");
+ }
+
+ iter = iter_next (iter);
+ }
+
+ ret = g_strdup (s->str);
+ g_string_free (s, TRUE);
+ return ret;
+}
diff --git a/gegl/gegl-instrument.h b/gegl/gegl-instrument.h
new file mode 100644
index 0000000..ef29a04
--- /dev/null
+++ b/gegl/gegl-instrument.h
@@ -0,0 +1,36 @@
+/* This file is part of GEGL
+ *
+ * GEGL is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation; either
+ * version 3 of the License, or (at your option) any later version.
+ *
+ * GEGL is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public
+ * License along with GEGL; if not, see <http://www.gnu.org/licenses/>.
+ *
+ * Copyright 2006 Ãyvind KolÃs
+ */
+#ifndef GEGL_INSTRUMENT_H
+#define GEGL_INSTRUMENT_H
+
+/* return number of usecs since gegl was initialized */
+long gegl_ticks (void);
+
+
+/* store a timing instrumentation (parent is expected to exist,
+ * and to keep it's own record of the time-slice reported) */
+void gegl_instrument (const gchar *parent,
+ const gchar *scale,
+ long usecs);
+
+/* create a utf8 string with bar charts for where time disappears
+ * during a gegl-run
+ */
+gchar * gegl_instrument_utf8 (void);
+
+#endif
diff --git a/gegl/gegl-xml.c b/gegl/gegl-xml.c
index 7db897a..10cf408 100644
--- a/gegl/gegl-xml.c
+++ b/gegl/gegl-xml.c
@@ -33,6 +33,7 @@
#include "property-types/gegl-curve.h"
#include "property-types/gegl-path.h"
#include "property-types/gegl-paramspecs.h"
+#include "gegl-instrument.h"
#include "gegl-xml.h"
#ifdef G_OS_WIN32
@@ -521,6 +522,7 @@ 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;
@@ -556,6 +558,9 @@ 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);
+
return success ? GEGL_NODE (pd.gegl) : NULL;
}
diff --git a/gegl/process/gegl-eval-mgr.c b/gegl/process/gegl-eval-mgr.c
index ae3690e..27da126 100644
--- a/gegl/process/gegl-eval-mgr.c
+++ b/gegl/process/gegl-eval-mgr.c
@@ -28,6 +28,7 @@
#include "gegl-debug-rect-visitor.h"
#include "gegl-need-visitor.h"
#include "gegl-have-visitor.h"
+#include "gegl-instrument.h"
#include "graph/gegl-node.h"
#include "gegl-prepare-visitor.h"
#include "gegl-finish-visitor.h"
@@ -130,10 +131,13 @@ gegl_eval_mgr_apply (GeglEvalMgr *self)
GeglNode *root;
GeglBuffer *object;
GeglPad *pad;
+ glong time = gegl_ticks ();
gpointer context_id = self;
g_assert (GEGL_IS_EVAL_MGR (self));
+ gegl_instrument ("gegl", "process", 0);
+
root=self->node;
pad = gegl_node_get_pad (root, self->pad_name);
/* Use the redirect output NOP of a graph instead of a graph if a traversal
@@ -232,6 +236,8 @@ gegl_eval_mgr_apply (GeglEvalMgr *self)
gegl_visitor_dfs_traverse (self->finish_visitor, GEGL_VISITABLE (root));
g_object_unref (root);
+ time = gegl_ticks () - time;
+ gegl_instrument ("gegl", "process", time);
if (!pad || !G_IS_OBJECT (object))
{
diff --git a/gegl/process/gegl-eval-visitor.c b/gegl/process/gegl-eval-visitor.c
index 33dc0f7..6ae6e45 100644
--- a/gegl/process/gegl-eval-visitor.c
+++ b/gegl/process/gegl-eval-visitor.c
@@ -30,6 +30,7 @@
#include "operation/gegl-operation-context.h"
#include "graph/gegl-pad.h"
#include "graph/gegl-visitable.h"
+#include "gegl-instrument.h"
#include "operation/gegl-operation-sink.h"
#include "buffer/gegl-region.h"
@@ -88,12 +89,16 @@ gegl_eval_visitor_visit_pad (GeglVisitor *self,
else
{
/* Make the operation do it's actual processing */
+ glong time = gegl_ticks ();
GEGL_NOTE (GEGL_DEBUG_PROCESS, "For \"%s\" processing pad '%s' result_rect = %d, %d %dÃ%d",
gegl_pad_get_name (pad), gegl_node_get_debug_name (node),
context->result_rect.x, context->result_rect.y, context->result_rect.width, context->result_rect.height);
gegl_operation_process (operation, context, gegl_pad_get_name (pad),
&context->result_rect);
+ time = gegl_ticks () - time;
+
+ gegl_instrument ("process", gegl_node_get_operation (node), time);
}
if (gegl_pad_get_num_connections (pad) > 1)
diff --git a/gegl/process/gegl-finish-visitor.c b/gegl/process/gegl-finish-visitor.c
index d6f5bb2..630e9b5 100644
--- a/gegl/process/gegl-finish-visitor.c
+++ b/gegl/process/gegl-finish-visitor.c
@@ -26,6 +26,7 @@
#include "graph/gegl-node.h"
#include "graph/gegl-pad.h"
#include "graph/gegl-visitable.h"
+#include "gegl-instrument.h"
#include "operation/gegl-operation.h"
diff --git a/gegl/process/gegl-have-visitor.c b/gegl/process/gegl-have-visitor.c
index 1c5d30f..6c32435 100644
--- a/gegl/process/gegl-have-visitor.c
+++ b/gegl/process/gegl-have-visitor.c
@@ -28,6 +28,7 @@
#include "graph/gegl-node.h"
#include "graph/gegl-pad.h"
#include "graph/gegl-visitable.h"
+#include "gegl-instrument.h"
#include "operation/gegl-operation.h"
static void gegl_have_visitor_class_init (GeglHaveVisitorClass *klass);
@@ -57,6 +58,7 @@ gegl_have_visitor_visit_node (GeglVisitor *self,
GeglNode *node)
{
GeglOperation *operation;
+ glong time = gegl_ticks ();
GEGL_VISITOR_CLASS (gegl_have_visitor_parent_class)->visit_node (self, node);
if (!node)
@@ -70,4 +72,8 @@ gegl_have_visitor_visit_node (GeglVisitor *self,
gegl_node_get_debug_name (node),
node->have_rect.x, node->have_rect.y, node->have_rect.width, node->have_rect.height);
g_mutex_unlock (node->mutex);
+
+ time = gegl_ticks () - time;
+ gegl_instrument ("process", gegl_node_get_operation (node), time);
+ gegl_instrument (gegl_node_get_operation (node), "defined-region", time);
}
diff --git a/gegl/process/gegl-prepare-visitor.c b/gegl/process/gegl-prepare-visitor.c
index b59f30f..af48e91 100644
--- a/gegl/process/gegl-prepare-visitor.c
+++ b/gegl/process/gegl-prepare-visitor.c
@@ -26,6 +26,7 @@
#include "graph/gegl-node.h"
#include "graph/gegl-pad.h"
#include "graph/gegl-visitable.h"
+#include "gegl-instrument.h"
#include "operation/gegl-operation.h"
@@ -59,6 +60,8 @@ gegl_prepare_visitor_visit_node (GeglVisitor *self,
{
GeglOperation *operation = node->operation;
+ glong time = gegl_ticks ();
+
/* call the parent's class (gegl-visitor.c) visit_node function */
GEGL_VISITOR_CLASS (gegl_prepare_visitor_parent_class)->visit_node (self, node);
@@ -95,4 +98,7 @@ gegl_prepare_visitor_visit_node (GeglVisitor *self,
GeglRectangle empty ={0,};
gegl_node_set_need_rect (node, self->context_id, &empty);
}
+ time = gegl_ticks () - time;
+ gegl_instrument ("process", gegl_node_get_operation (node), time);
+ gegl_instrument (gegl_node_get_operation (node), "prepare", time);
}
[
Date Prev][
Date Next] [
Thread Prev][
Thread Next]
[
Thread Index]
[
Date Index]
[
Author Index]
