How to use ltrace with a Go program

Question

I'm trying to debug memory issue on Go, i.e. RSS keeps on increasing, no leak is found via pprof, most likely is due to Go not returning memory to OS when it's freed (classic scavenger issue in Go: https://github.com/golang/go/issues/30333)

I'm trying to understand how the memory is allocated into heap and when they are deallocated. strace doesn't help much so far, so I'm trying to use ltrace

ltrace -e malloc+free go run main.go

Unfortunately, it immediately crashes the program. Any ideas how to use ltrace on go program? or it's not possible at all?

go->malloc(56)                                                                                                                                     = 0x1f4f010
libpthread.so.0->free(nil)                                                                                                                         = <void>
go->free(0x1f4f010)                                                                                                                                = <void>
go->malloc(24)                                                                                                                                     = 0x1f4f050
go->malloc(24)                                                                                                                                     = 0x1f4f2c0
go->malloc(24)                                                                                                                                     = 0x1f4f2c0
go->malloc(24)                                                                                                                                     = 0x1f4f2c0
SIGILL: illegal instruction
PC=0x4aeb5e m=4 sigcode=2

goroutine 9 [syscall]:
syscall.Syscall6(0xf7, 0x1, 0x5865, 0xc000166dc8, 0x1000004, 0x0, 0x0, 0x4d0601, 0xc0003edf20, 0xc000166e08)
        /usr/local/go/src/syscall/asm_linux_amd64.s:44 +0x5 fp=0xc000166d78 sp=0xc000166d70 pc=0x4aeb35
os.(*Process).blockUntilWaitable(0xc000027b30, 0x203000, 0xc0002d0000, 0x2)
        /usr/local/go/src/os/wait_waitid.go:31 +0x98 fp=0xc000166e68 sp=0xc000166d78 pc=0x4d4db8
os.(*Process).wait(0xc000027b30, 0xa842a0, 0xa842a8, 0xa84298)
        /usr/local/go/src/os/exec_unix.go:22 +0x39 fp=0xc000166ee0 sp=0xc000166e68 pc=0x4cca69
os.(*Process).Wait(...)
        /usr/local/go/src/os/exec.go:125
os/exec.(*Cmd).Wait(0xc000325b80, 0x0, 0x0)
        /usr/local/go/src/os/exec/exec.go:501 +0x60 fp=0xc000166f58 sp=0xc000166ee0 pc=0x50bbc0
os/exec.(*Cmd).Run(0xc000325b80, 0xc000260e10, 0x27)
        /usr/local/go/src/os/exec/exec.go:341 +0x5c fp=0xc000166f80 sp=0xc000166f58 pc=0x50b05c
cmd/go/internal/work.(*Builder).toolID(0xc0000a55e0, 0xa3c61a, 0x7, 0xb, 0xc0001673c8)
        /usr/local/go/src/cmd/go/internal/work/buildid.go:193 +0x44d fp=0xc000167170 sp=0xc000166f80 pc=0x83a51d
cmd/go/internal/work.(*Builder).buildActionID(0xc0000a55e0, 0xc0002e9400, 0x0, 0x0, 0x0, 0x0)
        /usr/local/go/src/cmd/go/internal/work/exec.go:242 +0x1215 fp=0xc000167588 sp=0xc000167170 pc=0x840c15
cmd/go/internal/work.(*Builder).build(0xc0000a55e0, 0xc0002e9400, 0x0, 0x0)
        /usr/local/go/src/cmd/go/internal/work/exec.go:397 +0x52a6 fp=0xc000167e30 sp=0xc000167588 pc=0x847606
cmd/go/internal/work.(*Builder).Do.func2(0xc0002e9400)
        /usr/local/go/src/cmd/go/internal/work/exec.go:117 +0x36d fp=0xc000167ef0 sp=0xc000167e30 pc=0x87666d
cmd/go/internal/work.(*Builder).Do.func3(0xc000028d60, 0xc0000a55e0, 0xc0003d9740)
        /usr/local/go/src/cmd/go/internal/work/exec.go:177 +0x79 fp=0xc000167fc8 sp=0xc000167ef0 pc=0x876799
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1357 +0x1 fp=0xc000167fd0 sp=0xc000167fc8 pc=0x45c4c1
created by cmd/go/internal/work.(*Builder).Do
        /usr/local/go/src/cmd/go/internal/work/exec.go:164 +0x3a1

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xc000028d68)
        /usr/local/go/src/runtime/sema.go:56 +0x42
