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