[thirdparty/squid.git] / src / ProfStats.cc

/*
 * Copyright (C) 1996-2020 The Squid Software Foundation and contributors
 *
 * Squid software is distributed under GPLv2+ license and includes
 * contributions from numerous individuals and organizations.
 * Please see the COPYING and CONTRIBUTORS files for details.
 */

/* DEBUG: section 81    CPU Profiling Routines */

#include "squid.h"

#if USE_XPROF_STATS

#include "event.h"
#include "mgr/Registration.h"
#include "profiler/Profiler.h"
#include "SquidMath.h"
#include "Store.h"

/* Private stuff */

#define MAX_SORTLIST 200

static hrtime_t xprof_delta = 0;
static hrtime_t xprof_start_t = 0;
static hrtime_t xprof_verystart = 0;
static hrtime_t xprof_average_delta = 0;
static int xprof_events = 0;
static int xprof_inited = 0;
static xprof_stats_data Totals;

static TimersArray *xprof_stats_avg1sec = NULL;
static TimersArray *xprof_stats_avg5sec = NULL;
static TimersArray *xprof_stats_avg30sec = NULL;
static TimersArray *xprof_stats_avg1min = NULL;
static TimersArray *xprof_stats_avg5min = NULL;
static TimersArray *xprof_stats_avg30min = NULL;
static TimersArray *xprof_stats_avg1hour = NULL;
static TimersArray *xprof_stats_avg5hour = NULL;
static TimersArray *xprof_stats_avg24hour = NULL;

static xprof_stats_node *sortlist[XPROF_LAST + 2];
static void xprof_summary(StoreEntry * sentry);

static void
xprof_reset(xprof_stats_data * head)
{
    head->summ = 0;
    head->count = 0;
    head->delta = 0;
    head->best = XP_NOBEST;
    head->worst = 0;
    head->start = 0;
    head->stop = 0;
}

static void
xprof_move(xprof_stats_data * head, xprof_stats_data * hist)
{
    memcpy(hist, head, sizeof(xprof_stats_data));
}

static int
xprof_comp(const void *A, const void *B)
{
    const xprof_stats_node *ii = *(static_cast<const xprof_stats_node * const *>(A));
    const xprof_stats_node *jj = *(static_cast<const xprof_stats_node * const *>(B));

    if (ii->hist.summ < jj->hist.summ)
        return (1);

    if (ii->hist.summ > jj->hist.summ)
        return (-1);

    return (0);
}

static void
xprof_sorthist(TimersArray * xprof_list)
{
    for (int i = 0; i < XPROF_LAST; ++i) {
        sortlist[i] = xprof_list[i];
    }

    qsort(&sortlist[XPROF_PROF_UNACCOUNTED+1], XPROF_LAST - XPROF_PROF_UNACCOUNTED+1, sizeof(xprof_stats_node *), xprof_comp);
}

static double time_frame;

static void
xprof_show_item(StoreEntry * sentry, const char *name, xprof_stats_data * hist)
{
    storeAppendPrintf(sentry,
                      "%s\t %" PRIu64 "\t %" PRIu64 "\t %" PRIu64 "\t %" PRIu64 "\t %" PRIu64 "\t %.2f\t %6.3f\t\n",
                      name,
                      hist->count,
                      hist->summ,
                      (hist->best != XP_NOBEST ? hist->best : 0),
                      hist->count ? hist->summ / hist->count : 0,
                      hist->worst,
                      hist->count / time_frame,
                      Math::doublePercent((double) hist->summ, (double) hist->delta));
}

