From bc736e4f5ccc031969f8a6dd612ec53ef945d369 Mon Sep 17 00:00:00 2001
From: John Cupitt <jcupitt@gmail.com>
Date: Fri, 10 Aug 2012 15:19:45 +0100
Subject: [PATCH] better precision for --vips-progress times

does 3sf of float time now
---
 libvips/conversion/sequential.c | 27 ++++++++++++++++++++++++++-
 libvips/iofuncs/image.c         |  5 +++--
 2 files changed, 29 insertions(+), 3 deletions(-)

diff --git a/libvips/conversion/sequential.c b/libvips/conversion/sequential.c
index f3cc416d..50853cd1 100644
--- a/libvips/conversion/sequential.c
+++ b/libvips/conversion/sequential.c
@@ -7,6 +7,8 @@
  * 	- from VipsForeignLoad
  * 14/7/12
  * 	- support skip forwards as well, so we can do extract/insert
+ * 10/8/12
+ * 	- add @trace option
  */
 
 /*
@@ -60,6 +62,7 @@ typedef struct _VipsSequential {
 	VipsImage *in;
 
 	int y_pos;
+	gboolean trace;
 } VipsSequential;
 
 typedef VipsConversionClass VipsSequentialClass;
@@ -74,7 +77,9 @@ vips_sequential_generate( VipsRegion *or,
         VipsRect *r = &or->valid;
 	VipsRegion *ir = (VipsRegion *) seq;
 
-	VIPS_DEBUG_MSG( "vips_sequential_generate %d\n", r->top );
+	if( sequential->trace )
+		vips_diag( "VipsSequential", 
+			"%d lines, starting at line %d", r->height, r->top );
 
 	/* We can't go backwards, but we can skip forwards.
 	 */
@@ -106,6 +111,10 @@ vips_sequential_generate( VipsRegion *or,
 			return( -1 );
 
 		sequential->y_pos += rect.height;
+
+		if( sequential->trace )
+			vips_diag( "VipsSequential", 
+				"skipping %d lines", rect.height );
 	}
 
 	g_assert( sequential->y_pos == r->top );
@@ -168,11 +177,19 @@ vips_sequential_class_init( VipsSequentialClass *class )
 		_( "Input image" ),
 		VIPS_ARGUMENT_REQUIRED_INPUT,
 		G_STRUCT_OFFSET( VipsSequential, in ) );
+
+	VIPS_ARG_BOOL( class, "trace", 2, 
+		_( "trace" ), 
+		_( "trace pixel requests" ),
+		VIPS_ARGUMENT_OPTIONAL_INPUT,
+		G_STRUCT_OFFSET( VipsSequential, trace ),
+		TRUE );
 }
 
 static void
 vips_sequential_init( VipsSequential *sequential )
 {
+	sequential->trace = FALSE;
 }
 
 /**
@@ -181,6 +198,10 @@ vips_sequential_init( VipsSequential *sequential )
  * @out: output image
  * @...: %NULL-terminated list of optional named arguments
  *
+ * Optional arguments:
+ *
+ * @trace: trace requests
+ *
  * This operation behaves rather like vips_copy() between images
  * @in and @out, except that it checks that pixels are only requested
  * top-to-bottom. If an out of order request is made, it throws an exception.
@@ -188,6 +209,10 @@ vips_sequential_init( VipsSequential *sequential )
  * This operation is handy with tilecache for loading file formats which are 
  * strictly top-to-bottom, like PNG. 
  *
+ * If @trace is true, the operation will print diagnostic messages for each
+ * block of pixels which are processed. This can help find the cause of
+ * non-sequential accesses. 
+ *
  * See also: vips_image_cache().
  *
  * Returns: 0 on success, -1 on error.
diff --git a/libvips/iofuncs/image.c b/libvips/iofuncs/image.c
index f2920cca..c3039fb9 100644
--- a/libvips/iofuncs/image.c
+++ b/libvips/iofuncs/image.c
@@ -556,8 +556,9 @@ vips_image_posteval_cb( VipsImage *image, VipsProgress *progress )
 {
 	/* Spaces at end help to erase the %complete message we overwrite.
 	 */
-	printf( _( "%s %s: done in %ds          \n" ), 
-		g_get_prgname(), image->filename, progress->run );
+	printf( _( "%s %s: done in %.3gs          \n" ), 
+		g_get_prgname(), image->filename, 
+		g_timer_elapsed( progress->start, NULL ) );
 
 	return( 0 );
 }