src/ProfStats.cc

   1
   2 /*
   3  * $Id: ProfStats.cc,v 1.1 2002/10/02 11:06:31 robertc Exp $
   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
  39
  40 /* Private stuff */
  41
  42 #define MAX_SORTLIST 200
  43
  44 static hrtime_t xprof_delta = 0;
  45 static hrtime_t xprof_start_t = 0;
  46 static hrtime_t xprof_verystart = 0;
  47 static hrtime_t xprof_average_delta = 0;
  48 static int xprof_events = 0;
  49 static int xprof_inited = 0;
  50 static xprof_stats_data Totals;
  51
  52 static TimersArray *xprof_stats_avg1sec = NULL;
  53 static TimersArray *xprof_stats_avg5sec = NULL;
  54 static TimersArray *xprof_stats_avg30sec = NULL;
  55 static TimersArray *xprof_stats_avg1min = NULL;
  56 static TimersArray *xprof_stats_avg5min = NULL;
  57 static TimersArray *xprof_stats_avg30min = NULL;
  58 static TimersArray *xprof_stats_avg1hour = NULL;
  59 static TimersArray *xprof_stats_avg5hour = NULL;
  60 static TimersArray *xprof_stats_avg24hour = NULL;
  61
  62 static xprof_stats_node *sortlist[XPROF_LAST + 2];
  63
  64 static void
  65 xprof_reset(xprof_stats_data * head)
  66 {
  67     head->summ = 0;
  68     head->count = 0;
  69     head->delta = 0;
  70     head->best = XP_NOBEST;
  71     head->worst = 0;
  72     head->start = 0;
  73     head->stop = 0;
  74 }
  75
  76 static void
  77 xprof_move(xprof_stats_data * head, xprof_stats_data * hist)
  78 {
  79     memcpy(hist, head, sizeof(xprof_stats_data));
  80 }
  81
  82 static int
  83 xprof_comp(xprof_stats_node ** ii, xprof_stats_node ** jj)
  84 {
  85     if ((*ii)->hist.summ < (*jj)->hist.summ)
  86         return (1);
  87     if ((*ii)->hist.summ > (*jj)->hist.summ)
  88         return (-1);
  89
  90     return (0);
  91 }
  92
  93 static void
  94 xprof_sorthist(TimersArray * xprof_list)
  95 {
  96     int i;
  97
  98     for (i = 0; i < XPROF_LAST; i++) {
  99         sortlist[i] = xprof_list[i];
 100     }
 101     qsort(&sortlist[XPROF_hash_lookup], XPROF_LAST - XPROF_hash_lookup, sizeof(xprof_stats_node *), (QS *) xprof_comp);
 102 }
 103
 104 static double time_frame;
 105
 106 static void
 107 xprof_show_item(StoreEntry * sentry, const char *name, xprof_stats_data * hist)
 108 {
 109     storeAppendPrintf(sentry,
 110         "%s\t %llu\t %llu\t %llu\t %llu\t %llu\t %.2f\t %6.3f\t\n",
 111         name,
 112         hist->count,
 113         hist->summ,
 114         (hist->best != XP_NOBEST ? hist->best : 0),
 115         hist->count ? hist->summ / hist->count : 0,
 116         hist->worst,
 117         hist->count / time_frame,
 118         dpercent((double) hist->summ, (double) hist->delta));
 119 }
 120
 121 static void
 122 xprof_summary_item(StoreEntry * sentry, char *descr, TimersArray * list)
 123 {
 124     int i;
 125     xprof_stats_node **hist;
 126     xprof_stats_data *show;
 127     xprof_reset(&Totals);
 128     xprof_sorthist(list);
 129     hist = &sortlist[0];
 130
 131     show = &hist[0]->hist;
 132     if (!hist[0]->hist.delta)
 133         show = &hist[0]->accu;
 134
 135     time_frame = (double) show->delta / (double) xprof_average_delta;
 136
 137     storeAppendPrintf(sentry, "\n%s:", descr);
 138     storeAppendPrintf(sentry, " (Cumulated time: %llu, %.2f sec)\n",
 139         show->delta,
 140         time_frame
 141         );
 142     storeAppendPrintf(sentry,
 143         "Probe Name\t  Events\t cumulated time \t best case \t average \t worst case\t Rate / sec \t %% in int\n");
 144
 145     for (i = 0; i < XPROF_LAST; i++) {
 146         if (!hist[i]->name)
 147             continue;
 148
 149         show = &hist[i]->hist;
 150         if (!show->count)
 151             continue;
 152         xprof_show_item(sentry, hist[i]->name, show);
 153
 154         Totals.count += show->count;
 155         Totals.summ += show->summ;
 156         Totals.best += (show->best != XP_NOBEST ? show->best : 0);
 157         Totals.worst += show->worst;
 158         Totals.delta = (show->delta > Totals.delta ? show->delta : Totals.delta);
 159     }
 160     xprof_show_item(sentry, "TOTALS", &Totals);
 161 }
 162
 163 static void
 164 xprof_average(TimersArray ** list, int secs)
 165 {
 166     int i;
 167     TimersArray *head = xprof_Timers;
 168     TimersArray *hist;
 169     hrtime_t now;
 170     hrtime_t keep;
 171     int doavg = (xprof_events % secs);
 172
 173     if (!*list)
 174         *list = xcalloc(XPROF_LAST, sizeof(xprof_stats_node));
 175
 176     hist = *list;
 177     now = get_tick();
 178
 179     for (i = 0; i < XPROF_LAST; i++) {
 180         hist[i]->name = head[i]->name;
 181         hist[i]->accu.summ += head[i]->accu.summ;
 182         hist[i]->accu.count += head[i]->accu.count;     /* accumulate multisec */
 183
 184         if (!hist[i]->accu.best)
 185             hist[i]->accu.best = head[i]->accu.best;
 186
 187         if (hist[i]->accu.best > head[i]->accu.best)
 188             hist[i]->accu.best = head[i]->accu.best;
 189
 190         if (hist[i]->accu.worst < head[i]->accu.worst)
 191             hist[i]->accu.worst = head[i]->accu.worst;
 192
 193         hist[i]->accu.delta += xprof_delta;
 194         if (!doavg) {
 195             /* we have X seconds accumulated */
 196             xprof_move(&hist[i]->accu, &hist[i]->hist);
 197             xprof_reset(&hist[i]->accu);
 198
 199             hist[i]->accu.start = now;
 200         }
 201         /* reset 0sec counters */
 202         if (secs == 1) {
 203             keep = head[i]->accu.start;
 204             xprof_move(&head[i]->accu, &head[i]->hist);
 205             xprof_reset(&head[i]->accu);
 206             hist[i]->accu.delta = 0;
 207             head[i]->accu.start = keep;
 208         }
 209     }
 210 }
 211
 212 void
 213 xprof_summary(StoreEntry * sentry)
 214 {
 215     hrtime_t now = get_tick();
 216
 217     storeAppendPrintf(sentry, "CPU Profiling Statistics:\n");
 218     storeAppendPrintf(sentry,
 219         "  (CPU times are in arbitrary units, most probably in CPU clock ticks)\n");
 220     storeAppendPrintf(sentry,
 221         "Probe Name\t Event Count\t last Interval \t Avg Interval \t since squid start \t (since system boot) \n");
 222     storeAppendPrintf(sentry, "Total\t %lu\t %llu \t %llu \t %llu \t %llu\n",
 223         (long unsigned) xprof_events,
 224         xprof_delta,
 225         xprof_average_delta,
 226         now - xprof_verystart,
 227         now);
 228
 229     xprof_summary_item(sentry, "Last 1 sec averages", xprof_stats_avg1sec);
 230     xprof_summary_item(sentry, "Last 5 sec averages", xprof_stats_avg5sec);
 231     xprof_summary_item(sentry, "Last 30 sec averages", xprof_stats_avg30sec);
 232     xprof_summary_item(sentry, "Last 1 min averages", xprof_stats_avg1min);
 233     xprof_summary_item(sentry, "Last 5 min averages", xprof_stats_avg5min);
 234     xprof_summary_item(sentry, "Last 30 min averages", xprof_stats_avg30min);
 235     xprof_summary_item(sentry, "Last 1 hour averages", xprof_stats_avg1hour);
 236     xprof_summary_item(sentry, "Last 5 hour averages", xprof_stats_avg5hour);
 237     xprof_summary_item(sentry, "Last 24 hour averages", xprof_stats_avg24hour);
 238 }
 239
 240 static inline void
 241 xprof_chk_overhead(int samples)
 242 {
 243     while (samples--) {
 244         PROF_start(PROF_OVERHEAD);
 245         PROF_stop(PROF_OVERHEAD);
 246     }
 247 }
 248
 249 static hrtime_t now;
 250 static void
 251 xprof_Init(void)
 252 {
 253     if (xprof_inited)
 254         return;
 255
 256     xprof_delta = xprof_verystart = xprof_start_t = now;
 257
 258     xprof_inited = 1;
 259     cachemgrRegister("cpu_profile", "CPU Profiling Stats", xprof_summary, 0, 1);
 260 }
 261
 262 void
 263 xprof_event(void *data)
 264 {
 265     now = get_tick();
 266     xprof_Init();
 267     xprof_delta = now - xprof_start_t;
 268     xprof_start_t = now;
 269     xprof_events++;
 270
 271     if (!xprof_average_delta)
 272         xprof_average_delta = xprof_delta;
 273     if (xprof_average_delta > (xprof_delta >> 1))
 274         xprof_average_delta = xprof_average_delta - (xprof_average_delta >> 8) + (xprof_delta >> 8);
 275
 276     xprof_nesting++;
 277     xprof_chk_overhead(2);
 278     xprof_average(&xprof_stats_avg24hour, 24 * 3600);
 279     xprof_average(&xprof_stats_avg5hour, 5 * 3600);
 280     xprof_average(&xprof_stats_avg1hour, 3600);
 281     xprof_average(&xprof_stats_avg30min, 1800);
 282     xprof_average(&xprof_stats_avg5min, 300);
 283     xprof_average(&xprof_stats_avg1min, 60);
 284     xprof_average(&xprof_stats_avg30sec, 30);
 285     xprof_average(&xprof_stats_avg5sec, 5);
 286     xprof_average(&xprof_stats_avg1sec, 1);
 287     xprof_chk_overhead(30);
 288     xprof_nesting--;
 289
 290     eventAdd("cpuProfiling", xprof_event, NULL, 1.0, 1);
 291 }
 292
 293 #endif /* USE_XPROF_STATS */