static void
xprof_summary_item(StoreEntry * sentry, char const *descr, TimersArray * list)
{
    int i;
    xprof_stats_node **hist;
    xprof_stats_data *show;
    xprof_reset(&Totals);
    xprof_sorthist(list);
    hist = &sortlist[0];

    show = &hist[0]->hist;

    if (!hist[0]->hist.delta)
        show = &hist[0]->accu;

    time_frame = (double) show->delta / (double) xprof_average_delta;

    storeAppendPrintf(sentry, "\n%s:", descr);

    storeAppendPrintf(sentry, " (Cumulated time: %" PRIu64 ", %.2f sec)\n",
                      show->delta,
                      time_frame
                     );

    storeAppendPrintf(sentry,
                      "Probe Name\t  Events\t cumulated time \t best case \t average \t worst case\t Rate / sec \t %% in int\n");

    for (i = 0; i < XPROF_LAST; ++i) {
        if (!hist[i]->name)
            continue;

        show = &hist[i]->hist;

        if (!show->count)
            continue;

        xprof_show_item(sentry, hist[i]->name, show);

        Totals.count += show->count;

        Totals.summ += show->summ;

        Totals.best += (show->best != XP_NOBEST ? show->best : 0);

        Totals.worst += show->worst;

        Totals.delta = (show->delta > Totals.delta ? show->delta : Totals.delta);
    }

    xprof_show_item(sentry, "TOTALS", &Totals);
}

static void
xprof_average(TimersArray ** list, int secs)
{
    int i;
    TimersArray *head = xprof_Timers;
    TimersArray *hist;
    hrtime_t now;
    hrtime_t keep;
    int doavg = (xprof_events % secs);

    if (!*list)
        *list = (TimersArray *)xcalloc(XPROF_LAST, sizeof(xprof_stats_node));

    hist = *list;

    now = get_tick();

    for (i = 0; i < XPROF_LAST; ++i) {
        hist[i]->name = head[i]->name;
        hist[i]->accu.summ += head[i]->accu.summ;
        hist[i]->accu.count += head[i]->accu.count; /* accumulate multisec */

        if (!hist[i]->accu.best)
            hist[i]->accu.best = head[i]->accu.best;

        if (hist[i]->accu.best > head[i]->accu.best)
            hist[i]->accu.best = head[i]->accu.best;

        if (hist[i]->accu.worst < head[i]->accu.worst)
            hist[i]->accu.worst = head[i]->accu.worst;

        hist[i]->accu.delta += xprof_delta;

        if (!doavg) {
            /* we have X seconds accumulated */
            xprof_move(&hist[i]->accu, &hist[i]->hist);
            xprof_reset(&hist[i]->accu);

            hist[i]->accu.start = now;
        }

        /* reset 0sec counters */
        if (secs == 1) {
            keep = head[i]->accu.start;
            xprof_move(&head[i]->accu, &head[i]->hist);
            xprof_reset(&head[i]->accu);
            hist[i]->accu.delta = 0;
            head[i]->accu.start = keep;
        }
    }
}

void
xprof_summary(StoreEntry * sentry)
{
    hrtime_t now = get_tick();

    storeAppendPrintf(sentry, "CPU Profiling Statistics:\n");
    storeAppendPrintf(sentry,
                      "  (CPU times are in arbitrary units, most probably in CPU clock ticks)\n");
    storeAppendPrintf(sentry,
                      "Probe Name\t Event Count\t last Interval \t Avg Interval \t since squid start \t (since system boot) \n");
    storeAppendPrintf(sentry, "Total\t %lu\t %" PRIu64 " \t %" PRIu64 " \t %" PRIu64 " \t %" PRIu64 "\n",
                      (long unsigned) xprof_events,
                      xprof_delta,
                      xprof_average_delta,
                      now - xprof_verystart,
                      now);

    xprof_summary_item(sentry, "Last 1 sec averages", xprof_stats_avg1sec);
    xprof_summary_item(sentry, "Last 5 sec averages", xprof_stats_avg5sec);
    xprof_summary_item(sentry, "Last 30 sec averages", xprof_stats_avg30sec);
    xprof_summary_item(sentry, "Last 1 min averages", xprof_stats_avg1min);
    xprof_summary_item(sentry, "Last 5 min averages", xprof_stats_avg5min);
    xprof_summary_item(sentry, "Last 30 min averages", xprof_stats_avg30min);
    xprof_summary_item(sentry, "Last 1 hour averages", xprof_stats_avg1hour);
    xprof_summary_item(sentry, "Last 5 hour averages", xprof_stats_avg5hour);
    xprof_summary_item(sentry, "Last 24 hour averages", xprof_stats_avg24hour);
}

