Skip to content

gVisor on GCP with gVNIC has long epoll_wait() delays when sending HTTP data #9816

New issue

Have a question about this project? # for a free GitHub account to open an issue and contact its maintainers and the community.

#

By clicking “#”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? # to your account

Jump to bottom
Closed
ekzhang opened this issue Dec 13, 2023 · 16 comments · Fixed by #9889
Closed

gVisor on GCP with gVNIC has long epoll_wait() delays when sending HTTP data #9816

ekzhang opened this issue Dec 13, 2023 · 16 comments · Fixed by #9889
Assignees
@manninglucas
Labels
area: networking Issue related to networking type: bug Something isn't working

Comments

@ekzhang
Copy link
Contributor

ekzhang commented Dec 13, 2023 •
edited
Loading

Description

gVisor containers have unusually slow outbound network performance on newer Google Compute Engine machines, taking an average of 40 seconds to send 10 MiB of data over an HTTP request. Usually it takes <1 second.

This only happens when using asynchronous-I/O user libraries (sendto and epoll_wait), and also only on GCP instances with gVNIC network drivers. When testing on Ubuntu 20.04 on GCP using the legacy VirtIO driver format, the issue does not happen.

It is also not reproducible when using synchronous I/O (write system call or curl command), or when running code outside of gVisor, or when running gVisor on AWS instances. From my tests the network delays only happen on the combination of:

  1. GCP instance with gVNIC drivers
  2. HTTP request from inside a gVisor container
  3. Using async I/O libraries in Python (delays with aiohttp / async httpx — but no delays with requests / urllib.request / sync httpx).

Steps to reproduce

We have been reproducing this by using a PUT request to a presigned PutObject URL to Google Cloud Storage.

First, create an instance in GCP Compute Engine. We can reproduce with a n2-standard-8 instance, with "gVNIC" NIC type in the advanced networking options. It is not reproducible with VirtIO NIC type. Set the boot disk to Ubuntu 20.04.

Create a Docker image with the following Dockerfile:

FROM python:3.11-slim-buster
RUN pip install aiohttp httpx
COPY main.py main.py

And for main.py, use this program (filling in url with some external URL that will take the request):

import asyncio
import time

from aiohttp import ClientSession

# We use a presigned URL to Google Cloud Storage to test, but we can also reproduce with AWS S3
# presigned URLs, as well as POST requests to public pastebins like https://paste.rs
#
# The delays do not happen with inbound HTTP traffic (GET requests) as far as we can tell.
url = "https://storage.googleapis.com/..."

async def main():
    s = time.monotonic()
    async with ClientSession() as session:
        await session.put(url, data="a" * (10 * 1024 * 1024))
    print(f"PUT 10MB time: {time.monotonic() - s:.2f} sec")


if __name__ == "__main__":
    asyncio.run(main())

Then use gVisor as a container runtime and run python main.py.

PUT 10MB time: 39.00 sec

With runc:

PUT 10MB time: 0.36 sec

When running the same file on the host directly (not inside a container runtime):

PUT 10MB time: 0.11 sec

runsc version

runsc version release-20231211.0
spec: 1.1.0-rc.1

docker version (if using docker)

24.0.7

uname

Linux eric-temp-testbed3-dec13 5.15.0-1047-gcp #55~20.04.1-Ubuntu SMP Wed Nov 15 11:38:25 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

kubectl (if using Kubernetes)

No response

repo state (if built from source)

No response

runsc debug logs (if available)

Relevant part of the debug logs, when running with strace, show 5-6 second gaps on some epoll_wait() system calls:

Debug logs with strace 

