High cpu load from uwsgi when using podman-compose (default conf)

[foursixnine]

Description of problem

Running with podman-compose (python 3.11, and 3.12) results in few errors, resulting in high load on wsgi and decreased peformance

as soon as I restart the containers, and after navigating to any of the pages:

Jul 29 21:35:36 istabl-antar02 kiwi_web[3053]: 127.0.0.1 - - [29/Jul/2024:21:35:36 +0000] "GET /accounts/login/ HTTP/1.1" 200 15292 "healthcheck" "curl/7.76.1" "-"


Jul 29 21:35:52 istabl-antar02 kiwi_web[3053]: [redacted] - - [29/Jul/2024:21:35:52 +0000] "MGLNDD_[redacted]_443" 400 157 "-" "-" "-"
Jul 29 21:36:04 istabl-antar02 systemd[1376]: [email protected]: State 'stop-sigterm' timed out. Killing.
Jul 29 21:36:04 istabl-antar02 systemd[1376]: [email protected]: Killing process 3053 (conmon) with signal SIGKILL.
Jul 29 21:36:04 istabl-antar02 systemd[1376]: [email protected]: Killing process 3148 (conmon) with signal SIGKILL.
Jul 29 21:36:04 istabl-antar02 systemd[1376]: [email protected]: Failed with result 'exit-code'.

the result of the podman-compose logs is:

Version or commit hash (if applicable)

using docker.io/kiwitcms/kiwi:latest

Steps to Reproduce

followed: https://kiwitcms.readthedocs.io/en/latest/installing_docker.html

1. vm has 2 cores & 2 gb of ram

Actual results

System is very slow, wsgi has high load

Expected results

Additional info (Python traceback, logs, etc.)

464fb643184e [uWSGI] getting INI configuration from /Kiwi/etc/uwsgi.conf
464fb643184e *** Starting uWSGI 2.0.26 (64bit) on [Mon Jul 29 21:34:33 2024] ***
464fb643184e compiled with version: 11.4.1 20231218 (Red Hat 11.4.1-3) on 12 June 2024 12:12:17
464fb643184e os: Linux-6.9.9-1-default #1 SMP PREEMPT_DYNAMIC Thu Jul 11 11:31:54 UTC 2024 (8c0f797)
464fb643184e nodename: 464fb643184e
464fb643184e machine: x86_64
464fb643184e clock source: unix
464fb643184e detected number of CPU cores: 2
464fb643184e current working directory: /
464fb643184e writing pidfile to /tmp/kiwitcms.pid
464fb643184e detected binary path: /venv/bin/uwsgi
464fb643184e !!! no internal routing support, rebuild with pcre support !!!
464fb643184e chdir() to /Kiwi
464fb643184e your processes number limit is 4194304
464fb643184e your memory page size is 4096 bytes
464fb643184e  *** WARNING: you have enabled harakiri without post buffering. Slow upload could be rejected on post-unbuffered webservers ***
464fb643184e detected max file descriptor number: 1048576
464fb643184e lock engine: pthread robust mutexes
464fb643184e thunder lock: disabled (you can enable it with --thunder-lock)
464fb643184e uwsgi socket 0 bound to UNIX address /tmp/kiwitcms.sock fd 3
464fb643184e Python version: 3.11.7 (main, Jan 22 2024, 00:00:00) [GCC 11.4.1 20231218 (Red Hat 11.4.1-3)]
464fb643184e PEP 405 virtualenv detected: /venv
464fb643184e Set PythonHome to /venv
464fb643184e *** Python threads support is disabled. You can enable it with --enable-threads ***
464fb643184e Python main interpreter initialized at 0x7f2984ec1558
464fb643184e your server socket listen backlog is limited to 100 connections
464fb643184e your mercy for graceful operations on workers is 60 seconds
464fb643184e mapped 218760 bytes (213 KB) for 2 cores
464fb643184e *** Operational MODE: preforking ***
464fb643184e WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x7f2984ec1558 pid: 7 (default app)
464fb643184e *** uWSGI is running in multiple interpreter mode ***
464fb643184e spawned uWSGI master process (pid: 7)
464fb643184e spawned uWSGI worker 1 (pid: 9, cores: 1)
464fb643184e spawned uWSGI worker 2 (pid: 10, cores: 1)
464fb643184e [pid: 9|app: 0|req: 1/1] 127.0.0.1 () {36 vars in 411 bytes} [Mon Jul 29 21:34:33 2024] GET /accounts/login/ => generated 0 bytes in 47 msecs (HTTP/1.1 302) 2 headers in 83 bytes (1 switches on core 0)
464fb643184e 127.0.0.1 - - [29/Jul/2024:21:34:33 +0000] "GET /accounts/login/ HTTP/1.1" 302 5 "healthcheck" "curl/7.76.1" "-"
464fb643184e 127.0.0.1 - - [29/Jul/2024:21:35:05 +0000] "GET /accounts/login/ HTTP/1.1" 200 15292 "healthcheck" "curl/7.76.1" "-"
464fb643184e [pid: 10|app: 0|req: 1/2] 127.0.0.1 () {36 vars in 411 bytes} [Mon Jul 29 21:35:04 2024] GET /accounts/login/ => generated 15292 bytes in 95 msecs (HTTP/1.1 200) 11 headers in 525 bytes (1 switches on core 0)
464fb643184e [pid: 9|app: 0|req: 2/3] 127.0.0.1 () {36 vars in 411 bytes} [Mon Jul 29 21:35:35 2024] GET /accounts/login/ => generated 15292 bytes in 114 msecs (HTTP/1.1 200) 11 headers in 525 bytes (1 switches on core 0)
464fb643184e 127.0.0.1 - - [29/Jul/2024:21:35:36 +0000] "GET /accounts/login/ HTTP/1.1" 200 15292 "healthcheck" "curl/7.76.1" "-"
464fb643184e [redacted-host] - - [29/Jul/2024:21:35:52 +0000] "MGLNDD_[redacted]_443" 400 157 "-" "-" "-"

