blob: fcf99c49d11810038f109e8e402e0a672cc95f2c [file] [log] [blame]
Willy Tarreau72c28532009-01-22 18:56:50 +01001/*
2 * haproxy log time reporter
3 *
4 * Copyright 2000-2009 Willy Tarreau <w@1wt.eu>
5 *
6 * This program is free software; you can redistribute it and/or
7 * modify it under the terms of the GNU General Public License
8 * as published by the Free Software Foundation; either version
9 * 2 of the License, or (at your option) any later version.
10 *
11 */
12
13/*
Willy Tarreau214c2032009-02-20 11:02:32 +010014 * gcc -O2 -o halog2 halog2.c -Iinclude src/ebtree.c src/eb32tree.c fgets2.c
Willy Tarreau72c28532009-01-22 18:56:50 +010015 *
16 * Usage:
17 * $0 [ min_delay [ min_count [ field_shift ]]] < haproxy.log
18 * Note: if min_delay < 0, it only outputs lines with status codes 5xx.
19 */
20
21#include <errno.h>
22#include <fcntl.h>
23#include <stdio.h>
24#include <stdlib.h>
25#include <syslog.h>
26#include <string.h>
27#include <unistd.h>
28#include <ctype.h>
29
Willy Tarreau45cb4fb2009-10-26 21:10:04 +010030#include <eb32tree.h>
Willy Tarreau72c28532009-01-22 18:56:50 +010031
32#define ACCEPT_FIELD 6
33#define TIME_FIELD 9
34#define STATUS_FIELD 10
35#define CONN_FIELD 15
36#define MAXLINE 16384
37#define QBITS 4
38
39#define SKIP_CHAR(p,c) do { while (1) if (!*p) break; else if (*(p++) == c) break; } while (0)
40
41/* [0] = err/date, [1] = req, [2] = conn, [3] = resp, [4] = data */
42static struct eb_root timers[5] = {
43 EB_ROOT_UNIQUE, EB_ROOT_UNIQUE, EB_ROOT_UNIQUE,
44 EB_ROOT_UNIQUE, EB_ROOT_UNIQUE,
45};
46
47struct timer {
48 struct eb32_node node;
49 unsigned int count;
50};
51
52
53#define FILT_COUNT_ONLY 0x01
54#define FILT_INVERT 0x02
55#define FILT_QUIET 0x04
56#define FILT_ERRORS_ONLY 0x08
57#define FILT_ACC_DELAY 0x10
58#define FILT_ACC_COUNT 0x20
59#define FILT_GRAPH_TIMERS 0x40
Willy Tarreau214c2032009-02-20 11:02:32 +010060#define FILT_PERCENTILE 0x80
Willy Tarreau5bdfd962009-10-14 15:16:29 +020061#define FILT_TIME_RESP 0x100
62
63#define FILT_INVERT_ERRORS 0x200
64#define FILT_INVERT_TIME_RESP 0x400
Willy Tarreau72c28532009-01-22 18:56:50 +010065
66unsigned int filter = 0;
67unsigned int filter_invert = 0;
Willy Tarreau214c2032009-02-20 11:02:32 +010068const char *line;
Willy Tarreau72c28532009-01-22 18:56:50 +010069
Willy Tarreau214c2032009-02-20 11:02:32 +010070const char *fgets2(FILE *stream);
Willy Tarreau72c28532009-01-22 18:56:50 +010071
72void die(const char *msg)
73{
74 fprintf(stderr,
75 "%s"
Willy Tarreau5bdfd962009-10-14 15:16:29 +020076 "Usage: halog [-c] [-v] [-gt] [-pct] [-s <skip>] [-e|-E] [-rt|-RT <time>] [-ad <delay>] [-ac <count>] < file.log\n"
Willy Tarreau72c28532009-01-22 18:56:50 +010077 "\n",
78 msg ? msg : ""
79 );
80 exit(1);
81}
82
83
84/* return pointer to first char not part of current field starting at <p>. */
85const char *field_stop(const char *p)
86{
87 unsigned char c;
88
89 while (1) {
90 c = *(p++);
91 if (c > ' ')
92 continue;
93 if (c == ' ' || c == '\t' || c == 0)
94 break;
95 }
96 return p - 1;
97}
98
99/* return field <field> (starting from 1) in string <p>. Only consider
100 * contiguous spaces (or tabs) as one delimiter. May return pointer to
101 * last char if field is not found. Equivalent to awk '{print $field}'.
102 */
103const char *field_start(const char *p, int field)
104{
105 unsigned char c;
106 while (1) {
107 /* skip spaces */
108 while (1) {
109 c = *p;
110 if (c > ' ')
111 break;
112 if (c == ' ' || c == '\t')
113 goto next;
114 if (!c) /* end of line */
115 return p;
116 /* other char => new field */
117 break;
118 next:
119 p++;
120 }
121
122 /* start of field */
123 field--;
124 if (!field)
125 return p;
126
127 /* skip this field */
128 while (1) {
129 c = *(p++);
130 if (c > ' ')
131 continue;
132 if (c == ' ' || c == '\t')
133 break;
134 if (c == '\0')
135 return p;
136 }
137 }
138}
139
140/* keep only the <bits> higher bits of <i> */
141static inline unsigned int quantify_u32(unsigned int i, int bits)
142{
143 int high;
144
145 if (!bits)
146 return 0;
147
148 if (i)
149 high = fls_auto(i); // 1 to 32
150 else
151 high = 0;
152
153 if (high <= bits)
154 return i;
155
156 return i & ~((1 << (high - bits)) - 1);
157}
158
159/* keep only the <bits> higher bits of the absolute value of <i>, as well as
160 * its sign. */
161static inline int quantify(int i, int bits)
162{
163 if (i >= 0)
164 return quantify_u32(i, bits);
165 else
166 return -quantify_u32(-i, bits);
167}
168
169/* Insert timer value <v> into tree <r>. A pre-allocated node must be passed
170 * in <alloc>. It may be NULL, in which case the function will allocate it
171 * itself. It will be reset to NULL once consumed. The caller is responsible
172 * for freeing the node once not used anymore. The node where the value was
173 * inserted is returned.
174 */
175struct timer *insert_timer(struct eb_root *r, struct timer **alloc, int v)
176{
177 struct timer *t = *alloc;
178 struct eb32_node *n;
179
180 if (!t) {
181 t = calloc(sizeof(*t), 1);
182 if (unlikely(!t)) {
183 fprintf(stderr, "%s: not enough memory\n", __FUNCTION__);
184 exit(1);
185 }
186 }
187 t->node.key = quantify(v, QBITS); // keep only the higher QBITS bits
188
189 n = eb32i_insert(r, &t->node);
190 if (n == &t->node)
191 t = NULL; /* node inserted, will malloc next time */
192
193 *alloc = t;
194 return container_of(n, struct timer, node);
195}
196
197/* Insert value value <v> into tree <r>. A pre-allocated node must be passed
198 * in <alloc>. It may be NULL, in which case the function will allocate it
199 * itself. It will be reset to NULL once consumed. The caller is responsible
200 * for freeing the node once not used anymore. The node where the value was
201 * inserted is returned.
202 */
203struct timer *insert_value(struct eb_root *r, struct timer **alloc, int v)
204{
205 struct timer *t = *alloc;
206 struct eb32_node *n;
207
208 if (!t) {
209 t = calloc(sizeof(*t), 1);
210 if (unlikely(!t)) {
211 fprintf(stderr, "%s: not enough memory\n", __FUNCTION__);
212 exit(1);
213 }
214 }
215 t->node.key = v;
216
217 n = eb32i_insert(r, &t->node);
218 if (n == &t->node)
219 t = NULL; /* node inserted, will malloc next time */
220
221 *alloc = t;
222 return container_of(n, struct timer, node);
223}
224
225int str2ic(const char *s)
226{
227 int i = 0;
228 int j, k;
229
230 if (*s != '-') {
231 /* positive number */
232 while (1) {
233 j = (*s++) - '0';
234 k = i * 10;
235 if ((unsigned)j > 9)
236 break;
237 i = k + j;
238 }
239 } else {
240 /* negative number */
241 s++;
242 while (1) {
243 j = (*s++) - '0';
244 k = i * 10;
245 if ((unsigned)j > 9)
246 break;
247 i = k - j;
248 }
249 }
250
251 return i;
252}
253
254
255/* Equivalent to strtoul with a length. */
256static inline unsigned int __strl2ui(const char *s, int len)
257{
258 unsigned int i = 0;
259 while (len-- > 0) {
260 i = i * 10 - '0';
261 i += (unsigned char)*s++;
262 }
263 return i;
264}
265
266unsigned int strl2ui(const char *s, int len)
267{
268 return __strl2ui(s, len);
269}
270
271/* Convert "[04/Dec/2008:09:49:40.555]" to an integer equivalent to the time of
272 * the day in milliseconds. It returns -1 for all unparsable values. The parser
273 * looks ugly but gcc emits far better code that way.
274 */
275int convert_date(const char *field)
276{
277 unsigned int h, m, s, ms;
278 unsigned char c;
279 const char *b, *e;
280
281 h = m = s = ms = 0;
282 e = field;
283
284 /* skip the date */
285 while (1) {
286 c = *(e++);
287 if (c == ':')
288 break;
289 if (!c)
290 goto out_err;
291 }
292
293 /* hour + ':' */
294 b = e;
295 while (1) {
296 c = *(e++) - '0';
297 if (c > 9)
298 break;
299 h = h * 10 + c;
300 }
301 if (c == (unsigned char)(0 - '0'))
302 goto out_err;
303
304 /* minute + ':' */
305 b = e;
306 while (1) {
307 c = *(e++) - '0';
308 if (c > 9)
309 break;
310 m = m * 10 + c;
311 }
312 if (c == (unsigned char)(0 - '0'))
313 goto out_err;
314
315 /* second + '.' or ']' */
316 b = e;
317 while (1) {
318 c = *(e++) - '0';
319 if (c > 9)
320 break;
321 s = s * 10 + c;
322 }
323 if (c == (unsigned char)(0 - '0'))
324 goto out_err;
325
326 /* if there's a '.', we have milliseconds */
327 if (c == (unsigned char)('.' - '0')) {
328 /* millisecond second + ']' */
329 b = e;
330 while (1) {
331 c = *(e++) - '0';
332 if (c > 9)
333 break;
334 ms = ms * 10 + c;
335 }
336 if (c == (unsigned char)(0 - '0'))
337 goto out_err;
338 }
339 return (((h * 60) + m) * 60 + s) * 1000 + ms;
340 out_err:
341 return -1;
342}
343
344void truncated_line(int linenum, const char *line)
345{
346 if (!(filter & FILT_QUIET))
347 fprintf(stderr, "Truncated line %d: %s\n", linenum, line);
348}
349
350int main(int argc, char **argv)
351{
352 const char *b, *e, *p;
353 const char *output_file = NULL;
354 int f, tot, last, linenum, err, parse_err;
355 struct timer *t = NULL, *t2;
356 struct eb32_node *n;
357 int val, test;
358 int array[5];
359 int filter_acc_delay = 0, filter_acc_count = 0;
Willy Tarreau5bdfd962009-10-14 15:16:29 +0200360 int filter_time_resp = 0;
Willy Tarreau72c28532009-01-22 18:56:50 +0100361 int skip_fields = 1;
362
363 argc--; argv++;
364 while (argc > 0) {
365 if (*argv[0] != '-')
366 break;
367
368 if (strcmp(argv[0], "-ad") == 0) {
369 if (argc < 2) die("missing option for -ad");
370 argc--; argv++;
371 filter |= FILT_ACC_DELAY;
372 filter_acc_delay = atol(*argv);
373 }
374 else if (strcmp(argv[0], "-ac") == 0) {
375 if (argc < 2) die("missing option for -ac");
376 argc--; argv++;
377 filter |= FILT_ACC_COUNT;
378 filter_acc_count = atol(*argv);
379 }
Willy Tarreau5bdfd962009-10-14 15:16:29 +0200380 else if (strcmp(argv[0], "-rt") == 0) {
381 if (argc < 2) die("missing option for -rt");
382 argc--; argv++;
383 filter |= FILT_TIME_RESP;
384 filter_time_resp = atol(*argv);
385 }
386 else if (strcmp(argv[0], "-RT") == 0) {
387 if (argc < 2) die("missing option for -RT");
388 argc--; argv++;
389 filter |= FILT_TIME_RESP | FILT_INVERT_TIME_RESP;
390 filter_time_resp = atol(*argv);
391 }
Willy Tarreau72c28532009-01-22 18:56:50 +0100392 else if (strcmp(argv[0], "-s") == 0) {
393 if (argc < 2) die("missing option for -s");
394 argc--; argv++;
395 skip_fields = atol(*argv);
396 }
397 else if (strcmp(argv[0], "-e") == 0)
398 filter |= FILT_ERRORS_ONLY;
Willy Tarreau5bdfd962009-10-14 15:16:29 +0200399 else if (strcmp(argv[0], "-E") == 0)
400 filter |= FILT_ERRORS_ONLY | FILT_INVERT_ERRORS;
Willy Tarreau72c28532009-01-22 18:56:50 +0100401 else if (strcmp(argv[0], "-c") == 0)
402 filter |= FILT_COUNT_ONLY;
403 else if (strcmp(argv[0], "-q") == 0)
404 filter |= FILT_QUIET;
405 else if (strcmp(argv[0], "-v") == 0)
406 filter_invert = !filter_invert;
407 else if (strcmp(argv[0], "-gt") == 0)
408 filter |= FILT_GRAPH_TIMERS;
Willy Tarreau214c2032009-02-20 11:02:32 +0100409 else if (strcmp(argv[0], "-pct") == 0)
410 filter |= FILT_PERCENTILE;
Willy Tarreau72c28532009-01-22 18:56:50 +0100411 else if (strcmp(argv[0], "-o") == 0) {
412 if (output_file)
413 die("Fatal: output file name already specified.\n");
414 if (argc < 2)
415 die("Fatal: missing output file name.\n");
416 output_file = argv[1];
417 }
418 argc--;
419 argv++;
420 }
421
422 if (!filter)
423 die("No action specified.\n");
424
425 if (filter & FILT_ACC_COUNT && !filter_acc_count)
426 filter_acc_count=1;
427
428 if (filter & FILT_ACC_DELAY && !filter_acc_delay)
429 filter_acc_delay = 1;
430
431 linenum = 0;
432 tot = 0;
433 parse_err = 0;
434
Willy Tarreau214c2032009-02-20 11:02:32 +0100435 while ((line = fgets2(stdin)) != NULL) {
Willy Tarreau72c28532009-01-22 18:56:50 +0100436 linenum++;
437
Willy Tarreau5bdfd962009-10-14 15:16:29 +0200438 test = 1;
439 if (filter & FILT_TIME_RESP) {
440 int tps;
441
442 /* only report lines with response times larger than filter_time_resp */
443 b = field_start(line, TIME_FIELD + skip_fields);
444 if (!*b) {
445 truncated_line(linenum, line);
446 continue;
447 }
448
449 e = field_stop(b + 1);
450 /* we have field TIME_FIELD in [b]..[e-1] */
451
452 p = b;
453 err = 0;
454 for (f = 0; f < 4 && *p; f++) {
455 tps = str2ic(p);
456 if (tps < 0) {
457 tps = -1;
458 err = 1;
459 }
460
461 SKIP_CHAR(p, '/');
462 }
463
464 if (f < 4) {
465 parse_err++;
466 continue;
467 }
468
469 test &= (tps >= filter_time_resp) ^ !!(filter & FILT_INVERT_TIME_RESP);
470 }
471
Willy Tarreau72c28532009-01-22 18:56:50 +0100472 if (filter & FILT_ERRORS_ONLY) {
473 /* only report erroneous status codes */
474 b = field_start(line, STATUS_FIELD + skip_fields);
475 if (!*b) {
476 truncated_line(linenum, line);
477 continue;
478 }
479 if (*b == '-') {
Willy Tarreau5bdfd962009-10-14 15:16:29 +0200480 test &= !!(filter & FILT_INVERT_ERRORS);
Willy Tarreau72c28532009-01-22 18:56:50 +0100481 } else {
482 val = strl2ui(b, 3);
Willy Tarreau5bdfd962009-10-14 15:16:29 +0200483 test &= (val >= 500 && val <= 599) ^ !!(filter & FILT_INVERT_ERRORS);
Willy Tarreau72c28532009-01-22 18:56:50 +0100484 }
Willy Tarreau72c28532009-01-22 18:56:50 +0100485 }
486
487 if (filter & (FILT_ACC_COUNT|FILT_ACC_DELAY)) {
488 b = field_start(line, ACCEPT_FIELD + skip_fields);
489 if (!*b) {
490 truncated_line(linenum, line);
491 continue;
492 }
493
Willy Tarreau214c2032009-02-20 11:02:32 +0100494 tot++;
Willy Tarreau72c28532009-01-22 18:56:50 +0100495 val = convert_date(b);
496 //printf("date=%s => %d\n", b, val);
497 if (val < 0) {
498 parse_err++;
499 continue;
500 }
501
502 t2 = insert_value(&timers[0], &t, val);
503 t2->count++;
504 continue;
505 }
506
Willy Tarreau214c2032009-02-20 11:02:32 +0100507 if (filter & (FILT_GRAPH_TIMERS|FILT_PERCENTILE)) {
Willy Tarreau72c28532009-01-22 18:56:50 +0100508 int f;
509
510 b = field_start(line, TIME_FIELD + skip_fields);
511 if (!*b) {
512 truncated_line(linenum, line);
513 continue;
514 }
515
516 e = field_stop(b + 1);
517 /* we have field TIME_FIELD in [b]..[e-1] */
518
519 p = b;
520 err = 0;
521 for (f = 0; f < 5 && *p; f++) {
522 array[f] = str2ic(p);
523 if (array[f] < 0) {
524 array[f] = -1;
525 err = 1;
526 }
527
528 SKIP_CHAR(p, '/');
529 }
530
531 if (f < 5) {
532 parse_err++;
533 continue;
534 }
535
536 /* if we find at least one negative time, we count one error
537 * with a time equal to the total session time. This will
538 * emphasize quantum timing effects associated to known
539 * timeouts. Note that on some buggy machines, it is possible
540 * that the total time is negative, hence the reason to reset
541 * it.
542 */
Willy Tarreau214c2032009-02-20 11:02:32 +0100543
544 if (filter & FILT_GRAPH_TIMERS) {
545 if (err) {
546 if (array[4] < 0)
547 array[4] = -1;
548 t2 = insert_timer(&timers[0], &t, array[4]); // total time
549 t2->count++;
550 } else {
551 int v;
Willy Tarreau72c28532009-01-22 18:56:50 +0100552
Willy Tarreau214c2032009-02-20 11:02:32 +0100553 t2 = insert_timer(&timers[1], &t, array[0]); t2->count++; // req
554 t2 = insert_timer(&timers[2], &t, array[2]); t2->count++; // conn
555 t2 = insert_timer(&timers[3], &t, array[3]); t2->count++; // resp
556
557 v = array[4] - array[0] - array[1] - array[2] - array[3]; // data time
558 if (v < 0 && !(filter & FILT_QUIET))
559 fprintf(stderr, "ERR: %s (%d %d %d %d %d => %d)\n",
560 line, array[0], array[1], array[2], array[3], array[4], v);
561 t2 = insert_timer(&timers[4], &t, v); t2->count++;
562 tot++;
563 }
564 } else { /* percentile */
565 if (err) {
566 if (array[4] < 0)
567 array[4] = -1;
568 t2 = insert_value(&timers[0], &t, array[4]); // total time
569 t2->count++;
570 } else {
571 int v;
Willy Tarreau72c28532009-01-22 18:56:50 +0100572
Willy Tarreau214c2032009-02-20 11:02:32 +0100573 t2 = insert_value(&timers[1], &t, array[0]); t2->count++; // req
574 t2 = insert_value(&timers[2], &t, array[2]); t2->count++; // conn
575 t2 = insert_value(&timers[3], &t, array[3]); t2->count++; // resp
576
577 v = array[4] - array[0] - array[1] - array[2] - array[3]; // data time
578 if (v < 0 && !(filter & FILT_QUIET))
579 fprintf(stderr, "ERR: %s (%d %d %d %d %d => %d)\n",
580 line, array[0], array[1], array[2], array[3], array[4], v);
581 t2 = insert_value(&timers[4], &t, v); t2->count++;
582 tot++;
583 }
Willy Tarreau72c28532009-01-22 18:56:50 +0100584 }
585 continue;
586 }
587
Willy Tarreau5bdfd962009-10-14 15:16:29 +0200588 test ^= filter_invert;
589 if (!test)
590 continue;
591
Willy Tarreau72c28532009-01-22 18:56:50 +0100592 /* all other cases mean we just want to count lines */
593 tot++;
Willy Tarreau5bdfd962009-10-14 15:16:29 +0200594 if (!(filter & FILT_COUNT_ONLY))
595 puts(line);
Willy Tarreau72c28532009-01-22 18:56:50 +0100596 }
597
598 if (t)
599 free(t);
600
601 if (filter & FILT_COUNT_ONLY) {
602 printf("%d\n", tot);
603 exit(0);
604 }
605
606 if (filter & FILT_ERRORS_ONLY)
607 exit(0);
608
609 if (filter & (FILT_ACC_COUNT|FILT_ACC_DELAY)) {
610 /* sort and count all timers. Output will look like this :
611 * <accept_date> <delta_ms from previous one> <nb entries>
612 */
613 n = eb32_first(&timers[0]);
614
615 if (n)
616 last = n->key;
617 while (n) {
618 unsigned int d, h, m, s, ms;
619
620 t = container_of(n, struct timer, node);
621 h = n->key;
622 d = h - last;
623 last = h;
624
625 if (d >= filter_acc_delay && t->count >= filter_acc_count) {
626 ms = h % 1000; h = h / 1000;
627 s = h % 60; h = h / 60;
628 m = h % 60; h = h / 60;
629 tot++;
630 printf("%02d:%02d:%02d.%03d %d %d %d\n", h, m, s, ms, last, d, t->count);
631 }
632 n = eb32_next(n);
633 }
634 }
635 else if (filter & FILT_GRAPH_TIMERS) {
636 /* sort all timers */
637 for (f = 0; f < 5; f++) {
638 struct eb32_node *n;
639 int val;
640
641 val = 0;
642 n = eb32_first(&timers[f]);
643 while (n) {
644 int i;
645 double d;
646
647 t = container_of(n, struct timer, node);
648 last = n->key;
649 val = t->count;
650
651 i = (last < 0) ? -last : last;
652 i = fls_auto(i) - QBITS;
653
654 if (i > 0)
655 d = val / (double)(1 << i);
656 else
657 d = val;
658
659 if (d > 0.0) {
660 printf("%d %d %f\n", f, last, d+1.0);
661 tot++;
662 }
663
664 n = eb32_next(n);
665 }
Willy Tarreau214c2032009-02-20 11:02:32 +0100666 }
667 }
668 else if (filter & FILT_PERCENTILE) {
669 /* report timers by percentile :
670 * <percent> <total> <max_req_time> <max_conn_time> <max_resp_time> <max_data_time>
671 * We don't count errs.
672 */
673 struct eb32_node *n[5];
674 unsigned long cum[5];
675 double step;
676
677 for (f = 1; f < 5; f++) {
678 n[f] = eb32_first(&timers[f]);
679 cum[f] = container_of(n[f], struct timer, node)->count;
680 }
681
682 for (step = 1; step <= 1000;) {
683 unsigned int thres = tot * (step / 1000.0);
684
685 printf("%3.1f %d ", step/10.0, thres);
686 for (f = 1; f < 5; f++) {
687 struct eb32_node *next;
688 while (cum[f] < thres) {
689 /* need to find other keys */
690 next = eb32_next(n[f]);
691 if (!next)
692 break;
693 n[f] = next;
694 cum[f] += container_of(next, struct timer, node)->count;
695 }
696
697 /* value still within $step % of total */
698 printf("%d ", n[f]->key);
699 }
700 putchar('\n');
701 if (step >= 100 && step < 900)
702 step += 50; // jump 5% by 5% between those steps.
703 else if (step >= 20 && step < 980)
704 step += 10;
705 else
706 step += 1;
Willy Tarreau72c28532009-01-22 18:56:50 +0100707 }
708 }
709
710 if (!(filter & FILT_QUIET))
711 fprintf(stderr, "%d lines in, %d lines out, %d parsing errors\n",
712 linenum, tot, parse_err);
713 exit(0);
714}
715
716/*
717 * Local variables:
718 * c-indent-level: 8
719 * c-basic-offset: 8
720 * End:
721 */