runtime/pprof: missing profile info for CGo code when compiled with CC="zig cc"

[motiejus]

TLDR: when profiling CGo programs compiled with zig cc, we are missing the profiles of pure C functions as observed with go tool pprof.

I work with the C++ toolchain at Uber and we recently switched to using zig cc to compile our CGo programs. I have not yet heard complains internally of
missing CGo profiles, but I suspect it's a matter of time. :)

Also, this seems to be the last suite of tests that fail when running CC="zig cc" ./all.bash on Linux amd64.

Go version: master (8d68b38)
Zig version: 0.10.1 and master (ziglang/zig@8853005)

Steps to reproduce

Compile testprogcgo with zig cc and clang-15:

$ cd src/runtime/testdata/testprogcgo
$ CC="/code/zig-linux-x86_64-0.10.1/zig cc" ../../../../bin/go build -o testprogcgo-zig-0.10.1
$ CC=clang-15 ../../../../bin/go build -o testprogcgo-clang-15

Run both resulting binaries:

$ ./testprogcgo-zig-0.10.1 CgoPprof
/tmp/prof1336230719
$ ./testprogcgo-clang-15 CgoPprof
/tmp/prof2489818717

Compare the profiles:

$ go tool pprof -traces ./testprogcgo-clang-15 /tmp/prof2489818717
File: testprogcgo-clang-15
Build ID: 57e147c5c3713dc48115b4856c5c9a568154a3cc
Type: cpu
Time: Apr 6, 2023 at 2:58pm (EEST)
Duration: 1.10s, Total samples = 1s (90.71%)
-----------+-------------------------------------------------------
	 990ms   cpuHog
			 cpuHog2
			 runtime.cgocall
			 main._Cfunc_cpuHog
			 main.CgoPprof
			 main.main
			 runtime.main
-----------+-------------------------------------------------------
	  10ms   runtime.futex
			 runtime.futexwakeup
			 runtime.notewakeup
			 runtime.exitsyscallfast_pidle
			 runtime.exitsyscallfast.func1
			 runtime.systemstack
			 runtime.exitsyscallfast
			 runtime.exitsyscall
			 runtime.cgocall
			 main._Cfunc_cpuHog
			 main.CgoPprof
			 main.main
			 runtime.main
-----------+-------------------------------------------------------
$ go tool pprof -traces ./testprogcgo-zig-0.10.1 /tmp/prof1336230719
File: testprogcgo-zig-0.10.1
Type: cpu
Time: Apr 6, 2023 at 2:56pm (EEST)
Duration: 1.10s, Total samples = 1s (90.70%)
-----------+-------------------------------------------------------
	 990ms   pprofCgoTraceback
			 pprofCgoTraceback
			 runtime.cgocallbackg
			 main._Cfunc_foo2
			 main.CgoPprofCallback
			 main._Cfunc_CheckM
			 runtime.forcegchelper
-----------+-------------------------------------------------------
	  10ms   runtime.malg
			 runtime.exitsyscall0
			 runtime.unspillArgs
			 runtime.exitsyscallfast_pidle
			 syscall.runtime_BeforeFork
			 runtime.cgocallbackg1
			 main._Cfunc_foo2
			 main.CgoPprofCallback
			 main._Cfunc_CheckM
			 runtime.forcegchelper
-----------+-------------------------------------------------------

Note that cpuHog and cpuHog2 are not present in the profile of the program that was compiled with zig cc. This is what the unit test TestCgoPprof asserts.

Background / steps taken

I have observed and compared the resulting compiler and linker flags from both builds did not observe anything standing out.

I would appreciate some help debugging this. I am somewhat comfortable looking at disassembly and the low-level compiler flags, but, in this case, I don't know where to look.

[motiejus]

Attaching both binaries for quick reference (this is x86_64 ELF, mind you)

testprogcgo-zig-0.10.1.pptx

testprogcgo-clang-15.pptx

[mknyszek]

CC @golang/runtime

[cherrymui]

