unflush buffer of main request would trigger repeatedly buffer appends into the busy buffer list from cosocket send

[kingluo]

Version: openresty-1.21.4.1

Descritpion

If you do ngx.say without ngx.flush, and use cosockets to send messages, the message buffers would be appended to the busy buffer list and do not get released until the main request finish. The busy buffer list would become bigger and bigger, and slow down the send operation dramatically.

Reproduce this issue

nginx.conf

error_log /dev/stderr info;
worker_processes auto;

events {}

http {
    server {
        listen 50000;

        location / {
            content_by_lua_block {
                ngx.say("hello")
                --ngx.flush(true)

                local sock = ngx.socket.tcp()
                local ok, err = sock:connect("unix:/tmp/echo.sock")
                assert(ok)
                ngx.update_time()
                local t1 = ngx.now()
                for _ = 1,100000 do
                    local sent = sock:send("hello")
                    local data = sock:receive(5)
                    assert(data=="hello")
                end
                ngx.log(ngx.INFO, "uds finish")
                ngx.update_time()
                local t2 = ngx.now()
                ngx.say("uds: ", t2-t1)
                sock:close()
                ngx.exit(200)
            }
        }
    }
}

/tmp/echo.go

package main

import (
    "io"
    "log"
    "net"
    "os"
)

const SockAddr = "/tmp/echo.sock"

func echoServer(c net.Conn) {
    log.Println("* start echo io")
    n, _ := io.Copy(c, c)
    log.Println("* end echo io, copy: ", n)
    c.Close()
}

func main() {
    log.Println("start unix server")
    if err := os.RemoveAll(SockAddr); err != nil {
        log.Fatal(err)
    }

    l, err := net.Listen("unix", SockAddr)
    if err != nil {
        log.Fatal("listen error:", err)
    }
    defer l.Close()
    for {
        log.Println("accept...")
        conn, err := l.Accept()
        if err != nil {
            log.Fatal("accept error:", err)
        }

        go echoServer(conn)
    }
}

If I don't flush the response, then the unix socket client bencharmk is slow:

# run nginx
nginx -p $PWD -c nginx.conf -g "daemon off;"

# run echo server
go run /tmp/echo.go

# curl localhost:50000
hello
uds: 54.944999933243

If I uncomment ngx.flush(true), then the benchmark is correct.

# curl localhost:50000
hello
uds: 2.289999961853

Locate the reason of this issue

