blkiomon: fix trace debug output
[blktrace.git] / blkiomon.c
1 /*
2  * I/O monitor based on block queue trace data
3  *
4  * Copyright IBM Corp. 2008
5  *
6  * Author(s): Martin Peschke <mp3@de.ibm.com>
7  *
8  *  This program is free software; you can redistribute it and/or modify
9  *  it under the terms of the GNU General Public License as published by
10  *  the Free Software Foundation; either version 2 of the License, or
11  *  (at your option) any later version.
12  *
13  *  This program is distributed in the hope that it will be useful,
14  *  but WITHOUT ANY WARRANTY; without even the implied warranty of
15  *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
16  *  GNU General Public License for more details.
17  *
18  *  You should have received a copy of the GNU General Public License
19  *  along with this program; if not, write to the Free Software
20  *  Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
21  */
22
23 #include <sys/types.h>
24 #include <sys/stat.h>
25 #include <fcntl.h>
26 #include <unistd.h>
27 #include <stdio.h>
28 #include <stdlib.h>
29 #include <string.h>
30 #include <signal.h>
31 #include <getopt.h>
32 #include <errno.h>
33 #include <locale.h>
34 #include <libgen.h>
35 #include <sys/msg.h>
36 #include <pthread.h>
37 #include <time.h>
38
39 #include "blktrace.h"
40 #include "rbtree.h"
41 #include "jhash.h"
42 #include "blkiomon.h"
43
44 struct trace {
45         struct blk_io_trace bit;
46         struct rb_node node;
47         struct trace *next;
48         long sequence;
49 };
50
51 struct rb_search {
52         struct rb_node **node_ptr;
53         struct rb_node *parent;
54 };
55
56 struct dstat_msg {
57         long mtype;
58         struct blkiomon_stat stat;
59 };
60
61 struct dstat {
62         struct dstat_msg msg;
63         struct rb_node node;
64         struct dstat *next;
65 };
66
67 struct output {
68         char *fn;
69         FILE *fp;
70         char *buf;
71         int pipe;
72 };
73
74 static char blkiomon_version[] = "0.2";
75
76 static FILE *ifp;
77 static int interval = -1;
78
79 static struct trace *vacant_traces_list = NULL;
80 static int vacant_traces = 0;
81
82 #define TRACE_HASH_SIZE 128
83 struct trace *thash[TRACE_HASH_SIZE] = {};
84
85 static struct dstat *vacant_dstats_list = NULL;
86 static struct rb_root dstat_tree[2] = { RB_ROOT, RB_ROOT };
87 static struct dstat *dstat_list[2] = {};
88 static int dstat_curr = 0;
89
90 static struct output drvdata, human, binary, debug;
91
92 static char *msg_q_name = NULL;
93 static int msg_q_id = -1, msg_q = -1;
94 static long msg_id = -1;
95
96 static pthread_t interval_thread;
97 static pthread_mutex_t dstat_mutex = PTHREAD_MUTEX_INITIALIZER;
98
99 int data_is_native = -1;
100
101 static int up = 1;
102
103 /* debugging */
104 static long leftover = 0, driverdata = 0, match = 0, mismatch = 0, sequence = 0;
105
106 static void dump_bit(struct trace *t, const char *descr)
107 {
108         struct blk_io_trace *bit = &t->bit;
109
110         if (!debug.fn)
111                 return;
112
113         fprintf(debug.fp, "--- %s ---\n", descr);
114         fprintf(debug.fp, "magic    %16d\n", bit->magic);
115         fprintf(debug.fp, "sequence %16d\n", bit->sequence);
116         fprintf(debug.fp, "time     %16ld\n", (unsigned long)bit->time);
117         fprintf(debug.fp, "sector   %16ld\n", (unsigned long)bit->sector);
118         fprintf(debug.fp, "bytes    %16d\n", bit->bytes);
119         fprintf(debug.fp, "action   %16x\n", bit->action);
120         fprintf(debug.fp, "pid      %16d\n", bit->pid);
121         fprintf(debug.fp, "device   %16d\n", bit->device);
122         fprintf(debug.fp, "cpu      %16d\n", bit->cpu);
123         fprintf(debug.fp, "error    %16d\n", bit->error);
124         fprintf(debug.fp, "pdu_len  %16d\n", bit->pdu_len);
125
126         fprintf(debug.fp, "order    %16ld\n", t->sequence);
127 }
128
129 static void dump_bits(struct trace *t1, struct trace *t2, const char *descr)
130 {
131         struct blk_io_trace *bit1 = &t1->bit;
132         struct blk_io_trace *bit2 = &t2->bit;
133
134         if (!debug.fn)
135                 return;
136
137         fprintf(debug.fp, "--- %s ---\n", descr);
138         fprintf(debug.fp, "magic    %16d %16d\n", bit1->magic, bit2->magic);
139         fprintf(debug.fp, "sequence %16d %16d\n",
140                 bit1->sequence, bit2->sequence);
141         fprintf(debug.fp, "time     %16ld %16ld\n",
142                 (unsigned long)bit1->time, (unsigned long)bit2->time);
143         fprintf(debug.fp, "sector   %16ld %16ld\n",
144                 (unsigned long)bit1->sector, (unsigned long)bit2->sector);
145         fprintf(debug.fp, "bytes    %16d %16d\n", bit1->bytes, bit2->bytes);
146         fprintf(debug.fp, "action   %16x %16x\n", bit1->action, bit2->action);
147         fprintf(debug.fp, "pid      %16d %16d\n", bit1->pid, bit2->pid);
148         fprintf(debug.fp, "device   %16d %16d\n", bit1->device, bit2->device);
149         fprintf(debug.fp, "cpu      %16d %16d\n", bit1->cpu, bit2->cpu);
150         fprintf(debug.fp, "error    %16d %16d\n", bit1->error, bit2->error);
151         fprintf(debug.fp, "pdu_len  %16d %16d\n", bit1->pdu_len, bit2->pdu_len);
152
153         fprintf(debug.fp, "order    %16ld %16ld\n", t1->sequence, t2->sequence);
154 }
155
156 static struct dstat *blkiomon_alloc_dstat(void)
157 {
158         struct dstat *dstat;
159
160         if (vacant_dstats_list) {
161                 dstat = vacant_dstats_list;
162                 vacant_dstats_list = dstat->next;
163         } else
164                 dstat = malloc(sizeof(*dstat));
165         if (!dstat) {
166                 perror("blkiomon: could not allocate device statistic");
167                 return NULL;
168         }
169
170         memset(dstat, 0, sizeof(*dstat));
171         return dstat;
172 }
173
174 static struct dstat *blkiomon_find_dstat(struct rb_search *search, __u32 device)
175 {
176         struct rb_node **p = &(dstat_tree[dstat_curr].rb_node);
177         struct rb_node *parent = NULL;
178         struct dstat *dstat;
179
180         while (*p) {
181                 parent = *p;
182
183                 dstat = rb_entry(parent, struct dstat, node);
184
185                 if (dstat->msg.stat.device < device)
186                         p = &(*p)->rb_left;
187                 else if (dstat->msg.stat.device > device)
188                         p = &(*p)->rb_right;
189                 else
190                         return dstat;
191         }
192         search->node_ptr = p;
193         search->parent = parent;
194         return NULL;
195 }
196
197 static struct dstat *blkiomon_get_dstat(__u32 device)
198 {
199         struct dstat *dstat;
200         struct rb_search search;
201
202         pthread_mutex_lock(&dstat_mutex);
203
204         dstat = blkiomon_find_dstat(&search, device);
205         if (dstat)
206                 goto out;
207
208         dstat = blkiomon_alloc_dstat();
209         if (!dstat)
210                 goto out;
211
212         dstat->msg.stat.device = device;
213         dstat->msg.stat.size_mm.min = -1ULL;
214         dstat->msg.stat.d2c_mm.min = -1ULL;
215
216         rb_link_node(&dstat->node, search.parent, search.node_ptr);
217         rb_insert_color(&dstat->node, &dstat_tree[dstat_curr]);
218
219         dstat->next = dstat_list[dstat_curr];
220         dstat_list[dstat_curr] = dstat;
221
222 out:
223         pthread_mutex_unlock(&dstat_mutex);
224         return dstat;
225 }
226
227 static int blkiomon_output_msg_q(struct dstat *dstat)
228 {
229         if (!msg_q_name)
230                 return 0;
231
232         dstat->msg.mtype = msg_id;
233         return msgsnd(msg_q, &dstat->msg, sizeof(struct blkiomon_stat), 0);
234 }
235
236 static int blkiomon_output_binary(struct dstat *dstat)
237 {
238         struct blkiomon_stat *p = &dstat->msg.stat;
239
240         if (!binary.fn)
241                 return 0;
242
243         if (fwrite(p, sizeof(*p), 1, binary.fp) != 1)
244                 goto failed;
245         if (binary.pipe && fflush(binary.fp))
246                 goto failed;
247         return 0;
248
249 failed:
250         fprintf(stderr, "blkiomon: could not write to %s\n", binary.fn);
251         fclose(binary.fp);
252         binary.fn = NULL;
253         return 1;
254 }
255
256 static struct dstat *blkiomon_output(struct dstat *head, struct timespec *ts)
257 {
258         struct dstat *dstat, *tail = NULL;
259
260         for (dstat = head; dstat; dstat = dstat->next) {
261                 dstat->msg.stat.time = ts->tv_sec;
262                 blkiomon_stat_print(human.fp, &dstat->msg.stat);
263                 blkiomon_stat_to_be(&dstat->msg.stat);
264                 blkiomon_output_binary(dstat);
265                 blkiomon_output_msg_q(dstat);
266                 tail = dstat;
267         }
268         return tail;
269 }
270
271 static void *blkiomon_interval(void *data)
272 {
273         struct timespec wake, r;
274         struct dstat *head, *tail;
275         int finished;
276
277         clock_gettime(CLOCK_REALTIME, &wake);
278
279         while (1) {
280                 wake.tv_sec += interval;
281                 if (clock_nanosleep(CLOCK_REALTIME, TIMER_ABSTIME, &wake, &r)) {
282                         perror("blkiomon: interrupted sleep");
283                         continue;
284                 }
285
286                 /* grab tree and make data gatherer build up another tree */
287                 pthread_mutex_lock(&dstat_mutex);
288                 finished = dstat_curr;
289                 dstat_curr = dstat_curr ? 0 : 1;
290                 pthread_mutex_unlock(&dstat_mutex);
291
292                 head = dstat_list[finished];
293                 if (!head)
294                         continue;
295                 dstat_list[finished] = NULL;
296                 dstat_tree[finished] = RB_ROOT;
297                 tail = blkiomon_output(head, &wake);
298
299                 pthread_mutex_lock(&dstat_mutex);
300                 tail->next = vacant_dstats_list;
301                 vacant_dstats_list = head;
302                 pthread_mutex_unlock(&dstat_mutex);
303         }
304         return data;
305 }
306
307 #define BLK_DATADIR(a) (((a) >> BLK_TC_SHIFT) & (BLK_TC_READ | BLK_TC_WRITE))
308
309 static int blkiomon_account(struct blk_io_trace *bit_d,
310                             struct blk_io_trace *bit_c)
311 {
312         struct dstat *dstat;
313         struct blkiomon_stat *p;
314         __u64 d2c = (bit_c->time - bit_d->time) / 1000; /* ns -> us */
315         __u32 size = bit_d->bytes;
316
317         dstat = blkiomon_get_dstat(bit_d->device);
318         if (!dstat)
319                 return 1;
320         p = &dstat->msg.stat;
321
322         if (BLK_DATADIR(bit_c->action) & BLK_TC_READ)
323                 p->read++;
324         else if (BLK_DATADIR(bit_c->action) & BLK_TC_WRITE)
325                 p->write++;
326         else
327                 p->bidir++;
328
329         histlog2_account(p->size_hist, size, &size_hist);
330         histlog2_account(p->d2c_hist, d2c, &d2c_hist);
331         minmax_account(&p->size_mm, size);
332         minmax_account(&p->d2c_mm, d2c);
333         return 0;
334 }
335
336 static struct trace *blkiomon_alloc_trace(void)
337 {
338         struct trace *t = vacant_traces_list;
339         if (t) {
340                 vacant_traces_list = t->next;
341                 vacant_traces--;
342         } else
343                 t = malloc(sizeof(*t));
344         memset(t, 0, sizeof(*t));
345         return t;
346 }
347
348 static void blkiomon_free_trace(struct trace *t)
349 {
350         if (vacant_traces < 256) {
351                 t->next = vacant_traces_list;
352                 vacant_traces_list = t;
353                 vacant_traces++;
354         } else
355                 free(t);
356 }
357
358 static int action(int a)
359 {
360         int bits = BLK_TC_WRITE | BLK_TC_READ | BLK_TC_FS | BLK_TC_PC;
361         return a & (BLK_TC_ACT(bits));
362 }
363
364 static void blkiomon_store_trace(struct trace *t)
365 {
366         int i = t->bit.sector % TRACE_HASH_SIZE;
367
368         t->next = thash[i];
369         thash[i] = t;
370 }
371
372 static struct trace *blkiomon_fetch_trace(struct blk_io_trace *bit)
373 {
374         int i = bit->sector % TRACE_HASH_SIZE;
375         struct trace *t, *prev = NULL;
376
377         for (t = thash[i]; t; t = t->next) {
378                 if (t->bit.device == bit->device &&
379                     t->bit.sector == bit->sector &&
380                     action(t->bit.action) == action(bit->action)) {
381                         if (prev)
382                                 prev->next = t->next;
383                         else
384                                 thash[i] = t->next;
385                         return t;
386                 }
387                 prev = t;
388         }
389         return NULL;
390 }
391
392 static struct trace *blkiomon_do_trace(struct trace *t)
393 {
394         struct trace *t_stored, *t_old, *t_young;
395
396         /* store trace if there is no match yet */
397         t_stored = blkiomon_fetch_trace(&t->bit);
398         if (!t_stored) {
399                 blkiomon_store_trace(t);
400                 return blkiomon_alloc_trace();
401         }
402
403         /* figure out older trace and younger trace */
404         if (t_stored->bit.time < t->bit.time) {
405                 t_old = t_stored;
406                 t_young = t;
407         } else {
408                 t_old = t;
409                 t_young = t_stored;
410         }
411
412         /* we need an older D trace and a younger C trace */
413         if (t_old->bit.action & BLK_TC_ACT(BLK_TC_ISSUE) &&
414             t_young->bit.action & BLK_TC_ACT(BLK_TC_COMPLETE)) {
415                 /* matching D and C traces - update statistics */
416                 match++;
417                 blkiomon_account(&t_old->bit, &t_young->bit);
418                 blkiomon_free_trace(t_stored);
419                 return t;
420         }
421
422         /* no matching D and C traces - keep more recent trace */
423         dump_bits(t_old, t_young, "mismatch");
424         mismatch++;
425         blkiomon_store_trace(t_young);
426         return t_old;
427 }
428
429 static int blkiomon_dump_drvdata(struct blk_io_trace *bit, void *pdu_buf)
430 {
431         if (!drvdata.fn)
432                 return 0;
433
434         if (fwrite(bit, sizeof(*bit), 1, drvdata.fp) != 1)
435                 goto failed;
436         if (fwrite(pdu_buf, bit->pdu_len, 1, drvdata.fp) != 1)
437                 goto failed;
438         if (drvdata.pipe && fflush(drvdata.fp))
439                 goto failed;
440         return 0;
441
442 failed:
443         fprintf(stderr, "blkiomon: could not write to %s\n", drvdata.fn);
444         fclose(drvdata.fp);
445         drvdata.fn = NULL;
446         return 1;
447 }
448
449 static int blkiomon_do_fifo(void)
450 {
451         struct trace *t;
452         struct blk_io_trace *bit;
453         void *pdu_buf = NULL;
454
455         t = blkiomon_alloc_trace();
456         if (!t)
457                 return 1;
458         bit = &t->bit;
459
460         while (up) {
461                 if (fread(bit, sizeof(*bit), 1, ifp) != 1) {
462                         if (!feof(ifp))
463                                 fprintf(stderr,
464                                         "blkiomon: could not read trace");
465                         break;
466                 }
467                 if (ferror(ifp)) {
468                         clearerr(ifp);
469                         perror("blkiomon: error while reading trace");
470                         break;
471                 }
472
473                 if (data_is_native == -1 && check_data_endianness(bit->magic))
474                         break;
475
476                 /* endianess */
477                 trace_to_cpu(bit);
478                 if (verify_trace(bit)) {
479                         perror("blkiomon: bad trace");
480                         break;
481                 }
482
483                 /* read additional trace payload */
484                 if (bit->pdu_len) {
485                         pdu_buf = realloc(pdu_buf, bit->pdu_len);
486                         if (fread(pdu_buf, bit->pdu_len, 1, ifp) != 1) {
487                                 clearerr(ifp);
488                                 perror("blkiomon: could not read payload");
489                                 break;
490                         }
491                 }
492
493                 t->sequence = sequence++;
494
495                 /* forward low-level device driver trace to other tool */
496                 if (bit->action & BLK_TC_ACT(BLK_TC_DRV_DATA)) {
497                         driverdata++;
498                         if (blkiomon_dump_drvdata(bit, pdu_buf))
499                                 break;
500                         continue;
501                 }
502
503                 if (!(bit->action & BLK_TC_ACT(BLK_TC_ISSUE | BLK_TC_COMPLETE)))
504                         continue;
505
506                 /* try to find matching trace and update statistics */
507                 t = blkiomon_do_trace(t);
508                 if (!t)
509                         break;
510                 bit = &t->bit;
511                 /* t and bit will be recycled for next incoming trace */
512         }
513         blkiomon_free_trace(t);
514         free(pdu_buf);
515         return 0;
516 }
517
518 static int blkiomon_open_output(struct output *out)
519 {
520         int mode, vbuf_size;
521
522         if (!out->fn)
523                 return 0;
524
525         if (!strcmp(out->fn, "-")) {
526                 out->fp = fdopen(STDOUT_FILENO, "w");
527                 mode = _IOLBF;
528                 vbuf_size = 4096;
529                 out->pipe = 1;
530         } else {
531                 out->fp = fopen(out->fn, "w");
532                 mode = _IOFBF;
533                 vbuf_size = 128 * 1024;
534                 out->pipe = 0;
535         }
536         if (!out->fp)
537                 goto failed;
538         out->buf = malloc(128 * 1024);
539         if (setvbuf(out->fp, out->buf, mode, vbuf_size))
540                 goto failed;
541         return 0;
542
543 failed:
544         fprintf(stderr, "blkiomon: could not write to %s\n", out->fn);
545         out->fn = NULL;
546         free(out->buf);
547         return 1;
548 }
549
550 static int blkiomon_open_msg_q(void)
551 {
552         key_t key;
553
554         if (!msg_q_name)
555                 return 0;
556         if (!msg_q_id || msg_id <= 0)
557                 return 1;
558         key = ftok(msg_q_name, msg_q_id);
559         if (key == -1)
560                 return 1;
561         while (up) {
562                 msg_q = msgget(key, S_IRWXU);
563                 if (msg_q >= 0)
564                         break;
565         }
566         return (msg_q >= 0 ? 0 : -1);
567 }
568
569 static void blkiomon_debug(void)
570 {
571         int i;
572         struct trace *t;
573
574         if (!debug.fn)
575                 return;
576
577         for (i = 0; i < TRACE_HASH_SIZE; i++)
578                 for (t = thash[i]; t; t = t->next) {
579                         dump_bit(t, "leftover");
580                         leftover++;
581                 }
582
583         fprintf(debug.fp, "%ld leftover, %ld match, %ld mismatch, "
584                 "%ld driverdata, %ld overall\n",
585                 leftover, match, mismatch, driverdata, sequence);
586 }
587
588 #define S_OPTS "b:d:D:h:I:Q:q:m:V"
589
590 static char usage_str[] = "\n\nblkiomon " \
591         "-I <interval>       | --interval=<interval>\n" \
592         "[ -h <file>         | --human-readable=<file> ]\n" \
593         "[ -b <file>         | --binary=<file> ]\n" \
594         "[ -D <file>         | --debug=<file> ]\n" \
595         "[ -Q <path name>    | --msg-queue-name=<path name>]\n" \
596         "[ -q <msg queue id> | --msg-queue-id=<msg queue id>]\n" \
597         "[ -m <msg id>       | --msg-id=<msg id>]\n" \
598         "[ -V                | --version ]\n\n" \
599         "\t-I   Sample interval.\n" \
600         "\t-h   Human-readable output file.\n" \
601         "\t-b   Binary output file.\n" \
602         "\t-d   Output file for data emitted by low level device driver.\n" \
603         "\t-D   Output file for debugging data.\n" \
604         "\t-Qqm Output to message queue using given ID for messages.\n" \
605         "\t-V   Print program version.\n\n";
606
607 static struct option l_opts[] = {
608         {
609                 .name = "human-readable",
610                 .has_arg = required_argument,
611                 .flag = NULL,
612                 .val = 'h'
613         },
614         {
615                 .name = "binary",
616                 .has_arg = required_argument,
617                 .flag = NULL,
618                 .val = 'b'
619         },
620         {
621                 .name = "dump-lldd",
622                 .has_arg = required_argument,
623                 .flag = NULL,
624                 .val = 'd'
625         },
626         {
627                 .name = "debug",
628                 .has_arg = required_argument,
629                 .flag = NULL,
630                 .val = 'D'
631         },
632         {
633                 .name = "interval",
634                 .has_arg = required_argument,
635                 .flag = NULL,
636                 .val = 'I'
637         },
638         {
639                 .name = "msg-queue",
640                 .has_arg = required_argument,
641                 .flag = NULL,
642                 .val = 'Q'
643         },
644         {
645                 .name = "msg-queue-id",
646                 .has_arg = required_argument,
647                 .flag = NULL,
648                 .val = 'q'
649         },
650         {
651                 .name = "msg-id",
652                 .has_arg = required_argument,
653                 .flag = NULL,
654                 .val = 'm'
655         },
656         {
657                 .name = "version",
658                 .has_arg = no_argument,
659                 .flag = NULL,
660                 .val = 'V'
661         },
662         {
663                 .name = NULL,
664         }
665 };
666
667 static void blkiomon_signal(int signal)
668 {
669         fprintf(stderr, "blkiomon: terminated by signal\n");
670         up = signal & 0;
671 }
672
673 int main(int argc, char *argv[])
674 {
675         int c;
676
677         signal(SIGALRM, blkiomon_signal);
678         signal(SIGINT, blkiomon_signal);
679         signal(SIGTERM, blkiomon_signal);
680         signal(SIGQUIT, blkiomon_signal);
681
682         while ((c = getopt_long(argc, argv, S_OPTS, l_opts, NULL)) != -1) {
683                 switch (c) {
684                 case 'h':
685                         human.fn = optarg;
686                         break;
687                 case 'b':
688                         binary.fn = optarg;
689                         break;
690                 case 'd':
691                         drvdata.fn = optarg;
692                         break;
693                 case 'D':
694                         debug.fn = optarg;
695                         break;
696                 case 'I':
697                         interval = atoi(optarg);
698                         break;
699                 case 'Q':
700                         msg_q_name = optarg;
701                         break;
702                 case 'q':
703                         msg_q_id = atoi(optarg);
704                         break;
705                 case 'm':
706                         msg_id = atoi(optarg);
707                         break;
708                 case 'V':
709                         printf("%s version %s\n", argv[0], blkiomon_version);
710                         return 0;
711                 default:
712                         fprintf(stderr, "Usage: %s", usage_str);
713                         return 1;
714                 }
715         }
716
717         if (interval <= 0) {
718                 fprintf(stderr, "Usage: %s", usage_str);
719                 return 1;
720         }
721
722         ifp = fdopen(STDIN_FILENO, "r");
723         if (!ifp) {
724                 perror("blkiomon: could not open stdin for reading");
725                 return 1;
726         }
727
728         if (blkiomon_open_output(&human))
729                 return 1;
730         if (blkiomon_open_output(&binary))
731                 return 1;
732         if (blkiomon_open_output(&drvdata))
733                 return 1;
734         if (blkiomon_open_output(&debug))
735                 return 1;
736         if (blkiomon_open_msg_q())
737                 return 1;
738
739         if (pthread_create(&interval_thread, NULL, blkiomon_interval, NULL)) {
740                 perror("blkiomon: could not create thread");
741                 return 1;
742         }
743
744         blkiomon_do_fifo();
745
746         blkiomon_debug();
747         return 0;
748 }