src/ProfStats.cc

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