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 int hist_buckets;
67
68
static pthread_mutex_t mtx = PTHREAD_MUTEX_INITIALIZER;
69
70
static int end_of_file = 0;
71
static double delay = 1;
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 int 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
        INT_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 0
update(void)
139
{
140
        char t[VTIM_FORMAT_SIZE];
141 0
        const unsigned w = COLS / hist_range;
142 0
        const unsigned n = w * hist_range;
143 0
        unsigned bm[n], bh[n];
144
        unsigned max;
145
        unsigned i, j, scale;
146
        int k, l;
147
148 0
        erase();
149
150
        /* Draw horizontal axis */
151 0
        for (i = 0; i < n; ++i)
152 0
                (void)mvaddch(LINES - 2, i, '-');
153 0
        for (k = 0, l = hist_low; k < hist_range; ++k, ++l) {
154 0
                (void)mvaddch(LINES - 2, w * k, '+');
155 0
                mvprintw(LINES - 1, w * k, "|1e%d", l);
156
        }
157
158 0
        if (end_of_file)
159 0
                mvprintw(0, 0, "%*s", COLS - 1, "EOF");
160
        else
161 0
                mvprintw(0, 0, "%*s", COLS - 1, ident);
162
163
        /* count our flock */
164 0
        for (i = 0; i < n; ++i)
165 0
                bm[i] = bh[i] = 0;
166 0
        for (k = 0, max = 1; k < hist_buckets; ++k) {
167 0
                l = k * n / hist_buckets;
168 0
                bm[l] += bucket_miss[k];
169 0
                bh[l] += bucket_hit[k];
170 0
                if (bm[l] + bh[l] > max)
171 0
                        max = bm[l] + bh[l];
172
        }
173
174
        /* scale,time */
175 0
        assert(LINES - 3 >= 0);
176 0
        for (i = 0; max / scales[i] > (unsigned)(LINES - 3); ++i)
177
                /* nothing */ ;
178 0
        scale = scales[i];
179
180 0
        if (vsl_t0 > 0) {
181 0
                VTIM_format(vsl_ts, t);
182
183 0
                mvprintw(0, 0, "1:%u, n = %u, d = %g @ %s x %g",
184
                    scale, nhist, delay, t, timebend);
185
        } else
186 0
                mvprintw(0, 0, "1:%u, n = %u, d = %g",
187
                    scale, nhist, delay);
188
189 0
        for (j = 2; j < LINES - 3; j += 5)
190 0
                mvprintw(j, 0, "%u_", (LINES - 3 - j) * scale);
191
192
        /* show them */
193 0
        for (i = 0; i < n; ++i) {
194 0
                for (j = 0; j < bm[i] / scale; ++j)
195 0
                        (void)mvaddch(LINES - 3 - j, i, '#');
196 0
                for (; j < (bm[i] + bh[i]) / scale; ++j)
197 0
                        (void)mvaddch(LINES - 3 - j, i, '|');
198
        }
199
200 0
        refresh();
201 0
}
202
203
inline static void
204 0
upd_vsl_ts(const char *p)
205
{
206
        double t;
207
208 0
        if (timebend == 0)
209 0
                return;
210
211 0
        p = strchr(p, ' ');
212
213 0
        if (p == NULL)
214 0
                return;
215
216 0
        t = strtod(p + 1, NULL);
217
218 0
        if (t > vsl_ts)
219 0
                vsl_ts = t;
220
}
221
222
static int v_matchproto_ (VSLQ_dispatch_f)
223 0
accumulate(struct VSL_data *vsl, struct VSL_transaction * const pt[],
224
    void *priv)
225
{
226
        int i, tag, skip, match, hit;
227
        unsigned u;
228 0
        double value = 0;
229
        struct VSL_transaction *tr;
230
        double t;
231
        const char *tsp;
232
233
        (void)vsl;
234
        (void)priv;
235
236 0
        for (tr = pt[0]; tr != NULL; tr = *++pt) {
237 0
                if (tr->reason == VSL_r_esi)
238
                        /* Skip ESI requests */
239 0
                        continue;
240
241 0
                hit = 0;
242 0
                skip = 0;
243 0
                match = 0;
244 0
                tsp = NULL;
245 0
                while (skip == 0) {
246 0
                        i = VSL_Next(tr->c);
247 0
                        if (i == -3) {
248
                                /* overrun - need to skip forward */
249 0
                                AZ(pthread_mutex_lock(&mtx));
250 0
                                vsl_to = vsl_t0 = vsl_ts = 0;
251 0
                                t0 = VTIM_mono();
252 0
                                AZ(pthread_mutex_unlock(&mtx));
253 0
                                break;
254
                        }
255 0
                        if (i != 1)
256 0
                                break;
257
258
                        /* get the value we want and register if it's a hit */
259 0
                        tag = VSL_TAG(tr->c->rec.ptr);
260
261 0
                        switch (tag) {
262
                        case SLT_Hit:
263 0
                                hit = 1;
264 0
                                break;
265
                        case SLT_VCL_return:
266 0
                                if (!strcasecmp(VSL_CDATA(tr->c->rec.ptr),
267 0
                                    "restart") ||
268 0
                                    !strcasecmp(VSL_CDATA(tr->c->rec.ptr),
269
                                    "retry"))
270 0
                                        skip = 1;
271 0
                                break;
272
                        case SLT_Timestamp:
273 0
                                tsp = VSL_CDATA(tr->c->rec.ptr);
274
                                /* FALLTHROUGH */
275
                        default:
276 0
                                if (tag != match_tag)
277 0
                                        break;
278
279 0
                                if (active_profile->prefix &&
280 0
                                    strncmp(VSL_CDATA(tr->c->rec.ptr),
281 0
                                    active_profile->prefix,
282 0
                                    strlen(active_profile->prefix)) != 0)
283 0
                                        break;
284
285 0
                                i = sscanf(VSL_CDATA(tr->c->rec.ptr),
286
                                    format, &value);
287 0
                                if (i != 1)
288 0
                                        break;
289 0
                                match = 1;
290 0
                                break;
291
                        }
292
                }
293
294 0
                if (skip || !match)
295 0
                        continue;
296
297
                /* select bucket */
298 0
                i = HIST_RES * (log(value) / log_ten);
299 0
                if (i < hist_low * HIST_RES)
300 0
                        i = hist_low * HIST_RES;
301 0
                if (i >= hist_high * HIST_RES)
302 0
                        i = hist_high * HIST_RES - 1;
303 0
                i -= hist_low * HIST_RES;
304 0
                assert(i >= 0);
305 0
                assert(i < hist_buckets);
306
307 0
                AZ(pthread_mutex_lock(&mtx));
308
309
                /*
310
                 * only parse the last tsp seen in this transaction -
311
                 * it should be the latest.
312
                 */
313 0
                if (tsp)
314 0
                        upd_vsl_ts(tsp);
315
316
                /* phase out old data */
317 0
                if (nhist == HIST_N) {
318 0
                        u = rr_hist[next_hist];
319 0
                        if (u >= hist_buckets) {
320 0
                                u -= hist_buckets;
321 0
                                assert(u < hist_buckets);
322 0
                                assert(bucket_hit[u] > 0);
323 0
                                bucket_hit[u]--;
324
                        } else {
325 0
                                assert(bucket_miss[u] > 0);
326 0
                                bucket_miss[u]--;
327
                        }
328
                } else {
329 0
                        ++nhist;
330
                }
331
332
                /* phase in new data */
333 0
                if (hit) {
334 0
                        bucket_hit[i]++;
335 0
                        rr_hist[next_hist] = i + hist_buckets;
336
                } else {
337 0
                        bucket_miss[i]++;
338 0
                        rr_hist[next_hist] = i;
339
                }
340 0
                if (++next_hist == HIST_N) {
341 0
                        next_hist = 0;
342
                }
343 0
                AZ(pthread_mutex_unlock(&mtx));
344
        }
345
346 0
        if (vsl_ts < vsl_to)
347 0
                return (0);
348
349 0
        t = VTIM_mono();
350
351 0
        AZ(pthread_mutex_lock(&mtx));
352 0
        if (vsl_t0 == 0)
353 0
                vsl_to = vsl_t0 = vsl_ts;
354
355 0
        assert(t > t0);
356 0
        vsl_to = vsl_t0 + (t - t0) * timebend;
357
358 0
        if (vsl_ts > vsl_to) {
359 0
                double when = VTIM_real() + vsl_ts - vsl_to;
360
                struct timespec ts;
361 0
                ts.tv_nsec = (long)(modf(when, &t) * 1e9);
362 0
                ts.tv_sec = (long)t;
363 0
                i = pthread_cond_timedwait(&timebend_cv, &mtx, &ts);
364 0
                assert(i == 0 || i == ETIMEDOUT);
365
        }
366 0
        AZ(pthread_mutex_unlock(&mtx));
367
368 0
        return (0);
369
}
370
371
static int v_matchproto_(VUT_cb_f)
372 0
sighup(struct VUT *v)
373
{
374 0
        assert(v == vut);
375 0
        quit = 1;
376 0
        return (1);
377
}
378
379
static void * v_matchproto_(pthread_t)
380 0
do_curses(void *arg)
381
{
382
        int ch;
383
        (void)arg;
384
385 0
        initscr();
386 0
        raw();
387 0
        noecho();
388 0
        nonl();
389 0
        intrflush(stdscr, FALSE);
390 0
        curs_set(0);
391 0
        erase();
392 0
        while (!quit) {
393 0
                AZ(pthread_mutex_lock(&mtx));
394 0
                update();
395 0
                AZ(pthread_mutex_unlock(&mtx));
396
397 0
                timeout(delay * 1000);
398 0
                switch ((ch = getch())) {
399
                case ERR:
400 0
                        break;
401
#ifdef KEY_RESIZE
402
                case KEY_RESIZE:
403 0
                        erase();
404 0
                        break;
405
#endif
406
                case '\014':    /* Ctrl-L */
407
                case '\024':    /* Ctrl-T */
408 0
                        redrawwin(stdscr);
409 0
                        refresh();
410 0
                        break;
411
                case '\032':    /* Ctrl-Z */
412 0
                        endwin();
413 0
                        raise(SIGTSTP);
414 0
                        break;
415
                case '\003':    /* Ctrl-C */
416
                case '\021':    /* Ctrl-Q */
417
                case 'Q':
418
                case 'q':
419 0
                        raise(SIGINT);
420 0
                        endwin();
421 0
                        return (NULL);
422
                case '0':
423
                case '1':
424
                case '2':
425
                case '3':
426
                case '4':
427
                case '5':
428
                case '6':
429
                case '7':
430
                case '8':
431
                case '9':
432 0
                        delay = 1 << (ch - '0');
433 0
                        break;
434
                case '+':
435 0
                        delay /= 2;
436 0
                        if (delay < 1e-3)
437 0
                                delay = 1e-3;
438 0
                        break;
439
                case '-':
440 0
                        delay *= 2;
441 0
                        break;
442
                case '>':
443
                case '<':
444
                        /* see below */
445 0
                        break;
446
                default:
447 0
                        beep();
448 0
                        break;
449
                }
450
451 0
                if (ch == '<' || ch == '>') {
452 0
                        AZ(pthread_mutex_lock(&mtx));
453 0
                        vsl_to = vsl_t0 = vsl_ts;
454 0
                        t0 = VTIM_mono();
455 0
                        if (timebend == 0)
456 0
                                timebend = 1;
457 0
                        else if (ch == '<')
458 0
                                timebend /= 2;
459
                        else
460 0
                                timebend *= 2;
461 0
                        AZ(pthread_cond_broadcast(&timebend_cv));
462 0
                        AZ(pthread_mutex_unlock(&mtx));
463
                }
464
        }
465 0
        endwin();
466 0
        return (NULL);
467
}
468
469
/*--------------------------------------------------------------------*/
470
471
static void v_noreturn_
472 4
usage(int status)
473
{
474
        const char **opt;
475
476 4
        fprintf(stderr, "Usage: %s <options>\n\n", vut->progname);
477 4
        fprintf(stderr, "Options:\n");
478 84
        for (opt = vopt_spec.vopt_usage; *opt != NULL; opt += 2)
479 80
                fprintf(stderr, " %-25s %s\n", *opt, *(opt + 1));
480 4
        exit(status);
481
}
482
483
static void
484 2
profile_error(const char *s)
485
{
486 2
        fprintf(stderr, "-P: '%s' is not a valid"
487
            " profile name or definition\n", s);
488 2
        exit(1);
489
}
490
491
static void
492 0
vut_sighandler(int sig)
493
{
494 0
        VUT_Signaled(vut, sig);
495 0
}
496
497
int
498 24
main(int argc, char **argv)
499
{
500
        int i;
501
        const char *colon, *ptag;
502 24
        const char *profile = "responsetime";
503
        pthread_t thr;
504 24
        int fnum = -1;
505 24
        struct profile cli_p = {0};
506 24
        cli_p.name = 0;
507
508 24
        vut = VUT_InitProg(argc, argv, &vopt_spec);
509 20
        AN(vut);
510 20
        AZ(pthread_cond_init(&timebend_cv, NULL));
511
512 44
        while ((i = getopt(argc, argv, vopt_spec.vopt_optstring)) != -1) {
513 18
                switch (i) {
514
                case 'h':
515
                        /* Usage help */
516 2
                        usage(0);
517
                case 'p':
518 2
                        delay = strtod(optarg, NULL);
519 2
                        if (delay <= 0)
520 2
                                VUT_Error(vut, 1, "-p: invalid '%s'", optarg);
521 0
                        break;
522
                case 'P':
523 6
                        colon = strchr(optarg, ':');
524
                        /* no colon, take the profile as a name */
525 6
                        if (colon == NULL) {
526 2
                                profile = optarg;
527 2
                                break;
528
                        }
529
                        /* else it's a definition, we hope */
530 4
                        if (colon == optarg + 1 &&
531 0
                            (*optarg == 'b' || *optarg == 'c')) {
532 0
                                cli_p.VSL_arg = *optarg;
533 0
                                ptag = colon + 1;
534 0
                                colon = strchr(colon + 1, ':');
535 0
                                if (colon == NULL)
536 0
                                        profile_error(optarg);
537
                        } else {
538 4
                                ptag = optarg;
539 4
                                cli_p.VSL_arg = 'c';
540
                        }
541
542 4
                        assert(colon);
543 4
                        if (sscanf(colon + 1, "%d:%d:%d", &cli_p.field,
544
                            &cli_p.hist_low, &cli_p.hist_high) != 3)
545 2
                                profile_error(optarg);
546
547 2
                        match_tag = VSL_Name2Tag(ptag, colon - ptag);
548 2
                        if (match_tag < 0)
549 2
                                VUT_Error(vut, 1,
550
                                    "-P: '%s' is not a valid tag name",
551
                                    optarg);
552 0
                        cli_p.name = "custom";
553 0
                        cli_p.tag = match_tag;
554 0
                        profile = NULL;
555 0
                        active_profile = &cli_p;
556
557 0
                        break;
558
                case 'B':
559 4
                        timebend = strtod(optarg, NULL);
560 4
                        if (timebend == 0)
561 2
                                VUT_Error(vut, 1,
562
                                    "-B: being able to bend time does not"
563
                                    " mean we can stop it"
564
                                    " (invalid factor '%s')", optarg);
565 2
                        if (timebend < 0)
566 2
                                VUT_Error(vut, 1,
567
                                    "-B: being able to bend time does not"
568
                                    " mean we can make it go backwards"
569
                                    " (invalid factor '%s')", optarg);
570 0
                        break;
571
                default:
572 4
                        if (!VUT_Arg(vut, i, optarg))
573 0
                                usage(1);
574
                }
575
        }
576
577 6
        if (optind != argc)
578 2
                usage(1);
579
580
        /* Check for valid grouping mode */
581 4
        assert(vut->g_arg < VSL_g__MAX);
582 4
        if (vut->g_arg != VSL_g_vxid && vut->g_arg != VSL_g_request)
583 2
                VUT_Error(vut, 1, "Invalid grouping mode: %s"
584
                    " (only vxid and request are supported)",
585 2
                    VSLQ_grouping[vut->g_arg]);
586
587 2
        if (profile) {
588 16
                for (active_profile = profiles; active_profile->name;
589 12
                     active_profile++) {
590 12
                        if (strcmp(active_profile->name, profile) == 0)
591 0
                                break;
592
                }
593
        }
594 2
        AN(active_profile);
595 2
        if (!active_profile->name)
596 2
                VUT_Error(vut, 1, "-P: No such profile '%s'", profile);
597
598 0
        assert(active_profile->VSL_arg == 'b' ||
599
            active_profile->VSL_arg == 'c');
600 0
        assert(VUT_Arg(vut, active_profile->VSL_arg, NULL));
601 0
        match_tag = active_profile->tag;
602 0
        fnum = active_profile->field;
603 0
        hist_low = active_profile->hist_low;
604 0
        hist_high = active_profile->hist_high;
605
606 0
        hist_range = hist_high - hist_low;
607 0
        hist_buckets = hist_range * HIST_RES;
608 0
        bucket_hit = calloc(hist_buckets, sizeof *bucket_hit);
609 0
        bucket_miss = calloc(hist_buckets, sizeof *bucket_miss);
610
611 0
        if (timebend > 0)
612 0
                t0 = VTIM_mono();
613
614 0
        format = malloc(4L * fnum);
615 0
        AN(format);
616 0
        for (i = 0; i < fnum - 1; i++)
617 0
                strcpy(format + 4 * i, "%*s ");
618 0
        strcpy(format + 4 * (fnum - 1), "%lf");
619
620 0
        log_ten = log(10.0);
621
622 0
        VUT_Signal(vut_sighandler);
623 0
        VUT_Setup(vut);
624 0
        ident = VSM_Dup(vut->vsm, "Arg", "-i");
625 0
        if (pthread_create(&thr, NULL, do_curses, NULL) != 0)
626 0
                VUT_Error(vut, 1, "pthread_create(): %s", strerror(errno));
627 0
        vut->dispatch_f = accumulate;
628 0
        vut->dispatch_priv = NULL;
629 0
        vut->sighup_f = sighup;
630 0
        VUT_Main(vut);
631 0
        end_of_file = 1;
632 0
        AZ(pthread_join(thr, NULL));
633 0
        VUT_Fini(&vut);
634 0
        exit(0);
635
}