Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

runtime: MADVISE syscall seems not to be called when using signal.Notify according to strace #42231

Closed
leighhopcroft opened this issue Oct 27, 2020 · 3 comments

Comments

@leighhopcroft
Copy link

@leighhopcroft leighhopcroft commented Oct 27, 2020

What version of Go are you using (go version)?

$ go version
go version go1.15.2 linux/amd64

Does this issue reproduce with the latest release?

yes

What operating system and processor architecture are you using (go env)?

go env Output
$ go env
GO111MODULE="auto"
GOARCH="amd64"
GOBIN=""
GOCACHE="/root/.cache/go-build"
GOENV="/root/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/workspaces/go-freeosmemory/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build028233962=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I built three different go programs:

"direct" https://play.golang.org/p/JN6OdiiGLzn

Define a function to makeGarbage in an infinate loop, call direct from main.

"background" https://play.golang.org/p/8RuVoEdudbW

Define a channel of os.Signal, call makeGarbage in a goroutine and wait forever on empty channel in main.

"notify" https://play.golang.org/p/CXPOnvefgvQ

Define a channel of os.Signal, call signal.Notify to catch SIGINT, call makeGarbage in a goroutine and wait on chan recv for SIGINT to occur.

I then ran all three binaries using strace -q -e trace=memory ./${BINARY_NAME}

What did you expect to see?

All three programs showing relevant mmap and madvise syscalls corresponding to the allocation and freeing of OS memory.

What did you see instead?

"direct" and "background" behave as expected with the following typical output (ignoring SIGURG lines):

