[openresty-en] Possible memory leak / slow GC?

rpaprocki · 2014-10-02T12:38:04+00:00

Hello! On Fri, Oct 3, 2014 at 2:48 PM, Matthieu Labour wrote: > Unless you guys think it does not make sense. > I think it makes sense. Patches welco...

[openresty-en] Possible memory leak / slow GC?

rpaprocki

Hello!

While writing some example code, I discovered that my openresty
installation seems to hang on to large tables in memory for some time.
Below is the code I was using to test:

location /search {
		content_by_lua '
			local linear = {}
			local hash = {}
			local match = 5000000
			local linear_start
			local linear_finish
			local hash_start
			local hash_finish

			for i = 1,match do
				linear[i] = i
				hash[i] = true
			end

			ngx.update_time()
			linear_start = ngx.now()

			-- linear search
			for i = 1,#hash do
				if (linear[i] == match) then
					ngx.update_time()
					linear_finish = ngx.now()
				end
			end

			ngx.update_time()
			local hash_start = ngx.now()

			-- hashmap search
			if (hash[match] == true) then
				ngx.update_time()
				hash_finish = ngx.now()
			end

			-- removed for debugging memory leak
			--ngx.say("Linear search took: " .. linear_finish - linear_start)
			--ngx.say("Hash search took: " .. hash_finish - hash_start)
		';
}


I would think that the large tables would be removed from memory,
however, according to ps, the nginx worker process maintains a large
amount of RSS mem:

root@fw01-west:~# /etc/init.d/nginx restart && ps aux | grep nginx |
grep worker && curl host.com/search && ps aux | grep nginx | grep worker
&& sleep 5 && ps aux | grep nginx | grep worker

freewaf  17070  1.8  0.9 157820  5032 ?        S    21:23   0:02 nginx:
worker process
freewaf  17070  2.0 26.7 289028 136188 ?       S    21:23   0:02 nginx:
worker process
freewaf  17070  1.9 26.7 289028 136188 ?       S    21:23   0:02 nginx:
worker process

Repeating multiple requests to this location will eventually result in a
core dump stemming from an OOM (this test VM has 512MB; I was able to
duplicate this results on an 8-core 32GB baremetal machine). I found
that after a decent amount of requests to either the same or other
server {}, garbage collection runs at the RSS reduces to normal levels;
however, I was not able to track down any differences in debug logs
after a specific request in which the RSS drops (I will continue to
search). I am running the latest stable openresty build with FRiCKLE's
cache purge module (I don't know that this would be the culprit, but I
am not sure):

root@fw01-west:~# /usr/local/openresty/nginx/sbin/nginx -V
nginx version: openresty/1.7.2.1
built by gcc 4.7.2 (Debian 4.7.2-5)
TLS SNI support enabled
configure arguments: --prefix=/usr/local/openresty/nginx --with-debug
--with-cc-opt='-DNGX_LUA_USE_ASSERT -DNGX_LUA_ABORT_AT_PANIC'
--add-module=../ngx_devel_kit-0.2.19
--add-module=../echo-nginx-module-0.54
--add-module=../xss-nginx-module-0.04 --add-module=../ngx_coolkit-0.2rc1
--add-module=../set-misc-nginx-module-0.24
--add-module=../form-input-nginx-module-0.09
--add-module=../encrypted-session-nginx-module-0.03
--add-module=../srcache-nginx-module-0.28 --add-module=../ngx_lua-0.9.10
--add-module=../ngx_lua_upstream-0.02
--add-module=../headers-more-nginx-module-0.25
--add-module=../array-var-nginx-module-0.03
--add-module=../memc-nginx-module-0.15
--add-module=../redis2-nginx-module-0.11
--add-module=../redis-nginx-module-0.3.7
--add-module=../rds-json-nginx-module-0.13
--add-module=../rds-csv-nginx-module-0.05
--with-ld-opt=-Wl,-rpath,/usr/local/openresty/luajit/lib
--with-http_realip_module
--add-module=/usr/local/src/ngx_openresty-1.7.2.1/bundle/ngx_cache_purge-2.1
--with-http_ssl_module

Any ideas of what to test further? Or what string to search for in the
debug log to see under what conditions the table memory is cleared? Full
relevant config show below:

