Subzero: Rewrite the pass timing infrastructure.

Subzero: Rewrite the pass timing infrastructure.

This makes it much more useful for individual analysis and long-term translation performance tracking.

1. Collect and report aggregated across the entire translation, instead of function-by-function.  If you really care about a single function, just extract it and translate it separately for analysis.

2. Remove "-verbose time" and just use -timing.

3. Collects two kinds of timings: cumulative and flat.  Cumulative measures the total time, even if a callee also times itself.  Flat only measures the currently active timer at the top of the stack.  The flat times should add up to 100%, but cumulative will usually add up to much more than 100%.

BUG= none
R=jvoung@chromium.org

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

[Jim Stichnoth, 2014-09-27 16:15:56]

stichnot@chromium.org changed reviewers:
+ jvoung@chromium.org, kschimpf@google.com

[Jim Stichnoth, 2014-09-27 16:22:23]

Early results show that register allocation is taking 50% of the total
translation time.  Yikes!

They're also showing nearly 0 time for "parse" (see the timer in main()), so
Karl, am I doing something wrong?  Invocation is:

./llvm2ice -O2 -bitcode-format=pnacl -disable-globals -externalize
-ffunction-sections -o
.../native_client/tests/spec2k/176.gcc/gcc.opt.stripped.sz.s
.../native_client/tests/spec2k/176.gcc/gcc.opt.stripped.pexe -timing

https://codereview.chromium.org/610813002/diff/1/Makefile.standalone
File Makefile.standalone (right):

https://codereview.chromium.org/610813002/diff/1/Makefile.standalone#newcode116
Makefile.standalone:116: check-lit: llvm2ice make_symlink
This was actually broken after the Debug/Release change.  Running "make check"
or "make check-lit" wouldn't actually rebuild llvm2ice as necessary.

[Jim Stichnoth, 2014-09-28 14:26:40]

The latest patchset also has a couple of regalloc performance improvements.

https://codereview.chromium.org/610813002/diff/20001/src/IceCfg.cpp
File src/IceCfg.cpp (right):

https://codereview.chromium.org/610813002/diff/20001/src/IceCfg.cpp#newcode312
src/IceCfg.cpp:312: (*I)->doBranchOpt(NextNode == E ? NULL : *NextNode);
This was a bug pointed out by valgrind.

https://codereview.chromium.org/610813002/diff/20001/src/IceOperand.cpp
File src/IceOperand.cpp (right):

https://codereview.chromium.org/610813002/diff/20001/src/IceOperand.cpp#newco...
src/IceOperand.cpp:124: bool LiveRange::overlaps(InstNumberT OtherBegin) const {
This is called quite a bit, so provide a better implementation.

(Tested by computing both ways and asserting the same result.)

https://codereview.chromium.org/610813002/diff/20001/src/IceRegAlloc.cpp
File src/IceRegAlloc.cpp (right):

https://codereview.chromium.org/610813002/diff/20001/src/IceRegAlloc.cpp#newc...
src/IceRegAlloc.cpp:285: if (Free[RegNum] && Item.overlaps(Cur)) {
Performance optimization to check Free[] before the overlaps() test.

[Karl, 2014-09-29 16:55:07]

Also note. Using "recursive" and "nonrecursive" is not standard terminology.
Typically, it is called "flat" and "cumulative" (see pprof as example).

https://codereview.chromium.org/610813002/diff/20001/src/IceGlobalContext.cpp
File src/IceGlobalContext.cpp (right):

https://codereview.chromium.org/610813002/diff/20001/src/IceGlobalContext.cpp...
src/IceGlobalContext.cpp:136: FullNames.push_back(Prefix + Name);
Minor nit. There is a lot of string building going on in this method 2 strings
to create Prefix, and one more for the full name).

https://codereview.chromium.org/610813002/diff/20001/src/IceGlobalContext.cpp...
src/IceGlobalContext.cpp:149: typedef std::map<IceString, double> MapType;
Using string as the key can be quite expensive. Consider using a counter to give
each timer a unique key. Use this key for data updates. It will cut down on the
overhead considerably. Note that tsd::map using a binary tree and will be doing
a lot of expensive compares.

Alternatively, use the pointer value of the timer for the key (if you aren't
worried about ordering).

[Jim Stichnoth, 2014-09-30 17:50:50]

The bug in measuring the parse time was fixed in patchset 6.  Sorry Karl... :)

https://codereview.chromium.org/610813002/diff/20001/src/IceGlobalContext.cpp
File src/IceGlobalContext.cpp (right):

https://codereview.chromium.org/610813002/diff/20001/src/IceGlobalContext.cpp...
src/IceGlobalContext.cpp:136: FullNames.push_back(Prefix + Name);
On 2014/09/29 16:55:07, Karl wrote:
> Minor nit. There is a lot of string building going on in this method 2 strings
> to create Prefix, and one more for the full name).

