gvisor-tap-vsock icon indicating copy to clipboard operation
gvisor-tap-vsock copied to clipboard

100% CPU usage on macOS on sleep

Open steinybot opened this issue 1 month ago • 0 comments

Hi,

A few users of podman are experiencing an issue where gvproxy is consuming 100% CPU on one or more threads on macOS. This typically happens after sleep and may be related to network proxies or vpns. The issue was first raised here https://github.com/containers/podman/issues/27279.

What I was seeing is that after sleep I would unlock my MacBook and see that the CPU usage for gvproxy was up at 1200% percent. Image

Podman runs gvproxy with these arguments:

/opt/homebrew/Cellar/podman/5.6.2/libexec/podman/gvproxy -mtu 1500 -ssh-port 63695 -listen-vfkit unixgram:///var/folders/p1/tbxygbp918l6xpk3q9cx_9xm0000gp/T/podman/podman-machine-default-gvproxy.sock -forward-dest /run/podman/podman.sock -forward-user root -forward-identity /Users/jason.pickens/.local/share/containers/podman/machine/machine -forward-sock /var/folders/p1/tbxygbp918l6xpk3q9cx_9xm0000gp/T/podman/podman-machine-default-api.sock -pid-file /var/folders/p1/tbxygbp918l6xpk3q9cx_9xm0000gp/T/podman/gvproxy.pid -log-file /var/folders/p1/tbxygbp918l6xpk3q9cx_9xm0000gp/T/podman/gvproxy.log

I checked the log and it contained:

❯ less /var/folders/p1/tbxygbp918l6xpk3q9cx_9xm0000gp/T/podman/gvproxy.log
time="2025-12-03T10:45:52+13:00" level=info msg="gvproxy version v0.8.7"
time="2025-12-03T10:45:52+13:00" level=info msg="waiting for clients..."
time="2025-12-03T14:01:56+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 192.36.143.130:123: connect: network is unreachable\n"
time="2025-12-03T14:39:10+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 45.231.168.6:123: connect: network is unreachable\n"
time="2025-12-03T14:39:13+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 132.248.30.3:123: connect: network is unreachable\n"
time="2025-12-03T15:12:01+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 192.36.143.130:123: connect: network is unreachable\n"
time="2025-12-03T15:13:10+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 192.36.143.130:123: connect: network is unreachable\n"
time="2025-12-03T15:46:16+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 192.36.143.130:123: connect: network is unreachable\n"
time="2025-12-03T15:46:27+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 45.231.168.6:123: connect: network is unreachable\n"
time="2025-12-03T15:46:29+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 132.248.30.3:123: connect: network is unreachable\n"
time="2025-12-03T16:03:09+13:00" level=error msg="Can't proxy a datagram to udp: write udp 10.10.10.10:0->6.6.1.85:123: write: broken pipe\n"
time="2025-12-03T16:20:31+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 192.36.143.130:123: connect: network is unreachable\n"
time="2025-12-03T16:20:42+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 45.231.168.6:123: connect: network is unreachable\n"
time="2025-12-03T16:20:43+13:00" level=error msg="Can't proxy a datagram to udp: dial udp 132.248.30.3:123: connect: network is unreachable\n"
time="2025-12-03T18:13:38+13:00" level=error msg="Can't proxy a datagram to udp: write udp 10.10.10.10:54288->6.6.1.85:123: write: broken pipe\n"
time="2025-12-03T21:01:56+13:00" level=error msg="Can't proxy a datagram to udp: write udp 10.10.10.10:65025->6.6.1.85:123: write: broken pipe\n"

The log does not always contain this so these errors could be a red herring but they are likely related given that it is port 123.

I would then see multiple NTP connections for the gvproxy process that would never close. The number correlated to the number of threads stuck at 100%.

❯ lsof -p 51681 | grep ntp
gvproxy 51681 jason.pickens    8u     IPv4 0xa4e2cacb93e95b33      0t0                 UDP 10.10.10.10:58733->6.6.1.85:ntp
gvproxy 51681 jason.pickens   14u     IPv4 0x4cf04fffe9df7795      0t0                 UDP 10.10.10.10:63616->6.6.1.85:ntp
gvproxy 51681 jason.pickens   16u     IPv4 0xa4eb936652186552      0t0                 UDP 10.10.10.10:63070->6.6.1.85:ntp
gvproxy 51681 jason.pickens   17u     IPv4 0xd0e3ee15924321e5      0t0                 UDP 10.10.10.10:56963->6.6.1.85:ntp
gvproxy 51681 jason.pickens   19u     IPv4 0xb38d5af81d62af45      0t0                 UDP 10.10.10.10:56892->6.6.1.85:ntp
gvproxy 51681 jason.pickens   22u     IPv4 0xef4d7ec6694531db      0t0                 UDP 10.10.10.10:49352->6.6.1.85:ntp
gvproxy 51681 jason.pickens   25u     IPv4 0xbe76200e2d8dc14a      0t0                 UDP 10.10.10.10:49346->6.6.1.85:ntp
gvproxy 51681 jason.pickens   26u     IPv4 0xf7cd0c551a9ba292      0t0                 UDP 10.10.10.10:56741->6.6.1.85:ntp
gvproxy 51681 jason.pickens   27u     IPv4  0x86f9115ffd7bb48      0t0                 UDP 10.10.10.10:61083->6.6.1.85:ntp
gvproxy 51681 jason.pickens   28u     IPv4 0x7481d656ca8cb8a9      0t0                 UDP 10.10.10.10:52968->6.6.1.85:ntp
gvproxy 51681 jason.pickens   29u     IPv4 0xa4fe5ddfa423def2      0t0                 UDP 10.10.10.10:59627->6.6.1.85:ntp
gvproxy 51681 jason.pickens   30u     IPv4 0x1c9b8708b817e8d9      0t0                 UDP 10.10.10.10:53673->6.6.1.85:ntp
gvproxy 51681 jason.pickens   31u     IPv4 0x1a54d41666ab044a      0t0                 UDP 10.10.10.10:57939->6.6.1.85:ntp
gvproxy 51681 jason.pickens   32u     IPv4 0x437cebf62ab2f961      0t0                 UDP 10.10.10.10:65130->6.6.1.85:ntp
gvproxy 51681 jason.pickens   33u     IPv4  0xcea711337797a9a      0t0                 UDP 10.10.10.10:60839->6.6.1.85:ntp
gvproxy 51681 jason.pickens   35u     IPv4 0x91c3530bde6e5fc7      0t0                 UDP 10.10.10.10:58305->6.6.1.85:ntp

It seems that something related to the sleeps and/or proxies/vpns are disturbing the NTP association in such a way that cause gvproxy to get into a bad state and spin the thread.

steinybot avatar Dec 10 '25 21:12 steinybot