I1213 23:10:12.164929   19894 strace.go:564] [   1:   1] python E clock_gettime(0x1, 0x7ed943a3f290)
I1213 23:10:12.164966   19894 strace.go:602] [   1:   1] python X clock_gettime(0x1, 0x7ed943a3f290 {sec=0 nsec=603625005}) = 0 (0x0) (5.877µs)
I1213 23:10:12.165028   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x0)
I1213 23:10:12.165059   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x0) = 1 (0x1) (12.189µs)
I1213 23:10:12.165125   19894 strace.go:564] [   1:   1] python E clock_gettime(0x1, 0x7ed943a3f2c0)
I1213 23:10:12.165135   19894 strace.go:602] [   1:   1] python X clock_gettime(0x1, 0x7ed943a3f2c0 {sec=0 nsec=603802443}) = 0 (0x0) (1.059µs)
I1213 23:10:12.165222   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c200010, 0x903700, 0x0, null, 0x0)
I1213 23:10:12.165365   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c200010, 0x903700, 0x0, null, 0x0) = 164220 (0x2817c) (131.105µs)
I1213 23:10:12.165434   19894 strace.go:564] [   1:   1] python E clock_gettime(0x1, 0x7ed943a3f2c0)
I1213 23:10:12.165450   19894 strace.go:602] [   1:   1] python X clock_gettime(0x1, 0x7ed943a3f2c0 {sec=0 nsec=604115078}) = 0 (0x0) (2.753µs)
I1213 23:10:12.165513   19894 strace.go:564] [   1:   1] python E clock_gettime(0x1, 0x7ed943a3f290)
I1213 23:10:12.165521   19894 strace.go:602] [   1:   1] python X clock_gettime(0x1, 0x7ed943a3f290 {sec=0 nsec=604188624}) = 0 (0x0) (668ns)
I1213 23:10:12.165563   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x4956c)
I1213 23:10:12.561365   19894 calibrated_clock.go:74] CalibratedClock(Monotonic): ready
I1213 23:10:12.561429   19894 calibrated_clock.go:74] CalibratedClock(Realtime): ready
D1213 23:10:14.561480   19894 sampler.go:191] Time: Adjusting syscall overhead down to 875
D1213 23:10:14.561550   19894 sampler.go:191] Time: Adjusting syscall overhead down to 875
D1213 23:10:15.561935   19894 sampler.go:191] Time: Adjusting syscall overhead down to 766
D1213 23:10:15.561986   19894 sampler.go:191] Time: Adjusting syscall overhead down to 766
D1213 23:10:16.562149   19894 sampler.go:191] Time: Adjusting syscall overhead down to 671
D1213 23:10:20.562217   19894 sampler.go:191] Time: Adjusting syscall overhead down to 671
D1213 23:10:21.561904   19894 sampler.go:191] Time: Adjusting syscall overhead down to 588
D1213 23:10:22.561653   19894 sampler.go:191] Time: Adjusting syscall overhead down to 515
D1213 23:10:23.561829   19894 sampler.go:191] Time: Adjusting syscall overhead down to 451
D1213 23:10:24.561835   19894 sampler.go:191] Time: Adjusting syscall overhead down to 588
D1213 23:10:24.561893   19894 sampler.go:191] Time: Adjusting syscall overhead down to 395
I1213 23:10:25.757615   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x4956c) = 1 (0x1) (13.592023307s)
I1213 23:10:25.757798   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c22818c, 0x8db584, 0x0, null, 0x0)
I1213 23:10:25.758111   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c22818c, 0x8db584, 0x0, null, 0x0) = 586352 (0x8f270) (285.658µs)
I1213 23:10:25.758251   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46054)
I1213 23:10:25.758292   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46054) = 1 (0x1) (6.394µs)
I1213 23:10:25.758390   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c2b73fc, 0x84c314, 0x0, null, 0x0)
I1213 23:10:25.758445   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c2b73fc, 0x84c314, 0x0, null, 0x0) = 38640 (0x96f0) (38.06µs)
I1213 23:10:25.758518   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46053)
I1213 23:10:25.758540   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46053) = 1 (0x1) (5.28µs)
I1213 23:10:25.758599   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c2c0aec, 0x842c24, 0x0, null, 0x0)
I1213 23:10:25.758653   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c2c0aec, 0x842c24, 0x0, null, 0x0) = 34500 (0x86c4) (43.424µs)
I1213 23:10:25.758696   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46053)
I1213 23:10:25.758709   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46053) = 1 (0x1) (2.912µs)
I1213 23:10:25.758803   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c2c91b0, 0x83a560, 0x0, null, 0x0)
I1213 23:10:25.758843   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c2c91b0, 0x83a560, 0x0, null, 0x0) = 38640 (0x96f0) (25.363µs)
I1213 23:10:25.758903   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46053)
I1213 23:10:25.758924   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46053) = 1 (0x1) (3.463µs)
I1213 23:10:25.758977   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c2d28a0, 0x830e70, 0x0, null, 0x0)
I1213 23:10:25.759031   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c2d28a0, 0x830e70, 0x0, null, 0x0) = 37260 (0x918c) (40.853µs)
I1213 23:10:25.759077   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46053)
I1213 23:10:25.759088   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46053) = 1 (0x1) (1.54µs)
I1213 23:10:25.759117   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c2dba2c, 0x827ce4, 0x0, null, 0x0)
I1213 23:10:25.759138   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c2dba2c, 0x827ce4, 0x0, null, 0x0) = 1380 (0x564) (13.077µs)
I1213 23:10:25.759199   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46053)
I1213 23:10:25.759324   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46053) = 1 (0x1) (35.937µs)
I1213 23:10:25.759410   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c2dbf90, 0x827780, 0x0, null, 0x0)
I1213 23:10:25.759537   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c2dbf90, 0x827780, 0x0, null, 0x0) = 41400 (0xa1b8) (109.392µs)
I1213 23:10:25.759616   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46052)
I1213 23:10:25.759655   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46052) = 1 (0x1) (17.426µs)
I1213 23:10:25.759724   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c2e6148, 0x81d5c8, 0x0, null, 0x0)
I1213 23:10:25.759764   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c2e6148, 0x81d5c8, 0x0, null, 0x0) = 45540 (0xb1e4) (25.057µs)
I1213 23:10:25.759814   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46052)
I1213 23:10:25.763188   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46052) = 1 (0x1) (3.351292ms)
I1213 23:10:25.763312   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c2f132c, 0x8123e4, 0x0, null, 0x0)
I1213 23:10:25.763490   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c2f132c, 0x8123e4, 0x0, null, 0x0) = 565724 (0x8a1dc) (133.623µs)
I1213 23:10:25.763654   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x4604e)
I1213 23:10:25.763719   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x4604e) = 1 (0x1) (4.921µs)
I1213 23:10:25.763843   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c37b508, 0x788208, 0x0, null, 0x0)
I1213 23:10:25.763973   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c37b508, 0x788208, 0x0, null, 0x0) = 117300 (0x1ca34) (110.741µs)
I1213 23:10:25.764189   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x4604e)
I1213 23:10:25.764217   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x4604e) = 1 (0x1) (3.736µs)
I1213 23:10:25.764303   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c397f3c, 0x76b7d4, 0x0, null, 0x0)
I1213 23:10:25.764329   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c397f3c, 0x76b7d4, 0x0, null, 0x0) = 63480 (0xf7f8) (18.21µs)
I1213 23:10:25.764384   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x4604d)
I1213 23:10:25.769314   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x4604d) = 1 (0x1) (4.91386ms)
I1213 23:10:25.769417   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c3a7734, 0x75bfdc, 0x0, null, 0x0)
I1213 23:10:25.769617   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c3a7734, 0x75bfdc, 0x0, null, 0x0) = 540812 (0x8408c) (164.185µs)
I1213 23:10:25.769739   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46048)
I1213 23:10:25.769768   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46048) = 1 (0x1) (3.895µs)
I1213 23:10:25.769824   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c42b7c0, 0x6d7f50, 0x0, null, 0x0)
I1213 23:10:25.769859   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c42b7c0, 0x6d7f50, 0x0, null, 0x0) = 64860 (0xfd5c) (20.559µs)
I1213 23:10:25.769925   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46048)
I1213 23:10:25.769949   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46048) = 1 (0x1) (2.194µs)
I1213 23:10:25.770006   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c43b51c, 0x6c81f4, 0x0, null, 0x0)
I1213 23:10:25.770057   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c43b51c, 0x6c81f4, 0x0, null, 0x0) = 49680 (0xc210) (33.126µs)
I1213 23:10:25.770158   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46048)
I1213 23:10:25.770192   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46048) = 1 (0x1) (3.101µs)
I1213 23:10:25.770255   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c44772c, 0x6bbfe4, 0x0, null, 0x0)
I1213 23:10:25.770396   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c44772c, 0x6bbfe4, 0x0, null, 0x0) = 1380 (0x564) (124.045µs)
I1213 23:10:25.770467   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46047)
I1213 23:10:25.770483   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46047) = 1 (0x1) (3.694µs)
I1213 23:10:25.770579   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c447c90, 0x6bba80, 0x0, null, 0x0)
I1213 23:10:25.770622   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c447c90, 0x6bba80, 0x0, null, 0x0) = 51060 (0xc774) (27.475µs)
I1213 23:10:25.770661   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46047)
I1213 23:10:25.770672   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46047) = 1 (0x1) (1.931µs)
I1213 23:10:25.770694   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c454404, 0x6af30c, 0x0, null, 0x0)
I1213 23:10:25.770725   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c454404, 0x6af30c, 0x0, null, 0x0) = 52440 (0xccd8) (22.784µs)
I1213 23:10:25.770785   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46047)
I1213 23:10:25.773733   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46047) = 1 (0x1) (2.929232ms)
I1213 23:10:25.773850   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c4610dc, 0x6a2634, 0x0, null, 0x0)
I1213 23:10:25.774043   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c4610dc, 0x6a2634, 0x0, null, 0x0) = 557444 (0x88184) (144.158µs)
I1213 23:10:25.774140   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46044)
I1213 23:10:25.774170   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46044) = 1 (0x1) (4.586µs)
I1213 23:10:25.774226   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c4e9260, 0x61a4b0, 0x0, null, 0x0)
I1213 23:10:25.774263   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c4e9260, 0x61a4b0, 0x0, null, 0x0) = 67620 (0x10824) (28.161µs)
I1213 23:10:25.774326   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46044)
I1213 23:10:25.774343   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46044) = 1 (0x1) (2.239µs)
I1213 23:10:25.774391   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c4f9a84, 0x609c8c, 0x0, null, 0x0)
I1213 23:10:25.774425   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c4f9a84, 0x609c8c, 0x0, null, 0x0) = 67620 (0x10824) (24.838µs)
I1213 23:10:25.774498   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46043)
I1213 23:10:25.774522   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46043) = 1 (0x1) (3.857µs)
I1213 23:10:25.774617   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c50a2a8, 0x5f9468, 0x0, null, 0x0)
I1213 23:10:25.774671   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c50a2a8, 0x5f9468, 0x0, null, 0x0) = 1380 (0x564) (26.282µs)
I1213 23:10:25.774740   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x46043)
I1213 23:10:31.184335   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x46043) = 1 (0x1) (5.409564835s)
I1213 23:10:31.184559   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c50a80c, 0x5f8f04, 0x0, null, 0x0)
I1213 23:10:31.184733   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c50a80c, 0x5f8f04, 0x0, null, 0x0) = 573932 (0x8c1ec) (157.116µs)
I1213 23:10:31.184875   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x44b21)
I1213 23:10:31.184896   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x44b21) = 1 (0x1) (4.056µs)
I1213 23:10:31.184960   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c5969f8, 0x56cd18, 0x0, null, 0x0)
I1213 23:10:31.184990   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c5969f8, 0x56cd18, 0x0, null, 0x0) = 40020 (0x9c54) (21.611µs)
I1213 23:10:31.185039   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x44b21)
I1213 23:10:31.188321   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x44b21) = 1 (0x1) (3.261229ms)
I1213 23:10:31.188463   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c5a064c, 0x5630c4, 0x0, null, 0x0)
I1213 23:10:31.188650   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c5a064c, 0x5630c4, 0x0, null, 0x0) = 543644 (0x84b9c) (166.399µs)
I1213 23:10:31.188784   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x44b1d)
I1213 23:10:31.188818   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x44b1d) = 1 (0x1) (5.554µs)
I1213 23:10:31.188915   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c6251e8, 0x4de528, 0x0, null, 0x0)
I1213 23:10:31.188958   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c6251e8, 0x4de528, 0x0, null, 0x0) = 55200 (0xd7a0) (23.258µs)
I1213 23:10:31.189072   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x44b1d)
I1213 23:10:31.189114   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x44b1d) = 1 (0x1) (3.791µs)
I1213 23:10:31.189173   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c632988, 0x4d0d88, 0x0, null, 0x0)
I1213 23:10:31.189234   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c632988, 0x4d0d88, 0x0, null, 0x0) = 59340 (0xe7cc) (42.624µs)
I1213 23:10:31.189329   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x44b1d)
I1213 23:10:31.189346   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x44b1d) = 1 (0x1) (4.091µs)
I1213 23:10:31.189409   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c641154, 0x4c25bc, 0x0, null, 0x0)
I1213 23:10:31.189438   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c641154, 0x4c25bc, 0x0, null, 0x0) = 2760 (0xac8) (16.143µs)
I1213 23:10:31.189516   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x44b1c)
I1213 23:10:31.189543   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x44b1c) = 1 (0x1) (4.591µs)
I1213 23:10:31.189602   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c641c1c, 0x4c1af4, 0x0, null, 0x0)
I1213 23:10:31.189644   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c641c1c, 0x4c1af4, 0x0, null, 0x0) = 57960 (0xe268) (28.602µs)
I1213 23:10:31.189693   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x44b1c)
I1213 23:10:36.404302   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x44b1c) = 1 (0x1) (5.214580833s)
I1213 23:10:36.404569   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec95c64fe84, 0x4b388c, 0x0, null, 0x0)
I1213 23:10:36.404753   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec95c64fe84, 0x4b388c, 0x0, null, 0x0) = 527012 (0x80aa4) (161.363µs)
I1213 23:10:36.404894   19894 strace.go:561] [   1:   1] python E brk(0x559cdaa16000)
I1213 23:10:36.404937   19894 strace.go:599] [   1:   1] python X brk(0x559cdaa16000) = 94132171268096 (0x559cdaa16000) (7.55µs)
I1213 23:10:36.407575   19894 strace.go:564] [   1:   1] python E munmap(0x7ec95c200000, 0x904000)
I1213 23:10:36.407763   19894 strace.go:602] [   1:   1] python X munmap(0x7ec95c200000, 0x904000) = 0 (0x0) (153.571µs)
I1213 23:10:36.407945   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x436ba)
I1213 23:10:36.612075   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x436ba) = 1 (0x1) (204.086637ms)
I1213 23:10:36.612255   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cda5c22b0, 0x432de8, 0x0, null, 0x0)
I1213 23:10:36.612517   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cda5c22b0, 0x432de8, 0x0, null, 0x0) = 561584 (0x891b0) (230.843µs)
I1213 23:10:36.612627   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x435ed)
I1213 23:10:36.612658   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x435ed) = 1 (0x1) (6.118µs)
I1213 23:10:36.612696   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cda64b460, 0x3a9c38, 0x0, null, 0x0)
I1213 23:10:36.612727   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cda64b460, 0x3a9c38, 0x0, null, 0x0) = 37260 (0x918c) (22.272µs)
I1213 23:10:36.612757   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x435ed)
I1213 23:10:36.616372   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x435ed) = 1 (0x1) (3.59869ms)
I1213 23:10:36.616495   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cda6545ec, 0x3a0aac, 0x0, null, 0x0)
I1213 23:10:36.616653   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cda6545ec, 0x3a0aac, 0x0, null, 0x0) = 582212 (0x8e244) (139.297µs)
I1213 23:10:36.616727   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x435e9)
I1213 23:10:36.616745   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x435e9) = 1 (0x1) (3.012µs)
I1213 23:10:36.616771   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cda6e2830, 0x312868, 0x0, null, 0x0)
I1213 23:10:36.616797   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cda6e2830, 0x312868, 0x0, null, 0x0) = 53820 (0xd23c) (18.506µs)
I1213 23:10:36.616819   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x435e9)
I1213 23:10:36.619435   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x435e9) = 1 (0x1) (2.587351ms)
I1213 23:10:36.619552   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cda6efa6c, 0x30562c, 0x0, null, 0x0)
I1213 23:10:36.619706   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cda6efa6c, 0x30562c, 0x0, null, 0x0) = 546404 (0x85664) (139.328µs)
I1213 23:10:36.619791   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x435e6)
I1213 23:10:36.619813   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x435e6) = 1 (0x1) (4.003µs)
I1213 23:10:36.619861   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cda7750d0, 0x27ffc8, 0x0, null, 0x0)
I1213 23:10:36.619892   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cda7750d0, 0x27ffc8, 0x0, null, 0x0) = 69000 (0x10d88) (22.767µs)
I1213 23:10:36.619920   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x435e6)
D1213 23:10:41.561403   19894 sampler.go:191] Time: Adjusting syscall overhead down to 346
I1213 23:10:42.212876   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x435e6) = 1 (0x1) (5.592910751s)
I1213 23:10:42.213066   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cda785e58, 0x26f240, 0x0, null, 0x0)
I1213 23:10:42.213335   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cda785e58, 0x26f240, 0x0, null, 0x0) = 594632 (0x912c8) (226.963µs)
I1213 23:10:42.213432   19894 strace.go:561] [   1:   1] python E brk(0x559cdabf4000)
I1213 23:10:42.213454   19894 strace.go:599] [   1:   1] python X brk(0x559cdabf4000) = 94132173225984 (0x559cdabf4000) (5.715µs)
I1213 23:10:42.215072   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x4200b)
I1213 23:10:42.215129   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x4200b) = 1 (0x1) (7.475µs)
I1213 23:10:42.215218   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cda9f50b0, 0x1ddf78, 0x0, null, 0x0)
I1213 23:10:42.215327   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cda9f50b0, 0x1ddf78, 0x0, null, 0x0) = 325680 (0x4f830) (96.783µs)
I1213 23:10:42.215373   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x4200a)
I1213 23:10:42.215389   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x4200a) = 1 (0x1) (3.459µs)
I1213 23:10:42.215410   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cdaa448e0, 0x18e748, 0x0, null, 0x0)
I1213 23:10:42.215441   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cdaa448e0, 0x18e748, 0x0, null, 0x0) = 49680 (0xc210) (23.595µs)
I1213 23:10:42.215461   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x4200a)
I1213 23:10:42.215471   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x4200a) = 1 (0x1) (1.058µs)
I1213 23:10:42.215483   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cdaa50af0, 0x182538, 0x0, null, 0x0)
I1213 23:10:42.215495   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cdaa50af0, 0x182538, 0x0, null, 0x0) = 2760 (0xac8) (4.871µs)
I1213 23:10:42.215507   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x4200a)
I1213 23:10:42.215526   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x4200a) = 1 (0x1) (775ns)
I1213 23:10:42.215549   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cdaa515b8, 0x181a70, 0x0, null, 0x0)
I1213 23:10:42.215564   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cdaa515b8, 0x181a70, 0x0, null, 0x0) = 6824 (0x1aa8) (8.585µs)
I1213 23:10:42.215578   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x4200a)
I1213 23:10:42.218277   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x4200a) = 1 (0x1) (2.675702ms)
I1213 23:10:42.218446   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cdaa53060, 0x17ffc8, 0x0, null, 0x0)
I1213 23:10:42.218592   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cdaa53060, 0x17ffc8, 0x0, null, 0x0) = 534060 (0x8262c) (125.752µs)
I1213 23:10:42.218728   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x42008)
I1213 23:10:42.218768   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x42008) = 1 (0x1) (3.944µs)
I1213 23:10:42.218865   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cdaad568c, 0xfd99c, 0x0, null, 0x0)
I1213 23:10:42.218911   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cdaad568c, 0xfd99c, 0x0, null, 0x0) = 128340 (0x1f554) (30.209µs)
I1213 23:10:42.219201   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x42008)
I1213 23:10:42.219239   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x42008) = 1 (0x1) (7.796µs)
I1213 23:10:42.219314   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cda5c22b0, 0xde448, 0x0, null, 0x0)
I1213 23:10:42.219352   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cda5c22b0, 0xde448, 0x0, null, 0x0) = 68852 (0x10cf4) (27.847µs)
I1213 23:10:42.219438   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x42006)
I1213 23:10:42.219450   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x42006) = 1 (0x1) (2.062µs)
I1213 23:10:42.219479   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cda5d2fa4, 0xcd754, 0x0, null, 0x0)
I1213 23:10:42.219546   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cda5d2fa4, 0xcd754, 0x0, null, 0x0) = 16560 (0x40b0) (44.79µs)
I1213 23:10:42.219662   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x42006)
I1213 23:10:42.219697   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x42006) = 1 (0x1) (4.789µs)
I1213 23:10:42.219735   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cda5d7054, 0xc96a4, 0x0, null, 0x0)
I1213 23:10:42.219781   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cda5d7054, 0xc96a4, 0x0, null, 0x0) = 67620 (0x10824) (30.795µs)
I1213 23:10:42.219811   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x42006)
I1213 23:10:47.397385   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x42006) = 1 (0x1) (5.17754334s)
I1213 23:10:47.397563   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cda5e7878, 0xb8e80, 0x0, null, 0x0)
I1213 23:10:47.397756   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cda5e7878, 0xb8e80, 0x0, null, 0x0) = 524324 (0x80024) (160.173µs)
I1213 23:10:47.397897   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x40bcc)
I1213 23:10:50.831688   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLOUT data=[0x6, 0x0]}}, 0x2, 0x40bcc) = 1 (0x1) (3.433760727s)
I1213 23:10:50.831911   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x559cda6a0710, 0x38e5c, 0x0, null, 0x0)
I1213 23:10:50.832009   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x559cda6a0710, 0x38e5c, 0x0, null, 0x0) = 233052 (0x38e5c) (76.394µs)
I1213 23:10:50.832246   19894 strace.go:570] [   1:   1] python E epoll_ctl(0x3 anon_inode:[eventpoll], EPOLL_CTL_MOD, 0x6 socket:[9], 0x7ed943a3ef8c {events=EPOLLIN data=[0x6, 0x0]})
I1213 23:10:50.832270   19894 strace.go:608] [   1:   1] python X epoll_ctl(0x3 anon_inode:[eventpoll], EPOLL_CTL_MOD, 0x6 socket:[9], 0x7ed943a3ef8c {events=EPOLLIN data=[0x6, 0x0]}) = 0 (0x0) (5.536µs)
I1213 23:10:50.832380   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x3fe61)
I1213 23:10:51.058814   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {{events=EPOLLIN data=[0x6, 0x0]}}, 0x2, 0x3fe61) = 1 (0x1) (226.400769ms)
I1213 23:10:51.059026   19894 strace.go:576] [   1:   1] python E recvfrom(0x6 socket:[9], 0x7ec9600a5010, 0x40000, 0x0, 0x0, null)
I1213 23:10:51.059068   19894 strace.go:614] [   1:   1] python X recvfrom(0x6 socket:[9], 0x7ec9600a5010, 0x40000, 0x0, null, null) = 539 (0x21b) (20.974µs)
I1213 23:10:51.059437   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x0)
I1213 23:10:51.059459   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec9601075d0 {}, 0x2, 0x0) = 0 (0x0) (2.801µs)
I1213 23:10:51.059946   19894 strace.go:564] [   1:   1] python E munmap(0x7ec960200000, 0xa01000)
I1213 23:10:51.060065   19894 strace.go:602] [   1:   1] python X munmap(0x7ec960200000, 0xa01000) = 0 (0x0) (101.137µs)
I1213 23:10:51.060156   19894 strace.go:564] [   1:   1] python E munmap(0x7ec95f600000, 0xa01000)
I1213 23:10:51.060424   19894 strace.go:602] [   1:   1] python X munmap(0x7ec95f600000, 0xa01000) = 0 (0x0) (236.77µs)
I1213 23:10:51.060838   19894 strace.go:576] [   1:   1] python E sendto(0x6 socket:[9], 0x7ec960d691d0, 0x18, 0x0, null, 0x0)
I1213 23:10:51.060980   19894 strace.go:614] [   1:   1] python X sendto(0x6 socket:[9], 0x7ec960d691d0, 0x18, 0x0, null, 0x0) = 24 (0x18) (91.553µs)
I1213 23:10:51.061110   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec960d40710 {}, 0x2, 0x0)
I1213 23:10:51.061127   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec960d40710 {}, 0x2, 0x0) = 0 (0x0) (1.142µs)
D1213 23:10:51.061234   19894 usertrap_amd64.go:212] [   1:   1] Found the pattern at ip 7ec96277c4a0:sysno 1
D1213 23:10:51.061246   19894 usertrap_amd64.go:122] [   1:   1] Allocate a new trap: 0xc000152360 67
D1213 23:10:51.061258   19894 usertrap_amd64.go:225] [   1:   1] Apply the binary patch addr 7ec96277c4a0 trap addr 654f0 ([184 1 0 0 0 15 5] -> [255 36 37 240 84 6 0])
I1213 23:10:51.061294   19894 strace.go:567] [   1:   1] python E write(0x1 host:[2], 0x7ec960d12710 "PUT 10MB time: 39.00 sec", 0x18)
I1213 23:10:51.061331   19894 strace.go:605] [   1:   1] python X write(0x1 host:[2], ..., 0x18) = 24 (0x18) (27.83µs)
I1213 23:10:51.061382   19894 strace.go:567] [   1:   1] python E write(0x1 host:[2], 0x7ec9625274d0 "\n", 0x1)
I1213 23:10:51.061412   19894 strace.go:605] [   1:   1] python X write(0x1 host:[2], ..., 0x1) = 1 (0x1) (13.265µs)
I1213 23:10:51.061482   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec960d40410 {}, 0x2, 0x0)
I1213 23:10:51.061520   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec960d40410 {{events=EPOLLIN data=[0x6, 0x0]}}, 0x2, 0x0) = 1 (0x1) (7.134µs)
I1213 23:10:51.061623   19894 strace.go:576] [   1:   1] python E recvfrom(0x6 socket:[9], 0x7ec9600a5010, 0x40000, 0x0, 0x0, null)
I1213 23:10:51.061657   19894 strace.go:614] [   1:   1] python X recvfrom(0x6 socket:[9], 0x7ec9600a5010, 0x40000, 0x0, null, null) = 0 (0x0) (4.626µs)
I1213 23:10:51.061765   19894 strace.go:570] [   1:   1] python E epoll_ctl(0x3 anon_inode:[eventpoll], EPOLL_CTL_DEL, 0x6 socket:[9], 0x7ed943a3efac {events=EPOLLIN|EPOLLERR|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRBAND|EPOLLMSG|EPOLLRDHUP|0x5800 data=[0x2c49f5b8, 0x0]})
I1213 23:10:51.061784   19894 strace.go:608] [   1:   1] python X epoll_ctl(0x3 anon_inode:[eventpoll], EPOLL_CTL_DEL, 0x6 socket:[9], 0x7ed943a3efac {events=EPOLLIN|EPOLLERR|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRBAND|EPOLLMSG|EPOLLRDHUP|0x5800 data=[0x2c49f5b8, 0x0]}) = 0 (0x0) (5.423µs)
I1213 23:10:51.061843   19894 strace.go:559] [   1:   1] python E getpid()
I1213 23:10:51.061856   19894 strace.go:596] [   1:   1] python X getpid() = 1 (0x1) (992ns)
I1213 23:10:51.062031   19894 strace.go:570] [   1:   1] python E rt_sigaction(SIGINT, 0x7ed943a3f040 {Handler: 0x7ec9621e3ad1, Flags: SA_RESTORER|SA_ONSTACK, Restorer: 0x7ec96277d730, Mask: []}, 0x7ed943a3f0e0, 0x8)
I1213 23:10:51.062048   19894 strace.go:608] [   1:   1] python X rt_sigaction(SIGINT, 0x7ed943a3f040 {Handler: 0x7ec9621e3ad1, Flags: SA_RESTORER|SA_ONSTACK, Restorer: 0x7ec96277d730, Mask: []}, 0x7ed943a3f0e0 {Handler: 0x7ec9621e3ad1, Flags: SA_RESTORER|SA_ONSTACK, Restorer: 0x7ec96277d730, Mask: []}, 0x8) = 0 (0x0) (3.577µs)
I1213 23:10:51.062186   19894 strace.go:559] [   1:   1] python E getpid()
I1213 23:10:51.062196   19894 strace.go:596] [   1:   1] python X getpid() = 1 (0x1) (577ns)
I1213 23:10:51.062226   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec961dc4f80 {}, 0x1, 0x0)
I1213 23:10:51.062240   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec961dc4f80 {}, 0x1, 0x0) = 0 (0x0) (1.214µs)
I1213 23:10:51.062358   19894 strace.go:561] [   1:   1] python E close(0x6 socket:[9])
I1213 23:10:51.062403   19894 strace.go:599] [   1:   1] python X close(0x6 socket:[9]) = 0 (0x0) (37.383µs)
I1213 23:10:51.062459   19894 strace.go:564] [   1:   1] python E munmap(0x7ec9600a5000, 0x41000)
I1213 23:10:51.062546   19894 strace.go:602] [   1:   1] python X munmap(0x7ec9600a5000, 0x41000) = 0 (0x0) (75.52µs)
I1213 23:10:51.063839   19894 strace.go:564] [   1:   1] python E munmap(0x7ec95d800000, 0xa34000)
I1213 23:10:51.064042   19894 strace.go:602] [   1:   1] python X munmap(0x7ec95d800000, 0xa34000) = 0 (0x0) (180.844µs)
I1213 23:10:51.064228   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec961dc4f80 {}, 0x1, 0x0)
I1213 23:10:51.064253   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec961dc4f80 {}, 0x1, 0x0) = 0 (0x0) (1.899µs)
I1213 23:10:51.064348   19894 strace.go:559] [   1:   1] python E getpid()
I1213 23:10:51.064357   19894 strace.go:596] [   1:   1] python X getpid() = 1 (0x1) (548ns)
I1213 23:10:51.064415   19894 strace.go:559] [   1:   1] python E getpid()
I1213 23:10:51.064421   19894 strace.go:596] [   1:   1] python X getpid() = 1 (0x1) (212ns)
I1213 23:10:51.064434   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec961dc4f70 {}, 0x1, 0x0)
I1213 23:10:51.064441   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec961dc4f70 {}, 0x1, 0x0) = 0 (0x0) (502ns)
I1213 23:10:51.064520   19894 strace.go:559] [   1:   1] python E gettid()
I1213 23:10:51.064528   19894 strace.go:596] [   1:   1] python X gettid() = 1 (0x1) (1.206µs)
I1213 23:10:51.064620   19894 strace.go:576] [   1:   1] python E mmap(0x0, 0x801000, 0x0, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, 0xffffffffffffffff (bad FD), 0x0)
I1213 23:10:51.064635   19894 strace.go:614] [   1:   1] python X mmap(0x0, 0x801000, 0x0, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, 0xffffffffffffffff (bad FD), 0x0) = 139403368333312 (0x7ec960400000) (6.222µs)
I1213 23:10:51.064661   19894 strace.go:567] [   1:   1] python E mprotect(0x7ec960401000, 0x800000, 0x3)
I1213 23:10:51.064671   19894 strace.go:605] [   1:   1] python X mprotect(0x7ec960401000, 0x800000, 0x3) = 0 (0x0) (3.262µs)
I1213 23:10:51.065312   19894 strace.go:573] [   1:   1] python E clone(CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, 0x7ec960bfffb0, 0x7ec960c009d0, 0x7ec960c009d0, 0x7ec960c00700)
I1213 23:10:51.065395   19894 strace.go:611] [   1:   1] python X clone(CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, 0x7ec960bfffb0, 0x7ec960c009d0, 0x7ec960c009d0, 0x7ec960c00700) = 3 (0x3) (64.716µs)
I1213 23:10:51.065428   19894 strace.go:576] [   1:   1] python E futex(0x559cda5b7100, FUTEX_WAIT_BITSET|FUTEX_CLOCK_REALTIME|FUTEX_PRIVATE_FLAG, 0x0, null, 0x0, 0xffffffff)
I1213 23:10:51.065458   19894 strace.go:564] [   1:   3] python E set_robust_list(0x7ec960c009e0, 0x18)
I1213 23:10:51.065490   19894 strace.go:602] [   1:   3] python X set_robust_list(0x7ec960c009e0, 0x18) = 0 (0x0) (1.503µs)
I1213 23:10:51.065521   19894 strace.go:576] [   1:   3] python E mmap(0x0, 0x8000000, 0x0, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, 0xffffffffffffffff (bad FD), 0x0)
I1213 23:10:51.065535   19894 strace.go:614] [   1:   3] python X mmap(0x0, 0x8000000, 0x0, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, 0xffffffffffffffff (bad FD), 0x0) = 139403095703552 (0x7ec950000000) (5.788µs)
I1213 23:10:51.065545   19894 strace.go:564] [   1:   3] python E munmap(0x7ec954000000, 0x4000000)
I1213 23:10:51.065553   19894 strace.go:602] [   1:   3] python X munmap(0x7ec954000000, 0x4000000) = 0 (0x0) (2.284µs)
I1213 23:10:51.065560   19894 strace.go:567] [   1:   3] python E mprotect(0x7ec950000000, 0x21000, 0x3)
I1213 23:10:51.065568   19894 strace.go:605] [   1:   3] python X mprotect(0x7ec950000000, 0x21000, 0x3) = 0 (0x0) (1.775µs)
I1213 23:10:51.066166   19894 strace.go:559] [   1:   3] python E gettid()
I1213 23:10:51.066182   19894 strace.go:596] [   1:   3] python X gettid() = 3 (0x3) (1.46µs)
I1213 23:10:51.066219   19894 strace.go:576] [   1:   3] python E mmap(0x0, 0x4000, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, 0xffffffffffffffff (bad FD), 0x0)
I1213 23:10:51.066275   19894 strace.go:614] [   1:   3] python X mmap(0x0, 0x4000, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, 0xffffffffffffffff (bad FD), 0x0) = 139403376807936 (0x7ec960c15000) (47.078µs)
I1213 23:10:51.066317   19894 strace.go:559] [   1:   3] python E gettid()
I1213 23:10:51.066324   19894 strace.go:596] [   1:   3] python X gettid() = 3 (0x3) (357ns)
I1213 23:10:51.066339   19894 strace.go:576] [   1:   3] python E futex(0x559cda5b7100, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x7ec960d12a40, 0x7ec960c15278)
I1213 23:10:51.066353   19894 strace.go:614] [   1:   3] python X futex(0x559cda5b7100, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x7ec960d12a40, 0x7ec960c15278) = 1 (0x1) (6.795µs)
I1213 23:10:51.066383   19894 strace.go:614] [   1:   1] python X futex(0x559cda5b7100, FUTEX_WAIT_BITSET|FUTEX_CLOCK_REALTIME|FUTEX_PRIVATE_FLAG, 0x0, null, 0x0, 0xffffffff) = 0 (0x0) (942.572µs)
I1213 23:10:51.066407   19894 strace.go:576] [   1:   1] python E futex(0x7ec9625250f0, FUTEX_WAIT|FUTEX_PRIVATE_FLAG, 0x0, 0x7ed943a3eb10 {sec=0 nsec=4999580}, 0x0, 0x50)
I1213 23:10:51.066421   19894 strace.go:576] [   1:   3] python E futex(0x559cda57a930, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x7ec960d56700, 0x7ec960d40390)
I1213 23:10:51.066430   19894 strace.go:614] [   1:   3] python X futex(0x559cda57a930, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x7ec960d56700, 0x7ec960d40390) = 1 (0x1) (1.806µs)
I1213 23:10:51.066444   19894 strace.go:614] [   1:   2] python X futex(0x559cda57a930, FUTEX_WAIT_BITSET|FUTEX_CLOCK_REALTIME|FUTEX_PRIVATE_FLAG, 0x0, null, 0x0, 0xffffffff) = 0 (0x0) (38.969100377s)
I1213 23:10:51.066460   19894 strace.go:576] [   1:   3] python E futex(0x7ec9625250f0, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x7ec9625250e8, 0x7ec9625250c8)
I1213 23:10:51.066469   19894 strace.go:576] [   1:   2] python E futex(0x7ec9625250f8, FUTEX_WAIT|FUTEX_PRIVATE_FLAG, 0x2, null, 0x7ec9625250f8, 0xffffffff)
I1213 23:10:51.066480   19894 strace.go:614] [   1:   3] python X futex(0x7ec9625250f0, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x7ec9625250e8, 0x7ec9625250c8) = 1 (0x1) (1.716µs)
I1213 23:10:51.066497   19894 strace.go:614] [   1:   1] python X futex(0x7ec9625250f0, FUTEX_WAIT|FUTEX_PRIVATE_FLAG, 0x0, 0x7ed943a3eb10 {sec=0 nsec=4999580}, 0x0, 0x50) = 0 (0x0) (82.16µs)
I1213 23:10:51.066511   19894 strace.go:576] [   1:   1] python E futex(0x7ec9625250f8, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x0, 0x50)
I1213 23:10:51.066518   19894 strace.go:614] [   1:   1] python X futex(0x7ec9625250f8, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x0, 0x50) = 1 (0x1) (687ns)
I1213 23:10:51.066525   19894 strace.go:614] [   1:   2] python X futex(0x7ec9625250f8, FUTEX_WAIT|FUTEX_PRIVATE_FLAG, 0x2, null, 0x7ec9625250f8, 0xffffffff) = 0 (0x0) (45.799µs)
I1213 23:10:51.066512   19894 strace.go:576] [   1:   3] python E futex(0x7ec9625250f8, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x0, 0x7ec9625250c8)
I1213 23:10:51.066546   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec961dc4f70 {}, 0x1, 0xffffffff)
I1213 23:10:51.066554   19894 strace.go:614] [   1:   3] python X futex(0x7ec9625250f8, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x0, 0x7ec9625250c8) = 0 (0x0) (2.637µs)
I1213 23:10:51.066564   19894 strace.go:576] [   1:   2] python E futex(0x7ec9625250f8, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x0, 0xffffffff)
I1213 23:10:51.066576   19894 strace.go:614] [   1:   2] python X futex(0x7ec9625250f8, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x0, 0xffffffff) = 0 (0x0) (499ns)
I1213 23:10:51.066584   19894 strace.go:576] [   1:   3] python E futex(0x7ec958000b20, FUTEX_WAIT_BITSET|FUTEX_CLOCK_REALTIME|FUTEX_PRIVATE_FLAG, 0x0, null, 0x0, 0xffffffff)
I1213 23:10:51.066617   19894 strace.go:576] [   1:   2] python E futex(0x7ec958000b20, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x7ec9622d79a0, 0x6)
I1213 23:10:51.066636   19894 strace.go:614] [   1:   2] python X futex(0x7ec958000b20, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x7ec9622d79a0, 0x6) = 1 (0x1) (6.255µs)
I1213 23:10:51.066655   19894 strace.go:614] [   1:   3] python X futex(0x7ec958000b20, FUTEX_WAIT_BITSET|FUTEX_CLOCK_REALTIME|FUTEX_PRIVATE_FLAG, 0x0, null, 0x0, 0xffffffff) = 0 (0x0) (56.796µs)
I1213 23:10:51.066743   19894 strace.go:576] [   1:   3] python E futex(0x7ec9625250f4, FUTEX_WAIT|FUTEX_PRIVATE_FLAG, 0x0, 0x7ec960bff730 {sec=0 nsec=4999776}, 0x0, 0x50)
I1213 23:10:51.066761   19894 strace.go:564] [   1:   2] python E munmap(0x7ec962591000, 0x4000)
I1213 23:10:51.066807   19894 strace.go:602] [   1:   2] python X munmap(0x7ec962591000, 0x4000) = 0 (0x0) (37.294µs)
I1213 23:10:51.066837   19894 strace.go:576] [   1:   2] python E futex(0x7ec9625250f4, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x7ec9625250e8, 0x7ec9625250c8)
I1213 23:10:51.066849   19894 strace.go:614] [   1:   2] python X futex(0x7ec9625250f4, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x7ec9625250e8, 0x7ec9625250c8) = 1 (0x1) (889ns)
I1213 23:10:51.066858   19894 strace.go:614] [   1:   3] python X futex(0x7ec9625250f4, FUTEX_WAIT|FUTEX_PRIVATE_FLAG, 0x0, 0x7ec960bff730 {sec=0 nsec=4999776}, 0x0, 0x50) = 0 (0x0) (103.392µs)
I1213 23:10:51.066895   19894 strace.go:576] [   1:   3] python E futex(0x7ec9625250f8, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x0, 0x50)
I1213 23:10:51.066908   19894 strace.go:614] [   1:   3] python X futex(0x7ec9625250f8, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x0, 0x50) = 0 (0x0) (482ns)
D1213 23:10:51.066891   19894 usertrap_amd64.go:212] [   1:   2] Found the pattern at ip 7ec961f33e70:sysno 28
D1213 23:10:51.066925   19894 usertrap_amd64.go:122] [   1:   2] Allocate a new trap: 0xc000152360 68
D1213 23:10:51.066957   19894 usertrap_amd64.go:225] [   1:   2] Apply the binary patch addr 7ec961f33e70 trap addr 65540 ([184 28 0 0 0 15 5] -> [255 36 37 64 85 6 0])
I1213 23:10:51.066975   19894 strace.go:576] [   1:   3] python E sendto(0x5 socket:[2], 0x7ec961340200, 0x1, 0x0, null, 0x0)
I1213 23:10:51.067023   19894 strace.go:614] [   1:   3] python X sendto(0x5 socket:[2], 0x7ec961340200, 0x1, 0x0, null, 0x0) = 1 (0x1) (28.607µs)
I1213 23:10:51.067050   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec961dc4f70 {{events=EPOLLIN data=[0x4, 0x0]}}, 0x1, 0xffffffff) = 1 (0x1) (488.748µs)
I1213 23:10:51.066977   19894 strace.go:567] [   1:   2] python E madvise(0x7ec95ec00000, 0x7fb000, 0x4)
I1213 23:10:51.067086   19894 strace.go:564] [   1:   3] python E munmap(0x7ec960c15000, 0x4000)
I1213 23:10:51.067182   19894 strace.go:605] [   1:   2] python X madvise(0x7ec95ec00000, 0x7fb000, 0x4) = 0 (0x0) (110.179µs)
I1213 23:10:51.067229   19894 strace.go:576] [   1:   1] python E futex(0x7ec9625250f0, FUTEX_WAIT|FUTEX_PRIVATE_FLAG, 0x0, 0x7ed943a3ef50 {sec=0 nsec=4999585}, 0x0, 0x50)
I1213 23:10:51.067257   19894 strace.go:561] [   1:   2] python E exit(0x0)
I1213 23:10:51.067285   19894 strace.go:599] [   1:   2] python X exit(0x0) = 0 (0x0) (2.445µs)
D1213 23:10:51.067296   19894 task_exit.go:204] [   1:   2] Transitioning from exit state TaskExitNone to TaskExitInitiated
I1213 23:10:51.067367   19894 strace.go:602] [   1:   3] python X munmap(0x7ec960c15000, 0x4000) = 0 (0x0) (265.323µs)
D1213 23:10:51.067402   19894 task_exit.go:204] [   1:   2] Transitioning from exit state TaskExitInitiated to TaskExitZombie
D1213 23:10:51.067415   19894 task_exit.go:204] [   1:   2] Transitioning from exit state TaskExitZombie to TaskExitDead
I1213 23:10:51.067421   19894 strace.go:576] [   1:   3] python E futex(0x7ec9625250f0, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x7ec9625250e8, 0x7ec9625250c8)
I1213 23:10:51.067442   19894 strace.go:614] [   1:   3] python X futex(0x7ec9625250f0, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x7ec9625250e8, 0x7ec9625250c8) = 1 (0x1) (1.43µs)
I1213 23:10:51.067458   19894 strace.go:614] [   1:   1] python X futex(0x7ec9625250f0, FUTEX_WAIT|FUTEX_PRIVATE_FLAG, 0x0, 0x7ed943a3ef50 {sec=0 nsec=4999585}, 0x0, 0x50) = 0 (0x0) (206.989µs)
I1213 23:10:51.067497   19894 strace.go:576] [   1:   1] python E futex(0x7ec9625250f8, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x0, 0x50)
I1213 23:10:51.067505   19894 strace.go:614] [   1:   1] python X futex(0x7ec9625250f8, FUTEX_WAKE|FUTEX_PRIVATE_FLAG, 0x1, null, 0x0, 0x50) = 0 (0x0) (370ns)
I1213 23:10:51.067513   19894 strace.go:567] [   1:   3] python E madvise(0x7ec960400000, 0x7fb000, 0x4)
I1213 23:10:51.067594   19894 strace.go:576] [   1:   1] python E recvfrom(0x4 socket:[1], 0x559cda586f70, 0x1000, 0x0, 0x0, null)
I1213 23:10:51.067638   19894 strace.go:614] [   1:   1] python X recvfrom(0x4 socket:[1], 0x559cda586f70, 0x1000, 0x0, null, null) = 1 (0x1) (18.665µs)
I1213 23:10:51.067606   19894 strace.go:605] [   1:   3] python X madvise(0x7ec960400000, 0x7fb000, 0x4) = 0 (0x0) (85.195µs)
I1213 23:10:51.067702   19894 strace.go:576] [   1:   1] python E recvfrom(0x4 socket:[1], 0x559cda586fa0, 0x1000, 0x0, 0x0, null)
I1213 23:10:51.067745   19894 strace.go:614] [   1:   1] python X recvfrom(0x4 socket:[1], 0x559cda586fa0, 0x1000, 0x0, 0x0, null) = 0 (0x0) errno=11 (request would block) (9.303µs)
I1213 23:10:51.067715   19894 strace.go:561] [   1:   3] python E exit(0x0)
I1213 23:10:51.067772   19894 strace.go:599] [   1:   3] python X exit(0x0) = 0 (0x0) (1.397µs)
D1213 23:10:51.067782   19894 task_exit.go:204] [   1:   3] Transitioning from exit state TaskExitNone to TaskExitInitiated
D1213 23:10:51.067799   19894 task_exit.go:204] [   1:   3] Transitioning from exit state TaskExitInitiated to TaskExitZombie
D1213 23:10:51.067804   19894 task_exit.go:204] [   1:   3] Transitioning from exit state TaskExitZombie to TaskExitDead
I1213 23:10:51.067822   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec961dc4fc0 {}, 0x1, 0x0)
I1213 23:10:51.067844   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec961dc4fc0 {}, 0x1, 0x0) = 0 (0x0) (3.031µs)
I1213 23:10:51.067957   19894 strace.go:570] [   1:   1] python E epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec961dc4fc0 {}, 0x1, 0x0)
I1213 23:10:51.067968   19894 strace.go:608] [   1:   1] python X epoll_wait(0x3 anon_inode:[eventpoll], 0x7ec961dc4fc0 {}, 0x1, 0x0) = 0 (0x0) (795ns)
I1213 23:10:51.068026   19894 strace.go:559] [   1:   1] python E getpid()
I1213 23:10:51.068038   19894 strace.go:596] [   1:   1] python X getpid() = 1 (0x1) (765ns)
I1213 23:10:51.068132   19894 strace.go:570] [   1:   1] python E epoll_ctl(0x3 anon_inode:[eventpoll], EPOLL_CTL_DEL, 0x4 socket:[1], 0x7ed943a3f05c {events=EPOLLIN|EPOLLERR|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRBAND|EPOLLMSG|EPOLLRDHUP|0x5800 data=[0x2c49f5b8, 0x0]})
I1213 23:10:51.068154   19894 strace.go:608] [   1:   1] python X epoll_ctl(0x3 anon_inode:[eventpoll], EPOLL_CTL_DEL, 0x4 socket:[1], 0x7ed943a3f05c {events=EPOLLIN|EPOLLERR|EPOLLRDNORM|EPOLLRDBAND|EPOLLWRBAND|EPOLLMSG|EPOLLRDHUP|0x5800 data=[0x2c49f5b8, 0x0]}) = 0 (0x0) (5.363µs)
I1213 23:10:51.068209   19894 strace.go:561] [   1:   1] python E close(0x4 socket:[1])
I1213 23:10:51.068236   19894 strace.go:599] [   1:   1] python X close(0x4 socket:[1]) = 0 (0x0) (9.802µs)
I1213 23:10:51.068281   19894 strace.go:561] [   1:   1] python E close(0x5 socket:[2])
I1213 23:10:51.068294   19894 strace.go:599] [   1:   1] python X close(0x5 socket:[2]) = 0 (0x0) (3.071µs)
I1213 23:10:51.068347   19894 strace.go:561] [   1:   1] python E close(0x3 anon_inode:[eventpoll])
I1213 23:10:51.068359   19894 strace.go:599] [   1:   1] python X close(0x3 anon_inode:[eventpoll]) = 0 (0x0) (2.363µs)
I1213 23:10:51.068543   19894 strace.go:570] [   1:   1] python E rt_sigaction(SIGINT, 0x7ed943a3f380 {Handler: SIG_DFL, Flags: SA_RESTORER|SA_ONSTACK, Restorer: 0x7ec96277d730, Mask: []}, 0x7ed943a3f420, 0x8)
I1213 23:10:51.068570   19894 strace.go:608] [   1:   1] python X rt_sigaction(SIGINT, 0x7ed943a3f380 {Handler: SIG_DFL, Flags: SA_RESTORER|SA_ONSTACK, Restorer: 0x7ec96277d730, Mask: []}, 0x7ed943a3f420 {Handler: 0x7ec9621e3ad1, Flags: SA_RESTORER|SA_ONSTACK, Restorer: 0x7ec96277d730, Mask: []}, 0x8) = 0 (0x0) (4.027µs)
I1213 23:10:51.095008   19894 strace.go:564] [   1:   1] python E munmap(0x7ec96119a000, 0x66000)
I1213 23:10:51.095153   19894 strace.go:602] [   1:   1] python X munmap(0x7ec96119a000, 0x66000) = 0 (0x0) (93.52µs)
I1213 23:10:51.095308   19894 strace.go:564] [   1:   1] python E munmap(0x7ec96259c000, 0x4000)
I1213 23:10:51.095509   19894 strace.go:602] [   1:   1] python X munmap(0x7ec96259c000, 0x4000) = 0 (0x0) (162.545µs)
I1213 23:10:51.097270   19894 strace.go:561] [   1:   1] python E exit_group(0x0)
I1213 23:10:51.097290   19894 strace.go:599] [   1:   1] python X exit_group(0x0) = 0 (0x0) (1.665µs)
D1213 23:10:51.097298   19894 task_exit.go:204] [   1:   1] Transitioning from exit state TaskExitNone to TaskExitInitiated
I1213 23:10:51.100651   19894 loader.go:1093] Gofer socket disconnected, killing container "657a39d3e806af78673d94fd"
D1213 23:10:51.100681   19894 task_exit.go:361] [   1:   1] Init process terminating, killing namespace
D1213 23:10:51.100703   19894 task_signals.go:481] [   1:   1] No task notified of signal 9
D1213 23:10:51.100718   19894 task_exit.go:204] [   1:   1] Transitioning from exit state TaskExitInitiated to TaskExitZombie
D1213 23:10:51.100726   19894 task_exit.go:204] [   1:   1] Transitioning from exit state TaskExitZombie to TaskExitDead
D1213 23:10:51.100749   19894 controller.go:506] containerManager.Wait returned, cid: 657a39d3e806af78673d94fd, waitStatus: 0x0, err: <nil>
I1213 23:10:51.100752   19894 boot.go:498] application exiting with exit status 0
D1213 23:10:51.100801   19894 urpc.go:568] urpc: successfully marshalled 36 bytes.
I1213 23:10:51.100830   19894 watchdog.go:221] Stopping watchdog
I1213 23:10:51.100879   19894 watchdog.go:225] Watchdog stopped
I1213 23:10:51.101071   19894 main.go:224] Exiting with status: 0
@ekzhang ekzhang added the type: bug Something isn't working label Dec 13, 2023
@manninglucas manninglucas added the area: networking Issue related to networking label Dec 14, 2023
@manninglucas manninglucas assigned manninglucas and unassigned kevinGC Dec 14, 2023
@danielnorberg
Copy link

