PATCH: $time_custom supports a custom log timestamp

Hi there. The company I work for, SourceForge, wanted the ability to
have a custom timestamp in a log file, so I created a patch for this. I
have been authorized to release it back to the nginx community. See
what you think of my design and let me know if you have any ideas for
improvements.

The patch implements the following:

For every named log format there may be defined a custom timestamp
format
that will be passed to strftime() for expansion. This string is
accessed
via $time_custom instead of $time_local. (It defaults to expanding to
an
empty string unless the user specifies a time_custom_format value for
the
named log format.) Inside the custom format one extra variable
expansion
is supported: the use of “$ms” will substitute a 3-digit milliseconds
value at that point.

For example:

log_format  main  '$remote_addr - $remote_user [$time_custom] 

“$request” ’
'$status $body_bytes_sent “$http_referer” ’
‘"$http_user_agent" “$http_x_forwarded_for”’;

time_custom_format main '%d/%b/%Y:%H:%M:%S.$ms %z';

That defines a log format that is like $time_local except that it gets
millisecond logging resolution. Obviously, the string doesn’t need to
be quite so similar to the default, but you get the idea.

Here’s the patch:

http://opencoder.net/nginx-time_custom.patch

The code caches the strftime() expansion so that all loggers using the
named log format cause strftime() to be called at most once per second.

Please let me know what you think.

…wayne…

Hi,

The code caches the strftime() expansion so that all loggers using the
named log format cause strftime() to be called at most once per second.

Could you elaborate a little bit more on that part? If the time is
cached for one second, it makes little sense to use millisecond
precision. Or did I get something wrong? I suppose that in debug mode
I’d like strftime() value to be not cached at all, so that I get
millisecond-accurate times and I can measure request/response times to
backends etc. OTOH in production mode if I’m under heavy load (tons of
reqs/s) I may want to see millisecond-accurate times for some reason.
In that case maybe strftime() can be cached request-wise instead of
second-wise. But, if you log only one line per request, such caching
doesn’t bring any improvement. So maybe you could make caching
configurable via some other directive? And does
not-caching-strftime-value cause big performance impact anyway?

These are my thoughts. It’s a nice piece of work anyway!

Cheers,

Hi Wayne,

Off-topic, but would SF be willing to provide a small blurb that I can
add to the wiki propaganda? Something along the lines about how Nginx
single-handedly saved SF from destruction by an asteriod or perhaps a
falling piano would fit the bill nicely, but if you can’t provide that,
then some general info of how SF is utilizing Nginx and what benefit SF
derives from Nginx (vs some other web server/proxy) would be nice as
well.

You can see the front page of the wiki (http://wiki.nginx.org) for an
idea of what we’re looking for.

Regards,
Cliff

Hi,

Wayne Davison wrote:

Hi there. The company I work for, SourceForge, wanted the ability to
have a custom timestamp in a log file, so I created a patch for this. I
have been authorized to release it back to the nginx community.

What license are they releasing it under? BSD (like Nginx) or another
one?

Thanks,

Marcus.

On Mon, Aug 24, 2009 at 09:20:05PM +0200, Micha?? Jaszczyk wrote:

If the time is cached for one second, it makes little sense to use
millisecond precision.

The milliseconds are added after the conversion from a particular second
to an ASCII representation of that second is done. The caching just
avoids re-converting the same second into ASCII. The converting of
milliseconds into the log buffer is done once per request.

…wayne…

On Mon, Aug 24, 2009 at 11:02:49AM -0700, Wayne Davison wrote:

Here’s the patch:

http://opencoder.net/nginx-time_custom.patch

I updated a patch a little, and replaced the patch at the above link
with the new (complete) set of changes. To see what changed, see the
following two patches (which could be incrementally applied if you
grabbed the prior patch):

  1. I optimized away a once-a-second call to strchr() for those using
    the $ms expansion. (After the first time we find the ‘$’ in the
    expanded string, it should be in the same place each time after that.)

    http://opencoder.net/nginx-time_custom-strchr.patch

  2. I tweaked the variable lookup to use a new getlen pointer in the
    ngx_http_log_var_t structure. This lets me add the $time_custom var
    into the normal list of log vars, and remove the special-case var-
    finding code I had used for $time_custom.

    http://opencoder.net/nginx-time_custom-lookup.patch

…wayne…

On Tue, Aug 25, 2009 at 03:50:41AM +0300, Marcus C. wrote:

What license are they releasing it under? BSD (like Nginx) or another one?

The patch is released under BSD, in order to match nginx.

…wayne…