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


/*
 * $Id: ProfStats.cc,v 1.3 2003/01/23 00:37:14 robertc Exp $
 *
 * DEBUG: section 81     CPU Profiling Routines
 * AUTHOR: Andres Kroonmaa
 *
 * SQUID Internet Object Cache  http://squid.nlanr.net/Squid/
 * ----------------------------------------------------------
 *
 *  Squid is the result of efforts by numerous individuals from the
 *  Internet community.  Development is led by Duane Wessels of the
 *  National Laboratory for Applied Network Research and funded by the
 *  National Science Foundation.  Squid is Copyrighted (C) 1998 by
 *  the Regents of the University of California.  Please see the
 *  COPYRIGHT file for full details.  Squid incorporates software
 *  developed and/or copyrighted by other sources.  Please see the
 *  CREDITS file for full details.
 *
 *  This program is free software; you can redistribute it and/or modify
 *  it under the terms of the GNU General Public License as published by
 *  the Free Software Foundation; either version 2 of the License, or
 *  (at your option) any later version.
 *  
 *  This program is distributed in the hope that it will be useful,
 *  but WITHOUT ANY WARRANTY; without even the implied warranty of
 *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
 *  GNU General Public License for more details.
 *  
 *  You should have received a copy of the GNU General Public License
 *  along with this program; if not, write to the Free Software
 *  Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111, USA.
 *
 */

#include "squid.h"

#ifdef USE_XPROF_STATS
#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_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)
{
    int i;

    for (i = 0; i < XPROF_LAST; i++) {
	sortlist[i] = xprof_list[i];
    }
    qsort(&sortlist[XPROF_hash_lookup], XPROF_LAST - XPROF_hash_lookup, 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 %llu\t %llu\t %llu\t %llu\t %llu\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,
	dpercent((double) hist->summ, (double) hist->delta));
}

static void
xprof_summary_item(StoreEntry * sentry, char *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: %llu, %.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 %llu \t %llu \t %llu \t %llu\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 hrtime_t now;
static void
xprof_Init(void)
{
    if (xprof_inited)
	return;

    xprof_delta = xprof_verystart = xprof_start_t = now;

    xprof_inited = 1;
    cachemgrRegister("cpu_profile", "CPU Profiling Stats", xprof_summary, 0, 1);
}

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_nesting++;
    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);
    xprof_nesting--;

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

#endif /* USE_XPROF_STATS */
Commit	Line	Data
88bfe092	1
88bfe092	2	/*
528b2c61	3	* $Id: ProfStats.cc,v 1.3 2003/01/23 00:37:14 robertc Exp $
88bfe092	4	*
	5	* DEBUG: section 81 CPU Profiling Routines
	6	* AUTHOR: Andres Kroonmaa
	7	*
	8	* SQUID Internet Object Cache http://squid.nlanr.net/Squid/
	9	* ----------------------------------------------------------
	10	*
	11	* Squid is the result of efforts by numerous individuals from the
	12	* Internet community. Development is led by Duane Wessels of the
	13	* National Laboratory for Applied Network Research and funded by the
	14	* National Science Foundation. Squid is Copyrighted (C) 1998 by
	15	* the Regents of the University of California. Please see the
	16	* COPYRIGHT file for full details. Squid incorporates software
	17	* developed and/or copyrighted by other sources. Please see the
	18	* CREDITS file for full details.
	19	*
	20	* This program is free software; you can redistribute it and/or modify
	21	* it under the terms of the GNU General Public License as published by
	22	* the Free Software Foundation; either version 2 of the License, or
	23	* (at your option) any later version.
	24	*
	25	* This program is distributed in the hope that it will be useful,
	26	* but WITHOUT ANY WARRANTY; without even the implied warranty of
	27	* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
	28	* GNU General Public License for more details.
	29	*
	30	* You should have received a copy of the GNU General Public License
	31	* along with this program; if not, write to the Free Software
	32	* Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111, USA.
	33	*
	34	*/
	35
	36	#include "squid.h"
	37
	38	#ifdef USE_XPROF_STATS
