Commit 01517a5f authored by Øyvind Kolås's avatar Øyvind Kolås

added instrumentation framework

parent d0ddbbf4
2006-09-17 Øyvind Kolås <pippin@gimp.org>
* gegl/gegl-instrument.[ch]: NEW files providing an instrumentation
framework for GEGL.
* gegl/Makefile.am: added gegl-instrument.[ch]
* gegl/gegl-node.[ch]: removed per node instrumentation fields from
structure.
* gegl/gegl-debug-rect-visitor.c: (visit_node): no longer print
instrumentation in debug rects.
* gegl/gegl-eval-mgr.c: (gegl_eval_mgr_apply): instrument
* gegl/gegl-eval-visitor.c: (visit_pad): instrument
* gegl/gegl-have-visitor.c: (visit_node):instrument
* gegl/gegl-prepare-visitor.c: (visit_node): instrument
* gegl/gegl-xml.c: (gegl_xml_parse): instrument
* gegl/gegl.c: (main): instrument
* gegl/gegl-init.c: (gegl_init): instrument,
(gegl_exit): instrument and conditionally print
instrumentation stats if GEGL_DEBUG_TIME is
set.
2006-09-15 Kevin Cozens <kcozens@cvs.gnome.org>
* gegl/Makefile.am: References to gegl-debug-time-visitor.[ch]
......
......@@ -3,6 +3,7 @@
through gegl.h in other places */
#include <stdio.h>
#include <string.h>
#include "gegl-instrument.h"
#include <unistd.h>
#include "gegl-options.h"
......@@ -14,8 +15,6 @@ static gchar *usage = "Usage: %s <xmlfile>\n"
static gint main_interactive (GeglNode *gegl,
GeglOptions *o);
unsigned int babl_ticks (void);
gint
main (gint argc,
gchar **argv)
......@@ -88,9 +87,9 @@ main (gint argc,
break;
case GEGL_RUN_MODE_PNG:
{
glong ticks;
glong timing;
ticks = babl_ticks ();
timing = gegl_ticks ();
GeglNode *output = gegl_graph_create_node (GEGL_GRAPH (gegl),
"operation", "png-save",
"path", o->output,
......@@ -100,8 +99,10 @@ main (gint argc,
gegl_node_connect (output, "input", gegl_graph_output (GEGL_GRAPH (gegl), "output"), "output");
gegl_node_apply (output, "output");
timing = gegl_ticks()-timing;
if (o->stats)
g_print ("usecs: %li", babl_ticks()-ticks);
g_print ("usecs: %li", timing);
g_object_unref (gegl);
g_free (o);
......
......@@ -14,6 +14,7 @@ EXTRA_DIST = \
gegl-eval-mgr.h \
gegl-eval-visitor.h \
gegl-have-visitor.h \
gegl-instrument.h \
gegl-need-visitor.h \
gegl-debug-rect-visitor.h \
gegl-prepare-visitor.h
......@@ -29,6 +30,7 @@ GEGL_sources = \
gegl-graph.c \
gegl-have-visitor.c \
gegl-init.c \
gegl-instrument.c \
gegl-need-visitor.c \
gegl-node.c \
gegl-object.c \
......
......@@ -66,8 +66,7 @@ visit_node (GeglVisitor *self,
"\thave: %ix%i %i,%i\n"
"\tneed: %ix%i %i,%i\n"
"\tresult: %ix%i %i,%i\n"
"\trefs: %i\n"
"\tusecs: %ld",
"\trefs: %i",
gegl_node_get_debug_name (node),
node->have_rect.w, node->have_rect.h,
node->have_rect.x, node->have_rect.y,
......@@ -75,6 +74,5 @@ visit_node (GeglVisitor *self,
node->need_rect.x, node->need_rect.y,
node->result_rect.w, node->result_rect.h,
node->result_rect.x, node->result_rect.y,
node->refs,
node->usecs);
node->refs);
}
......@@ -30,6 +30,7 @@
#include "gegl-need-visitor.h"
#include "gegl-cr-visitor.h"
#include "gegl-debug-rect-visitor.h"
#include "gegl-instrument.h"
#if 0
#include "gegl-debug-time-visitor.h"
#endif
......@@ -80,10 +81,13 @@ gegl_eval_mgr_apply (GeglEvalMgr *self,
GeglVisitor *cr_visitor;
GeglVisitor *eval_visitor;
GeglPad *pad;
glong time = gegl_ticks ();
g_return_if_fail (GEGL_IS_EVAL_MGR (self));
g_return_if_fail (GEGL_IS_NODE (root));
gegl_instrument ("gegl", "process", 0);
if (pad_name == NULL)
pad_name = "output";
pad = gegl_node_get_pad (root, pad_name);
......@@ -158,4 +162,6 @@ gegl_eval_mgr_apply (GeglEvalMgr *self,
root->is_root = FALSE;
g_object_unref (root);
time = gegl_ticks () - time;
gegl_instrument ("gegl", "process", time);
}
......@@ -30,6 +30,7 @@
#include "gegl-node.h"
#include "gegl-pad.h"
#include "gegl-visitable.h"
#include "gegl-instrument.h"
static void gegl_eval_visitor_class_init (GeglEvalVisitorClass *klass);
......@@ -53,7 +54,6 @@ gegl_eval_visitor_init (GeglEvalVisitor *self)
{
}
long babl_ticks (void);
extern long babl_total_usecs;
static void
......@@ -67,12 +67,14 @@ visit_pad (GeglVisitor *self,
if (gegl_pad_is_output (pad))
{
glong start_time = babl_ticks ();
glong babl_timer = babl_total_usecs;
glong time = gegl_ticks ();
glong babl_time = babl_total_usecs;
gegl_operation_process (operation, gegl_pad_get_name (pad));
babl_timer = babl_total_usecs - babl_timer;
node->usecs += (babl_ticks () - start_time) - babl_timer;
node->babl_usecs += babl_timer;
babl_time = babl_total_usecs - babl_time;
time = gegl_ticks ()-time;
gegl_instrument ("process", gegl_node_get_op_type_name (node), time);
gegl_instrument (gegl_node_get_op_type_name (node), "babl", babl_time);
}
else if (gegl_pad_is_input (pad))
{
......
......@@ -29,7 +29,7 @@
#include "gegl-node.h"
#include "gegl-pad.h"
#include "gegl-visitable.h"
#include "gegl-instrument.h"
static void gegl_have_visitor_class_init (GeglHaveVisitorClass *klass);
static void visit_node (GeglVisitor *self,
......@@ -58,9 +58,14 @@ visit_node (GeglVisitor *self,
{
GeglRect rect;
GeglOperation *operation = node->operation;
glong time = gegl_ticks ();
GEGL_VISITOR_CLASS (gegl_have_visitor_parent_class)->visit_node (self, node);
rect = gegl_operation_get_defined_region (operation);
gegl_node_set_have_rect (operation->node, rect.x, rect.y, rect.w, rect.h);
time = gegl_ticks () - time;
gegl_instrument ("process", gegl_node_get_op_type_name (node), time);
gegl_instrument (gegl_node_get_op_type_name (node), "defined-region", time);
}
......@@ -21,6 +21,7 @@
#include "config.h"
#include <babl/babl.h>
#include <glib-object.h>
#include "gegl-instrument.h"
#include "gegl-types.h"
#include "gegl-init.h"
#include "buffer/gegl-buffer-allocator.h"
......@@ -30,6 +31,8 @@
static gboolean gegl_initialized = FALSE;
static glong global_time = 0;
void
gegl_init (int *argc,
char ***argv)
......@@ -38,6 +41,8 @@ gegl_init (int *argc,
if (gegl_initialized)
return;
g_assert (global_time == 0);
global_time = gegl_ticks ();
g_type_init ();
babl_init ();
......@@ -61,17 +66,23 @@ gegl_init (int *argc,
g_free (module_path);
g_free (load_inhibit);
}
gegl_instrument ("gegl", "gegl_init", gegl_ticks () - global_time);
gegl_initialized = TRUE;
}
void gegl_buffer_stats (void);
void gegl_tile_mem_stats (void);
#include <stdio.h>
void
gegl_exit (void)
{
long timing = gegl_ticks ();
gegl_buffer_allocators_free ();
babl_destroy ();
timing = gegl_ticks () - timing;
gegl_instrument ("gegl", "gegl_exit", timing);
/* used when tracking buffer leaks (also tracks tiles, as well
* as tiles.
......@@ -81,4 +92,11 @@ gegl_exit (void)
gegl_buffer_stats ();
gegl_tile_mem_stats ();
}
global_time = gegl_ticks () - global_time;
gegl_instrument ("gegl", "gegl", global_time);
if(getenv("GEGL_DEBUG_TIME")!=NULL)
{
printf ("\n%s", gegl_instrument_xhtml ());
}
}
/* 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 2 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, write to the
* Free Software Foundation, Inc., 51 Franklin Street, Fifth Floor,
* Boston, MA 02110-1301, USA.
*
* Copyright 2006 Øyvind Kolås
*/
#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;
};
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;
}
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_malloc0 (sizeof (Timing));
root->name = g_strdup (parent_name);
}
parent = timing_find (root, parent_name);
if (!parent)
g_warning ("%s", parent_name);
g_assert (parent);
iter = timing_find (parent, name);
if (!iter)
{
iter = g_malloc0 (sizeof (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>
GString *
tab_to (GString *string, gint position)
{
gchar *p;
gint curcount = 0;
gint i;
p = strrchr (string->str, '\n');
if (!p)
{
p=string->str;
position-=1;
}
while (p && *p!='\0')
{
curcount++;
p++;
}
if (curcount > position)
{
g_warning ("tab overflow");
}
else
{
for (i=0;i<=position-curcount;i++)
string = g_string_append (string, " ");
}
return string;
}
static gchar *eight[]={
" ",
"▏",
"▍",
"▌",
"▋",
"▊",
"▉",
"█"};
GString *
bar (GString *string, gint width, gfloat value)
{
gboolean utf8 = TRUE;
gint i;
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;
}
gchar *
gegl_instrument_xhtml (void)
{
GString *s = g_string_new ("");
gchar *ret;
Timing *iter = root;
while (iter)
{
gchar *buf;
s = tab_to (s, timing_depth (iter) * 2);
s = g_string_append (s, iter->name);
s = tab_to (s, 23);
buf = g_strdup_printf ("%f", seconds (iter->usecs));
s = g_string_append (s, buf);
g_free (buf);
s = tab_to (s, 34);
s = bar (s, 46, normalized (iter->usecs));
s = g_string_append (s, "\n");
if (timing_depth(iter_next (iter)) < timing_depth (iter))
{
s = tab_to (s, timing_depth (iter) * 2);
s = g_string_append (s, "other");
s = tab_to (s, 23);
buf = g_strdup_printf ("%f", seconds (timing_other (iter->parent)));
s = g_string_append (s, buf);
g_free (buf);
s = tab_to (s, 34);
s = bar (s, 46, normalized (timing_other (iter->parent)));
s = g_string_append (s, "\n");
}
iter = iter_next (iter);
}
ret = g_strdup (s->str);
g_string_free (s, TRUE);
return ret;
}
/* 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 2 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, write to the
* Free Software Foundation, Inc., 51 Franklin Street, Fifth Floor,
* Boston, MA 02110-1301, USA.
*
* Copyright 2006 Øyvind Kolås
*/
#ifndef GEGL_INSTRUMENT_H
#define GEGL_INSTRUMENT_H
long gegl_ticks (void);
void
gegl_instrument (const gchar *parent,
const gchar *scale,
long usecs);
gchar *
gegl_instrument_xhtml (void);
#endif
......@@ -117,8 +117,6 @@ gegl_node_init (GeglNode *self)
self->refs = 0;
self->enabled = TRUE;
self->is_graph = FALSE;
self->usecs = 0;
self->babl_usecs = 0;
}
static void
......
......@@ -63,9 +63,6 @@ struct _GeglNode
when it drops to zero, the op is asked to clean it's pads
*/
gboolean enabled;
glong usecs;
glong babl_usecs;
};
struct _GeglNodeClass
......
......@@ -28,6 +28,7 @@
#include "gegl-node.h"
#include "gegl-pad.h"
#include "gegl-visitable.h"
#include "gegl-instrument.h"
static void gegl_prepare_visitor_class_init (GeglPrepareVisitorClass *klass);
......@@ -58,6 +59,7 @@ visit_node (GeglVisitor *self,
GeglOperation *operation = node->operation;
GEGL_VISITOR_CLASS (gegl_prepare_visitor_parent_class)->visit_node (self, node);
glong time = gegl_ticks ();
/* prepare the operation for the coming evaluation (all properties
* should be set now).
......@@ -80,4 +82,7 @@ visit_node (GeglVisitor *self,
gegl_operation_prepare (operation);
gegl_node_set_need_rect (node, 0, 0, 0, 0);
time = gegl_ticks () - time;
gegl_instrument ("process", gegl_node_get_op_type_name (node), time);
gegl_instrument (gegl_node_get_op_type_name (node), "prepare", time);
}
......@@ -28,6 +28,7 @@
#include "gegl-node.h"
#include "gegl-pad.h"
#include "gegl-color.h"
#include "gegl-instrument.h"
typedef struct _ParseData ParseData;
......@@ -307,6 +308,7 @@ void each_ref (gpointer value,
GeglNode *gegl_xml_parse (const gchar *xmldata)
{
glong time = gegl_ticks ();
GeglNode *ret;
ParseData *pd;
GMarkupParseContext *context;
......@@ -326,6 +328,9 @@ GeglNode *gegl_xml_parse (const gchar *xmldata)
ret = GEGL_NODE (pd->gegl);
g_free (pd);
time = gegl_ticks () - time;
gegl_instrument ("gegl", "gegl_xml_parse", time);
return ret;
}
......
......@@ -3,6 +3,7 @@
through gegl.h in other places */
#include <stdio.h>
#include <string.h>
#include "gegl-instrument.h"
#include <unistd.h>
#include "gegl-options.h"
......@@ -14,8 +15,6 @@ static gchar *usage = "Usage: %s <xmlfile>\n"
static gint main_interactive (GeglNode *gegl,
GeglOptions *o);
unsigned int babl_ticks (void);
gint
main (gint argc,
gchar **argv)
......@@ -88,9 +87,9 @@ main (gint argc,
break;
case GEGL_RUN_MODE_PNG:
{
glong ticks;
glong timing;
ticks = babl_ticks ();
timing = gegl_ticks ();
GeglNode *output = gegl_graph_create_node (GEGL_GRAPH (gegl),
"operation", "png-save",
"path", o->output,
......@@ -100,8 +99,10 @@ main (gint argc,
gegl_node_connect (output, "input", gegl_graph_output (GEGL_GRAPH (gegl), "output"), "output");
gegl_node_apply (output, "output");
timing = gegl_ticks()-timing;
if (o->stats)
g_print ("usecs: %li", babl_ticks()-ticks);
g_print ("usecs: %li", timing);
g_object_unref (gegl);
g_free (o);
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment