Re: Can someone help with the interpretation of pprof output?

[Volker Dobler]

Hard to tell without actual code.

pprof call graph look strange to me.

What happens if you replace

    time.Now().Month().String()

with a simple

    "April"

?

V.

Am Montag, 1. April 2013 19:45:21 UTC+2 schrieb Lars Grote:

Hi,

I'm a bit stuck with the interpretation of the pprof output that I'm getting. Here is quick explanation of what the program is doing:

The program takes csv like data as input and processes it line by line in a pipeline of steps. A step can be anything from simple mapping of columns to executing complex templates. Each step takes one line as input and emits zero or more lines. Each of those steps is running in it's own goroutine and they are connected by channels. 

The configuration that is used for this sample is a simple MappingStep that maps data from one Column to another and is able to prefix the data, the second step that is used executes two very simple text templates. 

{{ index .Cells 0 | replace "example" "ExampleReplace" }} 

and 

{{ thisMonth }} - {{ index .Cells 0}}

replace and thisMonth are very simple functions that I wrote. replace is quite obvious and thisMonth is nothing more than time.Now().Month().String()

I don't have much experience in writing efficient go code, but I do my best. I thought pprof could help me improve the performance of my program, but at the moment It doesn't help but confuses me ;)

I attached the svg file which is generated by pprof. Here are the top20:

    3411  73.6%  73.6%     4498  97.0% time.ParseDuration

     115   2.5%  76.0%      156   3.4% runtime.printeface

      70   1.5%  77.6%      294   6.3% time.Parse

      58   1.3%  78.8%     2293  49.5% reflect.Value.call

      58   1.3%  80.1%       59   1.3% runtime.interhash

      51   1.1%  81.2%      144   3.1% runtime.MCache_Alloc

      43   0.9%  82.1%       90   1.9% runtime.isNaN

      41   0.9%  83.0%      141   3.0% runtime.convT2I

      36   0.8%  83.7%       54   1.2% bufio.(*Reader).ReadRune

      31   0.7%  84.4%       51   1.1% runtime.assertE2T

      31   0.7%  85.1%       86   1.9% strings.IndexAny

      26   0.6%  85.6%       41   0.9% runtime.MCentral_FreeList

      23   0.5%  86.1%       67   1.4% reflect.(*commonType).Out

      23   0.5%  86.6%     2734  59.0% text/template.(*state).evalCall

      22   0.5%  87.1%      128   2.8% encoding/csv.(*Reader).parseField

      22   0.5%  87.6%       59   1.3% reflect.(*commonType).In

      21   0.5%  88.0%       33   0.7% bytes.(*Buffer).WriteByte

      21   0.5%  88.5%      263   5.7% text/template.(*state).evalField

      20   0.4%  88.9%       57   1.2% runtime.MCentral_AllocList

      20   0.4%  89.3%     3029  65.3% text/template.(*state).walk

As far as I understood this means that 97% of the cpu time (of the samples taken) is spend in time.ParseDuration. I don't call this function once in my code and I see no point why any of the standard library code that I'm using should do so. I don't use any packages that are not part of the standard library (thumbs up for the std lib).

The call hierarchy as far as I understand from the svg doesn't really help me in understanding what is happening. I would be great if some one could give me a hint how I can figure out what is going on here. 

Thanks for your time!

Lars

 

[Kamil Kisiel]

Are you profiling on OS X with go 1.0.3 by any chance? It's been known to produce inaccurate profiles.

[Lars Grote]

Hi Kamil, 

yes that is my exact setup. I didn't know about an issue with that. I'll try to run this test again on Linux. 

Thanks for your answer!

Lars

[Lars Grote]

Hi Volker, 

the graph loks more or less the same with out executing this templates at all. So the calling of time.Now().Month().String() can't be the root cause. Thanks for answer!

Lars

[Lars Grote]

Hi Kamil,

thanks for your quick and correct response! I compiled and profiled again on a virtual server. The result looks much more realistic. 

Thanks again,

Lars

On Monday, April 1, 2013 9:01:07 PM UTC+2, Kamil Kisiel wrote: