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 6125
update(void)
139 6125
{
140
        char t[VTIM_FORMAT_SIZE];
141 6125
        const unsigned w = COLS / hist_range;
142 6125
        const unsigned n = w * hist_range;
143 6125
        unsigned bm[n], bh[n];
144
        unsigned max;
145
        unsigned i, j, scale;
146
        unsigned k, l;
147
148 6125
        erase();
149
150
        /* Draw horizontal axis */
151 447445
        for (i = 0; i < n; ++i)
152 441320
                (void)mvaddch(LINES - 2, i, '-');
153 60970
        for (k = 0, l = hist_low; k < hist_range; ++k, ++l) {
154 54845
                (void)mvaddch(LINES - 2, w * k, '+');
155 54845
                mvprintw(LINES - 1, w * k, "|1e%d", l);
156
        }
157
158 6125
        if (end_of_file)
159 0
                mvprintw(0, 0, "%*s", COLS - 1, "EOF");
160
        else
161 6125
                mvprintw(0, 0, "%*s", COLS - 1, ident);
162
163
        /* count our flock */
164 6125
        memset(bm, 0, sizeof bm);
165 6125
        memset(bh, 0, sizeof bh);
166 5490625
        for (k = 0, max = 1; k < hist_buckets; ++k) {
167 5484500
                l = k * n / hist_buckets;
168 5484500
                assert(l < n);
169 5484500
                bm[l] += bucket_miss[k];
170 5484500
                bh[l] += bucket_hit[k];
171 5484500
                if (bm[l] + bh[l] > max)
172 0
                        max = bm[l] + bh[l];
173
        }
174
175
        /* scale,time */
176 6125
        assert(LINES - 3 >= 0);
177 6125
        for (i = 0; max / scales[i] > (unsigned)(LINES - 3); ++i)
178
                /* nothing */ ;
179 6125
        scale = scales[i];
180
181 6125
        if (vsl_t0 > 0) {
182 6005
                VTIM_format(vsl_ts, t);
183
184 6005
                mvprintw(0, 0, "1:%u, n = %u, d = %g @ %s x %g",
185
                    scale, nhist, 1e-3 * ms_delay, t, timebend);
186
        } else
187 120
                mvprintw(0, 0, "1:%u, n = %u, d = %g",
188
                    scale, nhist, 1e-3 * ms_delay);
189
190 30625
        for (j = 5; j < LINES - 2; j += 5)
191 24500
                mvprintw((LINES - 2) - j, 0, "%u_", j * scale);
192
193
        /* show them */
194 447445
        for (i = 0; i < n; ++i) {
195 447415
                for (j = 0; j < bm[i] / scale; ++j)
196 6095
                        (void)mvaddch((LINES - 3) - j, i, '#');
197 441375
                for (; j < (bm[i] + bh[i]) / scale; ++j)
198 55
                        (void)mvaddch((LINES - 3) - j, i, '|');
199
        }
200
201 6125
        refresh();
202 6125
}
203
204
inline static void
205 20
upd_vsl_ts(const char *p)
206
{
207
        double t;
208
209 20
        if (timebend == 0)
210 15
                return;
211
212 5
        p = strchr(p, ' ');
213
214 5
        if (p == NULL)
215 0
                return;
216
217 5
        t = strtod(p + 1, NULL);
218
219 5
        if (t > vsl_ts)
220 5
                vsl_ts = t;
221
}
222
223
static int v_matchproto_ (VSLQ_dispatch_f)
224 75
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 75
        double value = 0;
230
        struct VSL_transaction *tr;
231
        double t;
232
        const char *tsp;
233
234
        (void)vsl;
235
        (void)priv;
