blkparse.c

   1 /*
   2  * block queue tracing parse application
   3  *
   4  * Copyright (C) 2005 Jens Axboe <axboe@suse.de>
   5  *
   6  *  This program is free software; you can redistribute it and/or modify
   7  *  it under the terms of the GNU General Public License as published by
   8  *  the Free Software Foundation; either version 2 of the License, or
   9  *  (at your option) any later version.
  10  *
  11  *  This program is distributed in the hope that it will be useful,
  12  *  but WITHOUT ANY WARRANTY; without even the implied warranty of
  13  *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  14  *  GNU General Public License for more details.
  15  *
  16  *  You should have received a copy of the GNU General Public License
  17  *  along with this program; if not, write to the Free Software
  18  *  Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
  19  *
  20  */
  21 #include <sys/types.h>
  22 #include <sys/stat.h>
  23 #include <unistd.h>
  24 #include <stdio.h>
  25 #include <fcntl.h>
  26 #include <stdlib.h>
  27 #include <string.h>
  28 #include <getopt.h>
  29 #include <errno.h>
  30 #include <signal.h>
  31 #include <locale.h>
  32
  33 #include "blktrace.h"
  34 #include "rbtree.h"
  35
  36 #define SECONDS(x)              ((unsigned long long)(x) / 1000000000)
  37 #define NANO_SECONDS(x)         ((unsigned long long)(x) % 1000000000)
  38
  39 #define MINORBITS       20
  40 #define MINORMASK       ((1U << MINORBITS) - 1)
  41 #define MAJOR(dev)      ((unsigned int) ((dev) >> MINORBITS))
  42 #define MINOR(dev)      ((unsigned int) ((dev) & MINORMASK))
  43
  44 #define min(a, b)       ((a) < (b) ? (a) : (b))
  45
  46 struct io_stats {
  47         unsigned long qreads, qwrites, creads, cwrites, mreads, mwrites;
  48         unsigned long ireads, iwrites;
  49         unsigned long long qread_kb, qwrite_kb, cread_kb, cwrite_kb;
  50         unsigned long long iread_kb, iwrite_kb;
  51 };
  52
  53 struct per_cpu_info {
  54         int cpu;
  55         int nelems;
  56
  57         int fd;
  58         char fname[128];
  59
  60         struct io_stats io_stats;
  61 };
  62
  63 struct per_dev_info {
  64         dev_t id;
  65         char *name;
  66
  67         int backwards;
  68         unsigned long long events;
  69         unsigned long long last_reported_time;
  70         struct io_stats io_stats;
  71
  72         int ncpus;
  73         struct per_cpu_info *cpus;
  74 };
  75
  76 struct per_process_info {
  77         char name[16];
  78         __u32 pid;
  79         struct io_stats io_stats;
  80         struct per_process_info *hash_next, *list_next;
  81
  82         /*
  83          * individual io stats
  84          */
  85         unsigned long long longest_allocation_wait[2];
  86         unsigned long long longest_dispatch_wait[2];
  87         unsigned long long longest_completion_wait[2];
  88 };
  89
  90 #define PPI_HASH_SHIFT  (8)
  91 static struct per_process_info *ppi_hash[1 << PPI_HASH_SHIFT];
  92 static struct per_process_info *ppi_list;
  93
  94 #define S_OPTS  "i:o:b:stq"
  95 static struct option l_opts[] = {
  96         {
  97                 .name = "input",
  98                 .has_arg = 1,
  99                 .flag = NULL,
 100                 .val = 'i'
 101         },
 102         {
 103                 .name = "output",
 104                 .has_arg = 1,
 105                 .flag = NULL,
 106                 .val = 'o'
 107         },
 108         {
 109                 .name = "batch",
 110                 .has_arg = 1,
 111                 .flag = NULL,
 112                 .val = 'b'
 113         },
 114         {
 115                 .name = "per program stats",
 116                 .has_arg = 0,
 117                 .flag = NULL,
 118                 .val = 's'
 119         },
 120         {
 121                 .name = "track ios",
 122                 .has_arg = 0,
 123                 .flag = NULL,
 124                 .val = 't'
 125         },
 126         {
 127                 .name = "quiet",
 128                 .has_arg = 0,
 129                 .flag = NULL,
 130                 .val = 'q'
 131         },
 132         {
 133                 .name = NULL,
 134                 .has_arg = 0,
 135                 .flag = NULL,
 136                 .val = 0
 137         }
 138 };
 139
 140 static struct rb_root rb_sort_root;
 141 static struct rb_root rb_track_root;
 142
 143 /*
 144  * for sorting the displayed output
 145  */
 146 struct trace {
 147         struct blk_io_trace *bit;
 148         struct rb_node rb_node;
 149 };
 150
 151 /*
 152  * for tracking individual ios
 153  */
 154 struct io_track {
 155         struct rb_node rb_node;
 156
 157         dev_t device;
 158         __u64 sector;
 159         __u32 pid;
 160         unsigned long long allocation_time;
 161         unsigned long long queue_time;
 162         unsigned long long dispatch_time;
 163         unsigned long long completion_time;
 164 };
 165
 166 static int ndevices;
 167 static struct per_dev_info *devices;
 168 static char *get_dev_name(struct per_dev_info *, char *, int);
 169
 170 static FILE *ofp;
 171 static char *output_name;
 172
 173 static unsigned long long genesis_time;
 174
 175 static int per_process_stats;
 176 static int track_ios;
 177
 178 #define RB_BATCH_DEFAULT        (1024)
 179 static int rb_batch = RB_BATCH_DEFAULT;
 180
 181 static int pipeline;
 182
 183 #define is_done()       (*(volatile int *)(&done))
 184 static volatile int done;
 185
 186 static inline unsigned long hash_long(unsigned long val)
 187 {
 188 #if __WORDSIZE == 32
 189         val *= 0x9e370001UL;
 190 #elif __WORDSIZE == 64
 191         val *= 0x9e37fffffffc0001UL;
 192 #else
 193 #error unknown word size
 194 #endif
 195
 196         return val >> (__WORDSIZE - PPI_HASH_SHIFT);
 197 }
 198
 199 static inline void add_process_to_hash(struct per_process_info *ppi)
 200 {
 201         const int hash_idx = hash_long(ppi->pid);
 202
 203         ppi->hash_next = ppi_hash[hash_idx];
 204         ppi_hash[hash_idx] = ppi;
 205 }
 206
 207 static inline void add_process_to_list(struct per_process_info *ppi)
 208 {
 209         ppi->list_next = ppi_list;
 210         ppi_list = ppi;
 211 }
 212
 213 static struct per_process_info *find_process_by_pid(__u32 pid)
 214 {
 215         const int hash_idx = hash_long(pid);
 216         struct per_process_info *ppi;
 217
 218         ppi = ppi_hash[hash_idx];
 219         while (ppi) {
 220                 if (ppi->pid == pid)
 221                         return ppi;
 222
 223                 ppi = ppi->hash_next;
 224         }
 225
 226         return NULL;
 227 }
 228
 229 static inline int trace_rb_insert(struct trace *t)
 230 {
 231         struct rb_node **p = &rb_sort_root.rb_node;
 232         struct rb_node *parent = NULL;
 233         struct trace *__t;
 234
 235         if (genesis_time == 0 || t->bit->time < genesis_time)
 236                 genesis_time = t->bit->time;
 237
 238         while (*p) {
 239                 parent = *p;
 240                 __t = rb_entry(parent, struct trace, rb_node);
 241
 242                 if (t->bit->time < __t->bit->time)
 243                         p = &(*p)->rb_left;
 244                 else if (t->bit->time > __t->bit->time)
 245                         p = &(*p)->rb_right;
 246                 else if (t->bit->device < __t->bit->device)
 247                         p = &(*p)->rb_left;
 248                 else if (t->bit->device > __t->bit->device)
 249                         p = &(*p)->rb_right;
 250                 else if (t->bit->sequence < __t->bit->sequence)
 251                         p = &(*p)->rb_left;
 252                 else if (t->bit->sequence > __t->bit->sequence)
 253                         p = &(*p)->rb_right;
 254                 else if (t->bit->device == __t->bit->device) {
 255                         fprintf(stderr,
 256                                 "sequence alias (%d) on device %d,%d!\n",
 257                                 t->bit->sequence,
 258                                 MAJOR(t->bit->device), MINOR(t->bit->device));
 259                         return 1;
 260                 }
 261         }
 262
 263         rb_link_node(&t->rb_node, parent, p);
 264         rb_insert_color(&t->rb_node, &rb_sort_root);
 265         return 0;
 266 }
 267
 268 static inline int track_rb_insert(struct io_track *iot)
 269 {
 270         struct rb_node **p = &rb_track_root.rb_node;
 271         struct rb_node *parent = NULL;
 272         struct io_track *__iot;
 273
 274         while (*p) {
 275                 parent = *p;
 276
 277                 __iot = rb_entry(parent, struct io_track, rb_node);
 278
 279                 if (iot->device < __iot->device)
 280                         p = &(*p)->rb_left;
 281                 else if (iot->device > __iot->device)
 282                         p = &(*p)->rb_right;
 283                 else if (iot->sector < __iot->sector)
 284                         p = &(*p)->rb_left;
 285                 else if (iot->sector > __iot->sector)
 286                         p = &(*p)->rb_right;
 287                 else {
 288                         fprintf(stderr,
 289                                 "sector alias (%llu) on device %d,%d!\n",
 290                                 iot->sector,
 291                                 MAJOR(iot->device), MINOR(iot->device));
 292                         return 1;
 293                 }
 294         }
 295
 296         rb_link_node(&iot->rb_node, parent, p);
 297         rb_insert_color(&iot->rb_node, &rb_track_root);
 298         return 0;
 299 }
 300
 301 static struct io_track *__find_track(dev_t device, __u64 sector)
 302 {
 303         struct rb_node **p = &rb_track_root.rb_node;
 304         struct rb_node *parent = NULL;
 305         struct io_track *__iot;
 306
 307         while (*p) {
 308                 parent = *p;
 309
 310                 __iot = rb_entry(parent, struct io_track, rb_node);
 311
 312                 if (device < __iot->device)
 313                         p = &(*p)->rb_left;
 314                 else if (device > __iot->device)
 315                         p = &(*p)->rb_right;
 316                 else if (sector < __iot->sector)
 317                         p = &(*p)->rb_left;
 318                 else if (sector > __iot->sector)
 319                         p = &(*p)->rb_right;
 320                 else
 321                         return __iot;
 322         }
 323
 324         return NULL;
 325 }
 326
 327 static struct io_track *find_track(__u32 pid, dev_t device, __u64 sector)
 328 {
 329         struct io_track *iot;
 330
 331         iot = __find_track(device, sector);
 332         if (!iot) {
 333                 iot = malloc(sizeof(*iot));
 334                 iot->pid = pid;
 335                 iot->device = device;
 336                 iot->sector = sector;
 337                 track_rb_insert(iot);
 338         }
 339
 340         return iot;
 341 }
 342
 343 static void log_track_merge(struct blk_io_trace *t)
 344 {
 345         struct io_track *iot;
 346
 347         if (!track_ios)
 348                 return;
 349         if ((t->action & BLK_TC_ACT(BLK_TC_FS)) == 0)
 350                 return;
 351
 352         iot = __find_track(t->device, t->sector - (t->bytes >> 10));
 353         if (!iot) {
 354                 fprintf(stderr, "Trying to merge on non-existing request\n");
 355                 return;
 356         }
 357
 358         rb_erase(&iot->rb_node, &rb_track_root);
 359         iot->sector -= t->bytes >> 10;
 360         track_rb_insert(iot);
 361 }
 362
 363 static void log_track_getrq(struct blk_io_trace *t)
 364 {
 365         struct io_track *iot;
 366
 367         if (!track_ios)
 368                 return;
 369
 370         iot = find_track(t->pid, t->device, t->sector);
 371         iot->allocation_time = t->time;
 372 }
 373
 374
 375 /*
 376  * return time between rq allocation and queue
 377  */
 378 static unsigned long long log_track_queue(struct blk_io_trace *t)
 379 {
 380         unsigned long long elapsed;
 381         struct io_track *iot;
 382
 383         if (!track_ios)
 384                 return -1;
 385
 386         iot = find_track(t->pid, t->device, t->sector);
 387         iot->queue_time = t->time;
 388         elapsed = iot->queue_time - iot->allocation_time;
 389
 390         if (per_process_stats) {
 391                 struct per_process_info *ppi = find_process_by_pid(iot->pid);
 392                 int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0;
 393
 394                 if (ppi && elapsed > ppi->longest_allocation_wait[w])
 395                         ppi->longest_allocation_wait[w] = elapsed;
 396         }
 397
 398         return elapsed;
 399 }
 400
 401 /*
 402  * return time between queue and issue
 403  */
 404 static unsigned long long log_track_issue(struct blk_io_trace *t)
 405 {
 406         unsigned long long elapsed;
 407         struct io_track *iot;
 408
 409         if (!track_ios)
 410                 return -1;
 411         if ((t->action & BLK_TC_ACT(BLK_TC_FS)) == 0)
 412                 return -1;
 413
 414         iot = __find_track(t->device, t->sector);
 415         if (!iot) {
 416                 fprintf(stderr, "Trying to issue on non-existing request\n");
 417                 return -1;
 418         }
 419
 420         iot->dispatch_time = t->time;
 421         elapsed = iot->dispatch_time - iot->queue_time;
 422
 423         if (per_process_stats) {
 424                 struct per_process_info *ppi = find_process_by_pid(iot->pid);
 425                 int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0;
 426
 427                 if (ppi && elapsed > ppi->longest_dispatch_wait[w])
 428                         ppi->longest_dispatch_wait[w] = elapsed;
 429         }
 430
 431         return elapsed;
 432 }
 433
 434 /*
 435  * return time between dispatch and complete
 436  */
 437 static unsigned long long log_track_complete(struct blk_io_trace *t)
 438 {
 439         unsigned long long elapsed;
 440         struct io_track *iot;
 441
 442         if (!track_ios)
 443                 return -1;
 444         if ((t->action & BLK_TC_ACT(BLK_TC_FS)) == 0)
 445                 return -1;
 446
 447         iot = __find_track(t->device, t->sector);
 448         if (!iot) {
 449                 fprintf(stderr, "Trying to dispatch on non-existing request\n");
 450                 return -1;
 451         }
 452
 453         iot->completion_time = t->time;
 454         elapsed = iot->completion_time - iot->dispatch_time;
 455
 456         if (per_process_stats) {
 457                 struct per_process_info *ppi = find_process_by_pid(iot->pid);
 458                 int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0;
 459
 460                 if (ppi && elapsed > ppi->longest_completion_wait[w])
 461                         ppi->longest_completion_wait[w] = elapsed;
 462         }
 463
 464         /*
 465          * kill the trace, we don't need it after completion
 466          */
 467         rb_erase(&iot->rb_node, &rb_track_root);
 468         free(iot);
 469
 470         return elapsed;
 471 }
 472
 473
 474 static struct io_stats *find_process_io_stats(__u32 pid, char *name)
 475 {
 476         struct per_process_info *ppi = find_process_by_pid(pid);
 477
 478         if (!ppi) {
 479                 ppi = malloc(sizeof(*ppi));
 480                 memset(ppi, 0, sizeof(*ppi));
 481                 strncpy(ppi->name, name, sizeof(ppi->name));
 482                 ppi->pid = pid;
 483                 add_process_to_hash(ppi);
 484                 add_process_to_list(ppi);
 485         }
 486
 487         return &ppi->io_stats;
 488 }
 489
 490
 491 static void resize_cpu_info(struct per_dev_info *pdi, int cpu)
 492 {
 493         struct per_cpu_info *cpus = pdi->cpus;
 494         int ncpus = pdi->ncpus;
 495         int new_count = cpu + 1;
 496         int new_space, size;
 497         char *new_start;
 498
 499         size = new_count * sizeof(struct per_cpu_info);
 500         cpus = realloc(cpus, size);
 501         if (!cpus) {
 502                 char name[20];
 503                 fprintf(stderr, "Out of memory, CPU info for device %s (%d)\n",
 504                         get_dev_name(pdi, name, sizeof(name)), size);
 505                 exit(1);
 506         }
 507
 508         new_start = (char *)cpus + (ncpus * sizeof(struct per_cpu_info));
 509         new_space = (new_count - ncpus) * sizeof(struct per_cpu_info);
 510         memset(new_start, 0, new_space);
 511
 512         pdi->ncpus = new_count;
 513         pdi->cpus = cpus;
 514 }
 515
 516 static struct per_cpu_info *get_cpu_info(struct per_dev_info *pdi, int cpu)
 517 {
 518         if (cpu >= pdi->ncpus)
 519                 resize_cpu_info(pdi, cpu);
 520         return &pdi->cpus[cpu];
 521 }
 522
 523
 524 static int resize_devices(char *name)
 525 {
 526         int size = (ndevices + 1) * sizeof(struct per_dev_info);
 527
 528         devices = realloc(devices, size);
 529         if (!devices) {
 530                 fprintf(stderr, "Out of memory, device %s (%d)\n", name, size);
 531                 return 1;
 532         }
 533         memset(&devices[ndevices], 0, sizeof(struct per_dev_info));
 534         devices[ndevices].name = name;
 535         ndevices++;
 536         return 0;
 537 }
 538
 539 static struct per_dev_info *get_dev_info(dev_t id, int create)
 540 {
 541         int i;
 542
 543         for (i = 0; i < ndevices; i++)
 544                 if (devices[i].id == id)
 545                         return &devices[i];
 546         if (!create)
 547                 return NULL;
 548         if (resize_devices(NULL) != 0)
 549                 return NULL;
 550         return &devices[ndevices-1];
 551 }
 552
 553 static char *get_dev_name(struct per_dev_info *pdi, char *buffer, int size)
 554 {
 555         if (pdi->name)
 556                 snprintf(buffer, size, "%s", pdi->name);
 557         else
 558                 snprintf(buffer, size, "%d,%d", MAJOR(pdi->id), MINOR(pdi->id));
 559         return buffer;
 560 }
 561
 562
 563 static void check_time(struct per_dev_info *pdi, struct blk_io_trace *bit)
 564 {
 565         unsigned long long this = bit->time;
 566         unsigned long long last = pdi->last_reported_time;
 567
 568         pdi->backwards = (this < last) ? 'B' : ' ';
 569         pdi->last_reported_time = this;
 570 }
 571
 572
 573 static inline void __account_m(struct io_stats *ios, struct blk_io_trace *t,
 574                                int rw)
 575 {
 576         if (rw) {
 577                 ios->mwrites++;
 578                 ios->qwrite_kb += t->bytes >> 10;
 579         } else {
 580                 ios->mreads++;
 581                 ios->qread_kb += t->bytes >> 10;
 582         }
 583 }
 584
 585 static inline void account_m(struct blk_io_trace *t, struct per_cpu_info *pci,
 586                              int rw)
 587 {
 588         __account_m(&pci->io_stats, t, rw);
 589
 590         if (per_process_stats) {
 591                 struct io_stats *ios = find_process_io_stats(t->pid, t->comm);
 592
 593                 __account_m(ios, t, rw);
 594         }
 595 }
 596
 597 static inline void __account_q(struct io_stats *ios, struct blk_io_trace *t,
 598                                int rw)
 599 {
 600         if (rw) {
 601                 ios->qwrites++;
 602                 ios->qwrite_kb += t->bytes >> 10;
 603         } else {
 604                 ios->qreads++;
 605                 ios->qread_kb += t->bytes >> 10;
 606         }
 607 }
 608
 609 static inline void account_q(struct blk_io_trace *t, struct per_cpu_info *pci,
 610                              int rw)
 611 {
 612         __account_q(&pci->io_stats, t, rw);
 613
 614         if (per_process_stats) {
 615                 struct io_stats *ios = find_process_io_stats(t->pid, t->comm);
 616
 617                 __account_q(ios, t, rw);
 618         }
 619 }
 620
 621 static inline void __account_c(struct io_stats *ios, int rw, unsigned int bytes)
 622 {
 623         if (rw) {
 624                 ios->cwrites++;
 625                 ios->cwrite_kb += bytes >> 10;
 626         } else {
 627                 ios->creads++;
 628                 ios->cread_kb += bytes >> 10;
 629         }
 630 }
 631
 632 static inline void account_c(struct blk_io_trace *t, struct per_cpu_info *pci,
 633                              int rw, int bytes)
 634 {
 635         __account_c(&pci->io_stats, rw, bytes);
 636
 637         if (per_process_stats) {
 638                 struct io_stats *ios = find_process_io_stats(t->pid, t->comm);
 639
 640                 __account_c(ios, rw, bytes);
 641         }
 642 }
 643
 644 static inline void __account_i(struct io_stats *ios, int rw, unsigned int bytes)
 645 {
 646         if (rw) {
 647                 ios->iwrites++;
 648                 ios->iwrite_kb += bytes >> 10;
 649         } else {
 650                 ios->ireads++;
 651                 ios->iread_kb += bytes >> 10;
 652         }
 653 }
 654
 655 static inline void account_i(struct blk_io_trace *t, struct per_cpu_info *pci,
 656                              int rw)
 657 {
 658         __account_i(&pci->io_stats, rw, t->bytes);
 659
 660         if (per_process_stats) {
 661                 struct io_stats *ios = find_process_io_stats(t->pid, t->comm);
 662
 663                 __account_i(ios, rw, t->bytes);
 664         }
 665 }
 666
 667 static void output(struct per_cpu_info *pci, char *s)
 668 {
 669         fprintf(ofp, "%s", s);
 670 }
 671
 672 static char hstring[256];
 673 static char tstring[256];
 674
 675 static inline char *setup_header(struct per_cpu_info *pci,
 676                                  struct blk_io_trace *t, char act)
 677 {
 678         int w = t->action & BLK_TC_ACT(BLK_TC_WRITE);
 679         int b = t->action & BLK_TC_ACT(BLK_TC_BARRIER);
 680         int s = t->action & BLK_TC_ACT(BLK_TC_SYNC);
 681         char rwbs[4];
 682         int i = 0;
 683
 684         if (w)
 685                 rwbs[i++] = 'W';
 686         else
 687                 rwbs[i++] = 'R';
 688         if (b)
 689                 rwbs[i++] = 'B';
 690         if (s)
 691                 rwbs[i++] = 'S';
 692
 693         rwbs[i] = '\0';
 694
 695         sprintf(hstring, "%3d,%-3d %2d %8ld %5Lu.%09Lu %5u %c %3s",
 696                 MAJOR(t->device), MINOR(t->device), pci->cpu,
 697                 (unsigned long)t->sequence, SECONDS(t->time),
 698                 NANO_SECONDS(t->time), t->pid, act, rwbs);
 699
 700         return hstring;
 701 }
 702
 703 static void log_complete(struct per_cpu_info *pci, struct blk_io_trace *t,
 704                          char act)
 705 {
 706         unsigned long long elapsed = log_track_complete(t);
 707
 708         if (elapsed != -1ULL) {
 709                 unsigned long usec = elapsed / 1000;
 710
 711                 sprintf(tstring,"%s %Lu + %u (%8lu) [%d]\n",
 712                         setup_header(pci, t, act),
 713                         (unsigned long long)t->sector, t->bytes >> 9,
 714                         usec, t->error);
 715         } else {
 716                 sprintf(tstring,"%s %Lu + %u [%d]\n", setup_header(pci, t, act),
 717                         (unsigned long long)t->sector, t->bytes >> 9, t->error);
 718         }
 719
 720         output(pci, tstring);
 721 }
 722
 723 static void log_queue(struct per_cpu_info *pci, struct blk_io_trace *t,
 724                       char act)
 725 {
 726         unsigned long long elapsed = log_track_queue(t);
 727
 728         if (elapsed != -1ULL) {
 729                 unsigned long usec = elapsed / 1000;
 730
 731                 sprintf(tstring,"%s %Lu + %u (%8lu) [%s]\n",
 732                         setup_header(pci, t, act),
 733                         (unsigned long long)t->sector, t->bytes >> 9,
 734                         usec, t->comm);
 735         } else {
 736                 sprintf(tstring,"%s %Lu + %u [%s]\n", setup_header(pci, t, act),
 737                         (unsigned long long)t->sector, t->bytes >> 9, t->comm);
 738         }
 739         output(pci, tstring);
 740 }
 741
 742 static void log_issue(struct per_cpu_info *pci, struct blk_io_trace *t,
 743                       char act)
 744 {
 745         unsigned long long elapsed = log_track_issue(t);
 746
 747         if (elapsed != -1ULL) {
 748                 double usec = (double) elapsed / 1000;
 749
 750                 sprintf(tstring,"%s %Lu + %u (%8.2f) [%s]\n",
 751                         setup_header(pci, t, act),
 752                         (unsigned long long)t->sector, t->bytes >> 9,
 753                         usec, t->comm);
 754         } else {
 755                 sprintf(tstring,"%s %Lu + %u [%s]\n", setup_header(pci, t, act),
 756                         (unsigned long long)t->sector, t->bytes >> 9, t->comm);
 757         }
 758
 759         output(pci, tstring);
 760 }
 761
 762 static void log_merge(struct per_cpu_info *pci, struct blk_io_trace *t,
 763                       char act)
 764 {
 765         log_track_merge(t);
 766
 767         sprintf(tstring,"%s %Lu + %u [%s]\n", setup_header(pci, t, act),
 768                 (unsigned long long)t->sector, t->bytes >> 9, t->comm);
 769         output(pci, tstring);
 770 }
 771
 772 static void log_generic(struct per_cpu_info *pci, struct blk_io_trace *t,
 773                         char act)
 774 {
 775         sprintf(tstring,"%s %Lu + %u [%s]\n", setup_header(pci, t, act),
 776                 (unsigned long long)t->sector, t->bytes >> 9, t->comm);
 777         output(pci, tstring);
 778 }
 779
 780 static int log_pc(struct per_cpu_info *pci, struct blk_io_trace *t, char act)
 781 {
 782         unsigned char *buf;
 783         int i;
 784
 785         sprintf(tstring,"%s ", setup_header(pci, t, act));
 786         output(pci, tstring);
 787
 788         buf = (unsigned char *) t + sizeof(*t);
 789         for (i = 0; i < t->pdu_len; i++) {
 790                 sprintf(tstring,"%02x ", buf[i]);
 791                 output(pci, tstring);
 792         }
 793
 794         if (act == 'C') {
 795                 sprintf(tstring,"[%d]\n", t->error);
 796                 output(pci, tstring);
 797         } else {
 798                 sprintf(tstring,"[%s]\n", t->comm);
 799                 output(pci, tstring);
 800         }
 801         return 0;
 802 }
 803
 804 static int dump_trace_pc(struct blk_io_trace *t, struct per_cpu_info *pci)
 805 {
 806         int ret = 0;
 807
 808         switch (t->action & 0xffff) {
 809                 case __BLK_TA_QUEUE:
 810                         log_generic(pci, t, 'Q');
 811                         break;
 812                 case __BLK_TA_GETRQ:
 813                         log_generic(pci, t, 'G');
 814                         break;
 815                 case __BLK_TA_SLEEPRQ:
 816                         log_generic(pci, t, 'S');
 817                         break;
 818                 case __BLK_TA_REQUEUE:
 819                         log_generic(pci, t, 'R');
 820                         break;
 821                 case __BLK_TA_ISSUE:
 822                         ret = log_pc(pci, t, 'D');
 823                         break;
 824                 case __BLK_TA_COMPLETE:
 825                         log_pc(pci, t, 'C');
 826                         break;
 827                 default:
 828                         fprintf(stderr, "Bad pc action %x\n", t->action);
 829                         ret = 1;
 830                         break;
 831         }
 832
 833         return ret;
 834 }
 835
 836 static void dump_trace_fs(struct blk_io_trace *t, struct per_cpu_info *pci)
 837 {
 838         int w = t->action & BLK_TC_ACT(BLK_TC_WRITE);
 839         int act = t->action & 0xffff;
 840
 841         switch (act) {
 842                 case __BLK_TA_QUEUE:
 843                         account_q(t, pci, w);
 844                         log_queue(pci, t, 'Q');
 845                         break;
 846                 case __BLK_TA_BACKMERGE:
 847                         account_m(t, pci, w);
 848                         log_merge(pci, t, 'M');
 849                         break;
 850                 case __BLK_TA_FRONTMERGE:
 851                         account_m(t, pci, w);
 852                         log_merge(pci, t, 'F');
 853                         break;
 854                 case __BLK_TA_GETRQ:
 855                         log_track_getrq(t);
 856                         log_generic(pci, t, 'G');
 857                         break;
 858                 case __BLK_TA_SLEEPRQ:
 859                         log_generic(pci, t, 'S');
 860                         break;
 861                 case __BLK_TA_REQUEUE:
 862                         account_c(t, pci, w, -t->bytes);
 863                         log_queue(pci, t, 'R');
 864                         break;
 865                 case __BLK_TA_ISSUE:
 866                         account_i(t, pci, w);
 867                         log_issue(pci, t, 'D');
 868                         break;
 869                 case __BLK_TA_COMPLETE:
 870                         account_c(t, pci, w, t->bytes);
 871                         log_complete(pci, t, 'C');
 872                         break;
 873                 default:
 874                         fprintf(stderr, "Bad fs action %x\n", t->action);
 875                         break;
 876         }
 877 }
 878
 879 static int dump_trace(struct blk_io_trace *t, struct per_cpu_info *pci,
 880                         struct per_dev_info *pdi)
 881 {
 882         int ret = 0;
 883
 884         if (t->action & BLK_TC_ACT(BLK_TC_PC))
 885                 ret = dump_trace_pc(t, pci);
 886         else
 887                 dump_trace_fs(t, pci);
 888
 889         pdi->events++;
 890         return ret;
 891 }
 892
 893 static void dump_io_stats(struct io_stats *ios, char *msg)
 894 {
 895         fprintf(ofp, "%s\n", msg);
 896
 897         fprintf(ofp, " Reads Queued:    %'8lu, %'8LuKiB\t", ios->qreads, ios->qread_kb);
 898         fprintf(ofp, " Writes Queued:    %'8lu, %'8LuKiB\n", ios->qwrites,ios->qwrite_kb);
 899
 900         fprintf(ofp, " Read Dispatches: %'8lu, %'8LuKiB\t", ios->ireads, ios->iread_kb);
 901         fprintf(ofp, " Write Dispatches: %'8lu, %'8LuKiB\n", ios->iwrites,ios->iwrite_kb);
 902         fprintf(ofp, " Reads Completed: %'8lu, %'8LuKiB\t", ios->creads, ios->cread_kb);
 903         fprintf(ofp, " Writes Completed: %'8lu, %'8LuKiB\n", ios->cwrites,ios->cwrite_kb);
 904         fprintf(ofp, " Read Merges:     %'8lu%8c\t", ios->mreads, ' ');
 905
 906         fprintf(ofp, " Write Merges:     %'8lu\n", ios->mwrites);
 907 }
 908
 909 static void dump_wait_stats(struct per_process_info *ppi)
 910 {
 911         unsigned long rawait = ppi->longest_allocation_wait[0] / 1000;
 912         unsigned long rdwait = ppi->longest_dispatch_wait[0] / 1000;
 913         unsigned long rcwait = ppi->longest_completion_wait[0] / 1000;
 914         unsigned long wawait = ppi->longest_allocation_wait[1] / 1000;
 915         unsigned long wdwait = ppi->longest_dispatch_wait[1] / 1000;
 916         unsigned long wcwait = ppi->longest_completion_wait[1] / 1000;
 917
 918         fprintf(ofp, " Allocation wait: %'8lu%8c\t", rawait, ' ');
 919         fprintf(ofp, " Allocation wait:  %'8lu\n", wawait);
 920         fprintf(ofp, " Dispatch wait:   %'8lu%8c\t", rdwait, ' ');
 921         fprintf(ofp, " Dispatch wait:    %'8lu\n", wdwait);
 922         fprintf(ofp, " Completion wait: %'8lu%8c\t", rcwait, ' ');
 923         fprintf(ofp, " Completion wait:  %'8lu\n", wcwait);
 924 }
 925
 926 static void show_process_stats(void)
 927 {
 928         struct per_process_info *ppi;
 929
 930         ppi = ppi_list;
 931         while (ppi) {
 932                 dump_io_stats(&ppi->io_stats, ppi->name);
 933                 dump_wait_stats(ppi);
 934                 ppi = ppi->list_next;
 935         }
 936
 937         fprintf(ofp, "\n");
 938 }
 939
 940 static void show_device_and_cpu_stats(void)
 941 {
 942         struct per_dev_info *pdi;
 943         struct per_cpu_info *pci;
 944         struct io_stats total, *ios;
 945         int i, j, pci_events;
 946         char line[3 + 8/*cpu*/ + 2 + 32/*dev*/ + 3];
 947         char name[32];
 948
 949         for (pdi = devices, i = 0; i < ndevices; i++, pdi++) {
 950
 951                 memset(&total, 0, sizeof(total));
 952                 pci_events = 0;
 953
 954                 if (i > 0)
 955                         fprintf(ofp, "\n");
 956
 957                 for (pci = pdi->cpus, j = 0; j < pdi->ncpus; j++, pci++) {
 958                         if (!pci->nelems)
 959                                 continue;
 960
 961                         ios = &pci->io_stats;
 962                         total.qreads += ios->qreads;
 963                         total.qwrites += ios->qwrites;
 964                         total.creads += ios->creads;
 965                         total.cwrites += ios->cwrites;
 966                         total.mreads += ios->mreads;
 967                         total.mwrites += ios->mwrites;
 968                         total.ireads += ios->ireads;
 969                         total.iwrites += ios->iwrites;
 970                         total.qread_kb += ios->qread_kb;
 971                         total.qwrite_kb += ios->qwrite_kb;
 972                         total.cread_kb += ios->cread_kb;
 973                         total.cwrite_kb += ios->cwrite_kb;
 974                         total.iread_kb += ios->iread_kb;
 975                         total.iwrite_kb += ios->iwrite_kb;
 976
 977                         snprintf(line, sizeof(line) - 1, "CPU%d (%s):",
 978                                  j, get_dev_name(pdi, name, sizeof(name)));
 979                         dump_io_stats(ios, line);
 980                         pci_events++;
 981                 }
 982
 983                 if (pci_events > 1) {
 984                         fprintf(ofp, "\n");
 985                         snprintf(line, sizeof(line) - 1, "Total (%s):",
 986                                  get_dev_name(pdi, name, sizeof(name)));
 987                         dump_io_stats(&total, line);
 988                 }
 989
 990                 fprintf(ofp, "Events (%s): %'Lu\n",
 991                         get_dev_name(pdi, line, sizeof(line)), pdi->events);
 992         }
 993 }
 994
 995 static struct blk_io_trace *find_trace(void *p, unsigned long offset, int nr)
 996 {
 997         unsigned long max_offset = min(offset,nr * sizeof(struct blk_io_trace));
 998         unsigned long off;
 999         struct blk_io_trace *bit;
1000         __u32 magic;
1001
1002         for (off = 0; off < max_offset; off++) {
1003                 bit = p + off;
1004
1005                 magic = be32_to_cpu(bit->magic);
1006                 if ((magic & 0xffffff00) == BLK_IO_TRACE_MAGIC)
1007                         return bit;
1008         }
1009
1010         return NULL;
1011 }
1012
1013 static int sort_entries(void *traces, unsigned long offset, int nr,
1014                         struct per_dev_info *fpdi, struct per_cpu_info *fpci)
1015 {
1016         struct per_dev_info *pdi;
1017         struct per_cpu_info *pci;
1018         struct blk_io_trace *bit;
1019         struct trace *t;
1020         void *start = traces;
1021
1022         while (traces - start <= offset - sizeof(*bit)) {
1023                 if (!nr)
1024                         break;
1025
1026                 bit = find_trace(traces, offset - (traces - start), nr);
1027                 if (!bit)
1028                         break;
1029
1030                 t = malloc(sizeof(*t));
1031                 if (!t) {
1032                         fprintf(stderr, "Out of memory, seq %d on dev %d,%d\n",
1033                                 bit->sequence,
1034                                 MAJOR(bit->device), MINOR(bit->device));
1035                         return -1;
1036                 }
1037                 t->bit = bit;
1038                 memset(&t->rb_node, 0, sizeof(t->rb_node));
1039
1040                 trace_to_cpu(bit);
1041
1042                 if (verify_trace(bit)) {
1043                         free(t);
1044                         break;
1045                 }
1046
1047                 pdi = fpdi ? fpdi : get_dev_info(bit->device, 1);
1048                 pdi->id = bit->device;
1049                 pci = fpci ? fpci : get_cpu_info(pdi, bit->cpu);
1050                 pci->cpu = bit->cpu;
1051                 pci->nelems++;
1052
1053                 if (trace_rb_insert(t)) {
1054                         free(t);
1055                         return -1;
1056                 }
1057
1058                 traces += sizeof(*bit) + bit->pdu_len;
1059                 nr--;
1060         }
1061
1062         return 0;
1063 }
1064
1065 static void free_entries_rb(void)
1066 {
1067         struct rb_node *n;
1068
1069         while ((n = rb_first(&rb_sort_root)) != NULL) {
1070                 struct trace *t = rb_entry(n, struct trace, rb_node);
1071
1072                 rb_erase(&t->rb_node, &rb_sort_root);
1073                 free(t);
1074         }
1075 }
1076
1077 static void show_entries_rb(void)
1078 {
1079         struct per_dev_info *pdi;
1080         struct blk_io_trace *bit;
1081         struct rb_node *n;
1082         struct trace *t;
1083         int cpu;
1084
1085         n = rb_first(&rb_sort_root);
1086         if (!n)
1087                 return;
1088
1089         do {
1090                 t = rb_entry(n, struct trace, rb_node);
1091                 bit = t->bit;
1092
1093                 pdi = get_dev_info(bit->device, 0);
1094                 if (!pdi) {
1095                         fprintf(stderr, "Unknown device ID? (%d,%d)\n",
1096                                 MAJOR(bit->device), MINOR(bit->device));
1097                         break;
1098                 }
1099                 cpu = bit->cpu;
1100                 if (cpu > pdi->ncpus) {
1101                         fprintf(stderr, "Unknown CPU ID? (%d, device %d,%d)\n",
1102                                 cpu, MAJOR(bit->device), MINOR(bit->device));
1103                         break;
1104                 }
1105
1106                 bit->time -= genesis_time;
1107
1108                 check_time(pdi, bit);
1109
1110                 if (dump_trace(bit, &pdi->cpus[cpu], pdi))
1111                         break;
1112
1113         } while ((n = rb_next(n)) != NULL);
1114 }
1115
1116 static int read_data(int fd, void *buffer, int bytes, int block)
1117 {
1118         int ret, bytes_left, fl;
1119         void *p;
1120
1121         fl = fcntl(fd, F_GETFL);
1122
1123         if (!block)
1124                 fcntl(fd, F_SETFL, fl | O_NONBLOCK);
1125         else
1126                 fcntl(fd, F_SETFL, fl & ~O_NONBLOCK);
1127
1128         bytes_left = bytes;
1129         p = buffer;
1130         while (bytes_left > 0) {
1131                 ret = read(fd, p, bytes_left);
1132                 if (!ret)
1133                         return 1;
1134                 else if (ret < 0) {
1135                         if (errno != EAGAIN)
1136                                 perror("read");
1137                         return -1;
1138                 } else {
1139                         p += ret;
1140                         bytes_left -= ret;
1141                 }
1142         }
1143
1144         return 0;
1145 }
1146
1147 static int do_file(void)
1148 {
1149         struct per_dev_info *pdi;
1150         int i, j, nfiles = 0;
1151
1152         for (pdi = devices, i = 0; i < ndevices; i++, pdi++) {
1153                 for (j = 0;; j++, nfiles++) {
1154                         struct per_cpu_info *pci;
1155                         struct stat st;
1156                         void *tb;
1157
1158                         pci = get_cpu_info(pdi, j);
1159                         pci->cpu = j;
1160
1161                         snprintf(pci->fname, sizeof(pci->fname)-1,
1162                                  "%s_out.%d", pdi->name, j);
1163                         if (stat(pci->fname, &st) < 0)
1164                                 break;
1165                         if (!st.st_size)
1166                                 continue;
1167
1168                         printf("Processing %s\n", pci->fname);
1169
1170                         tb = malloc(st.st_size);
1171                         if (!tb) {
1172                                 fprintf(stderr, "Out of memory, skip file %s\n",
1173                                         pci->fname);
1174                                 continue;
1175                         }
1176
1177                         pci->fd = open(pci->fname, O_RDONLY);
1178                         if (pci->fd < 0) {
1179                                 perror(pci->fname);
1180                                 free(tb);
1181                                 continue;
1182                         }
1183
1184                         if (read_data(pci->fd, tb, st.st_size, 1)) {
1185                                 close(pci->fd);
1186                                 free(tb);
1187                                 continue;
1188                         }
1189
1190                         if (sort_entries(tb, st.st_size, ~0U, pdi, pci) == -1) {
1191                                 close(pci->fd);
1192                                 free(tb);
1193                                 continue;
1194                         }
1195
1196                         printf("Completed %s (CPU%d %d, entries)\n",
1197                                 pci->fname, j, pci->nelems);
1198                         close(pci->fd);
1199                 }
1200         }
1201
1202         if (!nfiles) {
1203                 fprintf(stderr, "No files found\n");
1204                 return 1;
1205         }
1206
1207         show_entries_rb();
1208         return 0;
1209 }
1210
1211 static void resize_buffer(void **buffer, long *size, long offset)
1212 {
1213         long old_size = *size;
1214
1215         if (*size == 0)
1216                 *size = 64 * sizeof(struct blk_io_trace);
1217
1218         *size *= 2;
1219         *buffer = realloc(*buffer, *size);
1220
1221         if (old_size)
1222                 memset(*buffer + offset, 0, *size - old_size);
1223 }
1224
1225 static int read_sort_events(int fd, void **buffer, long *max_offset)
1226 {
1227         long offset;
1228         int events;
1229
1230         events = offset = 0;
1231         do {
1232                 struct blk_io_trace *t;
1233                 int pdu_len;
1234                 __u32 magic;
1235
1236                 if (*max_offset - offset < sizeof(*t))
1237                         resize_buffer(buffer, max_offset, offset);
1238
1239                 if (read_data(fd, *buffer + offset, sizeof(*t), !events))
1240                         break;
1241
1242                 t = *buffer + offset;
1243                 offset += sizeof(*t);
1244
1245                 magic = be32_to_cpu(t->magic);
1246                 if ((magic & 0xffffff00) != BLK_IO_TRACE_MAGIC) {
1247                         fprintf(stderr, "Bad magic %x\n", magic);
1248                         break;
1249                 }
1250
1251                 pdu_len = be16_to_cpu(t->pdu_len);
1252                 if (pdu_len) {
1253                         if (*max_offset - offset <= pdu_len)
1254                                 resize_buffer(buffer, max_offset, offset);
1255
1256                         if (read_data(fd, *buffer + offset, pdu_len, 1))
1257                                 break;
1258
1259                         offset += pdu_len;
1260                 }
1261
1262                 events++;
1263         } while (!is_done() && events < rb_batch);
1264
1265         return events;
1266 }
1267
1268 static int do_stdin(void)
1269 {
1270         int fd;
1271         void *ptr = NULL;
1272         long max_offset;
1273
1274         fd = dup(STDIN_FILENO);
1275         max_offset = 0;
1276         do {
1277                 int events;
1278
1279                 events = read_sort_events(fd, &ptr, &max_offset);
1280                 if (!events)
1281                         break;
1282
1283                 if (sort_entries(ptr, ~0UL, events, NULL, NULL) == -1)
1284                         break;
1285
1286                 show_entries_rb();
1287                 free_entries_rb();
1288         } while (1);
1289
1290         if (ptr)
1291                 free(ptr);
1292
1293         close(fd);
1294         return 0;
1295 }
1296
1297 static void flush_output(void)
1298 {
1299         fflush(ofp);
1300 }
1301
1302 static void handle_sigint(int sig)
1303 {
1304         done = 1;
1305         flush_output();
1306 }
1307
1308 static void usage(char *prog)
1309 {
1310         fprintf(stderr, "Usage: %s [-i <name>] [-o <output>] [-s] <name>...\n",
1311                         prog);
1312 }
1313
1314 int main(int argc, char *argv[])
1315 {
1316         char *ofp_buffer;
1317         int c, ret, mode;
1318         int per_device_and_cpu_stats = 1;
1319
1320         while ((c = getopt_long(argc, argv, S_OPTS, l_opts, NULL)) != -1) {
1321                 switch (c) {
1322                 case 'i':
1323                         if (!strcmp(optarg, "-") && !pipeline)
1324                                 pipeline = 1;
1325                         else if (resize_devices(optarg) != 0)
1326                                 return 1;
1327                         break;
1328                 case 'o':
1329                         output_name = optarg;
1330                         break;
1331                 case 'b':
1332                         rb_batch = atoi(optarg);
1333                         if (rb_batch <= 0)
1334                                 rb_batch = RB_BATCH_DEFAULT;
1335                         break;
1336                 case 's':
1337                         per_process_stats = 1;
1338                         break;
1339                 case 't':
1340                         track_ios = 1;
1341                         break;
1342                 case 'q':
1343                         per_device_and_cpu_stats = 0;
1344                         break;
1345                 default:
1346                         usage(argv[0]);
1347                         return 1;
1348                 }
1349         }
1350
1351         while (optind < argc) {
1352                 if (!strcmp(argv[optind], "-") && !pipeline)
1353                         pipeline = 1;
1354                 else if (resize_devices(argv[optind]) != 0)
1355                         return 1;
1356                 optind++;
1357         }
1358
1359         if (!pipeline && !ndevices) {
1360                 usage(argv[0]);
1361                 return 1;
1362         }
1363
1364         memset(&rb_sort_root, 0, sizeof(rb_sort_root));
1365         memset(&rb_track_root, 0, sizeof(rb_track_root));
1366
1367         signal(SIGINT, handle_sigint);
1368         signal(SIGHUP, handle_sigint);
1369         signal(SIGTERM, handle_sigint);
1370
1371         setlocale(LC_NUMERIC, "en_US");
1372
1373         if (!output_name) {
1374                 ofp = fdopen(STDOUT_FILENO, "w");
1375                 mode = _IOLBF;
1376         } else {
1377                 char ofname[128];
1378
1379                 snprintf(ofname, sizeof(ofname) - 1, "%s.log", output_name);
1380                 ofp = fopen(ofname, "w");
1381                 mode = _IOFBF;
1382         }
1383
1384         if (!ofp) {
1385                 perror("fopen");
1386                 return 1;
1387         }
1388
1389         ofp_buffer = malloc(4096);
1390         if (setvbuf(ofp, ofp_buffer, mode, 4096)) {
1391                 perror("setvbuf");
1392                 return 1;
1393         }
1394
1395         if (pipeline)
1396                 ret = do_stdin();
1397         else
1398                 ret = do_file();
1399
1400         if (per_process_stats)
1401                 show_process_stats();
1402
1403         if (per_device_and_cpu_stats)
1404                 show_device_and_cpu_stats();
1405
1406         flush_output();
1407         return ret;
1408 }