[blktrace.git] / iowatcher / blkparse.c

/*
 * Copyright (C) 2012 Fusion-io
 *
 *  This program is free software; you can redistribute it and/or
 *  modify it under the terms of the GNU General Public
 *  License v2 as published by the Free Software Foundation.
 *
 *  This program is distributed in the hope that it will be useful,
 *  but WITHOUT ANY WARRANTY; without even the implied warranty of
 *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
 *  GNU General Public License for more details.
 *
 *  You should have received a copy of the GNU General Public License
 *  along with this program; if not, write to the Free Software
 *  Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
 *
 *  Parts of this file were imported from Jens Axboe's blktrace sources (also GPL)
 */
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <unistd.h>
#include <stdlib.h>
#include <stdio.h>
#include <math.h>
#include <inttypes.h>
#include <string.h>
#include <asm/types.h>
#include <errno.h>
#include <sys/mman.h>
#include <time.h>
#include <math.h>

#include "plot.h"
#include "blkparse.h"
#include "list.h"
#include "tracers.h"

#define IO_HASH_TABLE_BITS  11
#define IO_HASH_TABLE_SIZE (1 << IO_HASH_TABLE_BITS)
static struct list_head io_hash_table[IO_HASH_TABLE_SIZE];
static u64 ios_in_flight = 0;


/*
 * Trace categories
 */
enum {
	BLK_TC_READ	= 1 << 0,	/* reads */
	BLK_TC_WRITE	= 1 << 1,	/* writes */
	BLK_TC_FLUSH	= 1 << 2,	/* flush */
	BLK_TC_SYNC	= 1 << 3,	/* sync */
	BLK_TC_QUEUE	= 1 << 4,	/* queueing/merging */
	BLK_TC_REQUEUE	= 1 << 5,	/* requeueing */
	BLK_TC_ISSUE	= 1 << 6,	/* issue */
	BLK_TC_COMPLETE	= 1 << 7,	/* completions */
	BLK_TC_FS	= 1 << 8,	/* fs requests */
	BLK_TC_PC	= 1 << 9,	/* pc requests */
	BLK_TC_NOTIFY	= 1 << 10,	/* special message */
	BLK_TC_AHEAD	= 1 << 11,	/* readahead */
	BLK_TC_META	= 1 << 12,	/* metadata */
	BLK_TC_DISCARD	= 1 << 13,	/* discard requests */
	BLK_TC_DRV_DATA	= 1 << 14,	/* binary driver data */
	BLK_TC_FUA	= 1 << 15,	/* fua requests */

	BLK_TC_END	= 1 << 15,	/* we've run out of bits! */
};

#define BLK_TC_SHIFT		(16)
#define BLK_TC_ACT(act)		((act) << BLK_TC_SHIFT)
#define BLK_DATADIR(a) (((a) >> BLK_TC_SHIFT) & (BLK_TC_READ | BLK_TC_WRITE))

/*
 * Basic trace actions
 */
enum {
	__BLK_TA_QUEUE = 1,		/* queued */
	__BLK_TA_BACKMERGE,		/* back merged to existing rq */
	__BLK_TA_FRONTMERGE,		/* front merge to existing rq */
	__BLK_TA_GETRQ,			/* allocated new request */
	__BLK_TA_SLEEPRQ,		/* sleeping on rq allocation */
	__BLK_TA_REQUEUE,		/* request requeued */
	__BLK_TA_ISSUE,			/* sent to driver */
	__BLK_TA_COMPLETE,		/* completed by driver */
	__BLK_TA_PLUG,			/* queue was plugged */
	__BLK_TA_UNPLUG_IO,		/* queue was unplugged by io */
	__BLK_TA_UNPLUG_TIMER,		/* queue was unplugged by timer */
	__BLK_TA_INSERT,		/* insert request */
	__BLK_TA_SPLIT,			/* bio was split */
	__BLK_TA_BOUNCE,		/* bio was bounced */
	__BLK_TA_REMAP,			/* bio was remapped */
	__BLK_TA_ABORT,			/* request aborted */
	__BLK_TA_DRV_DATA,		/* binary driver data */
};

/*
 * Notify events.
 */
enum blktrace_notify {
	__BLK_TN_PROCESS = 0,		/* establish pid/name mapping */
	__BLK_TN_TIMESTAMP,		/* include system clock */
	__BLK_TN_MESSAGE,               /* Character string message */
};

/*
 * Trace actions in full. Additionally, read or write is masked
 */
#define BLK_TA_QUEUE		(__BLK_TA_QUEUE | BLK_TC_ACT(BLK_TC_QUEUE))
#define BLK_TA_BACKMERGE	(__BLK_TA_BACKMERGE | BLK_TC_ACT(BLK_TC_QUEUE))
#define BLK_TA_FRONTMERGE	(__BLK_TA_FRONTMERGE | BLK_TC_ACT(BLK_TC_QUEUE))
#define	BLK_TA_GETRQ		(__BLK_TA_GETRQ | BLK_TC_ACT(BLK_TC_QUEUE))
#define	BLK_TA_SLEEPRQ		(__BLK_TA_SLEEPRQ | BLK_TC_ACT(BLK_TC_QUEUE))
#define	BLK_TA_REQUEUE		(__BLK_TA_REQUEUE | BLK_TC_ACT(BLK_TC_REQUEUE))
#define BLK_TA_ISSUE		(__BLK_TA_ISSUE | BLK_TC_ACT(BLK_TC_ISSUE))
#define BLK_TA_COMPLETE		(__BLK_TA_COMPLETE| BLK_TC_ACT(BLK_TC_COMPLETE))
#define BLK_TA_PLUG		(__BLK_TA_PLUG | BLK_TC_ACT(BLK_TC_QUEUE))
#define BLK_TA_UNPLUG_IO	(__BLK_TA_UNPLUG_IO | BLK_TC_ACT(BLK_TC_QUEUE))
#define BLK_TA_UNPLUG_TIMER	(__BLK_TA_UNPLUG_TIMER | BLK_TC_ACT(BLK_TC_QUEUE))
#define BLK_TA_INSERT		(__BLK_TA_INSERT | BLK_TC_ACT(BLK_TC_QUEUE))
#define BLK_TA_SPLIT		(__BLK_TA_SPLIT)
#define BLK_TA_BOUNCE		(__BLK_TA_BOUNCE)
#define BLK_TA_REMAP		(__BLK_TA_REMAP | BLK_TC_ACT(BLK_TC_QUEUE))
#define BLK_TA_ABORT		(__BLK_TA_ABORT | BLK_TC_ACT(BLK_TC_QUEUE))
#define BLK_TA_DRV_DATA		(__BLK_TA_DRV_DATA | BLK_TC_ACT(BLK_TC_DRV_DATA))

#define BLK_TN_PROCESS		(__BLK_TN_PROCESS | BLK_TC_ACT(BLK_TC_NOTIFY))
#define BLK_TN_TIMESTAMP	(__BLK_TN_TIMESTAMP | BLK_TC_ACT(BLK_TC_NOTIFY))
#define BLK_TN_MESSAGE		(__BLK_TN_MESSAGE | BLK_TC_ACT(BLK_TC_NOTIFY))

#define BLK_IO_TRACE_MAGIC	0x65617400
#define BLK_IO_TRACE_VERSION	0x07
/*
 * The trace itself
 */
struct blk_io_trace {
	__u32 magic;		/* MAGIC << 8 | version */
	__u32 sequence;		/* event number */
	__u64 time;		/* in nanoseconds */
	__u64 sector;		/* disk offset */
	__u32 bytes;		/* transfer length */
	__u32 action;		/* what happened */
	__u32 pid;		/* who did it */
	__u32 device;		/* device identifier (dev_t) */
	__u32 cpu;		/* on what cpu did it happen */
	__u16 error;		/* completion error */
	__u16 pdu_len;		/* length of data after this trace */
};

struct pending_io {
	/* sector offset of this IO */
	u64 sector;

	/* time this IO was dispatched */
	u64 dispatch_time;
	/* time this IO was finished */
	u64 completion_time;
	struct list_head hash_list;
};

#define MINORBITS 20
#define MINORMASK ((1 << MINORBITS) - 1)
#define SECONDS(x)              ((unsigned long long)(x) / 1000000000)
#define NANO_SECONDS(x)         ((unsigned long long)(x) % 1000000000)
#define DOUBLE_TO_NANO_ULL(d)   ((unsigned long long)((d) * 1000000000))
#define CHECK_MAGIC(t)          (((t)->magic & 0xffffff00) == BLK_IO_TRACE_MAGIC)