static inline void
xprof_chk_overhead(int samples)
{
    while (samples--) {
        PROF_start(PROF_OVERHEAD);
        PROF_stop(PROF_OVERHEAD);
    }
}

static void
xprofRegisterWithCacheManager(void)
{
    Mgr::RegisterAction("cpu_profile", "CPU Profiling Stats", xprof_summary, 0, 1);
}

static hrtime_t now;

// TODO: this gets called once per event. Make it only happen when enabling xprof.
static void
xprof_Init(void)
{
    if (xprof_inited)
        return;

    xprof_delta = xprof_verystart = xprof_start_t = now;

    xprof_inited = 1;

    xprofRegisterWithCacheManager(); //moved here so it's not double-init'ed
}

void
xprof_event(void *data)
{
    now = get_tick();
    xprof_Init();
    xprof_delta = now - xprof_start_t;
    xprof_start_t = now;
    ++xprof_events;

    if (!xprof_average_delta)
        xprof_average_delta = xprof_delta;

    if (xprof_average_delta > (xprof_delta >> 1))
        xprof_average_delta = xprof_average_delta - (xprof_average_delta >> 8) + (xprof_delta >> 8);

    xprof_chk_overhead(2);

    xprof_average(&xprof_stats_avg24hour, 24 * 3600);

    xprof_average(&xprof_stats_avg5hour, 5 * 3600);

    xprof_average(&xprof_stats_avg1hour, 3600);

    xprof_average(&xprof_stats_avg30min, 1800);

    xprof_average(&xprof_stats_avg5min, 300);

    xprof_average(&xprof_stats_avg1min, 60);

    xprof_average(&xprof_stats_avg30sec, 30);

    xprof_average(&xprof_stats_avg5sec, 5);

    xprof_average(&xprof_stats_avg1sec, 1);

    xprof_chk_overhead(30);

    eventAdd("cpuProfiling", xprof_event, NULL, 1.0, 1);
}

#endif /* USE_XPROF_STATS */
Commit	Line	Data
88bfe092	1	/*
77b1029d	2	* Copyright (C) 1996-2020 The Squid Software Foundation and contributors
88bfe092	3	*
bbc27441 AJ	4	* Squid software is distributed under GPLv2+ license and includes
	5	* contributions from numerous individuals and organizations.
	6	* Please see the COPYING and CONTRIBUTORS files for details.
88bfe092	7	*/
88bfe092	8
bbc27441 AJ	9	/* DEBUG: section 81 CPU Profiling Routines */
bbc27441 AJ	10
582c2af2	11	#include "squid.h"
88bfe092	12
32d002cb	13	#if USE_XPROF_STATS
a98bcbee	14
a98bcbee	15	#include "event.h"
8822ebee	16	#include "mgr/Registration.h"
582c2af2	17	#include "profiler/Profiler.h"
a98bcbee	18	#include "SquidMath.h"
e6ccf245	19	#include "Store.h"
88bfe092	20
	21	/* Private stuff */
	22
	23	#define MAX_SORTLIST 200
	24
	25	static hrtime_t xprof_delta = 0;
	26	static hrtime_t xprof_start_t = 0;
	27	static hrtime_t xprof_verystart = 0;
	28	static hrtime_t xprof_average_delta = 0;
	29	static int xprof_events = 0;
	30	static int xprof_inited = 0;
	31	static xprof_stats_data Totals;
	32
	33	static TimersArray *xprof_stats_avg1sec = NULL;
	34	static TimersArray *xprof_stats_avg5sec = NULL;
	35	static TimersArray *xprof_stats_avg30sec = NULL;
	36	static TimersArray *xprof_stats_avg1min = NULL;
	37	static TimersArray *xprof_stats_avg5min = NULL;
	38	static TimersArray *xprof_stats_avg30min = NULL;
	39	static TimersArray *xprof_stats_avg1hour = NULL;
	40	static TimersArray *xprof_stats_avg5hour = NULL;
	41	static TimersArray *xprof_stats_avg24hour = NULL;
	42
	43	static xprof_stats_node *sortlist[XPROF_LAST + 2];
