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.