Good point, and it does turn into a real performance problem if you try to add
very fine-grain timing.

I rewrote this as an explicit tree that is built dynamically as new paths are
added.  As such, there may be some extra overhead during the first function
translation, but subsequent functions should be quite fast.

I avoided imposing centralized compile-time marker ID management, using a
pattern of static initialization, while still allowing new marker IDs to be
added dynamically.

https://codereview.chromium.org/610813002/diff/20001/src/IceGlobalContext.cpp...
src/IceGlobalContext.cpp:149: typedef std::map<IceString, double> MapType;
On 2014/09/29 16:55:07, Karl wrote:
> Using string as the key can be quite expensive. Consider using a counter to
give
> each timer a unique key. Use this key for data updates. It will cut down on
the
> overhead considerably. Note that tsd::map using a binary tree and will be
doing
> a lot of expensive compares.
> 
> Alternatively, use the pointer value of the timer for the key (if you aren't
> worried about ordering).

Done, see the comment above.

[jvoung (off chromium), 2014-09-30 20:19:04]

https://codereview.chromium.org/610813002/diff/100001/src/IceGlobalContext.cpp
File src/IceGlobalContext.cpp (right):

https://codereview.chromium.org/610813002/diff/100001/src/IceGlobalContext.cp...
src/IceGlobalContext.cpp:392: void GlobalContext::pushTimer(TimerIdT ID) {
Timers.get()->push(ID); }
Could use the operator-> instead of get()-> -- I don't remember if we've adopted
a style for that.

https://codereview.chromium.org/610813002/diff/100001/src/IceGlobalContext.h
File src/IceGlobalContext.h (right):

https://codereview.chromium.org/610813002/diff/100001/src/IceGlobalContext.h#...
src/IceGlobalContext.h:156: void dumpTimers();
Can dumpTimers() be const? N/M, looks like no since there's an update() that
happens then to get the total time.

https://codereview.chromium.org/610813002/diff/100001/src/IceRegAlloc.cpp
File src/IceRegAlloc.cpp (right):

https://codereview.chromium.org/610813002/diff/100001/src/IceRegAlloc.cpp#new...
src/IceRegAlloc.cpp:67: static TimerIdT IDscan =
GlobalContext::getTimerID("scan");
If it makes sense, it might be better to say "linear_scan" or something since
"scan" could seem a bit generic when placed alongside other timer names. On the
other hand, there's also the regAlloc timer, but this is after the bitvector
creation.

https://codereview.chromium.org/610813002/diff/100001/src/IceRegAlloc.cpp#new...
src/IceRegAlloc.cpp:112: // of Variable::AllowRegisterOverlap.
Update comment about Variable::AllowRegisterOverlap now that it's not part of
Variable?

https://codereview.chromium.org/610813002/diff/100001/src/IceRegAlloc.cpp#new...
src/IceRegAlloc.cpp:289: // Don't assert(Free[RegNum]) because in theory (though
Based on the comment, it seems like there could still be a reason to see if
AllowOverlap should be set to false. Or maybe that was just an artifact of the
manual marking.

https://codereview.chromium.org/610813002/diff/100001/src/IceRegAlloc.cpp#new...
src/IceRegAlloc.cpp:292: // AllowRegisterOverlap.
AllowRegisterOverlap -> AllowOverlap

https://codereview.chromium.org/610813002/diff/100001/src/PNaClTranslator.cpp
File src/PNaClTranslator.cpp (right):

https://codereview.chromium.org/610813002/diff/100001/src/PNaClTranslator.cpp...
src/PNaClTranslator.cpp:855: ~FunctionParser() override{};
space between override and {}, or is that the clang-format preference?

[Jim Stichnoth, 2014-09-30 22:46:00]

https://codereview.chromium.org/610813002/diff/100001/src/IceGlobalContext.cpp
File src/IceGlobalContext.cpp (right):

https://codereview.chromium.org/610813002/diff/100001/src/IceGlobalContext.cp...
src/IceGlobalContext.cpp:392: void GlobalContext::pushTimer(TimerIdT ID) {
Timers.get()->push(ID); }
On 2014/09/30 20:19:04, jvoung wrote:
> Could use the operator-> instead of get()-> -- I don't remember if we've
adopted
> a style for that.

Done.

https://codereview.chromium.org/610813002/diff/100001/src/IceGlobalContext.h
File src/IceGlobalContext.h (right):

https://codereview.chromium.org/610813002/diff/100001/src/IceGlobalContext.h#...
src/IceGlobalContext.h:156: void dumpTimers();
On 2014/09/30 20:19:04, jvoung wrote:
> Can dumpTimers() be const? N/M, looks like no since there's an update() that
> happens then to get the total time.

