iowatcher: Fix io line graphs at the edge of the X axis
[blktrace.git] / iowatcher / blkparse.c
1 /*
2  * Copyright (C) 2012 Fusion-io
3  *
4  *  This program is free software; you can redistribute it and/or
5  *  modify it under the terms of the GNU General Public
6  *  License v2 as published by the Free Software Foundation.
7  *
8  *  This program is distributed in the hope that it will be useful,
9  *  but WITHOUT ANY WARRANTY; without even the implied warranty of
10  *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
11  *  GNU General Public License for more details.
12  *
13  *  You should have received a copy of the GNU General Public License
14  *  along with this program; if not, write to the Free Software
15  *  Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
16  *
17  *  Parts of this file were imported from Jens Axboe's blktrace sources (also GPL)
18  */
19 #include <sys/types.h>
20 #include <sys/stat.h>
21 #include <fcntl.h>
22 #include <unistd.h>
23 #include <stdlib.h>
24 #include <stdio.h>
25 #include <math.h>
26 #include <inttypes.h>
27 #include <string.h>
28 #include <asm/types.h>
29 #include <errno.h>
30 #include <sys/mman.h>
31 #include <time.h>
32 #include <math.h>
33
34 #include "plot.h"
35 #include "blkparse.h"
36 #include "list.h"
37 #include "tracers.h"
38
39 #define IO_HASH_TABLE_BITS  11
40 #define IO_HASH_TABLE_SIZE (1 << IO_HASH_TABLE_BITS)
41 static struct list_head io_hash_table[IO_HASH_TABLE_SIZE];
42 static u64 ios_in_flight = 0;
43
44
45 /*
46  * Trace categories
47  */
48 enum {
49         BLK_TC_READ     = 1 << 0,       /* reads */
50         BLK_TC_WRITE    = 1 << 1,       /* writes */
51         BLK_TC_FLUSH    = 1 << 2,       /* flush */
52         BLK_TC_SYNC     = 1 << 3,       /* sync */
53         BLK_TC_QUEUE    = 1 << 4,       /* queueing/merging */
54         BLK_TC_REQUEUE  = 1 << 5,       /* requeueing */
55         BLK_TC_ISSUE    = 1 << 6,       /* issue */
56         BLK_TC_COMPLETE = 1 << 7,       /* completions */
57         BLK_TC_FS       = 1 << 8,       /* fs requests */
58         BLK_TC_PC       = 1 << 9,       /* pc requests */
59         BLK_TC_NOTIFY   = 1 << 10,      /* special message */
60         BLK_TC_AHEAD    = 1 << 11,      /* readahead */
61         BLK_TC_META     = 1 << 12,      /* metadata */
62         BLK_TC_DISCARD  = 1 << 13,      /* discard requests */
63         BLK_TC_DRV_DATA = 1 << 14,      /* binary driver data */
64         BLK_TC_FUA      = 1 << 15,      /* fua requests */
65
66         BLK_TC_END      = 1 << 15,      /* we've run out of bits! */
67 };
68
69 #define BLK_TC_SHIFT            (16)
70 #define BLK_TC_ACT(act)         ((act) << BLK_TC_SHIFT)
71 #define BLK_DATADIR(a) (((a) >> BLK_TC_SHIFT) & (BLK_TC_READ | BLK_TC_WRITE))
72
73 /*
74  * Basic trace actions
75  */
76 enum {
77         __BLK_TA_QUEUE = 1,             /* queued */
78         __BLK_TA_BACKMERGE,             /* back merged to existing rq */
79         __BLK_TA_FRONTMERGE,            /* front merge to existing rq */
80         __BLK_TA_GETRQ,                 /* allocated new request */
81         __BLK_TA_SLEEPRQ,               /* sleeping on rq allocation */
82         __BLK_TA_REQUEUE,               /* request requeued */
83         __BLK_TA_ISSUE,                 /* sent to driver */
84         __BLK_TA_COMPLETE,              /* completed by driver */
85         __BLK_TA_PLUG,                  /* queue was plugged */
86         __BLK_TA_UNPLUG_IO,             /* queue was unplugged by io */
87         __BLK_TA_UNPLUG_TIMER,          /* queue was unplugged by timer */
88         __BLK_TA_INSERT,                /* insert request */
89         __BLK_TA_SPLIT,                 /* bio was split */
90         __BLK_TA_BOUNCE,                /* bio was bounced */
91         __BLK_TA_REMAP,                 /* bio was remapped */
92         __BLK_TA_ABORT,                 /* request aborted */
93         __BLK_TA_DRV_DATA,              /* binary driver data */
94 };
95
96 /*
97  * Notify events.
98  */
99 enum blktrace_notify {
100         __BLK_TN_PROCESS = 0,           /* establish pid/name mapping */
101         __BLK_TN_TIMESTAMP,             /* include system clock */
102         __BLK_TN_MESSAGE,               /* Character string message */
103 };
104
105 /*
106  * Trace actions in full. Additionally, read or write is masked
107  */
108 #define BLK_TA_QUEUE            (__BLK_TA_QUEUE | BLK_TC_ACT(BLK_TC_QUEUE))
109 #define BLK_TA_BACKMERGE        (__BLK_TA_BACKMERGE | BLK_TC_ACT(BLK_TC_QUEUE))
110 #define BLK_TA_FRONTMERGE       (__BLK_TA_FRONTMERGE | BLK_TC_ACT(BLK_TC_QUEUE))
111 #define BLK_TA_GETRQ            (__BLK_TA_GETRQ | BLK_TC_ACT(BLK_TC_QUEUE))
112 #define BLK_TA_SLEEPRQ          (__BLK_TA_SLEEPRQ | BLK_TC_ACT(BLK_TC_QUEUE))
113 #define BLK_TA_REQUEUE          (__BLK_TA_REQUEUE | BLK_TC_ACT(BLK_TC_REQUEUE))
114 #define BLK_TA_ISSUE            (__BLK_TA_ISSUE | BLK_TC_ACT(BLK_TC_ISSUE))
115 #define BLK_TA_COMPLETE         (__BLK_TA_COMPLETE| BLK_TC_ACT(BLK_TC_COMPLETE))
116 #define BLK_TA_PLUG             (__BLK_TA_PLUG | BLK_TC_ACT(BLK_TC_QUEUE))
117 #define BLK_TA_UNPLUG_IO        (__BLK_TA_UNPLUG_IO | BLK_TC_ACT(BLK_TC_QUEUE))
118 #define BLK_TA_UNPLUG_TIMER     (__BLK_TA_UNPLUG_TIMER | BLK_TC_ACT(BLK_TC_QUEUE))
119 #define BLK_TA_INSERT           (__BLK_TA_INSERT | BLK_TC_ACT(BLK_TC_QUEUE))
120 #define BLK_TA_SPLIT            (__BLK_TA_SPLIT)
121 #define BLK_TA_BOUNCE           (__BLK_TA_BOUNCE)
122 #define BLK_TA_REMAP            (__BLK_TA_REMAP | BLK_TC_ACT(BLK_TC_QUEUE))
123 #define BLK_TA_ABORT            (__BLK_TA_ABORT | BLK_TC_ACT(BLK_TC_QUEUE))
124 #define BLK_TA_DRV_DATA         (__BLK_TA_DRV_DATA | BLK_TC_ACT(BLK_TC_DRV_DATA))
125
126 #define BLK_TN_PROCESS          (__BLK_TN_PROCESS | BLK_TC_ACT(BLK_TC_NOTIFY))
127 #define BLK_TN_TIMESTAMP        (__BLK_TN_TIMESTAMP | BLK_TC_ACT(BLK_TC_NOTIFY))
128 #define BLK_TN_MESSAGE          (__BLK_TN_MESSAGE | BLK_TC_ACT(BLK_TC_NOTIFY))
129
130 #define BLK_IO_TRACE_MAGIC      0x65617400
131 #define BLK_IO_TRACE_VERSION    0x07
132 /*
133  * The trace itself
134  */
135 struct blk_io_trace {
136         __u32 magic;            /* MAGIC << 8 | version */
137         __u32 sequence;         /* event number */
138         __u64 time;             /* in nanoseconds */
139         __u64 sector;           /* disk offset */
140         __u32 bytes;            /* transfer length */
141         __u32 action;           /* what happened */
142         __u32 pid;              /* who did it */
143         __u32 device;           /* device identifier (dev_t) */
144         __u32 cpu;              /* on what cpu did it happen */
145         __u16 error;            /* completion error */
146         __u16 pdu_len;          /* length of data after this trace */
147 };
148
149 struct pending_io {
150         /* sector offset of this IO */
151         u64 sector;
152
153         /* time this IO was dispatched */
154         u64 dispatch_time;
155         /* time this IO was finished */
156         u64 completion_time;
157         struct list_head hash_list;
158 };
159
160 #define MINORBITS 20
161 #define MINORMASK ((1 << MINORBITS) - 1)
162 #define SECONDS(x)              ((unsigned long long)(x) / 1000000000)
163 #define NANO_SECONDS(x)         ((unsigned long long)(x) % 1000000000)
164 #define DOUBLE_TO_NANO_ULL(d)   ((unsigned long long)((d) * 1000000000))
165 #define CHECK_MAGIC(t)          (((t)->magic & 0xffffff00) == BLK_IO_TRACE_MAGIC)
166
167 void init_io_hash_table(void)
168 {
169         int i;
170         struct list_head *head;
171
172         for (i = 0; i < IO_HASH_TABLE_SIZE; i++) {
173                 head = io_hash_table + i;
174                 INIT_LIST_HEAD(head);
175         }
176 }
177
178 /* taken from the kernel hash.h */
179 static inline u64 hash_sector(u64 val)
180 {
181         u64 hash = val;
182
183         /*  Sigh, gcc can't optimise this alone like it does for 32 bits. */
184         u64 n = hash;
185         n <<= 18;
186         hash -= n;
187         n <<= 33;
188         hash -= n;
189         n <<= 3;
190         hash += n;
191         n <<= 3;
192         hash -= n;
193         n <<= 4;
194         hash += n;
195         n <<= 2;
196         hash += n;
197
198         /* High bits are more random, so use them. */
199         return hash >> (64 - IO_HASH_TABLE_BITS);
200 }
201
202 static int hash_table_insert(struct pending_io *ins_pio)
203 {
204         u64 sector = ins_pio->sector;
205         int slot = hash_sector(sector);
206         struct list_head *head;
207         struct pending_io *pio;
208
209         head = io_hash_table + slot;
210         list_for_each_entry(pio, head, hash_list) {
211                 if (pio->sector == sector)
212                         return -EEXIST;
213         }
214         list_add_tail(&ins_pio->hash_list, head);
215         return 0;
216 }
217
218 static struct pending_io *hash_table_search(u64 sector)
219 {
220         int slot = hash_sector(sector);
221         struct list_head *head;
222         struct pending_io *pio;
223
224         head = io_hash_table + slot;
225         list_for_each_entry(pio, head, hash_list) {
226                 if (pio->sector == sector)
227                         return pio;
228         }
229         return NULL;
230 }
231
232 static int hash_dispatched_io(struct blk_io_trace *io)
233 {
234         struct pending_io *pio;
235         int ret;
236
237         pio = calloc(1, sizeof(*pio));
238         pio->sector = io->sector;
239         pio->dispatch_time = io->time;
240
241         ret = hash_table_insert(pio);
242         if (ret == -EEXIST) {
243                 /* crud, the IO isn't here */
244                 free(pio);
245         }
246         return ret;
247 }
248
249 static struct pending_io *hash_completed_io(struct blk_io_trace *io)
250 {
251         struct pending_io *pio;
252
253         pio = hash_table_search(io->sector);
254
255         if (!pio)
256                 return NULL;
257         return pio;
258 }
259
260 static void handle_notify(struct trace *trace)
261 {
262         struct blk_io_trace *io = trace->io;
263         void *payload = (char *)io + sizeof(*io);
264         u32 two32[2];
265
266
267         if (io->action != BLK_TN_TIMESTAMP)
268                 return;
269
270         if (io->pdu_len != sizeof(two32))
271                 return;
272
273         memcpy(two32, payload, sizeof(two32));
274         trace->start_timestamp = io->time;
275         trace->abs_start_time.tv_sec = two32[0];
276         trace->abs_start_time.tv_nsec = two32[1];
277         if (trace->abs_start_time.tv_nsec < 0) {
278                 trace->abs_start_time.tv_sec--;
279                 trace->abs_start_time.tv_nsec += 1000000000;
280         }
281 }
282
283 int next_record(struct trace *trace)
284 {
285         int skip = trace->io->pdu_len;
286         u64 offset;
287
288         trace->cur += sizeof(*trace->io) + skip;
289         offset = trace->cur - trace->start;
290         if (offset >= trace->len)
291                 return 1;
292
293         trace->io = (struct blk_io_trace *)trace->cur;
294         return 0;
295 }
296
297 void first_record(struct trace *trace)
298 {
299         trace->cur = trace->start;
300         trace->io = (struct blk_io_trace *)trace->cur;
301 }
302
303 int is_io_event(struct blk_io_trace *test)
304 {
305         char *message;
306         if (!(test->action & BLK_TC_ACT(BLK_TC_NOTIFY)))
307                 return 1;
308         if (test->action == BLK_TN_MESSAGE) {
309                 int len = test->pdu_len;
310                 if (len < 3)
311                         return 0;
312                 message = (char *)(test + 1);
313                 if (strncmp(message, "fio ", 4) == 0) {
314                         return 1;
315                 }
316         }
317         return 0;
318 }
319
320 u64 find_last_time(struct trace *trace)
321 {
322         char *p = trace->start + trace->len;
323         struct blk_io_trace *test;
324         int search_len = 0;
325         u64 found = 0;
326
327         if (trace->len < sizeof(*trace->io))
328                 return 0;
329         p -= sizeof(*trace->io);
330         while (p >= trace->start) {
331                 test = (struct blk_io_trace *)p;
332                 if (CHECK_MAGIC(test) && is_io_event(test)) {
333                         u64 offset = p - trace->start;
334                         if (offset + sizeof(*test) + test->pdu_len == trace->len) {
335                                 return test->time;
336                         }
337                 }
338                 p--;
339                 search_len++;
340                 if (search_len > 8192) {
341                         break;
342                 }
343         }
344
345         /* searching backwards didn't work out, we'll have to scan the file */
346         first_record(trace);
347         while (1) {
348                 if (is_io_event(trace->io))
349                         found = trace->io->time;
350                 if (next_record(trace))
351                         break;
352         }
353         first_record(trace);
354         return found;
355 }
356
357 int parse_fio_bank_message(struct trace *trace, u64 *bank_ret, u64 *offset_ret,
358                            u64 *num_banks_ret)
359 {
360         char *s;
361         char *next;
362         char *message;
363         struct blk_io_trace *test = trace->io;
364         int len = test->pdu_len;
365         u64 bank;
366         u64 offset;
367         u64 num_banks;
368
369         if (!(test->action & BLK_TC_ACT(BLK_TC_NOTIFY)))
370                 return -1;
371         if (test->action != BLK_TN_MESSAGE)
372                 return -1;
373
374         /* the message is fio rw bank offset num_banks */
375         if (len < 3)
376                 return -1;
377         message = (char *)(test + 1);
378         if (strncmp(message, "fio r ", 6) != 0)
379                 return -1;
380
381         message = strndup(message, len);
382         s = strchr(message, ' ');
383         if (!s)
384                 goto out;
385         s++;
386         s = strchr(s, ' ');
387         if (!s)
388                 goto out;
389
390         bank = strtoll(s, &next, 10);
391         if (s == next)
392                 goto out;
393         s = next;
394
395         offset = strtoll(s, &next, 10);
396         if (s == next)
397                 goto out;
398         s = next;
399
400         num_banks = strtoll(s, &next, 10);
401         if (s == next)
402                 goto out;
403
404         *bank_ret = bank;
405         *offset_ret = offset;
406         *num_banks_ret = num_banks;
407
408         return 0;
409 out:
410         free(message);
411         return -1;
412 }
413
414 void find_highest_offset(struct trace *trace, u64 *max_ret, u64 *max_bank_ret,
415                          u64 *max_offset_ret)
416 {
417         u64 found = 0;
418         u64 max = 0;
419         u64 max_bank = 0;
420         u64 max_bank_offset = 0;
421         u64 num_banks = 0;
422         first_record(trace);
423         while (1) {
424                 if (!(trace->io->action & BLK_TC_ACT(BLK_TC_NOTIFY))) {
425                         found = trace->io->sector << 9;
426                         found += trace->io->bytes;
427
428                         if (max < found) {
429                                 max = found;
430                         }
431                 } else {
432                         u64 bank;
433                         u64 offset;
434                         if (!parse_fio_bank_message(trace, &bank,
435                                                     &offset, &num_banks)) {
436                                 if (bank > max_bank)
437                                         max_bank = bank;
438                                 if (offset > max_bank_offset)
439                                         max_bank_offset = offset;
440                         }
441                 }
442                 if (next_record(trace))
443                         break;
444         }
445         first_record(trace);
446         *max_ret = max;
447         *max_bank_ret = max_bank;
448         *max_offset_ret = max_bank_offset;
449 }
450
451 int filter_outliers(struct trace *trace, u64 max_offset,
452                     u64 *yzoom_min, u64 *yzoom_max)
453 {
454         int hits[11];
455         u64 max_per_bucket[11];
456         u64 bytes_per_bucket = max_offset / 10;
457         int slot;
458         int fat_count = 0;
459
460         memset(hits, 0, sizeof(int) * 11);
461         memset(max_per_bucket, 0, sizeof(u64) * 11);
462         first_record(trace);
463         while (1) {
464                 if (!(trace->io->action & BLK_TC_ACT(BLK_TC_NOTIFY))) {
465                         u64 top = (trace->io->sector << 9) + trace->io->bytes;
466                         slot = (int)(top / bytes_per_bucket);
467                         hits[slot]++;
468                         if (top > max_per_bucket[slot])
469                                 max_per_bucket[slot] = top;
470                 }
471                 if (next_record(trace))
472                         break;
473         }
474         first_record(trace);
475         for (slot = 0; slot < 11; slot++) {
476                 if (hits[slot] > fat_count) {
477                         fat_count = hits[slot];
478                 }
479         }
480
481         *yzoom_max = max_offset;
482         for (slot = 10; slot >= 0; slot--) {
483                 double d = hits[slot];
484
485                 if (d >= (double)fat_count * .05) {
486                         *yzoom_max = max_per_bucket[slot];
487                         break;
488                 }
489         }
490
491         *yzoom_min = 0;
492         for (slot = 0; slot < 10; slot++) {
493                 double d = hits[slot];
494
495                 if (d >= (double)fat_count * .05) {
496                         *yzoom_min = slot * bytes_per_bucket;
497                         break;
498                 }
499         }
500         return 0;
501 }
502
503 static char *find_trace_file(char *filename)
504 {
505         int ret;
506         struct stat st;
507         char line[1024];
508         char *dot;
509         char *try;
510
511         ret = stat(filename, &st);
512         if (ret == 0)
513                 return strdup(filename);
514
515         snprintf(line, 1024, "%s.%s", filename, "dump");
516         ret = stat(line, &st);
517         if (ret == 0)
518                 return strdup(line);
519
520         try = strdup(filename);
521         dot = strrchr(try, '.');
522         if (!dot || strcmp(".dump", dot) != 0) {
523                 if (dot)
524                         *dot = '\0';
525                 snprintf(line, 1024, "%s%s", try, ".blktrace.0");
526                 ret = stat(line, &st);
527                 if (ret == 0) {
528                         blktrace_to_dump(try);
529                         snprintf(line, 1024, "%s.%s", try, "dump");
530                         ret = stat(line, &st);
531                         if (ret == 0) {
532                                 free(try);
533                                 return strdup(line);
534                         }
535                 }
536         }
537         free(try);
538         return NULL;
539 }
540 struct trace *open_trace(char *filename)
541 {
542         int fd;
543         char *p;
544         struct stat st;
545         int ret;
546         struct trace *trace;
547         char *found_filename;
548
549         trace = calloc(1, sizeof(*trace));
550         if (!trace) {
551                 fprintf(stderr, "unable to allocate memory for trace\n");
552                 return NULL;
553         }
554
555         found_filename = find_trace_file(filename);
556         if (!found_filename) {
557                 fprintf(stderr, "Unable to find trace file %s\n", filename);
558                 goto fail;
559         }
560         filename = found_filename;
561
562         fd = open(filename, O_RDONLY);
563         if (fd < 0) {
564                 fprintf(stderr, "Unable to open trace file %s err %s\n", filename, strerror(errno));
565                 goto fail;
566         }
567         ret = fstat(fd, &st);
568         if (ret < 0) {
569                 fprintf(stderr, "stat failed on %s err %s\n", filename, strerror(errno));
570                 goto fail_fd;
571         }
572         p = mmap(NULL, st.st_size, PROT_READ, MAP_PRIVATE, fd, 0);
573         if (p == MAP_FAILED) {
574                 fprintf(stderr, "Unable to mmap trace file %s, err %s\n", filename, strerror(errno));
575                 goto fail_fd;
576         }
577         trace->fd = fd;
578         trace->len = st.st_size;
579         trace->start = p;
580         trace->cur = p;
581         trace->io = (struct blk_io_trace *)p;
582         return trace;
583
584 fail_fd:
585         close(fd);
586 fail:
587         free(trace);
588         return NULL;
589 }
590 static inline int tput_event(struct trace *trace)
591 {
592         if (trace->found_completion)
593                 return __BLK_TA_COMPLETE;
594         if (trace->found_issue)
595                 return __BLK_TA_ISSUE;
596         if (trace->found_queue)
597                 return __BLK_TA_QUEUE;
598
599         return __BLK_TA_COMPLETE;
600 }
601
602 static inline int io_event(struct trace *trace)
603 {
604         if (trace->found_queue)
605                 return __BLK_TA_QUEUE;
606         if (trace->found_issue)
607                 return __BLK_TA_ISSUE;
608         if (trace->found_completion)
609                 return __BLK_TA_COMPLETE;
610
611         return __BLK_TA_COMPLETE;
612 }
613
614 void add_tput(struct trace *trace, struct graph_line_data *gld)
615 {
616         struct blk_io_trace *io = trace->io;
617         int action = io->action & 0xffff;
618         int seconds;
619
620         if (io->action & BLK_TC_ACT(BLK_TC_NOTIFY))
621                 return;
622
623         if (action != tput_event(trace))
624                 return;
625
626         seconds = SECONDS(io->time);
627         if (seconds > gld->seconds) {
628                 fprintf(stderr, "Bad record %d %d %d\n", seconds, gld->seconds, action);
629                 abort();
630         }
631
632         gld->data[seconds].sum += io->bytes;
633         gld->data[seconds].count = 1;
634         if (gld->data[seconds].sum > gld->max)
635                 gld->max = gld->data[seconds].sum;
636 }
637
638 void add_io(struct trace *trace, struct graph_dot_data *gdd_writes,
639             struct graph_dot_data *gdd_reads)
640 {
641         struct blk_io_trace *io = trace->io;
642         int action = io->action & 0xffff;
643         u64 offset;
644
645         if (io->action & BLK_TC_ACT(BLK_TC_NOTIFY))
646                 return;
647
648         if (action != io_event(trace))
649                 return;
650
651         offset = io->sector << 9;
652
653         if (BLK_DATADIR(io->action) & BLK_TC_READ)
654                 set_gdd_bit(gdd_reads, offset, io->bytes, io->time);
655         else if (BLK_DATADIR(io->action) & BLK_TC_WRITE)
656                 set_gdd_bit(gdd_writes, offset, io->bytes, io->time);
657 }
658
659 void add_pending_io(struct trace *trace, struct graph_line_data *gld)
660 {
661         int ret;
662         int seconds;
663         struct blk_io_trace *io = trace->io;
664         int action = io->action & 0xffff;
665         double avg;
666
667         if (io->action & BLK_TC_ACT(BLK_TC_NOTIFY))
668                 return;
669
670         if (action != __BLK_TA_ISSUE)
671                 return;
672
673         seconds = SECONDS(io->time);
674         if (seconds > gld->seconds) {
675                 fprintf(stderr, "Bad record %d %d\n", seconds, gld->seconds);
676                 abort();
677         }
678
679         ret = hash_dispatched_io(trace->io);
680         if (ret)
681                 return;
682
683         ios_in_flight++;
684
685         gld->data[seconds].sum += ios_in_flight;
686         gld->data[seconds].count++;
687
688         avg = (double)gld->data[seconds].sum / gld->data[seconds].count;
689         if (gld->max < (u64)avg) {
690                 gld->max = avg;
691         }
692 }
693
694 void add_completed_io(struct trace *trace,
695                       struct graph_line_data *latency_gld)
696 {
697         struct blk_io_trace *io = trace->io;
698         int seconds;
699         int action = io->action & 0xffff;
700         struct pending_io *pio;
701         double avg;
702         u64 latency;
703
704         if (io->action & BLK_TC_ACT(BLK_TC_NOTIFY))
705                 return;
706
707         if (action != __BLK_TA_COMPLETE)
708                 return;
709
710         seconds = SECONDS(io->time);
711
712         pio = hash_completed_io(trace->io);
713         if (!pio)
714                 return;
715
716         if (ios_in_flight > 0)
717                 ios_in_flight--;
718         if (io->time >= pio->dispatch_time) {
719                 latency = io->time - pio->dispatch_time;
720                 latency_gld->data[seconds].sum += latency;
721                 latency_gld->data[seconds].count++;
722         }
723
724         list_del(&pio->hash_list);
725         free(pio);
726
727         avg = (double)latency_gld->data[seconds].sum /
728                 latency_gld->data[seconds].count;
729         if (latency_gld->max < (u64)avg) {
730                 latency_gld->max = avg;
731         }
732 }
733
734 void add_iop(struct trace *trace, struct graph_line_data *gld)
735 {
736         struct blk_io_trace *io = trace->io;
737         int action = io->action & 0xffff;
738         int seconds;
739
740         if (io->action & BLK_TC_ACT(BLK_TC_NOTIFY))
741                 return;
742
743         /* iops and tput use the same events */
744         if (action != tput_event(trace))
745                 return;
746
747         seconds = SECONDS(io->time);
748         if (seconds > gld->seconds) {
749                 fprintf(stderr, "Bad record %d %d\n", seconds, gld->seconds);
750                 abort();
751         }
752
753         gld->data[seconds].sum += 1;
754         gld->data[seconds].count = 1;
755         if (gld->data[seconds].sum > gld->max)
756                 gld->max = gld->data[seconds].sum;
757 }
758
759 void check_record(struct trace *trace)
760 {
761         struct blk_io_trace *io = trace->io;
762         int action = io->action & 0xffff;
763
764         if (!(io->action & BLK_TC_ACT(BLK_TC_NOTIFY))) {
765                 switch (action) {
766                 case __BLK_TA_COMPLETE:
767                         trace->found_completion = 1;
768                         break;
769                 case __BLK_TA_ISSUE:
770                         trace->found_issue = 1;
771                         break;
772                 case __BLK_TA_QUEUE:
773                         trace->found_queue = 1;
774                         break;
775                 };
776         }
777         handle_notify(trace);
778 }