Subzero: Improve the -timing output.

Subzero: Improve the -timing output.

For "Flat times" output, adds a column with cumulative percentage.  Also, since these percentages add up to less than 100% due to timer overhead, we go ahead and scale up all of the "Flat times" percentages proportionally, to make them add to 100%.  This makes it easier to compare breakdowns across different pexes.

Also, simplify the output to be simple tabular without extra brackets and whatnot.  E.g.:

Total across all functions - Cumulative times:
     Seconds   Pct  EventCnt TimerPath
    8.580407 82.6%         0 szmain
    8.580054 82.6%         0 szmain.parseModule
    8.405447 80.9%     46473 szmain.parseModule.parseFunctions
...
Total across all functions - Flat times:
     Seconds   Pct CumPct  EventCnt TimerName
    1.354678 16.0%  16.0%    100716 linearScan
    1.131292 13.3%  29.3%    139419 liveness
    0.728727  8.6%  37.9%     46473 genCode
...

BUG= none
R=jpp@chromium.org, kschimpf@google.com

Committed: https://gerrit.chromium.org/gerrit/gitweb?p=native_client/pnacl-subzero.git;a=commit;h=9a23e4318c73c21c39b693c69c51da37ee3a4d14

[Jim Stichnoth, 2016-04-08 20:58:56]

Description was changed from

==========
Subzero: Improve the -timing output.

BUG= none
==========

to

==========
Subzero: Improve the -timing output.

For "Flat times" output, adds a column with cumulative percentage.  Also, since
these percentages add up to less than 100% due to timer overhead, we go ahead
and scale up all of the "Flat times" percentages proportionally, to make them
add to 100%.  This makes it easier to compare breakdowns across different pexes.

Also, simplify the output to be simple tabular without extra brackets and
whatnot.  E.g.:

Total across all functions - Cumulative times:
     Seconds   Pct  EventCnt TimerPath
    8.580407 82.6%         0 szmain
    8.580054 82.6%         0 szmain.parseModule
    8.405447 80.9%     46473 szmain.parseModule.parseFunctions
...
Total across all functions - Flat times:
     Seconds   Pct CumPct  EventCnt TimerName
    1.354678 16.0%  16.0%    100716 linearScan
    1.131292 13.3%  29.3%    139419 liveness
    0.728727  8.6%  37.9%     46473 genCode


BUG= none
==========

[Jim Stichnoth, 2016-04-08 20:59:39]

Description was changed from

==========
Subzero: Improve the -timing output.

For "Flat times" output, adds a column with cumulative percentage.  Also, since
these percentages add up to less than 100% due to timer overhead, we go ahead
and scale up all of the "Flat times" percentages proportionally, to make them
add to 100%.  This makes it easier to compare breakdowns across different pexes.

Also, simplify the output to be simple tabular without extra brackets and
whatnot.  E.g.:

Total across all functions - Cumulative times:
     Seconds   Pct  EventCnt TimerPath
    8.580407 82.6%         0 szmain
    8.580054 82.6%         0 szmain.parseModule
    8.405447 80.9%     46473 szmain.parseModule.parseFunctions
...
Total across all functions - Flat times:
     Seconds   Pct CumPct  EventCnt TimerName
    1.354678 16.0%  16.0%    100716 linearScan
    1.131292 13.3%  29.3%    139419 liveness
    0.728727  8.6%  37.9%     46473 genCode


BUG= none
==========

to

==========
Subzero: Improve the -timing output.

For "Flat times" output, adds a column with cumulative percentage.  Also, since
these percentages add up to less than 100% due to timer overhead, we go ahead
and scale up all of the "Flat times" percentages proportionally, to make them
add to 100%.  This makes it easier to compare breakdowns across different pexes.

Also, simplify the output to be simple tabular without extra brackets and
whatnot.  E.g.:

Total across all functions - Cumulative times:
     Seconds   Pct  EventCnt TimerPath
    8.580407 82.6%         0 szmain
    8.580054 82.6%         0 szmain.parseModule
    8.405447 80.9%     46473 szmain.parseModule.parseFunctions
...
Total across all functions - Flat times:
     Seconds   Pct CumPct  EventCnt TimerName
    1.354678 16.0%  16.0%    100716 linearScan
    1.131292 13.3%  29.3%    139419 liveness
    0.728727  8.6%  37.9%     46473 genCode
...

BUG= none
==========

[Jim Stichnoth, 2016-04-08 20:59:39]

stichnot@chromium.org changed reviewers:
+ eholk@chromium.org, jpp@chromium.org, kschimpf@google.com, sehr@chromium.org

[John, 2016-04-08 21:04:32]

lgtm

https://codereview.chromium.org/1870073005/diff/1/src/IceTimerTree.cpp
File src/IceTimerTree.cpp (right):

