X Print latency histogram in total output

A bit dirty patch to collect and print latency histogram for disk
access. Example outputs:

kirr@deco:~/src/tools/fs/ioping$ ./ioping -i 100ms -D .
4 KiB <<< . (ext4 /dev/sda3): request=1 time=128.7 us (warmup)
4 KiB <<< . (ext4 /dev/sda3): request=2 time=262.9 us
4 KiB <<< . (ext4 /dev/sda3): request=3 time=282.2 us
...
4 KiB <<< . (ext4 /dev/sda3): request=170 time=259.5 us
^C
--- . (ext4 /dev/sda3) ioping statistics ---
169 requests completed in 45.8 ms, 676 KiB read, 3.69 k iops, 14.4 MiB/s
generated 170 requests in 17.0 s, 680 KiB, 10 iops, 40.0 KiB/s
min/avg/max/mdev = 142.9 us / 270.9 us / 378.1 us / 28.8 us
< 142.9 us      0       |
< 165.7 us      0       |
< 188.5 us      0       |
< 211.2 us      0       |
< 234.0 us      0       |
< 256.8 us      21      | ******
< 279.6 us      29      | ********
< 302.3 us      8       | **
< 325.1 us      5       | *
< 347.9 us      4       | *
< 370.7 us      1       |
<       +∞      1       |

kirr@deco:~/src/tools/fs/ioping$ ./ioping -R -S 1024M -k .

--- . (ext4 /dev/sda3) ioping statistics ---
17.1 k requests completed in 2.90 s, 66.7 MiB read, 5.89 k iops, 23.0 MiB/s
generated 17.1 k requests in 3.00 s, 66.8 MiB, 5.70 k iops, 22.2 MiB/s
min/avg/max/mdev = 119.4 us / 169.8 us / 3.83 ms / 260.2 us
< 298.2 us      16623   | ************************************************
< 651.4 us      110     |
< 1.00 ms       64      |
< 1.36 ms       35      |
< 1.71 ms       37      |
< 2.06 ms       33      |
< 2.42 ms       20      |
< 2.77 ms       17      |
< 3.12 ms       19      |
< 3.48 ms       25      |
< 3.83 ms       4       |
<       +∞      0       |

ioping.c

@@ -520,6 +520,8 @@ off_t woffset = 0;
 
 long long stop_at_request = 0;
 
+long long hist_warmup = 100; /* N(requests) to estimate hist interval */
+
 int exiting = 0;
 
 void parse_options(int argc, char **argv)
@@ -1070,6 +1072,7 @@ static void random_memory(void *buf, size_t len)
 	}
 }
 
+#define HIST_NHIT 10
 struct statistics {
 	long long start, finish, load_time;
 	long long count, valid, too_slow, too_fast;
@@ -1077,6 +1080,11 @@ struct statistics {
 	double sum, sum2, avg, mdev;
 	double speed, iops, load_speed, load_iops;
 	long long size, load_size;
+
+	/* latency histogram */
+	long long hist_min, hist_max;	/* autodetected from min, max after several first runs */
+	long long hist_hits[HIST_NHIT];	/* N(hits) beloning to 100% / HIST_NHIT interval */
+	long long hist_too_slow, hist_too_fast; /* N samples outside [hist_min, hist_max] range */
 };
 
 static void start_statistics(struct statistics *s, unsigned long long start) {
@@ -1087,6 +1095,7 @@ static void start_statistics(struct statistics *s, unsigned long long start) {
 }
 
 static void add_statistics(struct statistics *s, long long val) {
+	long long i;
 	s->count++;
 	if (val < min_valid_time) {
 		s->too_fast++;
@@ -1100,7 +1109,36 @@ static void add_statistics(struct statistics *s, long long val) {
 			s->min = val;
 		if (val > s->max)
 			s->max = val;
+
+		if (s->valid < hist_warmup)
+			/* too early for hist */
+			return;
+
+		if (s->valid == hist_warmup) {
+			/* initialize hist range */
+			s->hist_min = s->min;
+			s->hist_max = s->max;
+			return;
 		}
+
+		/* update hist */
+		if (val < s->hist_min) {
+			s->hist_too_slow++;
+			return;
+		}
+		if (val > s->hist_max) {
+			s->hist_too_fast++;
+			return;
+		}
+
+		i = HIST_NHIT * (val - s->hist_min) / (s->hist_max - s->hist_min);
+		if (i == HIST_NHIT)
+			i--; // was exctly s->hist_max
+
+		s->hist_hits[i]++;
+	}
+
+
 }
 
 static void merge_statistics(struct statistics *s, struct statistics *o) {
@@ -1116,6 +1154,16 @@ static void merge_statistics(struct statistics *s, struct statistics *o) {
 		if (o->max > s->max)
 			s->max = o->max;
 	}
+
+	if (!(s->hist_min == 0 && s->hist_max == 0)) {
+		errx(1, "TODO histogram merge not implemented");
+	}
+	// simply override hists; this shuuld be enough for 1 job reporting in the end
+	s->hist_min	  = o->hist_min;
+	s->hist_max	  = o->hist_max;
+	memcpy(s->hist_hits, o->hist_hits, sizeof(s->hist_hits));
+	s->hist_too_slow  = o->hist_too_slow;
+	s->hist_too_fast  = o->hist_too_fast;
 }
 
 static void finish_statistics(struct statistics *s, unsigned long long finish) {
@@ -1152,6 +1200,44 @@ static void dump_statistics(struct statistics *s) {
 			(unsigned long)s->load_time);
 }
 
+// print histogram line of hits in [tmax_prev, tmax)
+static void print_hist_line(long long tmax, long long nhit, long long total) {
+	long long i;
+
+	printf("< ");
+	if (tmax == LONG_MAX) {
+		printf("      +∞");
+	} else {
+		print_time(tmax);
+	}
+
+	printf("\t%lld\t| ", nhit);
+
+	// "*" is for 2%
+	for (i = 0; i < 100 * nhit / total / 2; i++)
+		printf("*");
+
+	printf("\n");
+}
+
+static void print_histogram(struct statistics *s) {
+	int i;
+
+	if (s->valid < hist_warmup) {
+		printf("(not enough samples for histogram)\n");
+		return;
+	}
+
+	print_hist_line(s->hist_min, s->hist_too_slow, s->valid);
+
+	for (i = 0; i < HIST_NHIT; i++) {
+		long long tmax = s->hist_min + (i + 1) * (s->hist_max - s->hist_min) / HIST_NHIT;
+		print_hist_line(tmax, s->hist_hits[i], s->valid);
+	}
+
+	print_hist_line(LONG_MAX, s->hist_too_fast, s->valid);
+}
+
 int main (int argc, char **argv)
 {
 	ssize_t ret_size;
@@ -1508,5 +1594,7 @@ skip_preparation:
 	print_time(total.mdev);
 	printf("\n");
 
+	print_histogram(&total);
+
 	return 0;
 }

[Kirill Smelkov]

/cc @jm, @vpelletier, @rafael, @kazuhiko

[Rafael Monnerat]

seems interesting.

[Kirill Smelkov]

notified upstream about this patch: https://github.com/koct9i/ioping/issues/35