f3probe: add option --time-ops

In order to reduce probing time, one needs to time
reads, writes, and resets to evaluate how to change
the probing algorithm.
This patch adds these measurements.

A good 256MB drive produced the following measurements:
Probe time: 47.57 seconds
Probe read op: count=2014, total time=1.72s, avg op time=0.85ms
Probe write op: count=2003, total time=45.32s, avg op time=22.62ms
Probe reset op: count=3, total time=0.53s, avg op time=175.66ms

f3probe.c

@@ -47,6 +47,8 @@ static struct argp_option options[] = {
 		"Trade speed for less use of memory",		0},
 	{"manual-reset",	'm',	NULL,		0,
 		"Ask user to manually reset the drive",	0},
+	{"time-ops",		't',	NULL,		0,
+		"Time reads, writes, and resets",		0},
 	{ 0 }
 };
 
@@ -62,7 +64,8 @@ struct args {
 	bool		save;
 	bool		min_mem;
 	bool		manual_reset;
-	/* 2 free bytes. */
+	bool		time_ops;
+	/* 1 free bytes. */
 
 	/* Geometry. */
 	uint64_t	real_size_byte;
@@ -150,6 +153,10 @@ static error_t parse_opt(int key, char *arg, struct argp_state *state)
 		args->manual_reset = true;
 		break;
 
+	case 't':
+		args->time_ops = true;
+		break;
+
 	case ARGP_KEY_INIT:
 		args->filename = NULL;
 		break;
@@ -294,14 +301,24 @@ static void report_order(const char *prefix, int order)
 	printf("%s %.2f %s (2^%i Byte)\n", prefix, f, unit, order);
 }
 
