[squid-dev] [PATCH] Logging fast things

[Amos Jeffries]

-----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.



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

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.22 (MingW32)

iQEcBAEBAgAGBQJUbRD4AAoJELJo5wb/XPRja0wH/14AfleU+/nwpr/yc+/6Q1aj
M5FFkvYuW9QtcxNWIq2rnV7Pb+nxnI98JAawj2zggNwKUnP1Gtkb9WU+2pBIHkc+
0qJn8emyZOGaJtKmrndZL+dGRMenNmtTVFYEu90PvXbmBP/wB3vWUY7R2t4YB5f+
1I1pU5tJL1Ny74Akz97j/9Y4MrGIzDVzDWQ5ZfpCKhtR/3uL2+sHe/J2SrST3b1h
gGXnN3dQih3ubkz0gq40ab47yT/Crv+zQoTb0M2Rvf7mYp8XajBk20uO10PTCKyU
NYMwoW3C2j4btq+7+sBRRQANwuHh1lVHuauKvnzEg/zubGA+0C2VRTEnVAv7MRI=
=FRm1
-----END PGP SIGNATURE-----