reduce allocations when printing stack traces (#149)

[cstockton]

This implements proposal in #149 by adding a format method to Frame that accepts an io.Writer, allowing stack and StackTrace to grow a bytes.Buffer ahead of time. The benefits are illustrated in the benchmark comparison below, in summary allocations are reduced by 90-97% resulting in a 40-55% performance boost.

This comes at a slight cost in bytes used, which is around 5% higher on average with a single case reaching 36% (small stack, %s) which is probably not worth special casing. This trade off can be affected by adjusting stackMinLen with a more generous multiplier, lowering allocations at the expense of unused buffer.

benchmark                                         old ns/op     new ns/op     delta
BenchmarkStackFormatting/%s-stack-10-24           411           402           -2.19%
BenchmarkStackFormatting/%v-stack-10-24           411           416           +1.22%
BenchmarkStackFormatting/%+v-stack-10-24          29551         17147         -41.97%
BenchmarkStackFormatting/%s-stack-30-24           377           410           +8.75%
BenchmarkStackFormatting/%v-stack-30-24           411           385           -6.33%
BenchmarkStackFormatting/%+v-stack-30-24          65337         29997         -54.09%
BenchmarkStackFormatting/%s-stack-60-24           444           396           -10.81%
BenchmarkStackFormatting/%v-stack-60-24           441           385           -12.70%
BenchmarkStackFormatting/%+v-stack-60-24          67739         31652         -53.27%
BenchmarkStackFormatting/%s-stacktrace-10-24      12894         7409          -42.54%
BenchmarkStackFormatting/%v-stacktrace-10-24      20893         11611         -44.43%
BenchmarkStackFormatting/%+v-stacktrace-10-24     31120         17046         -45.22%
BenchmarkStackFormatting/%s-stacktrace-30-24      24363         13724         -43.67%
BenchmarkStackFormatting/%v-stacktrace-30-24      48716         23995         -50.75%
BenchmarkStackFormatting/%+v-stacktrace-30-24     68169         31939         -53.15%
BenchmarkStackFormatting/%s-stacktrace-60-24      25448         14208         -44.17%
BenchmarkStackFormatting/%v-stacktrace-60-24      46780         24099         -48.48%
BenchmarkStackFormatting/%+v-stacktrace-60-24     68103         34016         -50.05%

benchmark                                         old allocs     new allocs     delta
BenchmarkStackFormatting/%s-stack-10-24           2              2              +0.00%
BenchmarkStackFormatting/%v-stack-10-24           2              2              +0.00%
BenchmarkStackFormatting/%+v-stack-10-24          77             7              -90.91%
BenchmarkStackFormatting/%s-stack-30-24           2              2              +0.00%
BenchmarkStackFormatting/%v-stack-30-24           2              2              +0.00%
BenchmarkStackFormatting/%+v-stack-30-24          162            4              -97.53%
BenchmarkStackFormatting/%s-stack-60-24           2              2              +0.00%
BenchmarkStackFormatting/%v-stack-60-24           2              2              +0.00%
BenchmarkStackFormatting/%+v-stack-60-24          162            4              -97.53%
BenchmarkStackFormatting/%s-stacktrace-10-24      33             4              -87.88%
BenchmarkStackFormatting/%v-stacktrace-10-24      63             7              -88.89%
BenchmarkStackFormatting/%+v-stacktrace-10-24     77             7              -90.91%
BenchmarkStackFormatting/%s-stacktrace-30-24      67             4              -94.03%
BenchmarkStackFormatting/%v-stacktrace-30-24      131            4              -96.95%
BenchmarkStackFormatting/%+v-stacktrace-30-24     162            4              -97.53%
BenchmarkStackFormatting/%s-stacktrace-60-24      67             4              -94.03%
BenchmarkStackFormatting/%v-stacktrace-60-24      131            4              -96.95%
BenchmarkStackFormatting/%+v-stacktrace-60-24     162            4              -97.53%

benchmark                                         old bytes     new bytes     delta
BenchmarkStackFormatting/%s-stack-10-24           16            16            +0.00%
BenchmarkStackFormatting/%v-stack-10-24           16            16            +0.00%
BenchmarkStackFormatting/%+v-stack-10-24          2647          2954          +11.60%
BenchmarkStackFormatting/%s-stack-30-24           16            16            +0.00%
BenchmarkStackFormatting/%v-stack-30-24           16            16            +0.00%
BenchmarkStackFormatting/%+v-stack-30-24          5923          6269          +5.84%
BenchmarkStackFormatting/%s-stack-60-24           16            16            +0.00%
BenchmarkStackFormatting/%v-stack-60-24           16            16            +0.00%
BenchmarkStackFormatting/%+v-stack-60-24          5923          6269          +5.84%
BenchmarkStackFormatting/%s-stacktrace-10-24      632           864           +36.71%
BenchmarkStackFormatting/%v-stacktrace-10-24      920           924           +0.43%
BenchmarkStackFormatting/%+v-stacktrace-10-24     2671          2975          +11.38%
BenchmarkStackFormatting/%s-stacktrace-30-24      1313          1521          +15.84%
BenchmarkStackFormatting/%v-stacktrace-30-24      1922          1617          -15.87%
BenchmarkStackFormatting/%+v-stacktrace-30-24     5949          6295          +5.82%
BenchmarkStackFormatting/%s-stacktrace-60-24      1313          1521          +15.84%
BenchmarkStackFormatting/%v-stacktrace-60-24      1922          1617          -15.87%
BenchmarkStackFormatting/%+v-stacktrace-60-24     5949          5910          -0.66%

[cstockton]

Would you like any additional work done for this pull req @davecheney ?

[gregwebs]

@lysu do you want to pull this into our fork?

[cstockton]

@davecheney I'm glad to see performance improvements get in, was there any improvements I could have made to the patch that could have allowed me to maintain authorship?

I was trying to follow the commits above to see if I made any mistakes, from the diff it appears you didn't want to Grow a buffer? This has a pretty big impact on performance of the patch in the common %+v scenario:

BenchmarkStackFormatting/%+v-stack-10-24          15221         21093         +38.58%
BenchmarkStackFormatting/%+v-stack-30-24          28797         43941         +52.59%
BenchmarkStackFormatting/%+v-stack-60-24          28479         42015         +47.53%

BenchmarkStackFormatting/%+v-stack-10-24          6              19             +216.67%
BenchmarkStackFormatting/%+v-stack-30-24          3              33             +1000.00%
BenchmarkStackFormatting/%+v-stack-60-24          3              33             +1000.00%

That said I would have been happy to remove it to maintain authorship for the work I put into fixing this and patiently waiting for it to be reviewed and merged, just something to consider for your future contributors. Thanks.

[davecheney]

Please send a diff with the grow change. When I merged your change I found that it didn’t affect the benchmarks so I removed it. Please feel free to send a PR with it added back.

Sorry about obscuring the authorship, merge conflict and reverting other changes to this file were the cause.

On 28 Jan 2019, at 03:53, Chris Stockton notifications@github.com wrote:

@davecheney I'm glad to see performance improvements get in, was there any improvements I could have made to the patch that could have allowed me to maintain authorship?

I was trying to follow the commits above to see if I made any mistakes, from the diff it appears you didn't want to Grow a buffer? This has a pretty big impact on performance of the patch in the common %+v scenario:

BenchmarkStackFormatting/%+v-stack-10-24 15221 21093 +38.58% BenchmarkStackFormatting/%+v-stack-30-24 28797 43941 +52.59% BenchmarkStackFormatting/%+v-stack-60-24 28479 42015 +47.53%

BenchmarkStackFormatting/%+v-stack-10-24 6 19 +216.67% BenchmarkStackFormatting/%+v-stack-30-24 3 33 +1000.00% BenchmarkStackFormatting/%+v-stack-60-24 3 33 +1000.00% That said I would have been happy to remove it to maintain authorship for the work I put into fixing this and patiently waiting for it to be reviewed and merged, just something to consider for your future contributors. Thanks.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.