FAQ
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


--
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+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

Search Discussions

  • Volker Dobler at Apr 1, 2013 at 6:45 pm
    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
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Lars Grote at Apr 1, 2013 at 7:16 pm
    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
    On Monday, April 1, 2013 8:45:01 PM UTC+2, Volker Dobler wrote:

    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
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Kamil Kisiel at Apr 1, 2013 at 7:01 pm
    Are you profiling on OS X with go 1.0.3 by any chance? It's been known to
    produce inaccurate profiles.
    On Monday, April 1, 2013 10:45:21 AM UTC-7, Lars Grote wrote:

    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
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Lars Grote at Apr 1, 2013 at 7:08 pm
    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



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

    Are you profiling on OS X with go 1.0.3 by any chance? It's been known to
    produce inaccurate profiles.
    On Monday, April 1, 2013 10:45:21 AM UTC-7, Lars Grote wrote:

    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
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Lars Grote at Apr 1, 2013 at 7:58 pm
    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:

    Are you profiling on OS X with go 1.0.3 by any chance? It's been known to
    produce inaccurate profiles.
    On Monday, April 1, 2013 10:45:21 AM UTC-7, Lars Grote wrote:

    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
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
groupgolang-nuts @
categoriesgo
postedApr 1, '13 at 5:52p
activeApr 1, '13 at 7:58p
posts6
users3
websitegolang.org

People

Translate

site design / logo © 2022 Grokbase