bugfix: buffer bloat and CPU 100% when download large file was filtered by body_filter_by_lua. #1909

zhuizhuhaomeng · 2021-08-18T05:55:06Z

fix issue #1906
I hereby granted the copyright of the changes in this pull request
to the authors of this lua-nginx-module project.

agentzh · 2021-08-18T17:38:09Z

src/ngx_http_lua_bodyfilterby.c

+        }
+
+        for (ln = in; ln != NULL; ln = ln->next) {
+            cl = ngx_alloc_chain_link(r->pool);


We should avoid alloc chain (and free chain below). Small memory blocks can never get freed in nginx memory pools. We should recycle them instead.

ngx_alloc_chain_link allocate chain from the chain pool first and ngx_free_chain free the chain to the chain pool.
ngx_chain_t *
ngx_alloc_chain_link(ngx_pool_t *pool)
{
ngx_chain_t *cl;

cl = pool->chain; if (cl) { pool->chain = cl->next; return cl; } cl = ngx_palloc(pool, sizeof(ngx_chain_t)); if (cl == NULL) { return NULL; } return cl;

}

#define ngx_free_chain(pool, cl)
(cl)->next = (pool)->chain;
(pool)->chain = (cl)

agentzh · 2021-08-18T17:38:27Z

src/ngx_http_lua_bodyfilterby.c

+        for (cl = in; cl != NULL; cl = ln) {
+            ln = cl->next;
+            if (ngx_buf_size(cl->buf) == 0) {
+                ngx_free_chain(r->pool, cl);


see explanation above.

agentzh · 2021-08-18T17:39:04Z

src/ngx_http_lua_bodyfilterby.c

+         */
+        for (cl = in; cl != NULL; cl = ln) {
+            ln = cl->next;
+            if (ngx_buf_size(cl->buf) == 0) {


This does not look right to me. 0-sized can be special bufs indicating flush, eof, and etc.

waterdeng · 2021-08-19T07:14:50Z

It works for #1906.

Thank you .

…ed by body_filter_by_lua. When http body was change by lua script, ngx_http_lua_body_filter_param_set will mark the origin buf as consumed with code "cl->buf->pos = cl->buf->last". Because the buf was marked as consumed, the function ngx_output_chain will continue to write data to the output filter. When kernel socket send buffer is full, write to the socket will return EAGAIN. And the output buf will be cached in output chain. The output chain becomes longer and longer. Function ngx_chain_update_chains do an linear iteration of the output chain to put the new buf to the end of the chain. At the end, there are thounsands of bufs in the output chain which cause the CPU utilization become 100% and memory continue to grow up. nginx.conf: location /download { alias download; header_filter_by_lua_block { ngx.header.content_length = nil } body_filter_by_lua_block { ngx.arg[1]=ngx.arg[1] } } create a 2G file with the following cmd: mkdir -p /usr/local/openresty/nginx/download dd if=/dev/zero of=/usr/local/openresty/nginx/download/2G count=4096000 reproduce with the following cmd: curl -o /dev/null http://127.0.0.1/download/2G typical call stacks: 42706f: ngx_chain_update_chains[14] 47e993: ngx_http_chunked_body_filter[14] 483024: ngx_http_gzip_body_filter[14] 4864d3: ngx_http_ssi_body_filter[14] 489668: ngx_http_charset_body_filter[14] 48b86c: ngx_http_addition_body_filter[14] 48bf9c: ngx_http_gunzip_body_filter[14] 48d75e: ngx_http_trailers_filter[14] 4fb63c: ngx_http_lua_capture_body_filter[14] 509cb9: ngx_http_lua_body_filter[14] 42739e: ngx_output_chain[14] 48e1aa: ngx_http_copy_filter[14] 45ea2b: ngx_http_output_filter[14] 496569: ngx_http_static_handler[14] 45ec6e: ngx_http_core_content_phase[14] 459a25: ngx_http_core_run_phases[14] 463ed3: ngx_http_process_request[14] 4643ff: ngx_http_process_request_headers[14] 4647a6: ngx_http_process_request_line[14] 44c1fe: ngx_epoll_process_events[14] 4431c3: ngx_process_events_and_timers[14] 44a65a: ngx_worker_process_cycle[14] 449074: ngx_spawn_process[14] 44aaac: ngx_start_worker_processes[14] 44b213: ngx_master_process_cycle[14] 422df2: main[14] 23493: __libc_start_main[2] 422e5e: _start[14] 42706f: ngx_chain_update_chains[14] 509ce7: ngx_http_lua_body_filter[14] 42739e: ngx_output_chain[14] 48e1aa: ngx_http_copy_filter[14] 45ea2b: ngx_http_output_filter[14] 496569: ngx_http_static_handler[14] 45ec6e: ngx_http_core_content_phase[14] 459a25: ngx_http_core_run_phases[14] 463ed3: ngx_http_process_request[14] 4643ff: ngx_http_process_request_headers[14] 4647a6: ngx_http_process_request_line[14] 44c1fe: ngx_epoll_process_events[14] 4431c3: ngx_process_events_and_timers[14] 44a65a: ngx_worker_process_cycle[14] 449074: ngx_spawn_process[14] 44aaac: ngx_start_worker_processes[14] 44b213: ngx_master_process_cycle[14] 422df2: main[14] 23493: __libc_start_main[2] 422e5e: _start[14] 47d51f: ngx_http_write_filter[14] 47e973: ngx_http_chunked_body_filter[14] 483024: ngx_http_gzip_body_filter[14] 4864d3: ngx_http_ssi_body_filter[14] 489668: ngx_http_charset_body_filter[14] 48b86c: ngx_http_addition_body_filter[14] 48bf9c: ngx_http_gunzip_body_filter[14] 48d75e: ngx_http_trailers_filter[14] 4fb63c: ngx_http_lua_capture_body_filter[14] 509cb9: ngx_http_lua_body_filter[14] 42739e: ngx_output_chain[14] 48e1aa: ngx_http_copy_filter[14] 45ea2b: ngx_http_output_filter[14] 496569: ngx_http_static_handler[14] 45ec6e: ngx_http_core_content_phase[14] 459a25: ngx_http_core_run_phases[14] 463ed3: ngx_http_process_request[14] 4643ff: ngx_http_process_request_headers[14] 4647a6: ngx_http_process_request_line[14] 44c1fe: ngx_epoll_process_events[14] 4431c3: ngx_process_events_and_timers[14] 44a65a: ngx_worker_process_cycle[14] 449074: ngx_spawn_process[14] 44aaac: ngx_start_worker_processes[14] 44b213: ngx_master_process_cycle[14] 422df2: main[14] 23493: __libc_start_main[2] 422e5e: _start[14]

doujiang24 · 2021-09-02T16:13:13Z

src/ngx_http_lua_bodyfilterby.c

+    if (in != NULL) {
+        if (ngx_chain_add_copy(r->pool, &ctx->filter_in_bufs, in) != NGX_OK) {


Suggested change

if (in != NULL) {

if (ngx_chain_add_copy(r->pool, &ctx->filter_in_bufs, in) != NGX_OK) {

if (in != NULL

&& ngx_chain_add_copy(r->pool, &ctx->filter_in_bufs, in) != NGX_OK)

{

doujiang24 · 2021-09-02T16:15:08Z

src/ngx_http_lua_bodyfilterby.c

+        if (rc != NGX_OK) {
+            if (ctx->filter_busy_bufs != NULL
+                && (r->connection->buffered
+                    & (NGX_HTTP_LOWLEVEL_BUFFERED | NGX_LOWLEVEL_BUFFERED))) {


Suggested change

if (rc != NGX_OK) {

if (ctx->filter_busy_bufs != NULL

&& (r->connection->buffered

& (NGX_HTTP_LOWLEVEL_BUFFERED | NGX_LOWLEVEL_BUFFERED))) {

if (rc != NGX_OK

&& ctx->filter_busy_bufs != NULL

&& (r->connection->buffered

& (NGX_HTTP_LOWLEVEL_BUFFERED | NGX_LOWLEVEL_BUFFERED)))

{

doujiang24 · 2021-09-02T16:19:51Z

src/ngx_http_lua_common.h

@@ -548,6 +548,9 @@ typedef struct ngx_http_lua_ctx_s {
    ngx_chain_t             *busy_bufs;
    ngx_chain_t             *free_recv_bufs;

+    ngx_chain_t             *filter_in_bufs;  /* for the body filter */
+    ngx_chain_t             *filter_busy_bufs;  /* for the body filter */


can we use union here to save memory?
like:

union { ngx_chain_t *filter_busy_bufs; ngx_chain_t *busy_bufs; };

Maybe filter_in_bufs can union with free_recv_bufs?

doujiang24 · 2021-09-02T16:23:21Z

src/ngx_http_lua_output.c

+    ngx_log_debug2(NGX_LOG_DEBUG_HTTP, r->connection->log, 0,
+                   "%s has %sbusy bufs",
+                   newline ? "lua say response" : "lua print response",
+                   ctx->busy_bufs != NULL ? "" : "not ");


Suggested change

ctx->busy_bufs != NULL ? "" : "not ");

ctx->busy_bufs != NULL ? "" : "no ");

mergify bot added the needs-test-cases label Aug 18, 2021

zhuizhuhaomeng force-pushed the body_filter branch 2 times, most recently from 11a3a7f to f424d25 Compare August 18, 2021 07:49

zhuizhuhaomeng mentioned this pull request Aug 18, 2021

Strange thing while change ngx.arg[1] in body_filter_by_lua* #1906

Closed

agentzh requested changes Aug 18, 2021

View reviewed changes

zhuizhuhaomeng force-pushed the body_filter branch 3 times, most recently from 6071b2b to 8dc45ef Compare August 29, 2021 13:14

mergify bot removed the needs-test-cases label Aug 29, 2021

zhuizhuhaomeng force-pushed the body_filter branch 4 times, most recently from c8fe8aa to b71d186 Compare August 29, 2021 15:28

agentzh approved these changes Aug 30, 2021

View reviewed changes

zhuizhuhaomeng added 2 commits August 30, 2021 16:10

tests: fixed typo.

4b3fb72

zhuizhuhaomeng force-pushed the body_filter branch from 3a6812d to 4b3fb72 Compare August 30, 2021 08:11

doujiang24 reviewed Sep 2, 2021

View reviewed changes

change: change grammar of error log.

7031273

zhuizhuhaomeng force-pushed the body_filter branch from e2f73a0 to 7031273 Compare September 3, 2021 00:12

doujiang24 approved these changes Sep 3, 2021

View reviewed changes

zhuizhuhaomeng merged commit 3820d0e into master Sep 3, 2021

doujiang24 deleted the body_filter branch September 4, 2021 01:50

fs7744 mentioned this pull request Sep 30, 2022

bug: hold_body_chunk will missing last chunk apache/apisix#8027

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

bugfix: buffer bloat and CPU 100% when download large file was filtered by body_filter_by_lua. #1909

bugfix: buffer bloat and CPU 100% when download large file was filtered by body_filter_by_lua. #1909

Uh oh!

zhuizhuhaomeng commented Aug 18, 2021 •

edited

Loading

Uh oh!

agentzh Aug 18, 2021

Uh oh!

zhuizhuhaomeng Aug 19, 2021

Uh oh!

agentzh Aug 18, 2021

Uh oh!

zhuizhuhaomeng Aug 19, 2021

Uh oh!

agentzh Aug 18, 2021

Uh oh!

waterdeng commented Aug 19, 2021

Uh oh!

doujiang24 Sep 2, 2021

Uh oh!

doujiang24 Sep 2, 2021

Uh oh!

doujiang24 Sep 2, 2021

Uh oh!

doujiang24 Sep 2, 2021

Uh oh!

Uh oh!

		if (in != NULL) {
		if (ngx_chain_add_copy(r->pool, &ctx->filter_in_bufs, in) != NGX_OK) {

	ctx->busy_bufs != NULL ? "" : "not ");
	ctx->busy_bufs != NULL ? "" : "no ");

bugfix: buffer bloat and CPU 100% when download large file was filtered by body_filter_by_lua. #1909

bugfix: buffer bloat and CPU 100% when download large file was filtered by body_filter_by_lua. #1909

Uh oh!

Conversation

zhuizhuhaomeng commented Aug 18, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

waterdeng commented Aug 19, 2021

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

zhuizhuhaomeng commented Aug 18, 2021 •

edited

Loading