Right - we must track that last iota of runtime!

https://codereview.chromium.org/610813002/diff/100001/src/IceRegAlloc.cpp
File src/IceRegAlloc.cpp (right):

https://codereview.chromium.org/610813002/diff/100001/src/IceRegAlloc.cpp#new...
src/IceRegAlloc.cpp:67: static TimerIdT IDscan =
GlobalContext::getTimerID("scan");
On 2014/09/30 20:19:04, jvoung wrote:
> If it makes sense, it might be better to say "linear_scan" or something since
> "scan" could seem a bit generic when placed alongside other timer names. On
the
> other hand, there's also the regAlloc timer, but this is after the bitvector
> creation.

Done, with "linearScan" to match the style of the others.

I think it's good to keep this timer in addition to the regAlloc timer, in case
regAlloc one day is changed to do substantially more work.

https://codereview.chromium.org/610813002/diff/100001/src/IceRegAlloc.cpp#new...
src/IceRegAlloc.cpp:112: // of Variable::AllowRegisterOverlap.
On 2014/09/30 20:19:04, jvoung wrote:
> Update comment about Variable::AllowRegisterOverlap now that it's not part of
> Variable?

Done.

https://codereview.chromium.org/610813002/diff/100001/src/IceRegAlloc.cpp#new...
src/IceRegAlloc.cpp:289: // Don't assert(Free[RegNum]) because in theory (though
On 2014/09/30 20:19:04, jvoung wrote:
> Based on the comment, it seems like there could still be a reason to see if
> AllowOverlap should be set to false. Or maybe that was just an artifact of the
> manual marking.

I think you're right and I may have incorrectly optimized that.  Reverting for
now.

https://codereview.chromium.org/610813002/diff/100001/src/IceRegAlloc.cpp#new...
src/IceRegAlloc.cpp:292: // AllowRegisterOverlap.
On 2014/09/30 20:19:04, jvoung wrote:
> AllowRegisterOverlap -> AllowOverlap

Done.

https://codereview.chromium.org/610813002/diff/100001/src/PNaClTranslator.cpp
File src/PNaClTranslator.cpp (right):

https://codereview.chromium.org/610813002/diff/100001/src/PNaClTranslator.cpp...
src/PNaClTranslator.cpp:855: ~FunctionParser() override{};
On 2014/09/30 20:19:04, jvoung wrote:
> space between override and {}, or is that the clang-format preference?

Sadly, clang-format on my machine is doing that.  Forcing it back, but I fear
this battle is not over...

https://codereview.chromium.org/610813002/diff/140001/src/IceOperand.cpp
File src/IceOperand.cpp (right):

https://codereview.chromium.org/610813002/diff/140001/src/IceOperand.cpp#newc...
src/IceOperand.cpp:138: // An equivalent but less inefficient implementation:
Actual comparisons indicated this was a lie.

The optimized implementation was completely broken.

For now, I'd like to keep this validation code around and paranoically enable it
at the first sign of suspicion.

[jvoung (off chromium), 2014-09-30 23:38:44]

lgtm

https://codereview.chromium.org/610813002/diff/100001/src/IceOperand.cpp
File src/IceOperand.cpp (right):

https://codereview.chromium.org/610813002/diff/100001/src/IceOperand.cpp#newc...
src/IceOperand.cpp:127: if (OtherBegin >= I->second)
So the issue was that the ranges are sorted the other way?

OtherBegin might be >= I->second for some of the earlier ranges, even though it
overlaps later?

[Jim Stichnoth, 2014-09-30 23:49:16]

https://codereview.chromium.org/610813002/diff/100001/src/IceOperand.cpp
File src/IceOperand.cpp (right):

https://codereview.chromium.org/610813002/diff/100001/src/IceOperand.cpp#newc...
src/IceOperand.cpp:127: if (OtherBegin >= I->second)
On 2014/09/30 23:38:44, jvoung wrote:
> So the issue was that the ranges are sorted the other way?
> 
> OtherBegin might be >= I->second for some of the earlier ranges, even though
it
> overlaps later?

No, the segments of the live range must be sorted, though that is only enforced
if the USE_SET define is enabled.  E.g., LiveRange::overlaps() relies on
iterating in increasing sorted order.

The only thing that makes sense to me is that I implemented something, validated
it against the original implementation, cleaned out the validation code, then
"optimized" the new implementation without re-validating. :(

[Jim Stichnoth, 2014-09-30 23:49:42]

Committed patchset #8 (id:140001) manually as
c4554d784583d26a02eca8610b43511ade516082 (presubmit successful).