e6ccf245	39	#include "Store.h"
88bfe092	40
	41	/* Private stuff */
	42
	43	#define MAX_SORTLIST 200
	44
	45	static hrtime_t xprof_delta = 0;
	46	static hrtime_t xprof_start_t = 0;
	47	static hrtime_t xprof_verystart = 0;
	48	static hrtime_t xprof_average_delta = 0;
	49	static int xprof_events = 0;
	50	static int xprof_inited = 0;
	51	static xprof_stats_data Totals;
	52
	53	static TimersArray *xprof_stats_avg1sec = NULL;
	54	static TimersArray *xprof_stats_avg5sec = NULL;
	55	static TimersArray *xprof_stats_avg30sec = NULL;
	56	static TimersArray *xprof_stats_avg1min = NULL;
	57	static TimersArray *xprof_stats_avg5min = NULL;
	58	static TimersArray *xprof_stats_avg30min = NULL;
	59	static TimersArray *xprof_stats_avg1hour = NULL;
	60	static TimersArray *xprof_stats_avg5hour = NULL;
	61	static TimersArray *xprof_stats_avg24hour = NULL;
	62
	63	static xprof_stats_node *sortlist[XPROF_LAST + 2];
	64
	65	static void
	66	xprof_reset(xprof_stats_data * head)
	67	{
	68	head->summ = 0;
	69	head->count = 0;
	70	head->delta = 0;
	71	head->best = XP_NOBEST;
	72	head->worst = 0;
	73	head->start = 0;
	74	head->stop = 0;
	75	}
	76
	77	static void
	78	xprof_move(xprof_stats_data * head, xprof_stats_data * hist)
	79	{
	80	memcpy(hist, head, sizeof(xprof_stats_data));
	81	}
	82
	83	static int
	84	xprof_comp(xprof_stats_node ii, xprof_stats_node jj)
	85	{
	86	if ((ii)->hist.summ < (jj)->hist.summ)
	87	return (1);
	88	if ((ii)->hist.summ > (jj)->hist.summ)
	89	return (-1);
	90
	91	return (0);
	92	}
	93
	94	static void
	95	xprof_sorthist(TimersArray * xprof_list)
	96	{
	97	int i;
	98
	99	for (i = 0; i < XPROF_LAST; i++) {
	100	sortlist[i] = xprof_list[i];
	101	}
	102	qsort(&sortlist[XPROF_hash_lookup], XPROF_LAST - XPROF_hash_lookup, sizeof(xprof_stats_node ), (QS ) xprof_comp);
	103	}
104
105	static double time_frame;
106
107	static void
108	xprof_show_item(StoreEntry * sentry, const char name, xprof_stats_data hist)
109	{
110	storeAppendPrintf(sentry,
111	"%s\t %llu\t %llu\t %llu\t %llu\t %llu\t %.2f\t %6.3f\t\n",
112	name,
113	hist->count,
114	hist->summ,
115	(hist->best != XP_NOBEST ? hist->best : 0),
116	hist->count ? hist->summ / hist->count : 0,
117	hist->worst,
118	hist->count / time_frame,
119	dpercent((double) hist->summ, (double) hist->delta));
120	}
121
122	static void
123	xprof_summary_item(StoreEntry * sentry, char descr, TimersArray list)
124	{
125	int i;
126	xprof_stats_node **hist;
127	xprof_stats_data *show;
128	xprof_reset(&Totals);
129	xprof_sorthist(list);
130	hist = &sortlist[0];
131
132	show = &hist[0]->hist;
133	if (!hist[0]->hist.delta)
134	show = &hist[0]->accu;
135
136	time_frame = (double) show->delta / (double) xprof_average_delta;
137
138	storeAppendPrintf(sentry, "\n%s:", descr);
139	storeAppendPrintf(sentry, " (Cumulated time: %llu, %.2f sec)\n",
140	show->delta,
141	time_frame
142	);
143	storeAppendPrintf(sentry,
144	"Probe Name\t Events\t cumulated time \t best case \t average \t worst case\t Rate / sec \t %% in int\n");
145
146	for (i = 0; i < XPROF_LAST; i++) {
147	if (!hist[i]->name)
148	continue;
149
150	show = &hist[i]->hist;
151	if (!show->count)
152	continue;
153	xprof_show_item(sentry, hist[i]->name, show);
154
155	Totals.count += show->count;
156	Totals.summ += show->summ;
157	Totals.best += (show->best != XP_NOBEST ? show->best : 0);
158	Totals.worst += show->worst;
159	Totals.delta = (show->delta > Totals.delta ? show->delta : Totals.delta);
160	}
161	xprof_show_item(sentry, "TOTALS", &Totals);
162	}
163
164	static void
165	xprof_average(TimersArray ** list, int secs)
166	{
167	int i;
168	TimersArray *head = xprof_Timers;
169	TimersArray *hist;
170	hrtime_t now;
171	hrtime_t keep;
172	int doavg = (xprof_events % secs);
173
174	if (!*list)
e6ccf245	175	list = (TimersArray )xcalloc(XPROF_LAST, sizeof(xprof_stats_node));
88bfe092	176
	177	hist = *list;
	178	now = get_tick();
	179
	180	for (i = 0; i < XPROF_LAST; i++) {
	181	hist[i]->name = head[i]->name;
	182	hist[i]->accu.summ += head[i]->accu.summ;
	183	hist[i]->accu.count += head[i]->accu.count; /* accumulate multisec */
	184
	185	if (!hist[i]->accu.best)
	186	hist[i]->accu.best = head[i]->accu.best;
	187
	188	if (hist[i]->accu.best > head[i]->accu.best)
	189	hist[i]->accu.best = head[i]->accu.best;
	190
	191	if (hist[i]->accu.worst < head[i]->accu.worst)
	192	hist[i]->accu.worst = head[i]->accu.worst;
	193
	194	hist[i]->accu.delta += xprof_delta;
	195	if (!doavg) {
	196	/* we have X seconds accumulated */
	197	xprof_move(&hist[i]->accu, &hist[i]->hist);
	198	xprof_reset(&hist[i]->accu);
	199
	200	hist[i]->accu.start = now;
	201	}
	202	/* reset 0sec counters */
	203	if (secs == 1) {
	204	keep = head[i]->accu.start;
	205	xprof_move(&head[i]->accu, &head[i]->hist);
	206	xprof_reset(&head[i]->accu);
	207	hist[i]->accu.delta = 0;
	208	head[i]->accu.start = keep;
	209	}
	210	}
	211	}
	212
	213	void
	214	xprof_summary(StoreEntry * sentry)
	215	{
	216	hrtime_t now = get_tick();
	217
	218	storeAppendPrintf(sentry, "CPU Profiling Statistics:\n");
	219	storeAppendPrintf(sentry,
	220	" (CPU times are in arbitrary units, most probably in CPU clock ticks)\n");
	221	storeAppendPrintf(sentry,
	222	"Probe Name\t Event Count\t last Interval \t Avg Interval \t since squid start \t (since system boot) \n");
	223	storeAppendPrintf(sentry, "Total\t %lu\t %llu \t %llu \t %llu \t %llu\n",
	224	(long unsigned) xprof_events,
	225	xprof_delta,
	226	xprof_average_delta,
	227	now - xprof_verystart,
	228	now);
	229
	230	xprof_summary_item(sentry, "Last 1 sec averages", xprof_stats_avg1sec);
	231	xprof_summary_item(sentry, "Last 5 sec averages", xprof_stats_avg5sec);
	232	xprof_summary_item(sentry, "Last 30 sec averages", xprof_stats_avg30sec);
	233	xprof_summary_item(sentry, "Last 1 min averages", xprof_stats_avg1min);
	234	xprof_summary_item(sentry, "Last 5 min averages", xprof_stats_avg5min);
	235	xprof_summary_item(sentry, "Last 30 min averages", xprof_stats_avg30min);
	236	xprof_summary_item(sentry, "Last 1 hour averages", xprof_stats_avg1hour);
	237	xprof_summary_item(sentry, "Last 5 hour averages", xprof_stats_avg5hour);
	238	xprof_summary_item(sentry, "Last 24 hour averages", xprof_stats_avg24hour);
	239	}