43ae1d95	44	static void xprof_summary(StoreEntry * sentry);
88bfe092	45
	46	static void
	47	xprof_reset(xprof_stats_data * head)
	48	{
	49	head->summ = 0;
	50	head->count = 0;
	51	head->delta = 0;
	52	head->best = XP_NOBEST;
	53	head->worst = 0;
	54	head->start = 0;
	55	head->stop = 0;
	56	}
	57
	58	static void
	59	xprof_move(xprof_stats_data * head, xprof_stats_data * hist)
	60	{
	61	memcpy(hist, head, sizeof(xprof_stats_data));
	62	}
	63
	64	static int
a7614b42	65	xprof_comp(const void A, const void B)
88bfe092	66	{
a7614b42 AJ	67	const xprof_stats_node ii = (static_cast<const xprof_stats_node * const *>(A));
	68	const xprof_stats_node jj = (static_cast<const xprof_stats_node * const *>(B));
	69
	70	if (ii->hist.summ < jj->hist.summ)
62e76326	71	return (1);
62e76326	72
a7614b42	73	if (ii->hist.summ > jj->hist.summ)
62e76326	74	return (-1);
88bfe092	75
	76	return (0);
	77	}
	78
	79	static void
	80	xprof_sorthist(TimersArray * xprof_list)
	81	{
5db6bf73	82	for (int i = 0; i < XPROF_LAST; ++i) {
62e76326	83	sortlist[i] = xprof_list[i];
88bfe092	84	}
62e76326	85
a7614b42	86	qsort(&sortlist[XPROF_PROF_UNACCOUNTED+1], XPROF_LAST - XPROF_PROF_UNACCOUNTED+1, sizeof(xprof_stats_node *), xprof_comp);
88bfe092	87	}
	88
	89	static double time_frame;
	90
	91	static void
	92	xprof_show_item(StoreEntry * sentry, const char name, xprof_stats_data hist)
	93	{
	94	storeAppendPrintf(sentry,
e2b35d08	95	"%s\t %" PRIu64 "\t %" PRIu64 "\t %" PRIu64 "\t %" PRIu64 "\t %" PRIu64 "\t %.2f\t %6.3f\t\n",
62e76326	96	name,
	97	hist->count,
	98	hist->summ,
	99	(hist->best != XP_NOBEST ? hist->best : 0),
	100	hist->count ? hist->summ / hist->count : 0,
	101	hist->worst,
	102	hist->count / time_frame,
a98bcbee	103	Math::doublePercent((double) hist->summ, (double) hist->delta));
88bfe092	104	}
	105
	106	static void
