Polling something every 20 us

[lnicola]

I'm not sure if it's the same problem, but my gitea burns CPU in a loop with a 200 20 ms us timeout, which seems quite absurd:

[pid   796] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid   796] futex(0x5debff8, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=77531654} <unfinished ...>
[pid   811] <... epoll_pwait resumed>[], 128, 1, NULL, 1) = 0
[pid   811] epoll_pwait(3, [], 128, 0, NULL, 140069537041208) = 0
[pid   811] epoll_pwait(3, [], 128, 77, NULL, 1) = 0
[pid   811] epoll_pwait(3, [], 128, 0, NULL, 140069537041208) = 0
[pid   811] epoll_pwait(3,  <unfinished ...>
[pid   796] <... futex resumed>)        = -1 ETIMEDOUT (Connection timed out)
[pid   796] futex(0xc004e76148, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid   810] <... futex resumed>)        = 0
[pid   796] <... futex resumed>)        = 1
[pid   810] futex(0xc004e76148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid   796] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0

Originally posted by @lnicola in #7910 (comment)

[lnicola]

More details:

• I'm using a pre-built 1.13.4-p0 on Ubuntu 20.04
• this is a slow VPS (the cheapest I found)
• even so, it doesn't use a lot of CPU, about 1%
• my binary is built with go 1.15.8
• I tried to record a profile, but go pprof says parsing profile: unrecognized profile format (both on go 1.16.2 and 1.13.8
• the trace file itself starts with a go 1.11 trace magic string
• opening a heap dump (http://localhost:6060/debug/pprof/heap) actually works
• the gitea instance should be idle (no HTTP connections, nothing new to index)
• it's not doing anything else besides the sleep and syncronization syscalls visible in the snippet above (strace prints pages and pages like that)
• I couldn't find any 200 us delay in the source code

CC @zeripath since you replied to me in the other issue and thanks for the help!

[lnicola]

trace.zip

profile.zip

Oh, I actually needed go tool trace, not go tool pprof. I'm not sure how to read these, but it might be a work queue polling for new items or something? You can probably ignore the xorm stuff, it's polling for new notifications every 10 seconds.

[lnicola]

This might actually be relatively normal. go seems to have a sysmon thread that wakes every 20 us (or less often, if it has nothing to do), see https://golang.org/src/runtime/proc.go around line 5100. I don't know why it's not going to sleep more often, though.

This is how the threads look like:

Thread 12 (LWP 14924):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:588
#1  0x000000000043bfa6 in runtime.futexsleep (addr=0xc0030fe548, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x000000000041481f in runtime.notesleep (n=0xc0030fe548) at /usr/local/go/src/runtime/lock_futex.go:159
#3  0x0000000000446705 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1924
#4  0x0000000000447edf in runtime.findrunnable (gp=0xc000048000, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2485
#5  0x0000000000448b57 in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2683
#6  0x00000000004490fd in runtime.park_m (gp=0xc002d7e780) at /usr/local/go/src/runtime/proc.go:2851
#7  0x0000000000476bbb in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:318
#8  0x0000000000000000 in ?? ()

Thread 11 (LWP 14923):
#0  runtime.epollwait () at /usr/local/go/src/runtime/sys_linux_amd64.s:725
#1  0x000000000043bc72 in runtime.netpoll (delay=502843, ~r1=...) at /usr/local/go/src/runtime/netpoll_epoll.go:126
#2  0x0000000000447be5 in runtime.findrunnable (gp=0xc000048000, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2448
#3  0x0000000000448b57 in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2683
#4  0x00000000004490fd in runtime.park_m (gp=0xc000000d80) at /usr/local/go/src/runtime/proc.go:2851
#5  0x0000000000476bbb in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:318
#6  0x0000000000000000 in ?? ()

Thread 10 (LWP 14922):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:588
#1  0x000000000043bfa6 in runtime.futexsleep (addr=0xc002d47d48, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x000000000041481f in runtime.notesleep (n=0xc002d47d48) at /usr/local/go/src/runtime/lock_futex.go:159
#3  0x0000000000446705 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1924
#4  0x0000000000447edf in runtime.findrunnable (gp=0xc000048000, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2485
#5  0x0000000000448b57 in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2683
#6  0x00000000004490fd in runtime.park_m (gp=0xc000000d80) at /usr/local/go/src/runtime/proc.go:2851
#7  0x0000000000476bbb in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:318
#8  0x0000000000000000 in ?? ()

Thread 9 (LWP 14921):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:588
#1  0x000000000043bfa6 in runtime.futexsleep (addr=0xc002d47948, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x000000000041481f in runtime.notesleep (n=0xc002d47948) at /usr/local/go/src/runtime/lock_futex.go:159
#3  0x0000000000446705 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1924
#4  0x0000000000447edf in runtime.findrunnable (gp=0xc000048000, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2485
#5  0x0000000000448b57 in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2683
#6  0x00000000004490fd in runtime.park_m (gp=0xc003074180) at /usr/local/go/src/runtime/proc.go:2851
#7  0x0000000000476bbb in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:318
#8  0x0000000000000000 in ?? ()

Thread 8 (LWP 14920):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:588
#1  0x000000000043bfa6 in runtime.futexsleep (addr=0xc002d47548, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x000000000041481f in runtime.notesleep (n=0xc002d47548) at /usr/local/go/src/runtime/lock_futex.go:159
#3  0x0000000000446705 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1924
#4  0x0000000000447edf in runtime.findrunnable (gp=0xc000048000, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2485
#5  0x0000000000448b57 in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2683
#6  0x00000000004490fd in runtime.park_m (gp=0xc002cfea80) at /usr/local/go/src/runtime/proc.go:2851
#7  0x0000000000476bbb in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:318
#8  0x0000000000000000 in ?? ()

Thread 7 (LWP 14913):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:588
#1  0x000000000043bfa6 in runtime.futexsleep (addr=0xc000daf148, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x000000000041481f in runtime.notesleep (n=0xc000daf148) at /usr/local/go/src/runtime/lock_futex.go:159
#3  0x0000000000446705 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1924
#4  0x0000000000447edf in runtime.findrunnable (gp=0xc000048000, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2485
#5  0x0000000000448b57 in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2683
#6  0x00000000004490fd in runtime.park_m (gp=0xc003074000) at /usr/local/go/src/runtime/proc.go:2851
#7  0x0000000000476bbb in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:318
#8  0x0000000000000000 in ?? ()

Thread 6 (LWP 14911):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:588
#1  0x000000000043bfa6 in runtime.futexsleep (addr=0xc000daed48, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x000000000041481f in runtime.notesleep (n=0xc000daed48) at /usr/local/go/src/runtime/lock_futex.go:159
#3  0x0000000000446705 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1924
#4  0x0000000000447edf in runtime.findrunnable (gp=0xc000048000, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2485
#5  0x0000000000448b57 in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2683
#6  0x0000000000449bb6 in runtime.goexit0 (gp=0xc002cff680) at /usr/local/go/src/runtime/proc.go:3010
#7  0x0000000000476bbb in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:318
#8  0x0000000000000000 in ?? ()

Thread 5 (LWP 14910):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:588
#1  0x000000000043bfa6 in runtime.futexsleep (addr=0x5e308b8 <runtime.newmHandoff+24>, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x000000000041481f in runtime.notesleep (n=0x5e308b8 <runtime.newmHandoff+24>) at /usr/local/go/src/runtime/lock_futex.go:159
#3  0x000000000044661a in runtime.templateThread () at /usr/local/go/src/runtime/proc.go:1902
#4  0x0000000000445128 in runtime.mstart1 () at /usr/local/go/src/runtime/proc.go:1172
#5  0x000000000044502e in runtime.mstart () at /usr/local/go/src/runtime/proc.go:1137
#6  0x000000000230f37c in crosscall_amd64 () at gcc_amd64.S:35
#7  0x00007ffdf1481d10 in ?? ()
#8  0x00000000063c2070 in ?? ()
#9  0x0000000000000000 in ?? ()

Thread 4 (LWP 14909):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:588
#1  0x000000000043bfa6 in runtime.futexsleep (addr=0xc00005ad48, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x000000000041481f in runtime.notesleep (n=0xc00005ad48) at /usr/local/go/src/runtime/lock_futex.go:159
#3  0x0000000000446ead in runtime.stoplockedm () at /usr/local/go/src/runtime/proc.go:2085
#4  0x0000000000448d0c in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2617
#5  0x00000000004490fd in runtime.park_m (gp=0xc001145b00) at /usr/local/go/src/runtime/proc.go:2851
#6  0x0000000000476bbb in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:318
#7  0x0000000000000000 in ?? ()

Thread 3 (LWP 14908):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:588
#1  0x000000000043bfa6 in runtime.futexsleep (addr=0xc00005a948, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x000000000041481f in runtime.notesleep (n=0xc00005a948) at /usr/local/go/src/runtime/lock_futex.go:159
#3  0x0000000000446705 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1924
--Type <RET> for more, q to quit, c to continue without paging--
#4  0x0000000000447edf in runtime.findrunnable (gp=0xc000048000, inheritTime=false) at /usr/local/go/src/runtime/proc.go:2485
#5  0x0000000000448b57 in runtime.schedule () at /usr/local/go/src/runtime/proc.go:2683
#6  0x00000000004490fd in runtime.park_m (gp=0xc002cc1800) at /usr/local/go/src/runtime/proc.go:2851
#7  0x0000000000476bbb in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:318
#8  0x0000000000000000 in ?? ()

Thread 2 (LWP 14907):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:588
#1  0x000000000043c017 in runtime.futexsleep (addr=0x5debff8 <runtime.sched+280>, val=0, ns=836603) at /usr/local/go/src/runtime/os_linux.go:51
#2  0x00000000004149b9 in runtime.notetsleep_internal (n=0x5debff8 <runtime.sched+280>, ns=836603, ~r2=<optimized out>) at /usr/local/go/src/runtime/lock_futex.go:201
#3  0x0000000000414a91 in runtime.notetsleep (n=0x5debff8 <runtime.sched+280>, ns=836603, ~r2=<optimized out>) at /usr/local/go/src/runtime/lock_futex.go:224
#4  0x000000000044dbba in runtime.sysmon () at /usr/local/go/src/runtime/proc.go:4679
#5  0x0000000000445128 in runtime.mstart1 () at /usr/local/go/src/runtime/proc.go:1172
#6  0x000000000044502e in runtime.mstart () at /usr/local/go/src/runtime/proc.go:1137
#7  0x000000000230f37c in crosscall_amd64 () at gcc_amd64.S:35
#8  0x00007ffdf1481c60 in ?? ()
#9  0x00000000063c1cb0 in ?? ()
#10 0x0000000000000000 in ?? ()

Thread 1 (LWP 14906):
#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:588
#1  0x000000000043bfa6 in runtime.futexsleep (addr=0x5e309c0 <runtime.sig>, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
#2  0x0000000000414906 in runtime.notetsleep_internal (n=0x5e309c0 <runtime.sig>, ns=-1, ~r2=<optimized out>) at /usr/local/go/src/runtime/lock_futex.go:182
#3  0x0000000000414b2c in runtime.notetsleepg (n=0x5e309c0 <runtime.sig>, ns=-1, ~r2=<optimized out>) at /usr/local/go/src/runtime/lock_futex.go:236
#4  0x000000000047517d in os/signal.signal_recv (~r0=<optimized out>) at /usr/local/go/src/runtime/sigqueue.go:147
#5  0x0000000001616e05 in os/signal.loop () at /usr/local/go/src/os/signal/signal_unix.go:23
#6  0x00000000004789c1 in runtime.goexit () at /usr/local/go/src/runtime/asm_amd64.s:1374
#7  0x0000000000000000 in ?? ()

[zeripath]

This all looks like it is happening at the go runtime level and is nothing particularly special to gitea.

[lnicola]

I guess you're right, I'm new to this. I still think it should throttle down a little, but it seems to work more or less as designed.