worker use 100% cpu

[dolgovas]

Hello! I'm using fork nginx (angie) and trying to enable zstd-module into my project.
And it works great on ubuntu22.04 and 24.04, but one of my server still use ubuntu20.04 and I met trouble...

After few requests angie started to use 100% for worker that accept request... and than another worker and another and another. And after around 100-200 request all 4 workers utilizing all of my vcpu.

Here is start of problem debug log and after that many-many thousands last of two strings. Worker processed like that cannot finishing with HUP signal. Only restart...

2024/11/27 14:03:06 [debug] 56414#56414: *138 http cleanup add: 0000559F3E406028
2024/11/27 14:03:06 [debug] 56414#56414: *138 init keepalive peer
2024/11/27 14:03:06 [debug] 56414#56414: *138 get keepalive peer
2024/11/27 14:03:06 [debug] 56414#56414: *138 get rr peer, try: 1
2024/11/27 14:03:06 [debug] 56414#56414: *138 get keepalive peer: using connection 00007FC7D8ED66D8
2024/11/27 14:03:06 [debug] 56414#56414: *138 event timer del: 22: 7256125
2024/11/27 14:03:06 [debug] 56414#56414: *138 http upstream connect: -4
2024/11/27 14:03:06 [debug] 56414#56414: *138 http upstream send request
2024/11/27 14:03:06 [debug] 56414#56414: *138 http upstream send request body
2024/11/27 14:03:06 [debug] 56414#56414: *138 chain writer buf fl:1 s:889
2024/11/27 14:03:06 [debug] 56414#56414: *138 chain writer in: 0000559F3E406078
2024/11/27 14:03:06 [debug] 56414#56414: *138 writev: 889 of 889
2024/11/27 14:03:06 [debug] 56414#56414: *138 chain writer out: 0000000000000000
2024/11/27 14:03:06 [debug] 56414#56414: *138 event timer add: 22: 3600000:10796191
2024/11/27 14:03:06 [debug] 56414#56414: *138 http finalize request: -4, "/lux-kube-v3-ui-vue-components-2107-styles?delimiter=%2F&max-keys=1000&prefix=2.2.143-wv3inbox-14214-4749345f.0%2F" a:1, c:2
2024/11/27 14:03:06 [debug] 56414#56414: *138 http request count:2 blk:0
2024/11/27 14:03:06 [debug] 56414#56414: *138 http run request: "/lux-kube-v3-ui-vue-components-2107-styles?delimiter=%2F&max-keys=1000&prefix=2.2.143-wv3inbox-14214-4749345f.0%2F"
2024/11/27 14:03:06 [debug] 56414#56414: *138 http upstream check client, write event:1, "/lux-kube-v3-ui-vue-components-2107-styles"
2024/11/27 14:03:06 [debug] 56414#56414: *143 http upstream request: "/lux-kube-web-push-4687-static/firebase-messaging-sw.js?"
2024/11/27 14:03:06 [debug] 56414#56414: *143 http upstream process header
2024/11/27 14:03:06 [debug] 56414#56414: *143 malloc: 0000559F3E407150:131072
2024/11/27 14:03:06 [debug] 56414#56414: *143 recv: eof:0, avail:-1
2024/11/27 14:03:06 [debug] 56414#56414: *143 recv: fd:30 395 of 131072
2024/11/27 14:03:06 [debug] 56414#56414: *143 http proxy status 200 "200 OK"
2024/11/27 14:03:06 [debug] 56414#56414: *143 http proxy header: "Content-Length: 2722"
2024/11/27 14:03:06 [debug] 56414#56414: *143 http proxy header: "Accept-Ranges: bytes"
2024/11/27 14:03:06 [debug] 56414#56414: *143 http proxy header: "Last-Modified: Wed, 27 Nov 2024 07:07:56 GMT"
2024/11/27 14:03:06 [debug] 56414#56414: *143 http proxy header: "x-rgw-object-type: Normal"
2024/11/27 14:03:06 [debug] 56414#56414: *143 http proxy header: "ETag: "1e8ff66b01c006f78fa76ea36c13e891""
2024/11/27 14:03:06 [debug] 56414#56414: *143 http proxy header: "x-amz-meta-mtime: 1732691275.597285236"
2024/11/27 14:03:06 [debug] 56414#56414: *143 http proxy header: "x-amz-request-id: tx000005dca0145fb0c9708-006746fc6a-2a2ff8f-default"
2024/11/27 14:03:06 [debug] 56414#56414: *143 http proxy header: "Content-Type: text/javascript; charset=utf-8"
2024/11/27 14:03:06 [debug] 56414#56414: *143 http proxy header: "Date: Wed, 27 Nov 2024 11:03:06 GMT"
2024/11/27 14:03:06 [debug] 56414#56414: *143 http proxy header: "Connection: Keep-Alive"
2024/11/27 14:03:06 [debug] 56414#56414: *143 http proxy header done
2024/11/27 14:03:06 [debug] 56414#56414: *143 HTTP/1.1 200 OK
Server: Angie
Date: Wed, 27 Nov 2024 11:03:06 GMT
Content-Type: text/javascript; charset=utf-8
Transfer-Encoding: chunked
Connection: keep-alive
Vary: Accept-Encoding
Last-Modified: Wed, 27 Nov 2024 07:07:56 GMT
ETag: W/"1e8ff66b01c006f78fa76ea36c13e891"
x-amz-meta-mtime: 1732691275.597285236
Content-Encoding: zstd