240
241	static inline void
242	xprof_chk_overhead(int samples)
243	{
244	while (samples--) {
245	PROF_start(PROF_OVERHEAD);
246	PROF_stop(PROF_OVERHEAD);
247	}
248	}
249
250	static hrtime_t now;
251	static void
252	xprof_Init(void)
253	{
254	if (xprof_inited)
255	return;
256
257	xprof_delta = xprof_verystart = xprof_start_t = now;
258
259	xprof_inited = 1;
260	cachemgrRegister("cpu_profile", "CPU Profiling Stats", xprof_summary, 0, 1);
261	}
262
263	void
264	xprof_event(void *data)
265	{
266	now = get_tick();
267	xprof_Init();
268	xprof_delta = now - xprof_start_t;
269	xprof_start_t = now;
270	xprof_events++;
271
272	if (!xprof_average_delta)
273	xprof_average_delta = xprof_delta;
274	if (xprof_average_delta > (xprof_delta >> 1))
275	xprof_average_delta = xprof_average_delta - (xprof_average_delta >> 8) + (xprof_delta >> 8);
276
277	xprof_nesting++;
278	xprof_chk_overhead(2);
279	xprof_average(&xprof_stats_avg24hour, 24 * 3600);
280	xprof_average(&xprof_stats_avg5hour, 5 * 3600);
281	xprof_average(&xprof_stats_avg1hour, 3600);
282	xprof_average(&xprof_stats_avg30min, 1800);
283	xprof_average(&xprof_stats_avg5min, 300);
284	xprof_average(&xprof_stats_avg1min, 60);
285	xprof_average(&xprof_stats_avg30sec, 30);
286	xprof_average(&xprof_stats_avg5sec, 5);
287	xprof_average(&xprof_stats_avg1sec, 1);
288	xprof_chk_overhead(30);
289	xprof_nesting--;
290
291	eventAdd("cpuProfiling", xprof_event, NULL, 1.0, 1);
292	}
293
294	#endif /* USE_XPROF_STATS */