Thanks for the clarification Than & Robert,
I think I'm understanding how to read the tree now. In order to discern the
call hierarchy
for an entry,I look at the caller/s and then can search the tree for the
caller/s and then
look at the caller's caller/s... etc.
One thing that is still puzzling me though is that I would expect the "cum"
value for the
caller of a function to be at least as big as the "cum" of the callee.
In this case it there is only one entry that is the caller of time.now and
that is time.Now time.now has a "cum" of 15.59% where time.Now has 0.03%.
I'm pasting the full output of the pprof execution below, in case it is
helpful to diagnose any problem, if there is a problem.
$ go tool pprof -tree -edgefraction 0 -nodefraction 0 -nodecount 100000
-focus time.now cpu.prof
File: worker.test
Build ID: eb61fef12cfb2b944ae334117319bec71750a839
Type: cpu
Time: Oct 19, 2019 at 9:21am (BST)
Duration: 1.21mins, Total samples = 132.61s (182.50%)
Active filters:
focus=time.now
Showing nodes accounting for 20.68s, 15.59% of 132.61s total
----------------------------------------------------------+-------------
flat flat% sum% cum cum% calls calls% + context
----------------------------------------------------------+-------------
0.04s 0.19% | time.Now
20.65s 15.57% 15.57% 20.68s 15.59% | time.now
0.03s 0.15% |
runtime.nanotime
----------------------------------------------------------+-------------
0.03s 100% | time.now
0.03s 0.023% 15.59% 0.03s 0.023% | runtime.nanotime
----------------------------------------------------------+-------------
0.02s 100% |
github.com/piersy/new_project/worker.NewWorker.func1
0 0% 15.59% 0.02s 0.015% |
github.com/piersy/new_project/network.(*Connection).ReadMessage
0.02s 100% |
github.com/piersy/new_project/network.(*Connection).read
----------------------------------------------------------+-------------
0.01s 100% |
github.com/piersy/new_project/worker.(*Listener).listen.func1
0 0% 15.59% 0.01s 0.0075% |
github.com/piersy/new_project/network.(*Connection).WriteTypedBytes
0.01s 100% |
github.com/piersy/new_project/network.(*Connection).write
----------------------------------------------------------+-------------
0.02s 100% |
github.com/piersy/new_project/network.(*Connection).ReadMessage
0 0% 15.59% 0.02s 0.015% |
github.com/piersy/new_project/network.(*Connection).read
0.02s 100% | time.Now
----------------------------------------------------------+-------------
0.01s 100% |
github.com/piersy/new_project/network.(*Connection).WriteTypedBytes
0 0% 15.59% 0.01s 0.0075% |
github.com/piersy/new_project/network.(*Connection).write
0.01s 100% | time.Now
----------------------------------------------------------+-------------
0.01s 50.00% |
github.com/piersy/connecter.(*Connecter).connect.func1
0 0% 15.59% 0.02s 0.015% |
github.com/piersy/connecter.(*Connecter).handle
0.02s 100% |
github.com/piersy/new_project/worker.NewWorker.func1
----------------------------------------------------------+-------------
0 0% 15.59% 0.01s 0.0075% |
github.com/piersy/connecter.(*Connecter).connect.func1
0.01s 100% |
github.com/piersy/connecter.(*Connecter).handle
----------------------------------------------------------+-------------
0 0% 15.59% 0.01s 0.0075% |
github.com/piersy/new_project/worker.(*Listener).listen.func1
0.01s 100% |
github.com/piersy/new_project/network.(*Connection).WriteTypedBytes
----------------------------------------------------------+-------------
0.02s 100% |
github.com/piersy/connecter.(*Connecter).handle
0 0% 15.59% 0.02s 0.015% |
github.com/piersy/new_project/worker.NewWorker.func1
0.02s 100% |
github.com/piersy/new_project/network.(*Connection).ReadMessage
----------------------------------------------------------+-------------
0 0% 15.59% 0.01s 0.0075% |
runtime.timerproc
0.01s 100% | time.sendTime
----------------------------------------------------------+-------------
0.02s 50.00% |
github.com/piersy/new_project/network.(*Connection).read
0.01s 25.00% |
github.com/piersy/new_project/network.(*Connection).write
0.01s 25.00% | time.sendTime
0 0% 15.59% 0.04s 0.03% | time.Now
0.04s 100% | time.now
----------------------------------------------------------+-------------
0.01s 100% |
runtime.timerproc
0 0% 15.59% 0.01s 0.0075% | time.sendTime
0.01s 100% | time.Now
----------------------------------------------------------+-------------
On Mon, Oct 21, 2019 at 2:11 PM Robert Engels <reng...@ix.netcom.com> wrote:
> Yes, that’s what I was referring to. It is much easier then the graph in
> some cases.
>
> Also github.com/robaho/goanalyzer might help depending on the workload
>
> On Oct 21, 2019, at 2:10 AM, Than McIntosh <th...@google.com> wrote:
>
>
> It can sometimes be useful in such situations to look at the pprof "tree"
> output style (as opposed to graph).
>
> Than
>
>
> On Sat, Oct 19, 2019 at 4:14 AM Piers Powlesland <
> pierspowlesl...@gmail.com> wrote:
>
>> Kind of, but due to the sheer number of nodes and edged the edges end up
>> lying on top of each other so in certain cases you end up having to check
>> the source of several nodes to see which is the caller.
>>
>> On Sat, 19 Oct 2019, 03:08 Robert Engels, <reng...@ix.netcom.com> wrote:
>>
>>> But also can’t you just find that node in the graph and see the callers?
>>>
>>> On Oct 18, 2019, at 8:54 PM, Robert Engels <reng...@ix.netcom.com>
>>> wrote:
>>>
>>>
>>> Yes. When using the command pprof viewer there is a way to show the
>>> hotspots with the callers. Again I don’t have access to dev at the moment.
>>>
>>> On Oct 18, 2019, at 8:44 PM, Piers Powlesland <pierspowlesl...@gmail.com>
>>> wrote:
>>>
>>>
>>> Hi Robert,
>>>
>>> I think I found the options you were referring to, and I was able to get
>>> the whole overview with the following.
>>>
>>> go tool pprof -http :9999 -edgefraction 0 -nodefraction 0 -nodecount
>>> 100000 cpu.prof
>>>
>>> Its a bit of a screenfull though, and I was wondering if there is any
>>> simpler way to find out who is calling what?
>>> So that I could dig down through top and if the function isn't in my
>>> code follow the callstack to find what part of my code
>>> initiated the call.
>>>
>>> On Fri, Oct 18, 2019 at 8:52 PM Robert Engels <reng...@ix.netcom.com>
>>> wrote:
>>>
>>>> I am pretty sure there is a way to filter nodes that are less than X %,
>>>> and some of that filtering is on by default - so you may want to turn that
>>>> off (can't say for sure since not at dev machine right now).
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> -----Original Message-----
>>>> >From: Ian Lance Taylor <i...@golang.org>
>>>> >Sent: Oct 18, 2019 2:43 PM
>>>> >To: Piers Powlesland <pierspowlesl...@gmail.com>
>>>> >Cc: golang-nuts <golang-nuts@googlegroups.com>
>>>> >Subject: Re: [go-nuts] pprof not showing call hierarchy for time.now
>>>> and time.Until
>>>> >
>>>> >On Fri, Oct 18, 2019 at 12:37 PM <pierspowlesl...@gmail.com> wrote:
>>>> >>
>>>> >> I used pprof to get an overview of where time is being spent in my
>>>> latest project and I'm
>>>> >> getting a result I don't understand. When using the web view, there
>>>> are certain function
>>>> >> calls that are taking up a large percentage of the time but they
>>>> appear un-rooted as in
>>>> >> there seems to be no parent call calling them.
>>>> >>
>>>> >> I have attached a picture of the web view showing just the un-rooted
>>>> functions.
>>>> >>
>>>> >> I generated the profile with the following command.
>>>> >>
>>>> >> go test -cpuprofile cpu.prof -count 4 . -run MyTest
>>>> >>
>>>> >> and I viewed the profile with the following command.
>>>> >>
>>>> >> go tool pprof -http :9999 cpu.prof
>>>> >>
>>>> >> I'd really like to track down what is causing all this time in the
>>>> time package, but I'm
>>>> >> at a bit of a loss.
>>>> >
>>>> >Which version of Go and which GOOS/GOARCH? There have been bugs in
>>>> >this area in the past, and at least some of them are fixed in 1.13.
>>>> >
>>>> >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.
>>>> >To view this discussion on the web visit
>>>> https://groups.google.com/d/msgid/golang-nuts/CAOyqgcWReW9e79szp29F11nmvVEzhZr7O%3D1Qp5WXkGBLwWprBA%40mail.gmail.com
>>>> .
>>>>
>>> --
>>> 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.
>>> To view this discussion on the web visit
>>> https://groups.google.com/d/msgid/golang-nuts/876AA5BF-E048-4A7D-8842-9E40B3F9FA26%40ix.netcom.com
>>> <https://groups.google.com/d/msgid/golang-nuts/876AA5BF-E048-4A7D-8842-9E40B3F9FA26%40ix.netcom.com?utm_medium=email&utm_source=footer>
>>> .
>>>
>>> --
>> 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.
>> To view this discussion on the web visit
>> https://groups.google.com/d/msgid/golang-nuts/CAFXacX%3DJrvC8VqUs%2BCQr0SOBgfH4vtO5fyrYGVFidduH067OrA%40mail.gmail.com
>> <https://groups.google.com/d/msgid/golang-nuts/CAFXacX%3DJrvC8VqUs%2BCQr0SOBgfH4vtO5fyrYGVFidduH067OrA%40mail.gmail.com?utm_medium=email&utm_source=footer>
>> .
>>
>
--
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.
To view this discussion on the web visit
https://groups.google.com/d/msgid/golang-nuts/CAFXacXnC1Nhwoa6RYnLuPgKyowQN8XMYAF9UU8MmmGnsLm-sJw%40mail.gmail.com.
