Issue 84 in unladen-swallow: regrtest.py cannot be run under -j always
codesite...@google.com
Owner: reid.kleckner
Labels: Type-Defect Priority-Medium
New issue 84 by reid.kleckner: regrtest.py cannot be run under -j always
http://code.google.com/p/unladen-swallow/issues/detail?id=84
We've been trying to get regrtest.py to run successfully under -j always
for awhile now. Here are the problems we've run into, and their fixes:
1. LLVM had a hard-coded limit on the size of generated machine code. I
committed a fix for this to LLVM.
2. During instruction scheduling, we overflowed a short in one of LLVM's
data structures. I committed a patch to LLVM to avoid the overflow and
allow longer basic blocks.
3. Currently, running regrtest.py under -j always segfaults during
test_import. I haven't traced the execution in GDB, because GDB traps a
number of times during the test suite and has to be continued manually.
Before the segfault, a number of tests fail with exceptions from os.fork
returning an error code claiming that the kernel can't allocate memory.
This happens for me on my desktop system which has 6 GB of RAM (that should
be plenty). My first theory for what's happening is that malloc is finally
returning NULL because it's run out of memory, and that's causing the
segfault.
Can someone else confirm this overnight? Save your state before you do,
because the Linux out-of-memory killer might come and reap your firefox
process.
--
You received this message because you are listed in the owner
or CC fields of this issue, or because you starred this issue.
You may adjust your issue notification preferences at:
http://code.google.com/hosting/settings
James Abbatiello
> Can someone else confirm this overnight? Save your state before you do,
> because the Linux out-of-memory killer might come and reap your firefox
> process.
I tried on Win32 with 3GB of RAM. Here's what it looks like:
======
>PCbuild\python.exe -j always Lib\test\regrtest.py
Testing with flags: sys.flags(debug=0, py3k_warning=0,
division_warning=0, division_new=0, inspect=0, interactive=0,
optimize=0, generate_debug_info=0, dont_write_bytecode=0,
no_user_site=0, no_site=0, ignore_environment=0, tabcheck=0,
verbose=0, unicode=0, bytes_warning=0, jit_control='always')
test_grammar
test test_grammar failed -- Traceback (most recent call last):
File "C:\Projects\unladen-swallow\lib\test\test_grammar.py", line
523, in testExec
if z != 2: self.fail('exec \'z=1+1\'\\n')
UnboundLocalError: local variable 'z' referenced before assignment
<snip>
test_coercion
test test_coercion failed -- Traceback (most recent call last):
File "C:\Projects\unladen-swallow\lib\test\test_coercion.py", line
284, in test_infix_binops
self.assertEquals(ires, z)
AssertionError: 4 != 2
<snip>
test_gc
test test_gc failed -- Traceback (most recent call last):
File "C:\Projects\unladen-swallow\lib\test\test_gc.py", line 262, in
test_get_count
assertEqual(gc.get_count(), (2, 0, 0))
AssertionError: (3, 0, 0) != (2, 0, 0)
<snip>
test_import
>
======
The test_grammar and test_coercion failures look like they are somehow
evading the "does this function use exec?" check but I haven't looked
into how exactly. They don't seem to have this problem when run
directly like "python Lib/test/test_grammar.py". The python process
gets up to about 1.7GB of memory usage and then it just stops and
drops back to the command prompt with no error message. This is
further than it has gotten before. In the past I've never gotten
beyond test_compile.
--
James Abbatiello
Collin Winter
On Thu, Oct 1, 2009 at 4:02 PM, James Abbatiello <abb...@gmail.com> wrote:
>
>
> On Wed, Sep 30, 2009 at 11:29 PM, <codesite...@google.com> wrote:
>> Can someone else confirm this overnight? Save your state before you do,
>> because the Linux out-of-memory killer might come and reap your firefox
>> process.
>
> I tried on Win32 with 3GB of RAM. Here's what it looks like:
>
> ======
>>PCbuild\python.exe -j always Lib\test\regrtest.py
> Testing with flags: sys.flags(debug=0, py3k_warning=0,
> division_warning=0, division_new=0, inspect=0, interactive=0,
> optimize=0, generate_debug_info=0, dont_write_bytecode=0,
> no_user_site=0, no_site=0, ignore_environment=0, tabcheck=0,
> verbose=0, unicode=0, bytes_warning=0, jit_control='always')
> test_grammar
> test test_grammar failed -- Traceback (most recent call last):
> File "C:\Projects\unladen-swallow\lib\test\test_grammar.py", line
> 523, in testExec
> if z != 2: self.fail('exec \'z=1+1\'\\n')
> UnboundLocalError: local variable 'z' referenced before assignment
That's bizarre. I ran this command on OS X (r847, release build):
./python.exe -j always ../fast-calls/Lib/test/regrtest.py. That passes
test_grammar for me, as it does when I run it stand-alone or via
"regrtest.py test_grammar". You're right, though, this is what you'd
expect if changes to the frame's locals weren't being propagated into
the LLVM frame. It's for this reason that we refuse to JIT-compile any
function that uses exec, so I'm very surprised that testExec is
failing in this way.
Can you do a clean build, or even better, a clean build in a fresh
checkout? Is this a release build or a --with-pydebug build?
> <snip>
> test_coercion
> test test_coercion failed -- Traceback (most recent call last):
> File "C:\Projects\unladen-swallow\lib\test\test_coercion.py", line
> 284, in test_infix_binops
> self.assertEquals(ires, z)
> AssertionError: 4 != 2
>
> <snip>
> test_gc
> test test_gc failed -- Traceback (most recent call last):
> File "C:\Projects\unladen-swallow\lib\test\test_gc.py", line 262, in
> test_get_count
> assertEqual(gc.get_count(), (2, 0, 0))
> AssertionError: (3, 0, 0) != (2, 0, 0)
>
> <snip>
> test_import
test_gc and test_coercion both pass for me under -j always regrtest.py
as well. Weird.
Thanks,
Collin Winter
Reid Kleckner
>>
>> ======
>>>PCbuild\python.exe -j always Lib\test\regrtest.py
>> Testing with flags: sys.flags(debug=0, py3k_warning=0,
>> division_warning=0, division_new=0, inspect=0, interactive=0,
>> optimize=0, generate_debug_info=0, dont_write_bytecode=0,
>> no_user_site=0, no_site=0, ignore_environment=0, tabcheck=0,
>> verbose=0, unicode=0, bytes_warning=0, jit_control='always')
>> test_grammar
>> test test_grammar failed -- Traceback (most recent call last):
>> File "C:\Projects\unladen-swallow\lib\test\test_grammar.py", line
>> 523, in testExec
>> if z != 2: self.fail('exec \'z=1+1\'\\n')
>> UnboundLocalError: local variable 'z' referenced before assignment
>
> That's bizarre. I ran this command on OS X (r847, release build):
> ./python.exe -j always ../fast-calls/Lib/test/regrtest.py. That passes
> test_grammar for me, as it does when I run it stand-alone or via
> "regrtest.py test_grammar". You're right, though, this is what you'd
> expect if changes to the frame's locals weren't being propagated into
> the LLVM frame. It's for this reason that we refuse to JIT-compile any
> function that uses exec, so I'm very surprised that testExec is
> failing in this way.
I've seen this as well, and I wasn't sure what it was.
> Can you do a clean build, or even better, a clean build in a fresh
> checkout? Is this a release build or a --with-pydebug build?
I did it with a release build. I'll try doing a clean build sometime tomorrow.
>> <snip>
>> test_coercion
>> test test_coercion failed -- Traceback (most recent call last):
>> File "C:\Projects\unladen-swallow\lib\test\test_coercion.py", line
>> 284, in test_infix_binops
>> self.assertEquals(ires, z)
>> AssertionError: 4 != 2
I'm pretty sure I saw that one too.
James Abbatiello
>
> That's bizarre. I ran this command on OS X (r847, release build):
> ./python.exe -j always ../fast-calls/Lib/test/regrtest.py. That passes
> test_grammar for me, as it does when I run it stand-alone or via
> "regrtest.py test_grammar". You're right, though, this is what you'd
> expect if changes to the frame's locals weren't being propagated into
> the LLVM frame. It's for this reason that we refuse to JIT-compile any
> function that uses exec, so I'm very surprised that testExec is
> failing in this way.
>
> Can you do a clean build, or even better, a clean build in a fresh
> checkout? Is this a release build or a --with-pydebug build?
It was a clean release build but I hadn't cleaned the .pyc files which
is where the problem came from. The old .pyc file has the code object
serialized without CO_USES_EXEC in co_flags. And of course the .pyc
file is only used when running via regrtest.py and not when running
standalone.
--
James Abbatiello
Collin Winter
Doh! I'll bump the import version number to minimize this. Thanks for
hunting this down!
Collin
James Abbatiello
> because the Linux out-of-memory killer might come and reap your firefox
> process.
Getting back on the original topic: I ran a debug build under the
debugger. And 7 hours (!) later it crashed in test_collections. It
is throwing a std::bad_alloc exception from "operator new()". Here's
the end of the call stack with the most recent call first:
kernel32.dll!_RaiseException@16() + 0x52 bytes
msvcr90d.dll!__CxxThrowException@8() + 0x52 bytes
msvcr90d.dll!operator new() + 0x77 bytes
> python26_d.dll!llvm::DenseMap<llvm::BasicBlock *,llvm::DominatorTreeBase<llvm::BasicBlock>::InfoRec,llvm::DenseMapInfo<llvm::BasicBlock *>,llvm::DenseMapInfo<llvm::DominatorTreeBase<llvm::BasicBlock>::InfoRec> >::grow(unsigned int AtLeast=131072) Line 357 + 0xe bytes C++
A couple of stack frames up is an llvm::DFSPass. I have the whole
call stack if anybody is interested. I'll leave the process suspended
in the debugger for as long as I can so if you want me to poke around,
say the word.
--
James Abbatiello
Jeffrey Yasskin
memory. (We'll want to catch those and turn them into Python
exceptions at some point.) I wouldn't expect the exact trace to be
particularly interesting. What matters more is the places that memory
was allocated, since that'll point us at the leak. Unfortunately, gdb
isn't going to tell you that. We'll have to run under OSX's
MallocDebug or google-perftools' heap-profiler or one of the valgrind
tools to track it down.
James Abbatiello
>
> std::bad_alloc is what we'd expect if it's simply running out of
> memory. (We'll want to catch those and turn them into Python
> exceptions at some point.) I wouldn't expect the exact trace to be
> particularly interesting. What matters more is the places that memory
> was allocated, since that'll point us at the leak. Unfortunately, gdb
> isn't going to tell you that. We'll have to run under OSX's
> MallocDebug or google-perftools' heap-profiler or one of the valgrind
> tools to track it down.
I suspected as much. I've been working on producing a reduced
testcase from test_collections, which is attached. Under -j always it
got up to over 800MB at its peak. Output looks like:
>python bigclass.py
loop 0: 0.000000 secs
loop 1: 0.000000 secs
loop 2: 0.000000 secs
loop 3: 0.000000 secs
loop 4: 0.000000 secs
loop 5: 0.000000 secs
loop 6: 0.000000 secs
loop 7: 0.000000 secs
loop 8: 0.000000 secs
loop 9: 0.000000 secs
loop 10: 0.016000 secs
loop 11: 0.016000 secs (0.999985x increase)
loop 12: 0.047000 secs (2.937534x increase)
loop 13: 0.078000 secs (1.659578x increase)
loop 14: 0.156000 secs (2.000000x increase)
loop 15: 0.375000 secs (2.403844x increase)
loop 16: 0.781000 secs (2.082667x increase)
loop 17: 1.937000 secs (2.480153x increase)
loop 18: 4.625000 secs (2.387713x increase)
loop 19: 11.703000 secs (2.530378x increase)
>python -j always bigclass.py
loop 0: 0.031000 secs
loop 1: 0.031000 secs (1.000008x increase)
loop 2: 0.031000 secs (0.999992x increase)
loop 3: 0.047000 secs (1.516132x increase)
loop 4: 0.047000 secs (1.000005x increase)
loop 5: 0.063000 secs (1.340420x increase)
loop 6: 0.093000 secs (1.476190x increase)
loop 7: 0.188000 secs (2.021506x increase)
loop 8: 0.375000 secs (1.994681x increase)
loop 9: 0.844000 secs (2.250666x increase)
loop 10: 2.797000 secs (3.313982x increase)
loop 11: 7.922000 secs (2.832320x increase)
loop 12: 29.485000 secs (3.721914x increase)
loop 13: 153.328000 secs (5.200203x increase)
loop 14: 636.641000 secs (4.152151x increase)
loop 15: 2773.985000 secs (4.357220x increase)
(I killed it here)
--
James Abbatiello
James Abbatiello
> I suspected as much. I've been working on producing a reduced
> testcase from test_collections, which is attached. Under -j always it
> got up to over 800MB at its peak. Output looks like:
With the below patch, things look like:
>python -j always bigclass.py
loop 0: 0.032000 secs
loop 1: 0.031000 secs (0.968745x increase)
loop 2: 0.031000 secs (1.000008x increase)
loop 3: 0.031000 secs (0.999992x increase)
loop 4: 0.047000 secs (1.516132x increase)
loop 5: 0.078000 secs (1.659578x increase)
loop 6: 0.094000 secs (1.205128x increase)
loop 7: 0.203000 secs (2.159570x increase)
loop 8: 0.391000 secs (1.926110x increase)
loop 9: 0.859000 secs (2.196931x increase)
loop 10: 3.000000 secs (3.492433x increase)
loop 11: 8.282000 secs (2.760667x increase)
loop 12: 30.531000 secs (3.686428x increase)
loop 13: 0.250000 secs (0.008188x increase)
loop 14: 1.328000 secs (5.312000x increase)
loop 15: 2.531000 secs (1.905873x increase)
loop 16: 2.078000 secs (0.821019x increase)
loop 17: 4.484000 secs (2.157844x increase)
loop 18: 10.016000 secs (2.233720x increase)
loop 19: 22.109000 secs (2.207368x increase)
And `python -j always Lib\test\regrtest.py` gets up to test_pydoc
before it runs out of memory. I'd be interested to see how far it
gets on a 64-bit platform.
This is just an ugly hack. A real solution would have to be on the
LLVM side but I'm not very familiar with the internals.
--
James Abbatiello
Index: Objects/codeobject.c
===================================================================
--- Objects/codeobject.c (revision 848)
+++ Objects/codeobject.c (working copy)
@@ -250,6 +250,10 @@
// exec.
if (code->co_flags & CO_USES_EXEC)
return 1;
+
+ if (PyString_Size(code->co_code) > 32000)
+ return 1;
+
if (code->co_llvm_function == NULL) {
code->co_llvm_function = _PyCode_ToLlvmIr(code);
if (code->co_llvm_function == NULL)
Jeffrey Yasskin
I think the apparent non-linearity here is the machine hitting cache
boundaries and then starting to swap. Still, thanks for the test case:
I'll see if I can use it to track down whatever's actually using the
memory. If I can't find it, I think your absolute size limit is a good
idea.
James Abbatiello
> I think the apparent non-linearity here is the machine hitting cache
> boundaries and then starting to swap. Still, thanks for the test case:
> I'll see if I can use it to track down whatever's actually using the
> memory. If I can't find it, I think your absolute size limit is a good
> idea.
Yes, those numbers aren't as convincing as I would have liked. Here's
a new test case. It has worse time performance but it doesn't seem to
soak up as much memory. Possibly these are separate problems.
0: 0.032000 secs
1: 0.015000 secs (0.468752x)
2: 0.047000 secs (3.133307x)
3: 0.078000 secs (1.659578x)
4: 0.188000 secs (2.410254x)
5: 0.531000 secs (2.824468x)
6: 1.671000 secs (3.146893x)
7: 6.438000 secs (3.852783x)
8: 29.375000 secs (4.562752x)
9: 191.343000 secs (6.513804x)
10: 745.672000 secs (3.897044x)
11: 3711.625000 secs (4.977557x)
--
James Abbatiello
Jeffrey Yasskin
Half of the space here is allocated inside _PyCode_ToOptimizedLlvmIr,
and the other half is in the JIT. It doesn't sound crazy for the JIT
to allocate as much as the IR, so I think the thing to do is apply
your patch to limit the size of functions that go through LLVM.
Reid Kleckner
in isolation there should be no difference between that and running
them together under regrtest.py.
Reid
Jeffrey Yasskin
Jeffrey Yasskin
> On Mon, Oct 5, 2009 at 9:41 PM, James Abbatiello <abb...@gmail.com> wrote:
>> On Mon, Oct 5, 2009 at 6:35 PM, Jeffrey Yasskin <jyas...@google.com> wrote:
>>> I think the apparent non-linearity here is the machine hitting cache
>>> boundaries and then starting to swap. Still, thanks for the test case:
>>> I'll see if I can use it to track down whatever's actually using the
>>> memory. If I can't find it, I think your absolute size limit is a good
>>> idea.
>>
>> a new test case. It has worse time performance but it doesn't seem to
>> soak up as much memory. Possibly these are separate problems.
>>
>> 0: 0.032000 secs
>> 1: 0.015000 secs (0.468752x)
>> 2: 0.047000 secs (3.133307x)
>> 3: 0.078000 secs (1.659578x)
>> 4: 0.188000 secs (2.410254x)
>> 5: 0.531000 secs (2.824468x)
>> 6: 1.671000 secs (3.146893x)
>> 7: 6.438000 secs (3.852783x)
>> 8: 29.375000 secs (4.562752x)
>> 9: 191.343000 secs (6.513804x)
>> 10: 745.672000 secs (3.897044x)
>> 11: 3711.625000 secs (4.977557x)
>
> DominatorTrees and GVN, at least in the samples I've taken. But it
> only gets up to 200MB, so the time growth is not swap-related. I'll
> look into this too.
>
instcombiner takes ~85% of the time on iteration 8, with 23% directly
in DoOneIteration (and functions inlined into it), and another 35% in
visitStoreInst:
23.6% 85.0% python.exe (anonymous
namespace)::InstCombiner::DoOneIteration(llvm::Function&, unsigned
int)
5.6% 35.7% python.exe (anonymous
namespace)::InstCombiner::visitStoreInst(llvm::StoreInst&)
1.0% 28.0% python.exe (anonymous
namespace)::InstCombiner::GetOrEnforceKnownAlignment(llvm::Value*,
unsigned int)
5.4% 24.3% python.exe
llvm::ComputeMaskedBits(llvm::Value*, llvm::APInt const&,
llvm::APInt&, llvm::APInt&, llvm::TargetData const*, unsigned int)
6.6% 16.7% python.exe
llvm::ComputeMaskedBits(llvm::Value*, llvm::APInt const&,
llvm::APInt&, llvm::APInt&, llvm::TargetData const*, unsigned int)
5.0% 9.0% python.exe
llvm::ComputeMaskedBits(llvm::Value*, llvm::APInt const&,
llvm::APInt&, llvm::APInt&, llvm::TargetData const*, unsigned int)
This might be off some since shark didn't necessarily get the
compilation. I'll run it again to check.
Jeffrey Yasskin
0.0% 95.8% python.exe llvm::FPPassManager::runOnFunction(llvm::Function&)
0.0% 44.0% python.exe (anonymous namespace)::InstCombiner::runOnFunction(llvm::Function&)
12.4% 43.9% python.exe (anonymous namespace)::InstCombiner::DoOneIteration(llvm::Function&, unsigned int)
2.8% 18.0% python.exe (anonymous namespace)::InstCombiner::visitStoreInst(llvm::StoreInst&)
0.5% 14.3% python.exe (anonymous namespace)::InstCombiner::GetOrEnforceKnownAlignment(llvm::Value*, unsigned int)
2.6% 12.4% python.exe llvm::ComputeMaskedBits(llvm::Value*, llvm::APInt const&, llvm::APInt&, llvm::APInt&, llvm::TargetData const*, unsigned int)
3.3% 8.6% python.exe llvm::ComputeMaskedBits(llvm::Value*, llvm::APInt const&, llvm::APInt&, llvm::APInt&, llvm::TargetData const*, unsigned int)
2.6% 4.8% python.exe llvm::ComputeMaskedBits(llvm::Value*, llvm::APInt const&, llvm::APInt&, llvm::APInt&, llvm::TargetData const*, unsigned int)
1.1% 1.2% python.exe llvm::ComputeMaskedBits(llvm::Value*, llvm::APInt const&, llvm::APInt&, llvm::APInt&, llvm::TargetData const*, unsigned int)
...
3.3% 3.3% python.exe llvm::Use::getUser() const
0.5% 2.3% python.exe (anonymous namespace)::InstCombiner::visitGetElementPtrInst(llvm::GetElementPtrInst&)
...
0.0% 30.3% python.exe (anonymous namespace)::CFGSimplifyPass::runOnFunction(llvm::Function&)
0.0% 30.0% python.exe IterativeSimplifyCFG(llvm::Function&)
0.1% 29.9% python.exe llvm::SimplifyCFG(llvm::BasicBlock*)
5.8% 29.1% python.exe TryToSimplifyUncondBranchFromEmptyBlock(llvm::BasicBlock*, llvm::BasicBlock*)
16.7% 16.7% python.exe llvm::Use::getUser() const
6.4% 6.4% python.exe llvm::PHINode::removeIncomingValue(unsigned int, bool)
Evidence that it's not just a lot of data:
0/exec: 0.000183 secs
0/llvm: 0.018555 secs
1/exec: 0.000456 secs (2.489583x)
1/llvm: 0.016740 secs (0.902191x)
2/exec: 0.000668 secs (1.465481x)
2/llvm: 0.030826 secs (1.841440x)
3/exec: 0.001185 secs (1.773733x)
3/llvm: 0.079226 secs (2.570116x)
4/exec: 0.002518 secs (2.124950x)
4/llvm: 0.259851 secs (3.279872x)
5/exec: 0.005022 secs (1.994508x)
5/llvm: 0.825521 secs (3.176899x)
6/exec: 0.013985 secs (2.784704x)
6/llvm: 2.383934 secs (2.887793x)
7/exec: 0.050981 secs (3.645413x)
7/llvm: 9.440545 secs (3.960070x)
8/exec: 0.050647 secs (0.993453x)
8/llvm: 45.619970 secs (4.832345x)
9/exec: 0.131348 secs (2.593403x)
(timing the exec call and the co_optimization=2 separately)
Jeffrey Yasskin
The instcombine part of this is reported as http://llvm.org/PR5150.
Thanks for the test case!
Jeffrey Yasskin
I sharked this, and after loop 12 where the "don't compile any more"
kicks in, we spend ~58% of our time in ConstantMirror and ~20% in
PyParser_ASTFromString. ConstantMirror's used in compiling the python
module that surrounds the big class, and it has a tuple of all the
variable names in the class. I think this is where the memory leak
comes from too. Because of some limitations in the JIT, we never run
globaldce to clean up unused GlobalVariables (ConstantMirror's
output), which means they and the PyObjects backing them stay around
forever.
todo-list+=globaldce
Jeffrey Yasskin
> On Thu, Oct 15, 2009 at 2:05 AM, Jeffrey Yasskin <jyas...@google.com> wrote:
>> That's the maximum number of Uses, right, not the average? We have a
>> couple blocks with O(N) in-edges (the unwind block and the
>> bail-to-interpreter block, at least), and those would each have a
>> couple phi nodes with O(N) operands. But there's a fixed number of
>> such phi nodes, so it shouldn't make the total number of Uses go above
>> O(N). getImpliedUser is known to be an expensive function, but I'd be
>> surprised if it's taking >O(n lg n) time. Although I've been surprised
>> at other LLVM bugs.
>>
>> One thing to look at is what's calling getImpliedUser. There may be an
>> algorithm that uses it more often than it needs to. I probably won't
>> get to look into this any more until the Q3 release is out and the JIT
>> allows us to run globaldce periodically, but it's definitely worth
>> chasing and filing LLVM bugs.
>
> Now that Q3 is out, I'm here to bother you again. I've done some more
> investigating and I think I have an idea of what's going on but I
> don't yet have a plan for a fix.
>
> The list of predecessors of a BasicBlock is not stored explicitly.
> Instead the code iterates over all Uses, throws out any Users that
> aren't TerminatorInsts, and grabs the parent block of each one. This
> means a getUser() call on each Use to find the type of the User.
>
> As you said, certain blocks are going to have a lot of in-edges. And
> they'll have a PHI which will have a lot of operands and a Use of each
> of the predecessor blocks.
>
> So lets say we are examining a block and it branches to one of those
> many-in-edges blocks. When we iterate over the predecessors we call
> getUser() on the Use belonging to the PHINode. This is slow because
> getUser() is slow when the User has a lot of Uses. And to add insult
> to injury, we skip over that PHINode because we aren't interested in
> it.
>
> The upshot is that finding the predecessors of a block can be slow
> when one of the *successors* of that block has a lot of predecessors.
> And since there are going to be O(n) blocks branching to the
> many-in-edges block, that means O(n) blocks for which it is slow to
> find the predecessors.
>
> The main culprits here are CanPropagatePredecessorsForPHIs and
> SplitCriticalEdge. The latter looks like it could be changed a bit to
> move the computation of OtherPreds down a bit and possibly bail out
> early and not have to iterate over all of them. I don't know if
> that's on the hot path or not or if it will help much. For the other,
> I don't have a really good idea.
>
> I suppose that we could steal a bit in Use to indicate that the User
> is a TerminatorInst but this feels a bit hackish. I'm hoping that
> somebody more familiar with LLVM internals and how everything fits
> together might have some thoughts. :)
Yeah, this definitely sounds like it could possibly be a problem. I'm
still not going to get a chance to look at it in depth, but Nick
sounded like he recognized the structure as a possible problem. To
file a bug (assuming Nick doesn't just fix it ;) we'd need to write a
script to generate successively larger test cases and show that `opt
-simplifycfg` takes a quadratic amount of time. See
http://llvm.org/PR3944 or http://llvm.org/PR5150 for sample scripts.
James Abbatiello
> Yeah, this definitely sounds like it could possibly be a problem. I'm
> still not going to get a chance to look at it in depth, but Nick
> sounded like he recognized the structure as a possible problem. To
> file a bug (assuming Nick doesn't just fix it ;) we'd need to write a
> script to generate successively larger test cases and show that `opt
> -simplifycfg` takes a quadratic amount of time. See
> http://llvm.org/PR3944 or http://llvm.org/PR5150 for sample scripts.
How about the attached script?
$ for B in 1000 2000 3000 4000 5000 6000 7000 8000 9000 10000; do
python previter-test.py $B | llvm-as | time opt -break-crit-edges >
/dev/null; done
0.01user 0.03system 0:00.13elapsed 33%CPU (0avgtext+0avgdata 109312maxresident)k
0inputs+0outputs (431major+0minor)pagefaults 0swaps
0.01user 0.01system 0:00.29elapsed 10%CPU (0avgtext+0avgdata 110336maxresident)k
0inputs+0outputs (431major+0minor)pagefaults 0swaps
0.01user 0.01system 0:00.51elapsed 5%CPU (0avgtext+0avgdata 110336maxresident)k
0inputs+0outputs (431major+0minor)pagefaults 0swaps
0.01user 0.00system 0:00.75elapsed 2%CPU (0avgtext+0avgdata 109312maxresident)k
0inputs+0outputs (431major+0minor)pagefaults 0swaps
0.01user 0.00system 0:01.27elapsed 1%CPU (0avgtext+0avgdata 110336maxresident)k
0inputs+0outputs (431major+0minor)pagefaults 0swaps
0.03user 0.00system 0:01.67elapsed 1%CPU (0avgtext+0avgdata 110336maxresident)k
0inputs+0outputs (431major+0minor)pagefaults 0swaps
0.01user 0.00system 0:02.17elapsed 0%CPU (0avgtext+0avgdata 110336maxresident)k
0inputs+0outputs (431major+0minor)pagefaults 0swaps
0.01user 0.01system 0:02.72elapsed 1%CPU (0avgtext+0avgdata 109312maxresident)k
0inputs+0outputs (431major+0minor)pagefaults 0swaps
0.01user 0.00system 0:06.16elapsed 0%CPU (0avgtext+0avgdata 110336maxresident)k
0inputs+0outputs (431major+0minor)pagefaults 0swaps
0.01user 0.01system 0:07.90elapsed 0%CPU (0avgtext+0avgdata 110336maxresident)k
0inputs+0outputs (431major+0minor)pagefaults 0swaps
Note that this is done under Cygwin so you should ignore everything
except wall-clock time.
--
James Abbatiello
Jeffrey Yasskin
> On Tue, Oct 27, 2009 at 1:24 PM, Jeffrey Yasskin <jyas...@google.com> wrote:
>> Yeah, this definitely sounds like it could possibly be a problem. I'm
>> still not going to get a chance to look at it in depth, but Nick
>> sounded like he recognized the structure as a possible problem. To
>> file a bug (assuming Nick doesn't just fix it ;) we'd need to write a
>> script to generate successively larger test cases and show that `opt
>> -simplifycfg` takes a quadratic amount of time. See
>> http://llvm.org/PR3944 or http://llvm.org/PR5150 for sample scripts.
>
> How about the attached script?
Nice script. I get:
$ for B in 4000 8000 12000 16000 20000 24000 28000; do
./previter-test.py $B|llvm-as|time opt -break-crit-edges > /dev/null;
done
1.40 real 0.55 user 0.11 sys
3.06 real 2.14 user 0.52 sys
8.48 real 6.34 user 1.50 sys
19.01 real 15.18 user 2.54 sys
47.14 real 36.16 user 5.76 sys
68.00 real 55.20 user 7.65 sys
88.97 real 74.37 user 9.73 sys
... which is ~linear after 16000 blocks. That's a Release+Debug-Asserts build.
James Abbatiello
> ... which is ~linear after 16000 blocks. That's a Release+Debug-Asserts build.
I think that's an "island of linearity". Here's a pretty graph:
http://spreadsheets.google.com/ccc?key=0AocrZyJL-71TdEZFS1lSLVh0NGlJZlpKWE9hdF95OWc
Red is experimentally collected data. Blue is a curve that I fit to that data.
The time isn't a monotonically increasing function of the input size
which I found surprising. I don't have an explanation for the humps
but I did a second run and they appeared both times.
--
James Abbatiello
Jeffrey Yasskin
James Abbatiello
> Huh! Well then please file an LLVM bug. :)
Filed http://llvm.org/bugs/show_bug.cgi?id=5361
Thanks for your help with this, Jeffrey.
--
James Abbatiello
Jeffrey Yasskin
You're quite welcome. :)
Did you pick break-crit-edges to focus on over simplifycfg because you
think they're the same problem, or because you found that simplifycfg
wasn't actually quadratic, or just because you had to pick one to work
on first? If it's the last, it's probably worth investigating
simplifycfg too and filing another bug if it's also quadratic.
Thanks again!
Jeffrey
James Abbatiello
> Did you pick break-crit-edges to focus on over simplifycfg because you
> think they're the same problem, or because you found that simplifycfg
> wasn't actually quadratic, or just because you had to pick one to work
> on first? If it's the last, it's probably worth investigating
> simplifycfg too and filing another bug if it's also quadratic.
I think the problems are at least related. I was able to come up with
a test-case that showed quadratic behavior in break-crit-edges but I
haven't been able to come up with one for simplifycfg. It may need
something else (maybe a constant-sized Phi per block) in order to hit
the right code path. If a fix for PR5361 doesn't come about
relatively quickly I may have some time to look into this in more
detail.
--
James Abbatiello
James Abbatiello
> I think the problems are at least related. I was able to come up with
> a test-case that showed quadratic behavior in break-crit-edges but I
> haven't been able to come up with one for simplifycfg. It may need
> something else (maybe a constant-sized Phi per block) in order to hit
> the right code path. If a fix for PR5361 doesn't come about
> relatively quickly I may have some time to look into this in more
> detail.
Well, I've had some time this weekend to look into simplifycfg. I
found a test case which looks rather different so it may not be a
related problem after all:
$ for B in 1000 2000 3000 4000 5000 6000 7000 8000 9000 10000; do
./simplifycfg-test.py $B | llvm-as | time -f "real %e" opt
-simplifycfg -f > /dev/null; done
real 0.35
real 1.17
real 2.50
real 4.37
real 6.79
real 9.68
real 13.17
real 17.11
real 21.65
real 26.68
If you think this looks good, I'll file another LLVM bug on it. I
could use a suggestion for what to put in the summary.
--
James Abbatiello
Jeffrey Yasskin
That's definitely quadratic (though note that user time is a better
estimate of a pass's running time). I'm amazed that simplifycfg is
enough to optimize this. I've reproduced this with a Release-Asserts
build from head, so definitely file it. The summary could be
"simplifycfg quadratic on sequence of br (load!=0) %end, %next
blocks". Then give an example of the block structure in the report so
people are only confused by the summary for a short time. ;)
Thanks!
Jeffrey
James Abbatiello
> That's definitely quadratic (though note that user time is a better
> estimate of a pass's running time). I'm amazed that simplifycfg is
> enough to optimize this. I've reproduced this with a Release-Asserts
> build from head, so definitely file it. The summary could be
> "simplifycfg quadratic on sequence of br (load!=0) %end, %next
> blocks". Then give an example of the block structure in the report so
> people are only confused by the summary for a short time. ;)
Filed http://llvm.org/bugs/show_bug.cgi?id=5860
I would have used user time but it doesn't work properly for me in Cygwin.
Thanks for looking it over for me.
--
James Abbatiello