It looks like the profile you got from zig is running testprogcgo CgoPprofCallback whereas the clang one is from testprogcgo CgoPprof? (The command line you pasted looks like both are running CgoPprof, but the second profile has main.CgoPprofCallback)

[prattmic]

The second profile looks like it has symbolization wrong. e.g., this doesn't make any sense:

runtime.malg
runtime.exitsyscall0
runtime.unspillArgs
runtime.exitsyscallfast_pidle
syscall.runtime_BeforeFork

Are you sure that the binary passed to pprof matches the binary used for the profile? In fact, you don't need to pass the binary to pprof at all, as the profile contains the symbol information. Do you get the same results if you drop the binary from the pprof cli?

[motiejus]

I may have messed something up. A fresh honest copy-paste now, single command, no previous state:

zig

$ rm -fr ~/.cache/{zig,go-build}; CC="/code/zig-linux-x86_64-0.10.1/zig cc" ../../../../bin/go build -o testprogcgo-zig-0.10.1 && go tool pprof -traces ./testprogcgo-zig-0.10.1 $(./testprogcgo-zig-0.10.1 CgoPprof)
File: testprogcgo-zig-0.10.1
Type: cpu
Time: Apr 6, 2023 at 8:07pm (EEST)
Duration: 1.10s, Total samples = 1s (90.72%)
-----------+-------------------------------------------------------
        1s   pprofCgoTraceback
             pprofCgoTraceback
             runtime.cgocallbackg
             main._Cfunc_foo2
             main.CgoPprofCallback
             main._Cfunc_CheckM
             runtime.forcegchelper
-----------+-------------------------------------------------------

clang-15

$ CC=clang-15 ../../../../bin/go build -o testprogcgo-clang-15 && go tool pprof -traces ./testprogcgo-clang-15 $(./testprogcgo-clang-15 CgoPprof)
# runtime/testdata/testprogcgo
In file included from _cgo_export.c:4:
bindm.go:25:15: warning: passing arguments to 'GoCheckBindM' without a prototype is deprecated in all versions of C and is not supported in C2x [-Wdeprecated-non-prototype]
bindm.go:17:13: warning: a function declaration without a prototype is deprecated in all versions of C and is treated as a zero-parameter prototype in C2x, conflicting with a subsequent declaration [-Wdeprecated-non-prototype]
cgo-gcc-export-header-prolog:50:13: note: conflicting prototype is here
# runtime/testdata/testprogcgo
./bindm.go:25:15: warning: passing arguments to 'GoCheckBindM' without a prototype is deprecated in all versions of C and is not supported in C2x [-Wdeprecated-non-prototype]
# runtime/testdata/testprogcgo
In file included from aprof_c.c:5:
bindm.go:25:15: warning: passing arguments to 'GoCheckBindM' without a prototype is deprecated in all versions of C and is not supported in C2x [-Wdeprecated-non-prototype]
bindm.go:17:13: warning: a function declaration without a prototype is deprecated in all versions of C and is treated as a zero-parameter prototype in C2x, conflicting with a subsequent declaration [-Wdeprecated-non-prototype]
cgo-gcc-export-header-prolog:50:13: note: conflicting prototype is here
File: testprogcgo-clang-15
Build ID: 57e147c5c3713dc48115b4856c5c9a568154a3cc
Type: cpu
Time: Apr 6, 2023 at 8:07pm (EEST)
Duration: 1.10s, Total samples = 990ms (89.81%)
-----------+-------------------------------------------------------
     990ms   cpuHog
             cpuHog2
             runtime.cgocall
             main._Cfunc_cpuHog
             main.CgoPprof
             main.main
             runtime.main
-----------+-------------------------------------------------------

testprogcgo-zig-0.10.1.pptx

testprogcgo-clang-15.pptx

@prattmic

Do you get the same results if you drop the binary from the pprof cli?

I get an interactive pprof shell:

