proxy cache lock responses always has 500ms delay

[sivasara]

Greetings everbody,

I have the following config. I give 3 simulatneous requests and 1 goes back
to the upstream and the 2 of them are in proxy_cache_lock. After the first
request completes, I am always seeing 500ms delay with proxy_cache_locked
requests. Is this expected behavior or am i missing something. 
Any help would be appreciated.

-nginx config:
user  nginx;
worker_processes  1;
error_log  logs/error.log;
pid        /var/run/nginx.pid;
events {}
http {
    proxy_cache_path /tmp/local_cache keys_zone=local_cache:250m levels=1:2
inactive=8s;
    proxy_temp_path /tmp/proxy_temp;

    log_format  main  '$remote_addr - $remote_user [$time_local] "$request"
'
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for" '
                      '$upstream_addr $upstream_response_time $request_time
$upstream_cache_status';

    access_log  logs/access.log  main;
    server {
        listen       80;
        server_name  localhost;

        location / {
                proxy_cache local_cache;
                proxy_cache_valid 200 1m;
                proxy_cache_lock on;
                proxy_pass http://192.168.126.22:9095;
        }

    }
}

ab -n 4 -c 3 http://192.168.126.22/test
access.log:
192.168.126.22 - - [13/Sep/2017:15:14:36 +0530] "GET /test HTTP/1.0" 200 12
"-" "ApacheBench/2.3" "-" 192.168.126.22:9095 0.003 0.004 MISS
192.168.126.22 - - [13/Sep/2017:15:14:36 +0530] "GET /test HTTP/1.0" 200 12
"-" "ApacheBench/2.3" "-" - - 0.000 HIT
192.168.126.22 - - [13/Sep/2017:15:14:36 +0530] "GET /test HTTP/1.0" 200 12
"-" "ApacheBench/2.3" "-" - - 0.502 HIT
192.168.126.22 - - [13/Sep/2017:15:14:36 +0530] "GET /test HTTP/1.0" 200 12
"-" "ApacheBench/2.3" "-" - - 0.502 HIT

upstream:
curl http://192.168.126.22:9095/test
Hello world!

nginx:
nginx -V
nginx version: nginx/1.10.2
built by gcc 4.8.5 20150623 (Red Hat 4.8.5-4) (GCC)
built with OpenSSL 1.0.1e-fips 11 Feb 2013
TLS SNI support enabled
configure arguments: --prefix=/usr/share/nginx --sbin-path=/usr/sbin/nginx
--modules-path=/usr/lib64/nginx/modules --conf-path=/etc/nginx/nginx.conf
--error-log-path=/var/log/nginx/error.log
--http-log-path=/var/log/nginx/access.log
--http-client-body-temp-path=/var/lib/nginx/tmp/client_body
--http-proxy-temp-path=/var/lib/nginx/tmp/proxy
--http-fastcgi-temp-path=/var/lib/nginx/tmp/fastcgi
--http-uwsgi-temp-path=/var/lib/nginx/tmp/uwsgi
--http-scgi-temp-path=/var/lib/nginx/tmp/scgi --pid-path=/run/nginx.pid
--lock-path=/run/lock/subsys/nginx --user=nginx --group=nginx
--with-file-aio --with-ipv6 --with-http_ssl_module --with-http_v2_module
--with-http_realip_module --with-http_addition_module
--with-http_xslt_module=dynamic --with-http_image_filter_module=dynamic
--with-http_geoip_module=dynamic --with-http_sub_module
--with-http_dav_module --with-http_flv_module --with-http_mp4_module
--with-http_gunzip_module --with-http_gzip_static_module
--with-http_random_index_module --with-http_secure_link_module
--with-http_degradation_module --with-http_slice_module
--with-http_stub_status_module --with-http_perl_module=dynamic
--with-mail=dynamic --with-mail_ssl_module --with-pcre --with-pcre-jit
--with-stream=dynamic --with-stream_ssl_module
--with-google_perftools_module --with-debug --with-cc-opt='-O2 -g -pipe
-Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector-strong
--param=ssp-buffer-size=4 -grecord-gcc-switches
-specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -m64 -mtune=generic'
--with-ld-opt='-Wl,-z,relro -specs=/usr/lib/rpm/redhat/redhat-hardened-ld
-Wl,-E'

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,276344,276344#msg-276344