How to interpret runtime._ExternalCode in a profile?

[Caleb Spare]

How should I interpret runtime._System calling into runtime._ExternalCode in a pprof profile?

I saw this taking >10% of CPU time, so I recompiled with CGO_ENABLED=0 and even so I see 6.62% of time in runtime._ExternalCode.

runtime._System is a root in the graph so I can't even figure out what part of my code this might be related to.

[Caleb Spare]

It seems like the difference between 10% and 6% was that I had recently deployed the no-cgo build. It appears that, over time, the amount of time spent in ExternalCode in my program slowly increases.

This seems like it's probably related to the bug I was originally investigating, which is that this server seems to slowly increase CPU usage and decrease throughput over time. It might be a new 1.10 bug. I'm going to keep investigating and possibly open an issue.

[Ian Lance Taylor]

On Sun, Feb 25, 2018 at 2:01 PM, Caleb Spare <ces...@gmail.com> wrote:

This is what you see when a profililng signal occurs while executing code for which the Go runtime could not generate a traceback, and the thread was not running the garbage collector.  The most common reason for being unable to get a traceback is running in cgo code.

If you are running on an ELF based system like GNU/Linux then consider, for testing purposes only, importing github.com/ianlancetaylor/cgosymbolizer.  No need to actually use the package for anything, just do a blank import somewhere.  If you're lucky that will give you a more detailed profile.

Ian

[Caleb Spare]

There's no cgo in this program or any of its non-stdlib dependencies.

The server is a static binary built with CGO_ENABLED=0.​ Can there still be cgo code running somehow?

[Ian Lance Taylor]

On Sun, Feb 25, 2018 at 3:30 PM, Caleb Spare <ces...@gmail.com> wrote:

There's no cgo in this program or any of its non-stdlib dependencies.

The server is a static binary built with CGO_ENABLED=0.​ Can there still be cgo code running somehow?

No, if it's CGO_ENABLED=0, then I think cgo code can not be the problem.

But I also can't think of any other plausible reason to have so many hits for this case.  It can happen if the profiling signal is received while executing in `gogo`, `systemstack`, `mcall`, or `morestack`.  But none of those occur all that often and they run for a short time.  It's hard to believe that they would show up when profiling a real program.  I don't know what is happening here.

The code path you are seeing is the `n == 0` case in `sigprof` in runtime/proc.go.

Ian

[Caleb Spare]

On a hunch, I profiled a benchmark which just calls time.Now in a loop. Indeed: 95% of the time is attributed to runtime._System -> runtime._ExternalCode.

My program does collect a lot of timing information as it runs and ends up calling time.Now quite a lot. I don't yet know for sure that most/all of the runtime._ExternalCode that shows up in my program's profile is time.Now, but that wouldn't surprise me.

This makes me curious: would it be feasible to make the profiler recognize a vDSO call and synthesize a more helpful stack?

[Dave Cheney]

I don't understand how that could happen. time.Now calls time.now (which is in assembly) so the former shouldn't be inlined, or omitted from profiling.

[Ian Lance Taylor]

On Sun, Feb 25, 2018 at 8:04 PM, Dave Cheney <da...@cheney.net> wrote:

I don't understand how that could happen. time.Now calls time.now (which is in assembly) so the former shouldn't be inlined, or omitted from profiling.

But on amd64 GNU/Linux time.Now is implemented by calling into the VDSO.  And it's true that if the profiling signal occurs while executing in the VDSO then the profiler will not be able to map the PC to any Go function, so the traceback will fail, and the profiler will indeed report  _System calling _ExternalCode.  Well spotted.

Ian

 

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Dave Cheney]

Ahh, thank you. That was the missing piece of my understanding.

[Ian Lance Taylor]

On Mon, Feb 26, 2018 at 12:55 PM, Ian Lance Taylor <ia...@golang.org> wrote:

On Sun, Feb 25, 2018 at 8:04 PM, Dave Cheney <da...@cheney.net> wrote:

I don't understand how that could happen. time.Now calls time.now (which is in assembly) so the former shouldn't be inlined, or omitted from profiling.

But on amd64 GNU/Linux time.Now is implemented by calling into the VDSO.  And it's true that if the profiling signal occurs while executing in the VDSO then the profiler will not be able to map the PC to any Go function, so the traceback will fail, and the profiler will indeed report  _System calling _ExternalCode.  Well spotted.

Caleb: what do you think of https://golang.org/cl/97315?  Would that have helped with your original problem?

[Caleb Spare]

I think that CL that would have helped me realize it was (probably) time.Now sooner. It certainly seems like a Pareto improvement.

However:

(1) I don't think that most Go developers know what _VDSO is any more than they know what _ExternalCode is, so it probably won't substantially help most pprof users. (Perhaps some Googling will lead to this conversation, though.)

(2) The thing that makes this unhelpful is that fact that _ExternalCode or _VDSO is disconnected from the Go stack that called it. If I have a program that, say, has a bunch of CPU overhead from calling os.Stat a bunch, then it should be clear from the profile where the call is coming from even if the big red box is just labeled syscall.Syscall.

I was about to file a bug asking for pprof to somehow understand that a particular VDSO call is connected to a particular time.Now call. Is that even possible/feasible?

[Caleb Spare]

I went ahead and optimistically filed https://github.com/golang/go/issues/24142.