Do timer allocation and string building outside of bench loops

Committed: http://code.google.com/p/skia/source/detail?r=10372

Committed: http://code.google.com/p/skia/source/detail?r=10473

[bsalomon, 2013-07-24 19:51:01]

I'm not saying this is perfect but it seems a lot cleaner to me and makes it
possible to profile bench with a long repeat count without seeing timer string
concats show up. Now the allocations for timer values are done up front. The
determination of the average, min, and string are done at the end.

AFAICT bench and bench_pictures take flags that control whether per-iter
(--logPerIter), minimum (--min), or average (no param) execution times are
logged where --logPerIter always overrides --min. I preserved that
functionality.

[borenet, 2013-07-25 14:17:05]

This LGTM but adding a couple more eyes since I didn't write the code.  Ben, I
think this will maintain the current output format.  Do you see anything that
indicates otherwise, or would be problematic in some way?

https://codereview.chromium.org/19862002/diff/8001/include/core/SkPostConfig.h
File include/core/SkPostConfig.h (right):

https://codereview.chromium.org/19862002/diff/8001/include/core/SkPostConfig....
include/core/SkPostConfig.h:158: #endif
Not sure if relevant here, but NOMINMAX is defined in our gyp files when
building with ANGLE.

https://codereview.chromium.org/19862002/diff/8001/tools/PictureBenchmark.cpp
File tools/PictureBenchmark.cpp (right):

https://codereview.chromium.org/19862002/diff/8001/tools/PictureBenchmark.cpp...
tools/PictureBenchmark.cpp:22: , fTimerResult(TimerData::kAvg_Result)
Maybe it would be good to set a TimerData::kDefault_Result so that this can be
changed in one place?

[benchen, 2013-07-25 14:39:21]

LGTM. The logger-related logic looks right, and per-iter logging functionality
is preserved.
Without unittests we cannot be 100% sure, but I'll keep an eye on my jobs to
ensure nothing breaks. Thank you.

On 2013/07/25 14:17:05, borenet wrote:
> This LGTM but adding a couple more eyes since I didn't write the code.  Ben, I
> think this will maintain the current output format.  Do you see anything that
> indicates otherwise, or would be problematic in some way?
> 
> https://codereview.chromium.org/19862002/diff/8001/include/core/SkPostConfig.h
> File include/core/SkPostConfig.h (right):
> 
>
https://codereview.chromium.org/19862002/diff/8001/include/core/SkPostConfig....
> include/core/SkPostConfig.h:158: #endif
> Not sure if relevant here, but NOMINMAX is defined in our gyp files when
> building with ANGLE.
> 
> https://codereview.chromium.org/19862002/diff/8001/tools/PictureBenchmark.cpp
> File tools/PictureBenchmark.cpp (right):
> 
>
https://codereview.chromium.org/19862002/diff/8001/tools/PictureBenchmark.cpp...
> tools/PictureBenchmark.cpp:22: , fTimerResult(TimerData::kAvg_Result)
> Maybe it would be good to set a TimerData::kDefault_Result so that this can be
> changed in one place?

[commit-bot: I haz the power, 2013-07-25 18:42:58]

CQ is trying da patch. Follow status at
https://skia-tree-status.appspot.com/cq/bsalomon@google.com/19862002/8001

[commit-bot: I haz the power, 2013-07-25 18:52:21]

Retried try job too often on Build-Mac10.7-Clang-x86-Release-Trybot for step(s)
BuildMost
http://108.170.217.252:10117/buildstatus?builder=Build-Mac10.7-Clang-x86-Rele...

[bsalomon, 2013-07-25 19:49:55]

https://codereview.chromium.org/19862002/diff/8001/tools/PictureBenchmark.cpp
File tools/PictureBenchmark.cpp (right):

https://codereview.chromium.org/19862002/diff/8001/tools/PictureBenchmark.cpp...
tools/PictureBenchmark.cpp:22: , fTimerResult(TimerData::kAvg_Result)
On 2013/07/25 14:17:05, borenet wrote:
> Maybe it would be good to set a TimerData::kDefault_Result so that this can be
> changed in one place?

