[Tracing] Fix inaccurate timer calculation in runtime statistics.

[Tracing] Fix inaccurate timer calculation in runtime statistics.

Previously we reset runtime counters and dump them when we enter, exit top level
trace events respectively. However, there is gap between two top level trace
events and runtime counters may be activated, resetting the counters makes the
accumulated time inaccurate, and we may end up with negative time due to the
nature of how we accumulate time.

This patch fixes this problem by only resetting counters when there's no
counters active, and before dump counters, we traverse current active counters
to calculate their time, and then restart their timer.

BUG=chromium:658145
Committed: https://crrev.com/92d9a56a152dcefc8a3004e9812977c457fd4d14
Cr-Commit-Position: refs/heads/master@{#40653}

[lpy, 2016-10-26 19:48:38]

The CQ bit was checked by lpy@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-10-26 19:48:43]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-10-26 19:54:54]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-10-26 19:54:55]

Dry run: Try jobs failed on following builders:
  v8_linux_gcc_compile_rel on master.tryserver.v8 (JOB_FAILED,
http://build.chromium.org/p/tryserver.v8/builders/v8_linux_gcc_compile_rel/bu...)

[lpy, 2016-10-26 20:19:38]

The CQ bit was checked by lpy@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-10-26 20:19:41]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[lpy, 2016-10-26 20:24:44]

Patchset #1 (id:1) has been deleted

[lpy, 2016-10-26 20:29:09]

lpy@chromium.org changed reviewers:
+ cbruni@chromium.org, fmeawad@chromium.org, jochen@chromium.org

[lpy, 2016-10-26 20:29:10]

ptal

[commit-bot: I haz the power, 2016-10-26 20:49:55]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-10-26 20:49:56]

Dry run: This issue passed the CQ dry run.

[jochen (gone - plz use gerrit), 2016-10-27 07:40:40]

deferring to cbruni

[Camillo Bruni, 2016-10-27 09:00:58]

Nice! Thanks for looking into this.
I think we have the same issue with the normal Print(), see my inline
suggestions.

https://codereview.chromium.org/2457523002/diff/20001/src/counters.cc
File src/counters.cc (right):

https://codereview.chromium.org/2457523002/diff/20001/src/counters.cc#newcode373
src/counters.cc:373: }
Can you add the same call to RuntimeCallStats::Print() which suffers from the
same issue. 

This probably didn't matter so much since we only miss on some marginal values
from the few timers that are active once we actually print the runtime stats.

https://codereview.chromium.org/2457523002/diff/20001/src/counters.h
File src/counters.h (right):

https://codereview.chromium.org/2457523002/diff/20001/src/counters.h#newcode532
src/counters.h:532: }
Maybe let's write this in a loop instead of recursive calls like in Stop()
(probably there won't be many timers active, but nevertheless). WDYT?

[lpy, 2016-10-27 16:59:18]

The CQ bit was checked by lpy@chromium.org to run a CQ dry run

[lpy, 2016-10-27 16:59:22]

https://codereview.chromium.org/2457523002/diff/20001/src/counters.cc
File src/counters.cc (right):

https://codereview.chromium.org/2457523002/diff/20001/src/counters.cc#newcode373
src/counters.cc:373: }
On 2016/10/27 09:00:58, Camillo Bruni wrote:
> Can you add the same call to RuntimeCallStats::Print() which suffers from the
> same issue. 
> 
> This probably didn't matter so much since we only miss on some marginal values
> from the few timers that are active once we actually print the runtime stats.

Done.

https://codereview.chromium.org/2457523002/diff/20001/src/counters.h
File src/counters.h (right):

https://codereview.chromium.org/2457523002/diff/20001/src/counters.h#newcode532
src/counters.h:532: }
On 2016/10/27 09:00:58, Camillo Bruni wrote:
> Maybe let's write this in a loop instead of recursive calls like in Stop()
> (probably there won't be many timers active, but nevertheless). WDYT?

We need to maintain the order of timer restart from parent to child, so a loop
will require to store timers.

[commit-bot: I haz the power, 2016-10-27 16:59:23]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-10-27 17:32:32]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-10-27 17:32:33]

Dry run: This issue passed the CQ dry run.

[Camillo Bruni, 2016-10-28 08:49:17]

LGTM

You're right, I thought that you could directly restart the timer after you've
done timer_->Elapsed() which would possibly lead to negative times due to how we
subtract the subtimers.

[jochen (gone - plz use gerrit), 2016-10-28 13:40:37]

rubberstamp lgtm

[lpy, 2016-10-28 17:40:31]

The CQ bit was checked by lpy@chromium.org

[commit-bot: I haz the power, 2016-10-28 17:40:36]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-10-28 18:04:49]

Committed patchset #2 (id:40001)

[commit-bot: I haz the power, 2016-11-17 22:17:07]

Description was changed from

==========
[Tracing] Fix inaccurate timer calculation in runtime statistics.

Previously we reset runtime counters and dump them when we enter, exit top level
trace events respectively. However, there is gap between two top level trace
events and runtime counters may be activated, resetting the counters makes the
accumulated time inaccurate, and we may end up with negative time due to the
nature of how we accumulate time.

This patch fixes this problem by only resetting counters when there's no
counters active, and before dump counters, we traverse current active counters
to calculate their time, and then restart their timer.

BUG=chromium:658145
==========

to

==========
[Tracing] Fix inaccurate timer calculation in runtime statistics.

Previously we reset runtime counters and dump them when we enter, exit top level
trace events respectively. However, there is gap between two top level trace
events and runtime counters may be activated, resetting the counters makes the
accumulated time inaccurate, and we may end up with negative time due to the
nature of how we accumulate time.

This patch fixes this problem by only resetting counters when there's no
counters active, and before dump counters, we traverse current active counters
to calculate their time, and then restart their timer.

BUG=chromium:658145

Committed: https://crrev.com/92d9a56a152dcefc8a3004e9812977c457fd4d14
Cr-Commit-Position: refs/heads/master@{#40653}
==========

[commit-bot: I haz the power, 2016-11-17 22:17:08]

Patchset 2 (id:??) landed as
https://crrev.com/92d9a56a152dcefc8a3004e9812977c457fd4d14
Cr-Commit-Position: refs/heads/master@{#40653}