$ CC="/code/zig-linux-x86_64-0.10.1/zig cc" ../../../../bin/go build -o testprogcgo-zig-0.10.1 && go tool pprof $(./testprogcgo-zig-0.10.1 CgoPprof)
# runtime/testdata/testprogcgo
In file included from _cgo_export.c:4:
bindm.go:25:15: warning: passing arguments to 'GoCheckBindM' without a prototype is deprecated in all versions of C and is not supported in C2x [-Wdeprecated-non-prototype]
                GoCheckBindM((uintptr_t)thread);
                            ^
bindm.go:17:13: warning: a function declaration without a prototype is deprecated in all versions of C and is treated as a zero-parameter prototype in C2x, conflicting with a subsequent declaration [-Wdeprecated-non-prototype]
extern void GoCheckBindM();
            ^
cgo-gcc-export-header-prolog:50:13: note: conflicting prototype is here
extern void GoCheckBindM(GoUintptr thread);
            ^
2 warnings generated.
# runtime/testdata/testprogcgo
./bindm.go:25:15: warning: passing arguments to 'GoCheckBindM' without a prototype is deprecated in all versions of C and is not supported in C2x [-Wdeprecated-non-prototype]
                GoCheckBindM((uintptr_t)thread);
                            ^
1 warning generated.
# runtime/testdata/testprogcgo
In file included from aprof_c.c:5:
bindm.go:25:15: warning: passing arguments to 'GoCheckBindM' without a prototype is deprecated in all versions of C and is not supported in C2x [-Wdeprecated-non-prototype]
                GoCheckBindM((uintptr_t)thread);
                            ^
bindm.go:17:13: warning: a function declaration without a prototype is deprecated in all versions of C and is treated as a zero-parameter prototype in C2x, conflicting with a subsequent declaration [-Wdeprecated-non-prototype]
extern void GoCheckBindM();
            ^
cgo-gcc-export-header-prolog:50:13: note: conflicting prototype is here
extern void GoCheckBindM(GoUintptr thread);
            ^
2 warnings generated.
File: testprogcgo-zig-0.10.1
Type: cpu
Time: Apr 6, 2023 at 8:10pm (EEST)
Duration: 1.10s, Total samples = 990ms (89.81%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) 

[cherrymui]

In the new one the call stack also doesn't make much sense. Maybe the symbolization is completely broken. And you probably run CgoPprof correctly but as the symbolization is wrong it shows main.CgoPprofCallback instead...

Do you know how zig's linker is implemented? Does it wrap a C linker, or it has its own implementation? Is there anything special?

(I sent CL https://golang.org/cl/482975 to fix the C compiler warning.)

[motiejus]

In the new one the call stack also doesn't make much sense. Maybe the symbolization is completely broken. And you probably run CgoPprof correctly but as the symbolization is wrong it shows main.CgoPprofCallback instead...

Do you know how zig's linker is implemented? Does it wrap a C linker, or it has its own implementation? Is there anything special?

On linux it wraps clang for compiling and ld.lld for linking, adds a few flags.

One can see the exact lld invocations with ZIG_VERBOSE_LINK=1 zig cc <...>. I can paste the output here, but there is a lot of linking going on, so tell me which files to narrow it down to.

cc @andrewrk

(I sent CL https://golang.org/cl/482975 to fix the C compiler warning.)

Thanks!

[cherrymui]

Hmmm, the symbolization definitely is wrong. I ran the zig binary you pasted above. I got a profile, which contains a sample like

     5: 0x44875a M=1 main.CgoPprofCallback /code/go/src/runtime/testdata/testprogcgo/pprof_callback.go:64 s=0

But that PC is actually corresponding to main.CgoPprof:

$ go tool addr2line ./testprogcgo-zig-0.10.1.pptx 
0x44875a
main.CgoPprof
/code/go/src/runtime/testdata/testprogcgo/pprof.go:81

which looks correct.

So it seems the symbolization collected at run time by the profiler is wrong.

I wonder if you use zig to link a cgo program that just panics, does it print the right panic stack trace?

The zig linking is definitely somewhat unusual. For a quick look, it puts the text section after the rodata section, instead of before like other linkers usually do (this probably doesn't matter, I just noted this is something unusual I saw). I'll see if there is anything differs that could matter.