Too many unused threads created to serve custom plugin request in embedded plugin server
abhisheksharma2805 opened this issue · 2 comments
PID PPID USER STAT VSZ %VSZ CPU %CPU COMMAND
32 1 kong S 454m 3% 0 0% nginx: worker process
31 1 kong S 406m 3% 1 0% nginx: worker process
33 1 kong S 403m 3% 2 0% nginx: worker process
34 1 kong S 403m 3% 1 0% nginx: worker process
1 0 kong S 365m 2% 0 0% nginx: master process /usr/local/openresty/nginx/sbin/nginx -p /usr/local/kong -c nginx.conf
35 31 kong S 53296 0% 3 0% {kong-python-plu} /usr/local/bin/python3.6 /usr/local/bin/kong-python-pluginserver -d /usr/local/kong/python-plugins
353 31 kong S 53296 0% 0 0% {kong-python-plu} /usr/local/bin/python3.6 /usr/local/bin/kong-python-pluginserver -d /usr/local/kong/python-plugins
42 31 kong S 53296 0% 2 0% {kong-python-plu} /usr/local/bin/python3.6 /usr/local/bin/kong-python-pluginserver -d /usr/local/kong/python-plugins
81 31 kong S 53296 0% 0 0% {kong-python-plu} /usr/local/bin/python3.6 /usr/local/bin/kong-python-pluginserver -d /usr/local/kong/python-plugins
166 31 kong S 53296 0% 3 0% {kong-python-plu} /usr/local/bin/python3.6 /usr/local/bin/kong-python-pluginserver -d /usr/local/kong/python-plugins
182 31 kong S 53296 0% 1 0% {kong-python-plu} /usr/local/bin/python3.6 /usr/local/bin/kong-python-pluginserver -d /usr/local/kong/python-plugins
191 31 kong S 53296 0% 0 0% {kong-python-plu} /usr/local/bin/python3.6 /usr/local/bin/kong-python-pluginserver -d /usr/local/kong/python-plugins
320 31 kong S 53296 0% 2 0% {kong-python-plu} /usr/local/bin/python3.6 /usr/local/bin/kong-python-pluginserver -d /usr/local/kong/python-plugins
335 31 kong S 53296 0% 0 0% {kong-python-plu} /usr/local/bin/python3.6 /usr/local/bin/kong-python-pluginserver -d /usr/local/kong/python-plugins
137 31 kong S 53296 0% 0 0% {kong-python-plu} /usr/local/bin/python3.6 /usr/local/bin/kong-python-pluginserver -d /usr/local/kong/python-plugins
369 31 kong S 53296 0% 1 0% {kong-python-plu} /usr/local/bin/python3.6 /usr/local/bin/kong-python-pluginserver -d /usr/local/kong/python-plugins
373 31 kong S 53296 0% 1 0% {kong-python-plu} /usr/local/bin/python3.6 /usr/local/bin/kong-python-pluginserver -d /usr/local/kong/python-plugins
470 31 kong S 53296 0% 1 0% {kong-python-plu} /usr/local/bin/python3.6 /usr/local/bin/kong-python-pluginserver -d /usr/local/kong/python-plugins
471 31 kong S 53296 0% 1 0% {kong-python-plu} /usr/local/bin/python3.6 /usr/local/bin/kong-python-pluginserver -d /usr/local/kong/python-plugins
I am running kong on 4 core machine with 4 worker processes and also running kong-python-pluginserver without any multiprocessing and gevent libraries.
I am seeing that initially a single worker process(PID: 31) creates kong-python-pluginserver process with single thread (PID: 35) and as more requests come it spawns new threads. I have seen count of these threads go as high as 5000.
But I see in my custom plugin logs that only PID: 35 is entertaining all the requests and no other thread is being used.
(Basically threading.active_count() is continuously increasing and going as high as 5000 and os.getpid() is always 35 in my logs).
Is this behaviour expected ? and
how can I improve on this if I want to process more plugin requests apart from multiprocessing option. Although I have not used but I am assuming the multiprocessing option can be faster but still too many threads being spawned for each plugin process and only 1 thread is entertaining all the requests per plugin process
After some more digging I see that high memory consumption has nothing to do with cache. Actually this issue is similar to https://github.com/Kong/kong-python-pdk/issues/34
In normal threading mode:
High memory consumption is due to lots of ghost threads (because of plugin returning from kong.response.error)
In multi-processing mode:
As 4 parallel processes are running (4 core CPU) with single thread each, after the plugin returns the error/exit response each of the processes becomes ghost in some time. Now no request is being served and the request gets timed out after 60sec and we get 499 errors:
2022/02/10 11:24:50 [error] 37#0: *34244 [kong] mp_rpc.lua:308 [auth_plugin] no data, client: 46.19.86.5, server: kong, request: "GET /v1/users HTTP/1.1", host: "zzz.yyy.com"
...
...
2022/02/10 11:24:58 [info] 37#0: *34482 epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while connecting to upstream, client: 100.36.63.49, server: kong, request: "GET /v1/users HTTP/1.1", upstream: "https://35.164.117.120:443/v1/users", host: "zzz-yyy.com"
46.19.86.5 - - [10/Feb/2022:11:24:58 +0000] "GET /v1/users 499 0 "-" "abc"
I am kind of stuck now and have no idea what to do.
Please resolve this at high priority.
@abhisheksharma2805 Thanks for reporting, I have opened #35. Since it looks same as #34, let's move discussion there for centeralize. Please reopen if the issue persists.