/* $Id: timer.c 6129 2003-01-19 00:39:49Z rra $ ** ** Timer functions, to gather profiling data. ** ** These functions log profiling information about where the server spends ** its time. While this doesn't provide as detailed of information as a ** profiling build would, it's much faster and simpler, and since it's fast ** enough to always leave on even on production servers, it can gather ** information *before* it's needed and show long-term trends. ** ** Functions that should have their time monitored need to call TMRstart(n) ** at the beginning of the segment of code and TMRstop(n) at the end. The ** time spent will be accumulated and added to the total for the counter n, ** where n should be one of the constants in timer.h or defined in your ** application. If you add new timers in the library code, add them to ** timer.h and also add a description to TMRsummary; if you add them in ** your application add them to your own description array. Also add them ** to innreport. ** ** Calls are sanity-checked to some degree and errors reported via ** warn/die, so all callers should have the proper warn and die handlers ** set up, if appropriate. ** ** Recursion is not allowed on a given timer. Setting multiple timers ** at once is fine (i.e., you may have a timer for the total time to write ** an article, how long the disk write takes, how long the history update ** takes, etc. which are components of the total article write time). If a ** timer is started while another timer is running, the new timer is ** considered to be a sub-timer of the running timer, and must be stopped ** before the parent timer is stopped. Note that the same timer number can ** be a sub-timer of more than one timer or a timer without a parent, and ** each of those counts will be reported separately. ** ** Note that this code is not thread-safe and in fact would need to be ** completely overhauled for a threaded server (since the idea of global ** timing statistics doesn't make as much sense when different tasks are ** done in different threads). */ #include "config.h" #include "clibrary.h" #include "portable/time.h" #include #include "inn/messages.h" #include "inn/timer.h" #include "libinn.h" /* Timer values are stored in a series of trees. This allows use to use nested timers. Each nested timer node is linked to three of its neighbours to make lookups easy and fast. The current position in the graph is given by timer_current. As an optimization, since most timers aren't nested, timer_list holds an array of pointers to non-nested timers that's filled in as TMRstart is called so that the non-nested case remains O(1). That array is stored in timers. This is the "top level" of the timer trees; if timer_current is NULL, any timer that's started is found in this array. If timer_current isn't NULL, there's a running timer, and starting a new timer adds to that tree. Note that without the parent pointer, this is a tree. id is the identifier of the timer. start stores the time (relative to the last summary) at which TMRstart was last called for each timer. total is the total time accrued by that timer since the last summary. count is the number of times the timer has been stopped since the last summary. */ struct timer { unsigned int id; unsigned long start; unsigned long total; unsigned long count; struct timer *parent; struct timer *brother; struct timer *child; }; static struct timer **timers = NULL; static struct timer *timer_current = NULL; unsigned int timer_count = 0; /* Names for all of the timers. These must be given in the same order as the definition of the enum in timer.h. */ static const char *const timer_name[TMR_APPLICATION] = { "hishave", "hisgrep", "hiswrite", "hissync", }; /* ** Returns the current time as a double. This is not used by any of the ** other timer code, but is used by various programs right now to keep track ** of elapsed time. */ double TMRnow_double(void) { struct timeval tv; gettimeofday(&tv, NULL); return (tv.tv_sec + tv.tv_usec * 1.0e-6); } /* ** Returns the number of milliseconds since the base time. This gives ** better resolution than time, but the return value is a lot easier to ** work with than a struct timeval. If the argument is true, also reset ** the base time. */ static unsigned long TMRgettime(bool reset) { unsigned long now; struct timeval tv; /* The time of the last summary, used as a base for times returned by TMRnow. Formerly, times were relative to the last call to TMRinit, which was only called once when innd was starting up; with that approach, times may overflow a 32-bit unsigned long about 50 days after the server starts up. While this may still work due to unsigned arithmetic, this approach is less confusing to follow. */ static struct timeval base; gettimeofday(&tv, NULL); now = (tv.tv_sec - base.tv_sec) * 1000; now += (tv.tv_usec - base.tv_usec) / 1000; if (reset) base = tv; return now; } /* ** Initialize the timer. Zero out even variables that would initially be ** zero so that this function can be called multiple times if wanted. */ void TMRinit(unsigned int count) { unsigned int i; /* TMRinit(0) disables all timers. */ TMRfree(); if (count != 0) { timers = xmalloc(count * sizeof(struct timer *)); for (i = 0; i < count; i++) timers[i] = NULL; TMRgettime(true); } timer_count = count; } /* ** Recursively destroy a timer node. */ static void TMRfreeone(struct timer *timer) { if (timer == NULL) return; if (timer->child != NULL) TMRfreeone(timer->child); if (timer->brother != NULL) TMRfreeone(timer->brother); free(timer); } /* ** Free all timers and the resources devoted to them. */ void TMRfree(void) { unsigned int i; if (timers != NULL) for (i = 0; i < timer_count; i++) TMRfreeone(timers[i]); free(timers); timers = NULL; timer_count = 0; } /* ** Allocate a new timer node. Takes the id and the parent pointer. */ static struct timer * TMRnew(unsigned int id, struct timer *parent) { struct timer *timer; timer = xmalloc(sizeof(struct timer)); timer->parent = parent; timer->brother = NULL; timer->child = NULL; timer->id = id; timer->start = 0; timer->total = 0; timer->count = 0; return timer; } /* ** Start a particular timer. If no timer is currently running, start one ** of the top-level timers in the timers array (creating a new one if ** needed). Otherwise, search for the timer among the children of the ** currently running timer, again creating a new timer if necessary. */ void TMRstart(unsigned int timer) { struct timer *search; if (timer_count == 0) { /* this should happen if innconf->timer == 0 */ return; } if (timer >= timer_count) { warn("timer %u is larger than the maximum timer %u, ignored", timer, timer_count - 1); return; } /* timers will be non-NULL if timer_count > 0. */ if (timer_current == NULL) { if (timers[timer] == NULL) timers[timer] = TMRnew(timer, NULL); timer_current = timers[timer]; } else { search = timer_current; /* Go to the "child" level and look for the good "brother"; the "brothers" are a simple linked list. */ if (search->child == NULL) { search->child = TMRnew(timer, search); timer_current = search->child; } else { search = search->child; while (search->id != timer && search->brother != NULL) search = search->brother; if (search->id != timer) { search->brother = TMRnew(timer, search->parent); timer_current = search->brother; } else { timer_current = search; } } } timer_current->start = TMRgettime(false); } /* ** Stop a particular timer, adding the total time to total and incrementing ** the count of times that timer has been invoked. */ void TMRstop(unsigned int timer) { if (timer_count == 0) { /* this should happen if innconf->timer == 0 */ return; } if (timer_current == NULL) warn("timer %u stopped when no timer was running", timer); else if (timer != timer_current->id) warn("timer %u stopped doesn't match running timer %u", timer, timer_current->id); else { timer_current->total += TMRgettime(false) - timer_current->start; timer_current->count++; timer_current = timer_current->parent; } } /* ** Return the current time in milliseconds since the last summary or the ** initialization of the timer. This is intended for use by the caller to ** determine when next to call TMRsummary. */ unsigned long TMRnow(void) { return TMRgettime(false); } /* ** Return the label associated with timer number id. Used internally ** to do the right thing when fetching from the timer_name or labels ** arrays */ static const char * TMRlabel(const char *const *labels, unsigned int id) { if (id >= TMR_APPLICATION) return labels[id - TMR_APPLICATION]; else return timer_name[id]; } /* ** Recursively summarize a single timer tree into the supplied buffer, ** returning the number of characters added to the buffer. */ static size_t TMRsumone(const char *const *labels, struct timer *timer, char *buf, size_t len) { struct timer *node; size_t off = 0; /* This results in "child/parent nn(nn)" instead of the arguably more intuitive "parent/child" but it's easy. Since we ensure sane snprintf semantics, it's safe to defer checking for overflow until after formatting all of the timer data. */ for (node = timer; node != NULL; node = node->parent) off += snprintf(buf + off, len - off, "%s/", TMRlabel(labels, node->id)); off--; off += snprintf(buf + off, len - off, " %lu(%lu) ", timer->total, timer->count); if (off == len) { warn("timer log too long while processing %s", TMRlabel(labels, timer->id)); return 0; } timer->total = 0; timer->count = 0; if (timer->child != NULL) off += TMRsumone(labels, timer->child, buf + off, len - off); if (timer->brother != NULL) off += TMRsumone(labels, timer->brother, buf + off, len - off); return off; } /* ** Summarize the current timer statistics, report them to syslog, and then ** reset them for the next polling interval. */ void TMRsummary(const char *prefix, const char *const *labels) { char *buf; unsigned int i; size_t len, off; /* To find the needed buffer size, note that a 64-bit unsigned number can be up to 20 digits long, so each timer can be 52 characters. We also allow another 27 characters for the introductory timestamp, plus some for the prefix. We may have timers recurring at multiple points in the structure, so this may not be long enough, but this is over-sized enough that it shouldn't be a problem. We use snprintf, so if the buffer isn't large enough it will just result in logged errors. */ len = 52 * timer_count + 27 + (prefix == NULL ? 0 : strlen(prefix)) + 1; buf = xmalloc(len); if (prefix == NULL) off = 0; else off = snprintf(buf, len, "%s ", prefix); off += snprintf(buf + off, len - off, "time %ld ", TMRgettime(true)); for (i = 0; i < timer_count; i++) if (timers[i] != NULL) off += TMRsumone(labels, timers[i], buf + off, len - off); syslog(LOG_NOTICE, "%s", buf); free(buf); }