blkparse_fmt.c revision e20e1347b9914aa05e30548c15d7cd5e412cc0e2 
1/*
2 * This file contains format parsing code for blkparse, allowing you to
3 * customize the individual action format and generel output format.
4 */
5#include <stdio.h>
6#include <string.h>
7#include <stdlib.h>
8#include <unistd.h>
9#include <ctype.h>
10#include <time.h>
11
12#include "blktrace.h"
13
14#define VALID_SPECS	"ABCDFGIMPQRSTUWX"
15
16#define HEADER		"%D %2c %8s %5T.%9t %5p %2a %3d "
17
18static char *override_format[256];
19
20static inline int valid_spec(int spec)
21{
22	return strchr(VALID_SPECS, spec) != NULL;
23}
24
25void set_all_format_specs(char *option)
26{
27	char *p;
28
29	for (p = VALID_SPECS; *p; p++)
30		if (override_format[(int)(*p)] == NULL)
31			override_format[(int)(*p)] = strdup(option);
32}
33
34int add_format_spec(char *option)
35{
36	int spec = optarg[0];
37
38	if (!valid_spec(spec)) {
39		fprintf(stderr,"Bad format specifier %c\n", spec);
40		return 1;
41	}
42	if (optarg[1] != ',') {
43		fprintf(stderr,"Bad format specifier - need ',' %s\n", option);
44		return 1;
45	}
46	option += 2;
47
48	override_format[spec] = strdup(option);
49
50	return 0;
51}
52
53static inline void fill_rwbs(char *rwbs, struct blk_io_trace *t)
54{
55	int w = t->action & BLK_TC_ACT(BLK_TC_WRITE);
56	int a = t->action & BLK_TC_ACT(BLK_TC_AHEAD);
57	int b = t->action & BLK_TC_ACT(BLK_TC_BARRIER);
58	int s = t->action & BLK_TC_ACT(BLK_TC_SYNC);
59	int m = t->action & BLK_TC_ACT(BLK_TC_META);
60	int d = t->action & BLK_TC_ACT(BLK_TC_DISCARD);
61	int i = 0;
62
63	if (d)
64		rwbs[i++] = 'D';
65	else if (w)
66		rwbs[i++] = 'W';
67	else if (t->bytes)
68		rwbs[i++] = 'R';
69	else
70		rwbs[i++] = 'N';
71	if (a)
72		rwbs[i++] = 'A';
73	if (b)
74		rwbs[i++] = 'B';
75	if (s)
76		rwbs[i++] = 'S';
77	if (m)
78		rwbs[i++] = 'M';
79
80	rwbs[i] = '\0';
81}
82
83static const char *
84print_time(unsigned long long timestamp)
85{
86	static char	timebuf[128];
87	struct tm	*tm;
88	time_t		sec;
89	unsigned long	nsec;
90
91	sec  = abs_start_time.tv_sec + SECONDS(timestamp);
92	nsec = abs_start_time.tv_nsec + NANO_SECONDS(timestamp);
93	if (nsec >= 1000000000) {
94		nsec -= 1000000000;
95		sec += 1;
96	}
97
98	tm = localtime(&sec);
99	snprintf(timebuf, sizeof(timebuf),
100			"%02u:%02u:%02u.%06lu",
101			tm->tm_hour,
102			tm->tm_min,
103			tm->tm_sec,
104			nsec / 1000);
105	return timebuf;
106}
107
108static inline int pdu_rest_is_zero(unsigned char *pdu, int len)
109{
110	static char zero[4096];
111
112	return !memcmp(pdu, zero, len);
113}
114
115static char *dump_pdu(unsigned char *pdu_buf, int pdu_len)
116{
117	static char p[4096];
118	int i, len;
119
120	if (!pdu_buf || !pdu_len)
121		return NULL;
122
123	for (len = 0, i = 0; i < pdu_len; i++) {
124		if (i)
125			len += sprintf(p + len, " ");
126
127		len += sprintf(p + len, "%02x", pdu_buf[i]);
128
129		/*
130		 * usually dump for cdb dumps where we can see lots of
131		 * zeroes, stop when the rest is just zeroes and indicate
132		 * so with a .. appended
133		 */
134		if (!pdu_buf[i] && pdu_rest_is_zero(pdu_buf + i, pdu_len - i)) {
135			sprintf(p + len, " ..");
136			break;
137		}
138	}
139
140	return p;
141}
142
143#define pdu_start(t)	(((void *) (t) + sizeof(struct blk_io_trace)))
144
145static unsigned int get_pdu_int(struct blk_io_trace *t)
146{
147	__u64 *val = pdu_start(t);
148
149	return be64_to_cpu(*val);
150}
151
152static void get_pdu_remap(struct blk_io_trace *t, struct blk_io_trace_remap *r)
153{
154	struct blk_io_trace_remap *__r = pdu_start(t);
155	__u64 sector_from = __r->sector_from;
156
157	r->device_from = be32_to_cpu(__r->device_from);
158	r->device_to   = be32_to_cpu(__r->device_to);
159	r->sector_from = be64_to_cpu(sector_from);
160}
161
162static void print_field(char *act, struct per_cpu_info *pci,
163			struct blk_io_trace *t, unsigned long long elapsed,
164			int pdu_len, unsigned char *pdu_buf, char field,
165			int minus, int has_w, int width)
166{
167	char format[64];
168
169	if (has_w) {
170		if (minus)
171			sprintf(format, "%%-%d", width);
172		else
173			sprintf(format, "%%%d", width);
174	} else
175		sprintf(format, "%%");
176
177	switch (field) {
178	case 'a':
179		fprintf(ofp, strcat(format, "s"), act);
180		break;
181	case 'c':
182		fprintf(ofp, strcat(format, "d"), pci->cpu);
183		break;
184	case 'C': {
185		char *name = find_process_name(t->pid);
186
187		fprintf(ofp, strcat(format, "s"), name);
188		break;
189	}
190	case 'd': {
191		char rwbs[6];
192
193		fill_rwbs(rwbs, t);
194		fprintf(ofp, strcat(format, "s"), rwbs);
195		break;
196	}
197	case 'D':	/* format width ignored */
198		fprintf(ofp,"%3d,%-3d", MAJOR(t->device), MINOR(t->device));
199		break;
200	case 'e':
201		fprintf(ofp, strcat(format, "d"), t->error);
202		break;
203	case 'M':
204		fprintf(ofp, strcat(format, "d"), MAJOR(t->device));
205		break;
206	case 'm':
207		fprintf(ofp, strcat(format, "d"), MINOR(t->device));
208		break;
209	case 'n':
210		fprintf(ofp, strcat(format, "u"), t_sec(t));
211		break;
212	case 'N':
213		fprintf(ofp, strcat(format, "u"), t->bytes);
214		break;
215	case 'p':
216		fprintf(ofp, strcat(format, "u"), t->pid);
217		break;
218	case 'P': { /* format width ignored */
219		char *p = dump_pdu(pdu_buf, pdu_len);
220		if (p)
221			fprintf(ofp, "%s", p);
222		break;
223	}
224	case 's':
225		fprintf(ofp, strcat(format, "ld"), t->sequence);
226		break;
227	case 'S':
228		fprintf(ofp, strcat(format, "lu"), t->sector);
229		break;
230	case 't':
231		sprintf(format, "%%0%dlu", has_w ? width : 9);
232		fprintf(ofp, format, NANO_SECONDS(t->time));
233		break;
234	case 'T':
235		fprintf(ofp, strcat(format, "d"), SECONDS(t->time));
236		break;
237	case 'u':
238		if (elapsed == -1ULL) {
239			fprintf(stderr, "Expecting elapsed value\n");
240			exit(1);
241		}
242		fprintf(ofp, strcat(format, "llu"), elapsed / 1000);
243		break;
244	case 'U':
245		fprintf(ofp, strcat(format, "u"), get_pdu_int(t));
246		break;
247	case 'z':
248		fprintf(ofp, strcat(format, "s"), print_time(t->time));
249		break;
250	default:
251		fprintf(ofp,strcat(format, "c"), field);
252		break;
253	}
254}
255
256static char *parse_field(char *act, struct per_cpu_info *pci,
257			 struct blk_io_trace *t, unsigned long long elapsed,
258			 int pdu_len, unsigned char *pdu_buf,
259			 char *master_format)
260{
261	int minus = 0;
262	int has_w = 0;
263	int width = 0;
264	char *p = master_format;
265
266	if (*p == '-') {
267		minus = 1;
268		p++;
269	}
270	if (isdigit(*p)) {
271		has_w = 1;
272		do {
273			width = (width * 10) + (*p++ - '0');
274		} while ((*p) && (isdigit(*p)));
275	}
276	if (*p) {
277		print_field(act, pci, t, elapsed, pdu_len, pdu_buf, *p++,
278			    minus, has_w, width);
279	}
280	return p;
281}
282
283static void process_default(char *act, struct per_cpu_info *pci,
284			    struct blk_io_trace *t, unsigned long long elapsed,
285			    int pdu_len, unsigned char *pdu_buf)
286{
287	struct blk_io_trace_remap r = { .device_from = 0, };
288	char rwbs[6];
289	char *name;
290
291	fill_rwbs(rwbs, t);
292
293	 /*
294	  * For remaps we have to modify the device using the remap structure
295	  * passed up.
296	  */
297	 if (act[0] == 'A') {
298		 get_pdu_remap(t, &r);
299		 t->device = r.device_to;
300	 }
301
302	/*
303	 * The header is always the same
304	 */
305	fprintf(ofp, "%3d,%-3d %2d %8d %5d.%09lu %5u %2s %3s ",
306		MAJOR(t->device), MINOR(t->device), pci->cpu, t->sequence,
307		(int) SECONDS(t->time), (unsigned long) NANO_SECONDS(t->time),
308		t->pid, act, rwbs);
309
310	name = find_process_name(t->pid);
311
312	switch (act[0]) {
313	case 'R':	/* Requeue */
314	case 'C': 	/* Complete */
315		if (t->action & BLK_TC_ACT(BLK_TC_PC)) {
316			char *p = dump_pdu(pdu_buf, pdu_len);
317			if (p)
318				fprintf(ofp, "(%s) ", p);
319			fprintf(ofp, "[%d]\n", t->error);
320		} else {
321			if (elapsed != -1ULL) {
322				if (t_sec(t))
323					fprintf(ofp, "%llu + %u (%8llu) [%d]\n",
324						(unsigned long long) t->sector,
325						t_sec(t), elapsed, t->error);
326				else
327					fprintf(ofp, "%llu (%8llu) [%d]\n",
328						(unsigned long long) t->sector,
329						elapsed, t->error);
330			} else {
331				if (t_sec(t))
332					fprintf(ofp, "%llu + %u [%d]\n",
333						(unsigned long long) t->sector,
334						t_sec(t), t->error);
335				else
336					fprintf(ofp, "%llu [%d]\n",
337						(unsigned long long) t->sector,
338						t->error);
339			}
340		}
341		break;
342
343	case 'D': 	/* Issue */
344	case 'I': 	/* Insert */
345	case 'Q': 	/* Queue */
346	case 'B':	/* Bounce */
347		if (t->action & BLK_TC_ACT(BLK_TC_PC)) {
348			char *p;
349			fprintf(ofp, "%u ", t->bytes);
350			p = dump_pdu(pdu_buf, pdu_len);
351			if (p)
352				fprintf(ofp, "(%s) ", p);
353			fprintf(ofp, "[%s]\n", name);
354		} else {
355			if (elapsed != -1ULL) {
356				if (t_sec(t))
357					fprintf(ofp, "%llu + %u (%8llu) [%s]\n",
358						(unsigned long long) t->sector,
359						t_sec(t), elapsed, name);
360				else
361					fprintf(ofp, "(%8llu) [%s]\n", elapsed,
362						name);
363			} else {
364				if (t_sec(t))
365					fprintf(ofp, "%llu + %u [%s]\n",
366						(unsigned long long) t->sector,
367						t_sec(t), name);
368				else
369					fprintf(ofp, "[%s]\n", name);
370			}
371		}
372		break;
373
374	case 'M':	/* Back merge */
375	case 'F':	/* Front merge */
376	case 'G':	/* Get request */
377	case 'S':	/* Sleep request */
378		if (t_sec(t))
379			fprintf(ofp, "%llu + %u [%s]\n",
380				(unsigned long long) t->sector, t_sec(t), name);
381		else
382			fprintf(ofp, "[%s]\n", name);
383		break;
384
385	case 'P':	/* Plug */
386		fprintf(ofp, "[%s]\n", name);
387		break;
388
389	case 'U':	/* Unplug IO */
390	case 'T': 	/* Unplug timer */
391		fprintf(ofp, "[%s] %u\n", name, get_pdu_int(t));
392		break;
393
394	case 'A': 	/* remap */
395		get_pdu_remap(t, &r);
396		fprintf(ofp, "%llu + %u <- (%d,%d) %llu\n",
397			(unsigned long long) t->sector, t_sec(t),
398			MAJOR(r.device_from), MINOR(r.device_from),
399			(unsigned long long) r.sector_from);
400		break;
401
402	case 'X': 	/* Split */
403		fprintf(ofp, "%llu / %u [%s]\n", (unsigned long long) t->sector,
404			get_pdu_int(t), name);
405		break;
406
407	case 'm':	/* Message */
408		fprintf(ofp, "%*s\n", pdu_len, pdu_buf);
409		break;
410
411	default:
412		fprintf(stderr, "Unknown action %c\n", act[0]);
413		break;
414	}
415
416}
417
418void process_fmt(char *act, struct per_cpu_info *pci, struct blk_io_trace *t,
419		 unsigned long long elapsed, int pdu_len,
420		 unsigned char *pdu_buf)
421{
422	char *p = override_format[(int) *act];
423
424	if (!p) {
425		process_default(act, pci, t, elapsed, pdu_len, pdu_buf);
426		return;
427	}
428
429	while (*p) {
430		switch (*p) {
431		case '%': 	/* Field specifier */
432			p++;
433			if (*p == '%')
434				fprintf(ofp, "%c", *p++);
435			else if (!*p)
436				fprintf(ofp, "%c", '%');
437			else
438				p = parse_field(act, pci, t, elapsed,
439						pdu_len, pdu_buf, p);
440			break;
441		case '\\': {	/* escape */
442			switch (p[1]) {
443			case 'b': fprintf(ofp, "\b"); break;
444			case 'n': fprintf(ofp, "\n"); break;
445			case 'r': fprintf(ofp, "\r"); break;
446			case 't': fprintf(ofp, "\t"); break;
447			default:
448				fprintf(stderr,
449					"Invalid escape char in format %c\n",
450					p[1]);
451				exit(1);
452				/*NOTREACHED*/
453			}
454			p += 2;
455			break;
456		}
457		default:
458			fprintf(ofp, "%c", *p++);
459			break;
460		}
461	}
462}
463
464
465