stat.c revision b9e1b49128450bcfd792165354b98026e3ac2734
1#include <stdio.h> 2#include <string.h> 3#include <sys/time.h> 4#include <sys/types.h> 5#include <sys/stat.h> 6#include <dirent.h> 7#include <libgen.h> 8#include <math.h> 9 10#include "fio.h" 11#include "diskutil.h" 12#include "lib/ieee754.h" 13#include "json.h" 14#include "lib/getrusage.h" 15#include "idletime.h" 16 17void update_rusage_stat(struct thread_data *td) 18{ 19 struct thread_stat *ts = &td->ts; 20 21 fio_getrusage(&td->ru_end); 22 ts->usr_time += mtime_since(&td->ru_start.ru_utime, 23 &td->ru_end.ru_utime); 24 ts->sys_time += mtime_since(&td->ru_start.ru_stime, 25 &td->ru_end.ru_stime); 26 ts->ctx += td->ru_end.ru_nvcsw + td->ru_end.ru_nivcsw 27 - (td->ru_start.ru_nvcsw + td->ru_start.ru_nivcsw); 28 ts->minf += td->ru_end.ru_minflt - td->ru_start.ru_minflt; 29 ts->majf += td->ru_end.ru_majflt - td->ru_start.ru_majflt; 30 31 memcpy(&td->ru_start, &td->ru_end, sizeof(td->ru_end)); 32} 33 34/* 35 * Given a latency, return the index of the corresponding bucket in 36 * the structure tracking percentiles. 37 * 38 * (1) find the group (and error bits) that the value (latency) 39 * belongs to by looking at its MSB. (2) find the bucket number in the 40 * group by looking at the index bits. 41 * 42 */ 43static unsigned int plat_val_to_idx(unsigned int val) 44{ 45 unsigned int msb, error_bits, base, offset, idx; 46 47 /* Find MSB starting from bit 0 */ 48 if (val == 0) 49 msb = 0; 50 else 51 msb = (sizeof(val)*8) - __builtin_clz(val) - 1; 52 53 /* 54 * MSB <= (FIO_IO_U_PLAT_BITS-1), cannot be rounded off. Use 55 * all bits of the sample as index 56 */ 57 if (msb <= FIO_IO_U_PLAT_BITS) 58 return val; 59 60 /* Compute the number of error bits to discard*/ 61 error_bits = msb - FIO_IO_U_PLAT_BITS; 62 63 /* Compute the number of buckets before the group */ 64 base = (error_bits + 1) << FIO_IO_U_PLAT_BITS; 65 66 /* 67 * Discard the error bits and apply the mask to find the 68 * index for the buckets in the group 69 */ 70 offset = (FIO_IO_U_PLAT_VAL - 1) & (val >> error_bits); 71 72 /* Make sure the index does not exceed (array size - 1) */ 73 idx = (base + offset) < (FIO_IO_U_PLAT_NR - 1)? 74 (base + offset) : (FIO_IO_U_PLAT_NR - 1); 75 76 return idx; 77} 78 79/* 80 * Convert the given index of the bucket array to the value 81 * represented by the bucket 82 */ 83static unsigned int plat_idx_to_val(unsigned int idx) 84{ 85 unsigned int error_bits, k, base; 86 87 assert(idx < FIO_IO_U_PLAT_NR); 88 89 /* MSB <= (FIO_IO_U_PLAT_BITS-1), cannot be rounded off. Use 90 * all bits of the sample as index */ 91 if (idx < (FIO_IO_U_PLAT_VAL << 1) ) 92 return idx; 93 94 /* Find the group and compute the minimum value of that group */ 95 error_bits = (idx >> FIO_IO_U_PLAT_BITS) -1; 96 base = 1 << (error_bits + FIO_IO_U_PLAT_BITS); 97 98 /* Find its bucket number of the group */ 99 k = idx % FIO_IO_U_PLAT_VAL; 100 101 /* Return the mean of the range of the bucket */ 102 return base + ((k + 0.5) * (1 << error_bits)); 103} 104 105static int double_cmp(const void *a, const void *b) 106{ 107 const fio_fp64_t fa = *(const fio_fp64_t *) a; 108 const fio_fp64_t fb = *(const fio_fp64_t *) b; 109 int cmp = 0; 110 111 if (fa.u.f > fb.u.f) 112 cmp = 1; 113 else if (fa.u.f < fb.u.f) 114 cmp = -1; 115 116 return cmp; 117} 118 119static unsigned int calc_clat_percentiles(unsigned int *io_u_plat, 120 unsigned long nr, fio_fp64_t *plist, 121 unsigned int **output, 122 unsigned int *maxv, 123 unsigned int *minv) 124{ 125 unsigned long sum = 0; 126 unsigned int len, i, j = 0; 127 unsigned int oval_len = 0; 128 unsigned int *ovals = NULL; 129 int is_last; 130 131 *minv = -1U; 132 *maxv = 0; 133 134 len = 0; 135 while (len < FIO_IO_U_LIST_MAX_LEN && plist[len].u.f != 0.0) 136 len++; 137 138 if (!len) 139 return 0; 140 141 /* 142 * Sort the percentile list. Note that it may already be sorted if 143 * we are using the default values, but since it's a short list this 144 * isn't a worry. Also note that this does not work for NaN values. 145 */ 146 if (len > 1) 147 qsort((void*)plist, len, sizeof(plist[0]), double_cmp); 148 149 /* 150 * Calculate bucket values, note down max and min values 151 */ 152 is_last = 0; 153 for (i = 0; i < FIO_IO_U_PLAT_NR && !is_last; i++) { 154 sum += io_u_plat[i]; 155 while (sum >= (plist[j].u.f / 100.0 * nr)) { 156 assert(plist[j].u.f <= 100.0); 157 158 if (j == oval_len) { 159 oval_len += 100; 160 ovals = realloc(ovals, oval_len * sizeof(unsigned int)); 161 } 162 163 ovals[j] = plat_idx_to_val(i); 164 if (ovals[j] < *minv) 165 *minv = ovals[j]; 166 if (ovals[j] > *maxv) 167 *maxv = ovals[j]; 168 169 is_last = (j == len - 1); 170 if (is_last) 171 break; 172 173 j++; 174 } 175 } 176 177 *output = ovals; 178 return len; 179} 180 181/* 182 * Find and display the p-th percentile of clat 183 */ 184static void show_clat_percentiles(unsigned int *io_u_plat, unsigned long nr, 185 fio_fp64_t *plist, unsigned int precision) 186{ 187 unsigned int len, j = 0, minv, maxv; 188 unsigned int *ovals; 189 int is_last, per_line, scale_down; 190 char fmt[32]; 191 192 len = calc_clat_percentiles(io_u_plat, nr, plist, &ovals, &maxv, &minv); 193 if (!len) 194 goto out; 195 196 /* 197 * We default to usecs, but if the value range is such that we 198 * should scale down to msecs, do that. 199 */ 200 if (minv > 2000 && maxv > 99999) { 201 scale_down = 1; 202 log_info(" clat percentiles (msec):\n |"); 203 } else { 204 scale_down = 0; 205 log_info(" clat percentiles (usec):\n |"); 206 } 207 208 snprintf(fmt, sizeof(fmt), "%%1.%uf", precision); 209 per_line = (80 - 7) / (precision + 14); 210 211 for (j = 0; j < len; j++) { 212 char fbuf[16], *ptr = fbuf; 213 214 /* for formatting */ 215 if (j != 0 && (j % per_line) == 0) 216 log_info(" |"); 217 218 /* end of the list */ 219 is_last = (j == len - 1); 220 221 if (plist[j].u.f < 10.0) 222 ptr += sprintf(fbuf, " "); 223 224 snprintf(ptr, sizeof(fbuf), fmt, plist[j].u.f); 225 226 if (scale_down) 227 ovals[j] = (ovals[j] + 999) / 1000; 228 229 log_info(" %sth=[%5u]%c", fbuf, ovals[j], is_last ? '\n' : ','); 230 231 if (is_last) 232 break; 233 234 if ((j % per_line) == per_line - 1) /* for formatting */ 235 log_info("\n"); 236 } 237 238out: 239 if (ovals) 240 free(ovals); 241} 242 243static int calc_lat(struct io_stat *is, unsigned long *min, unsigned long *max, 244 double *mean, double *dev) 245{ 246 double n = is->samples; 247 248 if (is->samples == 0) 249 return 0; 250 251 *min = is->min_val; 252 *max = is->max_val; 253 254 n = (double) is->samples; 255 *mean = is->mean.u.f; 256 257 if (n > 1.0) 258 *dev = sqrt(is->S.u.f / (n - 1.0)); 259 else 260 *dev = 0; 261 262 return 1; 263} 264 265void show_group_stats(struct group_run_stats *rs) 266{ 267 char *p1, *p2, *p3, *p4; 268 const char *ddir_str[] = { " READ", " WRITE" , " TRIM"}; 269 int i; 270 271 log_info("\nRun status group %d (all jobs):\n", rs->groupid); 272 273 for (i = 0; i < DDIR_RWDIR_CNT; i++) { 274 const int i2p = is_power_of_2(rs->kb_base); 275 276 if (!rs->max_run[i]) 277 continue; 278 279 p1 = num2str(rs->io_kb[i], 6, rs->kb_base, i2p); 280 p2 = num2str(rs->agg[i], 6, rs->kb_base, i2p); 281 p3 = num2str(rs->min_bw[i], 6, rs->kb_base, i2p); 282 p4 = num2str(rs->max_bw[i], 6, rs->kb_base, i2p); 283 284 log_info("%s: io=%sB, aggrb=%sB/s, minb=%sB/s, maxb=%sB/s," 285 " mint=%llumsec, maxt=%llumsec\n", 286 rs->unified_rw_rep ? " MIXED" : ddir_str[i], 287 p1, p2, p3, p4, rs->min_run[i], rs->max_run[i]); 288 289 free(p1); 290 free(p2); 291 free(p3); 292 free(p4); 293 } 294} 295 296#define ts_total_io_u(ts) \ 297 ((ts)->total_io_u[DDIR_READ] + (ts)->total_io_u[DDIR_WRITE] +\ 298 (ts)->total_io_u[DDIR_TRIM]) 299 300static void stat_calc_dist(unsigned int *map, unsigned long total, 301 double *io_u_dist) 302{ 303 int i; 304 305 /* 306 * Do depth distribution calculations 307 */ 308 for (i = 0; i < FIO_IO_U_MAP_NR; i++) { 309 if (total) { 310 io_u_dist[i] = (double) map[i] / (double) total; 311 io_u_dist[i] *= 100.0; 312 if (io_u_dist[i] < 0.1 && map[i]) 313 io_u_dist[i] = 0.1; 314 } else 315 io_u_dist[i] = 0.0; 316 } 317} 318 319static void stat_calc_lat(struct thread_stat *ts, double *dst, 320 unsigned int *src, int nr) 321{ 322 unsigned long total = ts_total_io_u(ts); 323 int i; 324 325 /* 326 * Do latency distribution calculations 327 */ 328 for (i = 0; i < nr; i++) { 329 if (total) { 330 dst[i] = (double) src[i] / (double) total; 331 dst[i] *= 100.0; 332 if (dst[i] < 0.01 && src[i]) 333 dst[i] = 0.01; 334 } else 335 dst[i] = 0.0; 336 } 337} 338 339static void stat_calc_lat_u(struct thread_stat *ts, double *io_u_lat) 340{ 341 stat_calc_lat(ts, io_u_lat, ts->io_u_lat_u, FIO_IO_U_LAT_U_NR); 342} 343 344static void stat_calc_lat_m(struct thread_stat *ts, double *io_u_lat) 345{ 346 stat_calc_lat(ts, io_u_lat, ts->io_u_lat_m, FIO_IO_U_LAT_M_NR); 347} 348 349static int usec_to_msec(unsigned long *min, unsigned long *max, double *mean, 350 double *dev) 351{ 352 if (*min > 1000 && *max > 1000 && *mean > 1000.0 && *dev > 1000.0) { 353 *min /= 1000; 354 *max /= 1000; 355 *mean /= 1000.0; 356 *dev /= 1000.0; 357 return 0; 358 } 359 360 return 1; 361} 362 363static void show_ddir_status(struct group_run_stats *rs, struct thread_stat *ts, 364 int ddir) 365{ 366 const char *ddir_str[] = { "read ", "write", "trim" }; 367 unsigned long min, max, runt; 368 unsigned long long bw, iops; 369 double mean, dev; 370 char *io_p, *bw_p, *iops_p; 371 int i2p; 372 373 assert(ddir_rw(ddir)); 374 375 if (!ts->runtime[ddir]) 376 return; 377 378 i2p = is_power_of_2(rs->kb_base); 379 runt = ts->runtime[ddir]; 380 381 bw = (1000 * ts->io_bytes[ddir]) / runt; 382 io_p = num2str(ts->io_bytes[ddir], 6, 1, i2p); 383 bw_p = num2str(bw, 6, 1, i2p); 384 385 iops = (1000 * (uint64_t)ts->total_io_u[ddir]) / runt; 386 iops_p = num2str(iops, 6, 1, 0); 387 388 log_info(" %s: io=%sB, bw=%sB/s, iops=%s, runt=%6llumsec\n", 389 rs->unified_rw_rep ? "mixed" : ddir_str[ddir], 390 io_p, bw_p, iops_p, ts->runtime[ddir]); 391 392 free(io_p); 393 free(bw_p); 394 free(iops_p); 395 396 if (calc_lat(&ts->slat_stat[ddir], &min, &max, &mean, &dev)) { 397 const char *base = "(usec)"; 398 char *minp, *maxp; 399 400 if (!usec_to_msec(&min, &max, &mean, &dev)) 401 base = "(msec)"; 402 403 minp = num2str(min, 6, 1, 0); 404 maxp = num2str(max, 6, 1, 0); 405 406 log_info(" slat %s: min=%s, max=%s, avg=%5.02f," 407 " stdev=%5.02f\n", base, minp, maxp, mean, dev); 408 409 free(minp); 410 free(maxp); 411 } 412 if (calc_lat(&ts->clat_stat[ddir], &min, &max, &mean, &dev)) { 413 const char *base = "(usec)"; 414 char *minp, *maxp; 415 416 if (!usec_to_msec(&min, &max, &mean, &dev)) 417 base = "(msec)"; 418 419 minp = num2str(min, 6, 1, 0); 420 maxp = num2str(max, 6, 1, 0); 421 422 log_info(" clat %s: min=%s, max=%s, avg=%5.02f," 423 " stdev=%5.02f\n", base, minp, maxp, mean, dev); 424 425 free(minp); 426 free(maxp); 427 } 428 if (calc_lat(&ts->lat_stat[ddir], &min, &max, &mean, &dev)) { 429 const char *base = "(usec)"; 430 char *minp, *maxp; 431 432 if (!usec_to_msec(&min, &max, &mean, &dev)) 433 base = "(msec)"; 434 435 minp = num2str(min, 6, 1, 0); 436 maxp = num2str(max, 6, 1, 0); 437 438 log_info(" lat %s: min=%s, max=%s, avg=%5.02f," 439 " stdev=%5.02f\n", base, minp, maxp, mean, dev); 440 441 free(minp); 442 free(maxp); 443 } 444 if (ts->clat_percentiles) { 445 show_clat_percentiles(ts->io_u_plat[ddir], 446 ts->clat_stat[ddir].samples, 447 ts->percentile_list, 448 ts->percentile_precision); 449 } 450 if (calc_lat(&ts->bw_stat[ddir], &min, &max, &mean, &dev)) { 451 double p_of_agg = 100.0; 452 const char *bw_str = "KB"; 453 454 if (rs->agg[ddir]) { 455 p_of_agg = mean * 100 / (double) rs->agg[ddir]; 456 if (p_of_agg > 100.0) 457 p_of_agg = 100.0; 458 } 459 460 if (mean > 999999.9) { 461 min /= 1000.0; 462 max /= 1000.0; 463 mean /= 1000.0; 464 dev /= 1000.0; 465 bw_str = "MB"; 466 } 467 468 log_info(" bw (%s/s) : min=%5lu, max=%5lu, per=%3.2f%%," 469 " avg=%5.02f, stdev=%5.02f\n", bw_str, min, max, 470 p_of_agg, mean, dev); 471 } 472} 473 474static int show_lat(double *io_u_lat, int nr, const char **ranges, 475 const char *msg) 476{ 477 int new_line = 1, i, line = 0, shown = 0; 478 479 for (i = 0; i < nr; i++) { 480 if (io_u_lat[i] <= 0.0) 481 continue; 482 shown = 1; 483 if (new_line) { 484 if (line) 485 log_info("\n"); 486 log_info(" lat (%s) : ", msg); 487 new_line = 0; 488 line = 0; 489 } 490 if (line) 491 log_info(", "); 492 log_info("%s%3.2f%%", ranges[i], io_u_lat[i]); 493 line++; 494 if (line == 5) 495 new_line = 1; 496 } 497 498 if (shown) 499 log_info("\n"); 500 501 return shown; 502} 503 504static void show_lat_u(double *io_u_lat_u) 505{ 506 const char *ranges[] = { "2=", "4=", "10=", "20=", "50=", "100=", 507 "250=", "500=", "750=", "1000=", }; 508 509 show_lat(io_u_lat_u, FIO_IO_U_LAT_U_NR, ranges, "usec"); 510} 511 512static void show_lat_m(double *io_u_lat_m) 513{ 514 const char *ranges[] = { "2=", "4=", "10=", "20=", "50=", "100=", 515 "250=", "500=", "750=", "1000=", "2000=", 516 ">=2000=", }; 517 518 show_lat(io_u_lat_m, FIO_IO_U_LAT_M_NR, ranges, "msec"); 519} 520 521static void show_latencies(double *io_u_lat_u, double *io_u_lat_m) 522{ 523 show_lat_u(io_u_lat_u); 524 show_lat_m(io_u_lat_m); 525} 526 527void show_thread_status(struct thread_stat *ts, struct group_run_stats *rs) 528{ 529 double usr_cpu, sys_cpu; 530 unsigned long runtime; 531 double io_u_dist[FIO_IO_U_MAP_NR]; 532 double io_u_lat_u[FIO_IO_U_LAT_U_NR]; 533 double io_u_lat_m[FIO_IO_U_LAT_M_NR]; 534 time_t time_p; 535 char time_buf[64]; 536 537 if (!(ts->io_bytes[DDIR_READ] + ts->io_bytes[DDIR_WRITE] + 538 ts->io_bytes[DDIR_TRIM]) && !(ts->total_io_u[DDIR_READ] + 539 ts->total_io_u[DDIR_WRITE] + ts->total_io_u[DDIR_TRIM])) 540 return; 541 542 time(&time_p); 543 os_ctime_r((const time_t *) &time_p, time_buf, sizeof(time_buf)); 544 545 if (!ts->error) { 546 log_info("%s: (groupid=%d, jobs=%d): err=%2d: pid=%d: %s", 547 ts->name, ts->groupid, ts->members, 548 ts->error, (int) ts->pid, time_buf); 549 } else { 550 log_info("%s: (groupid=%d, jobs=%d): err=%2d (%s): pid=%d: %s", 551 ts->name, ts->groupid, ts->members, 552 ts->error, ts->verror, (int) ts->pid, 553 time_buf); 554 } 555 556 if (strlen(ts->description)) 557 log_info(" Description : [%s]\n", ts->description); 558 559 if (ts->io_bytes[DDIR_READ]) 560 show_ddir_status(rs, ts, DDIR_READ); 561 if (ts->io_bytes[DDIR_WRITE]) 562 show_ddir_status(rs, ts, DDIR_WRITE); 563 if (ts->io_bytes[DDIR_TRIM]) 564 show_ddir_status(rs, ts, DDIR_TRIM); 565 566 stat_calc_lat_u(ts, io_u_lat_u); 567 stat_calc_lat_m(ts, io_u_lat_m); 568 show_latencies(io_u_lat_u, io_u_lat_m); 569 570 runtime = ts->total_run_time; 571 if (runtime) { 572 double runt = (double) runtime; 573 574 usr_cpu = (double) ts->usr_time * 100 / runt; 575 sys_cpu = (double) ts->sys_time * 100 / runt; 576 } else { 577 usr_cpu = 0; 578 sys_cpu = 0; 579 } 580 581 log_info(" cpu : usr=%3.2f%%, sys=%3.2f%%, ctx=%lu, majf=%lu," 582 " minf=%lu\n", usr_cpu, sys_cpu, ts->ctx, ts->majf, ts->minf); 583 584 stat_calc_dist(ts->io_u_map, ts_total_io_u(ts), io_u_dist); 585 log_info(" IO depths : 1=%3.1f%%, 2=%3.1f%%, 4=%3.1f%%, 8=%3.1f%%," 586 " 16=%3.1f%%, 32=%3.1f%%, >=64=%3.1f%%\n", io_u_dist[0], 587 io_u_dist[1], io_u_dist[2], 588 io_u_dist[3], io_u_dist[4], 589 io_u_dist[5], io_u_dist[6]); 590 591 stat_calc_dist(ts->io_u_submit, ts->total_submit, io_u_dist); 592 log_info(" submit : 0=%3.1f%%, 4=%3.1f%%, 8=%3.1f%%, 16=%3.1f%%," 593 " 32=%3.1f%%, 64=%3.1f%%, >=64=%3.1f%%\n", io_u_dist[0], 594 io_u_dist[1], io_u_dist[2], 595 io_u_dist[3], io_u_dist[4], 596 io_u_dist[5], io_u_dist[6]); 597 stat_calc_dist(ts->io_u_complete, ts->total_complete, io_u_dist); 598 log_info(" complete : 0=%3.1f%%, 4=%3.1f%%, 8=%3.1f%%, 16=%3.1f%%," 599 " 32=%3.1f%%, 64=%3.1f%%, >=64=%3.1f%%\n", io_u_dist[0], 600 io_u_dist[1], io_u_dist[2], 601 io_u_dist[3], io_u_dist[4], 602 io_u_dist[5], io_u_dist[6]); 603 log_info(" issued : total=r=%lu/w=%lu/d=%lu," 604 " short=r=%lu/w=%lu/d=%lu\n", 605 ts->total_io_u[0], ts->total_io_u[1], 606 ts->total_io_u[2], 607 ts->short_io_u[0], ts->short_io_u[1], 608 ts->short_io_u[2]); 609 if (ts->continue_on_error) { 610 log_info(" errors : total=%lu, first_error=%d/<%s>\n", 611 ts->total_err_count, 612 ts->first_error, 613 strerror(ts->first_error)); 614 } 615} 616 617static void show_ddir_status_terse(struct thread_stat *ts, 618 struct group_run_stats *rs, int ddir) 619{ 620 unsigned long min, max; 621 unsigned long long bw, iops; 622 unsigned int *ovals = NULL; 623 double mean, dev; 624 unsigned int len, minv, maxv; 625 int i; 626 627 assert(ddir_rw(ddir)); 628 629 iops = bw = 0; 630 if (ts->runtime[ddir]) { 631 uint64_t runt = ts->runtime[ddir]; 632 633 bw = ((1000 * ts->io_bytes[ddir]) / runt) / 1024; 634 iops = (1000 * (uint64_t) ts->total_io_u[ddir]) / runt; 635 } 636 637 log_info(";%llu;%llu;%llu;%llu", ts->io_bytes[ddir] >> 10, bw, iops, 638 ts->runtime[ddir]); 639 640 if (calc_lat(&ts->slat_stat[ddir], &min, &max, &mean, &dev)) 641 log_info(";%lu;%lu;%f;%f", min, max, mean, dev); 642 else 643 log_info(";%lu;%lu;%f;%f", 0UL, 0UL, 0.0, 0.0); 644 645 if (calc_lat(&ts->clat_stat[ddir], &min, &max, &mean, &dev)) 646 log_info(";%lu;%lu;%f;%f", min, max, mean, dev); 647 else 648 log_info(";%lu;%lu;%f;%f", 0UL, 0UL, 0.0, 0.0); 649 650 if (ts->clat_percentiles) { 651 len = calc_clat_percentiles(ts->io_u_plat[ddir], 652 ts->clat_stat[ddir].samples, 653 ts->percentile_list, &ovals, &maxv, 654 &minv); 655 } else 656 len = 0; 657 658 for (i = 0; i < FIO_IO_U_LIST_MAX_LEN; i++) { 659 if (i >= len) { 660 log_info(";0%%=0"); 661 continue; 662 } 663 log_info(";%f%%=%u", ts->percentile_list[i].u.f, ovals[i]); 664 } 665 666 if (calc_lat(&ts->lat_stat[ddir], &min, &max, &mean, &dev)) 667 log_info(";%lu;%lu;%f;%f", min, max, mean, dev); 668 else 669 log_info(";%lu;%lu;%f;%f", 0UL, 0UL, 0.0, 0.0); 670 671 if (ovals) 672 free(ovals); 673 674 if (calc_lat(&ts->bw_stat[ddir], &min, &max, &mean, &dev)) { 675 double p_of_agg = 100.0; 676 677 if (rs->agg[ddir]) { 678 p_of_agg = mean * 100 / (double) rs->agg[ddir]; 679 if (p_of_agg > 100.0) 680 p_of_agg = 100.0; 681 } 682 683 log_info(";%lu;%lu;%f%%;%f;%f", min, max, p_of_agg, mean, dev); 684 } else 685 log_info(";%lu;%lu;%f%%;%f;%f", 0UL, 0UL, 0.0, 0.0, 0.0); 686} 687 688static void add_ddir_status_json(struct thread_stat *ts, 689 struct group_run_stats *rs, int ddir, struct json_object *parent) 690{ 691 unsigned long min, max; 692 unsigned long long bw, iops; 693 unsigned int *ovals = NULL; 694 double mean, dev; 695 unsigned int len, minv, maxv; 696 int i; 697 const char *ddirname[] = {"read", "write", "trim"}; 698 struct json_object *dir_object, *tmp_object, *percentile_object; 699 char buf[120]; 700 double p_of_agg = 100.0; 701 702 assert(ddir_rw(ddir)); 703 704 if (ts->unified_rw_rep && ddir != DDIR_READ) 705 return; 706 707 dir_object = json_create_object(); 708 json_object_add_value_object(parent, 709 ts->unified_rw_rep ? "mixed" : ddirname[ddir], dir_object); 710 711 iops = bw = 0; 712 if (ts->runtime[ddir]) { 713 uint64_t runt = ts->runtime[ddir]; 714 715 bw = ((1000 * ts->io_bytes[ddir]) / runt) / 1024; 716 iops = (1000 * (uint64_t) ts->total_io_u[ddir]) / runt; 717 } 718 719 json_object_add_value_int(dir_object, "io_bytes", ts->io_bytes[ddir] >> 10); 720 json_object_add_value_int(dir_object, "bw", bw); 721 json_object_add_value_int(dir_object, "iops", iops); 722 json_object_add_value_int(dir_object, "runtime", ts->runtime[ddir]); 723 724 if (!calc_lat(&ts->slat_stat[ddir], &min, &max, &mean, &dev)) { 725 min = max = 0; 726 mean = dev = 0.0; 727 } 728 tmp_object = json_create_object(); 729 json_object_add_value_object(dir_object, "slat", tmp_object); 730 json_object_add_value_int(tmp_object, "min", min); 731 json_object_add_value_int(tmp_object, "max", max); 732 json_object_add_value_float(tmp_object, "mean", mean); 733 json_object_add_value_float(tmp_object, "stddev", dev); 734 735 if (!calc_lat(&ts->clat_stat[ddir], &min, &max, &mean, &dev)) { 736 min = max = 0; 737 mean = dev = 0.0; 738 } 739 tmp_object = json_create_object(); 740 json_object_add_value_object(dir_object, "clat", tmp_object); 741 json_object_add_value_int(tmp_object, "min", min); 742 json_object_add_value_int(tmp_object, "max", max); 743 json_object_add_value_float(tmp_object, "mean", mean); 744 json_object_add_value_float(tmp_object, "stddev", dev); 745 746 if (ts->clat_percentiles) { 747 len = calc_clat_percentiles(ts->io_u_plat[ddir], 748 ts->clat_stat[ddir].samples, 749 ts->percentile_list, &ovals, &maxv, 750 &minv); 751 } else 752 len = 0; 753 754 percentile_object = json_create_object(); 755 json_object_add_value_object(tmp_object, "percentile", percentile_object); 756 for (i = 0; i < FIO_IO_U_LIST_MAX_LEN; i++) { 757 if (i >= len) { 758 json_object_add_value_int(percentile_object, "0.00", 0); 759 continue; 760 } 761 snprintf(buf, sizeof(buf), "%f", ts->percentile_list[i].u.f); 762 json_object_add_value_int(percentile_object, (const char *)buf, ovals[i]); 763 } 764 765 if (!calc_lat(&ts->lat_stat[ddir], &min, &max, &mean, &dev)) { 766 min = max = 0; 767 mean = dev = 0.0; 768 } 769 tmp_object = json_create_object(); 770 json_object_add_value_object(dir_object, "lat", tmp_object); 771 json_object_add_value_int(tmp_object, "min", min); 772 json_object_add_value_int(tmp_object, "max", max); 773 json_object_add_value_float(tmp_object, "mean", mean); 774 json_object_add_value_float(tmp_object, "stddev", dev); 775 if (ovals) 776 free(ovals); 777 778 if (calc_lat(&ts->bw_stat[ddir], &min, &max, &mean, &dev)) { 779 if (rs->agg[ddir]) { 780 p_of_agg = mean * 100 / (double) rs->agg[ddir]; 781 if (p_of_agg > 100.0) 782 p_of_agg = 100.0; 783 } 784 } else { 785 min = max = 0; 786 p_of_agg = mean = dev = 0.0; 787 } 788 json_object_add_value_int(dir_object, "bw_min", min); 789 json_object_add_value_int(dir_object, "bw_max", max); 790 json_object_add_value_float(dir_object, "bw_agg", mean); 791 json_object_add_value_float(dir_object, "bw_mean", mean); 792 json_object_add_value_float(dir_object, "bw_dev", dev); 793} 794 795static void show_thread_status_terse_v2(struct thread_stat *ts, 796 struct group_run_stats *rs) 797{ 798 double io_u_dist[FIO_IO_U_MAP_NR]; 799 double io_u_lat_u[FIO_IO_U_LAT_U_NR]; 800 double io_u_lat_m[FIO_IO_U_LAT_M_NR]; 801 double usr_cpu, sys_cpu; 802 int i; 803 804 /* General Info */ 805 log_info("2;%s;%d;%d", ts->name, ts->groupid, ts->error); 806 /* Log Read Status */ 807 show_ddir_status_terse(ts, rs, DDIR_READ); 808 /* Log Write Status */ 809 show_ddir_status_terse(ts, rs, DDIR_WRITE); 810 /* Log Trim Status */ 811 show_ddir_status_terse(ts, rs, DDIR_TRIM); 812 813 /* CPU Usage */ 814 if (ts->total_run_time) { 815 double runt = (double) ts->total_run_time; 816 817 usr_cpu = (double) ts->usr_time * 100 / runt; 818 sys_cpu = (double) ts->sys_time * 100 / runt; 819 } else { 820 usr_cpu = 0; 821 sys_cpu = 0; 822 } 823 824 log_info(";%f%%;%f%%;%lu;%lu;%lu", usr_cpu, sys_cpu, ts->ctx, ts->majf, 825 ts->minf); 826 827 /* Calc % distribution of IO depths, usecond, msecond latency */ 828 stat_calc_dist(ts->io_u_map, ts_total_io_u(ts), io_u_dist); 829 stat_calc_lat_u(ts, io_u_lat_u); 830 stat_calc_lat_m(ts, io_u_lat_m); 831 832 /* Only show fixed 7 I/O depth levels*/ 833 log_info(";%3.1f%%;%3.1f%%;%3.1f%%;%3.1f%%;%3.1f%%;%3.1f%%;%3.1f%%", 834 io_u_dist[0], io_u_dist[1], io_u_dist[2], io_u_dist[3], 835 io_u_dist[4], io_u_dist[5], io_u_dist[6]); 836 837 /* Microsecond latency */ 838 for (i = 0; i < FIO_IO_U_LAT_U_NR; i++) 839 log_info(";%3.2f%%", io_u_lat_u[i]); 840 /* Millisecond latency */ 841 for (i = 0; i < FIO_IO_U_LAT_M_NR; i++) 842 log_info(";%3.2f%%", io_u_lat_m[i]); 843 /* Additional output if continue_on_error set - default off*/ 844 if (ts->continue_on_error) 845 log_info(";%lu;%d", ts->total_err_count, ts->first_error); 846 log_info("\n"); 847 848 /* Additional output if description is set */ 849 if (ts->description) 850 log_info(";%s", ts->description); 851 852 log_info("\n"); 853} 854 855static void show_thread_status_terse_v3_v4(struct thread_stat *ts, 856 struct group_run_stats *rs, int ver) 857{ 858 double io_u_dist[FIO_IO_U_MAP_NR]; 859 double io_u_lat_u[FIO_IO_U_LAT_U_NR]; 860 double io_u_lat_m[FIO_IO_U_LAT_M_NR]; 861 double usr_cpu, sys_cpu; 862 int i; 863 864 /* General Info */ 865 log_info("%d;%s;%s;%d;%d", ver, fio_version_string, 866 ts->name, ts->groupid, ts->error); 867 /* Log Read Status */ 868 show_ddir_status_terse(ts, rs, DDIR_READ); 869 /* Log Write Status */ 870 show_ddir_status_terse(ts, rs, DDIR_WRITE); 871 /* Log Trim Status */ 872 if (ver == 4) 873 show_ddir_status_terse(ts, rs, DDIR_TRIM); 874 875 /* CPU Usage */ 876 if (ts->total_run_time) { 877 double runt = (double) ts->total_run_time; 878 879 usr_cpu = (double) ts->usr_time * 100 / runt; 880 sys_cpu = (double) ts->sys_time * 100 / runt; 881 } else { 882 usr_cpu = 0; 883 sys_cpu = 0; 884 } 885 886 log_info(";%f%%;%f%%;%lu;%lu;%lu", usr_cpu, sys_cpu, ts->ctx, ts->majf, 887 ts->minf); 888 889 /* Calc % distribution of IO depths, usecond, msecond latency */ 890 stat_calc_dist(ts->io_u_map, ts_total_io_u(ts), io_u_dist); 891 stat_calc_lat_u(ts, io_u_lat_u); 892 stat_calc_lat_m(ts, io_u_lat_m); 893 894 /* Only show fixed 7 I/O depth levels*/ 895 log_info(";%3.1f%%;%3.1f%%;%3.1f%%;%3.1f%%;%3.1f%%;%3.1f%%;%3.1f%%", 896 io_u_dist[0], io_u_dist[1], io_u_dist[2], io_u_dist[3], 897 io_u_dist[4], io_u_dist[5], io_u_dist[6]); 898 899 /* Microsecond latency */ 900 for (i = 0; i < FIO_IO_U_LAT_U_NR; i++) 901 log_info(";%3.2f%%", io_u_lat_u[i]); 902 /* Millisecond latency */ 903 for (i = 0; i < FIO_IO_U_LAT_M_NR; i++) 904 log_info(";%3.2f%%", io_u_lat_m[i]); 905 906 /* disk util stats, if any */ 907 show_disk_util(1, NULL); 908 909 /* Additional output if continue_on_error set - default off*/ 910 if (ts->continue_on_error) 911 log_info(";%lu;%d", ts->total_err_count, ts->first_error); 912 913 /* Additional output if description is set */ 914 if (strlen(ts->description)) 915 log_info(";%s", ts->description); 916 917 log_info("\n"); 918} 919 920static struct json_object *show_thread_status_json(struct thread_stat *ts, 921 struct group_run_stats *rs) 922{ 923 struct json_object *root, *tmp; 924 double io_u_dist[FIO_IO_U_MAP_NR]; 925 double io_u_lat_u[FIO_IO_U_LAT_U_NR]; 926 double io_u_lat_m[FIO_IO_U_LAT_M_NR]; 927 double usr_cpu, sys_cpu; 928 int i; 929 930 root = json_create_object(); 931 json_object_add_value_string(root, "jobname", ts->name); 932 json_object_add_value_int(root, "groupid", ts->groupid); 933 json_object_add_value_int(root, "error", ts->error); 934 935 add_ddir_status_json(ts, rs, DDIR_READ, root); 936 add_ddir_status_json(ts, rs, DDIR_WRITE, root); 937 add_ddir_status_json(ts, rs, DDIR_TRIM, root); 938 939 /* CPU Usage */ 940 if (ts->total_run_time) { 941 double runt = (double) ts->total_run_time; 942 943 usr_cpu = (double) ts->usr_time * 100 / runt; 944 sys_cpu = (double) ts->sys_time * 100 / runt; 945 } else { 946 usr_cpu = 0; 947 sys_cpu = 0; 948 } 949 json_object_add_value_float(root, "usr_cpu", usr_cpu); 950 json_object_add_value_float(root, "sys_cpu", sys_cpu); 951 json_object_add_value_int(root, "ctx", ts->ctx); 952 json_object_add_value_int(root, "majf", ts->majf); 953 json_object_add_value_int(root, "minf", ts->minf); 954 955 956 /* Calc % distribution of IO depths, usecond, msecond latency */ 957 stat_calc_dist(ts->io_u_map, ts_total_io_u(ts), io_u_dist); 958 stat_calc_lat_u(ts, io_u_lat_u); 959 stat_calc_lat_m(ts, io_u_lat_m); 960 961 tmp = json_create_object(); 962 json_object_add_value_object(root, "iodepth_level", tmp); 963 /* Only show fixed 7 I/O depth levels*/ 964 for (i = 0; i < 7; i++) { 965 char name[20]; 966 if (i < 6) 967 snprintf(name, 20, "%d", 1 << i); 968 else 969 snprintf(name, 20, ">=%d", 1 << i); 970 json_object_add_value_float(tmp, (const char *)name, io_u_dist[i]); 971 } 972 973 tmp = json_create_object(); 974 json_object_add_value_object(root, "latency_us", tmp); 975 /* Microsecond latency */ 976 for (i = 0; i < FIO_IO_U_LAT_U_NR; i++) { 977 const char *ranges[] = { "2", "4", "10", "20", "50", "100", 978 "250", "500", "750", "1000", }; 979 json_object_add_value_float(tmp, ranges[i], io_u_lat_u[i]); 980 } 981 /* Millisecond latency */ 982 tmp = json_create_object(); 983 json_object_add_value_object(root, "latency_ms", tmp); 984 for (i = 0; i < FIO_IO_U_LAT_M_NR; i++) { 985 const char *ranges[] = { "2", "4", "10", "20", "50", "100", 986 "250", "500", "750", "1000", "2000", 987 ">=2000", }; 988 json_object_add_value_float(tmp, ranges[i], io_u_lat_m[i]); 989 } 990 991 /* Additional output if continue_on_error set - default off*/ 992 if (ts->continue_on_error) { 993 json_object_add_value_int(root, "total_err", ts->total_err_count); 994 json_object_add_value_int(root, "total_err", ts->first_error); 995 } 996 997 /* Additional output if description is set */ 998 if (strlen(ts->description)) 999 json_object_add_value_string(root, "desc", ts->description); 1000 1001 return root; 1002} 1003 1004static void show_thread_status_terse(struct thread_stat *ts, 1005 struct group_run_stats *rs) 1006{ 1007 if (terse_version == 2) 1008 show_thread_status_terse_v2(ts, rs); 1009 else if (terse_version == 3 || terse_version == 4) 1010 show_thread_status_terse_v3_v4(ts, rs, terse_version); 1011 else 1012 log_err("fio: bad terse version!? %d\n", terse_version); 1013} 1014 1015static void sum_stat(struct io_stat *dst, struct io_stat *src, int nr) 1016{ 1017 double mean, S; 1018 1019 if (src->samples == 0) 1020 return; 1021 1022 dst->min_val = min(dst->min_val, src->min_val); 1023 dst->max_val = max(dst->max_val, src->max_val); 1024 1025 /* 1026 * Compute new mean and S after the merge 1027 * <http://en.wikipedia.org/wiki/Algorithms_for_calculating_variance 1028 * #Parallel_algorithm> 1029 */ 1030 if (nr == 1) { 1031 mean = src->mean.u.f; 1032 S = src->S.u.f; 1033 } else { 1034 double delta = src->mean.u.f - dst->mean.u.f; 1035 1036 mean = ((src->mean.u.f * src->samples) + 1037 (dst->mean.u.f * dst->samples)) / 1038 (dst->samples + src->samples); 1039 1040 S = src->S.u.f + dst->S.u.f + pow(delta, 2.0) * 1041 (dst->samples * src->samples) / 1042 (dst->samples + src->samples); 1043 } 1044 1045 dst->samples += src->samples; 1046 dst->mean.u.f = mean; 1047 dst->S.u.f = S; 1048} 1049 1050void sum_group_stats(struct group_run_stats *dst, struct group_run_stats *src) 1051{ 1052 int i; 1053 1054 for (i = 0; i < DDIR_RWDIR_CNT; i++) { 1055 if (dst->max_run[i] < src->max_run[i]) 1056 dst->max_run[i] = src->max_run[i]; 1057 if (dst->min_run[i] && dst->min_run[i] > src->min_run[i]) 1058 dst->min_run[i] = src->min_run[i]; 1059 if (dst->max_bw[i] < src->max_bw[i]) 1060 dst->max_bw[i] = src->max_bw[i]; 1061 if (dst->min_bw[i] && dst->min_bw[i] > src->min_bw[i]) 1062 dst->min_bw[i] = src->min_bw[i]; 1063 1064 dst->io_kb[i] += src->io_kb[i]; 1065 dst->agg[i] += src->agg[i]; 1066 } 1067 1068} 1069 1070void sum_thread_stats(struct thread_stat *dst, struct thread_stat *src, int nr) 1071{ 1072 int l, k; 1073 1074 for (l = 0; l < DDIR_RWDIR_CNT; l++) { 1075 if (!dst->unified_rw_rep) { 1076 sum_stat(&dst->clat_stat[l], &src->clat_stat[l], nr); 1077 sum_stat(&dst->slat_stat[l], &src->slat_stat[l], nr); 1078 sum_stat(&dst->lat_stat[l], &src->lat_stat[l], nr); 1079 sum_stat(&dst->bw_stat[l], &src->bw_stat[l], nr); 1080 1081 dst->io_bytes[l] += src->io_bytes[l]; 1082 1083 if (dst->runtime[l] < src->runtime[l]) 1084 dst->runtime[l] = src->runtime[l]; 1085 } else { 1086 sum_stat(&dst->clat_stat[0], &src->clat_stat[l], nr); 1087 sum_stat(&dst->slat_stat[0], &src->slat_stat[l], nr); 1088 sum_stat(&dst->lat_stat[0], &src->lat_stat[l], nr); 1089 sum_stat(&dst->bw_stat[0], &src->bw_stat[l], nr); 1090 1091 dst->io_bytes[0] += src->io_bytes[l]; 1092 1093 if (dst->runtime[0] < src->runtime[l]) 1094 dst->runtime[0] = src->runtime[l]; 1095 } 1096 } 1097 1098 dst->usr_time += src->usr_time; 1099 dst->sys_time += src->sys_time; 1100 dst->ctx += src->ctx; 1101 dst->majf += src->majf; 1102 dst->minf += src->minf; 1103 1104 for (k = 0; k < FIO_IO_U_MAP_NR; k++) 1105 dst->io_u_map[k] += src->io_u_map[k]; 1106 for (k = 0; k < FIO_IO_U_MAP_NR; k++) 1107 dst->io_u_submit[k] += src->io_u_submit[k]; 1108 for (k = 0; k < FIO_IO_U_MAP_NR; k++) 1109 dst->io_u_complete[k] += src->io_u_complete[k]; 1110 for (k = 0; k < FIO_IO_U_LAT_U_NR; k++) 1111 dst->io_u_lat_u[k] += src->io_u_lat_u[k]; 1112 for (k = 0; k < FIO_IO_U_LAT_M_NR; k++) 1113 dst->io_u_lat_m[k] += src->io_u_lat_m[k]; 1114 1115 for (k = 0; k < DDIR_RWDIR_CNT; k++) { 1116 if (!dst->unified_rw_rep) { 1117 dst->total_io_u[k] += src->total_io_u[k]; 1118 dst->short_io_u[k] += src->short_io_u[k]; 1119 } else { 1120 dst->total_io_u[0] += src->total_io_u[k]; 1121 dst->short_io_u[0] += src->short_io_u[k]; 1122 } 1123 } 1124 1125 for (k = 0; k < DDIR_RWDIR_CNT; k++) { 1126 int m; 1127 1128 for (m = 0; m < FIO_IO_U_PLAT_NR; m++) { 1129 if (!dst->unified_rw_rep) 1130 dst->io_u_plat[k][m] += src->io_u_plat[k][m]; 1131 else 1132 dst->io_u_plat[0][m] += src->io_u_plat[k][m]; 1133 } 1134 } 1135 1136 dst->total_run_time += src->total_run_time; 1137 dst->total_submit += src->total_submit; 1138 dst->total_complete += src->total_complete; 1139} 1140 1141void init_group_run_stat(struct group_run_stats *gs) 1142{ 1143 int i; 1144 memset(gs, 0, sizeof(*gs)); 1145 1146 for (i = 0; i < DDIR_RWDIR_CNT; i++) 1147 gs->min_bw[i] = gs->min_run[i] = ~0UL; 1148} 1149 1150void init_thread_stat(struct thread_stat *ts) 1151{ 1152 int j; 1153 1154 memset(ts, 0, sizeof(*ts)); 1155 1156 for (j = 0; j < DDIR_RWDIR_CNT; j++) { 1157 ts->lat_stat[j].min_val = -1UL; 1158 ts->clat_stat[j].min_val = -1UL; 1159 ts->slat_stat[j].min_val = -1UL; 1160 ts->bw_stat[j].min_val = -1UL; 1161 } 1162 ts->groupid = -1; 1163} 1164 1165void show_run_stats(void) 1166{ 1167 struct group_run_stats *runstats, *rs; 1168 struct thread_data *td; 1169 struct thread_stat *threadstats, *ts; 1170 int i, j, nr_ts, last_ts, idx; 1171 int kb_base_warned = 0; 1172 struct json_object *root = NULL; 1173 struct json_array *array = NULL; 1174 1175 runstats = malloc(sizeof(struct group_run_stats) * (groupid + 1)); 1176 1177 for (i = 0; i < groupid + 1; i++) 1178 init_group_run_stat(&runstats[i]); 1179 1180 /* 1181 * find out how many threads stats we need. if group reporting isn't 1182 * enabled, it's one-per-td. 1183 */ 1184 nr_ts = 0; 1185 last_ts = -1; 1186 for_each_td(td, i) { 1187 if (!td->o.group_reporting) { 1188 nr_ts++; 1189 continue; 1190 } 1191 if (last_ts == td->groupid) 1192 continue; 1193 1194 last_ts = td->groupid; 1195 nr_ts++; 1196 } 1197 1198 threadstats = malloc(nr_ts * sizeof(struct thread_stat)); 1199 1200 for (i = 0; i < nr_ts; i++) 1201 init_thread_stat(&threadstats[i]); 1202 1203 j = 0; 1204 last_ts = -1; 1205 idx = 0; 1206 for_each_td(td, i) { 1207 if (idx && (!td->o.group_reporting || 1208 (td->o.group_reporting && last_ts != td->groupid))) { 1209 idx = 0; 1210 j++; 1211 } 1212 1213 last_ts = td->groupid; 1214 1215 ts = &threadstats[j]; 1216 1217 ts->clat_percentiles = td->o.clat_percentiles; 1218 ts->percentile_precision = td->o.percentile_precision; 1219 memcpy(ts->percentile_list, td->o.percentile_list, sizeof(td->o.percentile_list)); 1220 1221 idx++; 1222 ts->members++; 1223 1224 if (ts->groupid == -1) { 1225 /* 1226 * These are per-group shared already 1227 */ 1228 strncpy(ts->name, td->o.name, FIO_JOBNAME_SIZE); 1229 if (td->o.description) 1230 strncpy(ts->description, td->o.description, 1231 FIO_JOBNAME_SIZE); 1232 else 1233 memset(ts->description, 0, FIO_JOBNAME_SIZE); 1234 1235 ts->groupid = td->groupid; 1236 1237 /* 1238 * first pid in group, not very useful... 1239 */ 1240 ts->pid = td->pid; 1241 1242 ts->kb_base = td->o.kb_base; 1243 ts->unified_rw_rep = td->o.unified_rw_rep; 1244 } else if (ts->kb_base != td->o.kb_base && !kb_base_warned) { 1245 log_info("fio: kb_base differs for jobs in group, using" 1246 " %u as the base\n", ts->kb_base); 1247 kb_base_warned = 1; 1248 } 1249 1250 ts->continue_on_error = td->o.continue_on_error; 1251 ts->total_err_count += td->total_err_count; 1252 ts->first_error = td->first_error; 1253 if (!ts->error) { 1254 if (!td->error && td->o.continue_on_error && 1255 td->first_error) { 1256 ts->error = td->first_error; 1257 strcpy(ts->verror, td->verror); 1258 } else if (td->error) { 1259 ts->error = td->error; 1260 strcpy(ts->verror, td->verror); 1261 } 1262 } 1263 1264 sum_thread_stats(ts, &td->ts, idx); 1265 } 1266 1267 for (i = 0; i < nr_ts; i++) { 1268 unsigned long long bw; 1269 1270 ts = &threadstats[i]; 1271 rs = &runstats[ts->groupid]; 1272 rs->kb_base = ts->kb_base; 1273 rs->unified_rw_rep += ts->unified_rw_rep; 1274 1275 for (j = 0; j < DDIR_RWDIR_CNT; j++) { 1276 if (!ts->runtime[j]) 1277 continue; 1278 if (ts->runtime[j] < rs->min_run[j] || !rs->min_run[j]) 1279 rs->min_run[j] = ts->runtime[j]; 1280 if (ts->runtime[j] > rs->max_run[j]) 1281 rs->max_run[j] = ts->runtime[j]; 1282 1283 bw = 0; 1284 if (ts->runtime[j]) { 1285 unsigned long runt = ts->runtime[j]; 1286 unsigned long long kb; 1287 1288 kb = ts->io_bytes[j] / rs->kb_base; 1289 bw = kb * 1000 / runt; 1290 } 1291 if (bw < rs->min_bw[j]) 1292 rs->min_bw[j] = bw; 1293 if (bw > rs->max_bw[j]) 1294 rs->max_bw[j] = bw; 1295 1296 rs->io_kb[j] += ts->io_bytes[j] / rs->kb_base; 1297 } 1298 } 1299 1300 for (i = 0; i < groupid + 1; i++) { 1301 int ddir; 1302 1303 rs = &runstats[i]; 1304 1305 for (ddir = 0; ddir < DDIR_RWDIR_CNT; ddir++) { 1306 if (rs->max_run[ddir]) 1307 rs->agg[ddir] = (rs->io_kb[ddir] * 1000) / 1308 rs->max_run[ddir]; 1309 } 1310 } 1311 1312 /* 1313 * don't overwrite last signal output 1314 */ 1315 if (output_format == FIO_OUTPUT_NORMAL) 1316 log_info("\n"); 1317 else if (output_format == FIO_OUTPUT_JSON) { 1318 root = json_create_object(); 1319 json_object_add_value_string(root, "fio version", fio_version_string); 1320 array = json_create_array(); 1321 json_object_add_value_array(root, "jobs", array); 1322 } 1323 1324 for (i = 0; i < nr_ts; i++) { 1325 ts = &threadstats[i]; 1326 rs = &runstats[ts->groupid]; 1327 1328 if (is_backend) 1329 fio_server_send_ts(ts, rs); 1330 else if (output_format == FIO_OUTPUT_TERSE) 1331 show_thread_status_terse(ts, rs); 1332 else if (output_format == FIO_OUTPUT_JSON) { 1333 struct json_object *tmp = show_thread_status_json(ts, rs); 1334 json_array_add_value_object(array, tmp); 1335 } else 1336 show_thread_status(ts, rs); 1337 } 1338 if (output_format == FIO_OUTPUT_JSON) { 1339 /* disk util stats, if any */ 1340 show_disk_util(1, root); 1341 1342 show_idle_prof_stats(FIO_OUTPUT_JSON, root); 1343 1344 json_print_object(root); 1345 log_info("\n"); 1346 json_free_object(root); 1347 } 1348 1349 for (i = 0; i < groupid + 1; i++) { 1350 rs = &runstats[i]; 1351 1352 rs->groupid = i; 1353 if (is_backend) 1354 fio_server_send_gs(rs); 1355 else if (output_format == FIO_OUTPUT_NORMAL) 1356 show_group_stats(rs); 1357 } 1358 1359 if (is_backend) 1360 fio_server_send_du(); 1361 else if (output_format == FIO_OUTPUT_NORMAL) { 1362 show_disk_util(0, NULL); 1363 show_idle_prof_stats(FIO_OUTPUT_NORMAL, NULL); 1364 } 1365 1366 free(runstats); 1367 free(threadstats); 1368} 1369 1370static void *__show_running_run_stats(void *arg) 1371{ 1372 struct thread_data *td; 1373 unsigned long long *rt; 1374 struct timeval tv; 1375 int i; 1376 1377 rt = malloc(thread_number * sizeof(unsigned long long)); 1378 fio_gettime(&tv, NULL); 1379 1380 for_each_td(td, i) { 1381 rt[i] = mtime_since(&td->start, &tv); 1382 if (td_read(td) && td->io_bytes[DDIR_READ]) 1383 td->ts.runtime[DDIR_READ] += rt[i]; 1384 if (td_write(td) && td->io_bytes[DDIR_WRITE]) 1385 td->ts.runtime[DDIR_WRITE] += rt[i]; 1386 if (td_trim(td) && td->io_bytes[DDIR_TRIM]) 1387 td->ts.runtime[DDIR_TRIM] += rt[i]; 1388 1389 td->update_rusage = 1; 1390 td->ts.io_bytes[DDIR_READ] = td->io_bytes[DDIR_READ]; 1391 td->ts.io_bytes[DDIR_WRITE] = td->io_bytes[DDIR_WRITE]; 1392 td->ts.io_bytes[DDIR_TRIM] = td->io_bytes[DDIR_TRIM]; 1393 td->ts.total_run_time = mtime_since(&td->epoch, &tv); 1394 } 1395 1396 for_each_td(td, i) { 1397 if (td->rusage_sem) { 1398 td->update_rusage = 1; 1399 fio_mutex_down(td->rusage_sem); 1400 } 1401 td->update_rusage = 0; 1402 } 1403 1404 show_run_stats(); 1405 1406 for_each_td(td, i) { 1407 if (td_read(td) && td->io_bytes[DDIR_READ]) 1408 td->ts.runtime[DDIR_READ] -= rt[i]; 1409 if (td_write(td) && td->io_bytes[DDIR_WRITE]) 1410 td->ts.runtime[DDIR_WRITE] -= rt[i]; 1411 if (td_trim(td) && td->io_bytes[DDIR_TRIM]) 1412 td->ts.runtime[DDIR_TRIM] -= rt[i]; 1413 } 1414 1415 free(rt); 1416 return NULL; 1417} 1418 1419/* 1420 * Called from signal handler. It _should_ be safe to just run this inline 1421 * in the sig handler, but we should be disturbing the system less by just 1422 * creating a thread to do it. 1423 */ 1424void show_running_run_stats(void) 1425{ 1426 pthread_t thread; 1427 1428 pthread_create(&thread, NULL, __show_running_run_stats, NULL); 1429 pthread_detach(thread); 1430} 1431 1432static inline void add_stat_sample(struct io_stat *is, unsigned long data) 1433{ 1434 double val = data; 1435 double delta; 1436 1437 if (data > is->max_val) 1438 is->max_val = data; 1439 if (data < is->min_val) 1440 is->min_val = data; 1441 1442 delta = val - is->mean.u.f; 1443 if (delta) { 1444 is->mean.u.f += delta / (is->samples + 1.0); 1445 is->S.u.f += delta * (val - is->mean.u.f); 1446 } 1447 1448 is->samples++; 1449} 1450 1451static void __add_log_sample(struct io_log *iolog, unsigned long val, 1452 enum fio_ddir ddir, unsigned int bs, 1453 unsigned long t) 1454{ 1455 const int nr_samples = iolog->nr_samples; 1456 1457 if (!iolog->nr_samples) 1458 iolog->avg_last = t; 1459 1460 if (iolog->nr_samples == iolog->max_samples) { 1461 int new_size = sizeof(struct io_sample) * iolog->max_samples*2; 1462 1463 iolog->log = realloc(iolog->log, new_size); 1464 iolog->max_samples <<= 1; 1465 } 1466 1467 iolog->log[nr_samples].val = val; 1468 iolog->log[nr_samples].time = t; 1469 iolog->log[nr_samples].ddir = ddir; 1470 iolog->log[nr_samples].bs = bs; 1471 iolog->nr_samples++; 1472} 1473 1474static inline void reset_io_stat(struct io_stat *ios) 1475{ 1476 ios->max_val = ios->min_val = ios->samples = 0; 1477 ios->mean.u.f = ios->S.u.f = 0; 1478} 1479 1480static void add_log_sample(struct thread_data *td, struct io_log *iolog, 1481 unsigned long val, enum fio_ddir ddir, 1482 unsigned int bs) 1483{ 1484 unsigned long elapsed, this_window; 1485 1486 if (!ddir_rw(ddir)) 1487 return; 1488 1489 elapsed = mtime_since_now(&td->epoch); 1490 1491 /* 1492 * If no time averaging, just add the log sample. 1493 */ 1494 if (!iolog->avg_msec) { 1495 __add_log_sample(iolog, val, ddir, bs, elapsed); 1496 return; 1497 } 1498 1499 /* 1500 * Add the sample. If the time period has passed, then 1501 * add that entry to the log and clear. 1502 */ 1503 add_stat_sample(&iolog->avg_window[ddir], val); 1504 1505 /* 1506 * If period hasn't passed, adding the above sample is all we 1507 * need to do. 1508 */ 1509 this_window = elapsed - iolog->avg_last; 1510 if (this_window < iolog->avg_msec) 1511 return; 1512 1513 /* 1514 * Note an entry in the log. Use the mean from the logged samples, 1515 * making sure to properly round up. Only write a log entry if we 1516 * had actual samples done. 1517 */ 1518 if (iolog->avg_window[DDIR_READ].samples) { 1519 unsigned long mr; 1520 1521 mr = iolog->avg_window[DDIR_READ].mean.u.f + 0.50; 1522 __add_log_sample(iolog, mr, DDIR_READ, 0, elapsed); 1523 } 1524 if (iolog->avg_window[DDIR_WRITE].samples) { 1525 unsigned long mw; 1526 1527 mw = iolog->avg_window[DDIR_WRITE].mean.u.f + 0.50; 1528 __add_log_sample(iolog, mw, DDIR_WRITE, 0, elapsed); 1529 } 1530 if (iolog->avg_window[DDIR_TRIM].samples) { 1531 unsigned long mw; 1532 1533 mw = iolog->avg_window[DDIR_TRIM].mean.u.f + 0.50; 1534 __add_log_sample(iolog, mw, DDIR_TRIM, 0, elapsed); 1535 } 1536 1537 1538 reset_io_stat(&iolog->avg_window[DDIR_READ]); 1539 reset_io_stat(&iolog->avg_window[DDIR_WRITE]); 1540 reset_io_stat(&iolog->avg_window[DDIR_TRIM]); 1541 iolog->avg_last = elapsed; 1542} 1543 1544void add_agg_sample(unsigned long val, enum fio_ddir ddir, unsigned int bs) 1545{ 1546 struct io_log *iolog; 1547 1548 if (!ddir_rw(ddir)) 1549 return; 1550 1551 iolog = agg_io_log[ddir]; 1552 __add_log_sample(iolog, val, ddir, bs, mtime_since_genesis()); 1553} 1554 1555static void add_clat_percentile_sample(struct thread_stat *ts, 1556 unsigned long usec, enum fio_ddir ddir) 1557{ 1558 unsigned int idx = plat_val_to_idx(usec); 1559 assert(idx < FIO_IO_U_PLAT_NR); 1560 1561 ts->io_u_plat[ddir][idx]++; 1562} 1563 1564void add_clat_sample(struct thread_data *td, enum fio_ddir ddir, 1565 unsigned long usec, unsigned int bs) 1566{ 1567 struct thread_stat *ts = &td->ts; 1568 1569 if (!ddir_rw(ddir)) 1570 return; 1571 1572 add_stat_sample(&ts->clat_stat[ddir], usec); 1573 1574 if (td->clat_log) 1575 add_log_sample(td, td->clat_log, usec, ddir, bs); 1576 1577 if (ts->clat_percentiles) 1578 add_clat_percentile_sample(ts, usec, ddir); 1579} 1580 1581void add_slat_sample(struct thread_data *td, enum fio_ddir ddir, 1582 unsigned long usec, unsigned int bs) 1583{ 1584 struct thread_stat *ts = &td->ts; 1585 1586 if (!ddir_rw(ddir)) 1587 return; 1588 1589 add_stat_sample(&ts->slat_stat[ddir], usec); 1590 1591 if (td->slat_log) 1592 add_log_sample(td, td->slat_log, usec, ddir, bs); 1593} 1594 1595void add_lat_sample(struct thread_data *td, enum fio_ddir ddir, 1596 unsigned long usec, unsigned int bs) 1597{ 1598 struct thread_stat *ts = &td->ts; 1599 1600 if (!ddir_rw(ddir)) 1601 return; 1602 1603 add_stat_sample(&ts->lat_stat[ddir], usec); 1604 1605 if (td->lat_log) 1606 add_log_sample(td, td->lat_log, usec, ddir, bs); 1607} 1608 1609void add_bw_sample(struct thread_data *td, enum fio_ddir ddir, unsigned int bs, 1610 struct timeval *t) 1611{ 1612 struct thread_stat *ts = &td->ts; 1613 unsigned long spent, rate; 1614 1615 if (!ddir_rw(ddir)) 1616 return; 1617 1618 spent = mtime_since(&td->bw_sample_time, t); 1619 if (spent < td->o.bw_avg_time) 1620 return; 1621 1622 /* 1623 * Compute both read and write rates for the interval. 1624 */ 1625 for (ddir = DDIR_READ; ddir < DDIR_RWDIR_CNT; ddir++) { 1626 uint64_t delta; 1627 1628 delta = td->this_io_bytes[ddir] - td->stat_io_bytes[ddir]; 1629 if (!delta) 1630 continue; /* No entries for interval */ 1631 1632 rate = delta * 1000 / spent / 1024; 1633 add_stat_sample(&ts->bw_stat[ddir], rate); 1634 1635 if (td->bw_log) 1636 add_log_sample(td, td->bw_log, rate, ddir, bs); 1637 1638 td->stat_io_bytes[ddir] = td->this_io_bytes[ddir]; 1639 } 1640 1641 fio_gettime(&td->bw_sample_time, NULL); 1642} 1643 1644void add_iops_sample(struct thread_data *td, enum fio_ddir ddir, 1645 struct timeval *t) 1646{ 1647 struct thread_stat *ts = &td->ts; 1648 unsigned long spent, iops; 1649 1650 if (!ddir_rw(ddir)) 1651 return; 1652 1653 spent = mtime_since(&td->iops_sample_time, t); 1654 if (spent < td->o.iops_avg_time) 1655 return; 1656 1657 /* 1658 * Compute both read and write rates for the interval. 1659 */ 1660 for (ddir = DDIR_READ; ddir < DDIR_RWDIR_CNT; ddir++) { 1661 uint64_t delta; 1662 1663 delta = td->this_io_blocks[ddir] - td->stat_io_blocks[ddir]; 1664 if (!delta) 1665 continue; /* No entries for interval */ 1666 1667 iops = (delta * 1000) / spent; 1668 add_stat_sample(&ts->iops_stat[ddir], iops); 1669 1670 if (td->iops_log) 1671 add_log_sample(td, td->iops_log, iops, ddir, 0); 1672 1673 td->stat_io_blocks[ddir] = td->this_io_blocks[ddir]; 1674 } 1675 1676 fio_gettime(&td->iops_sample_time, NULL); 1677} 1678