openresty each new request takes +0.05 sec

roman.alexandr · 2016-02-11T13:04:03+00:00

Hello! On Thu, Feb 11, 2016 at 1:26 PM, MK wrote: > Wow! I didn't expect to hear from The Man Himself! This looks perfect & > sorry I didn't kno...

openresty each new request takes +0.05 sec

roman.alexandr

Hi there!

Have a weird trouble with my openresty. As i catch lua spent a little bit more time on each request. Approx +0.05 sec. After few days in production server able to process ~30 requests per second (2xCPU, 4GB RAM, openresty + redis + rabbitmq on the same box). GarbageCollector show 290KB constantly on each request. Did try to replace my lua script with simple

content_by_lua_block {
    ngx.log(ngx.ERR, os.clock())
    ngx.log(ngx.ERR, string.format("GC: %dKB", collectgarbage("count")))
    collectgarbage("restart")
} 

Result is the same but numbers much lower.

Any clues welcome.

nginx -V
nginx version: openresty/1.9.3.2
built by gcc 5.2.1 20151010 (Ubuntu 5.2.1-22ubuntu2) 
built with OpenSSL 1.0.2d 9 Jul 2015
TLS SNI support enabled
configure arguments: 
--prefix=/usr/local/openresty/nginx 
--with-cc-opt=-O2 
--add-module=../ngx_devel_kit-0.2.19 
--add-module=../echo-nginx-module-0.58 
--add-module=../xss-nginx-module-0.05 
--add-module=../ngx_coolkit-0.2rc3 
--add-module=../set-misc-nginx-module-0.29 
--add-module=../form-input-nginx-module-0.11 
--add-module=../encrypted-session-nginx-module-0.04 
--add-module=../ngx_postgres-1.0rc7 
--add-module=../srcache-nginx-module-0.30 
--add-module=../ngx_lua-0.9.19 
--add-module=../ngx_lua_upstream-0.04 
--add-module=../headers-more-nginx-module-0.28 
--add-module=../array-var-nginx-module-0.04 
--add-module=../memc-nginx-module-0.16 
--add-module=../redis2-nginx-module-0.12 
--add-module=../redis-nginx-module-0.3.7 
--add-module=../rds-json-nginx-module-0.14 
--add-module=../rds-csv-nginx-module-0.07 
--with-ld-opt=-Wl,-rpath,/usr/local/openresty/luajit/lib 
--sbin-path=/usr/sbin/nginx 
--conf-path=/etc/nginx/nginx.conf 
--error-log-path=/var/log/nginx/error.log 
--http-client-body-temp-path=/var/lib/nginx/body 
--http-fastcgi-temp-path=/var/lib/nginx/fastcgi 
--http-log-path=/var/log/nginx/access.log 
--http-proxy-temp-path=/var/lib/nginx/proxy 
--http-scgi-temp-path=/var/lib/nginx/scgi 
--http-uwsgi-temp-path=/var/lib/nginx/uwsgi 
--lock-path=/var/lock/nginx.lock 
--pid-path=/var/run/nginx.pid 
--with-http_dav_module 
--with-http_flv_module 
--with-http_geoip_module 
--with-http_gzip_static_module 
--with-http_realip_module 
--with-http_stub_status_module 
--with-http_ssl_module 
--with-http_sub_module 
--with-ipv6 
--with-sha1=/usr/include/openssl 
--with-md5=/usr/include/openssl 
--with-http_stub_status_module 
--with-http_secure_link_module 
--with-http_sub_module

nginx.conf:

user www-data;
worker_processes auto;
pid /run/nginx.pid;
worker_rlimit_nofile 100000;


events {
 worker_connections 4096;
# multi_accept on;
    use epoll;
}


