stalled transfers in container for 5 seconds

Question

stalled transfers in container for 5 seconds

ensc opened this issue 2 years ago · 0 comments

I have a rootless podman container which downloads files from the host over http. Forwarding data in the container seems to stall for 5 seconds. This seems to be caused in slirp4netns which shows a delay of 5 seconds between two write().

Logs:

client in container (wget http://192.168.3.24/data-64KiB shows a similar behavior):

11:41:20.080134 epoll_create(10)        = 3
11:41:20.080148 socket(AF_INET, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 4
11:41:20.080174 epoll_ctl(3, EPOLL_CTL_ADD, 4, {events=EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, data={u32=0, u64=0}}) = 0
11:41:20.080191 connect(4, {sa_family=AF_INET, sin_port=htons(1230), sin_addr=inet_addr("192.168.3.24")}, 16) = -1 EINPROGRESS (Operation now in progress)
11:41:20.080231 epoll_wait(3, [{events=EPOLLOUT, data={u32=0, u64=0}}], 1, -1) = 1
11:41:20.080843 write(4, "GET /data-64KiB HTTP/1.0\r\n\r\n", 28) = 28
11:41:20.080870 read(4, 0x7ffcc87bc7c0, 65536) = -1 EAGAIN (Resource temporarily unavailable)
11:41:20.080886 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=0, u64=0}}], 1, -1) = 1
11:41:20.081170 read(4, "HTTP/1.1 200 OK\r\nDate: Tue, 23 A"..., 65536) = 190
11:41:20.081208 read(4, 0x7ffcc87bc7c0, 65536) = -1 EAGAIN (Resource temporarily unavailable)
11:41:20.081235 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=0, u64=0}}], 1, -1) = 1
11:41:20.081276 read(4, "C\334\270\257\r\204z\26\355/\232'\35\25L\212\3\24+\353/\304\311/\361%\323\325y\262\324\227"..., 65536) = 32768
11:41:20.081307 read(4, 0x7ffcc87bc7c0, 65536) = -1 EAGAIN (Resource temporarily unavailable)
11:41:20.081323 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT, data={u32=0, u64=0}}], 1, -1) = 1
11:41:25.082545 read(4, "\344\217\vB\36H\277I\10[\256yD\363p*\233N\272\347\243\304v\27\312\235q^\v\262dY"..., 65536) = 32522
11:41:25.082757 read(4, 0x7ffcc87bc7c0, 65536) = -1 EAGAIN (Resource temporarily unavailable)
11:41:25.082860 epoll_wait(3, [{events=EPOLLIN|EPOLLOUT|EPOLLRDHUP, data={u32=0, u64=0}}], 1, -1) = 1
11:41:25.083189 read(4, "\4\337\266x\357\362&B\357YO\347\264LZ\266zQ\32\365b\206)\377\307~w\222\"\350\3470"..., 65536) = 246
11:41:25.083382 exit_group(0)           = ?

http server (/sbin/busybox httpd -p 1230 -f); runs on host

11:41:20.080960 read(0, "GET /data-64KiB HTTP/1.0\r\n\r\n", 1024) = 28
11:41:20.080981 write(2, "[::ffff:192.168.3.24]:33218: url"..., 45) = 45
11:41:20.080997 stat("data-64KiB", {st_mode=S_IFREG|0644, st_size=65536, ...}) = 0
11:41:20.081017 setitimer(ITIMER_REAL, {it_interval={tv_sec=0, tv_usec=0}, it_value={tv_sec=0, tv_usec=0}}, {it_interval={tv_sec=0, tv_usec=0}, it_value={tv_sec=59, tv_usec=999929}}) = 0
11:41:20.081031 open("data-64KiB", O_RDONLY|O_LARGEFILE) = 3
11:41:20.081049 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f2b51b3c2f8}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
11:41:20.081063 write(2, "[::ffff:192.168.3.24]:33218: res"..., 42) = 42
11:41:20.081094 write(1, "HTTP/1.1 200 OK\r\nDate: Tue, 23 A"..., 190) = 190
11:41:20.081120 sendfile(1, 3, [0] => [65536], 9223372036854710272) = 65536
11:41:20.081147 sendfile(1, 3, [65536], 9223372036854710271) = 0
11:41:20.081163 shutdown(1, SHUT_WR) = 0
11:41:20.081188 exit_group(0) = ?

