src/ProfStats.cc

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