src/ProfStats.cc

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