lib/profiler/Profiler.cc

   1 /*
   2  * $Id$
   3  *
   4  * DEBUG: section 81    CPU Profiling Routines
   5  * AUTHOR: Andres Kroonmaa, Sep.2000
   6  *
   7  * SQUID Internet Object Cache  http://squid.nlanr.net/Squid/
   8  * ----------------------------------------------------------
   9  *
  10  *  Squid is the result of efforts by numerous individuals from the
  11  *  Internet community.  Development is led by Duane Wessels of the
  12  *  National Laboratory for Applied Network Research and funded by the
  13  *  National Science Foundation.  Squid is Copyrighted (C) 1998 by
  14  *  the Regents of the University of California.  Please see the
  15  *  COPYRIGHT file for full details.  Squid incorporates software
  16  *  developed and/or copyrighted by other sources.  Please see the
  17  *  CREDITS file for full details.
  18  *
  19  *  This program is free software; you can redistribute it and/or modify
  20  *  it under the terms of the GNU General Public License as published by
  21  *  the Free Software Foundation; either version 2 of the License, or
  22  *  (at your option) any later version.
  23  *
  24  *  This program is distributed in the hope that it will be useful,
  25  *  but WITHOUT ANY WARRANTY; without even the implied warranty of
  26  *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  27  *  GNU General Public License for more details.
  28  *
  29  *  You should have received a copy of the GNU General Public License
  30  *  along with this program; if not, write to the Free Software
  31  *  Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111, USA.
  32  *
  33  */
  34
  35 /**
  36  * CPU Profiling implementation.
  37  *
  38  * \par
  39  *  This library implements the Probes needed to gather stats.
  40  *  See src/ProfStats.c which implements historical recording and
  41  *  presentation in CacheMgr.cgi.
  42  *
  43  * \par
  44  *  For timing we prefer on-CPU ops that retrieve cpu ticks counter.
  45  *  For Intel, this is "rdtsc", which is 64-bit counter that virtually
  46  *  never wraps. For alpha, this is "rpcc" which is 32-bit counter and
  47  *  wraps every few seconds. Currently, no handling of wrapping counters
  48  *  is implemented. Other CPU's are also not covered. Potentially all
  49  *  modern CPU's has similar counters.
  50  *
  51  * Usage.
  52  *  Insert macro PROF_state(probename) in strategic places in code.
  53  *    PROF_start(probename);
  54  *     ...  section of code measured ...
  55  *    PROF_stop(probename);
  56  *
  57  *   probename must be added to the xprof_type.h enum list
  58  *   with prepended "XPROF_" string.
  59  *
  60  * \section description Description.
  61  * \par PROF
  62  *  gathers stats per probename into structures. It indexes these
  63  *  structures by enum type index in an array.
  64  *
  65  * \par PROF
  66  *  records best, best, average and worst values for delta time,
  67  *  also, if UNACCED is defined, it measures "empty" time during which
  68  *  no probes are in measuring state. This allows to see time "unaccounted"
  69  *  for. If OVERHEAD is defined, additional calculations are made at every
  70  *  probe to measure approximate overhead of the probe code itself.
  71  *
  72  * \par
  73  *  Probe data is stored in linked-list, so the more probes you define,
  74  *  the more overhead is added to find the deepest nested probe. To reduce
  75  *  average overhead, linked list is manipulated each time PR_start is
  76  *  called, so that probe just started is moved 1 position up in linkedlist.
  77  *  This way frequently used probes are moved closer to the head of list,
  78  *  reducing average overhead.
  79  *  Note that all overhead is on the scale of one hundred of CPU clock
  80  *  ticks, which on the scale of submicroseconds. Yet, to optimise really
  81  *  fast and frequent sections of code, we want to reduce this overhead
  82  *  to absolute minimum possible.
  83  *
  84  * \par
  85  *  For actual measurements, probe overhead cancels out mostly. Still,
  86  *  do not take the measured times as facts, they should be viewed in
  87  *  relative comparison to overall CPU time and on the same platform.
  88  *
  89  * \par
  90  *  Every 1 second, Event within squid is called that parses gathered
  91  *  statistics of every probe, and accumulates that into historical
  92  *  structures for last 1,5,30 secs, 1,5,30 mins, and 1,5 and 24 hours.
  93  *  Each second active probe stats are reset, and only historical data
  94  *  is presented in cachemgr output.
  95  *
  96  * \section reading Reading stats.
  97  * \par
  98  *  "Worst case" may be misleading. Anything can happen at any section
  99  *  of code that could delay reaching to probe stop. For eg. system may
 100  *  need to service interrupt routine, task switch could occur, or page
 101  *  fault needs to be handled. In this sense, this is quite meaningless
 102  *  metric. "Best case" shows fastest completion of probe section, and
 103  *  is also somewhat useless, unless you know that amount of work is
 104  *  constant. Best metric to watch is "average time" and total cumulated
 105  *  time in given timeframe, which really show percentage of time spent
 106  *  in given section of code, and its average completion time. This data
 107  *  could be used to detect bottlenecks withing squid and optimise them.
 108  *
 109  * \par
 110  *  TOTALS are quite off reality. Its there just to summarise cumulative
 111  *  times and percent column. Percent values over 100% shows that there
 112  *  have been some probes nested into each other.
 113  *
 114  */
 115
 116 #include "squid.h"
 117 #include "profiler/Profiler.h"
 118
 119 #if USE_XPROF_STATS
 120
 121 #if HAVE_ASSERT_H
 122 #include <assert.h>
 123 #endif
 124 #if HAVE_GNUMALLLOC_H
 125 #include <gnumalloc.h>
 126 #elif HAVE_MALLOC_H
 127 #include <malloc.h>
 128 #endif
 129 #if HAVE_UNISTD_H
 130 #include <unistd.h>
 131 #endif
 132
 133 /* Exported Data */
 134 TimersArray *xprof_Timers = NULL;
 135
 136 /* Private stuff */
 137
 138 /* new stuff */
 139 #define MAXSTACKDEPTH   512
 140
 141 struct _callstack_entry {
 142     int timer;          /* index into timers array */
 143     const char *name;
 144     hrtime_t start, stop, accum;
 145 };
 146
 147 struct _callstack_entry cstack[MAXSTACKDEPTH];
 148 int cstack_head = 0;
 149
 150 #if defined(_MSC_VER) /* Microsoft C Compiler ONLY */
 151 static __inline void
 152 #else
 153 static inline void
 154 #endif
 155 xprof_update(xprof_stats_data * head)
 156 {
 157     if (head->delta < head->best)
 158         head->best = head->delta;
 159     if (head->worst < head->delta)
 160         head->worst = head->delta;
 161     head->summ += head->delta;
 162     ++head->count;
 163 }
 164
 165 static xprof_stats_data *xp_UNACCOUNTED;
 166 static int xprof_inited = 0;
 167
 168 static void
 169 xprof_InitLib(void)
 170 {
 171     if (xprof_inited)
 172         return;
 173
 174     xprof_Timers = static_cast<TimersArray *>(calloc(XPROF_LAST + 2, sizeof(xprof_stats_node)));
 175
 176     xprof_Timers[XPROF_PROF_UNACCOUNTED]->name = "PROF_UNACCOUNTED";
 177     xprof_Timers[XPROF_PROF_UNACCOUNTED]->accu.start = get_tick();
 178     xp_UNACCOUNTED = &xprof_Timers[XPROF_PROF_UNACCOUNTED]->accu;
 179     cstack_head = 0;
 180     xprof_inited = 1;
 181 }
 182
 183 void
 184 xprof_start(xprof_type type, const char *timer)
 185 {
 186     hrtime_t tt = get_tick();
 187     if (!xprof_inited)
 188         xprof_InitLib();
 189
 190     /* If nested, stop current stack frame */
 191     if (cstack_head > 0) {
 192         cstack[cstack_head - 1].accum += get_tick() - cstack[cstack_head - 1].start;
 193         cstack[cstack_head - 1].start = -1;
 194     }
 195
 196     /* Are we at the first level? If so; stop the unaccounted timer */
 197     if (cstack_head == 0) {
 198         assert(xp_UNACCOUNTED->start != -1);
 199         xp_UNACCOUNTED->delta = tt - xp_UNACCOUNTED->start;
 200         xp_UNACCOUNTED->start = -1;
 201         xprof_update(xp_UNACCOUNTED);
 202     }
 203
 204     /* Allocate new stack frame */
 205     cstack[cstack_head].start = tt;
 206     cstack[cstack_head].stop = -1;
 207     cstack[cstack_head].accum = 0;
 208     cstack[cstack_head].timer = type;
 209     cstack[cstack_head].name = timer;
 210     ++cstack_head;
 211     assert(cstack_head < MAXSTACKDEPTH);
 212
 213 }
 214
 215 void
 216 xprof_stop(xprof_type type, const char *timer)
 217 {
 218     hrtime_t tt = get_tick();
 219     assert(cstack_head > 0);
 220     --cstack_head;
 221     assert(cstack[cstack_head].timer == type);
 222
 223     /* Record timer details */
 224     cstack[cstack_head].accum += tt - cstack[cstack_head].start;
 225     xprof_Timers[type]->accu.delta = cstack[cstack_head].accum;
 226     xprof_Timers[type]->name = timer;
 227
 228     /* Update */
 229     xprof_update(&xprof_Timers[type]->accu);
 230
 231     /* Restart previous timer if we're not at the top level */
 232     if (cstack_head > 0) {
 233         cstack[cstack_head - 1].start = tt;
 234         cstack[cstack_head - 1].stop = 0;
 235         return;
 236     }
 237     /* Get here? We're at the top level; unaccounted */
 238     xp_UNACCOUNTED->start = tt;
 239 }
 240
 241 #endif /* USE_XPROF_STATS */