slirp4netns (/usr/bin/slirp4netns --disable-host-loopback --mtu=65520 --enable-sandbox --enable-seccomp --enable-ipv6 -c -e 3 -r 4 6762 tap0)

11:41:18.319167 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 0 (Timeout)
11:41:18.819246 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 0 (Timeout)
11:41:19.319287 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 0 (Timeout)
11:41:19.819315 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 1 ([{fd=7, revents=POLLIN}])
11:41:20.080282 read(7, "RU\n\0\2\2\26\366\363\357%g\10\0E\0\0<\330\17@\0@\6\222\210\n\0\2d\300\250"..., 65536) = 74
11:41:20.080349 socket(AF_INET, SOCK_STREAM|SOCK_CLOEXEC, IPPROTO_IP) = 5
11:41:20.080379 fcntl(5, F_GETFL)       = 0x2 (flags O_RDWR)
11:41:20.080400 fcntl(5, F_SETFL, O_RDWR|O_NONBLOCK) = 0
11:41:20.080413 setsockopt(5, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
11:41:20.080443 setsockopt(5, SOL_SOCKET, SO_OOBINLINE, [1], 4) = 0
11:41:20.080458 setsockopt(5, SOL_TCP, TCP_NODELAY, [1], 4) = 0
11:41:20.080471 connect(5, {sa_family=AF_INET, sin_port=htons(1230), sin_addr=inet_addr("192.168.3.24")}, 16) = -1 EINPROGRESS (Operation now in progress)
11:41:20.080568 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLOUT|POLLERR}], 3, 499) = 1 ([{fd=5, revents=POLLOUT}])
11:41:20.080599 sendto(5, "", 0, 0, NULL, 0) = 0
11:41:20.080633 brk(0x55ab91975000)     = 0x55ab91975000
11:41:20.080728 brk(0x55ab919a5000)     = 0x55ab919a5000
11:41:20.080805 write(7, "\26\366\363\357%gRU\n\0\2\2\10\0E\0\0,\0N\0\0@\6\252Z\300\250\3\30\n\0"..., 58) = 58
11:41:20.080833 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 1 ([{fd=7, revents=POLLIN}])
11:41:20.080850 read(7, "RU\n\0\2\2\26\366\363\357%g\10\0E\0\0(\330\20@\0@\6\222\233\n\0\2d\300\250"..., 65536) = 54
11:41:20.080867 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 3, 499) = 1 ([{fd=7, revents=POLLIN}])
11:41:20.080882 read(7, "RU\n\0\2\2\26\366\363\357%g\10\0E\0\0D\330\21@\0@\6\222~\n\0\2d\300\250"..., 65536) = 82
11:41:20.080898 sendto(5, "GET /data-64KiB HTTP/1.0\r\n\r\n", 28, 0, NULL, 0) = 28
11:41:20.080928 write(7, "\26\366\363\357%gRU\n\0\2\2\10\0E\0\0(\0O\0\0@\6\252]\300\250\3\30\n\0"..., 54) = 54
11:41:20.080945 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 3, 499) = 1 ([{fd=5, revents=POLLIN}])
11:41:20.081121 recvfrom(5, "HTTP/1.1 200 OK\r\nDate: Tue, 23 A"..., 163840, 0, NULL, NULL) = 190
11:41:20.081142 write(7, "\26\366\363\357%gRU\n\0\2\2\10\0E\0\0\346\0P\0\0@\6\251\236\300\250\3\30\n\0"..., 244) = 244
11:41:20.081160 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 3, 499) = 2 ([{fd=7, revents=POLLIN}, {fd=5, revents=POLLIN}])
11:41:20.081175 read(7, "RU\n\0\2\2\26\366\363\357%g\10\0E\0\0(\330\22@\0@\6\222\231\n\0\2d\300\250"..., 65536) = 54
11:41:20.081193 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 3, 499) = 1 ([{fd=5, revents=POLLIN}])
11:41:20.081212 recvfrom(5, "C\334\270\257\r\204z\26\355/\232'\35\25L\212\3\24+\353/\304\311/\361%\323\325y\262\324\227"..., 163840, 0, NULL, NULL) = 65536
11:41:20.081248 write(7, "\26\366\363\357%gRU\n\0\2\2\10\0E\0\200(\0Q\0\0@\6*[\300\250\3\30\n\0"..., 32822) = 32822
11:41:20.081273 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 3, 499) = 2 ([{fd=7, revents=POLLIN}, {fd=5, revents=POLLIN}])
11:41:20.081288 read(7, "RU\n\0\2\2\26\366\363\357%g\10\0E\0\0(\330\23@\0@\6\222\230\n\0\2d\300\250"..., 65536) = 54
11:41:20.081302 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 3, 499) = 1 ([{fd=5, revents=POLLIN}])
11:41:20.081317 recvfrom(5, "", 130714, 0, NULL, NULL) = 0
11:41:20.081330 getpeername(5, {sa_family=AF_INET, sin_port=htons(1230), sin_addr=inet_addr("192.168.3.24")}, [128 => 16]) = 0
11:41:20.081345 getsockopt(5, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
11:41:20.081362 shutdown(5, SHUT_RD)    = 0
11:41:20.081373 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 0 (Timeout)
11:41:20.581297 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 0 (Timeout)
11:41:21.081316 close(4)                = 0
11:41:21.081713 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 0 (Timeout)
11:41:21.581701 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 0 (Timeout)
11:41:22.081783 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 0 (Timeout)
11:41:22.581860 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 0 (Timeout)
11:41:23.081878 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 0 (Timeout)
11:41:23.581920 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 0 (Timeout)
11:41:24.081995 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 0 (Timeout)
11:41:24.582047 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 0 (Timeout)
11:41:25.082016 write(7, "\26\366\363\357%gRU\n\0\2\2\10\0E\0\1772\0R\0\0@\6+P\300\250\3\30\n\0"..., 32576) = 32576
11:41:25.082281 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 1 ([{fd=7, revents=POLLIN}])
11:41:25.082463 read(7, "RU\n\0\2\2\26\366\363\357%g\10\0E\0\0(\330\24@\0@\6\222\227\n\0\2d\300\250"..., 65536) = 54
11:41:25.082719 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 1 ([{fd=7, revents=POLLIN}])
11:41:25.082867 read(7, "RU\n\0\2\2\26\366\363\357%g\10\0E\0\0(\330\25@\0@\6\222\226\n\0\2d\300\250"..., 65536) = 54
11:41:25.082979 write(7, "\26\366\363\357%gRU\n\0\2\2\10\0E\0\1\36\0S\0\0@\6\251c\300\250\3\30\n\0"..., 300) = 300
11:41:25.083122 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 1 ([{fd=7, revents=POLLIN}])
11:41:25.083955 read(7, "RU\n\0\2\2\26\366\363\357%g\10\0E\0\0(\330\26@\0@\6\222\225\n\0\2d\300\250"..., 65536) = 54
11:41:25.084072 shutdown(5, SHUT_WR)    = 0
11:41:25.084301 write(7, "\26\366\363\357%gRU\n\0\2\2\10\0E\0\0(\0T\0\0@\6\252X\300\250\3\30\n\0"..., 54) = 54
11:41:25.084485 poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}], 2, 499) = 0 (Timeout)

Environment:

Fedora 36
slirp4netns-1.2.0-0.2.beta.0.fc36.x86_64
podman-4.2.0-2.fc36.x86_64
kernel-5.18.18-200.fc36.x86_64