This is the journal log:

Jul 29 20:46:21 istabl-antar02 systemd[1339]: Starting KIWI rootless pod (podman-compose)...
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]: Traceback (most recent call last):
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:   File "/usr/bin/podman-compose-3.12", line 33, in <module>
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:     sys.exit(load_entry_point('podman-compose==1.2.0', 'console_scripts', 'podman-compose')())
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:   File "/usr/lib/python3.12/site-packages/podman_compose.py", line 3503, in main
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:     asyncio.run(async_main())
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:   File "/usr/lib64/python3.12/asyncio/runners.py", line 194, in run
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:     return runner.run(main)
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:            ^^^^^^^^^^^^^^^^
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:   File "/usr/lib64/python3.12/asyncio/runners.py", line 118, in run
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:     return self._loop.run_until_complete(task)
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:   File "/usr/lib64/python3.12/asyncio/base_events.py", line 687, in run_until_complete
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:     return future.result()
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:            ^^^^^^^^^^^^^^^
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:   File "/usr/lib/python3.12/site-packages/podman_compose.py", line 3499, in async_main
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:     await podman_compose.run()
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:   File "/usr/lib/python3.12/site-packages/podman_compose.py", line 1740, in run
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:     self._parse_compose_file()
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:   File "/usr/lib/python3.12/site-packages/podman_compose.py", line 1882, in _parse_compose_file
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:     raise RuntimeError(f"Project name [{dir_basename}] normalized to empty")
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]: RuntimeError: Project name [kiwitcms] normalized to empty
Jul 29 20:46:21 istabl-antar02 podman[2482]: 2024-07-29 20:46:21.330735204 +0000 UTC m=+0.040582802 pod start 4bc1bf499e3ef68d85ee29e596d4a5050729cb471f3f39dcbb70547b1550fe87 (image=
, name=pod_KIWI)

[atodorov]

Description of problem

