lib/timer.c

   1 /*  $Id: timer.c 6129 2003-01-19 00:39:49Z rra $
   2 **
   3 **  Timer functions, to gather profiling data.
   4 **
   5 **  These functions log profiling information about where the server spends
   6 **  its time.  While this doesn't provide as detailed of information as a
   7 **  profiling build would, it's much faster and simpler, and since it's fast
   8 **  enough to always leave on even on production servers, it can gather
   9 **  information *before* it's needed and show long-term trends.
  10 **
  11 **  Functions that should have their time monitored need to call TMRstart(n)
  12 **  at the beginning of the segment of code and TMRstop(n) at the end.  The
  13 **  time spent will be accumulated and added to the total for the counter n,
  14 **  where n should be one of the constants in timer.h or defined in your
  15 **  application.  If you add new timers in the library code, add them to
  16 **  timer.h and also add a description to TMRsummary; if you add them in
  17 **  your application add them to your own description array.  Also add them
  18 **  to innreport.
  19 **
  20 **  Calls are sanity-checked to some degree and errors reported via
  21 **  warn/die, so all callers should have the proper warn and die handlers
  22 **  set up, if appropriate.
  23 **
  24 **  Recursion is not allowed on a given timer.  Setting multiple timers
  25 **  at once is fine (i.e., you may have a timer for the total time to write
  26 **  an article, how long the disk write takes, how long the history update
  27 **  takes, etc. which are components of the total article write time).  If a
  28 **  timer is started while another timer is running, the new timer is
  29 **  considered to be a sub-timer of the running timer, and must be stopped
  30 **  before the parent timer is stopped.  Note that the same timer number can
  31 **  be a sub-timer of more than one timer or a timer without a parent, and
  32 **  each of those counts will be reported separately.
  33 **
  34 **  Note that this code is not thread-safe and in fact would need to be
  35 **  completely overhauled for a threaded server (since the idea of global
  36 **  timing statistics doesn't make as much sense when different tasks are
  37 **  done in different threads).
  38 */
  39
  40 #include "config.h"
  41 #include "clibrary.h"
  42 #include "portable/time.h"
  43 #include <syslog.h>
  44
  45 #include "inn/messages.h"
  46 #include "inn/timer.h"
  47 #include "libinn.h"
  48
  49 /* Timer values are stored in a series of trees.  This allows use to use
  50    nested timers.  Each nested timer node is linked to three of its
  51    neighbours to make lookups easy and fast.  The current position in the
  52    graph is given by timer_current.
  53
  54    As an optimization, since most timers aren't nested, timer_list holds an
  55    array of pointers to non-nested timers that's filled in as TMRstart is
  56    called so that the non-nested case remains O(1).  That array is stored in
  57    timers.  This is the "top level" of the timer trees; if timer_current is
  58    NULL, any timer that's started is found in this array.  If timer_current
  59    isn't NULL, there's a running timer, and starting a new timer adds to
  60    that tree.
  61
  62    Note that without the parent pointer, this is a tree.  id is the
  63    identifier of the timer.  start stores the time (relative to the last
  64    summary) at which TMRstart was last called for each timer.  total is
  65    the total time accrued by that timer since the last summary.  count is
  66    the number of times the timer has been stopped since the last summary. */
  67 struct timer {
  68     unsigned int id;
  69     unsigned long start;
  70     unsigned long total;
  71     unsigned long count;
  72
  73     struct timer *parent;
  74     struct timer *brother;
  75     struct timer *child;
  76 };
  77 static struct timer **timers = NULL;
  78 static struct timer *timer_current = NULL;
  79 unsigned int timer_count = 0;
  80
  81 /* Names for all of the timers.  These must be given in the same order
  82    as the definition of the enum in timer.h. */
  83 static const char *const timer_name[TMR_APPLICATION] = {
  84     "hishave", "hisgrep", "hiswrite", "hissync",
  85 };
  86
  87
  88 /*
  89 **  Returns the current time as a double.  This is not used by any of the
  90 **  other timer code, but is used by various programs right now to keep track
  91 **  of elapsed time.
  92 */
  93 double
  94 TMRnow_double(void)
  95 {
  96     struct timeval tv;
  97
  98     gettimeofday(&tv, NULL);
  99     return (tv.tv_sec + tv.tv_usec * 1.0e-6);
 100 }
 101
 102
 103 /*
 104 **  Returns the number of milliseconds since the base time.  This gives
 105 **  better resolution than time, but the return value is a lot easier to
 106 **  work with than a struct timeval.  If the argument is true, also reset
 107 **  the base time.
 108 */
 109 static unsigned long
 110 TMRgettime(bool reset)
 111 {
 112     unsigned long now;
 113     struct timeval tv;
 114
 115     /* The time of the last summary, used as a base for times returned by
 116        TMRnow.  Formerly, times were relative to the last call to TMRinit,
 117        which was only called once when innd was starting up; with that
 118        approach, times may overflow a 32-bit unsigned long about 50 days
 119        after the server starts up.  While this may still work due to unsigned
 120        arithmetic, this approach is less confusing to follow. */
 121     static struct timeval base;
 122
 123     gettimeofday(&tv, NULL);
 124     now = (tv.tv_sec - base.tv_sec) * 1000;
 125     now += (tv.tv_usec - base.tv_usec) / 1000;
 126     if (reset)
 127         base = tv;
 128     return now;
 129 }
 130
 131
 132 /*
 133 **  Initialize the timer.  Zero out even variables that would initially be
 134 **  zero so that this function can be called multiple times if wanted.
 135 */
 136 void
 137 TMRinit(unsigned int count)
 138 {
 139     unsigned int i;
 140
 141     /* TMRinit(0) disables all timers. */
 142     TMRfree();
 143     if (count != 0) {
 144         timers = xmalloc(count * sizeof(struct timer *));
 145         for (i = 0; i < count; i++)
 146             timers[i] = NULL;
 147         TMRgettime(true);
 148     }
 149     timer_count = count;
 150 }
 151
 152
 153 /*
 154 **  Recursively destroy a timer node.
 155 */
 156 static void
 157 TMRfreeone(struct timer *timer)
 158 {
 159     if (timer == NULL)
 160         return;
 161     if (timer->child != NULL)
 162         TMRfreeone(timer->child);
 163     if (timer->brother != NULL)
 164         TMRfreeone(timer->brother);
 165     free(timer);
 166 }
 167
 168
 169 /*
 170 **  Free all timers and the resources devoted to them.
 171 */
 172 void
 173 TMRfree(void)
 174 {
 175     unsigned int i;
 176
 177     if (timers != NULL)
 178         for (i = 0; i < timer_count; i++)
 179             TMRfreeone(timers[i]);
 180     free(timers);
 181     timers = NULL;
 182     timer_count = 0;
 183 }
 184
 185
 186 /*
 187 **  Allocate a new timer node.  Takes the id and the parent pointer.
 188 */
 189 static struct timer *
 190 TMRnew(unsigned int id, struct timer *parent)
 191 {
 192     struct timer *timer;
 193
 194     timer = xmalloc(sizeof(struct timer));
 195     timer->parent = parent;
 196     timer->brother = NULL;
 197     timer->child = NULL;
 198     timer->id = id;
 199     timer->start = 0;
 200     timer->total = 0;
 201     timer->count = 0;
 202     return timer;
 203 }
 204
 205
 206 /*
 207 **  Start a particular timer.  If no timer is currently running, start one
 208 **  of the top-level timers in the timers array (creating a new one if
 209 **  needed).  Otherwise, search for the timer among the children of the
 210 **  currently running timer, again creating a new timer if necessary.
 211 */
 212 void
 213 TMRstart(unsigned int timer)
 214 {
 215     struct timer *search;
 216
 217     if (timer_count == 0) {
 218         /* this should happen if innconf->timer == 0 */
 219         return;
 220     }
 221     if (timer >= timer_count) {
 222         warn("timer %u is larger than the maximum timer %u, ignored",
 223              timer, timer_count - 1);
 224         return;
 225     }
 226
 227     /* timers will be non-NULL if timer_count > 0. */
 228     if (timer_current == NULL) {
 229         if (timers[timer] == NULL)
 230             timers[timer] = TMRnew(timer, NULL);
 231         timer_current = timers[timer];
 232     } else {
 233         search = timer_current;
 234
 235         /* Go to the "child" level and look for the good "brother"; the
 236            "brothers" are a simple linked list. */
 237         if (search->child == NULL) {
 238             search->child = TMRnew(timer, search);
 239             timer_current = search->child;
 240         } else {
 241             search = search->child;
 242             while (search->id != timer && search->brother != NULL)
 243                 search = search->brother;
 244             if (search->id != timer) {
 245                 search->brother = TMRnew(timer, search->parent);
 246                 timer_current = search->brother;
 247             } else {
 248                 timer_current = search;
 249             }
 250         }
 251     }
 252     timer_current->start = TMRgettime(false);
 253 }
 254
 255
 256 /*
 257 **  Stop a particular timer, adding the total time to total and incrementing
 258 **  the count of times that timer has been invoked.
 259 */
 260 void
 261 TMRstop(unsigned int timer)
 262 {
 263     if (timer_count == 0) {
 264         /* this should happen if innconf->timer == 0 */
 265         return;
 266     }
 267     if (timer_current == NULL)
 268         warn("timer %u stopped when no timer was running", timer);
 269     else if (timer != timer_current->id)
 270         warn("timer %u stopped doesn't match running timer %u", timer,
 271              timer_current->id);
 272     else {
 273         timer_current->total += TMRgettime(false) - timer_current->start;
 274         timer_current->count++;
 275         timer_current = timer_current->parent;
 276     }
 277 }
 278
 279
 280 /*
 281 **  Return the current time in milliseconds since the last summary or the
 282 **  initialization of the timer.  This is intended for use by the caller to
 283 **  determine when next to call TMRsummary.
 284 */
 285 unsigned long
 286 TMRnow(void)
 287 {
 288     return TMRgettime(false);
 289 }
 290
 291
 292 /*
 293 **  Return the label associated with timer number id.  Used internally
 294 **  to do the right thing when fetching from the timer_name or labels
 295 **  arrays
 296 */
 297 static const char *
 298 TMRlabel(const char *const *labels, unsigned int id)
 299 {
 300     if (id >= TMR_APPLICATION)
 301         return labels[id - TMR_APPLICATION];
 302     else
 303         return timer_name[id];
 304 }
 305
 306
 307
 308 /*
 309 **  Recursively summarize a single timer tree into the supplied buffer,
 310 **  returning the number of characters added to the buffer.
 311 */
 312 static size_t
 313 TMRsumone(const char *const *labels, struct timer *timer, char *buf,
 314           size_t len)
 315 {
 316     struct timer *node;
 317     size_t off = 0;
 318
 319     /* This results in "child/parent nn(nn)" instead of the arguably more
 320        intuitive "parent/child" but it's easy.  Since we ensure sane snprintf
 321        semantics, it's safe to defer checking for overflow until after
 322        formatting all of the timer data. */
 323     for (node = timer; node != NULL; node = node->parent)
 324         off += snprintf(buf + off, len - off, "%s/",
 325                         TMRlabel(labels, node->id));
 326     off--;
 327     off += snprintf(buf + off, len - off, " %lu(%lu) ", timer->total,
 328                     timer->count);
 329     if (off == len) {
 330         warn("timer log too long while processing %s",
 331              TMRlabel(labels, timer->id));
 332         return 0;
 333     }
 334
 335     timer->total = 0;
 336     timer->count = 0;
 337     if (timer->child != NULL)
 338         off += TMRsumone(labels, timer->child, buf + off, len - off);
 339     if (timer->brother != NULL)
 340         off += TMRsumone(labels, timer->brother, buf + off, len - off);
 341     return off;
 342 }
 343
 344
 345 /*
 346 **  Summarize the current timer statistics, report them to syslog, and then
 347 **  reset them for the next polling interval.
 348 */
 349 void
 350 TMRsummary(const char *prefix, const char *const *labels)
 351 {
 352     char *buf;
 353     unsigned int i;
 354     size_t len, off;
 355
 356     /* To find the needed buffer size, note that a 64-bit unsigned number can
 357        be up to 20 digits long, so each timer can be 52 characters.  We also
 358        allow another 27 characters for the introductory timestamp, plus some
 359        for the prefix.  We may have timers recurring at multiple points in
 360        the structure, so this may not be long enough, but this is over-sized
 361        enough that it shouldn't be a problem.  We use snprintf, so if the
 362        buffer isn't large enough it will just result in logged errors. */
 363     len = 52 * timer_count + 27 + (prefix == NULL ? 0 : strlen(prefix)) + 1;
 364     buf = xmalloc(len);
 365     if (prefix == NULL)
 366         off = 0;
 367     else
 368         off = snprintf(buf, len, "%s ", prefix);
 369     off += snprintf(buf + off, len - off, "time %ld ", TMRgettime(true));
 370     for (i = 0; i < timer_count; i++)
 371         if (timers[i] != NULL)
 372             off += TMRsumone(labels, timers[i], buf + off, len - off);
 373     syslog(LOG_NOTICE, "%s", buf);
 374     free(buf);
 375 }