I am able to repro with docker using the runsc runtime on a c2 instance.

$ sudo docker run --rm --runtime=runsc -it repro python main.py
PUT 10MB time: 24.01 sec

Running with the default runtime is fast:

$ sudo docker run -it repro python main.py
PUT 10MB time: 0.17 sec

$ curl -H "Metadata-Flavor: Google" -s http://metadata.google.internal/computeMetadata/v1/instance/machine-type
projects/<redacted>/machineTypes/c2-standard-30

$ curl -H "Metadata-Flavor: Google" -s http://metadata.google.internal/computeMetadata/v1/instance/zone
projects/<redacted>/zones/europe-west4-a

$ uname -a
Linux dano-test-r2-gvnic-eu-c2-30-tier1 5.15.0-1045-gcp #53~20.04.2-Ubuntu SMP Wed Oct 18 12:59:20 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

@danielnorberg
Copy link

I tried upgrading to the latest gVNIC release, 1.3.4, but no improvement.

dano@dano-test-upgraded-gvnic-eu-c2-30-tier1:~$ sudo lshw -class network
  *-network
       description: Ethernet interface
       product: Compute Engine Virtual Ethernet [gVNIC]
       vendor: Google, Inc.
       physical id: 4
       bus info: pci@0000:00:04.0
       logical name: ens4
       version: 00
       serial: 42:01:ac:1e:70:2a
       width: 32 bits
       clock: 33MHz
       capabilities: msix bus_master cap_list ethernet physical
       configuration: autonegotiation=off broadcast=yes driver=gve driverversion=1.3.4 duplex=half ip=172.30.112.42 latency=0 link=yes multicast=yes port=twisted pair
       resources: irq:11 memory:c0102000-c0102fff memory:c0100000-c01001ff memory:c0000000-c00fffff

