<div dir="ltr">Hi Anton,<div class="gmail_extra"><br></div><div class="gmail_extra">Thanks for your efforts looking into this.</div><div class="gmail_extra"><br><div class="gmail_quote">On Thu, Jan 30, 2014 at 11:09 PM, Anton Yuzhaninov <span dir="ltr"><<a href="mailto:citrin@citrin.ru" target="_blank">citrin@citrin.ru</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex"><div class="im"><br></div>
1. Do you have the timer_resolution directive in you config? Try to remove it for test.<br></blockquote><div><br></div><div>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.</div>
<div><br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
<br>
2. Try to run<br>
curl --limit-rate 100k<br>
to be sure, that request time >> 1 ms.<br></blockquote><div><br></div><div>Adding --limit-rate does give me a non-zero request time, but it seems to take quite a different code-path. </div><div><br></div><div>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 </div>
<div><br></div><div>See <a href="https://gist.github.com/rcoup/8718307">https://gist.github.com/rcoup/8718307</a> 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.</div>
<div><br></div><div>192MB file / OS X / 1.5.9:</div><div>uncompressed: logged=0.207 wall=0.207 (uncompressed.log)</div><div>compressed: logged=0.000 wall=11.603 (compressed.log)</div><div>compressed with curl rate-limit: logged=18.316 wall=18.316 (compressed-ratelimit.log)<br>
</div><div><div>compressed with timer_resolution set: logged=0.000 wall=10.606 (compressed-timerres.log)</div></div><div><br></div><div><div>$ time gzip -1 -c /usr/local/nginx/html/big3.html > /dev/null<br></div><div><div>
real<span class="" style="white-space:pre">   </span>0m9.242s</div><div>user<span class="" style="white-space:pre">       </span>0m9.097s</div><div>sys<span class="" style="white-space:pre">        </span>0m0.098s</div></div></div><div>
<br></div><div>So it's definitely taking gzip >1ms to process. </div><div><br></div><div>HTH,<br></div><div><br></div><div>Rob :)</div></div></div></div>