http {


 ##
 # Basic Settings
 ##


 sendfile on;
 tcp_nopush on;
 tcp_nodelay on;
 keepalive_timeout 15;
 types_hash_max_size 2048;
    client_max_body_size 500M;
 # server_tokens off;
 # server_names_hash_bucket_size 64;
 # server_name_in_redirect off;


 include /etc/nginx/mime.types;
# default_type application/octet-stream;


    ##
    # Lua
    ##


#    init_by_lua_block { }


 
 ##
 # SSL Settings
 ##


 ssl_protocols TLSv1 TLSv1.1 TLSv1.2; # Dropping SSLv3, ref: POODLE
    ssl_session_cache shared:SSL:20m;
    ssl_session_timeout 180m;
 ssl_prefer_server_ciphers on;
    ssl_ciphers ECDH+AESGCM:ECDH+AES256:ECDH+AES128:DH+3DES:!ADH:!AECDH:!MD5;


 ##
 # Logging Settings
 ##


 #rewrite_log on;
    log_format custom '$remote_addr - $time_local - $status - $request - $request_body';
 access_log /var/log/nginx/access.log custom;
 error_log /var/log/nginx/error.log notice;


 ##
 # Gzip Settings
 ##


 gzip on;
 gzip_disable "msie6";


 # gzip_vary on;
 # gzip_proxied any;
 # gzip_comp_level 6;
 # gzip_buffers 16 8k;
 # gzip_http_version 1.1;
 # gzip_types text/plain text/css application/json application/_javascript_ text/xml application/xml application/xml+rss text/_javascript_;


 ##
 # Virtual Host Configs
 ##


 include /etc/nginx/vhosts/*;
}

P.S.: agentzh, thank you for your job. Really cool project, really cool documentation, really bright feature! Stay cool!!

agentzh

Hello!

On Wed, Feb 10, 2016 at 9:04 PM, Alexandr Roman wrote:
> Have a weird trouble with my openresty. As i catch lua spent a little bit
> more time on each request. Approx +0.05 sec. After few days in production
> server able to process ~30 requests per second (2xCPU, 4GB RAM, openresty +
> redis + rabbitmq on the same box).

Are you suggesting performance degration here? Is it CPU bound or IO
bound? How is your nginx workers' CPU usage?

It's better to sample some on-CPU and off-CPU flame graphs for your
nginx workers under load when something happens:

    https://openresty.org/#Profiling

> GarbageCollector show 290KB constantly on
> each request. Did try to replace my lua script with simple
>

Are you sure it's growing *forever* or just intermittent? I'm asking
this because most of the garbage collector does incur some delay in
collecting garbage. And you may want to tune the GC pace to fit your
use cases via the collectgarbage() (like tuning the setpause
parameter).

> content_by_lua_block {
>     ngx.log(ngx.ERR, os.clock())
>     ngx.log(ngx.ERR, string.format("GC: %dKB", collectgarbage("count")))
>     collectgarbage("restart")
> }
>

I've tested this example on my side with many requests (ab -n100000 -k
-c2 localhost:8080/t) and the error.log entries show the GC count is
always between the range 51K ~ 64K, no matter how many requests I keep
sending to the server.

BTW, restarting the GC upon every request is a bad idea. Also, using
os.clock() is also a bad idea since it may incur (expensive) system
calls.

It's wrong to just send a few test requests and check how the GC count
changes due to the inherent delay in collecting garbage with a mark
and sweep GC algorithm. You need some load to reason about memory
leaks.

>
> Result is the same but numbers much lower.
>
> Any clues welcome.
>
> nginx -V
> nginx version: openresty/1.9.3.2

You may also want to upgrade to the latest 1.9.7.3 formal release.

Best regards,
-agentzh

roman.alexandr

Thank you for reply!

Don't you see constantly increasing of running time when reproduce my issue? Cos' i don't really have troubles with memory, but with time shown by os.clock() and RPS.

Anyway, i gonna update openresty and try profile and will appear with new data if any.

Thanks once again.

On Thursday, February 11, 2016 at 4:00:50 PM UTC-5, agentzh wrote:

Hello!

On Wed, Feb 10, 2016 at 9:04 PM, Alexandr Roman wrote:
> Have a weird trouble with my openresty. As i catch lua spent a little bit
> more time on each request. Approx +0.05 sec. After few days in production
> server able to process ~30 requests per second (2xCPU, 4GB RAM, openresty +
> redis + rabbitmq on the same box).

Are you suggesting performance degration here? Is it CPU bound or IO
bound? How is your nginx workers' CPU usage?

It's better to sample some on-CPU and off-CPU flame graphs for your
nginx workers under load when something happens:

https://openresty.org/#Profiling

> GarbageCollector show 290KB constantly on
> each request. Did try to replace my lua script with simple
>

Are you sure it's growing *forever* or just intermittent? I'm asking
this because most of the garbage collector does incur some delay in
collecting garbage. And you may want to tune the GC pace to fit your
use cases via the collectgarbage() (like tuning the setpause
parameter).

> content_by_lua_block {
> ngx.log(ngx.ERR, os.clock())
> ngx.log(ngx.ERR, string.format("GC: %dKB", collectgarbage("count")))
> collectgarbage("restart")
> }
>

I've tested this example on my side with many requests (ab -n100000 -k
-c2 localhost:8080/t) and the error.log entries show the GC count is
always between the range 51K ~ 64K, no matter how many requests I keep
sending to the server.

BTW, restarting the GC upon every request is a bad idea. Also, using
os.clock() is also a bad idea since it may incur (expensive) system
calls.

It's wrong to just send a few test requests and check how the GC count
changes due to the inherent delay in collecting garbage with a mark
and sweep GC algorithm. You need some load to reason about memory
leaks.

>
> Result is the same but numbers much lower.
>
> Any clues welcome.
>
> nginx -V
> nginx version: openresty/1.9.3.2

You may also want to upgrade to the latest 1.9.7.3 formal release.

Best regards,
-agentzh

agentzh

Hello!

On Thu, Feb 11, 2016 at 1:16 PM, Alexandr Roman wrote:
> Thank you for reply!
>
> Don't you see constantly increasing of running time when reproduce my issue?
> Cos' i don't really have troubles with memory, but with time shown by
> os.clock() and RPS.
>
> Anyway, i gonna update openresty and try profile and will appear with new
> data if any.
>

The return value of the os.clock() always grows monotonically because
the CPU time of a process always grows monotonically. If you want
request processing time, you need to a difference instead of the
absolute value I'm afraid.

Also, BTW, for your test case, you're not benchmarking the processing
time of NGINX or Lua, you're benchmarking flushing data to your file
system without any buffering.

Regards,
-agentzh