add lots of instrumentation

also svg output

libvips/arithmetic/arithmetic.c

@@ -478,6 +478,8 @@ vips_arithmetic_gen( VipsRegion *or,
 	p[i] = NULL;
 	q = (VipsPel *) VIPS_REGION_ADDR( or, r->left, r->top );
 
+	VIPS_GATE_START( "vips_arithmetic_gen: work" );
+
 	for( y = 0; y < r->height; y++ ) {
 		class->process_line( arithmetic, q, p, r->width );
 
@@ -486,6 +488,8 @@ vips_arithmetic_gen( VipsRegion *or,
 		q += VIPS_REGION_LSKIP( or );
 	}
 
+	VIPS_GATE_STOP( "vips_arithmetic_gen: work" );
+
 	return( 0 );
 }
 

libvips/colour/XYZ2Lab.c

@@ -122,10 +122,6 @@ vips_XYZ2Lab_line( VipsColour *colour, VipsPel *out, VipsPel **in, int width )
 
 	(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;
 		int i;

libvips/colour/colour.c

@@ -259,6 +259,8 @@ vips_colour_gen( VipsRegion *or,
 		if( vips_region_prepare( ir[i], r ) ) 
 			return( -1 );
 
+	VIPS_GATE_START( "vips_colour_gen: work" ); 
+
 	for( y = 0; y < r->height; y++ ) {
 		for( i = 0; ir[i]; i++ )
 			p[i] = VIPS_REGION_ADDR( ir[i], r->left, r->top + y );
@@ -268,6 +270,8 @@ vips_colour_gen( VipsRegion *or,
 		class->process_line( colour, q, p, r->width );
 	}
 
+	VIPS_GATE_STOP( "vips_colour_gen: work" ); 
+
 	return( 0 );
 }
 

libvips/conversion/bandary.c

@@ -100,6 +100,8 @@ vips_bandary_gen( VipsRegion *or, void *seq, void *a, void *b, gboolean *stop )
 	p[i] = NULL;
 	q = VIPS_REGION_ADDR( or, r->left, r->top );
 
+	VIPS_GATE_START( "vips_bandary_gen: work" ); 
+
 	for( y = 0; y < r->height; y++ ) {
 		class->process_line( bandary, q, p, r->width );
 
@@ -108,6 +110,8 @@ vips_bandary_gen( VipsRegion *or, void *seq, void *a, void *b, gboolean *stop )
 		q += VIPS_REGION_LSKIP( or );
 	}
 
+	VIPS_GATE_STOP( "vips_bandary_gen: work" ); 
+
 	return( 0 );
 }
 

libvips/conversion/cast.c

@@ -339,6 +339,8 @@ vips_cast_gen( VipsRegion *or, void *vseq, void *a, void *b,
 	if( vips_region_prepare( ir, r ) )
 		return( -1 );
 
+	VIPS_GATE_START( "vips_cast_gen: work" );
+
 	for( y = to; y < bo; y++ ) {
 		VipsPel *in = VIPS_REGION_ADDR( ir, le, y ); 
 		VipsPel *out = VIPS_REGION_ADDR( or, le, y ); 
@@ -419,6 +421,8 @@ vips_cast_gen( VipsRegion *or, void *vseq, void *a, void *b,
 		} 
 	}
 
+	VIPS_GATE_STOP( "vips_cast_gen: work" );
+
 	return( 0 );
 }
 

libvips/conversion/embed.c

@@ -126,7 +126,8 @@ vips_embed_find_edge( VipsEmbed *embed, VipsRect *r, int i, VipsRect *out )
 	 * right edge. If we're strictly up/down/left/right of the image, we
 	 * can trim.
 	 */
-	if( i == 0 || i == 2 ) {
+	if( i == 0 || 
+		i == 2 ) {
 		VipsRect extend;
 
 		/* Above or below.
@@ -136,7 +137,8 @@ vips_embed_find_edge( VipsEmbed *embed, VipsRect *r, int i, VipsRect *out )
 		extend.height = embed->height;
 		vips_rect_intersectrect( out, &extend, out );
 	}
-	if( i == 1 || i == 3 ) {
+	if( i == 1 || 
+		i == 3 ) {
 		VipsRect extend;
 
 		/* Left or right.
@@ -176,6 +178,8 @@ vips_embed_paint_edge( VipsEmbed *embed,
 	VipsPel *q;
 	int y;
 
+	VIPS_GATE_START( "vips_embed_paint_edge: work" );
+
 	/* Pixels left to paint.
 	 */
 	todo = *r;
@@ -209,6 +213,8 @@ vips_embed_paint_edge( VipsEmbed *embed,
 			memcpy( q, p, bs * todo.width );
 		}
 	}
+
+	VIPS_GATE_STOP( "vips_embed_paint_edge: work" );
 }
 
 static int
@@ -258,19 +264,29 @@ vips_embed_gen( VipsRegion *or, void *seq, void *a, void *b, gboolean *stop )
 	switch( embed->extend ) {
 	case VIPS_EXTEND_BLACK:
 	case VIPS_EXTEND_WHITE:
+		VIPS_GATE_START( "vips_embed_gen: work1" );
+
 		/* Paint the borders a solid value.
 		 */
 		for( i = 0; i < 8; i++ )
 			vips_region_paint( or, &embed->border[i], 
 				embed->extend == 0 ? 0 : 255 );
+
+		VIPS_GATE_STOP( "vips_embed_gen: work1" );
+
 		break;
 
 	case VIPS_EXTEND_BACKGROUND:
+		VIPS_GATE_START( "vips_embed_gen: work2" );
+
 		/* Paint the borders a solid value.
 		 */
 		for( i = 0; i < 8; i++ )
 			vips_region_paint_pel( or, &embed->border[i], 
 				embed->ink ); 
+
+		VIPS_GATE_STOP( "vips_embed_gen: work2" );
+
 		break;
 
 	case VIPS_EXTEND_COPY:

libvips/conversion/sequential.c

@@ -129,8 +129,12 @@ vips_sequential_generate( VipsRegion *or,
 			"request for line %d, height %d", 
 			r->top, r->height );
 
+	VIPS_GATE_START( "vips_sequential_generate: wait" );
+
 	g_mutex_lock( sequential->lock );
 
+	VIPS_GATE_STOP( "vips_sequential_generate: wait" );
+
 	VIPS_DEBUG_MSG_GREEN( "thread %p has lock ...\n", g_thread_self() ); 
 
 	/* If we've seen an error, everything must stop.
@@ -167,6 +171,8 @@ vips_sequential_generate( VipsRegion *or,
 		VIPS_DEBUG_MSG_GREEN( "thread %p stalling for up to %gs ...\n", 
 			g_thread_self(), STALL_TIME ); 
 
+		VIPS_GATE_START( "vips_sequential_generate: wait" );
+
 		/* Exit the loop on timeout or condition passes. We have to
 		 * be wary of spurious wakeups. 
 		 */
@@ -181,6 +187,8 @@ vips_sequential_generate( VipsRegion *or,
 				break;
 #endif
 
+		VIPS_GATE_STOP( "vips_sequential_generate: wait" );
+
 		VIPS_DEBUG_MSG_GREEN( "thread %p awake again ...\n", 
 			g_thread_self() ); 
 	}

libvips/conversion/tilecache.c

@@ -598,8 +598,12 @@ vips_tile_cache_gen( VipsRegion *or,
 	GSList *work;
 	GSList *p;
 
+	VIPS_GATE_START( "vips_tile_cache_gen: wait1" );
+
 	g_mutex_lock( cache->lock );
 
+	VIPS_GATE_STOP( "vips_tile_cache_gen: wait1" );
+
 	VIPS_DEBUG_MSG( "vips_tile_cache_gen: "
 		"left = %d, top = %d, width = %d, height = %d\n",
 		r->left, r->top, r->width, r->height );
@@ -661,9 +665,16 @@ vips_tile_cache_gen( VipsRegion *or,
 					&tile->pos, 
 					tile->pos.left, tile->pos.top );
 
-				if( cache->threaded ) 
+				if( cache->threaded ) {
+					VIPS_GATE_START( "vips_tile_cache_gen: "
+							"wait2" );
+
 					g_mutex_lock( cache->lock );
 
+					VIPS_GATE_STOP( "vips_tile_cache_gen: "
+							"wait2" );
+				}
+
 				/* If there was an error calculating this
 				 * tile, just warn and carry on.
 				 *
@@ -713,8 +724,12 @@ vips_tile_cache_gen( VipsRegion *or,
 
 			VIPS_DEBUG_MSG( "vips_tile_cache_gen: waiting\n" ); 
 
+			VIPS_GATE_START( "vips_tile_cache_gen: wait3" );
+
 			g_cond_wait( cache->new_tile, cache->lock );
 
+			VIPS_GATE_STOP( "vips_tile_cache_gen: wait3" );
+
 			VIPS_DEBUG_MSG( "vips_tile_cache_gen: awake!\n" ); 
 		}
 	}
@@ -861,8 +876,12 @@ vips_line_cache_gen( VipsRegion *or,
 {
 	VipsBlockCache *block_cache = (VipsBlockCache *) b;
 
+	VIPS_GATE_START( "vips_line_cache_gen: wait" );
+
 	g_mutex_lock( block_cache->lock );
 
+	VIPS_GATE_STOP( "vips_line_cache_gen: wait" );
+
 	/* We size up the cache to the largest request.
 	 */
 	if( or->valid.height > 

libvips/convolution/im_conv.c

@@ -710,6 +710,8 @@ conv_gen( REGION *or, void *vseq, void *a, void *b )
 	if( im_prepare( ir, &s ) )
 		return( -1 );
 
+	VIPS_GATE_START( "conv_gen: work" ); 
+
         /* Fill offset array. Only do this if the bpl has changed since the 
 	 * previous im_prepare().
 	 */
@@ -774,6 +776,8 @@ conv_gen( REGION *or, void *vseq, void *a, void *b )
 		}
 	}
 
+	VIPS_GATE_STOP( "conv_gen: work" ); 
+
 	return( 0 );
 }
 
@@ -880,6 +884,8 @@ conv3x3_gen( REGION *or, void *vseq, void *a, void *b )
 	if( im_prepare( ir, &s ) )
 		return( -1 );
 
+	VIPS_GATE_START( "conv3x3_gen: work" ); 
+
 	for( y = to; y < bo; y++ ) { 
 		switch( in->BandFmt ) {
 		case IM_BANDFMT_UCHAR: 	
@@ -927,6 +933,8 @@ conv3x3_gen( REGION *or, void *vseq, void *a, void *b )
 		}
 	}
 
+	VIPS_GATE_STOP( "conv3x3_gen: work" ); 
+
 	return( 0 );
 }
 
@@ -958,6 +966,8 @@ convvec_gen( REGION *or, void *vseq, void *a, void *b )
 	if( im_prepare( ir, &s ) )
 		return( -1 );
 
+	VIPS_GATE_START( "convvec_gen: work" ); 
+
 	for( j = 0; j < conv->n_pass; j++ ) 
 		vips_executor_set_program( &convolve[j], 
 			conv->pass[j].vector, sz );
@@ -1006,6 +1016,8 @@ convvec_gen( REGION *or, void *vseq, void *a, void *b )
 #endif /*DEBUG_PIXELS*/
 	}
 
