src/ProfStats.cc

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