sync.(*WaitGroup).Wait(0xc000028d60)
        /usr/local/go/src/sync/waitgroup.go:130 +0x64
cmd/go/internal/work.(*Builder).Do(0xc0000a55e0, 0xc000152dc0)
        /usr/local/go/src/cmd/go/internal/work/exec.go:186 +0x3c5
cmd/go/internal/run.runRun(0xea3d40, 0xc0000201a0, 0x1, 0x1)
        /usr/local/go/src/cmd/go/internal/run/run.go:143 +0x54d
main.main()
        /usr/local/go/src/cmd/go/main.go:189 +0x57f

goroutine 6 [syscall]:
os/signal.signal_recv(0x0)
        /usr/local/go/src/runtime/sigqueue.go:147 +0x9c
os/signal.loop()
        /usr/local/go/src/os/signal/signal_unix.go:23 +0x22
created by os/signal.init.0
        /usr/local/go/src/os/signal/signal_unix.go:29 +0x41

goroutine 10 [runnable]:
os/exec.(*Cmd).Start.func1(0xc000325b80, 0xc0003d97e0)
        /usr/local/go/src/os/exec/exec.go:434
created by os/exec.(*Cmd).Start
        /usr/local/go/src/os/exec/exec.go:434 +0x608

goroutine 11 [runnable]:
os/exec.(*Cmd).Start.func1(0xc000325b80, 0xc0003d9820)
        /usr/local/go/src/os/exec/exec.go:434
created by os/exec.(*Cmd).Start
        /usr/local/go/src/os/exec/exec.go:434 +0x608

rax    0xf0013d48
rbx    0xc000030000
rcx    0xffffffffffffffff
rdx    0xc000166dc8
rdi    0x1
rsi    0x5865
rbp    0xc000166e58
rsp    0xc000166d70
r8     0x0
r9     0x0
r10    0x1000004
r11    0x202
r12    0xf1
r13    0x0
r14    0xb16d58
r15    0x0
rip    0x4aeb5e
rflags 0x10286
cs     0x33
fs     0x0
gs     0x0
+++ exited (status 2) +++

running with valgrind gives the following: https://pastebin.com/7Ky88mY0 as expected, it's not really a leak, most likely due to Go not returning memory to OS, I'm trying to understand when Go runtime performs the malloc and free here. PS. this still doesn't answer why running with ltrace causes the crash. — Dian Bakti, Jan 05 '20 at 10:30
Does [this](https://utcc.utoronto.ca/~cks/space/blog/programming/GoNoMemoryFreeing) answer your question? — Jonathan Hall, Jan 06 '20 at 04:26
Hi Flimzy, yes, this article is what I referred to "classic Go scavenger issue", i.e. Go is using madv_free and OS is not reclaiming. But in my case, madv_free is not even called when traced with strace. I filed an issue: https://github.com/golang/go/issues/36398 specifically because it seems to be regress in go >=1.13.1 — Dian Bakti, Jan 06 '20 at 08:45
and I'm still interested on why ltrace doesn't work with go :) — Dian Bakti, Jan 06 '20 at 08:46
I don't know why strace and ltrace cause go programs to fail. But, as an aside, I'll note that `ltrace go run ...` is only tracing the go driver program. You'll need either (a) `ltrace -f go run ...`, which will trace all the child processes of `go run`, or (b) `ltrace ./main` after building main with `go build -buildmode=pie ...`. By default, `go build` builds a static executable, and with no callouts to libc, ltrace won't show anything. — Mark Plotnick, Jan 09 '20 at 20:08
@MarkPlotnick thanks! Tried your approach, and worked as expected now. I can run `strace go run main.go` though. But you are right, `ltrace go run main.go` is still a mystery. — Dian Bakti, Jan 10 '20 at 10:16

How to use ltrace with a Go program

0 Answers0