Re: [go-nuts] How to interpret runtime._ExternalCode in a profile?

[Caleb Spare]

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

On Mon, Feb 26, 2018 at 2:35 PM, Caleb Spare  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  wrote:
>
>> On Mon, Feb 26, 2018 at 12:55 PM, Ian Lance Taylor 
>> wrote:
>>
>>> On Sun, Feb 25, 2018 at 8:04 PM, Dave Cheney  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 
> wrote:
>
>> On Sun, Feb 25, 2018 at 3:30 PM, Caleb Spare 
>> 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 
>>> wrote:
>>>
 On Sun, Feb 25, 2018 at 2:01 PM, Caleb Spare 
 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
 

Re: [go-nuts] How to interpret runtime._ExternalCode in a profile?

[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?

On Mon, Feb 26, 2018 at 2:05 PM, Ian Lance Taylor  wrote:

> On Mon, Feb 26, 2018 at 12:55 PM, Ian Lance Taylor 
> wrote:
>
>> On Sun, Feb 25, 2018 at 8:04 PM, Dave Cheney  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 
 wrote:

> On Sun, Feb 25, 2018 at 3:30 PM, Caleb Spare  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 
>> wrote:
>>
>>> On Sun, Feb 25, 2018 at 2:01 PM, Caleb Spare 
>>> 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 

Re: [go-nuts] How to interpret runtime._ExternalCode in a profile?

[Ian Lance Taylor]

On Mon, Feb 26, 2018 at 12:55 PM, Ian Lance Taylor  wrote:

> On Sun, Feb 25, 2018 at 8:04 PM, Dave Cheney  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 
>>> wrote:
>>>
 On Sun, Feb 25, 2018 at 3:30 PM, Caleb Spare  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 
> wrote:
>
>> On Sun, Feb 25, 2018 at 2:01 PM, Caleb Spare 
>> 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.

Re: [go-nuts] How to interpret runtime._ExternalCode in a profile?

[Dave Cheney]

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

-- 
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.

Re: [go-nuts] How to interpret runtime._ExternalCode in a profile?

[Ian Lance Taylor]

On Sun, Feb 25, 2018 at 8:04 PM, Dave Cheney  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 
>> wrote:
>>
>>> On Sun, Feb 25, 2018 at 3:30 PM, Caleb Spare  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 
 wrote:

> On Sun, Feb 25, 2018 at 2:01 PM, Caleb Spare  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.

Re: [go-nuts] How to interpret runtime._ExternalCode in a profile?

[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.

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  > wrote:
>
>> On Sun, Feb 25, 2018 at 3:30 PM, Caleb Spare > > 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 >> > wrote:
>>>
 On Sun, Feb 25, 2018 at 2:01 PM, Caleb Spare  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.