$ sudo docker run --rm --runtime=runsc -it repro python main.py
PUT 10MB time: 16.03 sec

@manninglucas
Copy link
Contributor

Thanks for the detailed reports! I was able to repro on my own machine. I'll let you know when I've found a root cause.

@manninglucas
Copy link
Contributor

manninglucas commented Dec 15, 2023 •
edited
Loading

Hi, it seems like we aren't handling the gVNIC hardware properly when setting up our fdbased link endpoints. A temporary workaround is to pass --gso=false as an argument to runsc. In docker you can do this by modifying /etc/docker/daemon.json.

@ekzhang
Copy link
Contributor Author

ekzhang commented Jan 3, 2024

Hi @manninglucas — just curious if you had an update on this? We haven't passed the -gso=false flag yet because of this note on the networking guide:

Note: Network performance, especially for large payloads, will be greatly reduced.

And because a lot of ML workloads have large payloads.

@manninglucas
Copy link
Contributor

Hi @ekzhang, sorry for the delay. I have a fix #9850 that should be checked in very soon.

@copybara-service copybara-service bot mentioned this issue Jan 4, 2024
Closed
@ekzhang
Copy link
Contributor Author

ekzhang commented Jan 4, 2024

Awesome, thank you!

copybara-service bot pushed a commit that referenced this issue Jan 5, 2024
@manninglucas @gvisor-bot
Set up configuration for doing host GSO with the GVE network driver (…
1ae161d 
…gVNIC).

