Re: (ITS#8054) Operation duration logging

[h.b.furuseth@usit.uio.no]

Cool feture, but please use fewer characteres in the already
bloated log.  How about "time=<integer>us" or even omit the "us"?

When duration is of interest, what's usually interesting is probably
which operations stand out as slower, not the actual speed.  When
duration is not of interest, then it's noise to keep small and boring.

And we should document at least the default log format (Statslog).

==

About the code, ignoring the above suggestion for now:


Once upon a time, floating-point was slow. Today, that extra code
to avoid it is a pessimization at least on my Linux/x86.  Try this:

#define TIMEDIFF_MS(a,b) \
     (((a)->tv_sec-(b)->tv_sec)*1000 + ((a)->tv_usec-(b)->tv_usec)/1000.0)

OTOH floating-point printf is compex, you save a bit by doing
msec = (int)t; printf("%d.%03d", msec, (int)((t-msec)*1000));
instead of printf("%4.3f", t);


%d format requires 'int msec;' and (int)(duration.tv_usec % 1000).


Since timersub() is use the same way each time, a macro could
instead compute duration and msec, and maybe declare them too:
     DURATION_DECLARE(duration, msec, op->o_hr_time);

For that matter, maybe we should get rid of the #ifdef-duplicated
Statslog() statements and put the ugliness in macros instead.
Like this, I think - an untested draft:

     DURATION_DECLARE(duration, msec, op->o_hr_time);
     StatslogDuration( LDAP_DEBUG_STATS,
         "%s DISCONNECT tag=%lu err=%d "DURATION_LOG_FMT" text=%s\n",
         op->o_log_prefix, rs->sr_tag, rs->sr_err,
         DURATION_LOG_ARG(duration, msec) /* no comma after this */
         rs->sr_text ? rs->sr_text : "", 0 );

#ifdef HAVE_GETTIMEOFDAY
#define DURATION_DECLARE(..blah..) <the duration code before Statslog>
#define DURATION_LOG_FMT "duration=%d.%03dms "
/* This is passed to StatslogDuration() without a comma before next arg.
  * So it is not an extra arg to StatslogDuration(), but it gives two
  * extra 'int' args to whatever StatslogDuration() passes it args on to.
  */
#define DURATION_LOG_ARG(duration,msec) (msec), 
(int)((duration).tv_usec%1000),
#define StatslogDuration <like Statslog, but using Log7 instead of Log5>
#else
#define DURATION_DECLARE(..blah..)
#define DURATION_LOG_FMT ""
#define DURATION_LOG_ARG(duration, msec)
#define StatslogDuration Statslog
#endif