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

/*
 * Copyright (C) 1996-2015 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(xprof_stats_node ** ii, xprof_stats_node ** jj)
{
    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 *), (QS *) 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);
}

// FIXME:
// this gets colled once per event. This doesn't seem to make much sense,
// does it?
static hrtime_t now;
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	/*
bde978a6	2	* Copyright (C) 1996-2015 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
	65	xprof_comp(xprof_stats_node ii, xprof_stats_node jj)
	66	{
	67	if ((ii)->hist.summ < (jj)->hist.summ)
62e76326	68	return (1);
62e76326	69
88bfe092	70	if ((ii)->hist.summ > (jj)->hist.summ)
62e76326	71	return (-1);
88bfe092	72
	73	return (0);
	74	}
	75
	76	static void
	77	xprof_sorthist(TimersArray * xprof_list)
	78	{
5db6bf73	79	for (int i = 0; i < XPROF_LAST; ++i) {
62e76326	80	sortlist[i] = xprof_list[i];
88bfe092	81	}
62e76326	82
1e6e2c8a	83	qsort(&sortlist[XPROF_PROF_UNACCOUNTED+1], XPROF_LAST - XPROF_PROF_UNACCOUNTED+1, sizeof(xprof_stats_node ), (QS ) xprof_comp);
88bfe092	84	}
	85
	86	static double time_frame;
	87
	88	static void
	89	xprof_show_item(StoreEntry * sentry, const char name, xprof_stats_data hist)
	90	{
	91	storeAppendPrintf(sentry,
e2b35d08	92	"%s\t %" PRIu64 "\t %" PRIu64 "\t %" PRIu64 "\t %" PRIu64 "\t %" PRIu64 "\t %.2f\t %6.3f\t\n",
62e76326	93	name,
	94	hist->count,
	95	hist->summ,
	96	(hist->best != XP_NOBEST ? hist->best : 0),
	97	hist->count ? hist->summ / hist->count : 0,
	98	hist->worst,
	99	hist->count / time_frame,
a98bcbee	100	Math::doublePercent((double) hist->summ, (double) hist->delta));
88bfe092	101	}
	102
	103	static void
43ae1d95	104	xprof_summary_item(StoreEntry * sentry, char const descr, TimersArray list)
88bfe092	105	{
	106	int i;
	107	xprof_stats_node **hist;
	108	xprof_stats_data *show;
	109	xprof_reset(&Totals);
	110	xprof_sorthist(list);
	111	hist = &sortlist[0];
	112
	113	show = &hist[0]->hist;
62e76326	114
88bfe092	115	if (!hist[0]->hist.delta)
62e76326	116	show = &hist[0]->accu;
88bfe092	117
	118	time_frame = (double) show->delta / (double) xprof_average_delta;
	119
	120	storeAppendPrintf(sentry, "\n%s:", descr);
62e76326	121
e2b35d08	122	storeAppendPrintf(sentry, " (Cumulated time: %" PRIu64 ", %.2f sec)\n",
62e76326	123	show->delta,
	124	time_frame
	125	);
	126
88bfe092	127	storeAppendPrintf(sentry,
62e76326	128	"Probe Name\t Events\t cumulated time \t best case \t average \t worst case\t Rate / sec \t %% in int\n");
88bfe092	129
5db6bf73	130	for (i = 0; i < XPROF_LAST; ++i) {
62e76326	131	if (!hist[i]->name)
	132	continue;
	133
	134	show = &hist[i]->hist;
	135
	136	if (!show->count)
	137	continue;
	138
	139	xprof_show_item(sentry, hist[i]->name, show);
	140
	141	Totals.count += show->count;
	142
	143	Totals.summ += show->summ;
	144
	145	Totals.best += (show->best != XP_NOBEST ? show->best : 0);
	146
	147	Totals.worst += show->worst;
	148
	149	Totals.delta = (show->delta > Totals.delta ? show->delta : Totals.delta);
88bfe092	150	}
62e76326	151
88bfe092	152	xprof_show_item(sentry, "TOTALS", &Totals);
	153	}
	154
	155	static void
	156	xprof_average(TimersArray ** list, int secs)
	157	{
	158	int i;
	159	TimersArray *head = xprof_Timers;
	160	TimersArray *hist;
	161	hrtime_t now;
	162	hrtime_t keep;
	163	int doavg = (xprof_events % secs);
	164
	165	if (!*list)
62e76326	166	list = (TimersArray )xcalloc(XPROF_LAST, sizeof(xprof_stats_node));
88bfe092	167
88bfe092	168	hist = *list;
62e76326	169
88bfe092	170	now = get_tick();
88bfe092	171
5db6bf73	172	for (i = 0; i < XPROF_LAST; ++i) {
62e76326	173	hist[i]->name = head[i]->name;
62e76326	174	hist[i]->accu.summ += head[i]->accu.summ;
f53969cc	175	hist[i]->accu.count += head[i]->accu.count; /* accumulate multisec */
62e76326	176
	177	if (!hist[i]->accu.best)
	178	hist[i]->accu.best = head[i]->accu.best;
	179
	180	if (hist[i]->accu.best > head[i]->accu.best)
	181	hist[i]->accu.best = head[i]->accu.best;
	182
	183	if (hist[i]->accu.worst < head[i]->accu.worst)
	184	hist[i]->accu.worst = head[i]->accu.worst;
	185
	186	hist[i]->accu.delta += xprof_delta;
	187
	188	if (!doavg) {
	189	/* we have X seconds accumulated */
	190	xprof_move(&hist[i]->accu, &hist[i]->hist);
	191	xprof_reset(&hist[i]->accu);
	192
	193	hist[i]->accu.start = now;
	194	}
	195
	196	/* reset 0sec counters */
	197	if (secs == 1) {
	198	keep = head[i]->accu.start;
	199	xprof_move(&head[i]->accu, &head[i]->hist);
	200	xprof_reset(&head[i]->accu);
	201	hist[i]->accu.delta = 0;
	202	head[i]->accu.start = keep;
	203	}
