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 <[email protected]>
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