How to obtain complete call chain of runtime functions in pprof, like 'mcall'

[Xiangdong JI]

Hi,

Given the attached screenshot of pprof output, I wonder how to figure out the callers of 'runtime.mcall' and their cost? Thanks.

(The image is generated by profiling BenchmarkGoroutineBlocking).

[Ian Lance Taylor]

On Wed, Mar 4, 2020 at 6:44 PM Xiangdong JI <xiangd...@arm.com> wrote:
>
> Given the attached screenshot of pprof output, I wonder how to figure out the callers of 'runtime.mcall' and their cost? Thanks.

You can't, but it doesn't matter. The mcall function is used when a
thread changes from executing one goroutine to a different goroutine.
Knowing the code that triggers the call into mcall won't tell you
anything. It's just where that goroutine happened to be preempted.

Ian

[Xiangdong JI]

Thanks Ian.

I'm using schedtrace and scheddetail to help understand the scheduling flow, the minimum monitoring window seems to be 1ms only, possible to get more detailed info?

Furthermore, sched* outputs extensive logs but what I expect, at present, might be something like when a goroutine is parked due to what reason, etc., can I get it with the existing diagnostics?  

 

On Thursday, March 5, 2020 at 11:24:23 AM UTC+8, Ian Lance Taylor wrote:

[Robert Engels]

You might be interested in github.com/robaho/go-analyzer which I believe significantly improves the profiling information when dealing with highly concurrent Go programs. 

On Mar 5, 2020, at 12:13 AM, Xiangdong JI <xiangd...@arm.com> wrote:



--
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...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/71ecd07a-0b42-4eba-9b22-5c7cc9821243%40googlegroups.com.

[Jake Montgomery]

I think you meant https://github.com/robaho/goanalyzer

On Thursday, March 5, 2020 at 7:09:18 AM UTC-5, Robert Engels wrote:

You might be interested in github.com/robaho/go-analyzer which I believe significantly improves the profiling information when dealing with highly concurrent Go programs. 

On Mar 5, 2020, at 12:13 AM, Xiangdong JI <xiang...@arm.com> wrote:



Thanks Ian.

I'm using schedtrace and scheddetail to help understand the scheduling flow, the minimum monitoring window seems to be 1ms only, possible to get more detailed info?

Furthermore, sched* outputs extensive logs but what I expect, at present, might be something like when a goroutine is parked due to what reason, etc., can I get it with the existing diagnostics?  

 

On Thursday, March 5, 2020 at 11:24:23 AM UTC+8, Ian Lance Taylor wrote:

On Wed, Mar 4, 2020 at 6:44 PM Xiangdong JI <xiang...@arm.com> wrote:
>
> Given the attached screenshot of pprof output, I wonder how to figure out the callers of 'runtime.mcall' and their cost? Thanks.

You can't, but it doesn't matter.  The mcall function is used when a
thread changes from executing one goroutine to a different goroutine.
Knowing the code that triggers the call into mcall won't tell you
anything.  It's just where that goroutine happened to be preempted.

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 golan...@googlegroups.com.

[Ian Lance Taylor]

On Wed, Mar 4, 2020 at 10:12 PM Xiangdong JI <xiangd...@arm.com> wrote:
>
> I'm using schedtrace and scheddetail to help understand the scheduling flow, the minimum monitoring window seems to be 1ms only, possible to get more detailed info?
> Furthermore, sched* outputs extensive logs but what I expect, at present, might be something like when a goroutine is parked due to what reason, etc., can I get it with the existing diagnostics?

Calling runtime.Stack(buf, true) should tell you for each parked
goroutine why it is parked. Of course it will also give you a lot
more that you don't care about, like the stack backtraces.

Ian

>
> On Thursday, March 5, 2020 at 11:24:23 AM UTC+8, Ian Lance Taylor wrote:
>>
>> On Wed, Mar 4, 2020 at 6:44 PM Xiangdong JI <xiang...@arm.com> wrote:
>> >
>> > Given the attached screenshot of pprof output, I wonder how to figure out the callers of 'runtime.mcall' and their cost? Thanks.
>>
>> You can't, but it doesn't matter. The mcall function is used when a
>> thread changes from executing one goroutine to a different goroutine.
>> Knowing the code that triggers the call into mcall won't tell you
>> anything. It's just where that goroutine happened to be preempted.
>>
>> 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...@googlegroups.com.

[Xiangdong JI]

Thanks Robert, I'm trying to utilize the tool now, the new output rendered by goanalyzer contains a page for PC:0 goroutines, which were discussed in #29103, but seems no further details are available, are they considered irrelevant to perf. analysis? 

On Thursday, March 5, 2020 at 8:09:18 PM UTC+8, Robert Engels wrote:

You might be interested in github.com/robaho/go-analyzer which I believe significantly improves the profiling information when dealing with highly concurrent Go programs. 

On Mar 5, 2020, at 12:13 AM, Xiangdong JI <xiang...@arm.com> wrote:



Thanks Ian.

I'm using schedtrace and scheddetail to help understand the scheduling flow, the minimum monitoring window seems to be 1ms only, possible to get more detailed info?

Furthermore, sched* outputs extensive logs but what I expect, at present, might be something like when a goroutine is parked due to what reason, etc., can I get it with the existing diagnostics?  

 

On Thursday, March 5, 2020 at 11:24:23 AM UTC+8, Ian Lance Taylor wrote:

On Wed, Mar 4, 2020 at 6:44 PM Xiangdong JI <xiang...@arm.com> wrote:
>
> Given the attached screenshot of pprof output, I wonder how to figure out the callers of 'runtime.mcall' and their cost? Thanks.

You can't, but it doesn't matter.  The mcall function is used when a
thread changes from executing one goroutine to a different goroutine.
Knowing the code that triggers the call into mcall won't tell you
anything.  It's just where that goroutine happened to be preempted.

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 golan...@googlegroups.com.

[Robert Engels]

I think they are relevant. It is because the profiler only records a record when there is a state transition, which is fine, but then the record needs to reflect it, and probably should at least point to the previous record - that is - use the same stack trace, so the accounting is correct. 

Seems like a bug to me but it doesn’t appear the Go team either felt the same, or had any desire to fix it. 

On Mar 8, 2020, at 12:37 PM, Xiangdong JI <xiangd...@arm.com> wrote:



To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/5b1f728e-68c5-407e-98c6-5e366fc28e53%40googlegroups.com.