Running with podman-compose (python 3.11, and 3.12) results in few errors, resulting in high load on wsgi and decreased peformance

Can you be more specific here. How do you know what it is the wsgi process that spikes the CPU load?

I tried a podman-compose up with podman-5.1.2-1.fc40.x86_64, podman-compose-1.2.0-1.fc40.noarch, Python 3.12.4
and htop barely registers the containers.

Is this before initial_setup or after ?

Did you pull all images from docker.io or from other docker registries ?

as soon as I restart the containers, and after navigating to any of the pages:

Jul 29 21:35:36 istabl-antar02 kiwi_web[3053]: 127.0.0.1 - - [29/Jul/2024:21:35:36 +0000] "GET /accounts/login/ HTTP/1.1" 200 15292 "healthcheck" "curl/7.76.1" "-"


Jul 29 21:35:52 istabl-antar02 kiwi_web[3053]: [redacted] - - [29/Jul/2024:21:35:52 +0000] "MGLNDD_[redacted]_443" 400 157 "-" "-" "-"
Jul 29 21:36:04 istabl-antar02 systemd[1376]: [email protected]: State 'stop-sigterm' timed out. Killing.
Jul 29 21:36:04 istabl-antar02 systemd[1376]: [email protected]: Killing process 3053 (conmon) with signal SIGKILL.
Jul 29 21:36:04 istabl-antar02 systemd[1376]: [email protected]: Killing process 3148 (conmon) with signal SIGKILL.
Jul 29 21:36:04 istabl-antar02 systemd[1376]: [email protected]: Failed with result 'exit-code'.

1. vm has 2 cores & 2 gb of ram

Is there any difference if you bump ram and CPU? I would suspect that RAM is more important b/c it is I/O driven application but still 2 GB should be enough for a single instance.

464fb643184e [redacted-host] - - [29/Jul/2024:21:35:52 +0000] "MGLNDD_[redacted]_443" 400 157 "-" "-" "-"

Only this line is unfamiliar. What is this ? Is it some sort of external probe ?

This is the journal log:

Jul 29 20:46:21 istabl-antar02 systemd[1339]: Starting KIWI rootless pod (podman-compose)...
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]: Traceback (most recent call last):
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:   File "/usr/bin/podman-compose-3.12", line 33, in <module>
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:     sys.exit(load_entry_point('podman-compose==1.2.0', 'console_scripts', 'podman-compose')())
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:   File "/usr/lib/python3.12/site-packages/podman_compose.py", line 3503, in main
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:     asyncio.run(async_main())
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:   File "/usr/lib64/python3.12/asyncio/runners.py", line 194, in run
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:     return runner.run(main)
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:            ^^^^^^^^^^^^^^^^
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:   File "/usr/lib64/python3.12/asyncio/runners.py", line 118, in run
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:     return self._loop.run_until_complete(task)
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:   File "/usr/lib64/python3.12/asyncio/base_events.py", line 687, in run_until_complete
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:     return future.result()
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:            ^^^^^^^^^^^^^^^
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:   File "/usr/lib/python3.12/site-packages/podman_compose.py", line 3499, in async_main
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:     await podman_compose.run()
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:   File "/usr/lib/python3.12/site-packages/podman_compose.py", line 1740, in run
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:     self._parse_compose_file()
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:   File "/usr/lib/python3.12/site-packages/podman_compose.py", line 1882, in _parse_compose_file
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]:     raise RuntimeError(f"Project name [{dir_basename}] normalized to empty")
Jul 29 20:46:21 istabl-antar02 podman-compose-3.12[2474]: RuntimeError: Project name [kiwitcms] normalized to empty
Jul 29 20:46:21 istabl-antar02 podman[2482]: 2024-07-29 20:46:21.330735204 +0000 UTC m=+0.040582802 pod start 4bc1bf499e3ef68d85ee29e596d4a5050729cb471f3f39dcbb70547b1550fe87 (image=
, name=pod_KIWI)

I am not seeing anything like this in th ejournal log from podman. Could it be that you are using a buggy version ?