void init_io_hash_table(void)
{
	int i;
	struct list_head *head;

	for (i = 0; i < IO_HASH_TABLE_SIZE; i++) {
		head = io_hash_table + i;
		INIT_LIST_HEAD(head);
	}
}

/* taken from the kernel hash.h */
static inline u64 hash_sector(u64 val)
{
	u64 hash = val;

	/*  Sigh, gcc can't optimise this alone like it does for 32 bits. */
	u64 n = hash;
	n <<= 18;
	hash -= n;
	n <<= 33;
	hash -= n;
	n <<= 3;
	hash += n;
	n <<= 3;
	hash -= n;
	n <<= 4;
	hash += n;
	n <<= 2;
	hash += n;

	/* High bits are more random, so use them. */
	return hash >> (64 - IO_HASH_TABLE_BITS);
}

static int hash_table_insert(struct pending_io *ins_pio)
{
	u64 sector = ins_pio->sector;
	int slot = hash_sector(sector);
	struct list_head *head;
	struct pending_io *pio;

	head = io_hash_table + slot;
	list_for_each_entry(pio, head, hash_list) {
		if (pio->sector == sector)
			return -EEXIST;
	}
	list_add_tail(&ins_pio->hash_list, head);
	return 0;
}

static struct pending_io *hash_table_search(u64 sector)
{
	int slot = hash_sector(sector);
	struct list_head *head;
	struct pending_io *pio;

	head = io_hash_table + slot;
	list_for_each_entry(pio, head, hash_list) {
		if (pio->sector == sector)
			return pio;
	}
	return NULL;
}

static int hash_dispatched_io(struct blk_io_trace *io)
{
	struct pending_io *pio;
	int ret;

	pio = calloc(1, sizeof(*pio));
	pio->sector = io->sector;
	pio->dispatch_time = io->time;

	ret = hash_table_insert(pio);
	if (ret == -EEXIST) {
		/* crud, the IO isn't here */
		free(pio);
	}
	return ret;
}

static struct pending_io *hash_completed_io(struct blk_io_trace *io)
{
	struct pending_io *pio;

	pio = hash_table_search(io->sector);

	if (!pio)
		return NULL;
	return pio;
}

static void handle_notify(struct trace *trace)
{
	struct blk_io_trace *io = trace->io;
	void *payload = (char *)io + sizeof(*io);
	u32 two32[2];


	if (io->action != BLK_TN_TIMESTAMP)
		return;

	if (io->pdu_len != sizeof(two32))
		return;

	memcpy(two32, payload, sizeof(two32));
	trace->start_timestamp = io->time;
	trace->abs_start_time.tv_sec = two32[0];
	trace->abs_start_time.tv_nsec = two32[1];
	if (trace->abs_start_time.tv_nsec < 0) {
		trace->abs_start_time.tv_sec--;
		trace->abs_start_time.tv_nsec += 1000000000;
	}
}

int next_record(struct trace *trace)
{
	int skip = trace->io->pdu_len;
	u64 offset;

	trace->cur += sizeof(*trace->io) + skip;
	offset = trace->cur - trace->start;
	if (offset >= trace->len)
		return 1;

	trace->io = (struct blk_io_trace *)trace->cur;
	return 0;
}

void first_record(struct trace *trace)
{
	trace->cur = trace->start;
	trace->io = (struct blk_io_trace *)trace->cur;
}

int is_io_event(struct blk_io_trace *test)
{
	char *message;
	if (!(test->action & BLK_TC_ACT(BLK_TC_NOTIFY)))
		return 1;
	if (test->action == BLK_TN_MESSAGE) {
		int len = test->pdu_len;
		if (len < 3)
			return 0;
		message = (char *)(test + 1);
		if (strncmp(message, "fio ", 4) == 0) {
			return 1;
		}
	}
	return 0;
}

u64 find_last_time(struct trace *trace)
{
	char *p = trace->start + trace->len;
	struct blk_io_trace *test;
	int search_len = 0;
	u64 found = 0;

	if (trace->len < sizeof(*trace->io))
		return 0;
	p -= sizeof(*trace->io);
	while (p >= trace->start) {
		test = (struct blk_io_trace *)p;
		if (CHECK_MAGIC(test) && is_io_event(test)) {
			u64 offset = p - trace->start;
			if (offset + sizeof(*test) + test->pdu_len == trace->len) {
				return test->time;
			}
		}
		p--;
		search_len++;
		if (search_len > 8192) {
			break;
		}
	}

	/* searching backwards didn't work out, we'll have to scan the file */
	first_record(trace);
	while (1) {
		if (is_io_event(trace->io))
			found = trace->io->time;
		if (next_record(trace))
			break;
	}
	first_record(trace);
	return found;
}

int parse_fio_bank_message(struct trace *trace, u64 *bank_ret, u64 *offset_ret,
			   u64 *num_banks_ret)
{
	char *s;
	char *next;
	char *message;
	struct blk_io_trace *test = trace->io;
	int len = test->pdu_len;
	u64 bank;
	u64 offset;
	u64 num_banks;

	if (!(test->action & BLK_TC_ACT(BLK_TC_NOTIFY)))
		return -1;
	if (test->action != BLK_TN_MESSAGE)
		return -1;

	/* the message is fio rw bank offset num_banks */
	if (len < 3)
		return -1;
	message = (char *)(test + 1);
	if (strncmp(message, "fio r ", 6) != 0)
		return -1;

	message = strndup(message, len);
	s = strchr(message, ' ');
	if (!s)
		goto out;
	s++;
	s = strchr(s, ' ');
	if (!s)
		goto out;

	bank = strtoll(s, &next, 10);
	if (s == next)
		goto out;
	s = next;

	offset = strtoll(s, &next, 10);
	if (s == next)
		goto out;
	s = next;

	num_banks = strtoll(s, &next, 10);
	if (s == next)
		goto out;

	*bank_ret = bank;
	*offset_ret = offset;
	*num_banks_ret = num_banks;

	return 0;
out:
	free(message);
	return -1;
}

void find_highest_offset(struct trace *trace, u64 *max_ret, u64 *max_bank_ret,
			 u64 *max_offset_ret)
{
	u64 found = 0;
	u64 max = 0;
	u64 max_bank = 0;
	u64 max_bank_offset = 0;
	u64 num_banks = 0;
	first_record(trace);
	while (1) {
		if (!(trace->io->action & BLK_TC_ACT(BLK_TC_NOTIFY))) {
			found = trace->io->sector << 9;
			found += trace->io->bytes;

			if (max < found) {
				max = found;
			}
		} else {
			u64 bank;
			u64 offset;
			if (!parse_fio_bank_message(trace, &bank,
						    &offset, &num_banks)) {
				if (bank > max_bank)
					max_bank = bank;
				if (offset > max_bank_offset)
					max_bank_offset = offset;
			}
		}
		if (next_record(trace))
			break;
	}
	first_record(trace);
	*max_ret = max;
	*max_bank_ret = max_bank;
	*max_offset_ret = max_bank_offset;
}

int filter_outliers(struct trace *trace, u64 max_offset,
		    u64 *yzoom_min, u64 *yzoom_max)
{
	int hits[11];
	u64 max_per_bucket[11];
	u64 bytes_per_bucket = max_offset / 10;
	int slot;
	int fat_count = 0;

	memset(hits, 0, sizeof(int) * 11);
	memset(max_per_bucket, 0, sizeof(u64) * 11);
	first_record(trace);
	while (1) {
		if (!(trace->io->action & BLK_TC_ACT(BLK_TC_NOTIFY))) {
			u64 top = (trace->io->sector << 9) + trace->io->bytes;
			slot = (int)(top / bytes_per_bucket);
			hits[slot]++;
			if (top > max_per_bucket[slot])
				max_per_bucket[slot] = top;
		}
		if (next_record(trace))
			break;
	}
	first_record(trace);
	for (slot = 0; slot < 11; slot++) {
		if (hits[slot] > fat_count) {
			fat_count = hits[slot];
		}
	}

	*yzoom_max = max_offset;
	for (slot = 10; slot >= 0; slot--) {
		double d = hits[slot];

		if (d >= (double)fat_count * .05) {
			*yzoom_max = max_per_bucket[slot];
			break;
		}
	}

	*yzoom_min = 0;
	for (slot = 0; slot < 10; slot++) {
		double d = hits[slot];

		if (d >= (double)fat_count * .05) {
			*yzoom_min = slot * bytes_per_bucket;
			break;
		}
	}
	return 0;
}

static char *find_trace_file(char *filename)
{
	int ret;
	struct stat st;
	char line[1024];
	char *dot;
	char *try;

	ret = stat(filename, &st);
	if (ret == 0)
		return strdup(filename);

	snprintf(line, 1024, "%s.%s", filename, "dump");
	ret = stat(line, &st);
	if (ret == 0)
		return strdup(line);

	try = strdup(filename);
	dot = strrchr(try, '.');
	if (!dot || strcmp(".dump", dot) != 0) {
		if (dot)
			*dot = '\0';
		snprintf(line, 1024, "%s%s", try, ".blktrace.0");
		ret = stat(line, &st);
		if (ret == 0) {
			blktrace_to_dump(try);
			snprintf(line, 1024, "%s.%s", try, "dump");
			ret = stat(line, &st);
			if (ret == 0) {
				free(try);
				return strdup(line);
			}
		}
	}
	free(try);
	return NULL;
}
struct trace *open_trace(char *filename)
{
	int fd;
	char *p;
	struct stat st;
	int ret;
	struct trace *trace;
	char *found_filename;

	trace = calloc(1, sizeof(*trace));
	if (!trace) {
		fprintf(stderr, "unable to allocate memory for trace\n");
		return NULL;
	}

	found_filename = find_trace_file(filename);
	if (!found_filename) {
		fprintf(stderr, "Unable to find trace file %s\n", filename);
		goto fail;
	}
	filename = found_filename;

	fd = open(filename, O_RDONLY);
	if (fd < 0) {
		fprintf(stderr, "Unable to open trace file %s err %s\n", filename, strerror(errno));
		goto fail;
	}
	ret = fstat(fd, &st);
	if (ret < 0) {
		fprintf(stderr, "stat failed on %s err %s\n", filename, strerror(errno));
		goto fail_fd;
	}
	p = mmap(NULL, st.st_size, PROT_READ, MAP_PRIVATE, fd, 0);
	if (p == MAP_FAILED) {
		fprintf(stderr, "Unable to mmap trace file %s, err %s\n", filename, strerror(errno));
		goto fail_fd;
	}
	trace->fd = fd;
	trace->len = st.st_size;
	trace->start = p;
	trace->cur = p;
	trace->io = (struct blk_io_trace *)p;
	return trace;

fail_fd:
	close(fd);
fail:
	free(trace);
	return NULL;
}
static inline int tput_event(struct trace *trace)
{
	if (trace->found_completion)
		return __BLK_TA_COMPLETE;
	if (trace->found_issue)
		return __BLK_TA_ISSUE;
	if (trace->found_queue)
		return __BLK_TA_QUEUE;

	return __BLK_TA_COMPLETE;
}

static inline int io_event(struct trace *trace)
{
	if (trace->found_queue)
		return __BLK_TA_QUEUE;
	if (trace->found_issue)
		return __BLK_TA_ISSUE;
	if (trace->found_completion)
		return __BLK_TA_COMPLETE;

	return __BLK_TA_COMPLETE;
}

void add_tput(struct trace *trace, struct graph_line_data *gld)
{
	struct blk_io_trace *io = trace->io;
	int action = io->action & 0xffff;
	int seconds;

	if (io->action & BLK_TC_ACT(BLK_TC_NOTIFY))
		return;

	if (action != tput_event(trace))
		return;

	seconds = SECONDS(io->time);
	if (seconds > gld->seconds) {
		fprintf(stderr, "Bad record %d %d %d\n", seconds, gld->seconds, action);
		abort();
	}

	gld->data[seconds].sum += io->bytes;
	gld->data[seconds].count = 1;
	if (gld->data[seconds].sum > gld->max)
		gld->max = gld->data[seconds].sum;
}

void add_io(struct trace *trace, struct graph_dot_data *gdd_writes,
	    struct graph_dot_data *gdd_reads)
{
	struct blk_io_trace *io = trace->io;
	int action = io->action & 0xffff;
	u64 offset;

	if (io->action & BLK_TC_ACT(BLK_TC_NOTIFY))
		return;

	if (action != io_event(trace))
		return;

	offset = io->sector << 9;

	if (BLK_DATADIR(io->action) & BLK_TC_READ)
		set_gdd_bit(gdd_reads, offset, io->bytes, io->time);
	else if (BLK_DATADIR(io->action) & BLK_TC_WRITE)
		set_gdd_bit(gdd_writes, offset, io->bytes, io->time);
}

void add_pending_io(struct trace *trace, struct graph_line_data *gld)
{
	int ret;
	int seconds;
	struct blk_io_trace *io = trace->io;
	int action = io->action & 0xffff;
	double avg;

	if (io->action & BLK_TC_ACT(BLK_TC_NOTIFY))
		return;

	if (action != __BLK_TA_ISSUE)
		return;

	seconds = SECONDS(io->time);
	if (seconds > gld->seconds) {
		fprintf(stderr, "Bad record %d %d\n", seconds, gld->seconds);
		abort();
	}

	ret = hash_dispatched_io(trace->io);
	if (ret)
		return;

	ios_in_flight++;

	gld->data[seconds].sum += ios_in_flight;
	gld->data[seconds].count++;

	avg = (double)gld->data[seconds].sum / gld->data[seconds].count;
	if (gld->max < (u64)avg) {
		gld->max = avg;
	}
}

void add_completed_io(struct trace *trace,
		      struct graph_line_data *latency_gld)
{
	struct blk_io_trace *io = trace->io;
	int seconds;
	int action = io->action & 0xffff;
	struct pending_io *pio;
	double avg;
	u64 latency;

	if (io->action & BLK_TC_ACT(BLK_TC_NOTIFY))
		return;

	if (action != __BLK_TA_COMPLETE)
		return;

	seconds = SECONDS(io->time);

	pio = hash_completed_io(trace->io);
	if (!pio)
		return;

	if (ios_in_flight > 0)
		ios_in_flight--;
	if (io->time >= pio->dispatch_time) {
		latency = io->time - pio->dispatch_time;
		latency_gld->data[seconds].sum += latency;
		latency_gld->data[seconds].count++;
	}

	list_del(&pio->hash_list);
	free(pio);

	avg = (double)latency_gld->data[seconds].sum /
		latency_gld->data[seconds].count;
	if (latency_gld->max < (u64)avg) {
		latency_gld->max = avg;
	}
}

void add_iop(struct trace *trace, struct graph_line_data *gld)
{
	struct blk_io_trace *io = trace->io;
	int action = io->action & 0xffff;
	int seconds;

	if (io->action & BLK_TC_ACT(BLK_TC_NOTIFY))
		return;

	/* iops and tput use the same events */
	if (action != tput_event(trace))
		return;

	seconds = SECONDS(io->time);
	if (seconds > gld->seconds) {
		fprintf(stderr, "Bad record %d %d\n", seconds, gld->seconds);
		abort();
	}

	gld->data[seconds].sum += 1;
	gld->data[seconds].count = 1;
	if (gld->data[seconds].sum > gld->max)
		gld->max = gld->data[seconds].sum;
}

void check_record(struct trace *trace)
{
	struct blk_io_trace *io = trace->io;
	int action = io->action & 0xffff;

	if (!(io->action & BLK_TC_ACT(BLK_TC_NOTIFY))) {
		switch (action) {
		case __BLK_TA_COMPLETE:
			trace->found_completion = 1;
			break;
		case __BLK_TA_ISSUE:
			trace->found_issue = 1;
			break;
		case __BLK_TA_QUEUE:
			trace->found_queue = 1;
			break;
		};
	}
	handle_notify(trace);
}
Commit	Line	Data
9e066e23 CM	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
bfb0e441 CM	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
9e066e23 CM	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;
bfb0e441	332	if (CHECK_MAGIC(test) && is_io_event(test)) {
9e066e23 CM	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) {
bfb0e441	348	if (is_io_event(trace->io))
9e066e23 CM	349	found = trace->io->time;
	350	if (next_record(trace))
	351	break;
	352	}
	353	first_record(trace);
	354	return found;
	355	}
	356
bfb0e441 CM	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)
9e066e23 CM	416	{
	417	u64 found = 0;
	418	u64 max = 0;
bfb0e441 CM	419	u64 max_bank = 0;
	420	u64 max_bank_offset = 0;
	421	u64 num_banks = 0;
9e066e23 CM	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	}
bfb0e441 CM	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	}
9e066e23 CM	441	}
	442	if (next_record(trace))
	443	break;
	444	}
	445	first_record(trace);
bfb0e441 CM	446	*max_ret = max;
	447	*max_bank_ret = max_bank;
	448	*max_offset_ret = max_bank_offset;
9e066e23 CM	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");
e199d546	516	ret = stat(line, &st);
9e066e23 CM	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	}
9e066e23 CM	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	}