236
237 150
        for (tr = pt[0]; tr != NULL; tr = *++pt) {
238 75
                if (tr->reason == VSL_r_esi)
239
                        /* Skip ESI requests */
240 0
                        continue;
241
242 75
                hit = 0;
243 75
                skip = 0;
244 75
                match = 0;
245 75
                tsp = NULL;
246 1740
                while (skip == 0) {
247 1665
                        i = VSL_Next(tr->c);
248 1665
                        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 1665
                        if (i != 1)
257 75
                                break;
258
259
                        /* get the value we want and register if it's a hit */
260 1590
                        tag = VSL_TAG(tr->c->rec.ptr);
261
262 1590
                        if (VSL_tagflags[tag])
263 0
                                continue;
264
265 1590
                        switch (tag) {
266
                        case SLT_Hit:
267 15
                                hit = 1;
268 15
                                break;
269
                        case SLT_VCL_return:
270 150
                                if (!strcasecmp(VSL_CDATA(tr->c->rec.ptr),
271 150
                                    "restart") ||
272 150
                                    !strcasecmp(VSL_CDATA(tr->c->rec.ptr),
273
                                    "retry"))
274 0
                                        skip = 1;
275 150
                                break;
276
                        case SLT_Timestamp:
277 195
                                tsp = VSL_CDATA(tr->c->rec.ptr);
278
                                /* FALLTHROUGH */
279
                        default:
280 1425
                                if (tag != match_tag)
281 1290
                                        break;
282
283 265
                                if (active_profile->prefix &&
284 260
                                    strncmp(VSL_CDATA(tr->c->rec.ptr),
285 130
                                    active_profile->prefix,
286 130
                                    strlen(active_profile->prefix)) != 0)
287 115
                                        break;
288
289 20
                                i = sscanf(VSL_CDATA(tr->c->rec.ptr),
290
                                    format, &value);
291 20
                                if (i != 1)
292 0
                                        break;
293 20
                                match = 1;
294 20
                                break;
295
                        }
296
                }
297
298 75
                if (skip || !match || value <= 0)
299 55
                        continue;
300
301
                /* select bucket */
302 20
                i = lround(HIST_RES * log(value) / log_ten);
303 20
                if (i < hist_low * HIST_RES)
304 0
                        i = hist_low * HIST_RES;
305 20
                if (i >= hist_high * HIST_RES)
306 5
                        i = hist_high * HIST_RES - 1;
307 20
                i -= hist_low * HIST_RES;
308 20
                assert(i >= 0);
309 20
                assert(i < hist_buckets);
310
311 20
                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 20
                if (tsp)
318 20
                        upd_vsl_ts(tsp);
319
320
                /* phase out old data */
321 20
                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 20
                        ++nhist;
334
                }
335
336
                /* phase in new data */
337 20
                if (hit) {
338 5
                        bucket_hit[i]++;
339 5
                        rr_hist[next_hist] = i + hist_buckets;
340
                } else {
341 15
                        bucket_miss[i]++;
342 15
                        rr_hist[next_hist] = i;
343
                }
344 20
                if (++next_hist == HIST_N) {
345 0
                        next_hist = 0;
346
                }
347 20
                AZ(pthread_mutex_unlock(&mtx));
348
        }
349
350 75
        if (vsl_ts < vsl_to)
351 20
                return (0);
352
353 55
        t = VTIM_mono();
354
355 55
        AZ(pthread_mutex_lock(&mtx));
356 55
        if (vsl_t0 == 0)
357 55
                vsl_to = vsl_t0 = vsl_ts;
358
359 55
        assert(t > t0);
360 55
        vsl_to = vsl_t0 + (t - t0) * timebend;
361
362 55
        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 55
        AZ(pthread_mutex_unlock(&mtx));
371
372 55
        return (0);
373
}
374
375
static int v_matchproto_(VUT_cb_f)
376 5
sighup(struct VUT *v)
377
{
378 5
        assert(v == vut);
379 5
        quit = 1;
380 5
        return (1);
381
}
382
383
static void * v_matchproto_(pthread_t)
384 15
do_curses(void *arg)
385
{
386
        int ch;
387
        (void)arg;
388
389 15
        initscr();
390 15
        raw();
391 15
        noecho();
392 15
        nonl();
393 15
        intrflush(stdscr, FALSE);
394 15
        curs_set(0);
395 15
        erase();
396 15
        while (!quit) {
397 6125
                AZ(pthread_mutex_lock(&mtx));
398 6125
                update();
399 6125
                AZ(pthread_mutex_unlock(&mtx));
400
401 6125
                assert(ms_delay > 0);
402 6125
                timeout(ms_delay);
403 6125
                switch ((ch = getch())) {
404
                case ERR:
405 6000
                        break;
406
#ifdef KEY_RESIZE
407
                case KEY_RESIZE:
408 5
                        erase();
409 5
                        break;
410
#endif
411
                case '\014':    /* Ctrl-L */
412
                case '\024':    /* Ctrl-T */
413 5
                        redrawwin(stdscr);
414 5
                        refresh();
415 5
                        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 10
                        AZ(raise(SIGINT));
425 10
                        quit = 1;
426 10
                        break;
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 10
                        ms_delay = 1000U << (ch - '0');
438 10
                        break;
439
                case '+':
440 60
                        ms_delay /= 2;
441 60
                        if (ms_delay < 1)
442 10
                                ms_delay = 1;
443 60
                        break;
444
                case '-':
445 10
                        ms_delay *= 2;
446 10
                        break;
447
                case '>':
448
                case '<':
449
                        /* see below */
450 20
                        break;
451
                default:
452 5
                        beep();
453 5
                        break;
454
                }
455
456 6125
                if (ch == '<' || ch == '>') {
457 20
                        AZ(pthread_mutex_lock(&mtx));
458 20
                        vsl_to = vsl_t0 = vsl_ts;
459 20
                        t0 = VTIM_mono();
460 20
                        if (timebend == 0)
461 5
                                timebend = 1;
462 15
                        else if (ch == '<')
463 10
                                timebend /= 2;
464
                        else
465 5
                                timebend *= 2;
466 20
                        AZ(pthread_cond_broadcast(&timebend_cv));
467 20
                        AZ(pthread_mutex_unlock(&mtx));
468
                }
469
        }
470 15
        endwin();
471 15
        return (NULL);
472
}
473
474
/*--------------------------------------------------------------------*/
475
476
static void v_noreturn_
477 15
usage(int status)
478
{
479
        const char **opt;
480
481 15
        fprintf(stderr, "Usage: %s <options>\n\n", vut->progname);
482 15
        fprintf(stderr, "Options:\n");
483 330
        for (opt = vopt_spec.vopt_usage; *opt != NULL; opt += 2)
484 315
                fprintf(stderr, " %-25s %s\n", *opt, *(opt + 1));
485 15
        exit(status);
486
}
487
488
static void v_noreturn_
489 25
profile_error(const char *s)
490
{
491 25
        fprintf(stderr, "-P: '%s' is not a valid"
492
            " profile name or definition\n", s);
493 25
        exit(1);
494
}
495
496
static void
497 15
vut_sighandler(int sig)
498
{
499
500 15
        if (vut != NULL)
501 15
                VUT_Signaled(vut, sig);
502 15
}
503
504
int
505 110
main(int argc, char **argv)
506
{
507
        int i;
508
        char *colon;
509 110
        const char *ptag, *profile = "responsetime";
510
        pthread_t thr;
511
        int fnum;
512 110
        struct profile cli_p = {0};
513
514 110
        vut = VUT_InitProg(argc, argv, &vopt_spec);
515 100
        AN(vut);
516 100
        AZ(pthread_cond_init(&timebend_cv, NULL));
517
518 250
        while ((i = getopt(argc, argv, vopt_spec.vopt_optstring)) != -1) {
519 120
                switch (i) {
520
                case 'h':
521
                        /* Usage help */
522 5
                        usage(0);
523
                case 'p':
524 15
                        ms_delay = lround(1e3 * strtod(optarg, NULL));
525 15
                        if (ms_delay <= 0)
526 10
                                VUT_Error(vut, 1, "-p: invalid '%s'", optarg);
527 5
                        break;
528
                case 'P':
529 55
                        colon = strchr(optarg, ':');
530
                        /* no colon, take the profile as a name */
531 55
                        if (colon == NULL) {
532 10
                                profile = optarg;
533 10
                                break;
534
                        }
535
                        /* else check if valid definition */
536 80
                        if (colon == optarg + 1 &&
537 35
                            (*optarg == 'b' || *optarg == 'c')) {
538 35
                                cli_p.VSL_arg = *optarg;
539 35
                                ptag = colon + 1;
540 35
                                colon = strchr(colon + 1, ':');
541 65
                                if (colon == NULL)
542 5
                                        profile_error(optarg);
543
                        } else {
544 10
                                ptag = optarg;
545 10
                                cli_p.VSL_arg = 'c';
546
                        }
547
548 40
                        assert(colon);
549
550 40
                        match_tag = VSL_Name2Tag(ptag, colon - ptag);
551 40
                        if (match_tag < 0)
552 5
                                VUT_Error(vut, 1,
553
                                    "-P: '%s' is not a valid tag name",
554
                                    optarg);
555
556 35
                        if (VSL_tagflags[match_tag])
557 5
                                VUT_Error(vut, 1,
558
                                    "-P: '%s' is an unsafe or binary record",
559
                                    optarg);
560
561 30
                        cli_p.prefix = colon + 1;
562
563 30
                        colon = strchr(colon + 1, ':');
564 30
                        if (colon == NULL)
565 5
                                profile_error(optarg);
566
567 25
                        *colon = '\0';
568 25
                        if (*cli_p.prefix == '\0')
569 20
                                cli_p.prefix = NULL;
570
571 25
                        if (sscanf(colon + 1, "%d",  &cli_p.field) != 1)
572 10
                                profile_error(optarg);
573
574 15
                        cli_p.name = "custom";
575 15
                        cli_p.tag = (enum VSL_tag_e)match_tag;
576 15
                        cli_p.hist_low = -6;
577 15
                        cli_p.hist_high = 3;
578 15
                        profile = NULL;
579 15
                        active_profile = &cli_p;
580
581 15
                        colon = strchr(colon + 1, ':');
582 15
                        if (colon == NULL)
583 5
                                break;
584
585 10
                        if (sscanf(colon + 1, "%d:%d",  &cli_p.hist_low,
586
                                   &cli_p.hist_high) != 2)
587 5
                                profile_error(optarg);
588
589 5
                        break;
590
                case 'B':
591 15
                        timebend = strtod(optarg, NULL);
592 15
                        if (timebend == 0)
593 5
                                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 10
                        if (timebend < 0)
598 5
                                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 5
                        break;
603
                default:
604 30
                        if (!VUT_Arg(vut, i, optarg))
605 5
                                usage(1);
606
                }
607
        }
608
609 30
        if (optind != argc)
610 5
                usage(1);
611
612
        /* Check for valid grouping mode */
613 25
        assert(vut->g_arg < VSL_g__MAX);
614 25
        if (vut->g_arg != VSL_g_vxid && vut->g_arg != VSL_g_request)
615 5
                VUT_Error(vut, 1, "Invalid grouping mode: %s"
616
                    " (only vxid and request are supported)",
617 5
                    VSLQ_grouping[vut->g_arg]);
618
619 20
        if (profile) {
620 90
                for (active_profile = profiles; active_profile->name;
621 60
                     active_profile++) {
622 70
                        if (strcmp(active_profile->name, profile) == 0)
623 10
                                break;
624
                }
625
        }
626 20
        AN(active_profile);
627 20
        if (!active_profile->name)
628 5
                VUT_Error(vut, 1, "-P: No such profile '%s'", profile);
629
630 15
        assert(active_profile->VSL_arg == 'b' ||
631
            active_profile->VSL_arg == 'c');
632 15
        assert(VUT_Arg(vut, active_profile->VSL_arg, NULL));
633 15
        match_tag = active_profile->tag;
634 15
        fnum = active_profile->field;
635 15
        hist_low = active_profile->hist_low;
636 15
        hist_high = active_profile->hist_high;
637
638 15
        hist_range = hist_high - hist_low;
639 15
        hist_buckets = hist_range * HIST_RES;
640 15
        bucket_hit = calloc(hist_buckets, sizeof *bucket_hit);
641 15
        bucket_miss = calloc(hist_buckets, sizeof *bucket_miss);
642
643 15
        if (timebend > 0)
644 5
                t0 = VTIM_mono();
645
646 15
        format = malloc(4L * fnum);
647 15
        AN(format);
648 55
        for (i = 0; i < fnum - 1; i++)
649 40
                strcpy(format + 4 * i, "%*s ");
650 15
        strcpy(format + 4 * (fnum - 1), "%lf");
651
652 15
        log_ten = log(10.0);
653
654 15
        VUT_Signal(vut_sighandler);
655 15
        VUT_Setup(vut);
656 15
        if (vut->vsm)
657 15
                ident = VSM_Dup(vut->vsm, "Arg", "-i");
658
        else
659 0
                ident = strdup("");
660 15
        AZ(pthread_create(&thr, NULL, do_curses, NULL));
661 15
        vut->dispatch_f = accumulate;
662 15
        vut->dispatch_priv = NULL;
663 15
        vut->sighup_f = sighup;
664 15
        VUT_Main(vut);
665 15
        end_of_file = 1;
666 15
        AZ(pthread_join(thr, NULL));
667 15
        VUT_Fini(&vut);
668 15
        exit(0);
669
}