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.
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 <[email protected] > <javascript:>> wrote: > >> On Sun, Feb 25, 2018 at 3:30 PM, Caleb Spare <[email protected] >> <javascript:>> 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 <[email protected] >>> <javascript:>> wrote: >>> >>>> On Sun, Feb 25, 2018 at 2:01 PM, Caleb Spare <[email protected] >>>> <javascript:>> 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 [email protected]. For more options, visit https://groups.google.com/d/optout.