Use perf top to check the hotspot: ngx_chain_update_chains.

       │    {
  0.00 │      endbr64
       │    ngx_chain_t  *cl;
       │
       │    if (*out) {
       │      mov     (%rcx),%r10
  0.01 │      mov     (%rdx),%rax
       │      test    %r10,%r10
       │    ↓ je      56
       │    if (*busy == NULL) {
       │      test    %rax,%rax
       │    ↓ je      b8
       │      nop
       │    *busy = *out;
       │
       │    } else {
       │    for (cl = *busy; cl->next; cl = cl->next) { /* void */ }
  5.95 │20:   mov     %rax,%r9
  0.02 │      mov     0x8(%rax),%rax
 93.94 │      test    %rax,%rax
       │    ↑ jne     20
       │
       │    cl->next = *out;
  0.01 │      mov     %r10,0x8(%r9)
       │    }

Use gdb to check which invokes ngx_chain_update_chains :

(gdb) bt
#0  0x00005621f736fc07 in ngx_chain_update_chains (p=0x5621f9038850, free=free@entry=0x5621f90397b8, busy=busy@entry=0x5621f90397c0, out=out@entry=0x7fa1ad4d8f68,
    tag=0x5621f75797a0 <ngx_http_lua_module>) at src/core/ngx_buf.c:195
#1  0x00005621f74710d4 in ngx_http_lua_socket_send (r=r@entry=0x5621f90388a0, u=u@entry=0x7fa1ad4d8de0) at ../ngx_lua-0.10.21/src/ngx_http_lua_socket_tcp.c:3388
#2  0x00005621f7471940 in ngx_http_lua_socket_tcp_send (L=0x7fa1ad4dc4e8) at ../ngx_lua-0.10.21/src/ngx_http_lua_socket_tcp.c:2935
#3  ngx_http_lua_socket_tcp_send (L=0x7fa1ad4dc4e8) at ../ngx_lua-0.10.21/src/ngx_http_lua_socket_tcp.c:2728
#4  0x00007fa1ae973044 in lj_BC_FUNCC () from /usr/local/openresty-debug/luajit/lib/libluajit-5.1.so.2
#5  0x00005621f7465501 in ngx_http_lua_run_thread (L=L@entry=0x7fa1ad4ea380, r=r@entry=0x5621f90388a0, ctx=ctx@entry=0x5621f90396a0, nrets=<optimized out>)
    at ../ngx_lua-0.10.21/src/ngx_http_lua_util.c:1185
#6  0x00005621f746e8b6 in ngx_http_lua_socket_tcp_resume_helper (r=0x5621f90388a0, socket_op=<optimized out>) at ../ngx_lua-0.10.21/src/ngx_http_lua_socket_tcp.c:6014
#7  0x00005621f7474c7f in ngx_http_lua_socket_handle_read_success (u=0x7fa1ad4d8de0, r=0x5621f90388a0) at ../ngx_lua-0.10.21/src/ngx_http_lua_socket_tcp.c:3511
#8  ngx_http_lua_socket_tcp_read (r=0x5621f90388a0, u=0x7fa1ad4d8de0) at ../ngx_lua-0.10.21/src/ngx_http_lua_socket_tcp.c:2522
#9  0x00005621f746c944 in ngx_http_lua_socket_tcp_handler (ev=0x5621f9085870) at ../ngx_lua-0.10.21/src/ngx_http_lua_socket_tcp.c:3265
...

The reason is: The busy buffer list is shared by the main request and cosockets created from the same main request. If the head part of the list (unflush ngx.say) keep still, the following of the list would not be cleared and get accumulated when you send more and more message via the cosocket).

How to verify the reason?

Use gdb to evaluate the breakpoint context:

b ngx_chain_update_chains
    command 1
    set $v = *busy
    set $cnt = 0
    while ($v != 0)
        set $cnt++
        set $v=$v->next
    end
    p $cnt
    continue
end

Output:

Breakpoint 1, ngx_chain_update_chains (p=0x55a53413e850, free=free@entry=0x55a53413f7b8, busy=busy@entry=0x55a53413f7c0, out=out@entry=0x7f80f353fe50, tag=0x55a5326887a0 <ngx_http_lua_module>) at src/core/ngx_buf.c:187
187     {
$11 = 80399

Breakpoint 1, ngx_chain_update_chains (p=0x55a53413e850, free=free@entry=0x55a53413f7b8, busy=busy@entry=0x55a53413f7c0, out=out@entry=0x7f80f353fe50, tag=0x55a5326887a0 <ngx_http_lua_module>) at src/core/ngx_buf.c:187
187     {
$12 = 80400

Breakpoint 1, ngx_chain_update_chains (p=0x55a53413e850, free=free@entry=0x55a53413f7b8, busy=busy@entry=0x55a53413f7c0, out=out@entry=0x7f80f353fe50, tag=0x55a5326887a0 <ngx_http_lua_module>) at src/core/ngx_buf.c:187
187     {
$13 = 80401

Breakpoint 1, ngx_chain_update_chains (p=0x55a53413e850, free=free@entry=0x55a53413f7b8, busy=busy@entry=0x55a53413f7c0, out=out@entry=0x7f80f353fe50, tag=0x55a5326887a0 <ngx_http_lua_module>) at src/core/ngx_buf.c:187
187     {
$14 = 80402

Breakpoint 1, ngx_chain_update_chains (p=0x55a53413e850, free=free@entry=0x55a53413f7b8, busy=busy@entry=0x55a53413f7c0, out=out@entry=0x7f80f353fe50, tag=0x55a5326887a0 <ngx_http_lua_module>) at src/core/ngx_buf.c:187
187     {
$15 = 80403

The busy buffer and free buffer mechanism is used to pool and reuse the buffers. But this bug seems exists for a long time. The workaround is to do ngx.flush each time you do ngx.say in my scenario.

@zhuizhuhaomeng @agentzh