Event Profiler Timers?

[Steven D. Morrey]

>From: Andreas Ericsson [ae at op5.se]
>Sent: Wednesday, June 10, 2009 2:47 AM
>To: Nagios Developers List
>Subject: Re: [Nagios-devel] Event Profiler Timers?
>
>Steven D. Morrey wrote:
>>>> Would it be better (i.e. worth the overhead), to use clock_t =
>>>> clock() to get the entry and exit?
>>> Could be. But then we might as well use gettimeofday() from the
>>> start so the wrap-around case at least gets exercised a lot instead
>>> of every 72 minutes.
>>
>>I don't follow you on that, can you elaborate on what you mean by the
>>wrap-around case and it being exercised, because I am not aware of it
>> and therefore have not taken it into consideration. My primary
>> reasons for wanting to use clock instead of gettimeofday were speed
>> and precision.
>>
>
>Righto. clock(3) returns a value that represents seconds in 1/1000000
>"scale". This means that, for 32-bit architectures, it will wrap around
>every 71m 34.96s. Consider this:
>
>start = clock();
>do_stuff();
>end = clock();
>
>if (end < start) {
>        /* wrapped around */
>        delta = (end + (1 << (sizeof(end) * CHAR_BIT)) - start;
>} else {
>        delta = end - start;
>}
>
>This might *look* right, but it really isn't. Some compilers can't
>store the intermittent value from the first case (which *will* wrap
>around once again), so it will get the result wrong, causing delta
>to end up as a huge number (clock_t can't be negative) and severely
>skewing the performance data. Since this will happen only for some
>compilers on some archs, and only every ~72 minutes, it will be
>pure hell to track down.
>
>Otoh, it might be worth doing something like this:
>
>clock_t start;
>double delta;
>
>start = clock();
>do_stuff();
>delta = clock_delta(start, clock());
>
>static double clock_delta(clock_t start, clock_t end)
>{
>        if (end > start) {
>               /* normal case */
>                delta = (double)(end - start);
>        }
>        if (end < start) {
>                /* wrap-around */
>                delta = (double)(end + (1 << (sizeof(end) * CHAR_BIT)));
>                delta -= (float)start;
>        }
>
>        return delta / CLOCKS_PER_SEC;
>}
>
>which should always provide the value as a fraction of seconds,
>which is almost certainly how you want to display it anyways.

This is fantastic information, and oddly enough explains a bug in a game server I once worked on, every hour and 15 minutes it would kick all the players out.
It was a truly nasty and annoying bug but now I know how and why it did it, so thanks for the excellent information.

>On a side-note, try to use arrays of doubles to store the total
>delta. It's much neater than having multiple global variables.

Yeah I'm going to make some changes to this and create a new profiler struct that holds both the timer and the counter, then create an array of those using the event type as a key, it'll make maintaining and extending a lot easier.

>The clock_delta function is also quite easily testable which
>alleviates the worries about the wrap-around case not being tested
>much.

Mind if I steal this code for something unrelated?

>> With gettimeofday we are talking about how much calendar time has
>> been spent, whereas with clock we are talking about how many ticks
>> were used by the program and then dividing that by clocks_per_second
>> to get a process time. I believe that clock would be more accurate
>> since it filters out the cost of other processes running on the
>> system.
>
>
>True, but the meaning of it would be hard to correlate against latency,
>since some events spend an inordinate amount of time switching contexts
>while others are fairly cpu-intensive but achieve a lot in wallclock
>time. Parsing passive check-results is CPU-intensive, but in wallclock
>time we can easily parse 50 or 100 of them in the same time it takes to
>fork and fire up a plugin. I'm not sure which of the values would be
>preferrable here, and I'm also not sure which of the processes gets the
>CPU-time attributed to it.

I really can't win for loosing with this one can I?  No matter which way we profile there is going to be either something added or something missing.

Thanks again for taking the time to read this.

Sincerely,
Steve


 NOTICE: This email message is for the sole use of the intended recipient(s) and may contain confidential and privileged information. Any unauthorized review, use, disclosure or distribution is prohibited. If you are not the intended recipient, please contact the sender by reply email and destroy all copies of the original message.



------------------------------------------------------------------------------
Crystal Reports - New Free Runtime and 30 Day Trial
Check out the new simplified licensing option that enables unlimited
royalty-free distribution of the report engine for externally facing 
server and web deployment.
http://p.sf.net/sfu/businessobjects