https://codereview.chromium.org/1870073005/diff/1/src/IceTimerTree.cpp#newcod...
src/IceTimerTree.cpp:231: void dumpHelper(Ostream &Str, const DumpMapType &Map,
double TotalTime,
TotalTime should be a local...

https://codereview.chromium.org/1870073005/diff/1/src/IceTimerTree.cpp#newcod...
src/IceTimerTree.cpp:240: for (auto &I : Map) {
const

https://codereview.chromium.org/1870073005/diff/1/src/IceTimerTree.cpp#newcod...
src/IceTimerTree.cpp:269: Str << Name << " - Cumulative times:\n";
Suggestion: don't end the Str << in the previous line,

  Str << Name << " - Cumulative times:\n"
      << " ... ";

[Jim Stichnoth, 2016-04-08 21:09:48]

https://codereview.chromium.org/1870073005/diff/1/src/IceTimerTree.cpp
File src/IceTimerTree.cpp (right):

https://codereview.chromium.org/1870073005/diff/1/src/IceTimerTree.cpp#newcod...
src/IceTimerTree.cpp:231: void dumpHelper(Ostream &Str, const DumpMapType &Map,
double TotalTime,
On 2016/04/08 21:04:31, John wrote:
> TotalTime should be a local...

Actually if AddPercents==false, then TotalTime needs to be passed in, but if
AddPercents==true, we need to recompute it from scratch.

https://codereview.chromium.org/1870073005/diff/1/src/IceTimerTree.cpp#newcod...
src/IceTimerTree.cpp:240: for (auto &I : Map) {
On 2016/04/08 21:04:32, John wrote:
> const

Done.

https://codereview.chromium.org/1870073005/diff/1/src/IceTimerTree.cpp#newcod...
src/IceTimerTree.cpp:269: Str << Name << " - Cumulative times:\n";
On 2016/04/08 21:04:31, John wrote:
> Suggestion: don't end the Str << in the previous line,
> 
>   Str << Name << " - Cumulative times:\n"
>       << " ... ";

Done.

[Karl, 2016-04-08 21:15:25]

Otherwise, LGTM.

https://codereview.chromium.org/1870073005/diff/20001/src/IceTimerTree.cpp
File src/IceTimerTree.cpp (right):

https://codereview.chromium.org/1870073005/diff/20001/src/IceTimerTree.cpp#ne...
src/IceTimerTree.cpp:232: bool AddPercents) {
This seems a bit overloaded, but there is not comment on it. That is, it defines
both (1) base TotalTime on found time, and (2) whether flat/cumulative times are
printed. Perhaps add a comment to make this clear?

Also, is there a reason for not being consistent of time base?

[Jim Stichnoth, 2016-04-09 00:09:22]

https://codereview.chromium.org/1870073005/diff/20001/src/IceTimerTree.cpp
File src/IceTimerTree.cpp (right):

https://codereview.chromium.org/1870073005/diff/20001/src/IceTimerTree.cpp#ne...
src/IceTimerTree.cpp:232: bool AddPercents) {
On 2016/04/08 21:15:25, Karl wrote:
> This seems a bit overloaded, but there is not comment on it. That is, it
defines
> both (1) base TotalTime on found time, and (2) whether flat/cumulative times
are
> printed. Perhaps add a comment to make this clear?

Done.

> 
> Also, is there a reason for not being consistent of time base?

Only the "flat times" are supposed to add up to 100% - have a close look at the
-timing output and it should make sense.

[Jim Stichnoth, 2016-04-09 00:09:33]

Description was changed from

==========
Subzero: Improve the -timing output.

For "Flat times" output, adds a column with cumulative percentage.  Also, since
these percentages add up to less than 100% due to timer overhead, we go ahead
and scale up all of the "Flat times" percentages proportionally, to make them
add to 100%.  This makes it easier to compare breakdowns across different pexes.

Also, simplify the output to be simple tabular without extra brackets and
whatnot.  E.g.:

Total across all functions - Cumulative times:
     Seconds   Pct  EventCnt TimerPath
    8.580407 82.6%         0 szmain
    8.580054 82.6%         0 szmain.parseModule
    8.405447 80.9%     46473 szmain.parseModule.parseFunctions
...
Total across all functions - Flat times:
     Seconds   Pct CumPct  EventCnt TimerName
    1.354678 16.0%  16.0%    100716 linearScan
    1.131292 13.3%  29.3%    139419 liveness
    0.728727  8.6%  37.9%     46473 genCode
...

BUG= none
==========

to

==========
Subzero: Improve the -timing output.

For "Flat times" output, adds a column with cumulative percentage.  Also, since
these percentages add up to less than 100% due to timer overhead, we go ahead
and scale up all of the "Flat times" percentages proportionally, to make them
add to 100%.  This makes it easier to compare breakdowns across different pexes.

Also, simplify the output to be simple tabular without extra brackets and
whatnot.  E.g.:

Total across all functions - Cumulative times:
     Seconds   Pct  EventCnt TimerPath
    8.580407 82.6%         0 szmain
    8.580054 82.6%         0 szmain.parseModule
    8.405447 80.9%     46473 szmain.parseModule.parseFunctions
...
Total across all functions - Flat times:
     Seconds   Pct CumPct  EventCnt TimerName
    1.354678 16.0%  16.0%    100716 linearScan
    1.131292 13.3%  29.3%    139419 liveness
    0.728727  8.6%  37.9%     46473 genCode
...

BUG= none
R=jpp@chromium.org, kschimpf@google.com

Committed:
https://gerrit.chromium.org/gerrit/gitweb?p=native_client/pnacl-subzero.git;a...
==========

[Jim Stichnoth, 2016-04-09 00:09:34]

Committed patchset #3 (id:40001) manually as
9a23e4318c73c21c39b693c69c51da37ee3a4d14 (presubmit successful).