100% CPU on all instances when http-fast-listen is enabled

[cillianderoiste]

We've been troubled by an issue for the past few months where all instances on our machines get stuck at 100% CPU usage. A typical machine has 5 instances and zeo, 2 CPUs (2.4GHz) and 8G RAM. We could avoid the issue by stopping all instances and then starting each one slowly, waiting for the CPU load to go down before starting the next one. Restarting all instances via supervisor reliably reproduced the issue. As soon as one instance got into this state, starting or restarting additional instances would cause them to also use all available CPU. Today we tried adding http-fast-listen = off to the buildout configuration for the instances and now we can restart all instances without any problem.

While investigating the issue we noticed that having a high CPU load when starting the instances made matters worse. For example, by running dd if=/dev/zero of=/dev/null three times in parallel, we could trigger the issue by starting 3 instances at the same time, rather than 5. We have also had this issue on a machine which runs 5 instances, each in a separate docker container.

I attempted to use the plone docker image to make a reproducible test case, by restricting the available CPU for the container and then creating a high load (with dd, as above) before starting the instance, but it was more difficult than I had hoped.

[davisagli]

@cillianderoiste Try using py-spy's dump command to find out what the instances are doing when they are stuck.

[cillianderoiste]

Thanks, here's what I see:

Thread 1539468 (idle): "MainThread"
    handle_write_event (waitress/wasyncore.py:514)
    write (waitress/wasyncore.py:113)
    poll (waitress/wasyncore.py:189)
    loop (waitress/wasyncore.py:245)
    run (waitress/server.py:322)
    serve (waitress/__init__.py:19)
    serve_paste (plone/recipe/zope2instance/ctl.py:917)
    serve (plone/recipe/zope2instance/ctl.py:942)
    serve (Zope2/Startup/serve.py:203)
    run (Zope2/Startup/serve.py:217)
    main (Zope2/Startup/serve.py:251)
    <module> (Zope2/Startup/serve.py:255)
    <module> (interpreter:342)
Thread 1539618 (idle): "zeostorage zeo client networking thread"
    select (selectors.py:468)
    _run_once (asyncio/base_events.py:1823)
    run_forever (asyncio/base_events.py:570)
    run (ZEO/asyncio/client.py:892)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 1539787 (idle): "waitress-0"
    wait (threading.py:302)
    handler_thread (waitress/task.py:72)
    run (threading.py:870)
    run (sentry_sdk/integrations/threading.py:67)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 1539788 (idle): "waitress-1"
    wait (threading.py:302)
    handler_thread (waitress/task.py:72)
    run (threading.py:870)
    run (sentry_sdk/integrations/threading.py:67)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 1539789 (idle): "waitress-2"
    wait (threading.py:302)
    handler_thread (waitress/task.py:72)
    run (threading.py:870)
    run (sentry_sdk/integrations/threading.py:67)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 1539791 (idle): "waitress-3"
    wait (threading.py:302)
    handler_thread (waitress/task.py:72)
    run (threading.py:870)
    run (sentry_sdk/integrations/threading.py:67)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 1539806 (idle): "slowlog_monitor"
    wait (threading.py:302)
    get (queue.py:170)
    run (slowlog/monitor.py:85)
    run (sentry_sdk/integrations/threading.py:67)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)

We are using the latest version of waitress 2.1.2, this is where it seems to be stuck: https://github.com/Pylons/waitress/blob/v2.1.2/src/waitress/wasyncore.py#L514

[cillianderoiste]

I don't know how to debug this further, but I did notice that if I pin waitress to 2.0.0 I can still reproduce the issue, but with 1.4.4 I cannot.

[digitalresistor]

waitress.wasyncore is not public API.

[fredvd]

Not seen this issue at all with a few Plone 6.0.0.2 setups that are actively in use, but the setup is smaller and uses only one zeoclient / zeoserver. One of those sites runs on a server with 3 other active Plone sites. Default recipe settings for threads and http-fast-listen . Could hint on a race conditions with multiple zeoclients?

[yurj]

@tschorr

[tschorr]

@tschorr

I haven't used waitress for a while now. Maybe in addition to the py-spy dump you could try strace -p <pid> on one of the hanging processes to get more information on what's going on.

[tschorr]

and btw what is the output of ulimit -a?

[yurj]

@tschorr

I haven't used waitress for a while now. Maybe in addition to the py-spy dump you could try strace -p <pid> on one of the hanging processes to get more information on what's going on.

Pylons/waitress#396 (comment)

Here an analysis on the code.

[tschorr]

@yurj I have read it :-)

[petschki]

Coming from here I'm still fighting with this even when http-fast-listen is turned off. My strace ouput looks like this:

select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})
select(15, [12 13], [14], [12 13 14], {tv_sec=1, tv_usec=0}) = 1 (out [14], left {tv_sec=0, tv_usec=999999})

and runs forever.

ulimit output:

core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 256616
max locked memory       (kbytes, -l) 65536
max memory size         (kbytes, -m) unlimited
open files                      (-n) 1024
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) 256616
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited

would be glad for hints

[tschorr]

@petschki before anything else did you ever try increasing the allowed number of open files? Sockets are files and 1024 is not really a lot.
The strace dump seems to confirm it is stuck in waitress, because asyncio (ZEO ) is supposed to use poll. You could try and toggle waitresses asyncore_use_poll parameter and see if the strace dump switches to poll.

[jensens]

For buildout-less Plone 6, I factored out (some time ago) this code snippet to here https://github.com/plone/waitress_fastlisten/blob/main/waitress_fastlisten.py

Probably the same problem may pop up.