1 /* $Id: timer.c 6129 2003-01-19 00:39:49Z rra $
3 ** Timer functions, to gather profiling data.
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.
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
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.
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.
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).
42 #include "portable/time.h"
45 #include "inn/messages.h"
46 #include "inn/timer.h"
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.
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
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. */
74 struct timer *brother;
77 static struct timer **timers = NULL;
78 static struct timer *timer_current = NULL;
79 unsigned int timer_count = 0;
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",
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
98 gettimeofday(&tv, NULL);
99 return (tv.tv_sec + tv.tv_usec * 1.0e-6);
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
110 TMRgettime(bool reset)
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;
123 gettimeofday(&tv, NULL);
124 now = (tv.tv_sec - base.tv_sec) * 1000;
125 now += (tv.tv_usec - base.tv_usec) / 1000;
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.
137 TMRinit(unsigned int count)
141 /* TMRinit(0) disables all timers. */
144 timers = xmalloc(count * sizeof(struct timer *));
145 for (i = 0; i < count; i++)
154 ** Recursively destroy a timer node.
157 TMRfreeone(struct timer *timer)
161 if (timer->child != NULL)
162 TMRfreeone(timer->child);
163 if (timer->brother != NULL)
164 TMRfreeone(timer->brother);
170 ** Free all timers and the resources devoted to them.
178 for (i = 0; i < timer_count; i++)
179 TMRfreeone(timers[i]);
187 ** Allocate a new timer node. Takes the id and the parent pointer.
189 static struct timer *
190 TMRnew(unsigned int id, struct timer *parent)
194 timer = xmalloc(sizeof(struct timer));
195 timer->parent = parent;
196 timer->brother = NULL;
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.
213 TMRstart(unsigned int timer)
215 struct timer *search;
217 if (timer_count == 0) {
218 /* this should happen if innconf->timer == 0 */
221 if (timer >= timer_count) {
222 warn("timer %u is larger than the maximum timer %u, ignored",
223 timer, timer_count - 1);
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];
233 search = timer_current;
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;
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;
248 timer_current = search;
252 timer_current->start = TMRgettime(false);
257 ** Stop a particular timer, adding the total time to total and incrementing
258 ** the count of times that timer has been invoked.
261 TMRstop(unsigned int timer)
263 if (timer_count == 0) {
264 /* this should happen if innconf->timer == 0 */
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,
273 timer_current->total += TMRgettime(false) - timer_current->start;
274 timer_current->count++;
275 timer_current = timer_current->parent;
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.
288 return TMRgettime(false);
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
298 TMRlabel(const char *const *labels, unsigned int id)
300 if (id >= TMR_APPLICATION)
301 return labels[id - TMR_APPLICATION];
303 return timer_name[id];
309 ** Recursively summarize a single timer tree into the supplied buffer,
310 ** returning the number of characters added to the buffer.
313 TMRsumone(const char *const *labels, struct timer *timer, char *buf,
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));
327 off += snprintf(buf + off, len - off, " %lu(%lu) ", timer->total,
330 warn("timer log too long while processing %s",
331 TMRlabel(labels, timer->id));
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);
346 ** Summarize the current timer statistics, report them to syslog, and then
347 ** reset them for the next polling interval.
350 TMRsummary(const char *prefix, const char *const *labels)
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;
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);