pprof not showing call hierarchy for time.now and time.Until

pierspo...@gmail.com

unread,

Oct 18, 2019, 3:37:23 PM10/18/19

to golang-nuts

Hi there,

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.

All help appreciated.

Thanks,

Piers

pprof.png

Ian Lance Taylor

unread,

Oct 18, 2019, 3:44:02 PM10/18/19

to Piers Powlesland, golang-nuts

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

Robert Engels

unread,

Oct 18, 2019, 3:52:47 PM10/18/19

to Ian Lance Taylor, Piers Powlesland, golang-nuts

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

>--
>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/CAOyqgcWReW9e79szp29F11nmvVEzhZr7O%3D1Qp5WXkGBLwWprBA%40mail.gmail.com.

Piers Powlesland

unread,

Oct 18, 2019, 8:57:11 PM10/18/19

to Ian Lance Taylor, golang-nuts

Hi Ian,

I was on go1.13.2 linux/amd64 so i upgraded to go1.13.3 linux/amd64.

I'm still seeing the same problem.

Piers Powlesland

unread,

Oct 18, 2019, 9:44:45 PM10/18/19

to Robert Engels, Ian Lance Taylor, golang-nuts

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.

Robert Engels

unread,

Oct 18, 2019, 9:54:28 PM10/18/19

to Piers Powlesland, Ian Lance Taylor, golang-nuts

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 <pierspo...@gmail.com> wrote:

Robert Engels

unread,

Oct 18, 2019, 10:09:13 PM10/18/19

to Piers Powlesland, Ian Lance Taylor, golang-nuts

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 <ren...@ix.netcom.com> wrote:

To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/876AA5BF-E048-4A7D-8842-9E40B3F9FA26%40ix.netcom.com.

Piers Powlesland

unread,

Oct 19, 2019, 4:14:35 AM10/19/19

to Robert Engels, Ian Lance Taylor, golang-nuts

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.

Than McIntosh

unread,

Oct 21, 2019, 3:11:01 AM10/21/19

to Piers Powlesland, Robert Engels, Ian Lance Taylor, golang-nuts

It can sometimes be useful in such situations to look at the pprof "tree" output style (as opposed to graph).

Than

To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/CAFXacX%3DJrvC8VqUs%2BCQr0SOBgfH4vtO5fyrYGVFidduH067OrA%40mail.gmail.com.

Piers Powlesland

unread,

Oct 21, 2019, 7:19:33 AM10/21/19

to Than McIntosh, Robert Engels, Ian Lance Taylor, golang-nuts

Hi Than,

Thanks for the tip.

I actually discovered that selecting a node and using the Focus option from the Refine in
the web view gets me a clear view of the callers and callees for the selected node.

I have tried the tree view, passing the focus option on the command line but I' don't understand

how to read it.

Here is a snippet from the top of the output for tree

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).Read
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).Write
0.01s 100% | github.com/piersy/new_project/network.(*Connection).write
----------------------------------------------------------+-------------
0.02s 100% | github.com/piersy/new_project/network.(*Connection).Read
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).Write
0 0% 15.59% 0.01s 0.0075% | github.com/piersy/new_project/network.(*Connection).write
0.01s 100% | time.Now
----------------------------------------------------------+-------------

In the web view when focused on time.now I can see the lower entries entries appearing in the call

hierarchy leading to time.now, but here in the tree view they appear disconnected, the only hint that

these entries call time.now is that I used the focus flag to focus on time.now.

In the case that I haven't used the focus flag, I'm wondering how I would be able to relate entries in

the tree to one another?

I also tried using the peek flag, which if set to time.now, only prints the first

entry from the tree output above.

Than McIntosh

unread,

Oct 21, 2019, 8:21:38 AM10/21/19

to Piers Powlesland, Robert Engels, Ian Lance Taylor, golang-nuts

The "tree" output format is modeled approximately after the output of the ancient unix tool "gprof" (see https://ftp.gnu.org/old-gnu/Manuals/gprof-2.9.1/html_chapter/gprof_5.html).

For tree output, you'll see entries of the form

Caller(s)
<flat> <cum> Function
Callee(s)

where "flat" shows the time spent in "Function" itself (as opposed to in things that "Function" calls) and "cum" shows total time spent inside the function (e.g. includes callees).

If you have a leaf function, then you would expect that "flat" == "cum". If you have a function that does very little but calls something that takes a long time, then you would expect that "flat" is small but "cum" is large.

With that, the fragment of the tree profile you sent seems pretty weird. The time.now function calls walltime and nanotime, both of which invoke VDSO functions on linux -- from the perspective of a non-expert in Go runtime stuff, I am not sure why there would be a lot of time attributed to time.now itself and not the functions it calls (stack switching, maybe?).

Than

Robert Engels

unread,

Oct 21, 2019, 9:12:36 AM10/21/19

to Than McIntosh, Piers Powlesland, Ian Lance Taylor, golang-nuts

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:

Piers Powlesland

unread,

Oct 21, 2019, 11:32:40 AM10/21/19

to Robert Engels, Than McIntosh, Ian Lance Taylor, golang-nuts

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

Reply all

Reply to author

Forward