2024/11/27 14:03:06 [debug] 56414#56414: *143 write new buf t:1 f:0 0000559F3E2779B0, pos 0000559F3E2779B0, size: 346 file: 0, size: 0
2024/11/27 14:03:06 [debug] 56414#56414: *143 http write filter: l:0 f:0 s:346
2024/11/27 14:03:06 [debug] 56414#56414: *143 http proxy filter init s:200 h:0 c:0 l:2722
2024/11/27 14:03:06 [debug] 56414#56414: *143 tcp_nodelay
2024/11/27 14:03:06 [debug] 56414#56414: *143 http output filter "/lux-kube-web-push-4687-static/firebase-messaging-sw.js?"
2024/11/27 14:03:06 [debug] 56414#56414: *143 http copy filter: "/lux-kube-web-push-4687-static/firebase-messaging-sw.js?"
2024/11/27 14:03:06 [debug] 56414#56414: *143 http postpone filter "/lux-kube-web-push-4687-static/firebase-messaging-sw.js?" 00007FFD3E94C670
2024/11/27 14:03:06 [debug] 56414#56414: *143 http zstd filter
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd alloc: 0000559F3E277BE0, size: 1144
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd in: 0000559F3E278058
2024/11/27 14:03:06 [debug] 56414#56414: *143 malloc: 0000559F3E427160:4096
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress in: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096 flush:1 redo:0
2024/11/27 14:03:06 [debug] 56414#56414: *143 malloc: 00007FC7D7D1A010:6012417
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd alloc: 00007FC7D7D1A010, size: 6012417
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress out: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress in: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096 flush:1 redo:1
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress out: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress in: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096 flush:1 redo:0
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress out: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress in: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096 flush:1 redo:1
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress out: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress in: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096 flush:1 redo:0
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress out: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress in: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096 flush:1 redo:1
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress out: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress in: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096 flush:1 redo:0
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress out: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress in: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096 flush:1 redo:1
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress out: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress in: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096 flush:1 redo:0
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress out: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress in: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096 flush:1 redo:1
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress out: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress in: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096 flush:1 redo:0
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress out: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096
2024/11/27 14:03:06 [debug] 56414#56414: *143 zstd compress in: src:0000000000000000 pos:0 size: 0, dst:0000559F3E427160 pos:0 size:4096 flush:1 redo:1

[tokers]

@dolgovas It would be nice to have a minimum reproducible case. BTW, could you capture a flame graph when Nginx workers occupy nearly 100% CPU time.

[dolgovas]

@dolgovas It would be nice to have a minimum reproducible case. BTW, could you capture a flame graph when Nginx workers occupy nearly 100% CPU time.

I'll try to make it ASAP

[dolgovas]

made via this instruction.

[hackoffme]

I have encountered the same issue described in this thread. After integrating the zstd-nginx-module into my Nginx server, the worker processes consume 100% CPU following the first request, leading to server unresponsiveness.
nginx/1.26.2
zstd-nginx-module 0.1.1
cat /usr/share/nginx/modules/zstd_* load_module "/usr/lib64/nginx/modules/ngx_http_zstd_filter_module.so"; load_module "/usr/lib64/nginx/modules/ngx_http_zstd_static_module.so";

Name:           zstd-nginx-module
Version:        0.1.1
Release:        1%{?dist}
Summary:        Zstandard compression module for Nginx
License:        BSD-2-Clause
Source0:        https://github.com/tokers/zstd-nginx-module/archive/refs/tags/%{version}.tar.gz

BuildRequires:  gcc
BuildRequires:  pcre-devel
BuildRequires:  zlib-devel
BuildRequires:  nginx-mod-devel
Requires:       nginx

%description
The zstd-nginx-module provides Zstandard compression for Nginx.

%prep
%autosetup -n %{name}-%{version}