+	VIPS_GATE_STOP( "convvec_gen: work" ); 
+
 	return( 0 );
 }
 

libvips/convolution/sharpen.c

@@ -138,6 +138,8 @@ vips_sharpen_generate( VipsRegion *or,
 		vips_region_prepare( in[1], r ) )
 		return( -1 );
 
+	VIPS_GATE_START( "vips_sharpen_generate: work" ); 
+
 	for( y = 0; y < r->height; y++ ) {
 		short *p1 = (short *) 
 			VIPS_REGION_ADDR( in[0], r->left, r->top + y );
@@ -179,6 +181,8 @@ vips_sharpen_generate( VipsRegion *or,
 		}
 	}
 
+	VIPS_GATE_STOP( "vips_sharpen_generate: work" ); 
+
 	return( 0 );
 }
 

libvips/foreign/jpeg2vips.c

@@ -888,6 +888,8 @@ read_jpeg_generate( VipsRegion *or,
 	printf( "read_jpeg_generate: line %d, %d rows\n", 
 		r->top, r->height );
 #endif /*DEBUG*/
+	
+	VIPS_GATE_START( "read_jpeg_generate: work" );
 
 	/* We're inside a tilecache where tiles are the full image width, so
 	 * this should always be true.
@@ -926,6 +928,8 @@ read_jpeg_generate( VipsRegion *or,
 		}
 	}
 
+	VIPS_GATE_STOP( "read_jpeg_generate: work" );
+
 	return( 0 );
 }
 

libvips/include/vips/operation.h

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

libvips/iofuncs/image.c

@@ -960,9 +960,15 @@ vips_image_real_invalidate( VipsImage *image )
 {
 	VIPS_DEBUG_MSG( "vips_image_real_invalidate: %p\n", image );
 
+	VIPS_GATE_START( "vips_image_real_invalidate: wait" );
+
 	g_mutex_lock( image->sslock );
+
+	VIPS_GATE_STOP( "vips_image_real_invalidate: wait" );
+
 	(void) vips_slist_map2( image->regions,
 		(VipsSListMap2Fn) vips_region_invalidate, NULL, NULL );
+
 	g_mutex_unlock( image->sslock );
 }
 

libvips/iofuncs/region.c

@@ -203,9 +203,15 @@ vips__region_start( VipsRegion *region )
 	VipsImage *image = region->im;
 
         if( !region->seq && image->start_fn ) {
+		VIPS_GATE_START( "vips__region_start: wait" );
+
                 g_mutex_lock( image->sslock );
+
+		VIPS_GATE_STOP( "vips__region_start: wait" );
+
                 region->seq = image->start_fn( image, 
 			image->client1, image->client2 );
+
                 g_mutex_unlock( image->sslock );
  
                 if( !region->seq ) {
@@ -229,9 +235,15 @@ vips__region_stop( VipsRegion *region )
         if( region->seq && image->stop_fn ) {
 		int result;
 
+		VIPS_GATE_START( "vips__region_stop: wait" );
+
                 g_mutex_lock( image->sslock );
+
+		VIPS_GATE_STOP( "vips__region_stop: wait" );
+
                	result = image->stop_fn( region->seq, 
 			image->client1, image->client2 );
+
                 g_mutex_unlock( image->sslock );
 
 		/* stop function can return an error, but we have nothing we
@@ -279,9 +291,16 @@ vips_region_dispose( GObject *gobject )
 
 	/* Detach from image. 
 	 */
+	VIPS_GATE_START( "vips_region_dispose: wait" );
+
 	g_mutex_lock( image->sslock );
+
+	VIPS_GATE_STOP( "vips_region_dispose: wait" );
+
 	image->regions = g_slist_remove( image->regions, region );
+
 	g_mutex_unlock( image->sslock );
+
 	region->im = NULL;
 
 	g_object_unref( image );
@@ -363,8 +382,12 @@ vips__region_take_ownership( VipsRegion *region )
 	/* Lock so that there's a memory barrier with the thread doing the
 	 * vips__region_no_ownership() before us.
 	 */
+	VIPS_GATE_START( "vips__region_take_ownership: wait" );
+
 	g_mutex_lock( region->im->sslock );
 
+	VIPS_GATE_STOP( "vips__region_take_ownership: wait" );
+
 	if( region->thread != g_thread_self() ) {
 		g_assert( region->thread == NULL );
 
@@ -399,8 +422,12 @@ vips__region_check_ownership( VipsRegion *region )
 void
 vips__region_no_ownership( VipsRegion *region )
 {
+	VIPS_GATE_START( "vips__region_no_ownership: wait" );
+
 	g_mutex_lock( region->im->sslock );
 
+	VIPS_GATE_STOP( "vips__region_no_ownership: wait" );
+
 	vips__region_check_ownership( region );
 
 	region->thread = NULL;
@@ -425,8 +452,14 @@ vips_region_build( VipsObject *object )
 
 	/* We're usually inside the ss lock anyway. But be safe ...
 	 */
+	VIPS_GATE_START( "vips_region_build: wait" );
+
 	g_mutex_lock( image->sslock );
+
+	VIPS_GATE_STOP( "vips_region_build: wait" );
+
 	image->regions = g_slist_prepend( image->regions, region );
+
 	g_mutex_unlock( image->sslock );
 
 	return( 0 );

libvips/iofuncs/semaphore.c

@@ -116,6 +116,8 @@ vips_semaphore_downn( VipsSemaphore *s, int n )
 {
 	int value_after_op;
 
+	VIPS_GATE_START( "vips_semaphore_downn: wait" );
+
 	g_mutex_lock( s->mutex );
 
 	while( s->v < n )
@@ -130,6 +132,8 @@ vips_semaphore_downn( VipsSemaphore *s, int n )
 		s->name, n, value_after_op );
 #endif /*DEBUG_IO*/
 
+	VIPS_GATE_STOP( "vips_semaphore_downn: wait" );
+
 	return( value_after_op );
 }
 

libvips/iofuncs/sink.c

@@ -234,7 +234,7 @@ sink_init( Sink *sink,
 	sink->b = b;
 
 	if( !(sink->t = vips_image_new()) ||
-		im_copy( sink->sink_base.im, sink->t ) ) {
+		vips_image_write( sink->sink_base.im, sink->t ) ) {
 		sink_free( sink );
 		return( -1 );
 	}

libvips/iofuncs/sinkdisc.c

@@ -169,8 +169,10 @@ wbuffer_write( WriteBuffer *wbuffer )
 		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: " ); 
 }
 
@@ -184,18 +186,14 @@ 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 );
 
@@ -513,7 +511,7 @@ vips_sink_disc( VipsImage *im, VipsRegionWrite write_fn, void *a )
 	 * started (if the allocate failed), and in any case, we don't care if
 	 * the final write went through or not.
 	 */
-	if( !result )
+	if( !result ) 
 		vips_semaphore_down( &write.buf->done );
 
 	vips_image_posteval( im );

libvips/iofuncs/threadpool.c

@@ -546,11 +546,11 @@ vips_thread_work_unit( VipsThread *thr )
 	if( thr->error )
 		return;
 
-	VIPS_GATE_START( "vips_thread_work_unit: allocate-wait" ); 
+	VIPS_GATE_START( "vips_thread_work_unit: wait" ); 
 
 	g_mutex_lock( pool->allocate_lock );
 
-	VIPS_GATE_STOP( "vips_thread_work_unit: allocate-wait" ); 
+	VIPS_GATE_STOP( "vips_thread_work_unit: wait" ); 
 
 	/* Has another worker signaled stop while we've been working?
 	 */
@@ -577,12 +577,10 @@ vips_thread_work_unit( VipsThread *thr )
 
 	/* Process a work unit.
 	 */
-	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.

tools/Makefile.am

@@ -26,6 +26,7 @@ bin_SCRIPTS = \
 	batch_image_convert \
 	batch_rubber_sheet \
 	batch_crop \
+	vipsprofile \
 	vips-7.37
 
 EXTRA_DIST = \
@@ -42,4 +43,5 @@ install-exec-hook:
 	chmod ugo+x ${DESTDIR}${bindir}/batch_image_convert
 	chmod ugo+x ${DESTDIR}${bindir}/batch_rubber_sheet
 	chmod ugo+x ${DESTDIR}${bindir}/batch_crop
+	chmod ugo+x ${DESTDIR}${bindir}/vipsprofile
 

tools/vipsprofile

@@ -135,6 +135,23 @@ for thread in threads:
 
 print 'last time =', last_time
 
+# calculate some simple stats
+print 'name\t\t\talive\twait\twait%'
+for thread in threads:
+    start = last_time
+    stop = 0
+    wait = 0
+    for event in thread.events:
+        if event.start < start:
+            start = event.start
+        if event.stop > stop:
+            stop = event.stop
+        if event.wait:
+            wait += event.stop - event.start
+
+    alive = stop - start
+    print thread.thread_name, alive, wait, 100 * wait / alive
+
 # do two gates overlap?
 def is_overlap(events, gate_name1, gate_name2):
     for event1 in events:
@@ -184,17 +201,25 @@ PIXELS_PER_SECOND = 1000
 PIXELS_PER_GATE = 20
 LEFT_BORDER = 320
 BAR_HEIGHT = 5
-WIDTH = int(LEFT_BORDER + last_time * PIXELS_PER_SECOND)
+WIDTH = int(LEFT_BORDER + last_time * PIXELS_PER_SECOND) + 50
 HEIGHT = int((total_y + 1) * PIXELS_PER_GATE)
 
-surface = cairo.ImageSurface(cairo.FORMAT_ARGB32, WIDTH + 50, HEIGHT)
+output_filename = "vips-profile.svg"
+print 'writing to', output_filename
+
+surface = cairo.SVGSurface(output_filename, WIDTH, HEIGHT)
+
 ctx = cairo.Context(surface)
 ctx.select_font_face('Sans')
 ctx.set_font_size(15)
 
+ctx.rectangle(0, 0, WIDTH, HEIGHT)
+ctx.set_source_rgba(0.0, 0.0, 0.3, 1.0)
+ctx.fill()
+
 def draw_event(ctx, event):
     left = event.start * PIXELS_PER_SECOND + LEFT_BORDER
-    top = event.total_y * PIXELS_PER_GATE 
+    top = event.total_y * PIXELS_PER_GATE + BAR_HEIGHT / 2 
     width = (event.stop - event.start) * PIXELS_PER_SECOND - 1
     height = BAR_HEIGHT
 
@@ -216,19 +241,19 @@ def draw_event(ctx, event):
         ctx.move_to(left + width / 2 - twidth / 2, top + theight)
         ctx.set_source_rgb(1.00, 0.83, 0.00)
         ctx.show_text(event.gate_name)
-        #ctx.stroke()
 
 for thread in threads:
+    ctx.rectangle(0, thread.total_y * PIXELS_PER_GATE, WIDTH, 1)
+    ctx.set_source_rgb(1.00, 1.00, 1.00)
+    ctx.fill()
+
     xbearing, ybearing, twidth, theight, xadvance, yadvance = \
             ctx.text_extents(thread.thread_name)
     ctx.move_to(0, theight + thread.total_y * PIXELS_PER_GATE)
     ctx.set_source_rgb(1.00, 1.00, 1.00)
     ctx.show_text(thread.thread_name)
-    #ctx.stroke()
 
     for event in thread.events:
         draw_event(ctx, event)
 
-output_filename = "example.png"
+surface.finish()
-print 'writing to', output_filename
-surface.write_to_png(output_filename)