grep -v SIGURG direct.strace.log Output
$ grep -v SIGURG direct.strace.log
mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa622d12000
mmap(NULL, 131072, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa622cf2000
mmap(NULL, 1048576, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa622bf2000
mmap(NULL, 8388608, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa6223f2000
mmap(NULL, 67108864, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa61e3f2000
mmap(NULL, 536870912, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa5fe3f2000
mmap(0xc000000000, 67108864, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xc000000000
mmap(0xc000000000, 67108864, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xc000000000
mmap(NULL, 33554432, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa5fc3f2000
mmap(NULL, 2165768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa5fc1e1000
mmap(0x7fa622cf2000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fa622cf2000
mmap(0x7fa622c72000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fa622c72000
mmap(0x7fa6227f8000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fa6227f8000
mmap(0x7fa620422000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fa620422000
mmap(0x7fa60e572000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fa60e572000
mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa5fc0e1000
mmap(NULL, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa5fc0d1000
mmap(NULL, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa5fc0c1000
mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa5fc041000
mmap(NULL, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa5fc031000
madvise(0xc000400000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc0005b4000, 8192, MADV_FREE)  = 0
madvise(0xc000400000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc0005b2000, 8192, MADV_FREE)  = 0
madvise(0xc000800000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc0009b4000, 8192, MADV_FREE)  = 0
madvise(0xc007800000, 2097152, MADV_HUGEPAGE) = 0
madvise(0xc007600000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc00778a000, 8192, MADV_FREE)  = 0
madvise(0xc007600000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc007788000, 8192, MADV_FREE)  = 0
madvise(0xc007a00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc007b16000, 8192, MADV_FREE)  = 0
madvise(0xc007a00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc007b14000, 8192, MADV_FREE)  = 0
madvise(0xc007a00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc007b12000, 8192, MADV_FREE)  = 0
madvise(0xc007a00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc007b10000, 8192, MADV_FREE)  = 0
madvise(0xc007a00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc007b0c000, 8192, MADV_FREE)  = 0
madvise(0xc007a00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc007b0a000, 8192, MADV_FREE)  = 0
madvise(0xc007a00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc007b08000, 8192, MADV_FREE)  = 0
madvise(0xc007a00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc007b06000, 8192, MADV_FREE)  = 0
madvise(0xc007a00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc007b04000, 8192, MADV_FREE)  = 0
madvise(0xc007a00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc007afe000, 8192, MADV_FREE)  = 0
madvise(0xc007a00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc007afc000, 8192, MADV_FREE)  = 0
madvise(0xc007a00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc007af8000, 8192, MADV_FREE)  = 0
madvise(0xc007a00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc007af6000, 8192, MADV_FREE)  = 0
madvise(0xc007a00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc007af4000, 8192, MADV_FREE)  = 0
madvise(0xc007a00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc007aa6000, 8192, MADV_FREE)  = 0
madvise(0xc007a00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc007aa4000, 8192, MADV_FREE)  = 0
madvise(0xc003000000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc00304c000, 8192, MADV_FREE)  = 0
madvise(0xc00aa00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc00ab48000, 8192, MADV_FREE)  = 0
madvise(0xc00aa00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc00ab46000, 8192, MADV_FREE)  = 0
madvise(0xc00d000000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc00d00e000, 8192, MADV_FREE)  = 0
madvise(0xc00aa00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc00aae8000, 8192, MADV_FREE)  = 0
madvise(0xc00aa00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc00aae6000, 8192, MADV_FREE)  = 0
madvise(0xc00aa00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc00aae4000, 8192, MADV_FREE)  = 0
madvise(0xc00aa00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc00aae2000, 8192, MADV_FREE)  = 0
madvise(0xc00aa00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc00aae0000, 8192, MADV_FREE)  = 0
madvise(0xc00aa00000, 2097152, MADV_NOHUGEPAGE) = 0
madvise(0xc00aade000, 8192, MADV_FREE)  = 0
madvise(0xc00aa00000, 2097152, MADV_NOHUGEPAGE) = 0
+++ killed by SIGINT +++

whereas "notify" shows the mmap calls but does not show any madvise calls. See the following typical output (ignoring SIGURG lines):

grep -v SIGURG notify.strace.log Output
$ grep -v SIGURG notify.strace.log
mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcb71cf3000
mmap(NULL, 131072, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcb71cd3000
mmap(NULL, 1048576, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcb71bd3000
mmap(NULL, 8388608, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcb713d3000
mmap(NULL, 67108864, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcb6d3d3000
mmap(NULL, 536870912, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcb4d3d3000
mmap(0xc000000000, 67108864, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xc000000000
mmap(0xc000000000, 67108864, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xc000000000
mmap(NULL, 33554432, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcb4b3d3000
mmap(NULL, 2165768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcb4b1c2000
mmap(0x7fcb71cd3000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fcb71cd3000
mmap(0x7fcb71c53000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fcb71c53000
mmap(0x7fcb717d9000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fcb717d9000
mmap(0x7fcb6f403000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fcb6f403000
mmap(0x7fcb5d553000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fcb5d553000
mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcb4b0c2000
mmap(NULL, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcb4b0b2000
mmap(NULL, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcb4b0a2000
--- SIGINT {si_signo=SIGINT, si_code=SI_KERNEL} ---
+++ exited with 0 +++

Does this mean that the memory is not actually being released back to the OS, or is it just that there is some interaction with signal.Notify and strace visibility of the madvise syscalls?

@odeke-em odeke-em changed the title madvise syscall seems not to be called when using signal.Notify according to strace runtime: MADVISE syscall seems not to be called when using signal.Notify according to strace Oct 27, 2020
@odeke-em
Copy link
Member

@odeke-em odeke-em commented Oct 27, 2020

Thank you @leighhopcroft for filing this issue, and welcome to the Go project!

I shall kindly rope in some experts @mknyszek @aclements @ianlancetaylor.

Loading

@mknyszek
Copy link
Contributor

@mknyszek mknyszek commented Oct 27, 2020

FWIW the runtime does think it's releasing memory to the OS (try running with GODEBUG=scavtrace=1,gctrace=1 set), and also I am seeing madvise calls in strace on linux/amd64, but it's not consistent. If I run strace ./main a bunch of times, sometimes it'll stop generating output, other times it will keep showing madvise calls among other things.

The fact that it's inconsistent suggests to me that for some reason strace is not interacting with the Go application well. I see there's a clone in there... ah! Right.

By default strace doesn't follow clone'd threads. So basically what's happening is in your first two examples we're getting lucky that it just all happens to run on the main thread. But it seems the inclusion of notify.Signal perturbs the scheduler just enough to have the scavenger running on a different thread.

If you include the -f flag to strace I think you now end up seeing all the madvise calls.

Loading

@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Oct 27, 2020

Yes, you must always use strace -f, never plain strace, when tracing Go programs.

Optimistically closing. Please comment if there is still a problem here.

Loading

@golang golang locked and limited conversation to collaborators Oct 27, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
5 participants