This change is mostly just plumbing configuration through the network stack.
This change will ensure that future unrecognized host network drivers will
not break GSO. It also makes it easier to add support for future network
drivers.

Fixes issue #9816

PiperOrigin-RevId: 592335983
@manninglucas
Copy link
Contributor

Hi @ekzhang, we've been trying to get this to work, but unfortunately we suspect getting gVNIC to work properly with gVisor will require specific hardware integrations that will take longer than originally anticipated. In the meantime you can try using our software GSO --sofware-gso=true to help with performance or large payloads. Using the previous generation virtio-based network drivers will also work. Sorry, I know this wasn't the answer you were looking for right now. I'll keep this bug updated with progress.

@ekzhang
Copy link
Contributor Author

ekzhang commented Jan 5, 2024

Thank you! We'll try using the -gso=false workaround you provided now. I saw -software-gso=true is enabled by default.

@copybara-service copybara-service bot mentioned this issue Jan 9, 2024
Closed
@manninglucas
Copy link
Contributor

Hi @ekzhang, we were able to find a fix for GSO on gVNIC (#9872). Let me know if the fix does not work for you.

@ekzhang
Copy link
Contributor Author

ekzhang commented Jan 10, 2024

Thank you! Will try soon.

@ekzhang
Copy link
Contributor Author

ekzhang commented Jan 10, 2024 •
edited
Loading

Hi @manninglucas — the latency looks better, but I can still reproduce the issue about half of the time I run my above script in the first comment of this issue. It does not reproduce with runc.

Half the time I'm getting latencies of 0.4 seconds, which matches runc, and the other half the time I'm getting latencies between 4-9 seconds.

runsc version 5b33e4a3d8ec
spec: 1.1.0-rc.1

The -gso=false flag still seems to act as a workaround, but it slows down the 10 MiB PUT request to about 1-2 seconds on average.

@ekzhang
Copy link
Contributor Author

ekzhang commented Jan 10, 2024 •
edited
Loading

Here are the latencies for 20 consecutive runs of the reproduction script at the beginning of the issue, from a n2-standard-8 GCP instance in us-central1:

(This is on 5b33e4a3d8ec, without the GSO workaround).

PUT 10MB time: 0.40 sec
PUT 10MB time: 0.35 sec
PUT 10MB time: 0.33 sec
PUT 10MB time: 4.59 sec
PUT 10MB time: 4.57 sec
PUT 10MB time: 0.30 sec
PUT 10MB time: 0.32 sec
PUT 10MB time: 4.67 sec
PUT 10MB time: 0.35 sec
PUT 10MB time: 0.33 sec
PUT 10MB time: 8.89 sec
PUT 10MB time: 0.29 sec
PUT 10MB time: 13.04 sec
PUT 10MB time: 4.59 sec
PUT 10MB time: 8.82 sec
PUT 10MB time: 0.29 sec
PUT 10MB time: 0.31 sec
PUT 10MB time: 4.74 sec
PUT 10MB time: 4.55 sec
PUT 10MB time: 4.55 sec

Here are the timings for runc, same parameters, PUT 10 MB:

PUT 10MB time: 0.33 sec
PUT 10MB time: 0.33 sec
PUT 10MB time: 0.37 sec
PUT 10MB time: 0.30 sec
PUT 10MB time: 0.31 sec
PUT 10MB time: 0.32 sec
PUT 10MB time: 0.28 sec
PUT 10MB time: 0.29 sec
PUT 10MB time: 0.30 sec
PUT 10MB time: 0.31 sec
PUT 10MB time: 0.22 sec
PUT 10MB time: 0.30 sec
PUT 10MB time: 0.39 sec
PUT 10MB time: 0.28 sec
PUT 10MB time: 0.32 sec
PUT 10MB time: 0.21 sec
PUT 10MB time: 0.28 sec
PUT 10MB time: 0.29 sec
PUT 10MB time: 0.31 sec
PUT 10MB time: 0.31 sec

And here are the timings with runsc with -gso=false, the workaround:

PUT 10MB time: 1.56 sec
PUT 10MB time: 1.60 sec
PUT 10MB time: 1.79 sec
PUT 10MB time: 1.11 sec
PUT 10MB time: 1.54 sec
PUT 10MB time: 1.58 sec
PUT 10MB time: 1.52 sec
PUT 10MB time: 1.19 sec
PUT 10MB time: 1.61 sec
PUT 10MB time: 9.29 sec
PUT 10MB time: 0.99 sec
PUT 10MB time: 0.86 sec
PUT 10MB time: 1.41 sec
PUT 10MB time: 1.58 sec
PUT 10MB time: 1.07 sec
PUT 10MB time: 4.69 sec
PUT 10MB time: 1.21 sec
PUT 10MB time: 0.30 sec
PUT 10MB time: 1.65 sec
PUT 10MB time: 1.51 sec

@manninglucas manninglucas reopened this Jan 10, 2024
@copybara-service copybara-service bot mentioned this issue Jan 13, 2024
Merged
@manninglucas
Copy link
Contributor

@ekzhang internal testing showed adding some extra padding to the maximum GSO packet resolves the issue. Let me know if you still see any slowdowns and I can reopen.

@ekzhang
Copy link
Contributor Author

ekzhang commented Jan 15, 2024

Thank you for the internal testing! I'll try it out and confirm on our end.

@ekzhang
Copy link
Contributor Author

ekzhang commented Jan 15, 2024

Confirmed, thank you very much :)

// TODO(b/319936470): Investigate why this needs to be at least 140 bytes. In
// Linux this value is at least 160, but in theory we should be able to use
// 138. In practice anything less than 140 starts to break GSO on gVNIC
// hardware.

Very interesting comment!

@thundergolfer thundergolfer mentioned this issue May 15, 2024
Closed
# for free to join this conversation on GitHub. Already have an account? # to comment
Assignees

@manninglucas manninglucas

Labels
area: networking Issue related to networking type: bug Something isn't working
Projects
None yet
Milestone
No milestone
4 participants
@danielnorberg @kevinGC @manninglucas @ekzhang