+static void report_ops(const char *op, uint64_t count, uint64_t time_us)
+{
+	printf("Probe %s op: count=%" PRIu64
+		", total time=%.2fs, avg op time=%.2fms\n",
+		op, count, time_us / 1e6, (time_us / count) / 1e3);
+}
+
 static int test_device(struct args *args)
 {
 	struct timeval t1, t2;
 	double time_s;
-	struct device *dev;
+	struct device *dev, *pdev;
 	enum fake_type fake_type;
 	uint64_t real_size_byte, announced_size_byte;
 	int wrap, block_order;
+	uint64_t read_count, read_time_us;
+	uint64_t write_count, write_time_us;
+	uint64_t reset_count, reset_time_us;
 
 	dev = args->debug
 		? create_file_device(args->filename, args->real_size_byte,
@@ -310,6 +327,14 @@ static int test_device(struct args *args)
 		: create_block_device(args->filename, args->manual_reset);
 	assert(dev);
 
+	if (args->time_ops) {
+		pdev = create_perf_device(dev);
+		assert(pdev);
+		dev = pdev;
+	} else {
+		pdev = NULL;
+	}
+
 	if (args->save) {
 		dev = create_safe_device(dev, probe_device_max_blocks(dev),
 			args->min_mem);
@@ -333,7 +358,18 @@ static int test_device(struct args *args)
 	 * make sure that the written blocks are recovered when
 	 * @args->save is true.
 	 */
+	if (args->time_ops)
+		perf_device_sample(pdev,
+			&read_count, &read_time_us,
+			&write_count, &write_time_us,
+			&reset_count, &reset_time_us);
+	if (args->save) {
+		printf("Probe finished, recovering blocks...");
+		fflush(stdout);
+	}
 	free_device(dev);
+	if (args->save)
+		printf(" Done\n\n");
 
 	fake_type = dev_param_to_type(real_size_byte, announced_size_byte,
 		wrap, block_order);
@@ -363,6 +399,12 @@ static int test_device(struct args *args)
 	report_order("\t        Module:", wrap);
 	report_order("\t    Block size:", block_order);
 	printf("\nProbe time: %.2f seconds\n", time_s);
+
+	if (args->time_ops) {
+		report_ops("read", read_count, read_time_us);
+		report_ops("write", write_count, write_time_us);
+		report_ops("reset", reset_count, reset_time_us);
+	}
 	return 0;
 }
 
@@ -376,6 +418,7 @@ int main(int argc, char **argv)
 		.save		= true,
 		.min_mem	= false,
 		.manual_reset	= false,
+		.time_ops	= false,
 		.real_size_byte	= 1ULL << 31,
 		.fake_size_byte	= 1ULL << 34,
 		.wrap		= 31,

libprobe.c

@@ -10,6 +10,7 @@
 #include <sys/ioctl.h>
 #include <sys/types.h>
 #include <sys/stat.h>
+#include <sys/time.h>
 #include <fcntl.h>
 #include <unistd.h>
 #include <stdint.h>
@@ -536,6 +537,133 @@ error:
 	return NULL;
 }
 
+struct perf_device {
+	/* This must be the first field. See dev_pdev() for details. */
+	struct device		dev;
+
+	struct device		*shadow_dev;
+
+	uint64_t		read_count;
+	uint64_t		read_time_us;
+	uint64_t		write_count;
+	uint64_t		write_time_us;
+	uint64_t		reset_count;
+	uint64_t		reset_time_us;
+};
+
+static inline struct perf_device *dev_pdev(struct device *dev)
+{
+	return (struct perf_device *)dev;
+}
+
+static inline uint64_t diff_timeval_us(const struct timeval *t1,
+	const struct timeval *t2)
+{
+	return (t2->tv_sec - t1->tv_sec) * 1000000ULL +
+		t2->tv_usec - t1->tv_usec;
+}
+
+static int pdev_read_block(struct device *dev, char *buf, int length,
+	uint64_t offset)
+{
+	struct perf_device *pdev = dev_pdev(dev);
+	struct timeval t1, t2;
+	int rc;
+
+	assert(!gettimeofday(&t1, NULL));
+	rc = pdev->shadow_dev->read_block(pdev->shadow_dev, buf,
+		length, offset);
+	assert(!gettimeofday(&t2, NULL));
+	pdev->read_count++;
+	pdev->read_time_us += diff_timeval_us(&t1, &t2);
+	return rc;
+}
+
+static int pdev_write_block(struct device *dev, const char *buf, int length,
+	uint64_t offset)
+{
+	struct perf_device *pdev = dev_pdev(dev);
+	struct timeval t1, t2;
+	int rc;
+
+	assert(!gettimeofday(&t1, NULL));
+	rc = pdev->shadow_dev->write_block(pdev->shadow_dev, buf,
+		length, offset);
+	assert(!gettimeofday(&t2, NULL));
+	pdev->write_count++;
+	pdev->write_time_us += diff_timeval_us(&t1, &t2);
+	return rc;
+}
+
+static int pdev_reset(struct device *dev)
+{
+	struct perf_device *pdev = dev_pdev(dev);
+	struct timeval t1, t2;
+	int rc;
+
+	assert(!gettimeofday(&t1, NULL));
+	rc = dev_reset(pdev->shadow_dev);
+	assert(!gettimeofday(&t2, NULL));
+	pdev->reset_count++;
+	pdev->reset_time_us += diff_timeval_us(&t1, &t2);
+	return rc;
+}
+
+static void pdev_free(struct device *dev)
+{
+	struct perf_device *pdev = dev_pdev(dev);
+	free_device(pdev->shadow_dev);
+}
+
+struct device *create_perf_device(struct device *dev)
+{
+	struct perf_device *pdev;
+
+	pdev = malloc(sizeof(*pdev));
+	if (!pdev)
+		return NULL;
+
+	pdev->shadow_dev = dev;
+	pdev->read_count = 0;
+	pdev->read_time_us = 0;
+	pdev->write_count = 0;
+	pdev->write_time_us = 0;
+	pdev->reset_count = 0;
+	pdev->reset_time_us = 0;
+
+	pdev->dev.size_byte = dev->size_byte;
+	pdev->dev.block_order = dev->block_order;
+	pdev->dev.read_block = pdev_read_block;
+	pdev->dev.write_block = pdev_write_block;
+	pdev->dev.reset	= pdev_reset;
+	pdev->dev.free = pdev_free;
+
+	return &pdev->dev;
+}
+
+void perf_device_sample(struct device *dev,
+	uint64_t *pread_count, uint64_t *pread_time_us,
+	uint64_t *pwrite_count, uint64_t *pwrite_time_us,
+	uint64_t *preset_count, uint64_t *preset_time_us)
+{
+	struct perf_device *pdev = dev_pdev(dev);
+
+	if (pread_count)
+		*pread_count = pdev->read_count;
+	if (pread_time_us)
+		*pread_time_us = pdev->read_time_us;
+
+	if (pwrite_count)
+		*pwrite_count = pdev->write_count;
+	if (pwrite_time_us)
+		*pwrite_time_us = pdev->write_time_us;
+
+	if (preset_count)
+		*preset_count = pdev->reset_count;
+	if (preset_time_us)
+		*preset_time_us = pdev->reset_time_us;
+}
+
 #define SDEV_BITMAP_WORD		long
 #define SDEV_BITMAP_BITS_PER_WORD	(8*sizeof(SDEV_BITMAP_WORD))
 struct safe_device {

libprobe.h

@@ -38,6 +38,12 @@ struct device *create_file_device(const char *filename,
 
 struct device *create_block_device(const char *filename, int manual_reset);
 
+struct device *create_perf_device(struct device *dev);
+void perf_device_sample(struct device *dev,
+	uint64_t *pread_count, uint64_t *pread_time_us,
+	uint64_t *pwrite_count, uint64_t *pwrite_time_us,
+	uint64_t *preset_count, uint64_t *preset_time_us);
+
 struct device *create_safe_device(struct device *dev, int max_blocks,
 	int min_memory);