I went ahead and optimistically filed https://github.com/golang/go/issues/24142.
On Mon, Feb 26, 2018 at 2:35 PM, Caleb Spare <cesp...@gmail.com> wrote: > 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? > > On Mon, Feb 26, 2018 at 2:05 PM, Ian Lance Taylor <i...@golang.org> wrote: > >> On Mon, Feb 26, 2018 at 12:55 PM, Ian Lance Taylor <i...@golang.org> >> wrote: >> >>> 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. >>> >> >> >> Caleb: what do you think of https://golang.org/cl/97315? Would that >> have helped with your original problem? >> >> 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. >> > > -- 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.