43ae1d95	107	xprof_summary_item(StoreEntry * sentry, char const descr, TimersArray list)
88bfe092	108	{
	109	int i;
	110	xprof_stats_node **hist;
	111	xprof_stats_data *show;
	112	xprof_reset(&Totals);
	113	xprof_sorthist(list);
	114	hist = &sortlist[0];
	115
	116	show = &hist[0]->hist;
62e76326	117
88bfe092	118	if (!hist[0]->hist.delta)
62e76326	119	show = &hist[0]->accu;
88bfe092	120
	121	time_frame = (double) show->delta / (double) xprof_average_delta;
	122
	123	storeAppendPrintf(sentry, "\n%s:", descr);
62e76326	124
e2b35d08	125	storeAppendPrintf(sentry, " (Cumulated time: %" PRIu64 ", %.2f sec)\n",
62e76326	126	show->delta,
	127	time_frame
	128	);
	129
88bfe092	130	storeAppendPrintf(sentry,
62e76326	131	"Probe Name\t Events\t cumulated time \t best case \t average \t worst case\t Rate / sec \t %% in int\n");
88bfe092	132
5db6bf73	133	for (i = 0; i < XPROF_LAST; ++i) {
62e76326	134	if (!hist[i]->name)
	135	continue;
	136
	137	show = &hist[i]->hist;
	138
	139	if (!show->count)
	140	continue;
	141
	142	xprof_show_item(sentry, hist[i]->name, show);
	143
	144	Totals.count += show->count;
	145
	146	Totals.summ += show->summ;
	147
	148	Totals.best += (show->best != XP_NOBEST ? show->best : 0);
	149
	150	Totals.worst += show->worst;
	151
	152	Totals.delta = (show->delta > Totals.delta ? show->delta : Totals.delta);
88bfe092	153	}
62e76326	154
88bfe092	155	xprof_show_item(sentry, "TOTALS", &Totals);
	156	}
	157
	158	static void
	159	xprof_average(TimersArray ** list, int secs)
	160	{
	161	int i;
	162	TimersArray *head = xprof_Timers;
	163	TimersArray *hist;
	164	hrtime_t now;
	165	hrtime_t keep;
	166	int doavg = (xprof_events % secs);
	167
	168	if (!*list)
62e76326	169	list = (TimersArray )xcalloc(XPROF_LAST, sizeof(xprof_stats_node));
88bfe092	170
88bfe092	171	hist = *list;
62e76326	172
88bfe092	173	now = get_tick();
88bfe092	174
5db6bf73	175	for (i = 0; i < XPROF_LAST; ++i) {
62e76326	176	hist[i]->name = head[i]->name;
62e76326	177	hist[i]->accu.summ += head[i]->accu.summ;
f53969cc	178	hist[i]->accu.count += head[i]->accu.count; /* accumulate multisec */
62e76326	179
	180	if (!hist[i]->accu.best)
	181	hist[i]->accu.best = head[i]->accu.best;
	182
	183	if (hist[i]->accu.best > head[i]->accu.best)
	184	hist[i]->accu.best = head[i]->accu.best;
	185
	186	if (hist[i]->accu.worst < head[i]->accu.worst)
	187	hist[i]->accu.worst = head[i]->accu.worst;
	188
	189	hist[i]->accu.delta += xprof_delta;
	190
	191	if (!doavg) {
	192	/* we have X seconds accumulated */
	193	xprof_move(&hist[i]->accu, &hist[i]->hist);
	194	xprof_reset(&hist[i]->accu);
	195
	196	hist[i]->accu.start = now;
	197	}
	198
	199	/* reset 0sec counters */
	200	if (secs == 1) {
	201	keep = head[i]->accu.start;
	202	xprof_move(&head[i]->accu, &head[i]->hist);
	203	xprof_reset(&head[i]->accu);
	204	hist[i]->accu.delta = 0;
	205	head[i]->accu.start = keep;
	206	}
88bfe092	207	}
	208	}
	209
	210	void
	211	xprof_summary(StoreEntry * sentry)
	212	{
	213	hrtime_t now = get_tick();
	214
	215	storeAppendPrintf(sentry, "CPU Profiling Statistics:\n");
	216	storeAppendPrintf(sentry,
62e76326	217	" (CPU times are in arbitrary units, most probably in CPU clock ticks)\n");
88bfe092	218	storeAppendPrintf(sentry,
62e76326	219	"Probe Name\t Event Count\t last Interval \t Avg Interval \t since squid start \t (since system boot) \n");
e2b35d08	220	storeAppendPrintf(sentry, "Total\t %lu\t %" PRIu64 " \t %" PRIu64 " \t %" PRIu64 " \t %" PRIu64 "\n",
62e76326	221	(long unsigned) xprof_events,
	222	xprof_delta,
	223	xprof_average_delta,
	224	now - xprof_verystart,
	225	now);
88bfe092	226
	227	xprof_summary_item(sentry, "Last 1 sec averages", xprof_stats_avg1sec);
	228	xprof_summary_item(sentry, "Last 5 sec averages", xprof_stats_avg5sec);
	229	xprof_summary_item(sentry, "Last 30 sec averages", xprof_stats_avg30sec);
	230	xprof_summary_item(sentry, "Last 1 min averages", xprof_stats_avg1min);
	231	xprof_summary_item(sentry, "Last 5 min averages", xprof_stats_avg5min);
	232	xprof_summary_item(sentry, "Last 30 min averages", xprof_stats_avg30min);
	233	xprof_summary_item(sentry, "Last 1 hour averages", xprof_stats_avg1hour);
	234	xprof_summary_item(sentry, "Last 5 hour averages", xprof_stats_avg5hour);
	235	xprof_summary_item(sentry, "Last 24 hour averages", xprof_stats_avg24hour);
	236	}
	237
	238	static inline void
	239	xprof_chk_overhead(int samples)
	240	{
	241	while (samples--) {
62e76326	242	PROF_start(PROF_OVERHEAD);
62e76326	243	PROF_stop(PROF_OVERHEAD);
88bfe092	244	}
	245	}
	246
