2 * block queue tracing parse application
4 * Copyright (C) 2005 Jens Axboe <axboe@suse.de>
5 * Copyright (C) 2006 Jens Axboe <axboe@kernel.dk>
7 * This program is free software; you can redistribute it and/or modify
8 * it under the terms of the GNU General Public License as published by
9 * the Free Software Foundation; either version 2 of the License, or
10 * (at your option) any later version.
12 * This program is distributed in the hope that it will be useful,
13 * but WITHOUT ANY WARRANTY; without even the implied warranty of
14 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
15 * GNU General Public License for more details.
17 * You should have received a copy of the GNU General Public License
18 * along with this program; if not, write to the Free Software
19 * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
22 #include <sys/types.h>
39 static char blkparse_version[] = "0.99.3";
42 unsigned long start, end;
43 struct skip_info *prev, *next;
51 unsigned long long events;
52 unsigned long long first_reported_time;
53 unsigned long long last_reported_time;
54 unsigned long long last_read_time;
55 struct io_stats io_stats;
57 unsigned long long seq_skips;
58 unsigned int max_depth[2];
59 unsigned int cur_depth[2];
61 struct rb_root rb_track;
66 unsigned long *cpu_map;
67 unsigned int cpu_map_max;
69 struct per_cpu_info *cpus;
73 * some duplicated effort here, we can unify this hash and the ppi hash later
75 struct process_pid_map {
78 struct process_pid_map *hash_next, *list_next;
81 #define PPM_HASH_SHIFT (8)
82 #define PPM_HASH_SIZE (1 << PPM_HASH_SHIFT)
83 #define PPM_HASH_MASK (PPM_HASH_SIZE - 1)
84 static struct process_pid_map *ppm_hash_table[PPM_HASH_SIZE];
86 struct per_process_info {
87 struct process_pid_map *ppm;
88 struct io_stats io_stats;
89 struct per_process_info *hash_next, *list_next;
95 unsigned long long longest_allocation_wait[2];
96 unsigned long long longest_dispatch_wait[2];
97 unsigned long long longest_completion_wait[2];
100 #define PPI_HASH_SHIFT (8)
101 #define PPI_HASH_SIZE (1 << PPI_HASH_SHIFT)
102 #define PPI_HASH_MASK (PPI_HASH_SIZE - 1)
103 static struct per_process_info *ppi_hash_table[PPI_HASH_SIZE];
104 static struct per_process_info *ppi_list;
105 static int ppi_list_entries;
107 #define S_OPTS "a:A:b:D:d:f:F:hi:o:Oqstw:vV"
108 static struct option l_opts[] = {
111 .has_arg = required_argument,
117 .has_arg = required_argument,
123 .has_arg = required_argument,
128 .name = "input-directory",
129 .has_arg = required_argument,
134 .name = "dump-binary",
135 .has_arg = required_argument,
141 .has_arg = required_argument,
146 .name = "format-spec",
147 .has_arg = required_argument,
152 .name = "hash-by-name",
153 .has_arg = no_argument,
159 .has_arg = required_argument,
165 .has_arg = required_argument,
170 .name = "no-text-output",
171 .has_arg = no_argument,
177 .has_arg = no_argument,
182 .name = "per-program-stats",
183 .has_arg = no_argument,
189 .has_arg = no_argument,
195 .has_arg = required_argument,
201 .has_arg = no_argument,
207 .has_arg = no_argument,
217 * for sorting the displayed output
220 struct blk_io_trace *bit;
221 struct rb_node rb_node;
223 unsigned long read_sequence;
226 static struct rb_root rb_sort_root;
227 static unsigned long rb_sort_entries;
229 static struct trace *trace_list;
234 static struct blk_io_trace *bit_alloc_list;
235 static struct trace *t_alloc_list;
238 * for tracking individual ios
241 struct rb_node rb_node;
243 struct process_pid_map *ppm;
245 unsigned long long allocation_time;
246 unsigned long long queue_time;
247 unsigned long long dispatch_time;
248 unsigned long long completion_time;
252 static struct per_dev_info *devices;
253 static char *get_dev_name(struct per_dev_info *, char *, int);
254 static int trace_rb_insert_last(struct per_dev_info *, struct trace *);
257 static char *output_name;
258 static char *input_dir;
260 static unsigned long long genesis_time;
261 static unsigned long long last_allowed_time;
262 static unsigned long long stopwatch_start; /* start from zero by default */
263 static unsigned long long stopwatch_end = -1ULL; /* "infinity" */
264 static unsigned long read_sequence;
266 static int per_process_stats;
267 static int per_device_and_cpu_stats = 1;
268 static int track_ios;
269 static int ppi_hash_by_pid = 1;
271 static unsigned int act_mask = -1U;
272 static int stats_printed;
273 int data_is_native = -1;
275 static FILE *dump_fp;
276 static char *dump_binary;
278 static unsigned int t_alloc_cache;
279 static unsigned int bit_alloc_cache;
281 #define RB_BATCH_DEFAULT (512)
282 static unsigned int rb_batch = RB_BATCH_DEFAULT;
285 static char *pipename;
287 static int text_output = 1;
289 #define is_done() (*(volatile int *)(&done))
290 static volatile int done;
292 struct timespec abs_start_time;
293 static unsigned long long start_timestamp;
295 #define JHASH_RANDOM (0x3af5f2ee)
297 #define CPUS_PER_LONG (8 * sizeof(unsigned long))
298 #define CPU_IDX(cpu) ((cpu) / CPUS_PER_LONG)
299 #define CPU_BIT(cpu) ((cpu) & (CPUS_PER_LONG - 1))
301 static void output_binary(void *buf, int len)
304 size_t n = fwrite(buf, len, 1, dump_fp);
313 static void resize_cpu_info(struct per_dev_info *pdi, int cpu)
315 struct per_cpu_info *cpus = pdi->cpus;
316 int ncpus = pdi->ncpus;
317 int new_count = cpu + 1;
321 size = new_count * sizeof(struct per_cpu_info);
322 cpus = realloc(cpus, size);
325 fprintf(stderr, "Out of memory, CPU info for device %s (%d)\n",
326 get_dev_name(pdi, name, sizeof(name)), size);
330 new_start = (char *)cpus + (ncpus * sizeof(struct per_cpu_info));
331 new_space = (new_count - ncpus) * sizeof(struct per_cpu_info);
332 memset(new_start, 0, new_space);
334 pdi->ncpus = new_count;
337 for (new_count = 0; new_count < pdi->ncpus; new_count++) {
338 struct per_cpu_info *pci = &pdi->cpus[new_count];
342 memset(&pci->rb_last, 0, sizeof(pci->rb_last));
343 pci->rb_last_entries = 0;
344 pci->last_sequence = -1;
349 static struct per_cpu_info *get_cpu_info(struct per_dev_info *pdi, int cpu)
351 struct per_cpu_info *pci;
353 if (cpu >= pdi->ncpus)
354 resize_cpu_info(pdi, cpu);
356 pci = &pdi->cpus[cpu];
362 static int resize_devices(char *name)
364 int size = (ndevices + 1) * sizeof(struct per_dev_info);
366 devices = realloc(devices, size);
368 fprintf(stderr, "Out of memory, device %s (%d)\n", name, size);
371 memset(&devices[ndevices], 0, sizeof(struct per_dev_info));
372 devices[ndevices].name = name;
377 static struct per_dev_info *get_dev_info(dev_t dev)
379 struct per_dev_info *pdi;
382 for (i = 0; i < ndevices; i++) {
384 devices[i].dev = dev;
385 if (devices[i].dev == dev)
389 if (resize_devices(NULL))
392 pdi = &devices[ndevices - 1];
394 pdi->first_reported_time = 0;
395 pdi->last_read_time = 0;
400 static void insert_skip(struct per_cpu_info *pci, unsigned long start,
403 struct skip_info *sip;
405 for (sip = pci->skips_tail; sip != NULL; sip = sip->prev) {
406 if (end == (sip->start - 1)) {
409 } else if (start == (sip->end + 1)) {
415 sip = malloc(sizeof(struct skip_info));
418 sip->prev = sip->next = NULL;
419 if (pci->skips_tail == NULL)
420 pci->skips_head = pci->skips_tail = sip;
422 sip->prev = pci->skips_tail;
423 pci->skips_tail->next = sip;
424 pci->skips_tail = sip;
428 static void remove_sip(struct per_cpu_info *pci, struct skip_info *sip)
430 if (sip->prev == NULL) {
431 if (sip->next == NULL)
432 pci->skips_head = pci->skips_tail = NULL;
434 pci->skips_head = sip->next;
435 sip->next->prev = NULL;
437 } else if (sip->next == NULL) {
438 pci->skips_tail = sip->prev;
439 sip->prev->next = NULL;
441 sip->prev->next = sip->next;
442 sip->next->prev = sip->prev;
445 sip->prev = sip->next = NULL;
449 #define IN_SKIP(sip,seq) (((sip)->start <= (seq)) && ((seq) <= sip->end))
450 static int check_current_skips(struct per_cpu_info *pci, unsigned long seq)
452 struct skip_info *sip;
454 for (sip = pci->skips_tail; sip != NULL; sip = sip->prev) {
455 if (IN_SKIP(sip, seq)) {
456 if (sip->start == seq) {
458 remove_sip(pci, sip);
461 } else if (sip->end == seq)
465 insert_skip(pci, seq + 1, sip->end);
474 static void collect_pdi_skips(struct per_dev_info *pdi)
476 struct skip_info *sip;
482 for (cpu = 0; cpu < pdi->ncpus; cpu++) {
483 struct per_cpu_info *pci = &pdi->cpus[cpu];
485 for (sip = pci->skips_head; sip != NULL; sip = sip->next) {
487 pdi->seq_skips += (sip->end - sip->start + 1);
489 fprintf(stderr,"(%d,%d): skipping %lu -> %lu\n",
490 MAJOR(pdi->dev), MINOR(pdi->dev),
491 sip->start, sip->end);
496 static void cpu_mark_online(struct per_dev_info *pdi, unsigned int cpu)
498 if (cpu >= pdi->cpu_map_max || !pdi->cpu_map) {
499 int new_max = (cpu + CPUS_PER_LONG) & ~(CPUS_PER_LONG - 1);
500 unsigned long *map = malloc(new_max / sizeof(long));
502 memset(map, 0, new_max / sizeof(long));
505 memcpy(map, pdi->cpu_map, pdi->cpu_map_max / sizeof(long));
510 pdi->cpu_map_max = new_max;
513 pdi->cpu_map[CPU_IDX(cpu)] |= (1UL << CPU_BIT(cpu));
516 static inline void cpu_mark_offline(struct per_dev_info *pdi, int cpu)
518 pdi->cpu_map[CPU_IDX(cpu)] &= ~(1UL << CPU_BIT(cpu));
521 static inline int cpu_is_online(struct per_dev_info *pdi, int cpu)
523 return (pdi->cpu_map[CPU_IDX(cpu)] & (1UL << CPU_BIT(cpu))) != 0;
526 static inline int ppm_hash_pid(pid_t pid)
528 return jhash_1word(pid, JHASH_RANDOM) & PPM_HASH_MASK;
531 static struct process_pid_map *find_ppm(pid_t pid)
533 const int hash_idx = ppm_hash_pid(pid);
534 struct process_pid_map *ppm;
536 ppm = ppm_hash_table[hash_idx];
541 ppm = ppm->hash_next;
547 static struct process_pid_map *add_ppm_hash(pid_t pid, const char *name)
549 const int hash_idx = ppm_hash_pid(pid);
550 struct process_pid_map *ppm;
554 ppm = malloc(sizeof(*ppm));
555 memset(ppm, 0, sizeof(*ppm));
557 strcpy(ppm->comm, name);
558 ppm->hash_next = ppm_hash_table[hash_idx];
559 ppm_hash_table[hash_idx] = ppm;
565 static void handle_notify(struct blk_io_trace *bit)
567 void *payload = (caddr_t) bit + sizeof(*bit);
570 switch (bit->action) {
572 add_ppm_hash(bit->pid, payload);
575 case BLK_TN_TIMESTAMP:
576 if (bit->pdu_len != sizeof(two32))
578 memcpy(two32, payload, sizeof(two32));
579 if (!data_is_native) {
580 two32[0] = be32_to_cpu(two32[0]);
581 two32[1] = be32_to_cpu(two32[1]);
583 start_timestamp = bit->time;
584 abs_start_time.tv_sec = two32[0];
585 abs_start_time.tv_nsec = two32[1];
586 if (abs_start_time.tv_nsec < 0) {
587 abs_start_time.tv_sec--;
588 abs_start_time.tv_nsec += 1000000000;
594 if (bit->pdu_len > 0) {
595 char msg[bit->pdu_len+1];
597 memcpy(msg, (char *)payload, bit->pdu_len);
598 msg[bit->pdu_len] = '\0';
601 "%3d,%-3d %2d %8s %5d.%09lu %5u %2s %3s %s\n",
602 MAJOR(bit->device), MINOR(bit->device),
603 bit->cpu, "0", (int) SECONDS(bit->time),
604 (unsigned long) NANO_SECONDS(bit->time),
610 /* Ignore unknown notify events */
615 char *find_process_name(pid_t pid)
617 struct process_pid_map *ppm = find_ppm(pid);
625 static inline int ppi_hash_pid(pid_t pid)
627 return jhash_1word(pid, JHASH_RANDOM) & PPI_HASH_MASK;
630 static inline int ppi_hash_name(const char *name)
632 return jhash(name, 16, JHASH_RANDOM) & PPI_HASH_MASK;
635 static inline int ppi_hash(struct per_process_info *ppi)
637 struct process_pid_map *ppm = ppi->ppm;
640 return ppi_hash_pid(ppm->pid);
642 return ppi_hash_name(ppm->comm);
645 static inline void add_ppi_to_hash(struct per_process_info *ppi)
647 const int hash_idx = ppi_hash(ppi);
649 ppi->hash_next = ppi_hash_table[hash_idx];
650 ppi_hash_table[hash_idx] = ppi;
653 static inline void add_ppi_to_list(struct per_process_info *ppi)
655 ppi->list_next = ppi_list;
660 static struct per_process_info *find_ppi_by_name(char *name)
662 const int hash_idx = ppi_hash_name(name);
663 struct per_process_info *ppi;
665 ppi = ppi_hash_table[hash_idx];
667 struct process_pid_map *ppm = ppi->ppm;
669 if (!strcmp(ppm->comm, name))
672 ppi = ppi->hash_next;
678 static struct per_process_info *find_ppi_by_pid(pid_t pid)
680 const int hash_idx = ppi_hash_pid(pid);
681 struct per_process_info *ppi;
683 ppi = ppi_hash_table[hash_idx];
685 struct process_pid_map *ppm = ppi->ppm;
690 ppi = ppi->hash_next;
696 static struct per_process_info *find_ppi(pid_t pid)
698 struct per_process_info *ppi;
702 return find_ppi_by_pid(pid);
704 name = find_process_name(pid);
708 ppi = find_ppi_by_name(name);
709 if (ppi && ppi->ppm->pid != pid)
710 ppi->more_than_one = 1;
716 * struct trace and blktrace allocation cache, we do potentially
717 * millions of mallocs for these structures while only using at most
718 * a few thousand at the time
720 static inline void t_free(struct trace *t)
722 if (t_alloc_cache < 1024) {
723 t->next = t_alloc_list;
730 static inline struct trace *t_alloc(void)
732 struct trace *t = t_alloc_list;
735 t_alloc_list = t->next;
740 return malloc(sizeof(*t));
743 static inline void bit_free(struct blk_io_trace *bit)
745 if (bit_alloc_cache < 1024 && !bit->pdu_len) {
747 * abuse a 64-bit field for a next pointer for the free item
749 bit->time = (__u64) (unsigned long) bit_alloc_list;
750 bit_alloc_list = (struct blk_io_trace *) bit;
756 static inline struct blk_io_trace *bit_alloc(void)
758 struct blk_io_trace *bit = bit_alloc_list;
761 bit_alloc_list = (struct blk_io_trace *) (unsigned long) \
767 return malloc(sizeof(*bit));
770 static inline void __put_trace_last(struct per_dev_info *pdi, struct trace *t)
772 struct per_cpu_info *pci = get_cpu_info(pdi, t->bit->cpu);
774 rb_erase(&t->rb_node, &pci->rb_last);
775 pci->rb_last_entries--;
781 static void put_trace(struct per_dev_info *pdi, struct trace *t)
783 rb_erase(&t->rb_node, &rb_sort_root);
786 trace_rb_insert_last(pdi, t);
789 static inline int trace_rb_insert(struct trace *t, struct rb_root *root)
791 struct rb_node **p = &root->rb_node;
792 struct rb_node *parent = NULL;
798 __t = rb_entry(parent, struct trace, rb_node);
800 if (t->bit->time < __t->bit->time)
802 else if (t->bit->time > __t->bit->time)
804 else if (t->bit->device < __t->bit->device)
806 else if (t->bit->device > __t->bit->device)
808 else if (t->bit->sequence < __t->bit->sequence)
810 else /* >= sequence */
814 rb_link_node(&t->rb_node, parent, p);
815 rb_insert_color(&t->rb_node, root);
819 static inline int trace_rb_insert_sort(struct trace *t)
821 if (!trace_rb_insert(t, &rb_sort_root)) {
829 static int trace_rb_insert_last(struct per_dev_info *pdi, struct trace *t)
831 struct per_cpu_info *pci = get_cpu_info(pdi, t->bit->cpu);
833 if (trace_rb_insert(t, &pci->rb_last))
836 pci->rb_last_entries++;
838 if (pci->rb_last_entries > rb_batch * pdi->nfiles) {
839 struct rb_node *n = rb_first(&pci->rb_last);
841 t = rb_entry(n, struct trace, rb_node);
842 __put_trace_last(pdi, t);
848 static struct trace *trace_rb_find(dev_t device, unsigned long sequence,
849 struct rb_root *root, int order)
851 struct rb_node *n = root->rb_node;
852 struct rb_node *prev = NULL;
856 __t = rb_entry(n, struct trace, rb_node);
859 if (device < __t->bit->device)
861 else if (device > __t->bit->device)
863 else if (sequence < __t->bit->sequence)
865 else if (sequence > __t->bit->sequence)
872 * hack - the list may not be sequence ordered because some
873 * events don't have sequence and time matched. so we end up
874 * being a little off in the rb lookup here, because we don't
875 * know the time we are looking for. compensate by browsing
876 * a little ahead from the last entry to find the match
881 while (((n = rb_next(prev)) != NULL) && max--) {
882 __t = rb_entry(n, struct trace, rb_node);
884 if (__t->bit->device == device &&
885 __t->bit->sequence == sequence)
895 static inline struct trace *trace_rb_find_last(struct per_dev_info *pdi,
896 struct per_cpu_info *pci,
899 return trace_rb_find(pdi->dev, seq, &pci->rb_last, 0);
902 static inline int track_rb_insert(struct per_dev_info *pdi,struct io_track *iot)
904 struct rb_node **p = &pdi->rb_track.rb_node;
905 struct rb_node *parent = NULL;
906 struct io_track *__iot;
910 __iot = rb_entry(parent, struct io_track, rb_node);
912 if (iot->sector < __iot->sector)
914 else if (iot->sector > __iot->sector)
918 "sector alias (%Lu) on device %d,%d!\n",
919 (unsigned long long) iot->sector,
920 MAJOR(pdi->dev), MINOR(pdi->dev));
925 rb_link_node(&iot->rb_node, parent, p);
926 rb_insert_color(&iot->rb_node, &pdi->rb_track);
930 static struct io_track *__find_track(struct per_dev_info *pdi, __u64 sector)
932 struct rb_node *n = pdi->rb_track.rb_node;
933 struct io_track *__iot;
936 __iot = rb_entry(n, struct io_track, rb_node);
938 if (sector < __iot->sector)
940 else if (sector > __iot->sector)
949 static struct io_track *find_track(struct per_dev_info *pdi, pid_t pid,
952 struct io_track *iot;
954 iot = __find_track(pdi, sector);
956 iot = malloc(sizeof(*iot));
957 iot->ppm = find_ppm(pid);
959 iot->ppm = add_ppm_hash(pid, "unknown");
960 iot->sector = sector;
961 track_rb_insert(pdi, iot);
967 static void log_track_frontmerge(struct per_dev_info *pdi,
968 struct blk_io_trace *t)
970 struct io_track *iot;
975 iot = __find_track(pdi, t->sector + t_sec(t));
978 fprintf(stderr, "merge not found for (%d,%d): %llu\n",
979 MAJOR(pdi->dev), MINOR(pdi->dev),
980 (unsigned long long) t->sector + t_sec(t));
984 rb_erase(&iot->rb_node, &pdi->rb_track);
985 iot->sector -= t_sec(t);
986 track_rb_insert(pdi, iot);
989 static void log_track_getrq(struct per_dev_info *pdi, struct blk_io_trace *t)
991 struct io_track *iot;
996 iot = find_track(pdi, t->pid, t->sector);
997 iot->allocation_time = t->time;
1000 static inline int is_remapper(struct per_dev_info *pdi)
1002 int major = MAJOR(pdi->dev);
1004 return (major == 253 || major == 9);
1008 * for md/dm setups, the interesting cycle is Q -> C. So track queueing
1009 * time here, as dispatch time
1011 static void log_track_queue(struct per_dev_info *pdi, struct blk_io_trace *t)
1013 struct io_track *iot;
1017 if (!is_remapper(pdi))
1020 iot = find_track(pdi, t->pid, t->sector);
1021 iot->dispatch_time = t->time;
1025 * return time between rq allocation and insertion
1027 static unsigned long long log_track_insert(struct per_dev_info *pdi,
1028 struct blk_io_trace *t)
1030 unsigned long long elapsed;
1031 struct io_track *iot;
1036 iot = find_track(pdi, t->pid, t->sector);
1037 iot->queue_time = t->time;
1039 if (!iot->allocation_time)
1042 elapsed = iot->queue_time - iot->allocation_time;
1044 if (per_process_stats) {
1045 struct per_process_info *ppi = find_ppi(iot->ppm->pid);
1046 int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0;
1048 if (ppi && elapsed > ppi->longest_allocation_wait[w])
1049 ppi->longest_allocation_wait[w] = elapsed;
1056 * return time between queue and issue
1058 static unsigned long long log_track_issue(struct per_dev_info *pdi,
1059 struct blk_io_trace *t)
1061 unsigned long long elapsed;
1062 struct io_track *iot;
1066 if ((t->action & BLK_TC_ACT(BLK_TC_FS)) == 0)
1069 iot = __find_track(pdi, t->sector);
1072 fprintf(stderr, "issue not found for (%d,%d): %llu\n",
1073 MAJOR(pdi->dev), MINOR(pdi->dev),
1074 (unsigned long long) t->sector);
1078 iot->dispatch_time = t->time;
1079 elapsed = iot->dispatch_time - iot->queue_time;
1081 if (per_process_stats) {
1082 struct per_process_info *ppi = find_ppi(iot->ppm->pid);
1083 int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0;
1085 if (ppi && elapsed > ppi->longest_dispatch_wait[w])
1086 ppi->longest_dispatch_wait[w] = elapsed;
1093 * return time between dispatch and complete
1095 static unsigned long long log_track_complete(struct per_dev_info *pdi,
1096 struct blk_io_trace *t)
1098 unsigned long long elapsed;
1099 struct io_track *iot;
1104 iot = __find_track(pdi, t->sector);
1107 fprintf(stderr,"complete not found for (%d,%d): %llu\n",
1108 MAJOR(pdi->dev), MINOR(pdi->dev),
1109 (unsigned long long) t->sector);
1113 iot->completion_time = t->time;
1114 elapsed = iot->completion_time - iot->dispatch_time;
1116 if (per_process_stats) {
1117 struct per_process_info *ppi = find_ppi(iot->ppm->pid);
1118 int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0;
1120 if (ppi && elapsed > ppi->longest_completion_wait[w])
1121 ppi->longest_completion_wait[w] = elapsed;
1125 * kill the trace, we don't need it after completion
1127 rb_erase(&iot->rb_node, &pdi->rb_track);
1134 static struct io_stats *find_process_io_stats(pid_t pid)
1136 struct per_process_info *ppi = find_ppi(pid);
1139 ppi = malloc(sizeof(*ppi));
1140 memset(ppi, 0, sizeof(*ppi));
1141 ppi->ppm = find_ppm(pid);
1143 ppi->ppm = add_ppm_hash(pid, "unknown");
1144 add_ppi_to_hash(ppi);
1145 add_ppi_to_list(ppi);
1148 return &ppi->io_stats;
1151 static char *get_dev_name(struct per_dev_info *pdi, char *buffer, int size)
1154 snprintf(buffer, size, "%s", pdi->name);
1156 snprintf(buffer, size, "%d,%d",MAJOR(pdi->dev),MINOR(pdi->dev));
1160 static void check_time(struct per_dev_info *pdi, struct blk_io_trace *bit)
1162 unsigned long long this = bit->time;
1163 unsigned long long last = pdi->last_reported_time;
1165 pdi->backwards = (this < last) ? 'B' : ' ';
1166 pdi->last_reported_time = this;
1169 static inline void __account_m(struct io_stats *ios, struct blk_io_trace *t,
1174 ios->mwrite_kb += t_kb(t);
1177 ios->mread_kb += t_kb(t);
1181 static inline void account_m(struct blk_io_trace *t, struct per_cpu_info *pci,
1184 __account_m(&pci->io_stats, t, rw);
1186 if (per_process_stats) {
1187 struct io_stats *ios = find_process_io_stats(t->pid);
1189 __account_m(ios, t, rw);
1193 static inline void __account_pc_queue(struct io_stats *ios,
1194 struct blk_io_trace *t, int rw)
1198 ios->qwrite_kb_pc += t_kb(t);
1201 ios->qread_kb += t_kb(t);
1205 static inline void account_pc_queue(struct blk_io_trace *t,
1206 struct per_cpu_info *pci, int rw)
1208 __account_pc_queue(&pci->io_stats, t, rw);
1210 if (per_process_stats) {
1211 struct io_stats *ios = find_process_io_stats(t->pid);
1213 __account_pc_queue(ios, t, rw);
1217 static inline void __account_pc_issue(struct io_stats *ios, int rw,
1222 ios->iwrite_kb_pc += bytes >> 10;
1225 ios->iread_kb_pc += bytes >> 10;
1229 static inline void account_pc_issue(struct blk_io_trace *t,
1230 struct per_cpu_info *pci, int rw)
1232 __account_pc_issue(&pci->io_stats, rw, t->bytes);
1234 if (per_process_stats) {
1235 struct io_stats *ios = find_process_io_stats(t->pid);
1237 __account_pc_issue(ios, rw, t->bytes);
1241 static inline void __account_pc_requeue(struct io_stats *ios,
1242 struct blk_io_trace *t, int rw)
1246 ios->iwrite_kb_pc -= t_kb(t);
1249 ios->iread_kb_pc -= t_kb(t);
1253 static inline void account_pc_requeue(struct blk_io_trace *t,
1254 struct per_cpu_info *pci, int rw)
1256 __account_pc_requeue(&pci->io_stats, t, rw);
1258 if (per_process_stats) {
1259 struct io_stats *ios = find_process_io_stats(t->pid);
1261 __account_pc_requeue(ios, t, rw);
1265 static inline void __account_pc_c(struct io_stats *ios, int rw)
1273 static inline void account_pc_c(struct blk_io_trace *t,
1274 struct per_cpu_info *pci, int rw)
1276 __account_pc_c(&pci->io_stats, rw);
1278 if (per_process_stats) {
1279 struct io_stats *ios = find_process_io_stats(t->pid);
1281 __account_pc_c(ios, rw);
1285 static inline void __account_queue(struct io_stats *ios, struct blk_io_trace *t,
1290 ios->qwrite_kb += t_kb(t);
1293 ios->qread_kb += t_kb(t);
1297 static inline void account_queue(struct blk_io_trace *t,
1298 struct per_cpu_info *pci, int rw)
1300 __account_queue(&pci->io_stats, t, rw);
1302 if (per_process_stats) {
1303 struct io_stats *ios = find_process_io_stats(t->pid);
1305 __account_queue(ios, t, rw);
1309 static inline void __account_c(struct io_stats *ios, int rw, int bytes)
1313 ios->cwrite_kb += bytes >> 10;
1316 ios->cread_kb += bytes >> 10;
1320 static inline void account_c(struct blk_io_trace *t, struct per_cpu_info *pci,
1323 __account_c(&pci->io_stats, rw, bytes);
1325 if (per_process_stats) {
1326 struct io_stats *ios = find_process_io_stats(t->pid);
1328 __account_c(ios, rw, bytes);
1332 static inline void __account_issue(struct io_stats *ios, int rw,
1337 ios->iwrite_kb += bytes >> 10;
1340 ios->iread_kb += bytes >> 10;
1344 static inline void account_issue(struct blk_io_trace *t,
1345 struct per_cpu_info *pci, int rw)
1347 __account_issue(&pci->io_stats, rw, t->bytes);
1349 if (per_process_stats) {
1350 struct io_stats *ios = find_process_io_stats(t->pid);
1352 __account_issue(ios, rw, t->bytes);
1356 static inline void __account_unplug(struct io_stats *ios, int timer)
1359 ios->timer_unplugs++;
1364 static inline void account_unplug(struct blk_io_trace *t,
1365 struct per_cpu_info *pci, int timer)
1367 __account_unplug(&pci->io_stats, timer);
1369 if (per_process_stats) {
1370 struct io_stats *ios = find_process_io_stats(t->pid);
1372 __account_unplug(ios, timer);
1376 static inline void __account_requeue(struct io_stats *ios,
1377 struct blk_io_trace *t, int rw)
1381 ios->iwrite_kb -= t_kb(t);
1384 ios->iread_kb -= t_kb(t);
1388 static inline void account_requeue(struct blk_io_trace *t,
1389 struct per_cpu_info *pci, int rw)
1391 __account_requeue(&pci->io_stats, t, rw);
1393 if (per_process_stats) {
1394 struct io_stats *ios = find_process_io_stats(t->pid);
1396 __account_requeue(ios, t, rw);
1400 static void log_complete(struct per_dev_info *pdi, struct per_cpu_info *pci,
1401 struct blk_io_trace *t, char *act)
1403 process_fmt(act, pci, t, log_track_complete(pdi, t), 0, NULL);
1406 static void log_insert(struct per_dev_info *pdi, struct per_cpu_info *pci,
1407 struct blk_io_trace *t, char *act)
1409 process_fmt(act, pci, t, log_track_insert(pdi, t), 0, NULL);
1412 static void log_queue(struct per_cpu_info *pci, struct blk_io_trace *t,
1415 process_fmt(act, pci, t, -1, 0, NULL);
1418 static void log_issue(struct per_dev_info *pdi, struct per_cpu_info *pci,
1419 struct blk_io_trace *t, char *act)
1421 process_fmt(act, pci, t, log_track_issue(pdi, t), 0, NULL);
1424 static void log_merge(struct per_dev_info *pdi, struct per_cpu_info *pci,
1425 struct blk_io_trace *t, char *act)
1428 log_track_frontmerge(pdi, t);
1430 process_fmt(act, pci, t, -1ULL, 0, NULL);
1433 static void log_action(struct per_cpu_info *pci, struct blk_io_trace *t,
1436 process_fmt(act, pci, t, -1ULL, 0, NULL);
1439 static void log_generic(struct per_cpu_info *pci, struct blk_io_trace *t,
1442 process_fmt(act, pci, t, -1ULL, 0, NULL);
1445 static void log_unplug(struct per_cpu_info *pci, struct blk_io_trace *t,
1448 process_fmt(act, pci, t, -1ULL, 0, NULL);
1451 static void log_split(struct per_cpu_info *pci, struct blk_io_trace *t,
1454 process_fmt(act, pci, t, -1ULL, 0, NULL);
1457 static void log_pc(struct per_cpu_info *pci, struct blk_io_trace *t, char *act)
1459 unsigned char *buf = (unsigned char *) t + sizeof(*t);
1461 process_fmt(act, pci, t, -1ULL, t->pdu_len, buf);
1464 static void dump_trace_pc(struct blk_io_trace *t, struct per_dev_info *pdi,
1465 struct per_cpu_info *pci)
1467 int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0;
1468 int act = t->action & 0xffff;
1471 case __BLK_TA_QUEUE:
1472 log_generic(pci, t, "Q");
1473 account_pc_queue(t, pci, w);
1475 case __BLK_TA_GETRQ:
1476 log_generic(pci, t, "G");
1478 case __BLK_TA_SLEEPRQ:
1479 log_generic(pci, t, "S");
1481 case __BLK_TA_REQUEUE:
1483 * can happen if we miss traces, don't let it go
1486 if (pdi->cur_depth[w])
1487 pdi->cur_depth[w]--;
1488 account_pc_requeue(t, pci, w);
1489 log_generic(pci, t, "R");
1491 case __BLK_TA_ISSUE:
1492 account_pc_issue(t, pci, w);
1493 pdi->cur_depth[w]++;
1494 if (pdi->cur_depth[w] > pdi->max_depth[w])
1495 pdi->max_depth[w] = pdi->cur_depth[w];
1496 log_pc(pci, t, "D");
1498 case __BLK_TA_COMPLETE:
1499 if (pdi->cur_depth[w])
1500 pdi->cur_depth[w]--;
1501 log_pc(pci, t, "C");
1502 account_pc_c(t, pci, w);
1504 case __BLK_TA_INSERT:
1505 log_pc(pci, t, "I");
1508 fprintf(stderr, "Bad pc action %x\n", act);
1513 static void dump_trace_fs(struct blk_io_trace *t, struct per_dev_info *pdi,
1514 struct per_cpu_info *pci)
1516 int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0;
1517 int act = t->action & 0xffff;
1520 case __BLK_TA_QUEUE:
1521 log_track_queue(pdi, t);
1522 account_queue(t, pci, w);
1523 log_queue(pci, t, "Q");
1525 case __BLK_TA_INSERT:
1526 log_insert(pdi, pci, t, "I");
1528 case __BLK_TA_BACKMERGE:
1529 account_m(t, pci, w);
1530 log_merge(pdi, pci, t, "M");
1532 case __BLK_TA_FRONTMERGE:
1533 account_m(t, pci, w);
1534 log_merge(pdi, pci, t, "F");
1536 case __BLK_TA_GETRQ:
1537 log_track_getrq(pdi, t);
1538 log_generic(pci, t, "G");
1540 case __BLK_TA_SLEEPRQ:
1541 log_generic(pci, t, "S");
1543 case __BLK_TA_REQUEUE:
1545 * can happen if we miss traces, don't let it go
1548 if (pdi->cur_depth[w])
1549 pdi->cur_depth[w]--;
1550 account_requeue(t, pci, w);
1551 log_queue(pci, t, "R");
1553 case __BLK_TA_ISSUE:
1554 account_issue(t, pci, w);
1555 pdi->cur_depth[w]++;
1556 if (pdi->cur_depth[w] > pdi->max_depth[w])
1557 pdi->max_depth[w] = pdi->cur_depth[w];
1558 log_issue(pdi, pci, t, "D");
1560 case __BLK_TA_COMPLETE:
1561 if (pdi->cur_depth[w])
1562 pdi->cur_depth[w]--;
1563 account_c(t, pci, w, t->bytes);
1564 log_complete(pdi, pci, t, "C");
1567 log_action(pci, t, "P");
1569 case __BLK_TA_UNPLUG_IO:
1570 account_unplug(t, pci, 0);
1571 log_unplug(pci, t, "U");
1573 case __BLK_TA_UNPLUG_TIMER:
1574 account_unplug(t, pci, 1);
1575 log_unplug(pci, t, "UT");
1577 case __BLK_TA_SPLIT:
1578 log_split(pci, t, "X");
1580 case __BLK_TA_BOUNCE:
1581 log_generic(pci, t, "B");
1583 case __BLK_TA_REMAP:
1584 log_generic(pci, t, "A");
1587 fprintf(stderr, "Bad fs action %x\n", t->action);
1592 static void dump_trace(struct blk_io_trace *t, struct per_cpu_info *pci,
1593 struct per_dev_info *pdi)
1596 if (t->action == BLK_TN_MESSAGE)
1598 else if (t->action & BLK_TC_ACT(BLK_TC_PC))
1599 dump_trace_pc(t, pdi, pci);
1601 dump_trace_fs(t, pdi, pci);
1605 pdi->first_reported_time = t->time;
1609 output_binary(t, sizeof(*t) + t->pdu_len);
1613 * print in a proper way, not too small and not too big. if more than
1614 * 1000,000K, turn into M and so on
1616 static char *size_cnv(char *dst, unsigned long long num, int in_kb)
1618 char suff[] = { '\0', 'K', 'M', 'G', 'P' };
1624 while (num > 1000 * 1000ULL && (i < sizeof(suff) - 1)) {
1629 sprintf(dst, "%'8Lu%c", num, suff[i]);
1633 static void dump_io_stats(struct per_dev_info *pdi, struct io_stats *ios,
1636 static char x[256], y[256];
1638 fprintf(ofp, "%s\n", msg);
1640 fprintf(ofp, " Reads Queued: %s, %siB\t", size_cnv(x, ios->qreads, 0), size_cnv(y, ios->qread_kb, 1));
1641 fprintf(ofp, " Writes Queued: %s, %siB\n", size_cnv(x, ios->qwrites, 0), size_cnv(y, ios->qwrite_kb, 1));
1642 fprintf(ofp, " Read Dispatches: %s, %siB\t", size_cnv(x, ios->ireads, 0), size_cnv(y, ios->iread_kb, 1));
1643 fprintf(ofp, " Write Dispatches: %s, %siB\n", size_cnv(x, ios->iwrites, 0), size_cnv(y, ios->iwrite_kb, 1));
1644 fprintf(ofp, " Reads Requeued: %s\t\t", size_cnv(x, ios->rrqueue, 0));
1645 fprintf(ofp, " Writes Requeued: %s\n", size_cnv(x, ios->wrqueue, 0));
1646 fprintf(ofp, " Reads Completed: %s, %siB\t", size_cnv(x, ios->creads, 0), size_cnv(y, ios->cread_kb, 1));
1647 fprintf(ofp, " Writes Completed: %s, %siB\n", size_cnv(x, ios->cwrites, 0), size_cnv(y, ios->cwrite_kb, 1));
1648 fprintf(ofp, " Read Merges: %s, %siB\t", size_cnv(x, ios->mreads, 0), size_cnv(y, ios->mread_kb, 1));
1649 fprintf(ofp, " Write Merges: %s, %siB\n", size_cnv(x, ios->mwrites, 0), size_cnv(y, ios->mwrite_kb, 1));
1651 fprintf(ofp, " Read depth: %'8u%8c\t", pdi->max_depth[0], ' ');
1652 fprintf(ofp, " Write depth: %'8u\n", pdi->max_depth[1]);
1654 if (ios->qreads_pc || ios->qwrites_pc || ios->ireads_pc || ios->iwrites_pc ||
1655 ios->rrqueue_pc || ios->wrqueue_pc || ios->creads_pc || ios->cwrites_pc) {
1656 fprintf(ofp, " PC Reads Queued: %s, %siB\t", size_cnv(x, ios->qreads_pc, 0), size_cnv(y, ios->qread_kb_pc, 1));
1657 fprintf(ofp, " PC Writes Queued: %s, %siB\n", size_cnv(x, ios->qwrites_pc, 0), size_cnv(y, ios->qwrite_kb_pc, 1));
1658 fprintf(ofp, " PC Read Disp.: %s, %siB\t", size_cnv(x, ios->ireads_pc, 0), size_cnv(y, ios->iread_kb_pc, 1));
1659 fprintf(ofp, " PC Write Disp.: %s, %siB\n", size_cnv(x, ios->iwrites_pc, 0), size_cnv(y, ios->iwrite_kb_pc, 1));
1660 fprintf(ofp, " PC Reads Req.: %s\t\t", size_cnv(x, ios->rrqueue_pc, 0));
1661 fprintf(ofp, " PC Writes Req.: %s\n", size_cnv(x, ios->wrqueue_pc, 0));
1662 fprintf(ofp, " PC Reads Compl.: %s\t\t", size_cnv(x, ios->creads_pc, 0));
1663 fprintf(ofp, " PC Writes Compl.: %s\n", size_cnv(x, ios->cwrites, 0));
1665 fprintf(ofp, " IO unplugs: %'8lu%8c\t", ios->io_unplugs, ' ');
1666 fprintf(ofp, " Timer unplugs: %'8lu\n", ios->timer_unplugs);
1669 static void dump_wait_stats(struct per_process_info *ppi)
1671 unsigned long rawait = ppi->longest_allocation_wait[0] / 1000;
1672 unsigned long rdwait = ppi->longest_dispatch_wait[0] / 1000;
1673 unsigned long rcwait = ppi->longest_completion_wait[0] / 1000;
1674 unsigned long wawait = ppi->longest_allocation_wait[1] / 1000;
1675 unsigned long wdwait = ppi->longest_dispatch_wait[1] / 1000;
1676 unsigned long wcwait = ppi->longest_completion_wait[1] / 1000;
1678 fprintf(ofp, " Allocation wait: %'8lu%8c\t", rawait, ' ');
1679 fprintf(ofp, " Allocation wait: %'8lu\n", wawait);
1680 fprintf(ofp, " Dispatch wait: %'8lu%8c\t", rdwait, ' ');
1681 fprintf(ofp, " Dispatch wait: %'8lu\n", wdwait);
1682 fprintf(ofp, " Completion wait: %'8lu%8c\t", rcwait, ' ');
1683 fprintf(ofp, " Completion wait: %'8lu\n", wcwait);
1686 static int ppi_name_compare(const void *p1, const void *p2)
1688 struct per_process_info *ppi1 = *((struct per_process_info **) p1);
1689 struct per_process_info *ppi2 = *((struct per_process_info **) p2);
1692 res = strverscmp(ppi1->ppm->comm, ppi2->ppm->comm);
1694 res = ppi1->ppm->pid > ppi2->ppm->pid;
1699 static void sort_process_list(void)
1701 struct per_process_info **ppis;
1702 struct per_process_info *ppi;
1705 ppis = malloc(ppi_list_entries * sizeof(struct per_process_info *));
1710 ppi = ppi->list_next;
1713 qsort(ppis, ppi_list_entries, sizeof(ppi), ppi_name_compare);
1715 i = ppi_list_entries - 1;
1720 ppi->list_next = ppi_list;
1728 static void show_process_stats(void)
1730 struct per_process_info *ppi;
1732 sort_process_list();
1736 struct process_pid_map *ppm = ppi->ppm;
1739 if (ppi->more_than_one)
1740 sprintf(name, "%s (%u, ...)", ppm->comm, ppm->pid);
1742 sprintf(name, "%s (%u)", ppm->comm, ppm->pid);
1744 dump_io_stats(NULL, &ppi->io_stats, name);
1745 dump_wait_stats(ppi);
1746 ppi = ppi->list_next;
1752 static void show_device_and_cpu_stats(void)
1754 struct per_dev_info *pdi;
1755 struct per_cpu_info *pci;
1756 struct io_stats total, *ios;
1757 unsigned long long rrate, wrate, msec;
1758 int i, j, pci_events;
1759 char line[3 + 8/*cpu*/ + 2 + 32/*dev*/ + 3];
1763 for (pdi = devices, i = 0; i < ndevices; i++, pdi++) {
1765 memset(&total, 0, sizeof(total));
1771 for (pci = pdi->cpus, j = 0; j < pdi->ncpus; j++, pci++) {
1775 ios = &pci->io_stats;
1776 total.qreads += ios->qreads;
1777 total.qwrites += ios->qwrites;
1778 total.creads += ios->creads;
1779 total.cwrites += ios->cwrites;
1780 total.mreads += ios->mreads;
1781 total.mwrites += ios->mwrites;
1782 total.ireads += ios->ireads;
1783 total.iwrites += ios->iwrites;
1784 total.rrqueue += ios->rrqueue;
1785 total.wrqueue += ios->wrqueue;
1786 total.qread_kb += ios->qread_kb;
1787 total.qwrite_kb += ios->qwrite_kb;
1788 total.cread_kb += ios->cread_kb;
1789 total.cwrite_kb += ios->cwrite_kb;
1790 total.iread_kb += ios->iread_kb;
1791 total.iwrite_kb += ios->iwrite_kb;
1792 total.mread_kb += ios->mread_kb;
1793 total.mwrite_kb += ios->mwrite_kb;
1795 total.qreads_pc += ios->qreads_pc;
1796 total.qwrites_pc += ios->qwrites_pc;
1797 total.creads_pc += ios->creads_pc;
1798 total.cwrites_pc += ios->cwrites_pc;
1799 total.ireads_pc += ios->ireads_pc;
1800 total.iwrites_pc += ios->iwrites_pc;
1801 total.rrqueue_pc += ios->rrqueue_pc;
1802 total.wrqueue_pc += ios->wrqueue_pc;
1803 total.qread_kb_pc += ios->qread_kb_pc;
1804 total.qwrite_kb_pc += ios->qwrite_kb_pc;
1805 total.iread_kb_pc += ios->iread_kb_pc;
1806 total.iwrite_kb_pc += ios->iwrite_kb_pc;
1808 total.timer_unplugs += ios->timer_unplugs;
1809 total.io_unplugs += ios->io_unplugs;
1811 snprintf(line, sizeof(line) - 1, "CPU%d (%s):",
1812 j, get_dev_name(pdi, name, sizeof(name)));
1813 dump_io_stats(pdi, ios, line);
1817 if (pci_events > 1) {
1819 snprintf(line, sizeof(line) - 1, "Total (%s):",
1820 get_dev_name(pdi, name, sizeof(name)));
1821 dump_io_stats(NULL, &total, line);
1825 msec = (pdi->last_reported_time - pdi->first_reported_time) / 1000000;
1827 rrate = 1000 * total.cread_kb / msec;
1828 wrate = 1000 * total.cwrite_kb / msec;
1831 fprintf(ofp, "\nThroughput (R/W): %'LuKiB/s / %'LuKiB/s\n",
1833 fprintf(ofp, "Events (%s): %'Lu entries\n",
1834 get_dev_name(pdi, line, sizeof(line)), pdi->events);
1836 collect_pdi_skips(pdi);
1837 if (!pdi->skips && !pdi->events)
1840 ratio = 100.0 * ((double)pdi->seq_skips /
1841 (double)(pdi->events + pdi->seq_skips));
1842 fprintf(ofp, "Skips: %'lu forward (%'llu - %5.1lf%%)\n",
1843 pdi->skips, pdi->seq_skips, ratio);
1847 static void find_genesis(void)
1849 struct trace *t = trace_list;
1851 genesis_time = -1ULL;
1853 if (t->bit->time < genesis_time)
1854 genesis_time = t->bit->time;
1859 /* The time stamp record will usually be the first
1860 * record in the trace, but not always.
1863 && start_timestamp != genesis_time) {
1864 long delta = genesis_time - start_timestamp;
1866 abs_start_time.tv_sec += SECONDS(delta);
1867 abs_start_time.tv_nsec += NANO_SECONDS(delta);
1868 if (abs_start_time.tv_nsec < 0) {
1869 abs_start_time.tv_nsec += 1000000000;
1870 abs_start_time.tv_sec -= 1;
1872 if (abs_start_time.tv_nsec > 1000000000) {
1873 abs_start_time.tv_nsec -= 1000000000;
1874 abs_start_time.tv_sec += 1;
1879 static inline int check_stopwatch(struct blk_io_trace *bit)
1881 if (bit->time < stopwatch_end &&
1882 bit->time >= stopwatch_start)
1889 * return youngest entry read
1891 static int sort_entries(unsigned long long *youngest)
1893 struct per_dev_info *pdi = NULL;
1894 struct per_cpu_info *pci = NULL;
1901 while ((t = trace_list) != NULL) {
1902 struct blk_io_trace *bit = t->bit;
1904 trace_list = t->next;
1906 bit->time -= genesis_time;
1908 if (bit->time < *youngest || !*youngest)
1909 *youngest = bit->time;
1911 if (!pdi || pdi->dev != bit->device) {
1912 pdi = get_dev_info(bit->device);
1916 if (!pci || pci->cpu != bit->cpu)
1917 pci = get_cpu_info(pdi, bit->cpu);
1919 if (bit->sequence < pci->smallest_seq_read)
1920 pci->smallest_seq_read = bit->sequence;
1922 if (check_stopwatch(bit)) {
1928 if (trace_rb_insert_sort(t))
1936 * to continue, we must have traces from all online cpus in the tree
1938 static int check_cpu_map(struct per_dev_info *pdi)
1940 unsigned long *cpu_map;
1947 * create a map of the cpus we have traces for
1949 cpu_map = malloc(pdi->cpu_map_max / sizeof(long));
1950 n = rb_first(&rb_sort_root);
1952 __t = rb_entry(n, struct trace, rb_node);
1953 cpu = __t->bit->cpu;
1955 cpu_map[CPU_IDX(cpu)] |= (1UL << CPU_BIT(cpu));
1960 * we can't continue if pdi->cpu_map has entries set that we don't
1961 * have in the sort rbtree. the opposite is not a problem, though
1964 for (i = 0; i < pdi->cpu_map_max / CPUS_PER_LONG; i++) {
1965 if (pdi->cpu_map[i] & ~(cpu_map[i])) {
1975 static int check_sequence(struct per_dev_info *pdi, struct trace *t, int force)
1977 struct blk_io_trace *bit = t->bit;
1978 unsigned long expected_sequence;
1979 struct per_cpu_info *pci;
1982 pci = get_cpu_info(pdi, bit->cpu);
1983 expected_sequence = pci->last_sequence + 1;
1985 if (!expected_sequence) {
1987 * 1 should be the first entry, just allow it
1989 if (bit->sequence == 1)
1991 if (bit->sequence == pci->smallest_seq_read)
1994 return check_cpu_map(pdi);
1997 if (bit->sequence == expected_sequence)
2001 * we may not have seen that sequence yet. if we are not doing
2002 * the final run, break and wait for more entries.
2004 if (expected_sequence < pci->smallest_seq_read) {
2005 __t = trace_rb_find_last(pdi, pci, expected_sequence);
2009 __put_trace_last(pdi, __t);
2011 } else if (!force) {
2015 if (check_current_skips(pci, bit->sequence))
2018 if (expected_sequence < bit->sequence)
2019 insert_skip(pci, expected_sequence, bit->sequence - 1);
2024 static void show_entries_rb(int force)
2026 struct per_dev_info *pdi = NULL;
2027 struct per_cpu_info *pci = NULL;
2028 struct blk_io_trace *bit;
2032 while ((n = rb_first(&rb_sort_root)) != NULL) {
2033 if (is_done() && !force && !pipeline)
2036 t = rb_entry(n, struct trace, rb_node);
2039 if (read_sequence - t->read_sequence < 1 && !force)
2042 if (!pdi || pdi->dev != bit->device) {
2043 pdi = get_dev_info(bit->device);
2048 fprintf(stderr, "Unknown device ID? (%d,%d)\n",
2049 MAJOR(bit->device), MINOR(bit->device));
2053 if (check_sequence(pdi, t, force))
2056 if (!force && bit->time > last_allowed_time)
2059 check_time(pdi, bit);
2061 if (!pci || pci->cpu != bit->cpu)
2062 pci = get_cpu_info(pdi, bit->cpu);
2064 pci->last_sequence = bit->sequence;
2068 if (bit->action & (act_mask << BLK_TC_SHIFT))
2069 dump_trace(bit, pci, pdi);
2075 static int read_data(int fd, void *buffer, int bytes, int block, int *fdblock)
2077 int ret, bytes_left, fl;
2080 if (block != *fdblock) {
2081 fl = fcntl(fd, F_GETFL);
2085 fcntl(fd, F_SETFL, fl | O_NONBLOCK);
2088 fcntl(fd, F_SETFL, fl & ~O_NONBLOCK);
2094 while (bytes_left > 0) {
2095 ret = read(fd, p, bytes_left);
2099 if (errno != EAGAIN) {
2105 * never do partial reads. we can return if we
2106 * didn't read anything and we should not block,
2107 * otherwise wait for data
2109 if ((bytes_left == bytes) && !block)
2123 static inline __u16 get_pdulen(struct blk_io_trace *bit)
2126 return bit->pdu_len;
2128 return __bswap_16(bit->pdu_len);
2131 static inline __u32 get_magic(struct blk_io_trace *bit)
2136 return __bswap_32(bit->magic);
2139 static int read_events(int fd, int always_block, int *fdblock)
2141 struct per_dev_info *pdi = NULL;
2142 unsigned int events = 0;
2144 while (!is_done() && events < rb_batch) {
2145 struct blk_io_trace *bit;
2147 int pdu_len, should_block, ret;
2152 should_block = !events || always_block;
2154 ret = read_data(fd, bit, sizeof(*bit), should_block, fdblock);
2157 if (!events && ret < 0)
2163 * look at first trace to check whether we need to convert
2164 * data in the future
2166 if (data_is_native == -1 && check_data_endianness(bit->magic))
2169 magic = get_magic(bit);
2170 if ((magic & 0xffffff00) != BLK_IO_TRACE_MAGIC) {
2171 fprintf(stderr, "Bad magic %x\n", magic);
2175 pdu_len = get_pdulen(bit);
2177 void *ptr = realloc(bit, sizeof(*bit) + pdu_len);
2179 if (read_data(fd, ptr + sizeof(*bit), pdu_len, 1, fdblock)) {
2189 if (verify_trace(bit)) {
2195 * not a real trace, so grab and handle it here
2197 if (bit->action & BLK_TC_ACT(BLK_TC_NOTIFY) && bit->action != BLK_TN_MESSAGE) {
2199 output_binary(bit, sizeof(*bit) + bit->pdu_len);
2204 memset(t, 0, sizeof(*t));
2206 t->read_sequence = read_sequence;
2208 t->next = trace_list;
2211 if (!pdi || pdi->dev != bit->device)
2212 pdi = get_dev_info(bit->device);
2214 if (bit->time > pdi->last_read_time)
2215 pdi->last_read_time = bit->time;
2224 * Managing input streams
2228 struct ms_stream *next;
2229 struct trace *first, *last;
2230 struct per_dev_info *pdi;
2234 #define MS_HASH(d, c) ((MAJOR(d) & 0xff) ^ (MINOR(d) & 0xff) ^ (cpu & 0xff))
2236 struct ms_stream *ms_head;
2237 struct ms_stream *ms_hash[256];
2239 static void ms_sort(struct ms_stream *msp);
2240 static int ms_prime(struct ms_stream *msp);
2242 static inline struct trace *ms_peek(struct ms_stream *msp)
2244 return (msp == NULL) ? NULL : msp->first;
2247 static inline __u64 ms_peek_time(struct ms_stream *msp)
2249 return ms_peek(msp)->bit->time;
2252 static inline void ms_resort(struct ms_stream *msp)
2254 if (msp->next && ms_peek_time(msp) > ms_peek_time(msp->next)) {
2255 ms_head = msp->next;
2261 static inline void ms_deq(struct ms_stream *msp)
2263 msp->first = msp->first->next;
2266 if (!ms_prime(msp)) {
2267 ms_head = msp->next;
2276 static void ms_sort(struct ms_stream *msp)
2278 __u64 msp_t = ms_peek_time(msp);
2279 struct ms_stream *this_msp = ms_head;
2281 if (this_msp == NULL)
2283 else if (msp_t < ms_peek_time(this_msp)) {
2284 msp->next = this_msp;
2288 while (this_msp->next && ms_peek_time(this_msp->next) < msp_t)
2289 this_msp = this_msp->next;
2291 msp->next = this_msp->next;
2292 this_msp->next = msp;
2296 static int ms_prime(struct ms_stream *msp)
2301 struct per_dev_info *pdi = msp->pdi;
2302 struct per_cpu_info *pci = get_cpu_info(pdi, msp->cpu);
2303 struct blk_io_trace *bit = NULL;
2304 int ret, pdu_len, ndone = 0;
2306 for (i = 0; !is_done() && pci->fd >= 0 && i < rb_batch; i++) {
2308 ret = read_data(pci->fd, bit, sizeof(*bit), 1, &pci->fdblock);
2312 if (data_is_native == -1 && check_data_endianness(bit->magic))
2315 magic = get_magic(bit);
2316 if ((magic & 0xffffff00) != BLK_IO_TRACE_MAGIC) {
2317 fprintf(stderr, "Bad magic %x\n", magic);
2322 pdu_len = get_pdulen(bit);
2324 void *ptr = realloc(bit, sizeof(*bit) + pdu_len);
2325 ret = read_data(pci->fd, ptr + sizeof(*bit), pdu_len,
2337 if (verify_trace(bit))
2340 if (bit->action & BLK_TC_ACT(BLK_TC_NOTIFY) && bit->action != BLK_TN_MESSAGE) {
2342 output_binary(bit, sizeof(*bit) + bit->pdu_len);
2349 if (bit->time > pdi->last_read_time)
2350 pdi->last_read_time = bit->time;
2353 memset(t, 0, sizeof(*t));
2356 if (msp->first == NULL)
2357 msp->first = msp->last = t;
2359 msp->last->next = t;
2369 if (bit) bit_free(bit);
2371 cpu_mark_offline(pdi, pci->cpu);
2378 static struct ms_stream *ms_alloc(struct per_dev_info *pdi, int cpu)
2380 struct ms_stream *msp = malloc(sizeof(*msp));
2383 msp->first = msp->last = NULL;
2393 static int setup_file(struct per_dev_info *pdi, int cpu)
2398 struct per_cpu_info *pci = get_cpu_info(pdi, cpu);
2403 p = strdup(pdi->name);
2405 if (strcmp(dname, ".")) {
2407 p = strdup(pdi->name);
2408 strcpy(pdi->name, basename(p));
2413 len = sprintf(pci->fname, "%s/", input_dir);
2415 snprintf(pci->fname + len, sizeof(pci->fname)-1-len,
2416 "%s.blktrace.%d", pdi->name, pci->cpu);
2417 if (stat(pci->fname, &st) < 0)
2422 pci->fd = open(pci->fname, O_RDONLY);
2428 printf("Input file %s added\n", pci->fname);
2429 cpu_mark_online(pdi, pci->cpu);
2432 ms_alloc(pdi, pci->cpu);
2437 static int handle(struct ms_stream *msp)
2440 struct per_dev_info *pdi;
2441 struct per_cpu_info *pci;
2442 struct blk_io_trace *bit;
2448 pci = get_cpu_info(pdi, msp->cpu);
2450 bit->time -= genesis_time;
2452 if (t->bit->time > stopwatch_end)
2455 pdi->last_reported_time = bit->time;
2456 if ((bit->action & (act_mask << BLK_TC_SHIFT))&&
2457 t->bit->time >= stopwatch_start)
2458 dump_trace(bit, pci, pdi);
2463 trace_rb_insert_last(pdi, t);
2473 * Check if we need to sanitize the name. We allow 'foo', or if foo.blktrace.X
2474 * is given, then strip back down to 'foo' to avoid missing files.
2476 static int name_fixup(char *name)
2483 b = strstr(name, ".blktrace.");
2490 static int do_file(void)
2493 struct per_dev_info *pdi;
2496 * first prepare all files for reading
2498 for (i = 0; i < ndevices; i++) {
2500 ret = name_fixup(pdi->name);
2504 for (cpu = 0; setup_file(pdi, cpu); cpu++)
2509 * Get the initial time stamp
2512 genesis_time = ms_peek_time(ms_head);
2515 * Keep processing traces while any are left
2517 while (!is_done() && ms_head && handle(ms_head))
2523 static void do_pipe(int fd)
2525 unsigned long long youngest;
2526 int events, fdblock;
2528 last_allowed_time = -1ULL;
2530 while ((events = read_events(fd, 0, &fdblock)) > 0) {
2534 smallest_seq_read = -1U;
2537 if (sort_entries(&youngest))
2540 if (youngest > stopwatch_end)
2546 if (rb_sort_entries)
2550 static int do_fifo(void)
2554 if (!strcmp(pipename, "-"))
2555 fd = dup(STDIN_FILENO);
2557 fd = open(pipename, O_RDONLY);
2560 perror("dup stdin");
2569 static void show_stats(void)
2578 if (per_process_stats)
2579 show_process_stats();
2581 if (per_device_and_cpu_stats)
2582 show_device_and_cpu_stats();
2587 static void handle_sigint(__attribute__((__unused__)) int sig)
2593 * Extract start and duration times from a string, allowing
2594 * us to specify a time interval of interest within a trace.
2595 * Format: "duration" (start is zero) or "start:duration".
2597 static int find_stopwatch_interval(char *string)
2602 value = strtod(string, &sp);
2604 fprintf(stderr,"Invalid stopwatch timer: %s\n", string);
2608 stopwatch_start = DOUBLE_TO_NANO_ULL(value);
2610 value = strtod(string, &sp);
2611 if (sp == string || *sp != '\0') {
2612 fprintf(stderr,"Invalid stopwatch duration time: %s\n",
2616 } else if (*sp != '\0') {
2617 fprintf(stderr,"Invalid stopwatch start timer: %s\n", string);
2620 stopwatch_end = DOUBLE_TO_NANO_ULL(value);
2621 if (stopwatch_end <= stopwatch_start) {
2622 fprintf(stderr, "Invalid stopwatch interval: %Lu -> %Lu\n",
2623 stopwatch_start, stopwatch_end);
2630 static int is_pipe(const char *str)
2634 if (!strcmp(str, "-"))
2636 if (!stat(str, &st) && S_ISFIFO(st.st_mode))
2642 #define S_OPTS "a:A:b:D:d:f:F:hi:o:Oqstw:vV"
2643 static char usage_str[] = "\n\n" \
2644 "-i <file> | --input=<file>\n" \
2645 "[ -a <action field> | --act-mask=<action field> ]\n" \
2646 "[ -A <action mask> | --set-mask=<action mask> ]\n" \
2647 "[ -b <traces> | --batch=<traces> ]\n" \
2648 "[ -d <file> | --dump-binary=<file> ]\n" \
2649 "[ -D <dir> | --input-directory=<dir> ]\n" \
2650 "[ -f <format> | --format=<format> ]\n" \
2651 "[ -F <spec> | --format-spec=<spec> ]\n" \
2652 "[ -h | --hash-by-name ]\n" \
2653 "[ -o <file> | --output=<file> ]\n" \
2654 "[ -O | --no-text-output ]\n" \
2655 "[ -q | --quiet ]\n" \
2656 "[ -s | --per-program-stats ]\n" \
2657 "[ -t | --track-ios ]\n" \
2658 "[ -w <time> | --stopwatch=<time> ]\n" \
2659 "[ -v | --verbose ]\n" \
2660 "[ -V | --version ]\n\n" \
2661 "\t-b stdin read batching\n" \
2662 "\t-d Output file. If specified, binary data is written to file\n" \
2663 "\t-D Directory to prepend to input file names\n" \
2664 "\t-f Output format. Customize the output format. The format field\n" \
2665 "\t identifies can be found in the documentation\n" \
2666 "\t-F Format specification. Can be found in the documentation\n" \
2667 "\t-h Hash processes by name, not pid\n" \
2668 "\t-i Input file containing trace data, or '-' for stdin\n" \
2669 "\t-o Output file. If not given, output is stdout\n" \
2670 "\t-O Do NOT output text data\n" \
2671 "\t-q Quiet. Don't display any stats at the end of the trace\n" \
2672 "\t-s Show per-program io statistics\n" \
2673 "\t-t Track individual ios. Will tell you the time a request took\n" \
2674 "\t to get queued, to get dispatched, and to get completed\n" \
2675 "\t-w Only parse data between the given time interval in seconds.\n" \
2676 "\t If 'start' isn't given, blkparse defaults the start time to 0\n" \
2677 "\t-v More verbose for marginal errors\n" \
2678 "\t-V Print program version info\n\n";
2680 static void usage(char *prog)
2682 fprintf(stderr, "Usage: %s %s %s", prog, blkparse_version, usage_str);
2685 int main(int argc, char *argv[])
2687 int i, c, ret, mode;
2688 int act_mask_tmp = 0;
2689 char *ofp_buffer = NULL;
2690 char *bin_ofp_buffer = NULL;
2692 while ((c = getopt_long(argc, argv, S_OPTS, l_opts, NULL)) != -1) {
2695 i = find_mask_map(optarg);
2697 fprintf(stderr,"Invalid action mask %s\n",
2705 if ((sscanf(optarg, "%x", &i) != 1) ||
2706 !valid_act_opt(i)) {
2708 "Invalid set action mask %s/0x%x\n",
2715 if (is_pipe(optarg) && !pipeline) {
2717 pipename = strdup(optarg);
2718 } else if (resize_devices(optarg) != 0)
2725 output_name = optarg;
2731 rb_batch = atoi(optarg);
2733 rb_batch = RB_BATCH_DEFAULT;
2736 per_process_stats = 1;
2742 per_device_and_cpu_stats = 0;
2745 if (find_stopwatch_interval(optarg) != 0)
2749 set_all_format_specs(optarg);
2752 if (add_format_spec(optarg) != 0)
2756 ppi_hash_by_pid = 0;
2762 printf("%s version %s\n", argv[0], blkparse_version);
2765 dump_binary = optarg;
2773 while (optind < argc) {
2774 if (is_pipe(argv[optind]) && !pipeline) {
2776 pipename = strdup(argv[optind]);
2777 } else if (resize_devices(argv[optind]) != 0)
2782 if (!pipeline && !ndevices) {
2787 if (act_mask_tmp != 0)
2788 act_mask = act_mask_tmp;
2790 memset(&rb_sort_root, 0, sizeof(rb_sort_root));
2792 signal(SIGINT, handle_sigint);
2793 signal(SIGHUP, handle_sigint);
2794 signal(SIGTERM, handle_sigint);
2796 setlocale(LC_NUMERIC, "en_US");
2800 ofp = fdopen(STDOUT_FILENO, "w");
2805 snprintf(ofname, sizeof(ofname) - 1, "%s", output_name);
2806 ofp = fopen(ofname, "w");
2815 ofp_buffer = malloc(4096);
2816 if (setvbuf(ofp, ofp_buffer, mode, 4096)) {
2823 dump_fp = fopen(dump_binary, "w");
2825 perror(dump_binary);
2829 bin_ofp_buffer = malloc(128 * 1024);
2830 if (setvbuf(dump_fp, bin_ofp_buffer, _IOFBF, 128 * 1024)) {
2831 perror("setvbuf binary");
2848 if (bin_ofp_buffer) {
2850 free(bin_ofp_buffer);