It doesn't make much sense to me for TimerData to define a kDefault value when
it requires a parameter to be specified in getResult(). It has no way of the
using a default. It seems like it's really has to be up to its caller to make a
decision about what statistic should be returned.

Or maybe a shorter way of saying the same thing is that the fact that Avg is the
default for bench_pictures seems like a property of bench_pictures and not
TimerData.

[commit-bot: I haz the power, 2013-07-25 19:50:09]

CQ is trying da patch. Follow status at
https://skia-tree-status.appspot.com/cq/bsalomon@google.com/19862002/23001

[commit-bot: I haz the power, 2013-07-25 20:01:23]

Change committed as 10372

[fmalita_google_do_not_use, 2013-07-25 21:22:58]

On 2013/07/25 20:01:23, I haz the power (commit-bot) wrote:
> Change committed as 10372

Looks like this is causing benchpictures garbled output and failures:

http://108.170.217.252:10115/builders/Perf-ChromeOS-Link-HD4000-x86_64-Releas...


[14:02:03.381813] running bench [1257 5744] desk_ebay.skp   copy_tiles: msecs =
�{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�,
�{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�
cmsecs = �{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�,
�{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�, �{^d�,
�{^d�
[14:02:03.381832] running bench [1272 907] desk_youtubetvvideo.skp   copy_tiles:
msecs = (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�,
(��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�,
(��b� cmsecs = (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�,
(��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, pc�d�, �^d�, (��b�,
(��b�, (��b�
[14:02:03.381850] running bench [1257 7340] tabl_theverge.skp   copy_tiles:
msecs = (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�,
(��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�,
(��b� cmsecs = (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�,
(��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, �]d�, `^_d�, (��b�,
(��b�, (��b�
[14:02:03.381868] running bench [1257 907] desk_googlehome.skp   copy_tiles:
msecs = $�*, $�*, $�*, $�*, $�*, $�*, $�*, $�*, $�*, $�*, $�*, $�*,
$�*, $�*, $�*, $�*, $�*, $�*, $�*, $�* cmsecs = $�*, $�*, $�*, $�*,
$�*, $�*, $�*, $�*, $�*, $�*, $�*, $�*, $�*, $�*, $�*, $�*, $�*,
$�*, $�*, $�*
[14:02:08.887898] running bench [1257 3122] desk_yahoonews.skp   copy_tiles:
msecs = �Vd�, �Vd�, �Vd�, �Vd�, �Vd�, �Vd�, �Vd�, �Vd�, �Vd�,
�Vd�,  �Vd�, �Vd�, �Vd�, �Vd�, �Vd�,  �Vd�, �Vd�, �Vd�,
�Vd�, �Vd�,  �Vd�, �Vd�, �Vd�, �Vd�, �Vd�,  �Vd�, �Vd�,
�Vd�, �Vd�, �Vd�,  �Vd�, �Vd�, �Vd�, �Vd�, �Vd�,  �Vd�,
�Vd�, �Vd�, �Vd�, �Vd�,  �Vd�, �Vd�, �Vd�, �Vd�, �Vd�, 
�Vd�, �Vd�, �Vd�, �Vd�, �Vd�,  �Vd�, �Vd�, �Vd�, �Vd�, �Vd�,
 �Vd�, �Vd�, �Vd�, �Vd�, �Vd� cmsecs = �Vd�, �Vd�, �Vd�, �Vd�,
�Vd�, �Vd�, �Vd�, �Vd�, �Vd�,  �Vd�, �Vd�, �Vd�, �Vd�, �Vd�,
 �Vd�, �Vd�, �Vd�, �Vd�, �Vd�,  �Vd�, �Vd�, �Vd�, �Vd�,
�Vd�,  �Vd�, �Vd�, �Vd�, �Vd�, �Vd�,  �Vd�, �Vd�, �Vd�,
�Vd�, �Vd�,  �Vd�, �Vd�, �Vd�, �Vd�, �Vd�,  �Vd�, �Vd�,
�Vd�, �Vd�, �Vd�,  �Vd�, �Vd�, �Vd�, �Vd�, �Vd�,  �Vd�,
�Vd�, �Vd�, �Vd�, �Vd�,  �Vd�, �Vd�, �Vd�, �Vd�, �Vd�, 
�Vd�, �Vd�, �Vd�, �Vd�, �Vd�
[14:02:08.887987] running bench [1257 2003] tabl_sahadan.skp   copy_tiles: msecs
= (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�,
`Zgd�, `Zgd�, `Zgd�, `Zgd�, `Zgd�, `Zgd�, `Zgd�, `Zgd�, `Zgd�, `Zgd�,
`Zgd� cmsecs = (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�,
(��b�, `Zgd�, `Zgd�, `Zgd�, `Zgd�, `Zgd�, `Zgd�, `Zgd�, `Zgd�, `Zgd�,
`Zgd�, `Zgd�
[14:02:08.888010] running bench [1257 2394] desk_amazon.skp   copy_tiles: msecs
= (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�,
(��b�, (��b�, �Vd�, �Vd�, �Vd�, �Vd�, �Vd�, �Vd�, �Vd�, �Vd�, �Vd�
cmsecs = (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�,
(��b�, (��b�, �Vd�, �Vd�, �Vd�, �Vd�, �Vd�, �Vd�, �Vd�, �Vd�, �Vd�
[14:02:08.888030] running bench [1272 908] desk_gmailthread.skp   copy_tiles:
msecs = 3��', 3��', 3��', 3��', 3��', 3��', 3��', 3��', 3��', 3��', 3��', 3��',
3��', 3��', 3��', 3��', 3��', 3��', 3��', 3��' cmsecs = 3��', 3��', 3��', 3��',
3��', 3��', 3��', 3��', 3��', 3��', 3��', 3��', 3��', 3��', 3��', 3��', 3��',
3��', 3��', 3��'
[14:02:08.888048] running bench [1257 4164] tabl_ukwsj.skp   copy_tiles: msecs =
(��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�,  #�d�,  #�d�,  #�d�, 
#�d�,  #�d�,  #�d�,  #�d�,  #�d�,  #�d�,  #�d�,  #�d�,  #�d�,  #�d�
cmsecs = (��b�, (��b�, (��b�, (��b�, (��b�, (��b�, (��b�,  #�d�,  #�d�,
 #�d�,  #�d�,  #�d�,  #�d�,  #�d�,  #�d�,  #�d�,  #�d�,  #�d�,  #�d�, 
#�d�
[14:02:08.888066] running bench [1272 907] desk_youtubetvbrowse.skp  
copy_tiles: msecs = ���
[14:02:08.888066] , ���
[14:02:08.888066] , ���
[14:02:08.888066] , ���
[14:02:08.888066] , ���
[14:02:08.888066] , ���
[14:02:08.888066] , ���
[14:02:08.888066] , ���
[14:02:08.888066] , ���
[14:02:08.888066] , ���
[14:02:08.888066] , ���
[14:02:08.888066] , ���
[14:02:08.888066] , ���
[14:02:08.888066] , ���

[scroggo, 2013-07-30 19:12:33]

Overall I like this CL. The reason it doesn't work properly is in
PictureBenchmark.cpp: you need to keep the SkString result of
get-PerIter/Normal-TimerFormat alive so the result of c_str() still points to
anything meaningful.

https://codereview.chromium.org/19862002/diff/23001/bench/TimerData.h
File bench/TimerData.h (right):

https://codereview.chromium.org/19862002/diff/23001/bench/TimerData.h#newcode31
bench/TimerData.h:31: bool appendTimes(BenchTimer*);
This boolean result is never used.

https://codereview.chromium.org/19862002/diff/23001/bench/TimerData.h#newcode51
bench/TimerData.h:51: int itersPerTiming = 1);
Could you add a comment explaining itersPerTiming? It seems it is only used for
longRunningTimer, which is (and was, before this CL) a bit of a hack.

https://codereview.chromium.org/19862002/diff/23001/include/core/SkPostConfig.h
File include/core/SkPostConfig.h (right):

https://codereview.chromium.org/19862002/diff/23001/include/core/SkPostConfig...
include/core/SkPostConfig.h:143: #ifndef NOMINMAX
Should this be in a different CL?

https://codereview.chromium.org/19862002/diff/23001/src/utils/win/SkWGL_win.cpp
File src/utils/win/SkWGL_win.cpp (right):

https://codereview.chromium.org/19862002/diff/23001/src/utils/win/SkWGL_win.c...
src/utils/win/SkWGL_win.cpp:315: num = SkTMin(num, 64U);
This seems like an unrelated change?

https://codereview.chromium.org/19862002/diff/23001/tools/PictureBenchmark.cpp
File tools/PictureBenchmark.cpp (right):

https://codereview.chromium.org/19862002/diff/23001/tools/PictureBenchmark.cp...
tools/PictureBenchmark.cpp:94: timeFormat =
fRenderer->getPerIterTimeFormat().c_str();
This is causing the problem: getPerIterTimeFormat returns an SkString as an
anonymous variable. c_str() returns a pointer to the SkString, which is then
destructed, so the pointer is no longer valid.

https://codereview.chromium.org/19862002/diff/23001/tools/bbh_shootout.cpp
File tools/bbh_shootout.cpp (left):

https://codereview.chromium.org/19862002/diff/23001/tools/bbh_shootout.cpp#ol...
tools/bbh_shootout.cpp:290: /*repeatDraw = */ 1,
The old code takes the sum of the times, since it claims a repeatDraw of 1. That
seems like a bug to me (in which case this CL fixes it), but I'm not familiar
with bbh_shootout, so that may be intended.

[bsalomon, 2013-07-31 15:21:39]

Sergio, Is it OK if the BBH shootout reports avg time per iteration rather than
total?

https://codereview.chromium.org/19862002/diff/23001/bench/TimerData.h
File bench/TimerData.h (right):

https://codereview.chromium.org/19862002/diff/23001/bench/TimerData.h#newcode31
bench/TimerData.h:31: bool appendTimes(BenchTimer*);
On 2013/07/30 19:12:34, scroggo wrote:
> This boolean result is never used.

I put SkAssertResult around the callers.

https://codereview.chromium.org/19862002/diff/23001/bench/TimerData.h#newcode51
bench/TimerData.h:51: int itersPerTiming = 1);
On 2013/07/30 19:12:34, scroggo wrote:
> Could you add a comment explaining itersPerTiming? It seems it is only used
for
> longRunningTimer, which is (and was, before this CL) a bit of a hack.

Done.

https://codereview.chromium.org/19862002/diff/23001/src/utils/win/SkWGL_win.cpp
File src/utils/win/SkWGL_win.cpp (right):

https://codereview.chromium.org/19862002/diff/23001/src/utils/win/SkWGL_win.c...
src/utils/win/SkWGL_win.cpp:315: num = SkTMin(num, 64U);
On 2013/07/30 19:12:34, scroggo wrote:
> This seems like an unrelated change?

moved all the minmax stuff to another cl

https://codereview.chromium.org/19862002/diff/23001/tools/PictureBenchmark.cpp
File tools/PictureBenchmark.cpp (right):

https://codereview.chromium.org/19862002/diff/23001/tools/PictureBenchmark.cp...
tools/PictureBenchmark.cpp:94: timeFormat =
fRenderer->getPerIterTimeFormat().c_str();
On 2013/07/30 19:12:34, scroggo wrote:
> This is causing the problem: getPerIterTimeFormat returns an SkString as an
> anonymous variable. c_str() returns a pointer to the SkString, which is then
> destructed, so the pointer is no longer valid.

Done.

https://codereview.chromium.org/19862002/diff/23001/tools/bbh_shootout.cpp
File tools/bbh_shootout.cpp (left):

https://codereview.chromium.org/19862002/diff/23001/tools/bbh_shootout.cpp#ol...
tools/bbh_shootout.cpp:290: /*repeatDraw = */ 1,
On 2013/07/30 19:12:34, scroggo wrote:
> The old code takes the sum of the times, since it claims a repeatDraw of 1.
That
> seems like a bug to me (in which case this CL fixes it), but I'm not familiar
> with bbh_shootout, so that may be intended.

Nice catch, adding sglez@.

[sglez, 2013-07-31 15:24:55]

On 2013/07/31 15:21:39, bsalomon wrote:
> Sergio, Is it OK if the BBH shootout reports avg time per iteration rather
than
> total?
> 

Sure. Thanks for catching my mistake.

> https://codereview.chromium.org/19862002/diff/23001/bench/TimerData.h
> File bench/TimerData.h (right):
> 
>
https://codereview.chromium.org/19862002/diff/23001/bench/TimerData.h#newcode31
> bench/TimerData.h:31: bool appendTimes(BenchTimer*);
> On 2013/07/30 19:12:34, scroggo wrote:
> > This boolean result is never used.
> 
> I put SkAssertResult around the callers.
> 
>
https://codereview.chromium.org/19862002/diff/23001/bench/TimerData.h#newcode51
> bench/TimerData.h:51: int itersPerTiming = 1);
> On 2013/07/30 19:12:34, scroggo wrote:
> > Could you add a comment explaining itersPerTiming? It seems it is only used
> for
> > longRunningTimer, which is (and was, before this CL) a bit of a hack.
> 
> Done.
> 
>
https://codereview.chromium.org/19862002/diff/23001/src/utils/win/SkWGL_win.cpp
> File src/utils/win/SkWGL_win.cpp (right):
> 
>
https://codereview.chromium.org/19862002/diff/23001/src/utils/win/SkWGL_win.c...
> src/utils/win/SkWGL_win.cpp:315: num = SkTMin(num, 64U);
> On 2013/07/30 19:12:34, scroggo wrote:
> > This seems like an unrelated change?
> 
> moved all the minmax stuff to another cl
> 
> https://codereview.chromium.org/19862002/diff/23001/tools/PictureBenchmark.cpp
> File tools/PictureBenchmark.cpp (right):
> 
>
https://codereview.chromium.org/19862002/diff/23001/tools/PictureBenchmark.cp...
> tools/PictureBenchmark.cpp:94: timeFormat =
> fRenderer->getPerIterTimeFormat().c_str();
> On 2013/07/30 19:12:34, scroggo wrote:
> > This is causing the problem: getPerIterTimeFormat returns an SkString as an
> > anonymous variable. c_str() returns a pointer to the SkString, which is then
> > destructed, so the pointer is no longer valid.
> 
> Done.
> 
> https://codereview.chromium.org/19862002/diff/23001/tools/bbh_shootout.cpp
> File tools/bbh_shootout.cpp (left):
> 
>
https://codereview.chromium.org/19862002/diff/23001/tools/bbh_shootout.cpp#ol...
> tools/bbh_shootout.cpp:290: /*repeatDraw = */ 1,
> On 2013/07/30 19:12:34, scroggo wrote:
> > The old code takes the sum of the times, since it claims a repeatDraw of 1.
> That
> > seems like a bug to me (in which case this CL fixes it), but I'm not
familiar
> > with bbh_shootout, so that may be intended.
> 
> Nice catch, adding sglez@.

[scroggo, 2013-07-31 15:29:22]

LGTM

Will this speed up our benchmarks much, as reported by the buildbots? Will that
trigger anything or should we make it easier for someone looking at them later
to know why the speed up occurred?

[bsalomon, 2013-07-31 15:43:39]

On 2013/07/31 15:29:22, scroggo wrote:
> LGTM
> 
> Will this speed up our benchmarks much, as reported by the buildbots? Will
that
> trigger anything or should we make it easier for someone looking at them later
> to know why the speed up occurred?

I believe the only thing that will speedup is the long running timer in bench
pictures (since string the concats are inside its start/end) but I doubt it will
be a very large change unless our repeat count is huge.

[commit-bot: I haz the power, 2013-07-31 18:57:18]

CQ is trying da patch. Follow status at
https://skia-tree-status.appspot.com/cq/bsalomon@google.com/19862002/50001

[commit-bot: I haz the power, 2013-07-31 20:01:01]

Change committed as 10473