chiark / gitweb /
debugging for thing that crashed
[innduct.git] / 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 }