stats: Add a function to report completion latency percentiles
[fio.git] / stat.c
CommitLineData
3c39a379
JA
1#include <stdio.h>
2#include <string.h>
3#include <sys/time.h>
4#include <sys/types.h>
5c4e1dbc 5#include <sys/stat.h>
3c39a379
JA
6#include <dirent.h>
7#include <libgen.h>
8#include <math.h>
9
10#include "fio.h"
7c9b1bce 11#include "diskutil.h"
3c39a379 12
3c39a379
JA
13void update_rusage_stat(struct thread_data *td)
14{
756867bd 15 struct thread_stat *ts = &td->ts;
3c39a379 16
079ad09b
JA
17 getrusage(RUSAGE_SELF, &ts->ru_end);
18
5ec10eaa
JA
19 ts->usr_time += mtime_since(&ts->ru_start.ru_utime,
20 &ts->ru_end.ru_utime);
21 ts->sys_time += mtime_since(&ts->ru_start.ru_stime,
22 &ts->ru_end.ru_stime);
23 ts->ctx += ts->ru_end.ru_nvcsw + ts->ru_end.ru_nivcsw
24 - (ts->ru_start.ru_nvcsw + ts->ru_start.ru_nivcsw);
e7823a94
JA
25 ts->minf += ts->ru_end.ru_minflt - ts->ru_start.ru_minflt;
26 ts->majf += ts->ru_end.ru_majflt - ts->ru_start.ru_majflt;
5ec10eaa 27
079ad09b 28 memcpy(&ts->ru_start, &ts->ru_end, sizeof(ts->ru_end));
3c39a379
JA
29}
30
83349190
YH
31/*
32 * Given a latency, return the index of the corresponding bucket in
33 * the structure tracking percentiles.
34 *
35 * (1) find the group (and error bits) that the value (latency)
36 * belongs to by looking at its MSB. (2) find the bucket number in the
37 * group by looking at the index bits.
38 *
39 */
40static unsigned int plat_val_to_idx(unsigned int val)
41{
42 unsigned int msb, error_bits, base, offset, idx;
43
44 /* Find MSB starting from bit 0 */
45 if (val == 0)
46 msb = 0;
47 else
48 msb = (sizeof(val)*8) - __builtin_clz(val) - 1;
49
50 /* MSB <= (FIO_IO_U_PLAT_BITS-1), cannot be rounded off. Use
51 * all bits of the sample as index */
52 if (msb <= FIO_IO_U_PLAT_BITS)
53 return val;
54
55 /* Compute the number of error bits to discard*/
56 error_bits = msb - FIO_IO_U_PLAT_BITS;
57
58 /* Compute the number of buckets before the group */
59 base = (error_bits + 1) << FIO_IO_U_PLAT_BITS;
60
61 /* Discard the error bits and apply the mask to find the
62 * index for the buckets in the group */
63 offset = (FIO_IO_U_PLAT_VAL - 1) & (val >> error_bits);
64
65 /* Make sure the index does not exceed (array size - 1) */
66 idx = (base + offset) < (FIO_IO_U_PLAT_NR - 1)?
67 (base + offset) : (FIO_IO_U_PLAT_NR - 1);
68
69 return idx;
70}
71
72/*
73 * Convert the given index of the bucket array to the value
74 * represented by the bucket
75 */
76static unsigned int plat_idx_to_val(unsigned int idx)
77{
78 unsigned int error_bits, k, base;
79
80 assert(idx < FIO_IO_U_PLAT_NR);
81
82 /* MSB <= (FIO_IO_U_PLAT_BITS-1), cannot be rounded off. Use
83 * all bits of the sample as index */
84 if (idx < (FIO_IO_U_PLAT_VAL << 1) )
85 return idx;
86
87 /* Find the group and compute the minimum value of that group */
88 error_bits = (idx >> FIO_IO_U_PLAT_BITS) -1;
89 base = 1 << (error_bits + FIO_IO_U_PLAT_BITS);
90
91 /* Find its bucket number of the group */
92 k = idx % FIO_IO_U_PLAT_VAL;
93
94 /* Return the mean of the range of the bucket */
95 return base + ((k + 0.5) * (1 << error_bits));
96}
97
98static int double_cmp(const void *a, const void *b)
99{
100 const double fa = *(const double *)a;
101 const double fb = *(const double *)b;
102 int cmp = 0;
103
104 if (fa > fb)
105 cmp = 1;
106 else if (fa < fb)
107 cmp = -1;
108
109 return cmp;
110}
111
112/*
113 * Find and display the p-th percentile of clat
114 */
115static void show_clat_percentiles(unsigned int* io_u_plat, unsigned long nr,
116 double* user_list)
117{
118 unsigned long sum = 0;
119 unsigned int len, i, j = 0;
120 static const double def_list[FIO_IO_U_LIST_MAX_LEN] = {
121 1.0, 5.0, 10.0, 20.0, 30.0,
122 40.0, 50.0, 60.0, 70.0, 80.0,
123 90.0, 95.0, 99.0, 99.5, 99.9};
124
125 const double* plist = user_list? user_list: def_list;
126 for (len = 0; len <FIO_IO_U_LIST_MAX_LEN && plist[len] != 0; len++) {}
127
128 /* Sort the user-specified list. Note that this does not work
129 for NaN values */
130 if (user_list && len > 1)
131 qsort((void*)user_list, len, sizeof(user_list[0]), double_cmp);
132
133 int is_last = 0;
134 log_info(" clat percentiles (usec) :");
135
136 for (i = 0; i <FIO_IO_U_PLAT_NR && !is_last; i++) {
137 sum += io_u_plat[i];
138 while (sum >= (plist[j]/100 * nr)) {
139 assert(plist[j] <= 100.0);
140
141 if (j!=0 && (j%4) == 0) /* for formatting */
142 log_info(" ");
143
144 /* end of the list */
145 is_last = (j == len - 1);
146
147 log_info(" %2.2fth=%u%c", plist[j], plat_idx_to_val(i),
148 (is_last? '\n' : ','));
149
150 if (is_last) break;
151
152 if (j%4 == 3) /* for formatting */
153 log_info("\n");
154 j++;
155 }
156 }
157}
158
3c39a379
JA
159static int calc_lat(struct io_stat *is, unsigned long *min, unsigned long *max,
160 double *mean, double *dev)
161{
68704084 162 double n = is->samples;
3c39a379
JA
163
164 if (is->samples == 0)
165 return 0;
166
167 *min = is->min_val;
168 *max = is->max_val;
169
170 n = (double) is->samples;
68704084 171 *mean = is->mean;
e6d276f2 172
68704084
JA
173 if (n > 1.0)
174 *dev = sqrt(is->S / (n - 1.0));
ef9c5c40 175 else
4b43f54e 176 *dev = 0;
ef9c5c40 177
3c39a379
JA
178 return 1;
179}
180
181static void show_group_stats(struct group_run_stats *rs, int id)
182{
dbe1125e
JA
183 char *p1, *p2, *p3, *p4;
184 const char *ddir_str[] = { " READ", " WRITE" };
185 int i;
186
6d86144d 187 log_info("\nRun status group %d (all jobs):\n", id);
3c39a379 188
dbe1125e 189 for (i = 0; i <= DDIR_WRITE; i++) {
90fef2d1
JA
190 const int i2p = is_power_of_2(rs->kb_base);
191
dbe1125e
JA
192 if (!rs->max_run[i])
193 continue;
194
90fef2d1
JA
195 p1 = num2str(rs->io_kb[i], 6, rs->kb_base, i2p);
196 p2 = num2str(rs->agg[i], 6, rs->kb_base, i2p);
197 p3 = num2str(rs->min_bw[i], 6, rs->kb_base, i2p);
198 p4 = num2str(rs->max_bw[i], 6, rs->kb_base, i2p);
dbe1125e 199
b22989b9 200 log_info("%s: io=%sB, aggrb=%sB/s, minb=%sB/s, maxb=%sB/s,"
5ec10eaa
JA
201 " mint=%llumsec, maxt=%llumsec\n", ddir_str[i], p1, p2,
202 p3, p4, rs->min_run[i],
203 rs->max_run[i]);
dbe1125e
JA
204
205 free(p1);
206 free(p2);
207 free(p3);
208 free(p4);
209 }
3c39a379
JA
210}
211
b3605062
JA
212#define ts_total_io_u(ts) \
213 ((ts)->total_io_u[0] + (ts)->total_io_u[1])
214
838bc709
JA
215static void stat_calc_dist(unsigned int *map, unsigned long total,
216 double *io_u_dist)
2270890c
JA
217{
218 int i;
219
220 /*
221 * Do depth distribution calculations
222 */
223 for (i = 0; i < FIO_IO_U_MAP_NR; i++) {
838bc709
JA
224 if (total) {
225 io_u_dist[i] = (double) map[i] / (double) total;
226 io_u_dist[i] *= 100.0;
227 if (io_u_dist[i] < 0.1 && map[i])
228 io_u_dist[i] = 0.1;
229 } else
230 io_u_dist[i] = 0.0;
2270890c
JA
231 }
232}
233
04a0feae
JA
234static void stat_calc_lat(struct thread_stat *ts, double *dst,
235 unsigned int *src, int nr)
2270890c 236{
838bc709 237 unsigned long total = ts_total_io_u(ts);
2270890c
JA
238 int i;
239
240 /*
241 * Do latency distribution calculations
242 */
04a0feae 243 for (i = 0; i < nr; i++) {
838bc709
JA
244 if (total) {
245 dst[i] = (double) src[i] / (double) total;
246 dst[i] *= 100.0;
247 if (dst[i] < 0.01 && src[i])
248 dst[i] = 0.01;
249 } else
250 dst[i] = 0.0;
2270890c
JA
251 }
252}
253
04a0feae
JA
254static void stat_calc_lat_u(struct thread_stat *ts, double *io_u_lat)
255{
256 stat_calc_lat(ts, io_u_lat, ts->io_u_lat_u, FIO_IO_U_LAT_U_NR);
257}
258
259static void stat_calc_lat_m(struct thread_stat *ts, double *io_u_lat)
260{
261 stat_calc_lat(ts, io_u_lat, ts->io_u_lat_m, FIO_IO_U_LAT_M_NR);
262}
263
ea2accc5
JA
264static int usec_to_msec(unsigned long *min, unsigned long *max, double *mean,
265 double *dev)
266{
267 if (*min > 1000 && *max > 1000 && *mean > 1000.0 && *dev > 1000.0) {
268 *min /= 1000;
269 *max /= 1000;
270 *mean /= 1000.0;
271 *dev /= 1000.0;
272 return 0;
273 }
274
275 return 1;
276}
277
756867bd 278static void show_ddir_status(struct group_run_stats *rs, struct thread_stat *ts,
3c39a379
JA
279 int ddir)
280{
3c9b60c1 281 const char *ddir_str[] = { "read ", "write" };
8879fd15 282 unsigned long min, max, runt;
b3605062 283 unsigned long long bw, iops;
3c39a379 284 double mean, dev;
b3605062 285 char *io_p, *bw_p, *iops_p;
90fef2d1 286 int i2p;
3c39a379 287
ff58fced
JA
288 assert(ddir_rw(ddir));
289
756867bd 290 if (!ts->runtime[ddir])
3c39a379
JA
291 return;
292
90fef2d1 293 i2p = is_power_of_2(rs->kb_base);
8879fd15
JA
294 runt = ts->runtime[ddir];
295
296 bw = (1000 * ts->io_bytes[ddir]) / runt;
90fef2d1
JA
297 io_p = num2str(ts->io_bytes[ddir], 6, 1, i2p);
298 bw_p = num2str(bw, 6, 1, i2p);
8879fd15 299
0aacc50c 300 iops = (1000 * (uint64_t)ts->total_io_u[ddir]) / runt;
b3605062 301 iops_p = num2str(iops, 6, 1, 0);
dbe1125e 302
cda99fa0 303 log_info(" %s: io=%sB, bw=%sB/s, iops=%s, runt=%6llumsec\n",
5ec10eaa
JA
304 ddir_str[ddir], io_p, bw_p, iops_p,
305 ts->runtime[ddir]);
dbe1125e
JA
306
307 free(io_p);
308 free(bw_p);
b3605062 309 free(iops_p);
3c39a379 310
d85f5118
JA
311 if (calc_lat(&ts->slat_stat[ddir], &min, &max, &mean, &dev)) {
312 const char *base = "(usec)";
d9309cb1 313 char *minp, *maxp;
d85f5118 314
ea2accc5 315 if (!usec_to_msec(&min, &max, &mean, &dev))
d85f5118 316 base = "(msec)";
ea2accc5 317
d9309cb1
JA
318 minp = num2str(min, 6, 1, 0);
319 maxp = num2str(max, 6, 1, 0);
320
5ec10eaa
JA
321 log_info(" slat %s: min=%s, max=%s, avg=%5.02f,"
322 " stdev=%5.02f\n", base, minp, maxp, mean, dev);
d9309cb1
JA
323
324 free(minp);
325 free(maxp);
d85f5118
JA
326 }
327 if (calc_lat(&ts->clat_stat[ddir], &min, &max, &mean, &dev)) {
328 const char *base = "(usec)";
d9309cb1 329 char *minp, *maxp;
d85f5118 330
ea2accc5
JA
331 if (!usec_to_msec(&min, &max, &mean, &dev))
332 base = "(msec)";
333
d9309cb1
JA
334 minp = num2str(min, 6, 1, 0);
335 maxp = num2str(max, 6, 1, 0);
5ec10eaa
JA
336
337 log_info(" clat %s: min=%s, max=%s, avg=%5.02f,"
338 " stdev=%5.02f\n", base, minp, maxp, mean, dev);
d9309cb1
JA
339
340 free(minp);
341 free(maxp);
d85f5118 342 }
02af0988
JA
343 if (calc_lat(&ts->lat_stat[ddir], &min, &max, &mean, &dev)) {
344 const char *base = "(usec)";
345 char *minp, *maxp;
346
347 if (!usec_to_msec(&min, &max, &mean, &dev))
348 base = "(msec)";
349
350 minp = num2str(min, 6, 1, 0);
351 maxp = num2str(max, 6, 1, 0);
352
353 log_info(" lat %s: min=%s, max=%s, avg=%5.02f,"
354 " stdev=%5.02f\n", base, minp, maxp, mean, dev);
355
356 free(minp);
357 free(maxp);
358 }
83349190
YH
359 if (ts->clat_percentiles) {
360 show_clat_percentiles(ts->io_u_plat[ddir],
361 ts->clat_stat[ddir].samples,
362 ts->percentile_list);
363 }
079ad09b 364 if (calc_lat(&ts->bw_stat[ddir], &min, &max, &mean, &dev)) {
3c39a379
JA
365 double p_of_agg;
366
367 p_of_agg = mean * 100 / (double) rs->agg[ddir];
b22989b9 368 log_info(" bw (KB/s) : min=%5lu, max=%5lu, per=%3.2f%%,"
5ec10eaa
JA
369 " avg=%5.02f, stdev=%5.02f\n", min, max, p_of_agg,
370 mean, dev);
3c39a379
JA
371 }
372}
373
04a0feae
JA
374static void show_lat(double *io_u_lat, int nr, const char **ranges,
375 const char *msg)
376{
377 int new_line = 1, i, line = 0;
378
379 for (i = 0; i < nr; i++) {
380 if (io_u_lat[i] <= 0.0)
381 continue;
382 if (new_line) {
4539ed73
JA
383 if (line)
384 log_info("\n");
04a0feae
JA
385 log_info(" lat (%s): ", msg);
386 new_line = 0;
387 line = 0;
388 }
389 if (line)
390 log_info(", ");
391 log_info("%s%3.2f%%", ranges[i], io_u_lat[i]);
392 line++;
393 if (line == 5)
394 new_line = 1;
395 }
04a0feae
JA
396}
397
398static void show_lat_u(double *io_u_lat_u)
399{
400 const char *ranges[] = { "2=", "4=", "10=", "20=", "50=", "100=",
401 "250=", "500=", "750=", "1000=", };
402
403 show_lat(io_u_lat_u, FIO_IO_U_LAT_U_NR, ranges, "usec");
404}
405
406static void show_lat_m(double *io_u_lat_m)
407{
408 const char *ranges[] = { "2=", "4=", "10=", "20=", "50=", "100=",
409 "250=", "500=", "750=", "1000=", "2000=",
410 ">=2000=", };
411
412 show_lat(io_u_lat_m, FIO_IO_U_LAT_M_NR, ranges, "msec");
413}
414
415static void show_latencies(double *io_u_lat_u, double *io_u_lat_m)
416{
417 show_lat_u(io_u_lat_u);
4539ed73 418 log_info("\n");
04a0feae
JA
419 show_lat_m(io_u_lat_m);
420 log_info("\n");
421}
422
756867bd 423static void show_thread_status(struct thread_stat *ts,
3c39a379
JA
424 struct group_run_stats *rs)
425{
426 double usr_cpu, sys_cpu;
69008999 427 unsigned long runtime;
71619dc2 428 double io_u_dist[FIO_IO_U_MAP_NR];
04a0feae
JA
429 double io_u_lat_u[FIO_IO_U_LAT_U_NR];
430 double io_u_lat_m[FIO_IO_U_LAT_M_NR];
3c39a379 431
b4c5e1ac
JA
432 if (!(ts->io_bytes[0] + ts->io_bytes[1]) &&
433 !(ts->total_io_u[0] + ts->total_io_u[1]))
3c39a379
JA
434 return;
435
5ec10eaa
JA
436 if (!ts->error) {
437 log_info("%s: (groupid=%d, jobs=%d): err=%2d: pid=%d\n",
438 ts->name, ts->groupid, ts->members,
5921e80c 439 ts->error, (int) ts->pid);
5ec10eaa
JA
440 } else {
441 log_info("%s: (groupid=%d, jobs=%d): err=%2d (%s): pid=%d\n",
442 ts->name, ts->groupid, ts->members,
5921e80c 443 ts->error, ts->verror, (int) ts->pid);
5ec10eaa 444 }
3c39a379 445
7bdce1bd 446 if (ts->description)
6d86144d 447 log_info(" Description : [%s]\n", ts->description);
7bdce1bd 448
756867bd
JA
449 if (ts->io_bytes[DDIR_READ])
450 show_ddir_status(rs, ts, DDIR_READ);
451 if (ts->io_bytes[DDIR_WRITE])
452 show_ddir_status(rs, ts, DDIR_WRITE);
3c39a379 453
756867bd 454 runtime = ts->total_run_time;
69008999 455 if (runtime) {
1e97cce9 456 double runt = (double) runtime;
3c39a379 457
756867bd
JA
458 usr_cpu = (double) ts->usr_time * 100 / runt;
459 sys_cpu = (double) ts->sys_time * 100 / runt;
3c39a379
JA
460 } else {
461 usr_cpu = 0;
462 sys_cpu = 0;
463 }
464
5ec10eaa
JA
465 log_info(" cpu : usr=%3.2f%%, sys=%3.2f%%, ctx=%lu, majf=%lu,"
466 " minf=%lu\n", usr_cpu, sys_cpu, ts->ctx, ts->majf, ts->minf);
71619dc2 467
838bc709 468 stat_calc_dist(ts->io_u_map, ts_total_io_u(ts), io_u_dist);
5ec10eaa
JA
469 log_info(" IO depths : 1=%3.1f%%, 2=%3.1f%%, 4=%3.1f%%, 8=%3.1f%%,"
470 " 16=%3.1f%%, 32=%3.1f%%, >=64=%3.1f%%\n", io_u_dist[0],
471 io_u_dist[1], io_u_dist[2],
472 io_u_dist[3], io_u_dist[4],
473 io_u_dist[5], io_u_dist[6]);
838bc709
JA
474
475 stat_calc_dist(ts->io_u_submit, ts->total_submit, io_u_dist);
476 log_info(" submit : 0=%3.1f%%, 4=%3.1f%%, 8=%3.1f%%, 16=%3.1f%%,"
477 " 32=%3.1f%%, 64=%3.1f%%, >=64=%3.1f%%\n", io_u_dist[0],
478 io_u_dist[1], io_u_dist[2],
479 io_u_dist[3], io_u_dist[4],
480 io_u_dist[5], io_u_dist[6]);
481 stat_calc_dist(ts->io_u_complete, ts->total_complete, io_u_dist);
482 log_info(" complete : 0=%3.1f%%, 4=%3.1f%%, 8=%3.1f%%, 16=%3.1f%%,"
483 " 32=%3.1f%%, 64=%3.1f%%, >=64=%3.1f%%\n", io_u_dist[0],
484 io_u_dist[1], io_u_dist[2],
485 io_u_dist[3], io_u_dist[4],
486 io_u_dist[5], io_u_dist[6]);
0d29de83 487 log_info(" issued r/w/d: total=%lu/%lu/%lu, short=%lu/%lu/%lu\n",
5ec10eaa 488 ts->total_io_u[0], ts->total_io_u[1],
0d29de83
JA
489 ts->total_io_u[2],
490 ts->short_io_u[0], ts->short_io_u[1],
491 ts->short_io_u[2]);
838bc709
JA
492 stat_calc_lat_u(ts, io_u_lat_u);
493 stat_calc_lat_m(ts, io_u_lat_m);
04a0feae 494 show_latencies(io_u_lat_u, io_u_lat_m);
f2bba182 495 if (ts->continue_on_error) {
1ec99eea
JA
496 log_info(" errors : total=%lu, first_error=%d/<%s>\n",
497 ts->total_err_count,
498 ts->first_error,
499 strerror(ts->first_error));
f2bba182 500 }
3c39a379
JA
501}
502
756867bd 503static void show_ddir_status_terse(struct thread_stat *ts,
c6ae0a5b
JA
504 struct group_run_stats *rs, int ddir)
505{
506 unsigned long min, max;
507 unsigned long long bw;
508 double mean, dev;
509
ff58fced
JA
510 assert(ddir_rw(ddir));
511
c6ae0a5b 512 bw = 0;
756867bd
JA
513 if (ts->runtime[ddir])
514 bw = ts->io_bytes[ddir] / ts->runtime[ddir];
c6ae0a5b 515
cda99fa0 516 log_info(";%llu;%llu;%llu", ts->io_bytes[ddir] >> 10, bw,
5ec10eaa 517 ts->runtime[ddir]);
c6ae0a5b 518
079ad09b 519 if (calc_lat(&ts->slat_stat[ddir], &min, &max, &mean, &dev))
6d86144d 520 log_info(";%lu;%lu;%f;%f", min, max, mean, dev);
c6ae0a5b 521 else
6d86144d 522 log_info(";%lu;%lu;%f;%f", 0UL, 0UL, 0.0, 0.0);
c6ae0a5b 523
079ad09b 524 if (calc_lat(&ts->clat_stat[ddir], &min, &max, &mean, &dev))
6d86144d 525 log_info(";%lu;%lu;%f;%f", min, max, mean, dev);
c6ae0a5b 526 else
6d86144d 527 log_info(";%lu;%lu;%f;%f", 0UL, 0UL, 0.0, 0.0);
c6ae0a5b 528
02af0988
JA
529 if (calc_lat(&ts->lat_stat[ddir], &min, &max, &mean, &dev))
530 log_info(";%lu;%lu;%f;%f", min, max, mean, dev);
531 else
532 log_info(";%lu;%lu;%f;%f", 0UL, 0UL, 0.0, 0.0);
533
079ad09b 534 if (calc_lat(&ts->bw_stat[ddir], &min, &max, &mean, &dev)) {
c6ae0a5b
JA
535 double p_of_agg;
536
537 p_of_agg = mean * 100 / (double) rs->agg[ddir];
6d86144d 538 log_info(";%lu;%lu;%f%%;%f;%f", min, max, p_of_agg, mean, dev);
c6ae0a5b 539 } else
6d86144d 540 log_info(";%lu;%lu;%f%%;%f;%f", 0UL, 0UL, 0.0, 0.0, 0.0);
c6ae0a5b
JA
541}
542
525c2bfa 543#define FIO_TERSE_VERSION "2"
c6ae0a5b 544
756867bd 545static void show_thread_status_terse(struct thread_stat *ts,
c6ae0a5b
JA
546 struct group_run_stats *rs)
547{
2270890c 548 double io_u_dist[FIO_IO_U_MAP_NR];
04a0feae
JA
549 double io_u_lat_u[FIO_IO_U_LAT_U_NR];
550 double io_u_lat_m[FIO_IO_U_LAT_M_NR];
c6ae0a5b 551 double usr_cpu, sys_cpu;
04a0feae 552 int i;
c6ae0a5b 553
562c2d2f 554 /* General Info */
525c2bfa
JA
555 log_info("%s;%s;%d;%d", FIO_TERSE_VERSION, ts->name, ts->groupid,
556 ts->error);
562c2d2f 557 /* Log Read Status */
756867bd 558 show_ddir_status_terse(ts, rs, 0);
562c2d2f 559 /* Log Write Status */
756867bd 560 show_ddir_status_terse(ts, rs, 1);
c6ae0a5b 561
562c2d2f 562 /* CPU Usage */
756867bd
JA
563 if (ts->total_run_time) {
564 double runt = (double) ts->total_run_time;
c6ae0a5b 565
756867bd
JA
566 usr_cpu = (double) ts->usr_time * 100 / runt;
567 sys_cpu = (double) ts->sys_time * 100 / runt;
c6ae0a5b
JA
568 } else {
569 usr_cpu = 0;
570 sys_cpu = 0;
571 }
572
5ec10eaa
JA
573 log_info(";%f%%;%f%%;%lu;%lu;%lu", usr_cpu, sys_cpu, ts->ctx, ts->majf,
574 ts->minf);
2270890c 575
562c2d2f 576 /* Calc % distribution of IO depths, usecond, msecond latency */
838bc709 577 stat_calc_dist(ts->io_u_map, ts_total_io_u(ts), io_u_dist);
04a0feae
JA
578 stat_calc_lat_u(ts, io_u_lat_u);
579 stat_calc_lat_m(ts, io_u_lat_m);
2270890c 580
562c2d2f 581 /* Only show fixed 7 I/O depth levels*/
5ec10eaa
JA
582 log_info(";%3.1f%%;%3.1f%%;%3.1f%%;%3.1f%%;%3.1f%%;%3.1f%%;%3.1f%%",
583 io_u_dist[0], io_u_dist[1], io_u_dist[2], io_u_dist[3],
584 io_u_dist[4], io_u_dist[5], io_u_dist[6]);
2270890c 585
562c2d2f 586 /* Microsecond latency */
04a0feae
JA
587 for (i = 0; i < FIO_IO_U_LAT_U_NR; i++)
588 log_info(";%3.2f%%", io_u_lat_u[i]);
562c2d2f 589 /* Millisecond latency */
04a0feae
JA
590 for (i = 0; i < FIO_IO_U_LAT_M_NR; i++)
591 log_info(";%3.2f%%", io_u_lat_m[i]);
562c2d2f 592 /* Additional output if continue_on_error set - default off*/
f2bba182
RR
593 if (ts->continue_on_error)
594 log_info(";%lu;%d", ts->total_err_count, ts->first_error);
04a0feae 595 log_info("\n");
2270890c 596
562c2d2f 597 /* Additional output if description is set */
2270890c 598 if (ts->description)
6d86144d 599 log_info(";%s", ts->description);
2270890c 600
6d86144d 601 log_info("\n");
756867bd
JA
602}
603
197574e4 604static void sum_stat(struct io_stat *dst, struct io_stat *src, int nr)
756867bd
JA
605{
606 double mean, S;
607
608 dst->min_val = min(dst->min_val, src->min_val);
609 dst->max_val = max(dst->max_val, src->max_val);
756867bd
JA
610
611 /*
cdcac5cf
YH
612 * Compute new mean and S after the merge
613 * <http://en.wikipedia.org/wiki/Algorithms_for_calculating_variance
614 * #Parallel_algorithm>
756867bd
JA
615 */
616 if (nr == 1) {
617 mean = src->mean;
618 S = src->S;
619 } else {
cdcac5cf
YH
620 double delta = src->mean - dst->mean;
621
622 mean = ((src->mean * src->samples) +
623 (dst->mean * dst->samples)) /
624 (dst->samples + src->samples);
625
626 S = src->S + dst->S + pow(delta, 2.0) *
627 (dst->samples * src->samples) /
628 (dst->samples + src->samples);
756867bd
JA
629 }
630
cdcac5cf 631 dst->samples += src->samples;
756867bd
JA
632 dst->mean = mean;
633 dst->S = S;
634}
635
3c39a379
JA
636void show_run_stats(void)
637{
638 struct group_run_stats *runstats, *rs;
639 struct thread_data *td;
756867bd 640 struct thread_stat *threadstats, *ts;
197574e4 641 int i, j, k, l, nr_ts, last_ts, idx;
90fef2d1 642 int kb_base_warned = 0;
3c39a379
JA
643
644 runstats = malloc(sizeof(struct group_run_stats) * (groupid + 1));
645
646 for (i = 0; i < groupid + 1; i++) {
647 rs = &runstats[i];
648
649 memset(rs, 0, sizeof(*rs));
650 rs->min_bw[0] = rs->min_run[0] = ~0UL;
651 rs->min_bw[1] = rs->min_run[1] = ~0UL;
652 }
653
756867bd
JA
654 /*
655 * find out how many threads stats we need. if group reporting isn't
656 * enabled, it's one-per-td.
657 */
658 nr_ts = 0;
659 last_ts = -1;
660 for_each_td(td, i) {
2dc1bbeb 661 if (!td->o.group_reporting) {
756867bd
JA
662 nr_ts++;
663 continue;
664 }
665 if (last_ts == td->groupid)
666 continue;
667
668 last_ts = td->groupid;
669 nr_ts++;
670 }
671
672 threadstats = malloc(nr_ts * sizeof(struct thread_stat));
673
674 for (i = 0; i < nr_ts; i++) {
675 ts = &threadstats[i];
676
677 memset(ts, 0, sizeof(*ts));
de64df05 678 for (j = 0; j <= DDIR_WRITE; j++) {
02af0988 679 ts->lat_stat[j].min_val = -1UL;
197574e4
JA
680 ts->clat_stat[j].min_val = -1UL;
681 ts->slat_stat[j].min_val = -1UL;
682 ts->bw_stat[j].min_val = -1UL;
683 }
7abd0e3a 684 ts->groupid = -1;
756867bd
JA
685 }
686
687 j = 0;
688 last_ts = -1;
197574e4 689 idx = 0;
34572e28 690 for_each_td(td, i) {
2dc1bbeb
JA
691 if (idx && (!td->o.group_reporting ||
692 (td->o.group_reporting && last_ts != td->groupid))) {
7abd0e3a
JA
693 idx = 0;
694 j++;
695 }
696
697 last_ts = td->groupid;
698
756867bd
JA
699 ts = &threadstats[j];
700
83349190
YH
701 ts->clat_percentiles = td->o.clat_percentiles;
702 if (td->o.overwrite_plist)
703 ts->percentile_list = td->o.percentile_list;
704 else
705 ts->percentile_list = NULL;
706
197574e4 707 idx++;
6586ee89 708 ts->members++;
756867bd 709
7abd0e3a 710 if (ts->groupid == -1) {
2dc84ba7
JA
711 /*
712 * These are per-group shared already
713 */
2dc1bbeb
JA
714 ts->name = td->o.name;
715 ts->description = td->o.description;
756867bd 716 ts->groupid = td->groupid;
2dc84ba7
JA
717
718 /*
719 * first pid in group, not very useful...
720 */
756867bd 721 ts->pid = td->pid;
90fef2d1
JA
722
723 ts->kb_base = td->o.kb_base;
724 } else if (ts->kb_base != td->o.kb_base && !kb_base_warned) {
725 log_info("fio: kb_base differs for jobs in group, using"
726 " %u as the base\n", ts->kb_base);
727 kb_base_warned = 1;
2dc84ba7
JA
728 }
729
f2bba182
RR
730 ts->continue_on_error = td->o.continue_on_error;
731 ts->total_err_count += td->total_err_count;
732 ts->first_error = td->first_error;
733 if (!ts->error) {
734 if (!td->error && td->o.continue_on_error &&
735 td->first_error) {
736 ts->error = td->first_error;
737 ts->verror = td->verror;
738 } else if (td->error) {
739 ts->error = td->error;
740 ts->verror = td->verror;
741 }
756867bd
JA
742 }
743
de64df05 744 for (l = 0; l <= DDIR_WRITE; l++) {
197574e4
JA
745 sum_stat(&ts->clat_stat[l], &td->ts.clat_stat[l], idx);
746 sum_stat(&ts->slat_stat[l], &td->ts.slat_stat[l], idx);
02af0988 747 sum_stat(&ts->lat_stat[l], &td->ts.lat_stat[l], idx);
197574e4 748 sum_stat(&ts->bw_stat[l], &td->ts.bw_stat[l], idx);
756867bd 749
197574e4
JA
750 ts->stat_io_bytes[l] += td->ts.stat_io_bytes[l];
751 ts->io_bytes[l] += td->ts.io_bytes[l];
752
753 if (ts->runtime[l] < td->ts.runtime[l])
754 ts->runtime[l] = td->ts.runtime[l];
755 }
756867bd
JA
756
757 ts->usr_time += td->ts.usr_time;
758 ts->sys_time += td->ts.sys_time;
759 ts->ctx += td->ts.ctx;
e7823a94
JA
760 ts->majf += td->ts.majf;
761 ts->minf += td->ts.minf;
756867bd
JA
762
763 for (k = 0; k < FIO_IO_U_MAP_NR; k++)
764 ts->io_u_map[k] += td->ts.io_u_map[k];
838bc709
JA
765 for (k = 0; k < FIO_IO_U_MAP_NR; k++)
766 ts->io_u_submit[k] += td->ts.io_u_submit[k];
767 for (k = 0; k < FIO_IO_U_MAP_NR; k++)
768 ts->io_u_complete[k] += td->ts.io_u_complete[k];
04a0feae
JA
769 for (k = 0; k < FIO_IO_U_LAT_U_NR; k++)
770 ts->io_u_lat_u[k] += td->ts.io_u_lat_u[k];
771 for (k = 0; k < FIO_IO_U_LAT_M_NR; k++)
772 ts->io_u_lat_m[k] += td->ts.io_u_lat_m[k];
773
756867bd 774
0d29de83 775 for (k = 0; k <= 2; k++) {
b3605062 776 ts->total_io_u[k] += td->ts.total_io_u[k];
30061b97 777 ts->short_io_u[k] += td->ts.short_io_u[k];
83349190
YH
778
779 int m;
780 for (m = 0; m < FIO_IO_U_PLAT_NR; m++)
781 ts->io_u_plat[k][m] += td->ts.io_u_plat[k][m];
30061b97 782 }
756867bd
JA
783
784 ts->total_run_time += td->ts.total_run_time;
838bc709
JA
785 ts->total_submit += td->ts.total_submit;
786 ts->total_complete += td->ts.total_complete;
756867bd
JA
787 }
788
789 for (i = 0; i < nr_ts; i++) {
94370ac4 790 unsigned long long bw;
3c39a379 791
756867bd
JA
792 ts = &threadstats[i];
793 rs = &runstats[ts->groupid];
90fef2d1 794 rs->kb_base = ts->kb_base;
3c39a379 795
de64df05 796 for (j = 0; j <= DDIR_WRITE; j++) {
94370ac4
JA
797 if (!ts->runtime[j])
798 continue;
799 if (ts->runtime[j] < rs->min_run[j] || !rs->min_run[j])
800 rs->min_run[j] = ts->runtime[j];
801 if (ts->runtime[j] > rs->max_run[j])
802 rs->max_run[j] = ts->runtime[j];
803
804 bw = 0;
8879fd15
JA
805 if (ts->runtime[j]) {
806 unsigned long runt;
807
90fef2d1 808 runt = ts->runtime[j];
8879fd15
JA
809 bw = ts->io_bytes[j] / runt;
810 }
94370ac4
JA
811 if (bw < rs->min_bw[j])
812 rs->min_bw[j] = bw;
813 if (bw > rs->max_bw[j])
814 rs->max_bw[j] = bw;
815
90fef2d1 816 rs->io_kb[j] += ts->io_bytes[j] / rs->kb_base;
94370ac4 817 }
3c39a379
JA
818 }
819
820 for (i = 0; i < groupid + 1; i++) {
8879fd15
JA
821 unsigned long max_run[2];
822
3c39a379 823 rs = &runstats[i];
90fef2d1
JA
824 max_run[0] = rs->max_run[0];
825 max_run[1] = rs->max_run[1];
3c39a379
JA
826
827 if (rs->max_run[0])
4cf1abc3 828 rs->agg[0] = (rs->io_kb[0] * 1000) / max_run[0];
3c39a379 829 if (rs->max_run[1])
4cf1abc3 830 rs->agg[1] = (rs->io_kb[1] * 1000) / max_run[1];
3c39a379
JA
831 }
832
833 /*
834 * don't overwrite last signal output
835 */
c6ae0a5b 836 if (!terse_output)
4ceb30d4 837 log_info("\n");
3c39a379 838
756867bd
JA
839 for (i = 0; i < nr_ts; i++) {
840 ts = &threadstats[i];
841 rs = &runstats[ts->groupid];
3c39a379 842
c6ae0a5b 843 if (terse_output)
756867bd 844 show_thread_status_terse(ts, rs);
c6ae0a5b 845 else
756867bd 846 show_thread_status(ts, rs);
3c39a379
JA
847 }
848
c6ae0a5b
JA
849 if (!terse_output) {
850 for (i = 0; i < groupid + 1; i++)
851 show_group_stats(&runstats[i], i);
3c39a379 852
c6ae0a5b
JA
853 show_disk_util();
854 }
eecf272f
JA
855
856 free(runstats);
756867bd 857 free(threadstats);
3c39a379
JA
858}
859
68704084 860static inline void add_stat_sample(struct io_stat *is, unsigned long data)
3c39a379 861{
68704084 862 double val = data;
6660cc67 863 double delta;
68704084
JA
864
865 if (data > is->max_val)
866 is->max_val = data;
867 if (data < is->min_val)
868 is->min_val = data;
869
870 delta = val - is->mean;
ef11d737
JA
871 if (delta) {
872 is->mean += delta / (is->samples + 1.0);
873 is->S += delta * (val - is->mean);
874 }
3c39a379 875
3c39a379
JA
876 is->samples++;
877}
878
bb3884d8 879static void __add_log_sample(struct io_log *iolog, unsigned long val,
306ddc97 880 enum fio_ddir ddir, unsigned int bs,
2b13e716 881 unsigned long t)
3c39a379 882{
306ddc97
JA
883 const int nr_samples = iolog->nr_samples;
884
3c39a379
JA
885 if (iolog->nr_samples == iolog->max_samples) {
886 int new_size = sizeof(struct io_sample) * iolog->max_samples*2;
887
888 iolog->log = realloc(iolog->log, new_size);
889 iolog->max_samples <<= 1;
890 }
891
306ddc97 892 iolog->log[nr_samples].val = val;
2b13e716 893 iolog->log[nr_samples].time = t;
306ddc97
JA
894 iolog->log[nr_samples].ddir = ddir;
895 iolog->log[nr_samples].bs = bs;
3c39a379
JA
896 iolog->nr_samples++;
897}
898
bb3884d8 899static void add_log_sample(struct thread_data *td, struct io_log *iolog,
306ddc97
JA
900 unsigned long val, enum fio_ddir ddir,
901 unsigned int bs)
bb3884d8 902{
ff58fced
JA
903 if (!ddir_rw(ddir))
904 return;
905
306ddc97 906 __add_log_sample(iolog, val, ddir, bs, mtime_since_now(&td->epoch));
bb3884d8
JA
907}
908
306ddc97 909void add_agg_sample(unsigned long val, enum fio_ddir ddir, unsigned int bs)
bb3884d8 910{
ff58fced 911 struct io_log *iolog;
bb3884d8 912
ff58fced
JA
913 if (!ddir_rw(ddir))
914 return;
915
916 iolog = agg_io_log[ddir];
306ddc97 917 __add_log_sample(iolog, val, ddir, bs, mtime_since_genesis());
bb3884d8
JA
918}
919
83349190
YH
920static void add_clat_percentile_sample(struct thread_stat *ts,
921 unsigned long usec, enum fio_ddir ddir)
922{
923 unsigned int idx = plat_val_to_idx(usec);
924 assert(idx < FIO_IO_U_PLAT_NR);
925
926 ts->io_u_plat[ddir][idx]++;
927}
928
1e97cce9 929void add_clat_sample(struct thread_data *td, enum fio_ddir ddir,
306ddc97 930 unsigned long usec, unsigned int bs)
3c39a379 931{
756867bd 932 struct thread_stat *ts = &td->ts;
079ad09b 933
ff58fced
JA
934 if (!ddir_rw(ddir))
935 return;
936
d85f5118 937 add_stat_sample(&ts->clat_stat[ddir], usec);
3c39a379 938
079ad09b 939 if (ts->clat_log)
306ddc97 940 add_log_sample(td, ts->clat_log, usec, ddir, bs);
83349190
YH
941
942 if (ts->clat_percentiles)
943 add_clat_percentile_sample(ts, usec, ddir);
3c39a379
JA
944}
945
1e97cce9 946void add_slat_sample(struct thread_data *td, enum fio_ddir ddir,
306ddc97 947 unsigned long usec, unsigned int bs)
3c39a379 948{
756867bd 949 struct thread_stat *ts = &td->ts;
079ad09b 950
ff58fced
JA
951 if (!ddir_rw(ddir))
952 return;
953
d85f5118 954 add_stat_sample(&ts->slat_stat[ddir], usec);
3c39a379 955
079ad09b 956 if (ts->slat_log)
306ddc97 957 add_log_sample(td, ts->slat_log, usec, ddir, bs);
3c39a379
JA
958}
959
02af0988
JA
960void add_lat_sample(struct thread_data *td, enum fio_ddir ddir,
961 unsigned long usec, unsigned int bs)
962{
963 struct thread_stat *ts = &td->ts;
964
ff58fced
JA
965 if (!ddir_rw(ddir))
966 return;
967
02af0988
JA
968 add_stat_sample(&ts->lat_stat[ddir], usec);
969
970 if (ts->lat_log)
971 add_log_sample(td, ts->lat_log, usec, ddir, bs);
972}
973
306ddc97 974void add_bw_sample(struct thread_data *td, enum fio_ddir ddir, unsigned int bs,
1e97cce9 975 struct timeval *t)
3c39a379 976{
756867bd 977 struct thread_stat *ts = &td->ts;
ff58fced
JA
978 unsigned long spent, rate;
979
980 if (!ddir_rw(ddir))
981 return;
3c39a379 982
ff58fced 983 spent = mtime_since(&ts->stat_sample_time[ddir], t);
2dc1bbeb 984 if (spent < td->o.bw_avg_time)
3c39a379
JA
985 return;
986
0b9d69ec
JA
987 rate = (td->this_io_bytes[ddir] - ts->stat_io_bytes[ddir]) *
988 1000 / spent / 1024;
079ad09b 989 add_stat_sample(&ts->bw_stat[ddir], rate);
3c39a379 990
079ad09b 991 if (ts->bw_log)
306ddc97 992 add_log_sample(td, ts->bw_log, rate, ddir, bs);
3c39a379 993
079ad09b
JA
994 fio_gettime(&ts->stat_sample_time[ddir], NULL);
995 ts->stat_io_bytes[ddir] = td->this_io_bytes[ddir];
3c39a379 996}