--------------------- PatchSet 1823 Date: 2001/04/06 14:22:58 Author: akroonmaa Branch: cpuProfiling Tag: (none) Log: Implement code profiling framework with CPU-tick resolution. Developers can enclose sections of code between profiling marks, and during a squid run in cachemgr output observe how many CPU ticks the section of code runs, with min, avg, max times gathered. Purpose - code optimisation and CPU-hog diagnostics. Members: acconfig.h:1.6->1.6.10.1 configure.in:1.19->1.19.10.1 include/config.h.in:1.6->1.6.10.1 include/profiling.h:1.1->1.1.2.1 lib/Makefile.in:1.7->1.7.20.1 lib/Profiler.c:1.1->1.1.2.1 lib/util.c:1.7->1.7.24.1 src/Makefile.in:1.8->1.8.2.1 src/ProfStats.c:1.1->1.1.2.1 src/main.c:1.20->1.20.6.1 src/squid.h:1.11->1.11.10.1 Index: squid/acconfig.h =================================================================== RCS file: /cvsroot/squid-sf//squid/Attic/acconfig.h,v retrieving revision 1.6 retrieving revision 1.6.10.1 diff -u -r1.6 -r1.6.10.1 --- squid/acconfig.h 10 Mar 2001 00:58:29 -0000 1.6 +++ squid/acconfig.h 6 Apr 2001 14:22:58 -0000 1.6.10.1 @@ -23,7 +23,7 @@ #ifndef __CONFIGURE_H__ #define __CONFIGURE_H__ @TOP@ -/* $Id: acconfig.h,v 1.6 2001/03/10 00:58:29 squidadm Exp $ */ +/* $Id: acconfig.h,v 1.6.10.1 2001/04/06 14:22:58 akroonmaa Exp $ */ /********************************* * START OF CONFIGURABLE OPTIONS * @@ -51,6 +51,9 @@ /* Define to use async disk I/O operations */ #undef USE_ASYNC_IO +/* Define to enable CPU profiling within Squid */ +#undef USE_XPROF_STATS + /* Defines how many threads to use for async I/O */ #undef ASYNC_IO_THREADS Index: squid/configure.in =================================================================== RCS file: /cvsroot/squid-sf//squid/configure.in,v retrieving revision 1.19 retrieving revision 1.19.10.1 diff -u -r1.19 -r1.19.10.1 --- squid/configure.in 10 Mar 2001 00:58:29 -0000 1.19 +++ squid/configure.in 6 Apr 2001 14:22:58 -0000 1.19.10.1 @@ -3,13 +3,13 @@ dnl dnl Duane Wessels, wessels@nlanr.net, February 1996 (autoconf v2.9) dnl -dnl $Id: configure.in,v 1.19 2001/03/10 00:58:29 squidadm Exp $ +dnl $Id: configure.in,v 1.19.10.1 2001/04/06 14:22:58 akroonmaa Exp $ dnl dnl dnl AC_INIT(src/main.c) AC_CONFIG_HEADER(include/autoconf.h) -AC_REVISION($Revision: 1.19 $)dnl +AC_REVISION($Revision: 1.19.10.1 $)dnl AC_PREFIX_DEFAULT(/usr/local/squid) AC_CONFIG_AUX_DIR(cfgaux) @@ -857,6 +857,25 @@ fi ]) +dnl Enable USE_XPROF_STATS +AC_ARG_ENABLE(cpu-profiling, +[ --enable-cpu-profiling + This option allows you to see which internal functions + in Squid are consuming how much CPU. Compiles in probes + that measure time spent in probed functions. Needs + source modifications to add new probes. This is meant + for developers to assist in performance optimisations + of Squid internal functions. + If you are not developer and not interested in the stats + you shouldn't enable this, as overhead added, although + small, is still overhead. See lib/Profiler.c for more. + ], +[ if test "$enableval" = "yes" ; then + echo "Enabling cpu-profiling" + AC_DEFINE(USE_XPROF_STATS, 1) + fi +]) + # Force some compilers to use ANSI features # case "$host" in Index: squid/include/config.h.in =================================================================== RCS file: /cvsroot/squid-sf//squid/include/Attic/config.h.in,v retrieving revision 1.6 retrieving revision 1.6.10.1 diff -u -r1.6 -r1.6.10.1 --- squid/include/config.h.in 11 Mar 2001 22:11:08 -0000 1.6 +++ squid/include/config.h.in 6 Apr 2001 14:22:59 -0000 1.6.10.1 @@ -1,5 +1,5 @@ /* - * $Id: config.h.in,v 1.6 2001/03/11 22:11:08 squidadm Exp $ + * $Id: config.h.in,v 1.6.10.1 2001/04/06 14:22:59 akroonmaa Exp $ * * AUTHOR: Duane Wessels * @@ -43,6 +43,18 @@ *--------------------------------------------------------------------------* ****************************************************************************/ +#ifdef USE_XPROF_STATS + +#if defined(__i386) +#define HAVE_TICKS +#elif defined(__alpha) +#define HAVE_TICKS +#else +#warning config: unknown CPU type - cannot use CPU-profiling +#undef USE_XPROF_STATS +#endif /* CPU type */ +#endif /* USE_XPROF_STATS */ + #ifdef USE_POSIX_REGEX #ifndef USE_RE_SYNTAX #define USE_RE_SYNTAX REG_EXTENDED /* default Syntax */ --- /dev/null Wed Feb 14 00:51:37 2007 +++ squid/include/profiling.h Wed Feb 14 00:51:50 2007 @@ -0,0 +1,55 @@ + +#ifndef _PROFILING_H_ +#define _PROFILING_H_ + +#include "config.h" + +#ifdef USE_XPROF_STATS + +#if !defined(_SQUID_SOLARIS_) +typedef long long hrtime_t; +#else +#include +#endif + +#define XP_NOBEST 99999999 + +typedef hrtime_t TICKF(void); + +typedef struct _xprof_stats xprof_stats_node; +struct _xprof_stats { + const char *name; + xprof_stats_node *next; + xprof_stats_node *hist; + hrtime_t start; + hrtime_t stop; + hrtime_t delta; + hrtime_t best; + hrtime_t worst; + hrtime_t count; + long long summ; +}; + +typedef enum { + PR_start, + PR_stop, + PR_getdelta, +} xprof_state; + +extern hrtime_t get_tick(void); +extern xprof_stats_node **xprof_Statsp; +extern xprof_stats_node *xp_OverhStartp; +extern xprof_stats_node *xp_OverhStopp; +extern xprof_stats_node *xp_Unaccountedp; + +extern void xprof_time(xprof_state state, const char *timer); +extern xprof_stats_node * xprof_get_timer(xprof_stats_node ** list, const char *timer); +extern void xprof_event(void *data); + +#define PROF xprof_time +#else +#define PROF(STATE,ARGS) ((void)0) + +#endif /* USE_XPROF_STATS */ + +#endif /* _PROFILING_H_ */ Index: squid/lib/Makefile.in =================================================================== RCS file: /cvsroot/squid-sf//squid/lib/Attic/Makefile.in,v retrieving revision 1.7 retrieving revision 1.7.20.1 diff -u -r1.7 -r1.7.20.1 --- squid/lib/Makefile.in 31 Jan 2001 22:20:27 -0000 1.7 +++ squid/lib/Makefile.in 6 Apr 2001 14:22:59 -0000 1.7.20.1 @@ -1,5 +1,5 @@ # -# $Id: Makefile.in,v 1.7 2001/01/31 22:20:27 hno Exp $ +# $Id: Makefile.in,v 1.7.20.1 2001/04/06 14:22:59 akroonmaa Exp $ # prefix = @prefix@ top_srcdir = @top_srcdir@ @@ -25,6 +25,7 @@ rfc1738.o \ rfc1035.o \ rfc2617.o \ + Profiler.o \ util.o \ getfullhostname.o \ base64.o \ --- /dev/null Wed Feb 14 00:51:37 2007 +++ squid/lib/Profiler.c Wed Feb 14 00:51:50 2007 @@ -0,0 +1,295 @@ + +/* + * $Id$ + * + * DEBUG: section 81 CPU Profiling Routines + * AUTHOR: Andres Kroonmaa, Sep.2000 + * + * 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. + * + */ + +/* + CPU Profiling implementation. + + This library implements the Probes needed to gather stats. + See src/ProfStats.c which implements historical recording and + presentation in CacheMgr.cgi. + + For timing we prefer on-CPU ops that retrieve cpu ticks counter. + For Intel, this is "rdtsc", which is 64-bit counter that virtually + never wraps. For alpha, this is "rpcc" which is 32-bit counter and + wraps every few seconds. Currently, no handling of wrapping counters + is implemented. Other CPU's are also not covered. Potentially all + modern CPU's has similar counters. + + Usage. + Insert macro PROF(state, "probename") in strategic places in code. + PROF(PR_start, "probename"); + ... section of code measured ... + PROF(PR_stop,"probename"); + + Description. + PROF gathers stats per probename into structures. It indexes these + structures by pointer value, not string contents. So, for each + invocation of PROF meaning the same probe, you have to pass the same + pointer to PROF. You can use string constants exactly as in example. + + PROF records best, best, average and worst values for delta time, + also, if UNACCED is defined, it measures "empty" time during which + no probes are in measuring state. This allows to see time "unaccounted" + for. If OVERHEAD is defined, additional calculations are made at every + probe to measure approximate overhead of the probe code itself. + + Probe data is stored in linked-list, so the more probes you define, + the more overhead is added to find the deepest nested probe. To reduce + average overhead, linked list is manipulated each time PR_start is + called, so that probe just started is moved 1 position up in linkedlist. + This way frequently used probes are moved closer to the head of list, + reducing average overhead. + Note that all overhead is on the scale of one hundred of CPU clock + ticks, which on the scale of submicroseconds. Yet, to optimise really + fast and frequent sections of code, we want to reduce this overhead + to absolute minimum possible. + + For actual measurements, probe overhead cancels out mostly. Still, + do not take the measured times as facts, they should be viewed in + relative comparison to overall CPU time and on the same platform. + + Every 1 second, Event within squid is called that parses gathered + statistics of every probe, and accumulates that into historical + structures for last 1,5,30 secs, 1,5,30 mins, and 1,5 and 24 hours. + Each second active probe stats are reset, and only historical data + is presented in cachemgr output. + + Reading stats. + "Worst case" may be misleading. Anything can happen at any section + of code that could delay reaching to probe stop. For eg. system may + need to service interrupt routine, task switch could occur, or page + fault needs to be handled. In this sense, this is quite meaningless + metric. "Best case" shows fastest completion of probe section, and + is also somewhat useless, unless you know that amount of work is + constant. Best metric to watch is "average time" and total cumulated + time in given timeframe, which really show percentage of time spent + in given section of code, and its average completion time. This data + could be used to detect bottlenecks withing squid and optimise them. + + TOTALS are quite off reality. Its there just to summarise cumulative + times and percent column. Percent values over 100% shows that there + have been some probes nested into each other. + + */ + +#include "config.h" + +#ifdef USE_XPROF_STATS + +#include "profiling.h" + +#if HAVE_STDIO_H +#include +#endif +#if HAVE_STDLIB_H +#include +#endif + +#if HAVE_GNUMALLLOC_H +#include +#elif HAVE_MALLOC_H && !defined(_SQUID_FREEBSD_) && !defined(_SQUID_NEXT_) +#include +#endif +#if HAVE_ERRNO_H +#include +#endif + +#define UNACCED 1 /* Try to account for time between probes */ +#define OVERHEAD 1 /* Try to account for probe overhead */ + +/* Private stuff */ +static xprof_stats_node xp_OverhStoph = + { "(probe_stop_overhead)", 0, 0, 0, 0, 0, XP_NOBEST, 0, 0, 0 }; + +static xprof_stats_node xp_OverhStop = + { "(probe_stop_overhead)", 0, &xp_OverhStoph, 0, 0, 0, XP_NOBEST, 0, 0, 0 }; + +static xprof_stats_node xp_OverhStarth = + { "(probe_start_overhead)", 0, 0, 0, 0, 0, XP_NOBEST, 0, 0, 0 }; + +static xprof_stats_node xp_OverhStart = + { "(probe_start_overhead)", &xp_OverhStop, &xp_OverhStarth, 0, 0, 0, XP_NOBEST, 0, 0, 0 }; + +static xprof_stats_node xp_Unaccountedh = + { "(UNACCOUNTED)", 0, 0, 0, 0, 0, XP_NOBEST, 0, 0, 0 }; + +static xprof_stats_node xp_Unaccounted = + { "(UNACCOUNTED)", &xp_OverhStart, &xp_Unaccountedh, 0, 0, 0, XP_NOBEST, 0, 0, 0 }; + +#if OVERHEAD +static int xprof_nesting = 0; +#endif + +#if defined(__i386) +hrtime_t inline +get_tick(void) +{ + hrtime_t regs; + asm volatile ("rdtsc":"=A" (regs)); + return regs; + /* We need return value, we rely on CC to optimise out needless subf calls */ + /* Note that "rdtsc" is relatively slow OP and stalls the CPU pipes, so use it wisely */ +} + +#elif defined(__alpha) +hrtime_t inline +get_tick(void) +{ + hrtime_t regs; + asm volatile ("rpcc $0":"=A" (regs)); /* I'm not sure of syntax */ + return regs; +} +#endif + +/* Public stuff */ +xprof_stats_node *xp_OverhStartp = &xp_OverhStart; +xprof_stats_node *xp_OverhStopp = &xp_OverhStop; +xprof_stats_node *xp_Unaccountedp = &xp_Unaccounted; + +static xprof_stats_node *xprof_Stats = &xp_OverhStop; +static xprof_stats_node *xprof_Hist = &xp_Unaccounted; + +xprof_stats_node **xprof_Statsp = &xprof_Hist; + +static xprof_stats_node *xp_last, *xp_prelast; +static xprof_stats_node *new; + +static xprof_stats_node * +xprof_get_new(const char *timer) +{ + xprof_stats_node *head; + /* Note that we never free */ + if ((head = calloc(1, sizeof(xprof_stats_node))) != NULL) + if ((head->hist = calloc(1, sizeof(xprof_stats_node))) != NULL) { + head->name = timer; + head->best = XP_NOBEST; + return head; + } + perror("xprof: malloc"); + exit(1); +} + +inline xprof_stats_node * +xprof_get_timer(xprof_stats_node ** list, const char *timer) +{ + xprof_stats_node *head = *list; + new = xp_last = NULL; + + while (head != NULL) { + if (timer == head->name) + return head; + xp_prelast = xp_last; + xp_last = head; + head = head->next; + } + /* new timer, slow part */ + + if (xp_last) + return xp_last->next = new = xprof_get_new(timer); + else + return *list = new = xprof_get_new(timer); + +} + +inline void +xprof_update(xprof_stats_node * head) +{ + head->delta = head->stop - head->start; + head->count++; + if (head->delta < head->best) + head->best = head->delta; + if (head->worst < head->delta) + head->worst = head->delta; + head->summ += head->delta; +} + +/* + * Warning: performance sensitive section. Optimise for speed! + */ +void +xprof_time(xprof_state state, const char *timer) +{ + xprof_stats_node *head; + + if (state == PR_stop) { + + xp_OverhStop.start = get_tick(); + head = xprof_get_timer(&xprof_Stats, timer); + head->stop = xp_OverhStop.start; + if (head->start) + xprof_update(head); + +#if UNACCED + --xprof_nesting; + if (xprof_nesting == 0) + xp_Unaccounted.start = xp_OverhStop.start; + else if (xprof_nesting < 0) + xprof_nesting = 0; +#endif + +#if OVERHEAD + xp_OverhStop.stop = get_tick(); + xprof_update(&xp_OverhStop); +#endif + return; + } + /* PR_start */ + xp_OverhStart.start = get_tick(); + +#if UNACCED + if (xprof_nesting == 0) { + xp_Unaccounted.stop = xp_OverhStart.start; + if (xp_Unaccounted.start) + xprof_update(&xp_Unaccounted); + } + xprof_nesting++; +#endif + + head = xprof_get_timer(&xprof_Stats, timer); + if (xp_prelast != NULL) { /* We move this item 1 pos up, to allow slow sort */ + if (xp_last->count <= head->count) { /* sort by frequency, so allow for faster searches */ + xp_last->next = head->next; /* remove head from chain */ + head->next = xp_last; /* insert in front of last */ + xp_prelast->next = head; /* update prelast to point at right place */ + } + } + head->start = xp_OverhStart.stop = get_tick(); +#if OVERHEAD + if (new == NULL) + xprof_update(&xp_OverhStart); +#endif +} + +#endif /* USE_XPROF_STATS */ Index: squid/lib/util.c =================================================================== RCS file: /cvsroot/squid-sf//squid/lib/util.c,v retrieving revision 1.7 retrieving revision 1.7.24.1 diff -u -r1.7 -r1.7.24.1 --- squid/lib/util.c 12 Jan 2001 08:20:31 -0000 1.7 +++ squid/lib/util.c 6 Apr 2001 14:22:59 -0000 1.7.24.1 @@ -1,6 +1,6 @@ /* - * $Id: util.c,v 1.7 2001/01/12 08:20:31 hno Exp $ + * $Id: util.c,v 1.7.24.1 2001/04/06 14:22:59 akroonmaa Exp $ * * DEBUG: * AUTHOR: Harvest Derived @@ -36,6 +36,7 @@ #define _etext etext #include "config.h" +#include "profiling.h" #if HAVE_STDIO_H #include Index: squid/src/Makefile.in =================================================================== RCS file: /cvsroot/squid-sf//squid/src/Attic/Makefile.in,v retrieving revision 1.8 retrieving revision 1.8.2.1 diff -u -r1.8 -r1.8.2.1 --- squid/src/Makefile.in 4 Apr 2001 06:45:08 -0000 1.8 +++ squid/src/Makefile.in 6 Apr 2001 14:22:59 -0000 1.8.2.1 @@ -1,7 +1,7 @@ # # Makefile for the Squid Object Cache server # -# $Id: Makefile.in,v 1.8 2001/04/04 06:45:08 squidadm Exp $ +# $Id: Makefile.in,v 1.8.2.1 2001/04/06 14:22:59 akroonmaa Exp $ # # Uncomment and customize the following to suit your needs: # @@ -91,6 +91,7 @@ SUID_UTILS = $(PINGER_EXE) CGIPROGS = $(CACHEMGR_EXE) OBJS = \ + ProfStats.o \ access_log.o \ acl.o \ asn.o \ --- /dev/null Wed Feb 14 00:51:37 2007 +++ squid/src/ProfStats.c Wed Feb 14 00:51:50 2007 @@ -0,0 +1,262 @@ + +/* + * $Id$ + * + * 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 + +/* Private stuff */ + +#define MAX_SORTLIST 200 + +static hrtime_t xprof_delta = 0; +static hrtime_t xprof_start = 0; +static hrtime_t xprof_verystart = 0; +static int xprof_events = 0; +static int xprof_inited = 0; +static xprof_stats_node Summs; + +static xprof_stats_node *xprof_stats_avg1sec = NULL; +static xprof_stats_node *xprof_stats_avg5sec = NULL; +static xprof_stats_node *xprof_stats_avg30sec = NULL; +static xprof_stats_node *xprof_stats_avg1min = NULL; +static xprof_stats_node *xprof_stats_avg5min = NULL; +static xprof_stats_node *xprof_stats_avg30min = NULL; +static xprof_stats_node *xprof_stats_avg1hour = NULL; +static xprof_stats_node *xprof_stats_avg5hour = NULL; +static xprof_stats_node *xprof_stats_avg24hour = NULL; + +static xprof_stats_node * sortlist[MAX_SORTLIST + 2]; + +static void +xprof_reset(xprof_stats_node * 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_node * head, xprof_stats_node * hist) +{ + memcpy(hist, head, sizeof(xprof_stats_node)); +} + +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(xprof_stats_node * xprof_list) +{ + static xprof_stats_node *mhead,*mlast; + int i,count; + + mlast = xprof_list; + mlast = mlast->next->next; // Point past fixed sctructures + + mhead = mlast->next; + count = 0; + while (mhead != NULL) { + sortlist[++count] = mhead; + mhead = mhead->next; + if (count == MAX_SORTLIST) + break; + } + + qsort(&sortlist[1], count, sizeof(xprof_stats_node *), &xprof_comp); + + for (i=1; i< count; i++) { + sortlist[i]->next = sortlist[i+1]; + } + sortlist[count]->next = NULL; + mlast->next = sortlist[1]; +} + +void +xprof_show_item(StoreEntry * sentry, xprof_stats_node * head) +{ + storeAppendPrintf(sentry, + "%s\t %llu\t %llu\t %llu\t %llu\t %llu\t %llu\t %6.3f%\t\n", + head->name, + head->count, + head->summ, + (head->best != XP_NOBEST ? head->best : 0 ), + head->count ? head->summ / head->count : 0, + head->worst, + head->delta, + dpercent((double) head->summ, (double) head->delta) ); +} + +void +xprof_summary_item(StoreEntry * sentry, char *descr, xprof_stats_node * list) +{ + xprof_stats_node *head, *hist; + + xprof_reset(&Summs); + Summs.name = "TOTALS"; + + xprof_sorthist(list); + + storeAppendPrintf(sentry, "\n%s:\n", descr); + storeAppendPrintf(sentry, + "Probe Name\t Events\t cumulated time \t best case \t average \t worst case\t interval time \t %% in int\n"); + + for (head = list; head != NULL; head = head->next) + if (head->hist != NULL) + if (head->hist->name != NULL) { + hist = head->hist; + xprof_show_item(sentry, hist); + Summs.count += hist->count; + Summs.summ += hist->summ; + Summs.best += (hist->best != XP_NOBEST ? hist->best : 0 ); + Summs.worst += hist->worst; + Summs.delta = (hist->delta > Summs.delta ? hist->delta : Summs.delta); + } + head = &Summs; + xprof_show_item(sentry, head); +} + +void +xprof_summary(StoreEntry * sentry) +{ + 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 interval time \t since squid start \t (since system boot) \n"); + storeAppendPrintf(sentry, "Total\t %lu\t %llu \t %llu \t %llu\n", + xprof_events, + xprof_delta, + get_tick() - xprof_verystart, + get_tick()); + +// xprof_summary_item(sentry, "Last instant averages", *xprof_Statsp); + 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); +} + +void +xprof_Init(void) +{ + xprof_inited = 1; + cachemgrRegister("cpu_profile", "CPU Profiling Stats", xprof_summary, 0, 1); +} + +void +xprof_average(xprof_stats_node ** xprof_list, int secs) +{ + xprof_stats_node *head = *xprof_Statsp; + xprof_stats_node *list; + hrtime_t now; + int doavg = (xprof_events % secs); + + while (head != NULL) { + list = xprof_get_timer(xprof_list, head->name); + list->summ += head->summ; + list->count += head->count; /* accumulate multisec */ + if (!list->best) + list->best = head->best; + if (list->best > head->best) + list->best = head->best; + if (list->worst < head->worst) + list->worst = head->worst; + + now = get_tick(); + list->delta = now - (list->start ? list->start : now); /* ticks since last event here */ + if (!doavg) { + /* we have X seconds accumulated */ + xprof_move(list, list->hist); + xprof_reset(list); + + list->start = now; + } + /* reset 0sec counters */ + if (secs == 1) { + xprof_move(head, head->hist); + xprof_reset(head); + } + head = head->next; + } +} + +void +xprof_event(void *data) +{ + hrtime_t now; + + if (!xprof_inited) + xprof_Init(); + + now = get_tick(); + xprof_delta = now - (xprof_start ? xprof_start : now); + xprof_start = now; + if (xprof_verystart == 0) + xprof_verystart = now; + xprof_events++; + + 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); + + eventAdd("cpuProfiling", xprof_event, NULL, 1.0, 1); + +} + +#endif /* USE_XPROF_STATS */ Index: squid/src/main.c =================================================================== RCS file: /cvsroot/squid-sf//squid/src/main.c,v retrieving revision 1.20 retrieving revision 1.20.6.1 diff -u -r1.20 -r1.20.6.1 --- squid/src/main.c 29 Mar 2001 09:41:31 -0000 1.20 +++ squid/src/main.c 6 Apr 2001 14:23:00 -0000 1.20.6.1 @@ -1,6 +1,6 @@ /* - * $Id: main.c,v 1.20 2001/03/29 09:41:31 squidadm Exp $ + * $Id: main.c,v 1.20.6.1 2001/04/06 14:23:00 akroonmaa Exp $ * * DEBUG: section 1 Startup and Main Loop * AUTHOR: Harvest Derived @@ -553,6 +553,9 @@ eventAdd("start_announce", start_announce, NULL, 3600.0, 1); eventAdd("ipcache_purgelru", ipcache_purgelru, NULL, 10.0, 1); eventAdd("fqdncache_purgelru", fqdncache_purgelru, NULL, 15.0, 1); +#if USE_XPROF_STATS + eventAdd("cpuProfiling", xprof_event, NULL, 1.0,1); +#endif } configured_once = 1; } Index: squid/src/squid.h =================================================================== RCS file: /cvsroot/squid-sf//squid/src/squid.h,v retrieving revision 1.11 retrieving revision 1.11.10.1 diff -u -r1.11 -r1.11.10.1 --- squid/src/squid.h 11 Mar 2001 22:11:09 -0000 1.11 +++ squid/src/squid.h 6 Apr 2001 14:23:00 -0000 1.11.10.1 @@ -1,6 +1,6 @@ /* - * $Id: squid.h,v 1.11 2001/03/11 22:11:09 squidadm Exp $ + * $Id: squid.h,v 1.11.10.1 2001/04/06 14:23:00 akroonmaa Exp $ * * AUTHOR: Duane Wessels * @@ -395,6 +395,7 @@ #include "globals.h" #include "util.h" +#include "profiling.h" /* * Mac OS X Server already has radix.h as a standard header, so