[squid-dev] [PATCH] Logging fast things

[Tsantilas Christos]

On 11/19/2014 11:51 PM, Amos Jeffries wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
>
> On 20/11/2014 7:35 a.m., Tsantilas Christos wrote:
>> Hi all,
>>
>> In many cases HITs logged with zero response times. The logging
>> entries are correct, those transaction took less than a
>> millisecond. However, to better monitor Squid performance and to
>> optimize things further, a user may want to see more precise
>> response time measurements logged.
>>
>> This patch add configurable "precision" for time-related fields
>> such as %tr, using a .n syntax similar to the syntax used by the
>> well-known printf(3) API to mean "maximum field width".
>>
>> Examples: %tr   -- 0 -- millisecond precision (no change compared
>> to today) %.3tr -- 0.123 -- microsecond precision (after this
>> project) %.6tr -- 0.123456 -- nanosecond precision (year 2050
>> trading platform??)
>>
>>
>> Technical notes ==================
>>
>> At the first stages of this patch I used double to record times
>> for logging, bug finally I selected to use timeval structures. I
>> hope it is good choice
>>
>> A problem I have was to identify uninitialized timeval values.
>> Currently squid uses signed integers to record millisecond values
>> and a negative value means uninitialized variable. Finally I used
>> -1 to the timeval::tv_sec field, to mark uninitialized timeval
>> variables. The timeval::tv_sec member is of type time_t and we are
>> already using "-1" to mark uninitialized time_t variables in some
>> places inside squid. An alternate approach is to use for this
>> purpose a MAXLONG, or maybe the std::numeric_limits<time_t>::max()
>> value.
>>
>> The DNS time (%dt code) is still in milliseconds.
>>
>> Also I did not touch mgr statistics. Still the statistics values
>> computed using milliseconds.
>>
>
> Yay! this has been on the TODO list for a long time :-).
>
>
> +1. The below are all documentation details, so when done can be
> committed without another audit IMO.

Applied to trunk with the fixes you are requested.

Regards,
    Christos

>
>
>
> Everywhere:
>
> * please be consistent with using struct on the type name. Its needed
> to be there in at least function/method paramaters by some compilers
> (doxygen in particular) to prevent confusion with class names.
>
>
> in src/AccessLogEntry.h
>
> * please take the opportunity to document what trTime is now that you
> are changing the code line.
>
>
> in src/SquidTime.h:
>
> * for the new tvSub/tvAdd functions please use the parameter ordering
> of output params before const/input params.
>
> * missing 'l' in miliseconds.
>   - in fact this typo is repeated in multiple places across the patch
>
> * missing spaces in:  ///timeval
>
> * for readability please place an empty line between previous function
> declaration and comment about the next
>
> * also in the doxygen, instead of (res = t1 + t2) please use syntax:
>    /// \param[out] res = t1 + t2
>
>
> in src/adaptation/icap/History.cc:
>
> * when changing debugs() lines please remove HERE macro.
>
>
> in src/adaptation/icap/History.h:
>
> * please take the opportunity to doxygen-format the comments on
> processingTime().
>   - in particular there is no longer a return value. Add the name
> ("total") of the parameter from .cc file and replace "returns" with:
>     \param[out] total time taken for all ICAP processing
>
> * comment indentation on pastTime is odd, please use space instead of
> tab to align.
>
>
> Amos
>