worker_processes  1;
pid /var/run/freewaf.pid;
user freewaf freewaf;
error_log logs/error.log warn;
worker_rlimit_core  500M;
working_directory   /tmp;

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

http {
	sendfile on;
	tcp_nopush on;


	lua_shared_dict stats 64m;

	client_body_buffer_size 512k;
	client_max_body_size 2m;
	proxy_http_version 1.1;

	proxy_cache_path /fw/shm/cache levels=1:2 keys_zone=fw:48m inactive=60m;
	proxy_temp_path /fw/shm/proxy_tmp 1 2;

	set_real_ip_from x.x.x.168;
	real_ip_header X-Forwarded-For;

	more_clear_input_headers X-WAF-LB;

	#proxy_intercept_errors on;
	error_page 403 /403-error.html;
	error_page 500 /500-error.html;
	error_page 502 /502-error.html;
	error_page 503 /503-error.html;
	error_page 504 /504-error.html;

	include conf.d/*.conf;
}

server {
	server_name host.com www.host.com;
	access_log off;
	error_log logs/host.com.error.log debug;
	client_max_body_size 128m;
	listen 80;

	location ~ ((4|5)0(0|2|3|4)-error.html) {
		internal;
		allow all;
	}

	location ~ /purge/(.*) {
		allow              127.0.0.1;
       		deny all;
	        proxy_cache_purge  fw $proxy_host$1$is_args$args;
	}

	location / {
		proxy_pass http://upstream_2;
		proxy_cache fw;
        	proxy_cache_key $proxy_host$uri$is_args$args;

        	add_header X-Cache-Status $upstream_cache_status;
		add_header X-Cache-Key $proxy_host$uri$is_args$args;

		log_by_lua '
			local time = ngx.time()
	        	local stats = ngx.shared.stats

	       		local ok, err = stats:add(time, 1)
	    	    	if not ok then
        	    		stats:incr(time, 1)
        		end
    		';
	}

	location /stats {
		content_by_lua '
			local stats = ngx.shared.stats
			for _, key in ipairs(stats:get_keys()) do
				ngx.say(key .. ": " .. stats:get(key))
			end
		';
	}

	location /wp-admin {
		proxy_pass http://upstream_2;
	}

	default_type text/html;
	proxy_set_header Host $host;
	proxy_set_header X-Forwarded-For $remote_addr;

}

upstream upstream_2 {
	#round robin;
	server x.x.x.47 weight=1 max_fails=1 fail_timeout=10;
}

And below is the debug log from 2 requests when the RSS mysteriously
cleared down to 5M from 133M. Note that the following extra messages
appeared for *45 and not *46, at the end of the event; perhaps this is
related to when GC runs?:

2014/10/01 21:28:53 [debug] 17525#0: *45 recv: fd:27 -1 of 1024
2014/10/01 21:28:53 [debug] 17525#0: *45 recv() not ready (11: Resource
temporarily unavailable)
2014/10/01 21:28:53 [debug] 17525#0: *45 free: 0000000000EEBEA0
2014/10/01 21:28:53 [debug] 17525#0: *45 http empty handler
2014/10/01 21:28:53 [debug] 17525#0: *45 http keepalive handler
2014/10/01 21:28:53 [debug] 17525#0: *45 malloc: 0000000000EEBEA0:1024


Full debug logs:

2014/10/01 21:28:53 [debug] 17525#0: *45 http header: "Host:
cryptobells.com"
2014/10/01 21:28:53 [debug] 17525#0: *45 http header: "Accept: */*"
2014/10/01 21:28:53 [debug] 17525#0: *45 http header: "X-WAF-LB: lb01-west"
2014/10/01 21:28:53 [debug] 17525#0: *45 http header: "X-Forwarded-For:
104.131.135.222"
2014/10/01 21:28:53 [debug] 17525#0: *45 http header done
2014/10/01 21:28:53 [debug] 17525#0: *45 event timer del: 27: 1412224193039
2014/10/01 21:28:53 [debug] 17525#0: *45 generic phase: 0
2014/10/01 21:28:53 [debug] 17525#0: *45 posix_memalign:
0000000000EDDAE0:4096 @16
2014/10/01 21:28:53 [debug] 17525#0: *45 add cleanup: 0000000000EDDB10
2014/10/01 21:28:53 [debug] 17525#0: *45 rewrite phase: 1
2014/10/01 21:28:53 [debug] 17525#0: *45 rewrite phase: 2
2014/10/01 21:28:53 [debug] 17525#0: *45 test location: "/"
2014/10/01 21:28:53 [debug] 17525#0: *45 test location: ~
"((4|5)0(0|2|3|4)-error.html)"
2014/10/01 21:28:53 [debug] 17525#0: *45 test location: ~ "/purge/(.*)"
2014/10/01 21:28:53 [debug] 17525#0: *45 using configuration "/"
2014/10/01 21:28:53 [debug] 17525#0: *45 http cl:-1 max:134217728
2014/10/01 21:28:53 [debug] 17525#0: *45 rewrite phase: 4
2014/10/01 21:28:53 [debug] 17525#0: *45 rewrite phase: 5
2014/10/01 21:28:53 [debug] 17525#0: *45 rewrite phase: 6
2014/10/01 21:28:53 [debug] 17525#0: *45 headers more rewrite handler,
uri "/"
2014/10/01 21:28:53 [debug] 17525#0: *45 post rewrite phase: 7
2014/10/01 21:28:53 [debug] 17525#0: *45 generic phase: 8
2014/10/01 21:28:53 [debug] 17525#0: *45 generic phase: 9
2014/10/01 21:28:53 [debug] 17525#0: *45 generic phase: 10
2014/10/01 21:28:53 [debug] 17525#0: *45 access phase: 11
2014/10/01 21:28:53 [debug] 17525#0: *45 access: DE878368 FFFFFFFF 2F878368
2014/10/01 21:28:53 [debug] 17525#0: *45 access: DE878368 FFFFFFFF D3F2CCC6
2014/10/01 21:28:53 [debug] 17525#0: *45 access: DE878368 FFFFFFFF 99E88FBC
2014/10/01 21:28:53 [debug] 17525#0: *45 access: DE878368 FFFFFFFF 9C9BD3C3
2014/10/01 21:28:53 [debug] 17525#0: *45 access: DE878368 FFFFFFFF 04E7E65B
2014/10/01 21:28:53 [debug] 17525#0: *45 access phase: 12
2014/10/01 21:28:53 [debug] 17525#0: *45 access phase: 13
2014/10/01 21:28:53 [debug] 17525#0: *45 lua access handler, uri:"/" c:1
2014/10/01 21:28:53 [debug] 17525#0: *45 post access phase: 14
2014/10/01 21:28:53 [debug] 17525#0: *45 http init upstream, client timer: 0
2014/10/01 21:28:53 [debug] 17525#0: *45 epoll add event: fd:27 op:3
ev:80002005
2014/10/01 21:28:53 [debug] 17525#0: *45 http script var: "upstream_2"
2014/10/01 21:28:53 [debug] 17525#0: *45 http script var: "/"
2014/10/01 21:28:53 [debug] 17525#0: *45 http script var: ""
2014/10/01 21:28:53 [debug] 17525#0: *45 http cache key: "upstream_2/"
2014/10/01 21:28:53 [debug] 17525#0: *45 add cleanup: 0000000000EDE3A0
2014/10/01 21:28:53 [debug] 17525#0: *45 http file cache exists: 0 e:1
2014/10/01 21:28:53 [debug] 17525#0: *45 cache file:
"/fw/shm/cache/f/0e/7c41b14e1103e18fac21de70c2d220ef"
2014/10/01 21:28:53 [debug] 17525#0: *45 add cleanup: 0000000000EDE3F0
2014/10/01 21:28:53 [debug] 17525#0: *45 http file cache fd: 28
2014/10/01 21:28:53 [debug] 17525#0: *45 malloc: 0000000000F47AB0:4096
2014/10/01 21:28:53 [debug] 17525#0: *45 read: 28, 0000000000F47AB0, 4096, 0
2014/10/01 21:28:53 [debug] 17525#0: *45 http upstream cache: 0
2014/10/01 21:28:53 [debug] 17525#0: *45 http proxy status 301 "301
Moved Permanently"
2014/10/01 21:28:53 [debug] 17525#0: *45 http proxy header: "Server:
nginx/1.7.5"
2014/10/01 21:28:53 [debug] 17525#0: *45 http proxy header: "Date: Wed,
01 Oct 2014 19:38:58 GMT"
2014/10/01 21:28:53 [debug] 17525#0: *45 http proxy header:
"Content-Type: text/html; charset="
2014/10/01 21:28:53 [debug] 17525#0: *45 http proxy header:
"Transfer-Encoding: chunked"
2014/10/01 21:28:53 [debug] 17525#0: *45 http proxy header: "Connection:
close"
2014/10/01 21:28:53 [debug] 17525#0: *45 http proxy header: "X-Pingback:
http://www.cryptobells.com/xmlrpc.php";
2014/10/01 21:28:53 [debug] 17525#0: *45 http proxy header: "Location:
http://www.cryptobells.com/";
2014/10/01 21:28:53 [debug] 17525#0: *45 http proxy header: "Expires:
Thu, 02 Oct 2014 19:38:58 GMT"
2014/10/01 21:28:53 [debug] 17525#0: *45 http proxy header:
"Cache-Control: max-age=86400"
2014/10/01 21:28:53 [debug] 17525#0: *45 http proxy header done
2014/10/01 21:28:53 [debug] 17525#0: *45 http file cache send:
/fw/shm/cache/f/0e/7c41b14e1103e18fac21de70c2d220ef
2014/10/01 21:28:53 [debug] 17525#0: *45 lua capture header filter, uri "/"
2014/10/01 21:28:53 [debug] 17525#0: *45 http script var: "HIT"
2014/10/01 21:28:53 [debug] 17525#0: *45 http script var: "upstream_2"
2014/10/01 21:28:53 [debug] 17525#0: *45 http script var: "/"
2014/10/01 21:28:53 [debug] 17525#0: *45 http script var: ""
2014/10/01 21:28:53 [debug] 17525#0: *45 posix_memalign:
0000000000F48AC0:4096 @16
2014/10/01 21:28:53 [debug] 17525#0: *45 HTTP/1.1 301 Moved Permanently
Server: openresty/1.7.2.1
Date: Thu, 02 Oct 2014 04:28:53 GMT
Content-Type: text/html; charset=
Transfer-Encoding: chunked
Connection: keep-alive
X-Pingback: http://www.host.com/xmlrpc.php
Location: http://www.host.com/
Expires: Thu, 02 Oct 2014 19:38:58 GMT
Cache-Control: max-age=86400
X-Cache-Status: HIT
X-Cache-Key: upstream_2/

2014/10/01 21:28:53 [debug] 17525#0: *45 write new buf t:1 f:0
0000000000F48AE0, pos 0000000000F48AE0, size: 390 file: 0, size: 0
2014/10/01 21:28:53 [debug] 17525#0: *45 http write filter: l:0 f:0 s:390
2014/10/01 21:28:53 [debug] 17525#0: *45 http output filter "/?"
2014/10/01 21:28:53 [debug] 17525#0: *45 http copy filter: "/?"
2014/10/01 21:28:53 [debug] 17525#0: *45 lua capture body filter, uri "/"
2014/10/01 21:28:53 [debug] 17525#0: *45 http postpone filter "/?"
00007FFFBB7BF130
2014/10/01 21:28:53 [debug] 17525#0: *45 http chunk: 0
2014/10/01 21:28:53 [debug] 17525#0: *45 write old buf t:1 f:0
0000000000F48AE0, pos 0000000000F48AE0, size: 390 file: 0, size: 0
2014/10/01 21:28:53 [debug] 17525#0: *45 write new buf t:0 f:0
0000000000000000, pos 00000000004F037A, size: 5 file: 0, size: 0
2014/10/01 21:28:53 [debug] 17525#0: *45 http write filter: l:1 f:0 s:395
2014/10/01 21:28:53 [debug] 17525#0: *45 http write filter limit 0
2014/10/01 21:28:53 [debug] 17525#0: *45 writev: 395
2014/10/01 21:28:53 [debug] 17525#0: *45 http write filter 0000000000000000
2014/10/01 21:28:53 [debug] 17525#0: *45 http copy filter: 0 "/?"
2014/10/01 21:28:53 [debug] 17525#0: *45 http finalize request: 0, "/?"
a:1, c:2
2014/10/01 21:28:53 [debug] 17525#0: *45 http request count:2 blk:0
2014/10/01 21:28:53 [debug] 17525#0: *45 http finalize request: -4, "/?"
a:1, c:1
2014/10/01 21:28:53 [debug] 17525#0: *45 set http keepalive handler
2014/10/01 21:28:53 [debug] 17525#0: *45 http close request
2014/10/01 21:28:53 [debug] 17525#0: *45 lua log handler, uri:"/" c:1
2014/10/01 21:28:53 [debug] 17525#0: *45 http log handler
2014/10/01 21:28:53 [debug] 17525#0: *45 run cleanup: 0000000000EDE3F0
2014/10/01 21:28:53 [debug] 17525#0: *45 file cleanup: fd:28
2014/10/01 21:28:53 [debug] 17525#0: *45 run cleanup: 0000000000EDE3A0
2014/10/01 21:28:53 [debug] 17525#0: *45 http file cache cleanup
2014/10/01 21:28:53 [debug] 17525#0: *45 http file cache free, fd: 28
2014/10/01 21:28:53 [debug] 17525#0: *45 run cleanup: 0000000000EDDB10
2014/10/01 21:28:53 [debug] 17525#0: *45 free: 0000000000F47AB0
2014/10/01 21:28:53 [debug] 17525#0: *45 free: 0000000000EF21C0, unused: 5
2014/10/01 21:28:53 [debug] 17525#0: *45 free: 0000000000EDDAE0, unused: 0
2014/10/01 21:28:53 [debug] 17525#0: *45 free: 0000000000F48AC0, unused:
3048
2014/10/01 21:28:53 [debug] 17525#0: *45 free: 0000000000EEBEA0
2014/10/01 21:28:53 [debug] 17525#0: *45 hc free: 0000000000000000 0
2014/10/01 21:28:53 [debug] 17525#0: *45 hc busy: 0000000000000000 0
2014/10/01 21:28:53 [debug] 17525#0: *45 tcp_nodelay
2014/10/01 21:28:53 [debug] 17525#0: *45 reusable connection: 1
2014/10/01 21:28:53 [debug] 17525#0: *45 event timer add: 27:
75000:1412224208039
2014/10/01 21:28:53 [debug] 17525#0: *45 post event 0000000000F95C58
2014/10/01 21:28:53 [debug] 17525#0: *45 delete posted event
0000000000F95C58
2014/10/01 21:28:53 [debug] 17525#0: *45 http keepalive handler
2014/10/01 21:28:53 [debug] 17525#0: *45 malloc: 0000000000EEBEA0:1024
2014/10/01 21:28:53 [debug] 17525#0: *45 recv: fd:27 -1 of 1024
2014/10/01 21:28:53 [debug] 17525#0: *45 recv() not ready (11: Resource
temporarily unavailable)
2014/10/01 21:28:53 [debug] 17525#0: *45 free: 0000000000EEBEA0
2014/10/01 21:28:53 [debug] 17525#0: *45 http empty handler
2014/10/01 21:28:53 [debug] 17525#0: *45 http keepalive handler
2014/10/01 21:28:53 [debug] 17525#0: *45 malloc: 0000000000EEBEA0:1024
2014/10/01 21:28:53 [debug] 17525#0: *45 recv: fd:27 -1 of 1024
2014/10/01 21:28:53 [info] 17525#0: *45 client 192.241.210.168 closed
keepalive connection (104: Connection reset by peer)
2014/10/01 21:28:53 [debug] 17525#0: *45 close http connection: 27
2014/10/01 21:28:53 [debug] 17525#0: *45 event timer del: 27: 1412224208039
2014/10/01 21:28:53 [debug] 17525#0: *45 reusable connection: 0
2014/10/01 21:28:53 [debug] 17525#0: *45 free: 0000000000EEBEA0
2014/10/01 21:28:53 [debug] 17525#0: *45 free: 0000000000EEBC80, unused: 0
2014/10/01 21:28:53 [debug] 17525#0: *45 free: 0000000000EEBD90, unused: 89
2014/10/01 21:28:53 [debug] 17525#0: *46 http header: "Host:
cryptobells.com"
2014/10/01 21:28:53 [debug] 17525#0: *46 http header: "Accept: */*"
2014/10/01 21:28:53 [debug] 17525#0: *46 http header: "X-WAF-LB: lb01-west"
2014/10/01 21:28:53 [debug] 17525#0: *46 http header: "X-Forwarded-For:
104.131.135.222"
2014/10/01 21:28:53 [debug] 17525#0: *46 http header done
2014/10/01 21:28:53 [debug] 17525#0: *46 event timer del: 27: 1412224193844
2014/10/01 21:28:53 [debug] 17525#0: *46 generic phase: 0
2014/10/01 21:28:53 [debug] 17525#0: *46 posix_memalign:
0000000000EDDAE0:4096 @16
2014/10/01 21:28:53 [debug] 17525#0: *46 add cleanup: 0000000000EDDB10
2014/10/01 21:28:53 [debug] 17525#0: *46 rewrite phase: 1
2014/10/01 21:28:53 [debug] 17525#0: *46 rewrite phase: 2
2014/10/01 21:28:53 [debug] 17525#0: *46 test location: "/"
2014/10/01 21:28:53 [debug] 17525#0: *46 test location: ~
"((4|5)0(0|2|3|4)-error.html)"
2014/10/01 21:28:53 [debug] 17525#0: *46 test location: ~ "/purge/(.*)"
2014/10/01 21:28:53 [debug] 17525#0: *46 using configuration "/"
2014/10/01 21:28:53 [debug] 17525#0: *46 http cl:-1 max:134217728
2014/10/01 21:28:53 [debug] 17525#0: *46 rewrite phase: 4
2014/10/01 21:28:53 [debug] 17525#0: *46 rewrite phase: 5
2014/10/01 21:28:53 [debug] 17525#0: *46 rewrite phase: 6
2014/10/01 21:28:53 [debug] 17525#0: *46 headers more rewrite handler,
uri "/"
2014/10/01 21:28:53 [debug] 17525#0: *46 post rewrite phase: 7
2014/10/01 21:28:53 [debug] 17525#0: *46 generic phase: 8
2014/10/01 21:28:53 [debug] 17525#0: *46 generic phase: 9
2014/10/01 21:28:53 [debug] 17525#0: *46 generic phase: 10
2014/10/01 21:28:53 [debug] 17525#0: *46 access phase: 11
2014/10/01 21:28:53 [debug] 17525#0: *46 access: DE878368 FFFFFFFF 2F878368
2014/10/01 21:28:53 [debug] 17525#0: *46 access: DE878368 FFFFFFFF D3F2CCC6
2014/10/01 21:28:53 [debug] 17525#0: *46 access: DE878368 FFFFFFFF 99E88FBC
2014/10/01 21:28:53 [debug] 17525#0: *46 access: DE878368 FFFFFFFF 9C9BD3C3
2014/10/01 21:28:53 [debug] 17525#0: *46 access: DE878368 FFFFFFFF 04E7E65B
2014/10/01 21:28:53 [debug] 17525#0: *46 access phase: 12
2014/10/01 21:28:53 [debug] 17525#0: *46 access phase: 13
2014/10/01 21:28:53 [debug] 17525#0: *46 lua access handler, uri:"/" c:1
2014/10/01 21:28:53 [debug] 17525#0: *46 post access phase: 14
2014/10/01 21:28:53 [debug] 17525#0: *46 http init upstream, client timer: 0
2014/10/01 21:28:53 [debug] 17525#0: *46 epoll add event: fd:27 op:3
ev:80002005
2014/10/01 21:28:53 [debug] 17525#0: *46 http script var: "upstream_2"
2014/10/01 21:28:53 [debug] 17525#0: *46 http script var: "/"
2014/10/01 21:28:53 [debug] 17525#0: *46 http script var: ""
2014/10/01 21:28:53 [debug] 17525#0: *46 http cache key: "upstream_2/"
2014/10/01 21:28:53 [debug] 17525#0: *46 add cleanup: 0000000000EDE3A0
2014/10/01 21:28:53 [debug] 17525#0: *46 http file cache exists: 0 e:1
2014/10/01 21:28:53 [debug] 17525#0: *46 cache file:
"/fw/shm/cache/f/0e/7c41b14e1103e18fac21de70c2d220ef"
2014/10/01 21:28:53 [debug] 17525#0: *46 add cleanup: 0000000000EDE3F0
2014/10/01 21:28:53 [debug] 17525#0: *46 http file cache fd: 28
2014/10/01 21:28:53 [debug] 17525#0: *46 malloc: 0000000000F47AB0:4096
2014/10/01 21:28:53 [debug] 17525#0: *46 read: 28, 0000000000F47AB0, 4096, 0
2014/10/01 21:28:53 [debug] 17525#0: *46 http upstream cache: 0
2014/10/01 21:28:53 [debug] 17525#0: *46 http proxy status 301 "301
Moved Permanently"
2014/10/01 21:28:53 [debug] 17525#0: *46 http proxy header: "Server:
nginx/1.7.5"
2014/10/01 21:28:53 [debug] 17525#0: *46 http proxy header: "Date: Wed,
01 Oct 2014 19:38:58 GMT"
2014/10/01 21:28:53 [debug] 17525#0: *46 http proxy header:
"Content-Type: text/html; charset="
2014/10/01 21:28:53 [debug] 17525#0: *46 http proxy header:
"Transfer-Encoding: chunked"
2014/10/01 21:28:53 [debug] 17525#0: *46 http proxy header: "Connection:
close"
2014/10/01 21:28:53 [debug] 17525#0: *46 http proxy header: "X-Pingback:
http://www.cryptobells.com/xmlrpc.php";
2014/10/01 21:28:53 [debug] 17525#0: *46 http proxy header: "Location:
http://www.cryptobells.com/";
2014/10/01 21:28:53 [debug] 17525#0: *46 http proxy header: "Expires:
Thu, 02 Oct 2014 19:38:58 GMT"
2014/10/01 21:28:53 [debug] 17525#0: *46 http proxy header:
"Cache-Control: max-age=86400"
2014/10/01 21:28:53 [debug] 17525#0: *46 http proxy header done
2014/10/01 21:28:53 [debug] 17525#0: *46 http file cache send:
/fw/shm/cache/f/0e/7c41b14e1103e18fac21de70c2d220ef
2014/10/01 21:28:53 [debug] 17525#0: *46 lua capture header filter, uri "/"
2014/10/01 21:28:53 [debug] 17525#0: *46 http script var: "HIT"
2014/10/01 21:28:53 [debug] 17525#0: *46 http script var: "upstream_2"
2014/10/01 21:28:53 [debug] 17525#0: *46 http script var: "/"
2014/10/01 21:28:53 [debug] 17525#0: *46 http script var: ""
2014/10/01 21:28:53 [debug] 17525#0: *46 posix_memalign:
0000000000F48AC0:4096 @16
2014/10/01 21:28:53 [debug] 17525#0: *46 HTTP/1.1 301 Moved Permanently
Server: openresty/1.7.2.1
Date: Thu, 02 Oct 2014 04:28:53 GMT
Content-Type: text/html; charset=
Transfer-Encoding: chunked
Connection: keep-alive
X-Pingback: http://www.host.com/xmlrpc.php
Location: http://www.host.com/
Expires: Thu, 02 Oct 2014 19:38:58 GMT
Cache-Control: max-age=86400
X-Cache-Status: HIT
X-Cache-Key: upstream_2/

