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