88bfe092	204	}
	205	}
	206
	207	void
	208	xprof_summary(StoreEntry * sentry)
	209	{
	210	hrtime_t now = get_tick();
	211
	212	storeAppendPrintf(sentry, "CPU Profiling Statistics:\n");
	213	storeAppendPrintf(sentry,
62e76326	214	" (CPU times are in arbitrary units, most probably in CPU clock ticks)\n");
88bfe092	215	storeAppendPrintf(sentry,
62e76326	216	"Probe Name\t Event Count\t last Interval \t Avg Interval \t since squid start \t (since system boot) \n");
e2b35d08	217	storeAppendPrintf(sentry, "Total\t %lu\t %" PRIu64 " \t %" PRIu64 " \t %" PRIu64 " \t %" PRIu64 "\n",
62e76326	218	(long unsigned) xprof_events,
	219	xprof_delta,
	220	xprof_average_delta,
	221	now - xprof_verystart,
	222	now);
88bfe092	223
	224	xprof_summary_item(sentry, "Last 1 sec averages", xprof_stats_avg1sec);
	225	xprof_summary_item(sentry, "Last 5 sec averages", xprof_stats_avg5sec);
	226	xprof_summary_item(sentry, "Last 30 sec averages", xprof_stats_avg30sec);
	227	xprof_summary_item(sentry, "Last 1 min averages", xprof_stats_avg1min);
	228	xprof_summary_item(sentry, "Last 5 min averages", xprof_stats_avg5min);
	229	xprof_summary_item(sentry, "Last 30 min averages", xprof_stats_avg30min);
	230	xprof_summary_item(sentry, "Last 1 hour averages", xprof_stats_avg1hour);
	231	xprof_summary_item(sentry, "Last 5 hour averages", xprof_stats_avg5hour);
	232	xprof_summary_item(sentry, "Last 24 hour averages", xprof_stats_avg24hour);
	233	}
	234
	235	static inline void
	236	xprof_chk_overhead(int samples)
	237	{
	238	while (samples--) {
62e76326	239	PROF_start(PROF_OVERHEAD);
62e76326	240	PROF_stop(PROF_OVERHEAD);
88bfe092	241	}
	242	}
	243
6b7d87bb FC	244	static void
	245	xprofRegisterWithCacheManager(void)
	246	{
8822ebee	247	Mgr::RegisterAction("cpu_profile", "CPU Profiling Stats", xprof_summary, 0, 1);
6b7d87bb FC	248	}
6b7d87bb FC	249
26ac0430	250	// FIXME:
6852be71 FC	251	// this gets colled once per event. This doesn't seem to make much sense,
6852be71 FC	252	// does it?
88bfe092	253	static hrtime_t now;
	254	static void
	255	xprof_Init(void)
	256	{
	257	if (xprof_inited)
62e76326	258	return;
88bfe092	259
	260	xprof_delta = xprof_verystart = xprof_start_t = now;
	261
	262	xprof_inited = 1;
6852be71 FC	263
6852be71 FC	264	xprofRegisterWithCacheManager(); //moved here so it's not double-init'ed
62ee09ca	265	}
62e76326	266
88bfe092	267	void
	268	xprof_event(void *data)
	269	{
	270	now = get_tick();
	271	xprof_Init();
	272	xprof_delta = now - xprof_start_t;
	273	xprof_start_t = now;
5db6bf73	274	++xprof_events;
88bfe092	275
88bfe092	276	if (!xprof_average_delta)
62e76326	277	xprof_average_delta = xprof_delta;
62e76326	278
88bfe092	279	if (xprof_average_delta > (xprof_delta >> 1))
62e76326	280	xprof_average_delta = xprof_average_delta - (xprof_average_delta >> 8) + (xprof_delta >> 8);
88bfe092	281
88bfe092	282	xprof_chk_overhead(2);
62e76326	283
88bfe092	284	xprof_average(&xprof_stats_avg24hour, 24 * 3600);
62e76326	285
88bfe092	286	xprof_average(&xprof_stats_avg5hour, 5 * 3600);
62e76326	287
88bfe092	288	xprof_average(&xprof_stats_avg1hour, 3600);
62e76326	289
88bfe092	290	xprof_average(&xprof_stats_avg30min, 1800);
62e76326	291
88bfe092	292	xprof_average(&xprof_stats_avg5min, 300);
62e76326	293
88bfe092	294	xprof_average(&xprof_stats_avg1min, 60);
62e76326	295
88bfe092	296	xprof_average(&xprof_stats_avg30sec, 30);
62e76326	297
88bfe092	298	xprof_average(&xprof_stats_avg5sec, 5);
62e76326	299
88bfe092	300	xprof_average(&xprof_stats_avg1sec, 1);
62e76326	301
88bfe092	302	xprof_chk_overhead(30);
62e76326	303
88bfe092	304	eventAdd("cpuProfiling", xprof_event, NULL, 1.0, 1);
	305	}
	306
	307	#endif /* USE_XPROF_STATS */
f53969cc	308