varnish-cache/bin/varnishhist/varnishhist.c
1
/*-
2
 * Copyright (c) 2006 Verdens Gang AS
3
 * Copyright (c) 2006-2015 Varnish Software AS
4
 * All rights reserved.
5
 *
6
 * Author: Poul-Henning Kamp <phk@phk.freebsd.dk>
7
 * Author: Dag-Erling Smørgrav <des@des.no>
8
 * Author: Guillaume Quintard <guillaume.quintard@gmail.com>
9
 *
10
 * Redistribution and use in source and binary forms, with or without
11
 * modification, are permitted provided that the following conditions
12
 * are met:
13
 * 1. Redistributions of source code must retain the above copyright
14
 *    notice, this list of conditions and the following disclaimer.
15
 * 2. Redistributions in binary form must reproduce the above copyright
16
 *    notice, this list of conditions and the following disclaimer in the
17
 *    documentation and/or other materials provided with the distribution.
18
 *
19
 * THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
20
 * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
21
 * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
22
 * ARE DISCLAIMED.  IN NO EVENT SHALL AUTHOR OR CONTRIBUTORS BE LIABLE
23
 * FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
24
 * DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
25
 * OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
26
 * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
27
 * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
28
 * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
29
 * SUCH DAMAGE.
30
 *
31
 * Log tailer for Varnish
32
 */
33
34
#include "config.h"
35
36
#include <errno.h>
37
#include <limits.h>
38
#include <math.h>
39
#include <pthread.h>
40
#include <signal.h>
41
#include <stdarg.h>
42
#include <stdlib.h>
43
#include <string.h>
44
#include <unistd.h>
45
46
#define VOPT_DEFINITION
47
#define VOPT_INC "varnishhist_options.h"
48
49
#include "vdef.h"
50
#include "vcurses.h"
51
#include "vapi/vsl.h"
52
#include "vapi/vsm.h"
53
#include "vapi/voptget.h"
54
#include "vas.h"
55
#include "vut.h"
56
#include "vtim.h"
57
58
#define HIST_N 2000             /* how far back we remember */
59
#define HIST_RES 100            /* bucket resolution */
60
61
static struct VUT *vut;
62
63
static int hist_low;
64
static int hist_high;
65
static int hist_range;
66
static unsigned hist_buckets;
67
68
static pthread_mutex_t mtx = PTHREAD_MUTEX_INITIALIZER;
69
70
static int end_of_file = 0;
71
static int ms_delay = 1000;
72
static unsigned rr_hist[HIST_N];
73
static unsigned nhist;
74
static unsigned next_hist;
75
static unsigned *bucket_miss;
76
static unsigned *bucket_hit;
77
static char *format;
78
static int match_tag;
79
static double timebend = 0, t0;
80
static double vsl_t0 = 0, vsl_to, vsl_ts = 0;
81
static pthread_cond_t timebend_cv;
82
static double log_ten;
83
static char *ident;
84
85
static const unsigned scales[] = {
86
        1,
87
        2,
88
        3,
89
        4,
90
        5,
91
        10,
92
        15,
93
        20,
94
        25,
95
        50,
96
        100,
97
        250,
98
        500,
99
        1000,
100
        2500,
101
        5000,
102
        10000,
103
        25000,
104
        50000,
105
        100000,
106
        UINT_MAX
107
};
108
109
struct profile {
110
        const char *name;
111
        char VSL_arg;
112
        enum VSL_tag_e tag;
113
        const char *prefix;
114
        int field;
115
        int hist_low;
116
        int hist_high;
117
};
118
119
#define HIS_PROF(name,vsl_arg,tag,prefix,field,hist_low,high_high,doc)  \
120
        {name,vsl_arg,tag,prefix,field,hist_low,high_high},
121
#define HIS_NO_PREFIX   NULL
122
#define HIS_CLIENT      'c'
123
#define HIS_BACKEND     'b'
124
static const struct profile profiles[] = {
125
#include "varnishhist_profiles.h"
126
        { NULL }
127
};
128
#undef HIS_NO_PREFIX
129
#undef HIS_BACKEND
130
#undef HIS_CLIENT
131
#undef HIS_PROF
132
133
static const struct profile *active_profile;
134
135
static volatile sig_atomic_t quit = 0;
136
137
static void
138 42
update(void)
139 42
{
140
        char t[VTIM_FORMAT_SIZE];
141 42
        const unsigned w = COLS / hist_range;
142 42
        const unsigned n = w * hist_range;
143 42
        unsigned bm[n], bh[n];
144
        unsigned max;
145
        unsigned i, j, scale;
146
        unsigned k, l;
147
148 42
        erase();
149
150
        /* Draw horizontal axis */
151 3066
        for (i = 0; i < n; ++i)
152 3024
                (void)mvaddch(LINES - 2, i, '-');
153 420
        for (k = 0, l = hist_low; k < hist_range; ++k, ++l) {
154 378
                (void)mvaddch(LINES - 2, w * k, '+');
155 378
                mvprintw(LINES - 1, w * k, "|1e%d", l);
156
        }
157
158 42
        if (end_of_file)
159 0
                mvprintw(0, 0, "%*s", COLS - 1, "EOF");
160
        else
161 42
                mvprintw(0, 0, "%*s", COLS - 1, ident);
162
163
        /* count our flock */
164 42
        memset(bm, 0, sizeof bm);
165 42
        memset(bh, 0, sizeof bh);
166 37842
        for (k = 0, max = 1; k < hist_buckets; ++k) {
167 37800
                l = k * n / hist_buckets;
168 37800
                assert(l < n);
169 37800
                bm[l] += bucket_miss[k];
170 37800
                bh[l] += bucket_hit[k];
171 37800
                if (bm[l] + bh[l] > max)
172 0
                        max = bm[l] + bh[l];
173
        }
174
175
        /* scale,time */
176 42
        assert(LINES - 3 >= 0);
177 42
        for (i = 0; max / scales[i] > (unsigned)(LINES - 3); ++i)
178
                /* nothing */ ;
179 42
        scale = scales[i];
180
181 42
        if (vsl_t0 > 0) {
182 0
                VTIM_format(vsl_ts, t);
183
184 0
                mvprintw(0, 0, "1:%u, n = %u, d = %g @ %s x %g",
185
                    scale, nhist, 1e-3 * ms_delay, t, timebend);
186
        } else
187 42
                mvprintw(0, 0, "1:%u, n = %u, d = %g",
188
                    scale, nhist, 1e-3 * ms_delay);
189
190 210
        for (j = 5; j < LINES - 2; j += 5)
191 168
                mvprintw((LINES - 2) - j, 0, "%u_", j * scale);
192
193
        /* show them */
194 3066
        for (i = 0; i < n; ++i) {
195 3060
                for (j = 0; j < bm[i] / scale; ++j)
196 36
                        (void)mvaddch((LINES - 3) - j, i, '#');
197 3024
                for (; j < (bm[i] + bh[i]) / scale; ++j)
198 0
                        (void)mvaddch((LINES - 3) - j, i, '|');
199
        }
200
201 42
        refresh();
202 42
}
203
204
inline static void
205 3
upd_vsl_ts(const char *p)
206
{
207
        double t;
208
209 3
        if (timebend == 0)
210 3
                return;
211
212 0
        p = strchr(p, ' ');
213
214 0
        if (p == NULL)
215 0
                return;
216
217 0
        t = strtod(p + 1, NULL);
218
219 0
        if (t > vsl_ts)
220 0
                vsl_ts = t;
221
}
222
223
static int v_matchproto_ (VSLQ_dispatch_f)
224 9
accumulate(struct VSL_data *vsl, struct VSL_transaction * const pt[],
225
    void *priv)
226
{
227
        int i, tag, skip, match, hit;
228
        unsigned u;
229 9
        double value = 0;
230
        struct VSL_transaction *tr;
231
        double t;
232
        const char *tsp;
233
234
        (void)vsl;
235
        (void)priv;
236
237 18
        for (tr = pt[0]; tr != NULL; tr = *++pt) {
238 9
                if (tr->reason == VSL_r_esi)
239
                        /* Skip ESI requests */
240 0
                        continue;
241
242 9
                hit = 0;
243 9
                skip = 0;
244 9
                match = 0;
245 9
                tsp = NULL;
246 225
                while (skip == 0) {
247 216
                        i = VSL_Next(tr->c);
248 216
                        if (i == -3) {
249
                                /* overrun - need to skip forward */
250 0
                                AZ(pthread_mutex_lock(&mtx));
251 0
                                vsl_to = vsl_t0 = vsl_ts = 0;
252 0
                                t0 = VTIM_mono();
253 0
                                AZ(pthread_mutex_unlock(&mtx));
254 0
                                break;
255
                        }
256 216
                        if (i != 1)
257 9
                                break;
258
259
                        /* get the value we want and register if it's a hit */
260 207
                        tag = VSL_TAG(tr->c->rec.ptr);
261
262 207
                        if (VSL_tagflags[tag])
263 0
                                continue;
264
265 207
                        switch (tag) {
266
                        case SLT_Hit:
267 0
                                hit = 1;
268 0
                                break;
269
                        case SLT_VCL_return:
270 18
                                if (!strcasecmp(VSL_CDATA(tr->c->rec.ptr),
271 18
                                    "restart") ||
272 18
                                    !strcasecmp(VSL_CDATA(tr->c->rec.ptr),
273
                                    "retry"))
274 0
                                        skip = 1;
275 18
                                break;
276
                        case SLT_Timestamp:
277 27
                                tsp = VSL_CDATA(tr->c->rec.ptr);
278
                                /* FALLTHROUGH */
279
                        default:
280 189
                                if (tag != match_tag)
281 162
                                        break;
282
283 54
                                if (active_profile->prefix &&
284 54
                                    strncmp(VSL_CDATA(tr->c->rec.ptr),
285 27
                                    active_profile->prefix,
286 27
                                    strlen(active_profile->prefix)) != 0)
287 24
                                        break;
288
289 3
                                i = sscanf(VSL_CDATA(tr->c->rec.ptr),
290
                                    format, &value);
291 3
                                if (i != 1)
292 0
                                        break;
293 3
                                match = 1;
294 3
                                break;
295
                        }
296
                }
297
298 9
                if (skip || !match)
299 6
                        continue;
300
301
                /* select bucket */
302 3
                i = HIST_RES * lround(log(value) / log_ten);
303 3
                if (i < hist_low * HIST_RES)
304 0
                        i = hist_low * HIST_RES;
305 3
                if (i >= hist_high * HIST_RES)
306 0
                        i = hist_high * HIST_RES - 1;
307 3
                i -= hist_low * HIST_RES;
308 3
                assert(i >= 0);
309 3
                assert(i < hist_buckets);
310
311 3
                AZ(pthread_mutex_lock(&mtx));
312
313
                /*
314
                 * only parse the last tsp seen in this transaction -
315
                 * it should be the latest.
316
                 */
317 3
                if (tsp)
318 3
                        upd_vsl_ts(tsp);
319
320
                /* phase out old data */
321 3
                if (nhist == HIST_N) {
322 0
                        u = rr_hist[next_hist];
323 0
                        if (u >= hist_buckets) {
324 0
                                u -= hist_buckets;
325 0
                                assert(u < hist_buckets);
326 0
                                assert(bucket_hit[u] > 0);
327 0
                                bucket_hit[u]--;
328
                        } else {
329 0
                                assert(bucket_miss[u] > 0);
330 0
                                bucket_miss[u]--;
331
                        }
332
                } else {
333 3
                        ++nhist;
334
                }
335
336
                /* phase in new data */
337 3
                if (hit) {
338 0
                        bucket_hit[i]++;
339 0
                        rr_hist[next_hist] = i + hist_buckets;
340
                } else {
341 3
                        bucket_miss[i]++;
342 3
                        rr_hist[next_hist] = i;
343
                }
344 3
                if (++next_hist == HIST_N) {
345 0
                        next_hist = 0;
346
                }
347 3
                AZ(pthread_mutex_unlock(&mtx));
348
        }
349
350 9
        if (vsl_ts < vsl_to)
351 0
                return (0);
352
353 9
        t = VTIM_mono();
354
355 9
        AZ(pthread_mutex_lock(&mtx));
356 9
        if (vsl_t0 == 0)
357 9
                vsl_to = vsl_t0 = vsl_ts;
358
359 9
        assert(t > t0);
360 9
        vsl_to = vsl_t0 + (t - t0) * timebend;
361
362 9
        if (vsl_ts > vsl_to) {
363 0
                double when = VTIM_real() + vsl_ts - vsl_to;
364
                struct timespec ts;
365 0
                ts.tv_nsec = (long)(modf(when, &t) * 1e9);
366 0
                ts.tv_sec = (long)t;
367 0
                i = pthread_cond_timedwait(&timebend_cv, &mtx, &ts);
368 0
                assert(i == 0 || i == ETIMEDOUT);
369
        }
370 9
        AZ(pthread_mutex_unlock(&mtx));
371
372 9
        return (0);
373
}
374
375
static int v_matchproto_(VUT_cb_f)
376 0
sighup(struct VUT *v)
377
{
378 0
        assert(v == vut);
379 0
        quit = 1;
380 0
        return (1);
381
}
382
383
static void * v_matchproto_(pthread_t)
384 3
do_curses(void *arg)
385
{
386
        int ch;
387
        (void)arg;
388
389 3
        initscr();
390 3
        raw();
391 3
        noecho();
392 3
        nonl();
393 3
        intrflush(stdscr, FALSE);
394 3
        curs_set(0);
395 3
        erase();
396 3
        while (!quit) {
397 42
                AZ(pthread_mutex_lock(&mtx));
398 42
                update();
399 42
                AZ(pthread_mutex_unlock(&mtx));
400
401 42
                assert(ms_delay > 0);
402 42
                timeout(ms_delay);
403 42
                switch ((ch = getch())) {
404
                case ERR:
405 21
                        break;
406
#ifdef KEY_RESIZE
407
                case KEY_RESIZE:
408 3
                        erase();
409 3
                        break;
410
#endif
411
                case '\014':    /* Ctrl-L */
412
                case '\024':    /* Ctrl-T */
413 0
                        redrawwin(stdscr);
414 0
                        refresh();
415 0
                        break;
416
                case '\032':    /* Ctrl-Z */
417 0
                        endwin();
418 0
                        AZ(raise(SIGTSTP));
419 0
                        break;
420
                case '\003':    /* Ctrl-C */
421
                case '\021':    /* Ctrl-Q */
422
                case 'Q':
423
                case 'q':
424 3
                        AZ(raise(SIGINT));
425 3
                        endwin();
426 3
                        return (NULL);
427
                case '0':
428
                case '1':
429
                case '2':
430
                case '3':
431
                case '4':
432
                case '5':
433
                case '6':
434
                case '7':
435
                case '8':
436
                case '9':
437 3
                        ms_delay = 1000U << (ch - '0');
438 3
                        break;
439
                case '+':
440 3
                        ms_delay /= 2;
441 3
                        if (ms_delay < 1)
442 0
                                ms_delay = 1;
443 3
                        break;
444
                case '-':
445 3
                        ms_delay *= 2;
446 3
                        break;
447
                case '>':
448
                case '<':
449
                        /* see below */
450 6
                        break;
451
                default:
452 0
                        beep();
453 0
                        break;
454
                }
455
456 39
                if (ch == '<' || ch == '>') {
457 6
                        AZ(pthread_mutex_lock(&mtx));
458 6
                        vsl_to = vsl_t0 = vsl_ts;
459 6
                        t0 = VTIM_mono();
460 6
                        if (timebend == 0)
461 3
                                timebend = 1;
462 3
                        else if (ch == '<')
463 3
                                timebend /= 2;
464
                        else
465 0
                                timebend *= 2;
466 6
                        AZ(pthread_cond_broadcast(&timebend_cv));
467 6
                        AZ(pthread_mutex_unlock(&mtx));
468
                }
469
        }
470 0
        endwin();
471 0
        return (NULL);
472
}
473
474
/*--------------------------------------------------------------------*/
475
476
static void v_noreturn_
477 6
usage(int status)
478
{
479
        const char **opt;
480
481 6
        fprintf(stderr, "Usage: %s <options>\n\n", vut->progname);
482 6
        fprintf(stderr, "Options:\n");
483 132
        for (opt = vopt_spec.vopt_usage; *opt != NULL; opt += 2)
484 126
                fprintf(stderr, " %-25s %s\n", *opt, *(opt + 1));
485 6
        exit(status);
486
}
487
488
static void v_noreturn_
489 3
profile_error(const char *s)
490
{
491 3
        fprintf(stderr, "-P: '%s' is not a valid"
492
            " profile name or definition\n", s);
493 3
        exit(1);
494
}
495
496
static void
497 3
vut_sighandler(int sig)
498
{
499
500 3
        if (vut != NULL)
501 3
                VUT_Signaled(vut, sig);
502 3
}
503
504
int
505 39
main(int argc, char **argv)
506
{
507
        int i;
508
        char *colon;
509 39
        const char *ptag, *profile = "responsetime";
510
        pthread_t thr;
511
        int fnum;
512 39
        struct profile cli_p = {0};
513
514 39
        vut = VUT_InitProg(argc, argv, &vopt_spec);
515 33
        AN(vut);
516 33
        AZ(pthread_cond_init(&timebend_cv, NULL));
517
518 75
        while ((i = getopt(argc, argv, vopt_spec.vopt_optstring)) != -1) {
519 30
                switch (i) {
520
                case 'h':
521
                        /* Usage help */
522 3
                        usage(0);
523
                case 'p':
524 3
                        ms_delay = lround(1e3 * strtod(optarg, NULL));
525 3
                        if (ms_delay <= 0)
526 3
                                VUT_Error(vut, 1, "-p: invalid '%s'", optarg);
527 0
                        break;
528
                case 'P':
529 9
                        colon = strchr(optarg, ':');
530
                        /* no colon, take the profile as a name */
531 9
                        if (colon == NULL) {
532 3
                                profile = optarg;
533 3
                                break;
534
                        }
535
                        /* else check if valid definition */
536 6
                        if (colon == optarg + 1 &&
537 0
                            (*optarg == 'b' || *optarg == 'c')) {
538 0
                                cli_p.VSL_arg = *optarg;
539 0
                                ptag = colon + 1;
540 0
                                colon = strchr(colon + 1, ':');
541 0
                                if (colon == NULL)
542 0
                                        profile_error(optarg);
543
                        } else {
544 6
                                ptag = optarg;
545 6
                                cli_p.VSL_arg = 'c';
546
                        }
547
548 6
                        assert(colon);
549
550 6
                        match_tag = VSL_Name2Tag(ptag, colon - ptag);
551 6
                        if (match_tag < 0)
552 3
                                VUT_Error(vut, 1,
553
                                    "-P: '%s' is not a valid tag name",
554
                                    optarg);
555
556 3
                        if (VSL_tagflags[match_tag])
557 0
                                VUT_Error(vut, 1,
558
                                    "-P: '%s' is an unsafe or binary record",
559
                                    optarg);
560
561 3
                        cli_p.prefix = colon + 1;
562
563 3
                        colon = strchr(colon + 1, ':');
564 3
                        if (colon == NULL)
565 0
                                profile_error(optarg);
566
567 3
                        *colon = '\0';
568 3
                        if (*cli_p.prefix == '\0')
569 3
                                cli_p.prefix = NULL;
570
571 3
                        if (sscanf(colon + 1, "%d",  &cli_p.field) != 1)
572 3
                                profile_error(optarg);
573
574 0
                        cli_p.name = "custom";
575 0
                        cli_p.tag = (enum VSL_tag_e)match_tag;
576 0
                        cli_p.hist_low = -6;
577 0
                        cli_p.hist_high = 3;
578 0
                        profile = NULL;
579 0
                        active_profile = &cli_p;
580
581 0
                        colon = strchr(colon + 1, ':');
582 0
                        if (colon == NULL)
583 0
                                break;
584
585 0
                        if (sscanf(colon + 1, "%d:%d",  &cli_p.hist_low,
586
                                   &cli_p.hist_high) != 2)
587 0
                                profile_error(optarg);
588
589 0
                        break;
590
                case 'B':
591 6
                        timebend = strtod(optarg, NULL);
592 6
                        if (timebend == 0)
593 3
                                VUT_Error(vut, 1,
594
                                    "-B: being able to bend time does not"
595
                                    " mean we can stop it"
596
                                    " (invalid factor '%s')", optarg);
597 3
                        if (timebend < 0)
598 3
                                VUT_Error(vut, 1,
599
                                    "-B: being able to bend time does not"
600
                                    " mean we can make it go backwards"
601
                                    " (invalid factor '%s')", optarg);
602 0
                        break;
603
                default:
604 9
                        if (!VUT_Arg(vut, i, optarg))
605 0
                                usage(1);
606
                }
607
        }
608
609 12
        if (optind != argc)
610 3
                usage(1);
611
612
        /* Check for valid grouping mode */
613 9
        assert(vut->g_arg < VSL_g__MAX);
614 9
        if (vut->g_arg != VSL_g_vxid && vut->g_arg != VSL_g_request)
615 3
                VUT_Error(vut, 1, "Invalid grouping mode: %s"
616
                    " (only vxid and request are supported)",
617 3
                    VSLQ_grouping[vut->g_arg]);
618
619 6
        if (profile) {
620 33
                for (active_profile = profiles; active_profile->name;
621 21
                     active_profile++) {
622 24
                        if (strcmp(active_profile->name, profile) == 0)
623 3
                                break;
624
                }
625
        }
626 6
        AN(active_profile);
627 6
        if (!active_profile->name)
628 3
                VUT_Error(vut, 1, "-P: No such profile '%s'", profile);
629
630 3
        assert(active_profile->VSL_arg == 'b' ||
631
            active_profile->VSL_arg == 'c');
632 3
        assert(VUT_Arg(vut, active_profile->VSL_arg, NULL));
633 3
        match_tag = active_profile->tag;
634 3
        fnum = active_profile->field;
635 3
        hist_low = active_profile->hist_low;
636 3
        hist_high = active_profile->hist_high;
637
638 3
        hist_range = hist_high - hist_low;
639 3
        hist_buckets = hist_range * HIST_RES;
640 3
        bucket_hit = calloc(hist_buckets, sizeof *bucket_hit);
641 3
        bucket_miss = calloc(hist_buckets, sizeof *bucket_miss);
642
643 3
        if (timebend > 0)
644 0
                t0 = VTIM_mono();
645
646 3
        format = malloc(4L * fnum);
647 3
        AN(format);
648 9
        for (i = 0; i < fnum - 1; i++)
649 6
                strcpy(format + 4 * i, "%*s ");
650 3
        strcpy(format + 4 * (fnum - 1), "%lf");
651
652 3
        log_ten = log(10.0);
653
654 3
        VUT_Signal(vut_sighandler);
655 3
        VUT_Setup(vut);
656 3
        if (vut->vsm)
657 3
                ident = VSM_Dup(vut->vsm, "Arg", "-i");
658
        else
659 0
                ident = strdup("");
660 3
        if (pthread_create(&thr, NULL, do_curses, NULL) != 0)
661 0
                VUT_Error(vut, 1, "pthread_create(): %s", strerror(errno));
662 3
        vut->dispatch_f = accumulate;
663 3
        vut->dispatch_priv = NULL;
664 3
        vut->sighup_f = sighup;
665 3
        VUT_Main(vut);
666 3
        end_of_file = 1;
667 3
        AZ(pthread_join(thr, NULL));
668 3
        VUT_Fini(&vut);
669 3
        exit(0);
670
}