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