6b7d87bb FC	247	static void
	248	xprofRegisterWithCacheManager(void)
	249	{
8822ebee	250	Mgr::RegisterAction("cpu_profile", "CPU Profiling Stats", xprof_summary, 0, 1);
6b7d87bb FC	251	}
6b7d87bb FC	252
88bfe092	253	static hrtime_t now;
9837567d AJ	254
9837567d AJ	255	// TODO: this gets called once per event. Make it only happen when enabling xprof.
88bfe092	256	static void
	257	xprof_Init(void)
	258	{
	259	if (xprof_inited)
62e76326	260	return;
88bfe092	261
	262	xprof_delta = xprof_verystart = xprof_start_t = now;
	263
	264	xprof_inited = 1;
6852be71 FC	265
6852be71 FC	266	xprofRegisterWithCacheManager(); //moved here so it's not double-init'ed
62ee09ca	267	}
62e76326	268
88bfe092	269	void
	270	xprof_event(void *data)
	271	{
	272	now = get_tick();
	273	xprof_Init();
	274	xprof_delta = now - xprof_start_t;
	275	xprof_start_t = now;
5db6bf73	276	++xprof_events;
88bfe092	277
88bfe092	278	if (!xprof_average_delta)
62e76326	279	xprof_average_delta = xprof_delta;
62e76326	280
88bfe092	281	if (xprof_average_delta > (xprof_delta >> 1))
62e76326	282	xprof_average_delta = xprof_average_delta - (xprof_average_delta >> 8) + (xprof_delta >> 8);
88bfe092	283
88bfe092	284	xprof_chk_overhead(2);
62e76326	285
88bfe092	286	xprof_average(&xprof_stats_avg24hour, 24 * 3600);
62e76326	287
88bfe092	288	xprof_average(&xprof_stats_avg5hour, 5 * 3600);
62e76326	289
88bfe092	290	xprof_average(&xprof_stats_avg1hour, 3600);
62e76326	291
88bfe092	292	xprof_average(&xprof_stats_avg30min, 1800);
62e76326	293
88bfe092	294	xprof_average(&xprof_stats_avg5min, 300);
62e76326	295
88bfe092	296	xprof_average(&xprof_stats_avg1min, 60);
62e76326	297
88bfe092	298	xprof_average(&xprof_stats_avg30sec, 30);
62e76326	299
88bfe092	300	xprof_average(&xprof_stats_avg5sec, 5);
62e76326	301
88bfe092	302	xprof_average(&xprof_stats_avg1sec, 1);
62e76326	303
88bfe092	304	xprof_chk_overhead(30);
62e76326	305
88bfe092	306	eventAdd("cpuProfiling", xprof_event, NULL, 1.0, 1);
	307	}
	308
	309	#endif /* USE_XPROF_STATS */
f53969cc	310