$request_time is 0.000 with gzip/chunked?

[Robert Coup]

Hi Anton,

Thanks for your efforts looking into this.

On Thu, Jan 30, 2014 at 11:09 PM, Anton Yuzhaninov <citrin at citrin.ru> wrote:

>
> 1. Do you have the timer_resolution directive in you config? Try to remove
> it for test.
>

No, just the default nginx.conf with changes as per my original email. If I
*add* "timer_resolution 100ms", ngx_time_update() gets called a lot when
the request isn't active, but I still get a 0.000 request time for gzip
requests, and it doesn't appear to be called between the start & end of the
request.


> 2. Try to run
> curl --limit-rate 100k
> to be sure, that request time >> 1 ms.
>

Adding --limit-rate does give me a non-zero request time, but it seems to
take quite a different code-path.

I added logging to ngx_time_update() and ngx_http_log_request_time() - the
elapsed time is definitely >0 if I call ngx_time_update() in the logger,
and for gzip requests ngx_time_update isn't called during request
processing, despite several

See https://gist.github.com/rcoup/8718307 for a series of debug logs and my
extra-logging patch. $request_time is at the end of the access log string
at the top of each log, search for "ngx_time_update" and
"ngx_http_log_request_time" to see when they're called.

192MB file / OS X / 1.5.9:
uncompressed: logged=0.207 wall=0.207 (uncompressed.log)
compressed: logged=0.000 wall=11.603 (compressed.log)
compressed with curl rate-limit: logged=18.316 wall=18.316
(compressed-ratelimit.log)
compressed with timer_resolution set: logged=0.000 wall=10.606
(compressed-timerres.log)

$ time gzip -1 -c /usr/local/nginx/html/big3.html > /dev/null
real 0m9.242s
user 0m9.097s
sys 0m0.098s

So it's definitely taking gzip >1ms to process.

HTH,

Rob :)
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx-devel/attachments/20140131/73186261/attachment.html>