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