Commit 000c0931 authored by Kirill Smelkov's avatar Kirill Smelkov

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       |
parent ec17b76d
...@@ -520,6 +520,8 @@ off_t woffset = 0; ...@@ -520,6 +520,8 @@ off_t woffset = 0;
long long stop_at_request = 0; long long stop_at_request = 0;
long long hist_warmup = 100; /* N(requests) to estimate hist interval */
int exiting = 0; int exiting = 0;
void parse_options(int argc, char **argv) void parse_options(int argc, char **argv)
...@@ -1070,6 +1072,7 @@ static void random_memory(void *buf, size_t len) ...@@ -1070,6 +1072,7 @@ static void random_memory(void *buf, size_t len)
} }
} }
#define HIST_NHIT 10
struct statistics { struct statistics {
long long start, finish, load_time; long long start, finish, load_time;
long long count, valid, too_slow, too_fast; long long count, valid, too_slow, too_fast;
...@@ -1077,6 +1080,11 @@ struct statistics { ...@@ -1077,6 +1080,11 @@ struct statistics {
double sum, sum2, avg, mdev; double sum, sum2, avg, mdev;
double speed, iops, load_speed, load_iops; double speed, iops, load_speed, load_iops;
long long size, load_size; 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) { 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) { ...@@ -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) { static void add_statistics(struct statistics *s, long long val) {
long long i;
s->count++; s->count++;
if (val < min_valid_time) { if (val < min_valid_time) {
s->too_fast++; s->too_fast++;
...@@ -1100,7 +1109,36 @@ static void add_statistics(struct statistics *s, long long val) { ...@@ -1100,7 +1109,36 @@ static void add_statistics(struct statistics *s, long long val) {
s->min = val; s->min = val;
if (val > s->max) if (val > s->max)
s->max = val; 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) { static void merge_statistics(struct statistics *s, struct statistics *o) {
...@@ -1116,6 +1154,16 @@ 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) if (o->max > s->max)
s->max = o->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) { static void finish_statistics(struct statistics *s, unsigned long long finish) {
...@@ -1152,6 +1200,44 @@ static void dump_statistics(struct statistics *s) { ...@@ -1152,6 +1200,44 @@ static void dump_statistics(struct statistics *s) {
(unsigned long)s->load_time); (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) int main (int argc, char **argv)
{ {
ssize_t ret_size; ssize_t ret_size;
...@@ -1508,5 +1594,7 @@ skip_preparation: ...@@ -1508,5 +1594,7 @@ skip_preparation:
print_time(total.mdev); print_time(total.mdev);
printf("\n"); printf("\n");
print_histogram(&total);
return 0; return 0;
} }
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment