[blktrace.git] / blkparse.c

#include <sys/types.h>
#include <sys/stat.h>
#include <unistd.h>
#include <stdio.h>
#include <fcntl.h>
#include <stdlib.h>

#include "blktrace.h" 

#define NELEMS(pfi) ((pfi)->stat.st_size / sizeof(struct blk_io_trace))

#define MAX_CPUS	(1 << 8)	/* only 8 bits for now */

struct per_file_info {
	int cpu;
	int nelems;
	struct stat stat;

	int fd;
	char *fname;
	FILE *ofp;
	char *ofname;
	int dfd;
	char *dname;

	unsigned long long start_time;
};

struct per_file_info per_file_info[MAX_CPUS];
struct per_file_info *current;

static unsigned long qreads, qwrites, creads, cwrites, mreads, mwrites;
static unsigned long long qread_kb, qwrite_kb, cread_kb, cwrite_kb;
static unsigned long long events, missed_events;

static inline void account_m(int rw, unsigned int bytes)
{
	if (rw) {
		mwrites++;
		qwrite_kb += bytes >> 10;
	} else {
		mreads++;
		qread_kb += bytes >> 10;
	}
}

static inline void account_q(int rw, unsigned int bytes)
{
	if (rw) {
		qwrites++;
		qwrite_kb += bytes >> 10;
	} else {
		qreads++;
		qread_kb += bytes >> 10;
	}
}

static inline void account_c(int rw, unsigned int bytes)
{
	if (rw) {
		cwrites++;
		cwrite_kb += bytes >> 10;
	} else {
		creads++;
		cread_kb += bytes >> 10;
	}
}

void output(char *s)
{
	printf("%s", s);
	fprintf(current->ofp,"%s",s);
}

char hstring[256];
char tstring[256];

inline char *setup_header(struct blk_io_trace *t, char act)
{
	int w = t->action & BLK_TC_ACT(BLK_TC_WRITE);
	int b = t->action & BLK_TC_ACT(BLK_TC_BARRIER);
	int s = t->action & BLK_TC_ACT(BLK_TC_SYNC);
	char rwbs[4];
	int i = 0;

	if (w)
		rwbs[i++] = 'W';
	else
		rwbs[i++] = 'R';
	if (b)
		rwbs[i++] = 'B';
	if (s)
		rwbs[i++] = 'S';

	rwbs[i] = '\0';

	sprintf(hstring, "%3d %15ld %12Lu %5u %c %3s", current->cpu,
		(unsigned long)t->sequence, (unsigned long long)t->time, t->pid,
		act, rwbs);

	return hstring;
}

void log_complete(struct blk_io_trace *t, char act)
{
	sprintf(tstring,"%s %Lu + %u [%d]\n", setup_header(t, act),
		(unsigned long long)t->sector, t->bytes >> 9, t->error);
	output(tstring);
}

void log_queue(struct blk_io_trace *t, char act)
{
	sprintf(tstring,"%s %Lu + %u\n", setup_header(t, act),
		(unsigned long long)t->sector, t->bytes >> 9);
	output(tstring);
}

void log_issue(struct blk_io_trace *t, char act)
{
	sprintf(tstring,"%s %Lu + %u\n", setup_header(t, act),
		(unsigned long long)t->sector, t->bytes >> 9);
	output(tstring);
}

void log_merge(struct blk_io_trace *t, char act)
{
	sprintf(tstring,"%s   %Lu + %u\n", setup_header(t, act),
		(unsigned long long)t->sector, t->bytes >> 9);
	output(tstring);
}

void log_generic(struct blk_io_trace *t, char act)
{
	sprintf(tstring,"%s %Lu + %u\n", setup_header(t, act),
		(unsigned long long)t->sector, t->bytes >> 9);
	output(tstring);
}

void log_pc(struct blk_io_trace *t, char act)
{
	int i, ret;
	unsigned char buf[64];

	sprintf(tstring,"%s\n", setup_header(t, act));
	output(tstring);

	if (t->pdu_len > sizeof(buf)) {
		fprintf(stderr, "Payload too large %d\n", t->pdu_len);
		return;
	}

	ret = read(current->dfd, buf, t->pdu_len);
	if (ret != t->pdu_len) {
		fprintf(stderr,"read(%d) failed on %s - %d\n", t->pdu_len, 
			current->dname, ret);
		exit(1);
	}

	for (i = 0; i < t->pdu_len; i++) {
		sprintf(tstring,"%02x ", buf[i]);
		output(tstring);
	}

	if (act == 'C') {
		sprintf(tstring,"[%d]", t->error);
		output(tstring);
	}

	printf("\n");
}

void dump_trace_pc(struct blk_io_trace *t)
{
	switch (t->action & 0xffff) {
		case __BLK_TA_QUEUE:
			log_generic(t, 'Q');
			break;
		case __BLK_TA_GETRQ:
			log_generic(t, 'G');
			break;
		case __BLK_TA_SLEEPRQ:
			log_generic(t, 'S');
			break;
		case __BLK_TA_REQUEUE:
			log_generic(t, 'R');
			break;
		case __BLK_TA_ISSUE:
			log_pc(t, 'D');
			break;
		case __BLK_TA_COMPLETE:
			log_pc(t, 'C');
			break;
		default:
			fprintf(stderr, "Bad pc action %x\n", t->action);
			return;
	}
	
	events++;
}

void dump_trace_fs(struct blk_io_trace *t)
{
	int w = t->action & BLK_TC_ACT(BLK_TC_WRITE);

	switch (t->action & 0xffff) {
		case __BLK_TA_QUEUE:
			account_q(w, t->bytes);
			log_queue(t, 'Q');
			break;
		case __BLK_TA_BACKMERGE:
			account_m(w, t->bytes);
			log_merge(t, 'M');
			break;
		case __BLK_TA_FRONTMERGE:
			account_m(w, t->bytes);
			log_merge(t, 'F');
			break;
		case __BLK_TA_GETRQ:
			log_generic(t, 'G');
			break;
		case __BLK_TA_SLEEPRQ:
			log_generic(t, 'S');
			break;
		case __BLK_TA_REQUEUE:
			log_queue(t, 'R');
			break;
		case __BLK_TA_ISSUE:
			log_issue(t, 'D');
			break;
		case __BLK_TA_COMPLETE:
			account_c(w, t->bytes);
			log_complete(t, 'C');
			break;
		default:
			fprintf(stderr, "Bad fs action %x\n", t->action);
			return;
	}
	
	events++;
}

void dump_trace(struct blk_io_trace *t)
{
	if (t->action & BLK_TC_ACT(BLK_TC_PC))
		dump_trace_pc(t);
	else
		dump_trace_fs(t);
}

void show_stats(void)
{
	printf("\nReads:");
	printf("\tQueued:    %'8lu, %'8LuKiB\n", qreads, qread_kb);
	printf("\tCompleted: %'8lu, %'8LuKiB\n", creads, cread_kb);
	printf("\tMerges:    %'8lu\n", mreads);

	printf("Writes:");
	printf("\tQueued:    %'8lu, %'8LuKiB\n", qwrites, qwrite_kb);
	printf("\tCompleted: %'8lu, %'8LuKiB\n", cwrites, cwrite_kb);
	printf("\tMerges:    %'8lu\n", mwrites);

	printf("Events: %'Lu\n", events);
	printf("Missed events: %'Lu\n", missed_events);
}

int compar(const void *t1, const void *t2)
{
	long v1 = (long)(((struct blk_io_trace *)t1)->sequence);
	long v2 = (long)(((struct blk_io_trace *)t2)->sequence);

	return v1 - v2;
}

int main(int argc, char *argv[])
{
	char *p, *dev;
	int i, nfiles, nelems, nb, ret;
	struct per_file_info *pfi;
	struct blk_io_trace *traces, *tip;

	if (argc != 2) {
		fprintf(stderr, "Usage %s <dev>\n", argv[0]);
		return 1;
	}

	dev = argv[1];

	printf("First pass:\n");
	nfiles = nelems = 0;
	for (i = 0, pfi = &per_file_info[0]; i < MAX_CPUS; i++, pfi++) {
		pfi->cpu = i;
		pfi->start_time = 0;

		pfi->fname = malloc(128);
		sprintf(pfi->fname, "%s_out.%d", dev, i);
		if (stat(pfi->fname, &pfi->stat) < 0)
			break;
		if (!S_ISREG(pfi->stat.st_mode)) {
			fprintf(stderr, "Bad file type %s\n", pfi->fname);
			return 1;
		}

		nfiles++;
		pfi->nelems = NELEMS(pfi);
		nelems += pfi->nelems;
		printf("\t%2d %10s %15d\n", i, pfi->fname, pfi->nelems);

	}
	printf("\t              %15d\n", nelems);

	if (!i) {
		fprintf(stderr, "No files found\n");
		return 1;
	}

	traces = malloc(nelems * sizeof(struct blk_io_trace));
	if (traces == NULL) {
		fprintf(stderr, "Can not allocate %d\n",
			nelems * (int) sizeof(struct blk_io_trace));
		return 1;
	}

	printf("Second pass:\n");
	p = (char *)traces;
	for (i = 0, pfi = per_file_info; i < nfiles; i++, pfi++) {
		pfi->fd = open(pfi->fname, O_RDONLY);
		if (pfi->fd < 0) {
			perror(pfi->fname);
			return 1;
		}

		pfi->dname = malloc(128);
		sprintf(pfi->dname, "%s_dat.%d", dev, i);
		pfi->dfd = open(pfi->dname, O_RDONLY);
		if (pfi->dfd < 0) {
			perror(pfi->dname);
			return 1;
		}

		pfi->ofname = malloc(128);
		sprintf(pfi->ofname, "%s_log.%d", dev, i);
		pfi->ofp = fopen(pfi->ofname, "w");
		if (pfi->ofp == NULL) {
			perror(pfi->ofname);
			return 1;
		}

		printf("\tProcessing %s...", pfi->fname); fflush(stdout);
		nb = pfi->stat.st_size;
		ret = read(pfi->fd, p, nb);
		if (ret != nb) {
			perror(pfi->fname);
			fprintf(stderr,"\nFATAL: read(%d) -> %d\n", nb, ret);
			return 1;
		}
		printf("\n"); fflush(stdout);
		p += nb;
		close(pfi->fd);
	}

	printf("Sorting..."); fflush(stdout);
	qsort(traces, nelems, sizeof(struct blk_io_trace), compar);
	printf("\n\n");

	for (i = 0, tip = traces; i < nelems; i++, tip++) {
		int cpu = tip->magic & 0xff;

		current = &per_file_info[cpu];

		/*
		 * offset time by first trace event. 
		 *
		 * NOTE: This is *cpu* relative, thus you can not 
		 * compare times ACROSS cpus.
		 */
		if (current->start_time == 0)
			current->start_time = tip->time;

		tip->time -= current->start_time;

		dump_trace(tip);
	}

	show_stats();
	return 0;
}
Commit	Line	Data
d0ca268b JA	1	#include <sys/types.h>
	2	#include <sys/stat.h>
	3	#include <unistd.h>
	4	#include <stdio.h>
	5	#include <fcntl.h>
	6	#include <stdlib.h>
	7
	8	#include "blktrace.h"
	9
	10	#define NELEMS(pfi) ((pfi)->stat.st_size / sizeof(struct blk_io_trace))
	11
	12	#define MAX_CPUS (1 << 8) /* only 8 bits for now */
	13
	14	struct per_file_info {
	15	int cpu;
	16	int nelems;
	17	struct stat stat;
	18
	19	int fd;
	20	char *fname;
	21	FILE *ofp;
	22	char *ofname;
	23	int dfd;
	24	char *dname;
	25
	26	unsigned long long start_time;
	27	};
	28
	29	struct per_file_info per_file_info[MAX_CPUS];
	30	struct per_file_info *current;
	31
	32	static unsigned long qreads, qwrites, creads, cwrites, mreads, mwrites;
	33	static unsigned long long qread_kb, qwrite_kb, cread_kb, cwrite_kb;
	34	static unsigned long long events, missed_events;
	35
	36	static inline void account_m(int rw, unsigned int bytes)
	37	{
	38	if (rw) {
	39	mwrites++;
	40	qwrite_kb += bytes >> 10;
	41	} else {
	42	mreads++;
	43	qread_kb += bytes >> 10;
	44	}
	45	}
	46
	47	static inline void account_q(int rw, unsigned int bytes)
	48	{
	49	if (rw) {
	50	qwrites++;
	51	qwrite_kb += bytes >> 10;
	52	} else {
	53	qreads++;
	54	qread_kb += bytes >> 10;
	55	}
	56	}
	57
	58	static inline void account_c(int rw, unsigned int bytes)
	59	{
	60	if (rw) {
	61	cwrites++;
	62	cwrite_kb += bytes >> 10;
	63	} else {
	64	creads++;
65	cread_kb += bytes >> 10;
66	}
67	}
68
69	void output(char *s)
70	{
71	printf("%s", s);
72	fprintf(current->ofp,"%s",s);
73	}
74
75	char hstring[256];
76	char tstring[256];
77
78	inline char setup_header(struct blk_io_trace t, char act)
79	{
80	int w = t->action & BLK_TC_ACT(BLK_TC_WRITE);
81	int b = t->action & BLK_TC_ACT(BLK_TC_BARRIER);
82	int s = t->action & BLK_TC_ACT(BLK_TC_SYNC);
83	char rwbs[4];
84	int i = 0;
85
86	if (w)
87	rwbs[i++] = 'W';
88	else
89	rwbs[i++] = 'R';
90	if (b)
91	rwbs[i++] = 'B';
92	if (s)
93	rwbs[i++] = 'S';
94
95	rwbs[i] = '\0';
96
97	sprintf(hstring, "%3d %15ld %12Lu %5u %c %3s", current->cpu,
98	(unsigned long)t->sequence, (unsigned long long)t->time, t->pid,
99	act, rwbs);
100
101	return hstring;
102	}
103
104	void log_complete(struct blk_io_trace *t, char act)
105	{
106	sprintf(tstring,"%s %Lu + %u [%d]\n", setup_header(t, act),
107	(unsigned long long)t->sector, t->bytes >> 9, t->error);
108	output(tstring);
109	}
110
111	void log_queue(struct blk_io_trace *t, char act)
112	{
113	sprintf(tstring,"%s %Lu + %u\n", setup_header(t, act),
114	(unsigned long long)t->sector, t->bytes >> 9);
115	output(tstring);
116	}
117
118	void log_issue(struct blk_io_trace *t, char act)
119	{
120	sprintf(tstring,"%s %Lu + %u\n", setup_header(t, act),
121	(unsigned long long)t->sector, t->bytes >> 9);
122	output(tstring);
123	}
124
125	void log_merge(struct blk_io_trace *t, char act)
126	{
127	sprintf(tstring,"%s %Lu + %u\n", setup_header(t, act),
128	(unsigned long long)t->sector, t->bytes >> 9);
129	output(tstring);
130	}
131
132	void log_generic(struct blk_io_trace *t, char act)
133	{
134	sprintf(tstring,"%s %Lu + %u\n", setup_header(t, act),
135	(unsigned long long)t->sector, t->bytes >> 9);
136	output(tstring);
137	}
138
139	void log_pc(struct blk_io_trace *t, char act)
140	{
141	int i, ret;
142	unsigned char buf[64];
143
144	sprintf(tstring,"%s\n", setup_header(t, act));
145	output(tstring);
146
147	if (t->pdu_len > sizeof(buf)) {
148	fprintf(stderr, "Payload too large %d\n", t->pdu_len);
149	return;
150	}
151
152	ret = read(current->dfd, buf, t->pdu_len);
153	if (ret != t->pdu_len) {
154	fprintf(stderr,"read(%d) failed on %s - %d\n", t->pdu_len,
155	current->dname, ret);
156	exit(1);
157	}
158
159	for (i = 0; i < t->pdu_len; i++) {
160	sprintf(tstring,"%02x ", buf[i]);
161	output(tstring);
162	}
163
164	if (act == 'C') {
165	sprintf(tstring,"[%d]", t->error);
166	output(tstring);
167	}
168
169	printf("\n");
170	}
171
172	void dump_trace_pc(struct blk_io_trace *t)
173	{
174	switch (t->action & 0xffff) {
175	case __BLK_TA_QUEUE:
176	log_generic(t, 'Q');
177	break;
178	case __BLK_TA_GETRQ:
179	log_generic(t, 'G');
180	break;
181	case __BLK_TA_SLEEPRQ:
182	log_generic(t, 'S');
183	break;
184	case __BLK_TA_REQUEUE:
185	log_generic(t, 'R');
186	break;
187	case __BLK_TA_ISSUE:
188	log_pc(t, 'D');
189	break;
190	case __BLK_TA_COMPLETE:
191	log_pc(t, 'C');
192	break;
193	default:
194	fprintf(stderr, "Bad pc action %x\n", t->action);
195	return;
196	}
197
198	events++;
199	}
200
201	void dump_trace_fs(struct blk_io_trace *t)
202	{
203	int w = t->action & BLK_TC_ACT(BLK_TC_WRITE);
204
205	switch (t->action & 0xffff) {
206	case __BLK_TA_QUEUE:
207	account_q(w, t->bytes);
208	log_queue(t, 'Q');
209	break;
210	case __BLK_TA_BACKMERGE:
211	account_m(w, t->bytes);
212	log_merge(t, 'M');
213	break;
214	case __BLK_TA_FRONTMERGE:
215	account_m(w, t->bytes);
216	log_merge(t, 'F');
217	break;
218	case __BLK_TA_GETRQ:
219	log_generic(t, 'G');
220	break;
221	case __BLK_TA_SLEEPRQ:
222	log_generic(t, 'S');
223	break;
224	case __BLK_TA_REQUEUE:
225	log_queue(t, 'R');
226	break;
227	case __BLK_TA_ISSUE:
228	log_issue(t, 'D');
229	break;
230	case __BLK_TA_COMPLETE:
231	account_c(w, t->bytes);
232	log_complete(t, 'C');
233	break;
234	default:
235	fprintf(stderr, "Bad fs action %x\n", t->action);
236	return;
237	}
238
239	events++;
240	}
241
242	void dump_trace(struct blk_io_trace *t)
243	{
244	if (t->action & BLK_TC_ACT(BLK_TC_PC))
245	dump_trace_pc(t);
246	else
247	dump_trace_fs(t);
248	}
249
250	void show_stats(void)
251	{
252	printf("\nReads:");
253	printf("\tQueued: %'8lu, %'8LuKiB\n", qreads, qread_kb);
254	printf("\tCompleted: %'8lu, %'8LuKiB\n", creads, cread_kb);
255	printf("\tMerges: %'8lu\n", mreads);
256
257	printf("Writes:");
258	printf("\tQueued: %'8lu, %'8LuKiB\n", qwrites, qwrite_kb);
259	printf("\tCompleted: %'8lu, %'8LuKiB\n", cwrites, cwrite_kb);
260	printf("\tMerges: %'8lu\n", mwrites);
261
262	printf("Events: %'Lu\n", events);
263	printf("Missed events: %'Lu\n", missed_events);
264	}
265
266	int compar(const void t1, const void t2)
267	{
268	long v1 = (long)(((struct blk_io_trace *)t1)->sequence);
269	long v2 = (long)(((struct blk_io_trace *)t2)->sequence);
270
271	return v1 - v2;
272	}
273
274	int main(int argc, char *argv[])
275	{
276	char p, dev;
277	int i, nfiles, nelems, nb, ret;
278	struct per_file_info *pfi;
279	struct blk_io_trace traces, tip;
280
281	if (argc != 2) {
282	fprintf(stderr, "Usage %s <dev>\n", argv[0]);
283	return 1;
284	}
285
286	dev = argv[1];
287
288	printf("First pass:\n");
289	nfiles = nelems = 0;
290	for (i = 0, pfi = &per_file_info[0]; i < MAX_CPUS; i++, pfi++) {
291	pfi->cpu = i;
292	pfi->start_time = 0;
293
294	pfi->fname = malloc(128);
295	sprintf(pfi->fname, "%s_out.%d", dev, i);
296	if (stat(pfi->fname, &pfi->stat) < 0)
297	break;
298	if (!S_ISREG(pfi->stat.st_mode)) {
299	fprintf(stderr, "Bad file type %s\n", pfi->fname);
300	return 1;
301	}
302
303	nfiles++;
304	pfi->nelems = NELEMS(pfi);
305	nelems += pfi->nelems;
306	printf("\t%2d %10s %15d\n", i, pfi->fname, pfi->nelems);
307
308	}
309	printf("\t %15d\n", nelems);
310
311	if (!i) {
312	fprintf(stderr, "No files found\n");
313	return 1;
314	}
315
316	traces = malloc(nelems * sizeof(struct blk_io_trace));
317	if (traces == NULL) {
318	fprintf(stderr, "Can not allocate %d\n",
319	nelems * (int) sizeof(struct blk_io_trace));
320	return 1;
321	}
322
323	printf("Second pass:\n");
324	p = (char *)traces;
325	for (i = 0, pfi = per_file_info; i < nfiles; i++, pfi++) {
326	pfi->fd = open(pfi->fname, O_RDONLY);
327	if (pfi->fd < 0) {
328	perror(pfi->fname);
329	return 1;
330	}
331
332	pfi->dname = malloc(128);
333	sprintf(pfi->dname, "%s_dat.%d", dev, i);
334	pfi->dfd = open(pfi->dname, O_RDONLY);
335	if (pfi->dfd < 0) {
336	perror(pfi->dname);
337	return 1;
338	}
339
340	pfi->ofname = malloc(128);
341	sprintf(pfi->ofname, "%s_log.%d", dev, i);
342	pfi->ofp = fopen(pfi->ofname, "w");
343	if (pfi->ofp == NULL) {
344	perror(pfi->ofname);
345	return 1;
346	}
347
348	printf("\tProcessing %s...", pfi->fname); fflush(stdout);
349	nb = pfi->stat.st_size;
350	ret = read(pfi->fd, p, nb);
351	if (ret != nb) {
352	perror(pfi->fname);
353	fprintf(stderr,"\nFATAL: read(%d) -> %d\n", nb, ret);
354	return 1;
355	}
356	printf("\n"); fflush(stdout);
357	p += nb;
358	close(pfi->fd);
359	}
360
361	printf("Sorting..."); fflush(stdout);
362	qsort(traces, nelems, sizeof(struct blk_io_trace), compar);
363	printf("\n\n");
364
365	for (i = 0, tip = traces; i < nelems; i++, tip++) {
366	int cpu = tip->magic & 0xff;
367
368	current = &per_file_info[cpu];
369
370	/*
371	* offset time by first trace event.
372	*
373	* NOTE: This is cpu relative, thus you can not
374	* compare times ACROSS cpus.
375	*/
376	if (current->start_time == 0)
377	current->start_time = tip->time;
378
379	tip->time -= current->start_time;
380
381	dump_trace(tip);
382	}
383
384	show_stats();
385	return 0;
386	}
387
388