On Sun, Feb 25, 2018 at 8:04 PM, Dave Cheney <d...@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 > > On Monday, 26 February 2018 14:02:13 UTC+11, Caleb Spare wrote: >> >> 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? >> >> On Sun, Feb 25, 2018 at 3:39 PM, Ian Lance Taylor <ia...@golang.org> >> wrote: >> >>> 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 >>> >>> >>> >>> >>>> On Sun, Feb 25, 2018 at 3:05 PM, Ian Lance Taylor <ia...@golang.org> >>>> wrote: >>>> >>>>> On Sun, Feb 25, 2018 at 2:01 PM, Caleb Spare <ces...@gmail.com> wrote: >>>>> >>>>>> 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. >>>>>> >>>>>> [image: Inline image 1] >>>>>> >>>>>> >>>>>> >>>>> >>>>> >>>>> >>>>> 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 >>>>> >>>> >>>> >>> >> -- > 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+unsubscr...@googlegroups.com. > For more options, visit https://groups.google.com/d/optout. > -- 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+unsubscr...@googlegroups.com. For more options, visit https://groups.google.com/d/optout.
