add --vips-profile

only added a few gates so far, try a visualiser next

ChangeLog

@@ -23,6 +23,7 @@
 - support XYZ as a PCS for vips_icc_import() and vips_icc_export()
 - add --strip option to jpegsave
 - added vips_gaussblur() convenience function
+- added --vips-profile, records and dumps thread timing info 
 
 15/11/13	started 7.36.4
 - improve compat with im_init_world()

TODO

@@ -1,3 +1,6 @@
+
+- parse and graph vips-profile data 
+
 - we're spending a lot of time on threading
 
 	$ time vips sharpen x.v x2.v
@@ -11,6 +14,19 @@
 
   almost 50% of CPU! ouch
 
+  could be just overcalculation on overlaps? do we get more overcalculation
+  with more threads?
+
+  valgrind finds no interesting functions in the profile for vips sharpen,
+  just 
+
+  	Lab2XYZ			20% 
+	conv_gen		15% 
+	extract_band		8%
+	etc. 
+
+  nor any difference between 1 thread and n thread runs
+
 - vips_gaussblur() should switch to float prec if given a float image?
 
   same for vips_conv()?
@@ -33,9 +49,6 @@
 
   note on memuse page
 
-- do much fancier profiling with timing on all locks saved in memory and
-  dumped on exit
-
 - use the webp advanced encoding api to set a write function for webp save to
   file
 

configure.ac

@@ -316,6 +316,13 @@ AC_CHECK_LIB(m,hypot,[AC_DEFINE(HAVE_HYPOT,1,[have hypot() in libm.])])
 PKG_CHECK_MODULES(REQUIRED, glib-2.0 >= 2.6 gmodule-2.0 libxml-2.0 gobject-2.0)
 PACKAGES_USED="$PACKAGES_USED glib-2.0 libxml-2.0 gmodule-2.0 gobject-2.0"
 