%build
%nginx_modconfigure
%nginx_modbuild

%install
pushd %{_vpath_builddir}
install -d %{buildroot}%{nginx_moddir}
install -m 0755 ngx_http_zstd_filter_module.so %{buildroot}%{nginx_moddir}/
install -m 0755 ngx_http_zstd_static_module.so %{buildroot}%{nginx_moddir}/

install -d %{buildroot}%{nginx_modconfdir}
echo 'load_module "%{nginx_moddir}/ngx_http_zstd_filter_module.so";' > %{buildroot}%{nginx_modconfdir}/zstd_filter.conf
echo 'load_module "%{nginx_moddir}/ngx_http_zstd_static_module.so";' > %{buildroot}%{nginx_modconfdir}/zstd_static.conf
popd

%files
%{nginx_modconfdir}/*
%{nginx_moddir}/*

[kamermans]

I'm also seeing this in an Ubuntu 22.04 container running Nginx:

nginx version: nginx/1.27.3
built by gcc 11.4.0 (Ubuntu 11.4.0-1ubuntu1~22.04)
built with OpenSSL 3.0.2 15 Mar 2022
TLS SNI support enabled
configure arguments: 
  --prefix=/etc/nginx
  --sbin-path=/usr/sbin/nginx
  --add-module=/opt/nginx/ngx_brotli
  --add-module=/opt/nginx/zstd-nginx-module
  --modules-path=/usr/lib/nginx/modules
  --conf-path=/etc/nginx/nginx.conf
  --error-log-path=/var/log/nginx/error.log
  --http-log-path=/var/log/nginx/access.log
  --pid-path=/var/run/nginx.pid
  --lock-path=/var/run/nginx.lock
  --http-client-body-temp-path=/var/cache/nginx/client_temp
  --http-proxy-temp-path=/var/cache/nginx/proxy_temp
  --http-fastcgi-temp-path=/var/cache/nginx/fastcgi_temp
  --http-uwsgi-temp-path=/var/cache/nginx/uwsgi_temp
  --http-scgi-temp-path=/var/cache/nginx/scgi_temp
  --user=nginx
  --group=nginx
  --with-compat
  --with-file-aio
  --with-threads
  --with-http_addition_module
  --with-http_auth_request_module
  --with-http_dav_module
  --with-http_flv_module
  --with-http_gunzip_module
  --with-http_gzip_static_module
  --with-http_mp4_module
  --with-http_random_index_module
  --with-http_realip_module
  --with-http_secure_link_module
  --with-http_slice_module
  --with-http_ssl_module
  --with-http_stub_status_module
  --with-http_sub_module
  --with-http_v2_module
  --with-http_v3_module
  --with-mail
  --with-mail_ssl_module
  --with-stream
  --with-stream_realip_module
  --with-stream_ssl_module
  --with-stream_ssl_preread_module
  --with-cc-opt='-g -O2 -ffile-prefix-map=/opt/nginx/nginx-1.27.3=. -flto=auto -ffat-lto-objects -flto=auto -ffat-lto-objects -fstack-protector-strong -Wformat -Werror=format-security -Wno-missing-field-initializers -Wp,-D_FORTIFY_SOURCE=2 -fPIC' 
  --with-ld-opt='-Wl,-Bsymbolic-functions -flto=auto -ffat-lto-objects -flto=auto -Wl,-z,relro -Wl,-z,now -Wl,--as-needed -pie'

I repackage the official deb source from nginx.org with the zstd and brotli added.

I'm using the official Ubuntu libzstd1 package:

# dpkg -s libzstd1
Package: libzstd1
Status: install ok installed
Priority: required
Section: libs
Installed-Size: 846
Maintainer: Ubuntu Developers <ubuntu-devel-discuss@lists.ubuntu.com>
Architecture: amd64
Multi-Arch: same
Source: libzstd
Version: 1.4.8+dfsg-3build1
Depends: libc6 (>= 2.14)

Here's a graph of the CPU usage from the instance start time to 30 minutes later when it started failing health checks. During this time period, this instance was getting about 140 client requests per second, although most of them would not have used ztsd, probably 5-10% of those requests were using zstd.

[dolgovas]

@tokers may be you need any additional info?

[bouk]

Seems related: #23

[madrzejewski]

Hello,

Same issue here with Openresty 1.27.1.2, after a few days I always have a few Nginx processes stuck at 100% CPU usage.

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                                                                                                                                                                                                                                                                             
1066324 nobody    20   0 4245900   2.2g 108800 R  98.8   0.9 577:10.60 nginx: worker process                                                                                                                                                                                                                                                                               
1066589 nobody    20   0 4245004   2.2g 107520 R  98.8   0.9 577:10.05 nginx: worker process                                                                                                                                                                                                                                                                               
1066791 nobody    20   0 4244876   2.2g 110080 R  98.8   0.9 577:22.89 nginx: worker process                                                                                                                                                                                                                                                                               
1066885 nobody    20   0 4246412   2.2g 110080 R  98.8   0.9 576:58.82 nginx: worker process

When I run GDB on one of the process to get a backstrace, I have this :

#0  0x00007f7742781e5c in ZSTD_compressStream2 () from /lib64/libzstd.so.1
#1  0x00007f774278240b in ZSTD_compressStream () from /lib64/libzstd.so.1
#2  0x000000000057f6c0 in ngx_http_zstd_filter_compress (r=0x19b1a070, r=0x19b1a070, ctx=0x19b1e8d0) at /usr/src/openresty/zstd-nginx-module/filter/ngx_http_zstd_filter_module.c:420
#3  ngx_http_zstd_body_filter (r=0x19b1a070, in=<optimized out>) at /usr/src/openresty/zstd-nginx-module/filter/ngx_http_zstd_filter_module.c:331
#4  0x00000000004a9ad1 in ngx_http_ssi_body_filter (r=<optimized out>, in=<optimized out>) at src/http/modules/ngx_http_ssi_filter_module.c:440
#5  0x00000000004ae876 in ngx_http_charset_body_filter (r=0x19b1a070, in=0x7ffdcba108c0) at src/http/modules/ngx_http_charset_filter_module.c:647
#6  0x00000000004af9b4 in ngx_http_gunzip_body_filter (r=0x19b1a070, in=0x7ffdcba108c0) at src/http/modules/ngx_http_gunzip_filter_module.c:185
#7  0x00000000004b1236 in ngx_http_trailers_filter (r=0x19b1a070, in=0x7ffdcba108c0) at src/http/modules/ngx_http_headers_filter_module.c:274
#8  0x00000000005202e4 in ngx_http_lua_capture_body_filter (r=0x19b1a070, in=0x7ffdcba108c0) at ../ngx_lua-0.10.28/src/ngx_http_lua_capturefilter.c:133
#9  0x000000000042d312 in ngx_output_chain (ctx=ctx@entry=0x19b1ecf8, in=in@entry=0x7ffdcba108c0) at src/core/ngx_output_chain.c:70
#10 0x00000000004b1c44 in ngx_http_copy_filter (r=0x19b1a070, in=0x7ffdcba108c0) at src/http/ngx_http_copy_filter_module.c:145
#11 0x000000000047bc27 in ngx_http_output_filter (r=r@entry=0x19b1a070, in=in@entry=0x7ffdcba108c0) at src/http/ngx_http_core_module.c:1874
#12 0x000000000047fce0 in ngx_http_send_special (r=r@entry=0x19b1a070, flags=flags@entry=2) at src/http/ngx_http_request.c:3647
#13 0x00000000004929bd in ngx_http_upstream_finalize_request (r=0x19b1a070, u=0x19b1d4c8, rc=-1) at src/http/ngx_http_upstream.c:4675
#14 0x000000000049396a in ngx_http_upstream_process_request (r=0x19b1a070, u=0x19b1d4c8) at src/http/ngx_http_upstream.c:4239
#15 0x0000000000492d94 in ngx_http_upstream_handler (ev=0xa45ca40) at src/http/ngx_http_upstream.c:1306
#16 0x0000000000455df3 in ngx_epoll_process_events (cycle=0x7cdf2130, timer=<optimized out>, flags=<optimized out>) at src/event/modules/ngx_epoll_module.c:901
#17 0x000000000044ab75 in ngx_process_events_and_timers (cycle=cycle@entry=0x7cdf2130) at src/event/ngx_event.c:258
#18 0x00000000004539c5 in ngx_worker_process_cycle (cycle=cycle@entry=0x7cdf2130, data=data@entry=0x1e) at src/os/unix/ngx_process_cycle.c:793
#19 0x00000000004523d7 in ngx_spawn_process (cycle=cycle@entry=0x7cdf2130, proc=proc@entry=0x453980 <ngx_worker_process_cycle>, data=data@entry=0x1e, name=name@entry=0x5d571d "worker process", respawn=respawn@entry=-4) at src/os/unix/ngx_process.c:207
#20 0x0000000000453fcc in ngx_start_worker_processes (cycle=cycle@entry=0x7cdf2130, n=45, type=type@entry=-4) at src/os/unix/ngx_process_cycle.c:382
#21 0x0000000000454e5a in ngx_master_process_cycle (cycle=0x7cdf2130) at src/os/unix/ngx_process_cycle.c:241
#22 0x000000000042806c in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:387