$request_time variable = 0 for small files.

C
Clima
  • 7 Mar '24
Greetings,
I'm investigating a bug, super easy to reproduce.
Thought you might be curious.

Minimal Nginx config. Create two files. 100M and 1M:
dd if=/dev/zero of=/var/www/file100M bs=100M count=1
dd if=/dev/zero of=/var/www/file1M bs=1M count=1

Get them files:
curl --limit-rate 10M   -o /dev/null 127.0.0.42:80/file100M
curl --limit-rate 100k  -o /dev/null 127.0.0.42:80/file1M

Both transfers take ~10s, but Nginx logs 0s request_time for the small file.

master_process off;
daemon off;
error_log /dev/stderr;
events {}
http
{
log_format req_time  "$request_time";
    server
    {
            server_name 127.0.0.42;
            listen 127.0.0.42:80;
            root /var/www/;
            index index.html;
            location /
            {
            access_log /dev/stderr req_time;
            error_log /dev/stderr;
            }
    }
}
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx/attachments/20240307/b10cd96a/attachment.htm>
J
J
  • 7 Mar '24
Hello,

On Thu, 7 Mar 2024 08:17:23 +0200
Clima Gabriel <clima.gabrielphoto at gmail.com> wrote:

> Greetings,
> I'm investigating a bug, super easy to reproduce.
> Thought you might be curious.
> 
> Minimal Nginx config. Create two files. 100M and 1M:
> dd if=/dev/zero of=/var/www/file100M bs=100M count=1
> dd if=/dev/zero of=/var/www/file1M bs=1M count=1
> 
> Get them files:
> curl --limit-rate 10M   -o /dev/null 127.0.0.42:80/file100M
> curl --limit-rate 100k  -o /dev/null 127.0.0.42:80/file1M
> 
> Both transfers take ~10s, but Nginx logs 0s request_time for the small file.
> 

This isn't an issue with nginx. The response nginx sends
truly does take 0s to reach the client's socket.

Curl's limit-rate flag only applies at the application layer, but it has
no effect on curl's tcp socket, or it's buffers/how fast things are
read into the buffer. The entire response sent by nginx is being
received into into curl's tcp socket buffer instantly, which is
auto-scaled to a large window size because you are making these
requests from local machine.

You can temporarily set tcp read window to smallest possible minimum,
default, and maximum to confirm. Like this:

sysctl -w net.ipv4.tcp_rmem="4096 4096 4096"

or just view tcp traffic via wireshark.

> master_process off;
> daemon off;
> error_log /dev/stderr;
> events {}
> http
> {
> log_format req_time  "$request_time";
>     server
>     {
>             server_name 127.0.0.42;
>             listen 127.0.0.42:80;
>             root /var/www/;
>             index index.html;
>             location /
>             {
>             access_log /dev/stderr req_time;
>             error_log /dev/stderr;
>             }
>     }
> }
C
Clima
  • 7 Mar '24
0.000  sysctl -w net.ipv4.tcp_rmem="4096 4096 4096"
0.072  sysctl -w net.ipv4.tcp_rmem="512 512 512"
0.106  sysctl -w net.ipv4.tcp_rmem="256 256 256"

You're right.
This was invaluable, thank you!

On Thu, Mar 7, 2024 at 11:46 AM J Carter <jordanc.carter at outlook.com> wrote:

> Hello,
>
> On Thu, 7 Mar 2024 08:17:23 +0200
> Clima Gabriel <clima.gabrielphoto at gmail.com> wrote:
>
> > Greetings,
> > I'm investigating a bug, super easy to reproduce.
> > Thought you might be curious.
> >
> > Minimal Nginx config. Create two files. 100M and 1M:
> > dd if=/dev/zero of=/var/www/file100M bs=100M count=1
> > dd if=/dev/zero of=/var/www/file1M bs=1M count=1
> >
> > Get them files:
> > curl --limit-rate 10M   -o /dev/null 127.0.0.42:80/file100M
> > curl --limit-rate 100k  -o /dev/null 127.0.0.42:80/file1M
> >
> > Both transfers take ~10s, but Nginx logs 0s request_time for the small
> file.
> >
>
> This isn't an issue with nginx. The response nginx sends
> truly does take 0s to reach the client's socket.
>
> Curl's limit-rate flag only applies at the application layer, but it has
> no effect on curl's tcp socket, or it's buffers/how fast things are
> read into the buffer. The entire response sent by nginx is being
> received into into curl's tcp socket buffer instantly, which is
> auto-scaled to a large window size because you are making these
> requests from local machine.
>
> You can temporarily set tcp read window to smallest possible minimum,
> default, and maximum to confirm. Like this:
>
> sysctl -w net.ipv4.tcp_rmem="4096 4096 4096"
>
> or just view tcp traffic via wireshark.
>
> > master_process off;
> > daemon off;
> > error_log /dev/stderr;
> > events {}
> > http
> > {
> > log_format req_time  "$request_time";
> >     server
> >     {
> >             server_name 127.0.0.42;
> >             listen 127.0.0.42:80;
> >             root /var/www/;
> >             index index.html;
> >             location /
> >             {
> >             access_log /dev/stderr req_time;
> >             error_log /dev/stderr;
> >             }
> >     }
> > }
> _______________________________________________
> nginx mailing list
> nginx at nginx.org
> https://mailman.nginx.org/mailman/listinfo/nginx
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx/attachments/20240307/5605db8e/attachment.htm>
  • Page 1 of 1
Reply