+# after 2.28 we have a monotonic timer
+PKG_CHECK_MODULES(THREADS, glib-2.0 >= 2.28,[
+  AC_DEFINE(HAVE_MONOTONIC_TIME,1,[define if your glib has g_get_monotonic_time().])
+  ],[
+  ]
+)
+
 # after 2.32 there are a new set of thread functions, annoyingly
 PKG_CHECK_MODULES(THREADS, glib-2.0 >= 2.32,[
   AC_DEFINE(HAVE_MUTEX_INIT,1,[define if your glib has g_mutex_init().])

libvips/colour/XYZ2Lab.c

@@ -57,6 +57,7 @@
 #include <math.h>
 
 #include <vips/vips.h>
+#include <vips/internal.h>
 
 #include "pcolour.h"
 
@@ -106,26 +107,24 @@ table_init( void *client )
 	return( NULL );
 }
 
-static void
-vips_XYZ2Lab_make_tables( void )
-{
-	static GOnce once = G_ONCE_INIT;
-
-	(void) g_once( &once, table_init, NULL );
-}
-
 /* Process a buffer of data.
  */
 static void
 vips_XYZ2Lab_line( VipsColour *colour, VipsPel *out, VipsPel **in, int width )
 {
+	static GOnce once = G_ONCE_INIT;
+
 	VipsXYZ2Lab *XYZ2Lab = (VipsXYZ2Lab *) colour;
 	float *p = (float *) in[0];
 	float *q = (float *) out;
 
 	int x;
 
-        vips_XYZ2Lab_make_tables();
+	(void) g_once( &once, table_init, NULL );
+
+	g_mutex_lock( vips__global_lock );
+	VIPS_OPERATION( colour )->pixels += width;
+	g_mutex_unlock( vips__global_lock );
 
 	for( x = 0; x < width; x++ ) {
 		float nX, nY, nZ;

libvips/convolution/im_conv.c

@@ -199,9 +199,14 @@ static int
 conv_evalstart( Conv *conv )
 {
 	/* Reset underflow/overflow count.
-	 */
+	 *
+	 * This often doesn't get called until eval has already finished, so
+	 * resetting here just wipes all records. 
+	 *
 	conv->overflow = 0;
 	conv->underflow = 0;
+	 *
+	 */
 
         return( 0 );
 }
@@ -209,12 +214,12 @@ conv_evalstart( Conv *conv )
 static int
 conv_evalend( Conv *conv )
 {
-	/* Print underflow/overflow count.
+	if( conv->overflow ) 
-	 */
+		vips_info( "im_conv", 
-	if( conv->overflow || conv->underflow )
+			_( "%d overflows detected" ), conv->overflow ); 
-		im_warn( "im_conv", 
+	if( conv->underflow )
-			_( "%d overflows and %d underflows detected" ),
+		vips_info( "im_conv", 
-			conv->overflow, conv->underflow );
+			_( "%d underflows detected" ), conv->underflow );
 
         return( 0 );
 }

libvips/include/vips/Makefile.am

@@ -1,6 +1,7 @@
 pkginclude_HEADERS = \
 	basic.h \
 	type.h \
+	gate.h \
 	almostdeprecated.h \
 	deprecated.h \
 	arithmetic.h \

libvips/include/vips/gate.h

@@ -0,0 +1,94 @@
+/* Thread profiling.
+ */
+
+/*
+
+    This file is part of VIPS.
+    
+    VIPS 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.
+
+    This program 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 this program; if not, write to the Free Software
+    Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
+    02110-1301  USA
+
+ */
+
+/*
+
+    These files are distributed with VIPS - http://www.vips.ecs.soton.ac.uk
+
+ */
+
+#ifndef VIPS_GATE_H
+#define VIPS_GATE_H
+
+#ifdef __cplusplus
+extern "C" {
+#endif /*__cplusplus*/
+
+#include <vips/vips.h>
+
+#define VIPS_GATE_SIZE (10000)
+
+/* A set of timing records. i is the index of the next slot we fill. 
+ */
+typedef struct _VipsThreadGateBlock {
+	struct _VipsThreadGateBlock *prev;
+
+	gint64 time[VIPS_GATE_SIZE];
+	int i;
+} VipsThreadGateBlock; 
+
+/* What we track for each gate-name.
+ */
+typedef struct _VipsThreadGate {
+	const char *name;
+	VipsThreadGateBlock *start;
+	VipsThreadGateBlock *stop;
+} VipsThreadGate; 
+
+/* One of these in per-thread private storage. 
+ */
+
+typedef struct _VipsThreadProfile {
+	/*< private >*/
+
+	const char *name;
+	GThread *thread;
+	GHashTable *gates;
+} VipsThreadProfile; 
+
+#define VIPS_GATE_START( NAME ) \
+G_STMT_START { \
+	if( vips__thread_profile ) \
+		vips__thread_gate_start( NAME ); \
+} G_STMT_END
+
+#define VIPS_GATE_STOP( NAME ) \
+G_STMT_START { \
+	if( vips__thread_profile ) \
+		vips__thread_gate_stop( NAME ); \
+} G_STMT_END
+
+extern gboolean vips__thread_profile;
+
+void vips__thread_profile_attach( const char *thread_name );
+void vips__thread_profile_stop( void );
+
+void vips__thread_gate_start( const char *gate_name ); 
+void vips__thread_gate_stop( const char *gate_name ); 
+
+#endif /*VIPS_GATE_H*/
+
+#ifdef __cplusplus
+}
+#endif /*__cplusplus*/

libvips/include/vips/operation.h

@@ -74,6 +74,10 @@ typedef struct _VipsOperation {
 	guint hash;
 	gboolean found_hash;
 
+	/* Pixels calculated ... handy for measuring over calculation.
+	 */
+	int pixels;
+
 } VipsOperation;
 
 typedef struct _VipsOperationClass {

libvips/include/vips/vips.h

@@ -101,6 +101,7 @@ extern "C" {
 #include <vips/util.h>
 #include <vips/object.h>
 #include <vips/type.h>
+#include <vips/gate.h>
 
 #include <vips/version.h>
 #include <vips/rect.h>
@@ -160,7 +161,7 @@ extern "C" {
 			vips__get_sizeof_vipsobject() ), \
 		vips_info( "vips_init", \
 			"application has sizeof(VipsObject) == %zd", \
-			sizeof( VipsObject() ) ), \
+			sizeof( VipsObject ) ), \
 		vips_error( "vips_init", "ABI mismatch" ), \
 		-1 ) : \
 		vips__init( ARGV0 ))

libvips/iofuncs/Makefile.am

@@ -2,6 +2,7 @@ noinst_LTLIBRARIES = libiofuncs.la
 
 libiofuncs_la_SOURCES = \
 	type.c \
+	gate.c \
 	enumtypes.c \
 	object.c \
 	base64.h \

libvips/iofuncs/gate.c

@@ -0,0 +1,247 @@
+/* gate.c --- thread profiling
+ *
+ * Written on: 18 nov 13
+ */
+
+/*
+
+    This file is part of VIPS.
+    
+    VIPS 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.
+
+    This program 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 this program; if not, write to the Free Software
+    Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
+    02110-1301  USA
+
+ */
+
+/*
+
+    These files are distributed with VIPS - http://www.vips.ecs.soton.ac.uk
+
+ */
+
+/*
+#define VIPS_DEBUG
+ */
+
+#ifdef HAVE_CONFIG_H
+#include <config.h>
+#endif /*HAVE_CONFIG_H*/
+#include <vips/intl.h>
+
+#include <vips/vips.h>
+#include <vips/internal.h>
+
+gboolean vips__thread_profile = FALSE;
+
+static GPrivate *vips_thread_profile_key = NULL;
+
+static FILE *vips__thread_fp = NULL;;
+
+static void
+vips_thread_gate_block_save( VipsThreadGateBlock *block, FILE *fp )
+{
+	int i;
+
+	for( i = block->i - 1; i >= 0; i-- )
+		fprintf( fp, "%" G_GINT64_FORMAT " ", block->time[i] );
+	fprintf( fp, "\n" ); 
+	if( block->prev )
+		vips_thread_gate_block_save( block->prev, fp ); 
+}
+
+static void
+vips_thread_profile_save_gate( VipsObject *key, VipsObject *value, FILE *fp )
+{
+	VipsThreadGate *gate = (VipsThreadGate *) value;
+
+	fprintf( fp, "gate: %s\n", gate->name );
+	fprintf( fp, "start:\n" );
+	vips_thread_gate_block_save( gate->start, fp );
+	fprintf( fp, "stop:\n" );
+	vips_thread_gate_block_save( gate->stop, fp );
+}
+
+static void
+vips_thread_profile_save( VipsThreadProfile *profile, FILE *fp )
+{
+	g_mutex_lock( vips__global_lock );
+
+	fprintf( fp, "thread: %s (%p)\n", profile->name, profile );
+	g_hash_table_foreach( profile->gates, 
+		(GHFunc) vips_thread_profile_save_gate, fp );
+
+	g_mutex_unlock( vips__global_lock );
+}
+
+
+static void
+vips_thread_profile_free( VipsThreadProfile *profile )
+{
+	if( vips__thread_fp )
+		vips_thread_profile_save( profile, vips__thread_fp ); 
+
+	VIPS_FREEF( g_hash_table_destroy, profile->gates );
+	VIPS_FREE( profile );
+}
+
+void
+vips__thread_profile_stop( void )
+{
+	if( vips__thread_profile ) 
+		VIPS_FREEF( fclose, vips__thread_fp ); 
+}
+
+static void
+vips_thread_gate_block_free( VipsThreadGateBlock *block )
+{
+	VIPS_FREEF( vips_thread_gate_block_free, block->prev );
+	VIPS_FREE( block );
+}
+
+static void
+vips_thread_gate_free( VipsThreadGate *gate )
+{
+	VIPS_FREEF( vips_thread_gate_block_free, gate->start );
+	VIPS_FREEF( vips_thread_gate_block_free, gate->stop );
+	VIPS_FREE( gate ); 
+}
+
+static void
+vips__thread_profile_init( void )
+{
+#ifdef HAVE_PRIVATE_INIT
+	static GPrivate private = 
+		G_PRIVATE_INIT( (GDestroyNotify) vips_thread_profile_free );
+
+	vips_thread_profile_key = &private;
+#else
+	if( !vips_thread_profile_key ) 
+		vips_thread_profile_key = g_private_new( 
+			(GDestroyNotify) vips_thread_profile_free );
+#endif
+
+	if( vips__thread_profile ) {
+		if( !(vips__thread_fp = 
+			vips__file_open_write( "vips-profile.txt", TRUE )) )
+			vips_error_exit( "unable to create profile log" ); 
+
+		printf( "recording profile in vips-profile.txt\n" );  
+	}
+}
+
+void
+vips__thread_profile_attach( const char *thread_name )
+{
+	static GOnce once = G_ONCE_INIT;
+
+	VipsThreadProfile *profile;
+
+	g_once( &once, (GThreadFunc) vips__thread_profile_init, NULL );
+
+	g_assert( !g_private_get( vips_thread_profile_key ) );
+
+	profile = g_new( VipsThreadProfile, 1 );
+	profile->name = thread_name; 
+	profile->gates = g_hash_table_new_full( 
+		g_str_hash, g_str_equal, 
+		NULL, (GDestroyNotify) vips_thread_gate_free );
+	g_private_set( vips_thread_profile_key, profile );
+}
+
+static VipsThreadProfile *
+vips_thread_profile_get( void )
+{
+	return( g_private_get( vips_thread_profile_key ) ); 
+}
+
+static VipsThreadGate *
+vips_thread_gate_new( const char *gate_name ) 
+{
+	VipsThreadGate *gate;
+
+	gate = g_new( VipsThreadGate, 1 );
+	gate->name = gate_name; 
+	gate->start = g_new0( VipsThreadGateBlock, 1 );
+	gate->stop = g_new0( VipsThreadGateBlock, 1 );
+
+	return( gate );
+}
+
+static void
+vips_thread_gate_block_add( VipsThreadGateBlock **block )
+{
+	VipsThreadGateBlock *new_block;
+
+	new_block = g_new0( VipsThreadGateBlock, 1 );
+	new_block->prev = *block;
+	*block = new_block;
+}
+
+static gint64
+vips_get_time( void )
+{
+#ifdef HAVE_MONOTONIC_TIME
+	return( g_get_monotonic_time() );  
+#else
+	GTimeVal time;
+
+	g_get_current_time( &time );
+
+	return( (gint64) time.tv_usec ); 
+#endif
+}
+
+void
+vips__thread_gate_start( const char *gate_name )
+{
+	VipsThreadProfile *profile;
+
+	if( (profile = vips_thread_profile_get()) ) { 
+		VipsThreadGate *gate;
+
+		if( !(gate = 
+			g_hash_table_lookup( profile->gates, gate_name )) ) {
+			gate = vips_thread_gate_new( gate_name );
+			g_hash_table_insert( profile->gates, 
+				(char *) gate_name, gate );
+		}
+
+		if( gate->start->i >= VIPS_GATE_SIZE )
+			vips_thread_gate_block_add( &gate->start );
+
+		gate->start->time[gate->start->i++] = vips_get_time();
+	}
+}
+
+void
+vips__thread_gate_stop( const char *gate_name )
+{
+	VipsThreadProfile *profile;
+
+	if( (profile = vips_thread_profile_get()) ) { 
+		VipsThreadGate *gate;
+
+		if( !(gate = 
+			g_hash_table_lookup( profile->gates, gate_name )) ) {
+			gate = vips_thread_gate_new( gate_name );
+			g_hash_table_insert( profile->gates, 
+				(char *) gate_name, gate );
+		}
+
+		if( gate->stop->i >= VIPS_GATE_SIZE )
+			vips_thread_gate_block_add( &gate->stop );
+
+		gate->stop->time[gate->stop->i++] = vips_get_time();
+	}
+}

libvips/iofuncs/init.c

@@ -371,8 +371,11 @@ vips_shutdown( void )
 #endif /*DEBUG*/
 
 	vips_cache_drop_all();
+
 	im_close_plugins();
 
+	vips__thread_profile_stop();
+
 	/* In dev releases, always show leaks. But not more than once, it's
 	 * annoying.
 	 */
@@ -460,6 +463,9 @@ static GOptionEntry option_entries[] = {
 	{ "vips-leak", 0, 0, 
 		G_OPTION_ARG_NONE, &vips__leak, 
 		N_( "leak-check on exit" ), NULL },
+	{ "vips-profile", 0, 0, 
+		G_OPTION_ARG_NONE, &vips__thread_profile, 
+		N_( "profile and dump timing on exit" ), NULL },
 	{ "vips-disc-threshold", 0, 0, 
 		G_OPTION_ARG_STRING, &vips__disc_threshold, 
 		N_( "images larger than N are decompressed to disc" ), "N" },

libvips/iofuncs/operation.c

@@ -93,8 +93,17 @@ G_DEFINE_ABSTRACT_TYPE( VipsOperation, vips_operation, VIPS_TYPE_OBJECT );
 static void
 vips_operation_finalize( GObject *gobject )
 {
+	VipsOperation *operation = VIPS_OPERATION( gobject );
+
 	VIPS_DEBUG_MSG( "vips_operation_finalize: %p\n", gobject );
 
+	if( operation->pixels ) {
+		VipsObjectClass *class = VIPS_OBJECT_GET_CLASS( gobject );
+
+		vips_info( class->nickname, 
+			_( "%d pixels calculated" ), operation->pixels ); 
+	}
+
 	G_OBJECT_CLASS( vips_operation_parent_class )->finalize( gobject );
 }
 

libvips/iofuncs/sinkdisc.c

@@ -168,8 +168,10 @@ wbuffer_write( WriteBuffer *wbuffer )
 	VIPS_DEBUG_MSG( "wbuffer_write: %d bytes from wbuffer %p\n", 
 		wbuffer->region->bpl * wbuffer->area.height, wbuffer );
 
+	VIPS_GATE_START( "wbuffer_write: " ); 
 	wbuffer->write_errno = write->write_fn( wbuffer->region, 
 		&wbuffer->area, write->a );
+	VIPS_GATE_STOP( "wbuffer_write: " ); 
 }
 
 /* Run this as a thread to do a BG write.
@@ -182,14 +184,18 @@ wbuffer_write_thread( void *data )
 	for(;;) {
 		/* Wait to be told to write.
 		 */
+		VIPS_GATE_START( "wbuffer_write_thread: wait go" ); 
 		vips_semaphore_down( &wbuffer->go );
+		VIPS_GATE_STOP( "wbuffer_write_thread: wait go" ); 
 
 		if( wbuffer->kill )
 			break;
 
 		/* Now block until the last worker finishes on this buffer.
 		 */
+		VIPS_GATE_START( "wbuffer_write_thread: wait tile" ); 
 		vips_semaphore_downn( &wbuffer->nwrite, 0 );
+		VIPS_GATE_STOP( "wbuffer_write_thread: wait tile" ); 
 
 		wbuffer_write( wbuffer );
 

libvips/iofuncs/threadpool.c

@@ -43,7 +43,6 @@
  */
 
 /* 
-#define TIME_THREAD
 #define VIPS_DEBUG_RED
 #define VIPS_DEBUG
  */
@@ -157,16 +156,43 @@ vips_g_cond_free( GCond *cond )
 #endif
 }
 
+typedef struct {
+	const char *domain; 
+	GThreadFunc func; 
+	gpointer data;
+} VipsThreadInfo; 
+
+static void *
+vips_thread_run( gpointer data )
+{
+	VipsThreadInfo *info = (VipsThreadInfo *) data;
+
+	void *result;
+
+	if( vips__thread_profile ) 
+		vips__thread_profile_attach( info->domain );
+
+	result = info->func( info->data );
+
+	return( result ); 
+}
+
 GThread *
 vips_g_thread_new( const char *domain, GThreadFunc func, gpointer data )
 {
 	GThread *thread;
+	VipsThreadInfo *info; 
 	GError *error = NULL;
 
+	info = g_new( VipsThreadInfo, 1 ); 
+	info->domain = domain;
+	info->func = func;
+	info->data = data;
+
 #ifdef HAVE_THREAD_NEW
-	thread = g_thread_try_new( domain, func, data, &error );
+	thread = g_thread_try_new( domain, vips_thread_run, info, &error );
 #else
-	thread = g_thread_create( func, data, TRUE, &error );
+	thread = g_thread_create( vips_thread_run, data, info, &error );
 #endif
 
 	if( !thread ) {
@@ -430,10 +456,6 @@ typedef struct {
 	 */
 	gboolean error;	
 
-#ifdef TIME_THREAD
-	double *btime, *etime;
-	int tpos;
-#endif /*TIME_THREAD*/
 } VipsThread;
 
 /* What we track for a group of threads working together.
@@ -474,37 +496,6 @@ typedef struct _VipsThreadpool {
 	gboolean stop;
 } VipsThreadpool;
 
-#ifdef TIME_THREAD
-/* Size of time buffers.
- */
-#define TBUF_SIZE (20000)
-static GTimer *thread_timer = NULL;
-#endif /*TIME_THREAD*/
-
-#ifdef TIME_THREAD
-/* Save time buffers.
- */
-static int
-vips_thread_save_time_buffers( VipsThread *thr )
-{
-	int i;
-	static int rn = 1;
-	FILE *fp;
-	char name[256];
-
-	vips_snprintf( name, 256, "time%d", rn++ );
-	printf( "vips_thread_save_time_buffers: "
-		"saving buffer to \"%s\"\n", name );
-	if( !(fp = vips__file_open_write( name, TRUE )) ) 
-		return( -1 );
-	for( i = 0; i < thr->tpos; i++ )
-		fprintf( fp, "%g, %g\n", thr->btime[i], thr->etime[i] );
-	fclose( fp );
-
-	return( 0 );
-}
-#endif /*TIME_THREAD*/
-
 /* Junk a thread.
  */
 static void
@@ -524,11 +515,6 @@ vips_thread_free( VipsThread *thr )
 
 	VIPS_FREEF( g_object_unref, thr->state );
 	thr->pool = NULL;
-
-#ifdef TIME_THREAD
-	if( thr->btime )
-		(void) vips_thread_save_time_buffers( thr );
-#endif /*TIME_THREAD*/
 }
 
 static int
@@ -549,38 +535,6 @@ vips_thread_allocate( VipsThread *thr )
 	return( 0 );
 }
 
-static int
-vips_thread_work( VipsThread *thr )
-{
-	VipsThreadpool *pool = thr->pool;
-	int result;
-
-	result = 0;
-
-#ifdef TIME_THREAD
-	/* Note start time.
-	 */
-	if( thr->btime && thr->tpos < TBUF_SIZE )
-		thr->btime[thr->tpos] = 
-			g_timer_elapsed( thread_timer, NULL );
-#endif /*TIME_THREAD*/
-
-	if( pool->work( thr->state, pool->a ) ) 
-		result = -1;
-
-#ifdef TIME_THREAD
-	/* Note stop time.
-	 */
-	if( thr->etime && thr->tpos < TBUF_SIZE ) {
-		thr->etime[thr->tpos] = 
-			g_timer_elapsed( thread_timer, NULL );
-		thr->tpos += 1;
-	}
-#endif /*TIME_THREAD*/
-
-	return( result );
-}
-
 /* The main loop: get some work, do it! Can run from many worker threads, or 
  * from the main thread if threading is off. 
  */
@@ -592,8 +546,12 @@ vips_thread_work_unit( VipsThread *thr )
 	if( thr->error )
 		return;
 
+	VIPS_GATE_START( "vips_thread_work_unit: allocate-wait" ); 
+
 	g_mutex_lock( pool->allocate_lock );
 
+	VIPS_GATE_STOP( "vips_thread_work_unit: allocate-wait" ); 
+
 	/* Has another worker signaled stop while we've been working?
 	 */
 	if( pool->stop ) {
@@ -619,10 +577,12 @@ vips_thread_work_unit( VipsThread *thr )
 
 	/* Process a work unit.
 	 */
-	if( vips_thread_work( thr ) ) {
+	VIPS_GATE_START( "vips_thread_work_unit: work" ); 
+	if( pool->work( thr->state, pool->a ) ) { 
 		thr->error = TRUE;
 		pool->error = TRUE;
 	}
+	VIPS_GATE_STOP( "vips_thread_work_unit: work" ); 
 }
 
 /* What runs as a thread ... loop, waiting to be told to do stuff.
@@ -635,6 +595,8 @@ vips_thread_main_loop( void *a )
 
 	g_assert( pool == thr->pool );
 
+	VIPS_GATE_START( "vips_thread_main_loop:" ); 
+
 	/* Process work units! Always tick, even if we are stopping, so the
 	 * main thread will wake up for exit. 
 	 */
@@ -650,6 +612,8 @@ vips_thread_main_loop( void *a )
 	 */
 	vips_semaphore_up( &pool->finish );
 
+	VIPS_GATE_STOP( "vips_thread_main_loop:" ); 
+
         return( NULL );
 }
 
@@ -667,26 +631,12 @@ vips_thread_new( VipsThreadpool *pool )
 	thr->thread = NULL;
 	thr->exit = 0;
 	thr->error = 0;
-#ifdef TIME_THREAD
-	thr->btime = NULL;
-	thr->etime = NULL;
-	thr->tpos = 0;
-#endif /*TIME_THREAD*/
 
 	/* We can't build the state here, it has to be done by the worker
 	 * itself the first time that allocate runs so that any regions are 
 	 * owned by the correct thread.
 	 */
 
-#ifdef TIME_THREAD
-	thr->btime = VIPS_ARRAY( pool->im, TBUF_SIZE, double );
-	thr->etime = VIPS_ARRAY( pool->im, TBUF_SIZE, double );
-	if( !thr->btime || !thr->etime ) {
-		vips_thread_free( thr );
-		return( NULL );
-	}
-#endif /*TIME_THREAD*/
-
 	if( !(thr->thread = vips_g_thread_new( "worker", 
 		vips_thread_main_loop, thr )) ) {  
 		vips_thread_free( thr );
@@ -908,11 +858,6 @@ vips_threadpool_run( VipsImage *im,
 	VipsThreadpool *pool; 
 	int result;
 
-#ifdef TIME_THREAD
-	if( !thread_timer )
-		thread_timer = g_timer_new();
-#endif /*TIME_THREAD*/
-
 	if( !(pool = vips_threadpool_new( im )) )
 		return( -1 );