2014/10/01 21:28:53 [debug] 17525#0: *46 write new buf t:1 f:0
0000000000F48AE0, pos 0000000000F48AE0, size: 390 file: 0, size: 0
2014/10/01 21:28:53 [debug] 17525#0: *46 http write filter: l:0 f:0 s:390
2014/10/01 21:28:53 [debug] 17525#0: *46 http output filter "/?"
2014/10/01 21:28:53 [debug] 17525#0: *46 http copy filter: "/?"
2014/10/01 21:28:53 [debug] 17525#0: *46 lua capture body filter, uri "/"
2014/10/01 21:28:53 [debug] 17525#0: *46 http postpone filter "/?"
00007FFFBB7BF130
2014/10/01 21:28:53 [debug] 17525#0: *46 http chunk: 0
2014/10/01 21:28:53 [debug] 17525#0: *46 write old buf t:1 f:0
0000000000F48AE0, pos 0000000000F48AE0, size: 390 file: 0, size: 0
2014/10/01 21:28:53 [debug] 17525#0: *46 write new buf t:0 f:0
0000000000000000, pos 00000000004F037A, size: 5 file: 0, size: 0
2014/10/01 21:28:53 [debug] 17525#0: *46 http write filter: l:1 f:0 s:395
2014/10/01 21:28:53 [debug] 17525#0: *46 http write filter limit 0
2014/10/01 21:28:53 [debug] 17525#0: *46 writev: 395
2014/10/01 21:28:53 [debug] 17525#0: *46 http write filter 0000000000000000
2014/10/01 21:28:53 [debug] 17525#0: *46 http copy filter: 0 "/?"
2014/10/01 21:28:53 [debug] 17525#0: *46 http finalize request: 0, "/?"
a:1, c:2
2014/10/01 21:28:53 [debug] 17525#0: *46 http request count:2 blk:0
2014/10/01 21:28:53 [debug] 17525#0: *46 http finalize request: -4, "/?"
a:1, c:1
2014/10/01 21:28:53 [debug] 17525#0: *46 set http keepalive handler
2014/10/01 21:28:53 [debug] 17525#0: *46 http close request
2014/10/01 21:28:53 [debug] 17525#0: *46 lua log handler, uri:"/" c:1
2014/10/01 21:28:53 [debug] 17525#0: *46 http log handler
2014/10/01 21:28:53 [debug] 17525#0: *46 run cleanup: 0000000000EDE3F0
2014/10/01 21:28:53 [debug] 17525#0: *46 file cleanup: fd:28
2014/10/01 21:28:53 [debug] 17525#0: *46 run cleanup: 0000000000EDE3A0
2014/10/01 21:28:53 [debug] 17525#0: *46 http file cache cleanup
2014/10/01 21:28:53 [debug] 17525#0: *46 http file cache free, fd: 28
2014/10/01 21:28:53 [debug] 17525#0: *46 run cleanup: 0000000000EDDB10
2014/10/01 21:28:53 [debug] 17525#0: *46 free: 0000000000F47AB0
2014/10/01 21:28:53 [debug] 17525#0: *46 free: 0000000000EF21C0, unused: 5
2014/10/01 21:28:53 [debug] 17525#0: *46 free: 0000000000EDDAE0, unused: 0
2014/10/01 21:28:53 [debug] 17525#0: *46 free: 0000000000F48AC0, unused:
3048
2014/10/01 21:28:53 [debug] 17525#0: *46 free: 0000000000EEBEA0
2014/10/01 21:28:53 [debug] 17525#0: *46 hc free: 0000000000000000 0
2014/10/01 21:28:53 [debug] 17525#0: *46 hc busy: 0000000000000000 0
2014/10/01 21:28:53 [debug] 17525#0: *46 tcp_nodelay
2014/10/01 21:28:53 [debug] 17525#0: *46 reusable connection: 1
2014/10/01 21:28:53 [debug] 17525#0: *46 event timer add: 27:
75000:1412224208844
2014/10/01 21:28:53 [debug] 17525#0: *46 post event 0000000000F95C58
2014/10/01 21:28:53 [debug] 17525#0: *46 delete posted event
0000000000F95C58
2014/10/01 21:28:53 [debug] 17525#0: *46 http keepalive handler
2014/10/01 21:28:53 [debug] 17525#0: *46 malloc: 0000000000EEBEA0:1024
2014/10/01 21:28:53 [debug] 17525#0: *46 recv: fd:27 -1 of 1024
2014/10/01 21:28:53 [info] 17525#0: *46 client 192.241.210.168 closed
keepalive connection (104: Connection reset by peer)
2014/10/01 21:28:53 [debug] 17525#0: *46 close http connection: 27
2014/10/01 21:28:53 [debug] 17525#0: *46 event timer del: 27: 1412224208844
2014/10/01 21:28:53 [debug] 17525#0: *46 reusable connection: 0
2014/10/01 21:28:53 [debug] 17525#0: *46 free: 0000000000EEBEA0
2014/10/01 21:28:53 [debug] 17525#0: *46 free: 0000000000EEBC80, unused: 0
2014/10/01 21:28:53 [debug] 17525#0: *46 free: 0000000000EEBD90, unused: 89

agentzh

Hello!

On Wed, Oct 1, 2014 at 9:38 PM, Robert Paprocki wrote:
> While writing some example code, I discovered that my openresty
> installation seems to hang on to large tables in memory for some time.
> Below is the code I was using to test:
>

I suggest you recycle your big Lua tables across requests via
table.clear(). Also, using the table.new() primitive to pre-allocate
your big Lua tables for the first time can also save the overhead in
table auto growing.

To make your table(s) persistent across requests, you can make use of
your own Lua module's data. See

    https://github.com/openresty/lua-nginx-module#data-sharing-within-an-nginx-worker

Avoid putting big pressure on LuaJIT's GC, which is not really strong :)

Regards,
-agentzh