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 #include <limits.h>
  33
  34 #include "blktrace.h"
  35 #include "rbtree.h"
  36 #include "jhash.h"
  37
  38 static char blkparse_version[] = "0.90";
  39
  40 struct per_dev_info {
  41         dev_t dev;
  42         char *name;
  43
  44         int backwards;
  45         unsigned long long events;
  46         unsigned long long last_reported_time;
  47         unsigned long long last_read_time;
  48         struct io_stats io_stats;
  49         unsigned long last_sequence;
  50         unsigned long skips;
  51
  52         struct rb_root rb_last;
  53         unsigned long rb_last_entries;
  54
  55         struct rb_root rb_track;
  56
  57         int nfiles;
  58         int ncpus;
  59         struct per_cpu_info *cpus;
  60 };
  61
  62 struct per_process_info {
  63         char name[16];
  64         __u32 pid;
  65         struct io_stats io_stats;
  66         struct per_process_info *hash_next, *list_next;
  67         int more_than_one;
  68
  69         /*
  70          * individual io stats
  71          */
  72         unsigned long long longest_allocation_wait[2];
  73         unsigned long long longest_dispatch_wait[2];
  74         unsigned long long longest_completion_wait[2];
  75 };
  76
  77 #define PPI_HASH_SHIFT  (8)
  78 #define PPI_HASH_SIZE   (1 << PPI_HASH_SHIFT)
  79 #define PPI_HASH_MASK   (PPI_HASH_SIZE - 1)
  80 static struct per_process_info *ppi_hash_table[PPI_HASH_SIZE];
  81 static struct per_process_info *ppi_list;
  82 static int ppi_list_entries;
  83
  84 #define S_OPTS  "i:o:b:stqw:f:F:vnm"
  85 static struct option l_opts[] = {
  86         {
  87                 .name = "input",
  88                 .has_arg = required_argument,
  89                 .flag = NULL,
  90                 .val = 'i'
  91         },
  92         {
  93                 .name = "output",
  94                 .has_arg = required_argument,
  95                 .flag = NULL,
  96                 .val = 'o'
  97         },
  98         {
  99                 .name = "batch",
 100                 .has_arg = required_argument,
 101                 .flag = NULL,
 102                 .val = 'b'
 103         },
 104         {
 105                 .name = "per program stats",
 106                 .has_arg = no_argument,
 107                 .flag = NULL,
 108                 .val = 's'
 109         },
 110         {
 111                 .name = "track ios",
 112                 .has_arg = no_argument,
 113                 .flag = NULL,
 114                 .val = 't'
 115         },
 116         {
 117                 .name = "quiet",
 118                 .has_arg = no_argument,
 119                 .flag = NULL,
 120                 .val = 'q'
 121         },
 122         {
 123                 .name = "stopwatch",
 124                 .has_arg = required_argument,
 125                 .flag = NULL,
 126                 .val = 'w'
 127         },
 128         {
 129                 .name = "format",
 130                 .has_arg = required_argument,
 131                 .flag = NULL,
 132                 .val = 'f'
 133         },
 134         {
 135                 .name = "format-spec",
 136                 .has_arg = required_argument,
 137                 .flag = NULL,
 138                 .val = 'F'
 139         },
 140         {
 141                 .name = "hash by name",
 142                 .has_arg = no_argument,
 143                 .flag = NULL,
 144                 .val = 'n'
 145         },
 146         {
 147                 .name = "missing",
 148                 .has_arg = no_argument,
 149                 .flag = NULL,
 150                 .val = 'm'
 151         },
 152         {
 153                 .name = "version",
 154                 .has_arg = no_argument,
 155                 .flag = NULL,
 156                 .val = 'v'
 157         },
 158 };
 159
 160 /*
 161  * for sorting the displayed output
 162  */
 163 struct trace {
 164         struct blk_io_trace *bit;
 165         struct rb_node rb_node;
 166         struct trace *next;
 167 };
 168
 169 static struct rb_root rb_sort_root;
 170 static unsigned long rb_sort_entries;
 171
 172 static struct trace *trace_list;
 173
 174 /*
 175  * allocation cache
 176  */
 177 static struct blk_io_trace *bit_alloc_list;
 178 static struct trace *t_alloc_list;
 179
 180 /*
 181  * for tracking individual ios
 182  */
 183 struct io_track {
 184         struct rb_node rb_node;
 185
 186         __u64 sector;
 187         __u32 pid;
 188         char comm[16];
 189         unsigned long long allocation_time;
 190         unsigned long long queue_time;
 191         unsigned long long dispatch_time;
 192         unsigned long long completion_time;
 193 };
 194
 195 static int ndevices;
 196 static struct per_dev_info *devices;
 197 static char *get_dev_name(struct per_dev_info *, char *, int);
 198
 199 FILE *ofp = NULL;
 200 static char *output_name;
 201
 202 static unsigned long long genesis_time;
 203 static unsigned long long last_allowed_time;
 204 static unsigned int smallest_seq_read;
 205 static unsigned long long stopwatch_start;      /* start from zero by default */
 206 static unsigned long long stopwatch_end = ULONG_LONG_MAX;       /* "infinity" */
 207
 208 static int per_process_stats;
 209 static int track_ios;
 210 static int ppi_hash_by_pid = 1;
 211 static int print_missing;
 212
 213 static unsigned int t_alloc_cache;
 214 static unsigned int bit_alloc_cache;
 215
 216 #define RB_BATCH_DEFAULT        (512)
 217 static unsigned int rb_batch = RB_BATCH_DEFAULT;
 218
 219 static int pipeline;
 220
 221 #define is_done()       (*(volatile int *)(&done))
 222 static volatile int done;
 223
 224 #define JHASH_RANDOM    (0x3af5f2ee)
 225
 226 static inline int ppi_hash_pid(__u32 pid)
 227 {
 228         return jhash_1word(pid, JHASH_RANDOM) & PPI_HASH_MASK;
 229 }
 230
 231 static inline int ppi_hash_name(const char *name)
 232 {
 233         return jhash(name, 16, JHASH_RANDOM) & PPI_HASH_MASK;
 234 }
 235
 236 static inline int ppi_hash(struct per_process_info *ppi)
 237 {
 238         if (ppi_hash_by_pid)
 239                 return ppi_hash_pid(ppi->pid);
 240
 241         return ppi_hash_name(ppi->name);
 242 }
 243
 244 static inline void add_process_to_hash(struct per_process_info *ppi)
 245 {
 246         const int hash_idx = ppi_hash(ppi);
 247
 248         ppi->hash_next = ppi_hash_table[hash_idx];
 249         ppi_hash_table[hash_idx] = ppi;
 250 }
 251
 252 static inline void add_process_to_list(struct per_process_info *ppi)
 253 {
 254         ppi->list_next = ppi_list;
 255         ppi_list = ppi;
 256         ppi_list_entries++;
 257 }
 258
 259 static struct per_process_info *find_process_by_name(char *name)
 260 {
 261         const int hash_idx = ppi_hash_name(name);
 262         struct per_process_info *ppi;
 263
 264         ppi = ppi_hash_table[hash_idx];
 265         while (ppi) {
 266                 if (!strcmp(ppi->name, name))
 267                         return ppi;
 268
 269                 ppi = ppi->hash_next;
 270         }
 271
 272         return NULL;
 273 }
 274
 275 static struct per_process_info *find_process_by_pid(__u32 pid)
 276 {
 277         const int hash_idx = ppi_hash_pid(pid);
 278         struct per_process_info *ppi;
 279
 280         ppi = ppi_hash_table[hash_idx];
 281         while (ppi) {
 282                 if (ppi->pid == pid)
 283                         return ppi;
 284
 285                 ppi = ppi->hash_next;
 286         }
 287
 288         return NULL;
 289 }
 290
 291 static struct per_process_info *find_process(__u32 pid, char *name)
 292 {
 293         struct per_process_info *ppi;
 294
 295         if (ppi_hash_by_pid)
 296                 return find_process_by_pid(pid);
 297
 298         ppi = find_process_by_name(name);
 299         if (ppi && ppi->pid != pid)
 300                 ppi->more_than_one = 1;
 301
 302         return ppi;
 303 }
 304
 305 static inline int trace_rb_insert(struct trace *t, struct rb_root *root,
 306                                   int check_time)
 307 {
 308         struct rb_node **p = &root->rb_node;
 309         struct rb_node *parent = NULL;
 310         struct trace *__t;
 311
 312         while (*p) {
 313                 parent = *p;
 314
 315                 __t = rb_entry(parent, struct trace, rb_node);
 316
 317                 if (check_time) {
 318                         if (t->bit->time < __t->bit->time) {
 319                                 p = &(*p)->rb_left;
 320                                 continue;
 321                         } else if (t->bit->time > __t->bit->time) {
 322                                 p = &(*p)->rb_right;
 323                                 continue;
 324                         }
 325                 }
 326                 if (t->bit->device < __t->bit->device)
 327                         p = &(*p)->rb_left;
 328                 else if (t->bit->device > __t->bit->device)
 329                         p = &(*p)->rb_right;
 330                 else if (t->bit->sequence < __t->bit->sequence)
 331                         p = &(*p)->rb_left;
 332                 else if (t->bit->sequence > __t->bit->sequence)
 333                         p = &(*p)->rb_right;
 334                 else if (t->bit->device == __t->bit->device) {
 335                         fprintf(stderr,
 336                                 "sequence alias (%d) on device %d,%d!\n",
 337                                 t->bit->sequence,
 338                                 MAJOR(t->bit->device), MINOR(t->bit->device));
 339                         return 1;
 340                 }
 341         }
 342
 343         rb_link_node(&t->rb_node, parent, p);
 344         rb_insert_color(&t->rb_node, root);
 345         return 0;
 346 }
 347
 348 static inline int trace_rb_insert_sort(struct trace *t)
 349 {
 350         if (!trace_rb_insert(t, &rb_sort_root, 1)) {
 351                 rb_sort_entries++;
 352                 return 0;
 353         }
 354
 355         return 1;
 356 }
 357
 358 static inline int trace_rb_insert_last(struct per_dev_info *pdi,struct trace *t)
 359 {
 360         if (!trace_rb_insert(t, &pdi->rb_last, 1)) {
 361                 pdi->rb_last_entries++;
 362                 return 0;
 363         }
 364
 365         return 1;
 366 }
 367
 368 static struct trace *trace_rb_find(dev_t device, unsigned long sequence,
 369                                    struct rb_root *root, int order)
 370 {
 371         struct rb_node *n = root->rb_node;
 372         struct rb_node *prev = NULL;
 373         struct trace *__t;
 374
 375         while (n) {
 376                 __t = rb_entry(n, struct trace, rb_node);
 377                 prev = n;
 378
 379                 if (device < __t->bit->device)
 380                         n = n->rb_left;
 381                 else if (device > __t->bit->device)
 382                         n = n->rb_right;
 383                 else if (sequence < __t->bit->sequence)
 384                         n = n->rb_left;
 385                 else if (sequence > __t->bit->sequence)
 386                         n = n->rb_right;
 387                 else
 388                         return __t;
 389         }
 390
 391         /*
 392          * hack - the list may not be sequence ordered because some
 393          * events don't have sequence and time matched. so we end up
 394          * being a little off in the rb lookup here, because we don't
 395          * know the time we are looking for. compensate by browsing
 396          * a little ahead from the last entry to find the match
 397          */
 398         if (order && prev) {
 399                 int max = 5;
 400
 401                 while (((n = rb_next(prev)) != NULL) && max--) {
 402                         __t = rb_entry(n, struct trace, rb_node);
 403
 404                         if (__t->bit->device == device &&
 405                             __t->bit->sequence == sequence)
 406                                 return __t;
 407
 408                         prev = n;
 409                 }
 410         }
 411
 412         return NULL;
 413 }
 414
 415 static inline struct trace *trace_rb_find_sort(dev_t dev, unsigned long seq)
 416 {
 417         return trace_rb_find(dev, seq, &rb_sort_root, 1);
 418 }
 419
 420 static inline struct trace *trace_rb_find_last(struct per_dev_info *pdi,
 421                                                unsigned long seq)
 422 {
 423         return trace_rb_find(pdi->dev, seq, &pdi->rb_last, 0);
 424 }
 425
 426 static inline int track_rb_insert(struct per_dev_info *pdi,struct io_track *iot)
 427 {
 428         struct rb_node **p = &pdi->rb_track.rb_node;
 429         struct rb_node *parent = NULL;
 430         struct io_track *__iot;
 431
 432         while (*p) {
 433                 parent = *p;
 434                 __iot = rb_entry(parent, struct io_track, rb_node);
 435
 436                 if (iot->sector < __iot->sector)
 437                         p = &(*p)->rb_left;
 438                 else if (iot->sector > __iot->sector)
 439                         p = &(*p)->rb_right;
 440                 else {
 441                         fprintf(stderr,
 442                                 "sector alias (%Lu) on device %d,%d!\n",
 443                                 (unsigned long long) iot->sector,
 444                                 MAJOR(pdi->dev), MINOR(pdi->dev));
 445                         return 1;
 446                 }
 447         }
 448
 449         rb_link_node(&iot->rb_node, parent, p);
 450         rb_insert_color(&iot->rb_node, &pdi->rb_track);
 451         return 0;
 452 }
 453
 454 static struct io_track *__find_track(struct per_dev_info *pdi, __u64 sector)
 455 {
 456         struct rb_node *n = pdi->rb_track.rb_node;
 457         struct io_track *__iot;
 458
 459         while (n) {
 460                 __iot = rb_entry(n, struct io_track, rb_node);
 461
 462                 if (sector < __iot->sector)
 463                         n = n->rb_left;
 464                 else if (sector > __iot->sector)
 465                         n = n->rb_right;
 466                 else
 467                         return __iot;
 468         }
 469
 470         return NULL;
 471 }
 472
 473 static struct io_track *find_track(struct per_dev_info *pdi, __u32 pid,
 474                                    char *comm, __u64 sector)
 475 {
 476         struct io_track *iot;
 477
 478         iot = __find_track(pdi, sector);
 479         if (!iot) {
 480                 iot = malloc(sizeof(*iot));
 481                 iot->pid = pid;
 482                 memcpy(iot->comm, comm, sizeof(iot->comm));
 483                 iot->sector = sector;
 484                 track_rb_insert(pdi, iot);
 485         }
 486
 487         return iot;
 488 }
 489
 490 static void log_track_frontmerge(struct per_dev_info *pdi,
 491                                  struct blk_io_trace *t)
 492 {
 493         struct io_track *iot;
 494
 495         if (!track_ios)
 496                 return;
 497
 498         iot = __find_track(pdi, t->sector + (t->bytes >> 9));
 499         if (!iot) {
 500                 fprintf(stderr, "merge not found for (%d,%d): %llu\n",
 501                         MAJOR(pdi->dev), MINOR(pdi->dev),
 502                         (unsigned long long) t->sector + (t->bytes >> 9));
 503                 return;
 504         }
 505
 506         rb_erase(&iot->rb_node, &pdi->rb_track);
 507         iot->sector -= t->bytes >> 9;
 508         track_rb_insert(pdi, iot);
 509 }
 510
 511 static void log_track_getrq(struct per_dev_info *pdi, struct blk_io_trace *t)
 512 {
 513         struct io_track *iot;
 514
 515         if (!track_ios)
 516                 return;
 517
 518         iot = find_track(pdi, t->pid, t->comm, t->sector);
 519         iot->allocation_time = t->time;
 520 }
 521
 522 /*
 523  * return time between rq allocation and insertion
 524  */
 525 static unsigned long long log_track_insert(struct per_dev_info *pdi,
 526                                            struct blk_io_trace *t)
 527 {
 528         unsigned long long elapsed;
 529         struct io_track *iot;
 530
 531         if (!track_ios)
 532                 return -1;
 533
 534         iot = find_track(pdi, t->pid, t->comm, t->sector);
 535         iot->queue_time = t->time;
 536
 537         if (!iot->allocation_time)
 538                 return -1;
 539
 540         elapsed = iot->queue_time - iot->allocation_time;
 541
 542         if (per_process_stats) {
 543                 struct per_process_info *ppi = find_process(iot->pid,iot->comm);
 544                 int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0;
 545
 546                 if (ppi && elapsed > ppi->longest_allocation_wait[w])
 547                         ppi->longest_allocation_wait[w] = elapsed;
 548         }
 549
 550         return elapsed;
 551 }
 552
 553 /*
 554  * return time between queue and issue
 555  */
 556 static unsigned long long log_track_issue(struct per_dev_info *pdi,
 557                                           struct blk_io_trace *t)
 558 {
 559         unsigned long long elapsed;
 560         struct io_track *iot;
 561
 562         if (!track_ios)
 563                 return -1;
 564         if ((t->action & BLK_TC_ACT(BLK_TC_FS)) == 0)
 565                 return -1;
 566
 567         iot = __find_track(pdi, t->sector);
 568         if (!iot) {
 569                 fprintf(stderr, "issue not found for (%d,%d): %llu\n",
 570                         MAJOR(pdi->dev), MINOR(pdi->dev),
 571                         (unsigned long long) t->sector);
 572                 return -1;
 573         }
 574
 575         iot->dispatch_time = t->time;
 576         elapsed = iot->dispatch_time - iot->queue_time;
 577
 578         if (per_process_stats) {
 579                 struct per_process_info *ppi = find_process(iot->pid,iot->comm);
 580                 int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0;
 581
 582                 if (ppi && elapsed > ppi->longest_dispatch_wait[w])
 583                         ppi->longest_dispatch_wait[w] = elapsed;
 584         }
 585
 586         return elapsed;
 587 }
 588
 589 /*
 590  * return time between dispatch and complete
 591  */
 592 static unsigned long long log_track_complete(struct per_dev_info *pdi,
 593                                              struct blk_io_trace *t)
 594 {
 595         unsigned long long elapsed;
 596         struct io_track *iot;
 597
 598         if (!track_ios)
 599                 return -1;
 600         if ((t->action & BLK_TC_ACT(BLK_TC_FS)) == 0)
 601                 return -1;
 602
 603         iot = __find_track(pdi, t->sector);
 604         if (!iot) {
 605                 fprintf(stderr, "complete not found for (%d,%d): %llu\n",
 606                         MAJOR(pdi->dev), MINOR(pdi->dev),
 607                         (unsigned long long) t->sector);
 608                 return -1;
 609         }
 610
 611         iot->completion_time = t->time;
 612         elapsed = iot->completion_time - iot->dispatch_time;
 613
 614         if (per_process_stats) {
 615                 struct per_process_info *ppi = find_process(iot->pid,iot->comm);
 616                 int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0;
 617
 618                 if (ppi && elapsed > ppi->longest_completion_wait[w])
 619                         ppi->longest_completion_wait[w] = elapsed;
 620         }
 621
 622         /*
 623          * kill the trace, we don't need it after completion
 624          */
 625         rb_erase(&iot->rb_node, &pdi->rb_track);
 626         free(iot);
 627
 628         return elapsed;
 629 }
 630
 631
 632 static struct io_stats *find_process_io_stats(__u32 pid, char *name)
 633 {
 634         struct per_process_info *ppi = find_process(pid, name);
 635
 636         if (!ppi) {
 637                 ppi = malloc(sizeof(*ppi));
 638                 memset(ppi, 0, sizeof(*ppi));
 639                 memcpy(ppi->name, name, 16);
 640                 ppi->pid = pid;
 641                 add_process_to_hash(ppi);
 642                 add_process_to_list(ppi);
 643         }
 644
 645         return &ppi->io_stats;
 646 }
 647
 648 static void resize_cpu_info(struct per_dev_info *pdi, int cpu)
 649 {
 650         struct per_cpu_info *cpus = pdi->cpus;
 651         int ncpus = pdi->ncpus;
 652         int new_count = cpu + 1;
 653         int new_space, size;
 654         char *new_start;
 655
 656         size = new_count * sizeof(struct per_cpu_info);
 657         cpus = realloc(cpus, size);
 658         if (!cpus) {
 659                 char name[20];
 660                 fprintf(stderr, "Out of memory, CPU info for device %s (%d)\n",
 661                         get_dev_name(pdi, name, sizeof(name)), size);
 662                 exit(1);
 663         }
 664
 665         new_start = (char *)cpus + (ncpus * sizeof(struct per_cpu_info));
 666         new_space = (new_count - ncpus) * sizeof(struct per_cpu_info);
 667         memset(new_start, 0, new_space);
 668
 669         pdi->ncpus = new_count;
 670         pdi->cpus = cpus;
 671 }
 672
 673 static struct per_cpu_info *get_cpu_info(struct per_dev_info *pdi, int cpu)
 674 {
 675         struct per_cpu_info *pci;
 676
 677         if (cpu >= pdi->ncpus)
 678                 resize_cpu_info(pdi, cpu);
 679
 680         pci = &pdi->cpus[cpu];
 681         pci->cpu = cpu;
 682         return pci;
 683 }
 684
 685
 686 static int resize_devices(char *name)
 687 {
 688         int size = (ndevices + 1) * sizeof(struct per_dev_info);
 689
 690         devices = realloc(devices, size);
 691         if (!devices) {
 692                 fprintf(stderr, "Out of memory, device %s (%d)\n", name, size);
 693                 return 1;
 694         }
 695         memset(&devices[ndevices], 0, sizeof(struct per_dev_info));
 696         devices[ndevices].name = name;
 697         ndevices++;
 698         return 0;
 699 }
 700
 701 static struct per_dev_info *get_dev_info(dev_t dev)
 702 {
 703         struct per_dev_info *pdi;
 704         int i;
 705
 706         for (i = 0; i < ndevices; i++) {
 707                 if (!devices[i].dev)
 708                         devices[i].dev = dev;
 709                 if (devices[i].dev == dev)
 710                         return &devices[i];
 711         }
 712
 713         if (resize_devices(NULL))
 714                 return NULL;
 715
 716         pdi = &devices[ndevices - 1];
 717         pdi->dev = dev;
 718         pdi->last_sequence = -1;
 719         pdi->last_read_time = 0;
 720         memset(&pdi->rb_last, 0, sizeof(pdi->rb_last));
 721         pdi->rb_last_entries = 0;
 722         return pdi;
 723 }
 724
 725 static char *get_dev_name(struct per_dev_info *pdi, char *buffer, int size)
 726 {
 727         if (pdi->name)
 728                 snprintf(buffer, size, "%s", pdi->name);
 729         else
 730                 snprintf(buffer, size, "%d,%d",MAJOR(pdi->dev),MINOR(pdi->dev));
 731         return buffer;
 732 }
 733
 734 static void check_time(struct per_dev_info *pdi, struct blk_io_trace *bit)
 735 {
 736         unsigned long long this = bit->time;
 737         unsigned long long last = pdi->last_reported_time;
 738
 739         pdi->backwards = (this < last) ? 'B' : ' ';
 740         pdi->last_reported_time = this;
 741 }
 742
 743 static inline void __account_m(struct io_stats *ios, struct blk_io_trace *t,
 744                                int rw)
 745 {
 746         if (rw) {
 747                 ios->mwrites++;
 748                 ios->qwrite_kb += t->bytes >> 10;
 749         } else {
 750                 ios->mreads++;
 751                 ios->qread_kb += t->bytes >> 10;
 752         }
 753 }
 754
 755 static inline void account_m(struct blk_io_trace *t, struct per_cpu_info *pci,
 756                              int rw)
 757 {
 758         __account_m(&pci->io_stats, t, rw);
 759
 760         if (per_process_stats) {
 761                 struct io_stats *ios = find_process_io_stats(t->pid, t->comm);
 762
 763                 __account_m(ios, t, rw);
 764         }
 765 }
 766
 767 static inline void __account_queue(struct io_stats *ios, struct blk_io_trace *t,
 768                                    int rw)
 769 {
 770         if (rw) {
 771                 ios->qwrites++;
 772                 ios->qwrite_kb += t->bytes >> 10;
 773         } else {
 774                 ios->qreads++;
 775                 ios->qread_kb += t->bytes >> 10;
 776         }
 777 }
 778
 779 static inline void account_queue(struct blk_io_trace *t,
 780                                  struct per_cpu_info *pci, int rw)
 781 {
 782         __account_queue(&pci->io_stats, t, rw);
 783
 784         if (per_process_stats) {
 785                 struct io_stats *ios = find_process_io_stats(t->pid, t->comm);
 786
 787                 __account_queue(ios, t, rw);
 788         }
 789 }
 790
 791 static inline void __account_c(struct io_stats *ios, int rw, unsigned int bytes)
 792 {
 793         if (rw) {
 794                 ios->cwrites++;
 795                 ios->cwrite_kb += bytes >> 10;
 796         } else {
 797                 ios->creads++;
 798                 ios->cread_kb += bytes >> 10;
 799         }
 800 }
 801
 802 static inline void account_c(struct blk_io_trace *t, struct per_cpu_info *pci,
 803                              int rw, int bytes)
 804 {
 805         __account_c(&pci->io_stats, rw, bytes);
 806
 807         if (per_process_stats) {
 808                 struct io_stats *ios = find_process_io_stats(t->pid, t->comm);
 809
 810                 __account_c(ios, rw, bytes);
 811         }
 812 }
 813
 814 static inline void __account_issue(struct io_stats *ios, int rw,
 815                                    unsigned int bytes)
 816 {
 817         if (rw) {
 818                 ios->iwrites++;
 819                 ios->iwrite_kb += bytes >> 10;
 820         } else {
 821                 ios->ireads++;
 822                 ios->iread_kb += bytes >> 10;
 823         }
 824 }
 825
 826 static inline void account_issue(struct blk_io_trace *t,
 827                                  struct per_cpu_info *pci, int rw)
 828 {
 829         __account_issue(&pci->io_stats, rw, t->bytes);
 830
 831         if (per_process_stats) {
 832                 struct io_stats *ios = find_process_io_stats(t->pid, t->comm);
 833
 834                 __account_issue(ios, rw, t->bytes);
 835         }
 836 }
 837
 838 static inline void __account_unplug(struct io_stats *ios, int timer)
 839 {
 840         if (timer)
 841                 ios->timer_unplugs++;
 842         else
 843                 ios->io_unplugs++;
 844 }
 845
 846 static inline void account_unplug(struct blk_io_trace *t,
 847                                   struct per_cpu_info *pci, int timer)
 848 {
 849         __account_unplug(&pci->io_stats, timer);
 850
 851         if (per_process_stats) {
 852                 struct io_stats *ios = find_process_io_stats(t->pid, t->comm);
 853
 854                 __account_unplug(ios, timer);
 855         }
 856 }
 857
 858 static void log_complete(struct per_dev_info *pdi, struct per_cpu_info *pci,
 859                          struct blk_io_trace *t, char *act)
 860 {
 861         process_fmt(act, pci, t, log_track_complete(pdi, t), 0, NULL);
 862 }
 863
 864 static void log_insert(struct per_dev_info *pdi, struct per_cpu_info *pci,
 865                        struct blk_io_trace *t, char *act)
 866 {
 867         process_fmt(act, pci, t, log_track_insert(pdi, t), 0, NULL);
 868 }
 869
 870 static void log_queue(struct per_cpu_info *pci, struct blk_io_trace *t,
 871                       char *act)
 872 {
 873         process_fmt(act, pci, t, -1, 0, NULL);
 874 }
 875
 876 static void log_issue(struct per_dev_info *pdi, struct per_cpu_info *pci,
 877                       struct blk_io_trace *t, char *act)
 878 {
 879         process_fmt(act, pci, t, log_track_issue(pdi, t), 0, NULL);
 880 }
 881
 882 static void log_merge(struct per_dev_info *pdi, struct per_cpu_info *pci,
 883                       struct blk_io_trace *t, char *act)
 884 {
 885         if (act[0] == 'F')
 886                 log_track_frontmerge(pdi, t);
 887
 888         process_fmt(act, pci, t, -1ULL, 0, NULL);
 889 }
 890
 891 static void log_action(struct per_cpu_info *pci, struct blk_io_trace *t,
 892                         char *act)
 893 {
 894         process_fmt(act, pci, t, -1ULL, 0, NULL);
 895 }
 896
 897 static void log_generic(struct per_cpu_info *pci, struct blk_io_trace *t,
 898                         char *act)
 899 {
 900         process_fmt(act, pci, t, -1ULL, 0, NULL);
 901 }
 902
 903 static void log_unplug(struct per_cpu_info *pci, struct blk_io_trace *t,
 904                       char *act)
 905 {
 906         process_fmt(act, pci, t, -1ULL, 0, NULL);
 907 }
 908
 909 static void log_split(struct per_cpu_info *pci, struct blk_io_trace *t,
 910                       char *act)
 911 {
 912         process_fmt(act, pci, t, -1ULL, 0, NULL);
 913 }
 914
 915 static void log_pc(struct per_cpu_info *pci, struct blk_io_trace *t, char *act)
 916 {
 917         unsigned char *buf = (unsigned char *) t + sizeof(*t);
 918
 919         process_fmt(act, pci, t, -1ULL, t->pdu_len, buf);
 920 }
 921
 922 static void dump_trace_pc(struct blk_io_trace *t, struct per_cpu_info *pci)
 923 {
 924         int act = t->action & 0xffff;
 925
 926         switch (act) {
 927                 case __BLK_TA_QUEUE:
 928                         log_generic(pci, t, "Q");
 929                         break;
 930                 case __BLK_TA_GETRQ:
 931                         log_generic(pci, t, "G");
 932                         break;
 933                 case __BLK_TA_SLEEPRQ:
 934                         log_generic(pci, t, "S");
 935                         break;
 936                 case __BLK_TA_REQUEUE:
 937                         log_generic(pci, t, "R");
 938                         break;
 939                 case __BLK_TA_ISSUE:
 940                         log_pc(pci, t, "D");
 941                         break;
 942                 case __BLK_TA_COMPLETE:
 943                         log_pc(pci, t, "C");
 944                         break;
 945                 case __BLK_TA_INSERT:
 946                         log_pc(pci, t, "I");
 947                         break;
 948                 default:
 949                         fprintf(stderr, "Bad pc action %x\n", act);
 950                         break;
 951         }
 952 }
 953
 954 static void dump_trace_fs(struct blk_io_trace *t, struct per_dev_info *pdi,
 955                           struct per_cpu_info *pci)
 956 {
 957         int w = t->action & BLK_TC_ACT(BLK_TC_WRITE);
 958         int act = t->action & 0xffff;
 959
 960         switch (act) {
 961                 case __BLK_TA_QUEUE:
 962                         account_queue(t, pci, w);
 963                         log_queue(pci, t, "Q");
 964                         break;
 965                 case __BLK_TA_INSERT:
 966                         log_insert(pdi, pci, t, "I");
 967                         break;
 968                 case __BLK_TA_BACKMERGE:
 969                         account_m(t, pci, w);
 970                         log_merge(pdi, pci, t, "M");
 971                         break;
 972                 case __BLK_TA_FRONTMERGE:
 973                         account_m(t, pci, w);
 974                         log_merge(pdi, pci, t, "F");
 975                         break;
 976                 case __BLK_TA_GETRQ:
 977                         log_track_getrq(pdi, t);
 978                         log_generic(pci, t, "G");
 979                         break;
 980                 case __BLK_TA_SLEEPRQ:
 981                         log_generic(pci, t, "S");
 982                         break;
 983                 case __BLK_TA_REQUEUE:
 984                         account_c(t, pci, w, -t->bytes);
 985                         log_queue(pci, t, "R");
 986                         break;
 987                 case __BLK_TA_ISSUE:
 988                         account_issue(t, pci, w);
 989                         log_issue(pdi, pci, t, "D");
 990                         break;
 991                 case __BLK_TA_COMPLETE:
 992                         account_c(t, pci, w, t->bytes);
 993                         log_complete(pdi, pci, t, "C");
 994                         break;
 995                 case __BLK_TA_PLUG:
 996                         log_action(pci, t, "P");
 997                         break;
 998                 case __BLK_TA_UNPLUG_IO:
 999                         account_unplug(t, pci, 0);
1000                         log_unplug(pci, t, "U");
1001                         break;
1002                 case __BLK_TA_UNPLUG_TIMER:
1003                         account_unplug(t, pci, 1);
1004                         log_unplug(pci, t, "UT");
1005                         break;
1006                 case __BLK_TA_SPLIT:
1007                         log_split(pci, t, "X");
1008                         break;
1009                 case __BLK_TA_BOUNCE:
1010                         log_generic(pci, t, "B");
1011                         break;
1012                 default:
1013                         fprintf(stderr, "Bad fs action %x\n", t->action);
1014                         break;
1015         }
1016 }
1017
1018 static void dump_trace(struct blk_io_trace *t, struct per_cpu_info *pci,
1019                        struct per_dev_info *pdi)
1020 {
1021         if (t->action & BLK_TC_ACT(BLK_TC_PC))
1022                 dump_trace_pc(t, pci);
1023         else
1024                 dump_trace_fs(t, pdi, pci);
1025
1026         pdi->events++;
1027 }
1028
1029 static void dump_io_stats(struct io_stats *ios, char *msg)
1030 {
1031         fprintf(ofp, "%s\n", msg);
1032
1033         fprintf(ofp, " Reads Queued:    %'8lu, %'8LuKiB\t", ios->qreads, ios->qread_kb);
1034         fprintf(ofp, " Writes Queued:    %'8lu, %'8LuKiB\n", ios->qwrites,ios->qwrite_kb);
1035
1036         fprintf(ofp, " Read Dispatches: %'8lu, %'8LuKiB\t", ios->ireads, ios->iread_kb);
1037         fprintf(ofp, " Write Dispatches: %'8lu, %'8LuKiB\n", ios->iwrites,ios->iwrite_kb);
1038         fprintf(ofp, " Reads Completed: %'8lu, %'8LuKiB\t", ios->creads, ios->cread_kb);
1039         fprintf(ofp, " Writes Completed: %'8lu, %'8LuKiB\n", ios->cwrites,ios->cwrite_kb);
1040         fprintf(ofp, " Read Merges:     %'8lu%8c\t", ios->mreads, ' ');
1041         fprintf(ofp, " Write Merges:     %'8lu\n", ios->mwrites);
1042         fprintf(ofp, " IO unplugs:      %'8lu%8c\t", ios->io_unplugs, ' ');
1043         fprintf(ofp, " Timer unplugs:    %'8lu\n", ios->timer_unplugs);
1044 }
1045
1046 static void dump_wait_stats(struct per_process_info *ppi)
1047 {
1048         unsigned long rawait = ppi->longest_allocation_wait[0] / 1000;
1049         unsigned long rdwait = ppi->longest_dispatch_wait[0] / 1000;
1050         unsigned long rcwait = ppi->longest_completion_wait[0] / 1000;
1051         unsigned long wawait = ppi->longest_allocation_wait[1] / 1000;
1052         unsigned long wdwait = ppi->longest_dispatch_wait[1] / 1000;
1053         unsigned long wcwait = ppi->longest_completion_wait[1] / 1000;
1054
1055         fprintf(ofp, " Allocation wait: %'8lu%8c\t", rawait, ' ');
1056         fprintf(ofp, " Allocation wait:  %'8lu\n", wawait);
1057         fprintf(ofp, " Dispatch wait:   %'8lu%8c\t", rdwait, ' ');
1058         fprintf(ofp, " Dispatch wait:    %'8lu\n", wdwait);
1059         fprintf(ofp, " Completion wait: %'8lu%8c\t", rcwait, ' ');
1060         fprintf(ofp, " Completion wait:  %'8lu\n", wcwait);
1061 }
1062
1063 static int ppi_name_compare(const void *p1, const void *p2)
1064 {
1065         struct per_process_info *ppi1 = *((struct per_process_info **) p1);
1066         struct per_process_info *ppi2 = *((struct per_process_info **) p2);
1067         int res;
1068
1069         res = strverscmp(ppi1->name, ppi2->name);
1070         if (!res)
1071                 res = ppi1->pid > ppi2->pid;
1072
1073         return res;
1074 }
1075
1076 static void sort_process_list(void)
1077 {
1078         struct per_process_info **ppis;
1079         struct per_process_info *ppi;
1080         int i = 0;
1081
1082         ppis = malloc(ppi_list_entries * sizeof(struct per_process_info *));
1083
1084         ppi = ppi_list;
1085         while (ppi) {
1086                 ppis[i++] = ppi;
1087                 ppi = ppi->list_next;
1088         }
1089
1090         qsort(ppis, ppi_list_entries, sizeof(ppi), ppi_name_compare);
1091
1092         i = ppi_list_entries - 1;
1093         ppi_list = NULL;
1094         while (i >= 0) {
1095                 ppi = ppis[i];
1096
1097                 ppi->list_next = ppi_list;
1098                 ppi_list = ppi;
1099                 i--;
1100         }
1101
1102         free(ppis);
1103 }
1104
1105 static void show_process_stats(void)
1106 {
1107         struct per_process_info *ppi;
1108
1109         sort_process_list();
1110
1111         ppi = ppi_list;
1112         while (ppi) {
1113                 char name[64];
1114
1115                 if (ppi->more_than_one)
1116                         sprintf(name, "%s (%u, ...)", ppi->name, ppi->pid);
1117                 else
1118                         sprintf(name, "%s (%u)", ppi->name, ppi->pid);
1119
1120                 dump_io_stats(&ppi->io_stats, name);
1121                 dump_wait_stats(ppi);
1122                 ppi = ppi->list_next;
1123         }
1124
1125         fprintf(ofp, "\n");
1126 }
1127
1128 static void show_device_and_cpu_stats(void)
1129 {
1130         struct per_dev_info *pdi;
1131         struct per_cpu_info *pci;
1132         struct io_stats total, *ios;
1133         int i, j, pci_events;
1134         char line[3 + 8/*cpu*/ + 2 + 32/*dev*/ + 3];
1135         char name[32];
1136
1137         for (pdi = devices, i = 0; i < ndevices; i++, pdi++) {
1138
1139                 memset(&total, 0, sizeof(total));
1140                 pci_events = 0;
1141
1142                 if (i > 0)
1143                         fprintf(ofp, "\n");
1144
1145                 for (pci = pdi->cpus, j = 0; j < pdi->ncpus; j++, pci++) {
1146                         if (!pci->nelems)
1147                                 continue;
1148
1149                         ios = &pci->io_stats;
1150                         total.qreads += ios->qreads;
1151                         total.qwrites += ios->qwrites;
1152                         total.creads += ios->creads;
1153                         total.cwrites += ios->cwrites;
1154                         total.mreads += ios->mreads;
1155                         total.mwrites += ios->mwrites;
1156                         total.ireads += ios->ireads;
1157                         total.iwrites += ios->iwrites;
1158                         total.qread_kb += ios->qread_kb;
1159                         total.qwrite_kb += ios->qwrite_kb;
1160                         total.cread_kb += ios->cread_kb;
1161                         total.cwrite_kb += ios->cwrite_kb;
1162                         total.iread_kb += ios->iread_kb;
1163                         total.iwrite_kb += ios->iwrite_kb;
1164                         total.timer_unplugs += ios->timer_unplugs;
1165                         total.io_unplugs += ios->io_unplugs;
1166
1167                         snprintf(line, sizeof(line) - 1, "CPU%d (%s):",
1168                                  j, get_dev_name(pdi, name, sizeof(name)));
1169                         dump_io_stats(ios, line);
1170                         pci_events++;
1171                 }
1172
1173                 if (pci_events > 1) {
1174                         fprintf(ofp, "\n");
1175                         snprintf(line, sizeof(line) - 1, "Total (%s):",
1176                                  get_dev_name(pdi, name, sizeof(name)));
1177                         dump_io_stats(&total, line);
1178                 }
1179
1180                 fprintf(ofp, "\nEvents (%s): %'Lu entries, %'lu skips\n",
1181                         get_dev_name(pdi, line, sizeof(line)), pdi->events,
1182                         pdi->skips);
1183         }
1184 }
1185
1186 /*
1187  * struct trace and blktrace allocation cache, we do potentially
1188  * millions of mallocs for these structures while only using at most
1189  * a few thousand at the time
1190  */
1191 static inline void t_free(struct trace *t)
1192 {
1193         if (t_alloc_cache < 1024) {
1194                 t->next = t_alloc_list;
1195                 t_alloc_list = t;
1196                 t_alloc_cache++;
1197         } else
1198                 free(t);
1199 }
1200
1201 static inline struct trace *t_alloc(void)
1202 {
1203         struct trace *t = t_alloc_list;
1204
1205         if (t) {
1206                 t_alloc_list = t->next;
1207                 t_alloc_cache--;
1208                 return t;
1209         }
1210
1211         return malloc(sizeof(*t));
1212 }
1213
1214 static inline void bit_free(struct blk_io_trace *bit)
1215 {
1216         if (bit_alloc_cache < 1024) {
1217                 /*
1218                  * abuse a 64-bit field for a next pointer for the free item
1219                  */
1220                 bit->time = (__u64) (unsigned long) bit_alloc_list;
1221                 bit_alloc_list = (struct blk_io_trace *) bit;
1222                 bit_alloc_cache++;
1223         } else
1224                 free(bit);
1225 }
1226
1227 static inline struct blk_io_trace *bit_alloc(void)
1228 {
1229         struct blk_io_trace *bit = bit_alloc_list;
1230
1231         if (bit) {
1232                 bit_alloc_list = (struct blk_io_trace *) (unsigned long) \
1233                                  bit->time;
1234                 bit_alloc_cache--;
1235                 return bit;
1236         }
1237
1238         return malloc(sizeof(*bit));
1239 }
1240
1241 static void find_genesis(void)
1242 {
1243         struct trace *t = trace_list;
1244
1245         genesis_time = -1ULL;
1246         while (t != NULL) {
1247                 if (t->bit->time < genesis_time)
1248                         genesis_time = t->bit->time;
1249
1250                 t = t->next;
1251         }
1252 }
1253
1254 static inline int check_stopwatch(struct blk_io_trace *bit)
1255 {
1256         if (bit->time < stopwatch_end &&
1257             bit->time >= stopwatch_start)
1258                 return 0;
1259
1260         return 1;
1261 }
1262
1263 /*
1264  * return youngest entry read
1265  */
1266 static int sort_entries(unsigned long long *youngest)
1267 {
1268         struct trace *t;
1269
1270         if (!genesis_time)
1271                 find_genesis();
1272
1273         *youngest = 0;
1274         while ((t = trace_list) != NULL) {
1275                 struct blk_io_trace *bit = t->bit;
1276
1277                 trace_list = t->next;
1278
1279                 bit->time -= genesis_time;
1280
1281                 if (bit->time < *youngest || !*youngest)
1282                         *youngest = bit->time;
1283
1284                 if (check_stopwatch(bit)) {
1285                         bit_free(bit);
1286                         t_free(t);
1287                         continue;
1288                 }
1289
1290                 if (trace_rb_insert_sort(t))
1291                         return -1;
1292
1293                 if (bit->sequence < smallest_seq_read)
1294                         smallest_seq_read = bit->sequence;
1295         }
1296
1297         return 0;
1298 }
1299
1300 static inline void __put_trace_last(struct per_dev_info *pdi, struct trace *t)
1301 {
1302         rb_erase(&t->rb_node, &pdi->rb_last);
1303         pdi->rb_last_entries--;
1304
1305         bit_free(t->bit);
1306         t_free(t);
1307 }
1308
1309 static void put_trace(struct per_dev_info *pdi, struct trace *t)
1310 {
1311         rb_erase(&t->rb_node, &rb_sort_root);
1312         rb_sort_entries--;
1313
1314         trace_rb_insert_last(pdi, t);
1315
1316         if (pdi->rb_last_entries > rb_batch * pdi->nfiles) {
1317                 struct rb_node *n = rb_first(&pdi->rb_last);
1318
1319                 t = rb_entry(n, struct trace, rb_node);
1320                 __put_trace_last(pdi, t);
1321         }
1322 }
1323
1324 static int check_sequence(struct per_dev_info *pdi, struct blk_io_trace *bit,
1325                           int force)
1326 {
1327         unsigned long expected_sequence = pdi->last_sequence + 1;
1328         struct trace *t;
1329
1330         /*
1331          * first entry, always ok
1332          */
1333         if (!expected_sequence)
1334                 return 0;
1335
1336         if (bit->sequence == expected_sequence)
1337                 return 0;
1338
1339         /*
1340          * we may not have seen that sequence yet. if we are not doing
1341          * the final run, break and wait for more entries.
1342          */
1343         if (expected_sequence < smallest_seq_read) {
1344                 t = trace_rb_find_last(pdi, expected_sequence);
1345                 if (!t)
1346                         goto skip;
1347
1348                 __put_trace_last(pdi, t);
1349                 return 0;
1350         } else if (!force)
1351                 return 1;
1352         else {
1353 skip:
1354                 if (print_missing) {
1355                         fprintf(stderr, "(%d,%d): skipping %lu -> %u\n",
1356                                 MAJOR(pdi->dev), MINOR(pdi->dev),
1357                                 pdi->last_sequence, bit->sequence);
1358                 }
1359                 pdi->skips++;
1360                 return 0;
1361         }
1362 }
1363
1364 static void show_entries_rb(int force)
1365 {
1366         struct per_dev_info *pdi = NULL;
1367         struct per_cpu_info *pci = NULL;
1368         struct blk_io_trace *bit;
1369         struct rb_node *n;
1370         struct trace *t;
1371
1372         if (force) {
1373                 n = rb_first(&rb_sort_root);
1374                 t = rb_entry(n, struct trace, rb_node);
1375                 fprintf(stderr, "first force %u\n", t->bit->sequence);
1376         }
1377
1378         while ((n = rb_first(&rb_sort_root)) != NULL) {
1379                 if (done)
1380                         break;
1381
1382                 t = rb_entry(n, struct trace, rb_node);
1383                 bit = t->bit;
1384
1385                 if (!pdi || pdi->dev != bit->device)
1386                         pdi = get_dev_info(bit->device);
1387
1388                 if (!pdi) {
1389                         fprintf(stderr, "Unknown device ID? (%d,%d)\n",
1390                                 MAJOR(bit->device), MINOR(bit->device));
1391                         break;
1392                 }
1393
1394                 if (check_sequence(pdi, bit, force))
1395                         break;
1396
1397                 if (!force && bit->time > last_allowed_time)
1398                         break;
1399
1400                 pdi->last_sequence = bit->sequence;
1401
1402                 check_time(pdi, bit);
1403
1404                 if (!pci || pci->cpu != bit->cpu)
1405                         pci = get_cpu_info(pdi, bit->cpu);
1406
1407                 dump_trace(bit, pci, pdi);
1408
1409                 put_trace(pdi, t);
1410         }
1411 }
1412
1413 static int read_data(int fd, void *buffer, int bytes, int block)
1414 {
1415         int ret, bytes_left, fl;
1416         void *p;
1417
1418         fl = fcntl(fd, F_GETFL);
1419
1420         if (!block)
1421                 fcntl(fd, F_SETFL, fl | O_NONBLOCK);
1422         else
1423                 fcntl(fd, F_SETFL, fl & ~O_NONBLOCK);
1424
1425         bytes_left = bytes;
1426         p = buffer;
1427         while (bytes_left > 0) {
1428                 ret = read(fd, p, bytes_left);
1429                 if (!ret)
1430                         return 1;
1431                 else if (ret < 0) {
1432                         if (errno != EAGAIN)
1433                                 perror("read");
1434
1435                         return -1;
1436                 } else {
1437                         p += ret;
1438                         bytes_left -= ret;
1439                 }
1440         }
1441
1442         return 0;
1443 }
1444
1445 static int read_events(int fd, int always_block)
1446 {
1447         struct per_dev_info *pdi = NULL;
1448         unsigned int events = 0;
1449
1450         while (!is_done() && events < rb_batch) {
1451                 struct blk_io_trace *bit;
1452                 struct trace *t;
1453                 int pdu_len;
1454                 __u32 magic;
1455
1456                 bit = bit_alloc();
1457
1458                 if (read_data(fd, bit, sizeof(*bit), !events || always_block))
1459                         break;
1460
1461                 magic = be32_to_cpu(bit->magic);
1462                 if ((magic & 0xffffff00) != BLK_IO_TRACE_MAGIC) {
1463                         fprintf(stderr, "Bad magic %x\n", magic);
1464                         break;
1465                 }
1466
1467                 pdu_len = be16_to_cpu(bit->pdu_len);
1468                 if (pdu_len) {
1469                         void *ptr = realloc(bit, sizeof(*bit) + pdu_len);
1470
1471                         if (read_data(fd, ptr + sizeof(*bit), pdu_len, 1))
1472                                 break;
1473
1474                         bit = ptr;
1475                 }
1476
1477                 trace_to_cpu(bit);
1478
1479                 if (verify_trace(bit)) {
1480                         bit_free(bit);
1481                         continue;
1482                 }
1483
1484                 t = t_alloc();
1485                 memset(t, 0, sizeof(*t));
1486                 t->bit = bit;
1487
1488                 t->next = trace_list;
1489                 trace_list = t;
1490
1491                 if (!pdi || pdi->dev != bit->device)
1492                         pdi = get_dev_info(bit->device);
1493
1494                 if (bit->time > pdi->last_read_time)
1495                         pdi->last_read_time = bit->time;
1496
1497                 events++;
1498         }
1499
1500         return events;
1501 }
1502
1503 static int do_file(void)
1504 {
1505         struct per_cpu_info *pci;
1506         struct per_dev_info *pdi;
1507         int i, j, events, events_added;
1508
1509         /*
1510          * first prepare all files for reading
1511          */
1512         for (i = 0; i < ndevices; i++) {
1513                 pdi = &devices[i];
1514                 pdi->nfiles = 0;
1515                 pdi->last_sequence = -1;
1516
1517                 for (j = 0;; j++) {
1518                         struct stat st;
1519
1520                         pci = get_cpu_info(pdi, j);
1521                         pci->cpu = j;
1522                         pci->fd = -1;
1523
1524                         snprintf(pci->fname, sizeof(pci->fname)-1,
1525                                  "%s.blktrace.%d", pdi->name, pci->cpu);
1526                         if (stat(pci->fname, &st) < 0)
1527                                 break;
1528                         if (st.st_size) {
1529                                 pci->fd = open(pci->fname, O_RDONLY);
1530                                 if (pci->fd < 0) {
1531                                         perror(pci->fname);
1532                                         continue;
1533                                 }
1534                         }
1535
1536                         printf("Input file %s added\n", pci->fname);
1537                         pdi->nfiles++;
1538                 }
1539         }
1540
1541         /*
1542          * now loop over the files reading in the data
1543          */
1544         do {
1545                 unsigned long long youngest;
1546
1547                 events_added = 0;
1548                 last_allowed_time = -1ULL;
1549                 smallest_seq_read = -1U;
1550
1551                 for (i = 0; i < ndevices; i++) {
1552                         pdi = &devices[i];
1553
1554                         for (j = 0; j < pdi->nfiles; j++) {
1555
1556                                 pci = get_cpu_info(pdi, j);
1557
1558                                 if (pci->fd == -1)
1559                                         continue;
1560
1561                                 events = read_events(pci->fd, 1);
1562                                 if (!events) {
1563                                         close(pci->fd);
1564                                         pci->fd = -1;
1565                                         continue;
1566                                 }
1567
1568                                 if (pdi->last_read_time < last_allowed_time)
1569                                         last_allowed_time = pdi->last_read_time;
1570
1571                                 events_added += events;
1572                         }
1573                 }
1574
1575                 if (sort_entries(&youngest))
1576                         break;
1577
1578                 if (youngest > stopwatch_end)
1579                         break;
1580
1581                 show_entries_rb(0);
1582
1583         } while (events_added);
1584
1585         if (rb_sort_entries)
1586                 show_entries_rb(1);
1587
1588         return 0;
1589 }
1590
1591 static int do_stdin(void)
1592 {
1593         unsigned long long youngest;
1594         int fd;
1595
1596         last_allowed_time = -1ULL;
1597         fd = dup(STDIN_FILENO);
1598         do {
1599                 int events;
1600
1601                 events = read_events(fd, 0);
1602                 if (!events)
1603                         break;
1604
1605                 if (sort_entries(&youngest))
1606                         break;
1607
1608                 if (youngest > stopwatch_end)
1609                         break;
1610
1611                 show_entries_rb(0);
1612         } while (1);
1613
1614         if (rb_sort_entries)
1615                 show_entries_rb(1);
1616
1617         close(fd);
1618         return 0;
1619 }
1620
1621 static void flush_output(void)
1622 {
1623         fflush(ofp);
1624 }
1625
1626 static void handle_sigint(__attribute__((__unused__)) int sig)
1627 {
1628         done = 1;
1629         flush_output();
1630 }
1631
1632 /*
1633  * Extract start and duration times from a string, allowing
1634  * us to specify a time interval of interest within a trace.
1635  * Format: "duration" (start is zero) or "start:duration".
1636  */
1637 static int find_stopwatch_interval(char *string)
1638 {
1639         double value;
1640         char *sp;
1641
1642         value = strtod(string, &sp);
1643         if (sp == string) {
1644                 fprintf(stderr,"Invalid stopwatch timer: %s\n", string);
1645                 return 1;
1646         }
1647         if (*sp == ':') {
1648                 stopwatch_start = DOUBLE_TO_NANO_ULL(value);
1649                 string = sp + 1;
1650                 value = strtod(string, &sp);
1651                 if (sp == string || *sp != '\0') {
1652                         fprintf(stderr,"Invalid stopwatch duration time: %s\n",
1653                                 string);
1654                         return 1;
1655                 }
1656         } else if (*sp != '\0') {
1657                 fprintf(stderr,"Invalid stopwatch start timer: %s\n", string);
1658                 return 1;
1659         }
1660         stopwatch_end = DOUBLE_TO_NANO_ULL(value);
1661         if (stopwatch_end <= stopwatch_start) {
1662                 fprintf(stderr, "Invalid stopwatch interval: %Lu -> %Lu\n",
1663                         stopwatch_start, stopwatch_end);
1664                 return 1;
1665         }
1666
1667         return 0;
1668 }
1669
1670 static char usage_str[] = \
1671         "[ -i <input name> ] [-o <output name> [ -s ] [ -t ] [ -q ]\n" \
1672         "[ -w start:stop ] [ -f output format ] [ -F format spec ] [ -v] \n\n" \
1673         "\t-i Input file containing trace data, or '-' for stdin\n" \
1674         "\t-o Output file. If not given, output is stdout\n" \
1675         "\t-b stdin read batching\n" \
1676         "\t-s Show per-program io statistics\n" \
1677         "\t-n Hash processes by name, not pid\n" \
1678         "\t-t Track individual ios. Will tell you the time a request took\n" \
1679         "\t   to get queued, to get dispatched, and to get completed\n" \
1680         "\t-q Quiet. Don't display any stats at the end of the trace\n" \
1681         "\t-w Only parse data between the given time interval in seconds.\n" \
1682         "\t   If 'start' isn't given, blkparse defaults the start time to 0\n" \
1683         "\t -f Output format. Customize the output format. The format field\n" \
1684         "\t    identifies can be found in the documentation\n" \
1685         "\t-F Format specification. Can be found in the documentation\n" \
1686         "\t-m Print missing entries\n" \
1687         "\t-v Print program version info\n\n";
1688
1689 static void usage(char *prog)
1690 {
1691         fprintf(stderr, "Usage: %s %s %s", prog, blkparse_version, usage_str);
1692 }
1693
1694 int main(int argc, char *argv[])
1695 {
1696         char *ofp_buffer;
1697         int c, ret, mode;
1698         int per_device_and_cpu_stats = 1;
1699
1700         while ((c = getopt_long(argc, argv, S_OPTS, l_opts, NULL)) != -1) {
1701                 switch (c) {
1702                 case 'i':
1703                         if (!strcmp(optarg, "-") && !pipeline)
1704                                 pipeline = 1;
1705                         else if (resize_devices(optarg) != 0)
1706                                 return 1;
1707                         break;
1708                 case 'o':
1709                         output_name = optarg;
1710                         break;
1711                 case 'b':
1712                         rb_batch = atoi(optarg);
1713                         if (rb_batch <= 0)
1714                                 rb_batch = RB_BATCH_DEFAULT;
1715                         break;
1716                 case 's':
1717                         per_process_stats = 1;
1718                         break;
1719                 case 't':
1720                         track_ios = 1;
1721                         break;
1722                 case 'q':
1723                         per_device_and_cpu_stats = 0;
1724                         break;
1725                 case 'w':
1726                         if (find_stopwatch_interval(optarg) != 0)
1727                                 return 1;
1728                         break;
1729                 case 'f':
1730                         set_all_format_specs(optarg);
1731                         break;
1732                 case 'F':
1733                         if (add_format_spec(optarg) != 0)
1734                                 return 1;
1735                         break;
1736                 case 'n':
1737                         ppi_hash_by_pid = 0;
1738                         break;
1739                 case 'm':
1740                         print_missing = 1;
1741                         break;
1742                 case 'v':
1743                         printf("%s version %s\n", argv[0], blkparse_version);
1744                         return 0;
1745                 default:
1746                         usage(argv[0]);
1747                         return 1;
1748                 }
1749         }
1750
1751         while (optind < argc) {
1752                 if (!strcmp(argv[optind], "-") && !pipeline)
1753                         pipeline = 1;
1754                 else if (resize_devices(argv[optind]) != 0)
1755                         return 1;
1756                 optind++;
1757         }
1758
1759         if (!pipeline && !ndevices) {
1760                 usage(argv[0]);
1761                 return 1;
1762         }
1763
1764         memset(&rb_sort_root, 0, sizeof(rb_sort_root));
1765
1766         signal(SIGINT, handle_sigint);
1767         signal(SIGHUP, handle_sigint);
1768         signal(SIGTERM, handle_sigint);
1769
1770         setlocale(LC_NUMERIC, "en_US");
1771
1772         if (!output_name) {
1773                 ofp = fdopen(STDOUT_FILENO, "w");
1774                 mode = _IOLBF;
1775         } else {
1776                 char ofname[128];
1777
1778                 snprintf(ofname, sizeof(ofname) - 1, "%s", output_name);
1779                 ofp = fopen(ofname, "w");
1780                 mode = _IOFBF;
1781         }
1782
1783         if (!ofp) {
1784                 perror("fopen");
1785                 return 1;
1786         }
1787
1788         ofp_buffer = malloc(4096);
1789         if (setvbuf(ofp, ofp_buffer, mode, 4096)) {
1790                 perror("setvbuf");
1791                 return 1;
1792         }
1793
1794         if (pipeline)
1795                 ret = do_stdin();
1796         else
1797                 ret = do_file();
1798
1799         if (per_process_stats)
1800                 show_process_stats();
1801
1802         if (per_device_and_cpu_stats)
1803                 show_device_and_cpu_stats();
1804
1805         flush_output();
1806         return ret;
1807 }