stack_alloc_speed

[Ben Goodrich]

With develop, I get a std::bad_alloc exception for the stack_alloc_speed test with clang++-3.5 (shown below) and all versions of g++

goodrich@CYBERPOWERPC:/opt/stan$ make CC=clang++ -j9 test/unit/memory/stack_alloc_speed
clang++ -I src -isystem lib/eigen_3.2.0 -isystem lib/boost_1.54.0 -Wall -DBOOST_RESULT_OF_USE_TR1 -DBOOST_NO_DECLTYPE -DBOOST_DISABLE_ASSERTS -pipe -fsanitize=memory -Wno-unused-function -Wno-uninitialized -Wno-c++11-long-long   -c -O3 -DGTEST_USE_OWN_TR1_TUPLE -DGTEST_HAS_PTHREAD=0 -Wno-c++11-long-long -I lib/gtest_1.7.0/include -I lib/gtest_1.7.0 lib/gtest_1.7.0/src/gtest-all.cc -o test/gtest.o
clang++ -I src -isystem lib/eigen_3.2.0 -isystem lib/boost_1.54.0 -Wall -DBOOST_RESULT_OF_USE_TR1 -DBOOST_NO_DECLTYPE -DBOOST_DISABLE_ASSERTS -pipe -fsanitize=memory -Wno-unused-function -Wno-uninitialized -Wno-c++11-long-long   -c -O3 -o bin/stan/agrad/rev/var_stack.o src/stan/agrad/rev/var_stack.cpp
ar -rs bin/libstan.a bin/stan/agrad/rev/var_stack.o
ar: creating bin/libstan.a
ar rv test/libgtest.a test/gtest.o
ar: creating test/libgtest.a
a - test/gtest.o
clang++ -I src -isystem lib/eigen_3.2.0 -isystem lib/boost_1.54.0 -Wall -DBOOST_RESULT_OF_USE_TR1 -DBOOST_NO_DECLTYPE -DBOOST_DISABLE_ASSERTS -pipe -fsanitize=memory -Wno-unused-function -Wno-uninitialized -Wno-c++11-long-long   -c -O3 -DGTEST_USE_OWN_TR1_TUPLE -DGTEST_HAS_PTHREAD=0 -Wno-c++11-long-long -I lib/gtest_1.7.0/include -I lib/gtest_1.7.0 src/test/unit/memory/stack_alloc_speed_test.cpp -o test/unit/memory/stack_alloc_speed.o
clang++ -I src -isystem lib/eigen_3.2.0 -isystem lib/boost_1.54.0 -Wall -DBOOST_RESULT_OF_USE_TR1 -DBOOST_NO_DECLTYPE -DBOOST_DISABLE_ASSERTS -pipe -fsanitize=memory -Wno-unused-function -Wno-uninitialized -Wno-c++11-long-long    -O3 lib/gtest_1.7.0/src/gtest_main.cc test/unit/memory/stack_alloc_speed.o -DGTEST_USE_OWN_TR1_TUPLE -DGTEST_HAS_PTHREAD=0 -Wno-c++11-long-long -I lib/gtest_1.7.0/include -I lib/gtest_1.7.0 -o test/unit/memory/stack_alloc_speed test/libgtest.a -Lbin -lstan
test/unit/memory/stack_alloc_speed --gtest_output="xml:test/unit/memory/stack_alloc_speed.xml"
==1550==ERROR: MemorySanitizer failed to allocate 0x1fffffffffff (35184372088831) bytes at address 35184372088832 (12)
FATAL: MemorySanitizer can not mmap the shadow memory.
FATAL: Make sure to compile with -fPIE and to link with -pie.
FATAL: Disabling ASLR is known to cause this error.
FATAL: If running under GDB, try 'set disable-randomization off'.
==1550==Process memory map follows:
        0x7f66934c6000-0x7f6693666000   /lib/x86_64-linux-gnu/libc-2.18.so
        0x7f6693666000-0x7f6693865000   /lib/x86_64-linux-gnu/libc-2.18.so
        0x7f6693865000-0x7f6693869000   /lib/x86_64-linux-gnu/libc-2.18.so
        0x7f6693869000-0x7f669386b000   /lib/x86_64-linux-gnu/libc-2.18.so
        0x7f669386b000-0x7f669386f000
        0x7f669386f000-0x7f6693884000   /lib/x86_64-linux-gnu/libgcc_s.so.1
        0x7f6693884000-0x7f6693a84000   /lib/x86_64-linux-gnu/libgcc_s.so.1
        0x7f6693a84000-0x7f6693a85000   /lib/x86_64-linux-gnu/libgcc_s.so.1
        0x7f6693a85000-0x7f6693b72000   /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.20
        0x7f6693b72000-0x7f6693d72000   /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.20
        0x7f6693d72000-0x7f6693d7a000   /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.20
        0x7f6693d7a000-0x7f6693d7c000   /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.20
        0x7f6693d7c000-0x7f6693d91000
        0x7f6693d91000-0x7f6693e92000   /lib/x86_64-linux-gnu/libm-2.18.so
        0x7f6693e92000-0x7f6694092000   /lib/x86_64-linux-gnu/libm-2.18.so
        0x7f6694092000-0x7f6694093000   /lib/x86_64-linux-gnu/libm-2.18.so
        0x7f6694093000-0x7f6694094000   /lib/x86_64-linux-gnu/libm-2.18.so
        0x7f6694094000-0x7f6694097000   /lib/x86_64-linux-gnu/libdl-2.18.so
        0x7f6694097000-0x7f6694296000   /lib/x86_64-linux-gnu/libdl-2.18.so
        0x7f6694296000-0x7f6694297000   /lib/x86_64-linux-gnu/libdl-2.18.so
        0x7f6694297000-0x7f6694298000   /lib/x86_64-linux-gnu/libdl-2.18.so
        0x7f6694298000-0x7f669429f000   /lib/x86_64-linux-gnu/librt-2.18.so
        0x7f669429f000-0x7f669449e000   /lib/x86_64-linux-gnu/librt-2.18.so
        0x7f669449e000-0x7f669449f000   /lib/x86_64-linux-gnu/librt-2.18.so
        0x7f669449f000-0x7f66944a0000   /lib/x86_64-linux-gnu/librt-2.18.so
        0x7f66944a0000-0x7f66944b8000   /lib/x86_64-linux-gnu/libpthread-2.18.so
        0x7f66944b8000-0x7f66946b7000   /lib/x86_64-linux-gnu/libpthread-2.18.so
        0x7f66946b7000-0x7f66946b8000   /lib/x86_64-linux-gnu/libpthread-2.18.so
        0x7f66946b8000-0x7f66946b9000   /lib/x86_64-linux-gnu/libpthread-2.18.so
        0x7f66946b9000-0x7f66946bd000
        0x7f66946bd000-0x7f66946dd000   /lib/x86_64-linux-gnu/ld-2.18.so
        0x7f6694884000-0x7f66948a6000
        0x7f66948d0000-0x7f66948dc000
        0x7f66948dc000-0x7f66948dd000   /lib/x86_64-linux-gnu/ld-2.18.so
        0x7f66948dd000-0x7f66948de000   /lib/x86_64-linux-gnu/ld-2.18.so
        0x7f66948de000-0x7f66948df000
        0x7f66948df000-0x7f6694a50000   /opt/stan/test/unit/memory/stack_alloc_speed
        0x7f6694c50000-0x7f6694c52000   /opt/stan/test/unit/memory/stack_alloc_speed
        0x7f6694c52000-0x7f669686d000
        0x7fffa0224000-0x7fffa0245000   [stack]
        0x7fffa03df000-0x7fffa03e1000   [vdso]
        0xffffffffff600000-0xffffffffff601000   [vsyscall]
==1550==End of process memory map.
make: *** [test/unit/memory/stack_alloc_speed] Error 77

The gdb output is not any more helpful

(gdb) run
Starting program: /opt/stan/test/unit/memory/./stack_alloc_speed
warning: Could not load shared library symbols for linux-vdso.so.1.
Do you need "set solib-search-path" or "set sysroot"?
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Running main() from gtest_main.cc
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from stack_alloc
[ RUN      ] stack_alloc.speed_of_allocator
Catchpoint 1 (exception thrown), 0x00007ffff7913f00 in __cxa_throw () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
(gdb) bt
#0  0x00007ffff7913f00 in __cxa_throw () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#1  0x000000000040480f in stack_alloc_speed_of_allocator_Test::TestBody() ()
#2  0x0000000000420661 in void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) ()
#3  0x000000000042276f in void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) ()
#4  0x000000000041500e in testing::Test::Run() ()
#5  0x00000000004150eb in testing::TestInfo::Run() ()
#6  0x00000000004151db in testing::TestCase::Run() ()
#7  0x000000000041544d in testing::internal::UnitTestImpl::RunAllTests() ()
#8  0x0000000000420d62 in bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) ()
#9  0x0000000000422b99 in bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) ()
#10 0x0000000000415686 in testing::UnitTest::Run() ()
#11 0x0000000000404321 in main ()

It passes if I change the second loop to terminate at 10000

goodrich@CYBERPOWERPC:/opt/stan$ cat src/test/unit/memory/stack_alloc_speed_test.cpp
#include <stan/memory/stack_alloc.hpp>
#include <gtest/gtest.h>

TEST(stack_alloc, speed_of_allocator) {
  stan::memory::stack_alloc allocator;
  for (size_t m = 0; m < 10000; m++) {
    for (size_t n = 1; n <= 100000; ++n) {
      allocator.alloc(n);
    }
    allocator.recover_all();
  }
}

Ben

[Bob Carpenter]

Thanks for diving into this. More inline.

On Mar 3, 2014, at 10:33 PM, Ben Goodrich <goodri...@gmail.com> wrote:

>
> With develop, I get a std::bad_alloc exception for the stack_alloc_speed test with clang++-3.5 (shown below) and all versions of g++
>

> ==1550==ERROR: MemorySanitizer failed to allocate 0x1fffffffffff (35184372088831) bytes at address 35184372088832 (12)

That's whack. No idea why it's trying to allocate so many bytes here.
The error makes it look like it's trying to swap:

> FATAL: MemorySanitizer can not mmap the shadow memory.

Any idea what PIE or -pie are?

> FATAL: Make sure to compile with -fPIE and to link with -pie.
> FATAL: Disabling ASLR is known to cause this error.

ASLR? That looks like "address space layout randomization". Does
that mean the test is just jumping up where it tries to do the allocation
each time? That doesn't seem realistic, but would cause the fail.

> FATAL: If running under GDB, try 'set disable-randomization off'.

Is that supposed to un-disable ASLR? Too many negations!

But it is jumped way up in memory:

>
> 0xffffffffff600000-0xffffffffff601000 [vsyscall]
> ==1550==End of process memory map.
> make: *** [test/unit/memory/stack_alloc_speed] Error 77
>
>
> The gdb output is not any more helpful

Thanks for trying!

>
> It passes if I change the second loop to terminate at 10000
>
> goodrich@CYBERPOWERPC:/opt/stan$ cat src/test/unit/memory/stack_alloc_speed_test.cpp
> #include <stan/memory/stack_alloc.hpp>
> #include <gtest/gtest.h>
>
> TEST(stack_alloc, speed_of_allocator) {
> stan::memory::stack_alloc allocator;
> for (size_t m = 0; m < 10000; m++) {
> for (size_t n = 1; n <= 100000; ++n) {
> allocator.alloc(n);
> }
> allocator.recover_all();
> }
> }

I think that's more illuminating because chaning that to 10K, it's 10K * 10K, so
it should just use 100MB. Whereas with 100K * 10K, it's using 1GB. Still, I
wouldn't think that'd balk.

I don't see why recover_all doesn't reset back to the beginning. Here's
the code:

inline void recover_all() {
cur_block_ = 0;
next_loc_ = blocks_[0];
cur_block_end_ = next_loc_ + sizes_[0];
}

These ever-shifting C++ compilers are really frustrating. I take it you
did this in earlier compilers without a problem?

Here's the sanitizer code that's throwing the error:

https://llvm.org/svn/llvm-project/compiler-rt/trunk/lib/msan/msan_allocator.cc

But I'm not going to worry about it if only the sanitizer is causing
problems. From looking at the code, it looks like it never deallocs (see
MSanDeallocate function). It's own doc:

http://clang.llvm.org/docs/MemorySanitizer.html

says it's an experimental tool.

Also, we don't want to check that all of our allocated memory is
clean --- we intentionally allocate memory that we don't ever fill
because we have sizes that overrun boundaries of blocks so have to
go in the next block. Could this be the source of the problem?

- Bob

[Ben Goodrich]

On Monday, March 3, 2014 5:12:13 PM UTC-5, Bob Carpenter wrote:

These ever-shifting C++ compilers are really frustrating.    I take it you
did this in earlier compilers without a problem?

Not sure about any of your other questions, but it is a problem today with earlier compilers and no -fsanatize=memory. You just get a std::bad_alloc exception, and an unhelpful backtrace from gdb. I'll try to bisect it.

Ben

[Daniel Lee]

Is this just a symptom of not being able to allocate a contiguous block of memory? Or do you think this is a bug our implementation somewhere?

--
You received this message because you are subscribed to the Google Groups "stan development mailing list" group.
To unsubscribe from this group and stop receiving emails from it, send an email to stan-dev+u...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

[Ben Goodrich]

This is weird. That test did pass at one point but git bisect terminates on a SHA where that test doesn't exist

goodrich@CYBERPOWERPC:/opt/stan$ git bisect log
git bisect start
# bad: [0a7bc82daa80efe891a2aa2176acc60466539d29] Merge branch 'develop' of https://github.com/stan-dev/stan into develop
git bisect bad 0a7bc82daa80efe891a2aa2176acc60466539d29
# good: [7d8c9b228f8ca96897db81fd930b430ce624efb7] Merge pull request #494 from stan-dev/hotfix/v2.1.1
git bisect good 7d8c9b228f8ca96897db81fd930b430ce624efb7
# bad: [2a0d7f4d961891b6300360ea0b9ee2f97ab77be4] Merge pull request #526 from stan-dev/feature/issue-427
git bisect bad 2a0d7f4d961891b6300360ea0b9ee2f97ab77be4
# bad: [479e612f9733086798b37a2949c45e30751a54b3] Merge pull request #539 from stan-dev/feature/issue-335-vect-log-prob
git bisect bad 479e612f9733086798b37a2949c45e30751a54b3
# bad: [51508f2f7e371a61d87a901177b17b4c557bb04a] Merge branch 'develop' into feature/persistent_sampler
git bisect bad 51508f2f7e371a61d87a901177b17b4c557bb04a
# bad: [f6f709303be2591241bbaa13189fcc99ab633eb1] Merge branch 'feature/issue_296' into develop
git bisect bad f6f709303be2591241bbaa13189fcc99ab633eb1
# good: [bb04ae5b1596ad0f5797166918d655f0205d0e53] Merge pull request #510 from stan-dev/feature/disable-failing-model-tests
git bisect good bb04ae5b1596ad0f5797166918d655f0205d0e53
# bad: [ef572c42e35a81941ef04496e1145e47867258a3] Merge pull request #505 from stan-dev/feature/issue-493-remove-test-dependency-on-compiling-grammars
git bisect bad ef572c42e35a81941ef04496e1145e47867258a3
# skip: [4253b49c6c79953d89d1bb3abc090fe6e1034de4] moved location of static pattern rule to after GRAMMAR_TESTS were defined
git bisect skip 4253b49c6c79953d89d1bb3abc090fe6e1034de4
# skip: [13a7440f5f60a979d18c78d29b599d433b1c796f] remove test dependency on compiling grammars
git bisect skip 13a7440f5f60a979d18c78d29b599d433b1c796f
# only skipped commits left to test
# possible first bad commit: [ef572c42e35a81941ef04496e1145e47867258a3] Merge pull request #505 from stan-dev/feature/issue-493-remove-test-dependency-on-compiling-grammars
# possible first bad commit: [4253b49c6c79953d89d1bb3abc090fe6e1034de4] moved location of static pattern rule to after GRAMMAR_TESTS were defined
# possible first bad commit: [13a7440f5f60a979d18c78d29b599d433b1c796f] remove test dependency on compiling grammars

I don't think those possible bad commits have anything to do with it.

Ben

[Ben Goodrich]

On Monday, March 3, 2014 5:23:09 PM UTC-5, Ben Goodrich wrote:

The last successful iteration is 65533 or 2^16-ish. Does that mean anything to anyone?

Ben

[Ben Goodrich]

On Monday, March 3, 2014 5:23:09 PM UTC-5, Ben Goodrich wrote:

I got a slightly more precise backtrace from gdb now

Catchpoint 1 (exception thrown), 0x00007ffff7913f00 in __cxa_throw () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
(gdb) bt
#0  0x00007ffff7913f00 in __cxa_throw () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6

#1  0x0000000000404a6e in stan::memory::stack_alloc::move_to_next_block (this=0x7fffffffdd50, len=65534) at src/stan/memory/stack_alloc.hpp:109
#2  0x0000000000404d90 in stan::memory::stack_alloc::alloc (this=0x7fffffffdd50, len=65534) at src/stan/memory/stack_alloc.hpp:171
#3  0x00000000004047c7 in stack_alloc_speed_of_allocator_Test::TestBody (this=0x64f640) at src/test/unit/memory/stack_alloc_speed_test.cpp:8
#4  0x0000000000429adc in testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void> (object=0x64f640, method=&virtual testing::Test::TestBody(), location=0x433903 "the test body")
    at lib/gtest_1.7.0/src/gtest.cc:2078
#5  0x000000000042511a in testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void> (object=0x64f640, method=&virtual testing::Test::TestBody(), location=0x433903 "the test body") at lib/gtest_1.7.0/src/gtest.cc:2114
#6  0x000000000040c5d9 in testing::Test::Run (this=0x64f640) at lib/gtest_1.7.0/src/gtest.cc:2151
#7  0x000000000040cdb8 in testing::TestInfo::Run (this=0x64f0a0) at lib/gtest_1.7.0/src/gtest.cc:2326
#8  0x000000000040d4aa in testing::TestCase::Run (this=0x64f400) at lib/gtest_1.7.0/src/gtest.cc:2444
#9  0x0000000000413c8a in testing::internal::UnitTestImpl::RunAllTests (this=0x64f130) at lib/gtest_1.7.0/src/gtest.cc:4315
#10 0x000000000042af36 in testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool> (object=0x64f130,
    method=(bool (testing::internal::UnitTestImpl::*)(testing::internal::UnitTestImpl * const)) 0x413a0e <testing::internal::UnitTestImpl::RunAllTests()>, location=0x4341e0 "auxiliary test code (environments or event listeners)")
    at lib/gtest_1.7.0/src/gtest.cc:2078
#11 0x0000000000425fb8 in testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool> (object=0x64f130,
    method=(bool (testing::internal::UnitTestImpl::*)(testing::internal::UnitTestImpl * const)) 0x413a0e <testing::internal::UnitTestImpl::RunAllTests()>, location=0x4341e0 "auxiliary test code (environments or event listeners)")
    at lib/gtest_1.7.0/src/gtest.cc:2114
#12 0x00000000004129a2 in testing::UnitTest::Run (this=0x64ecf0 <testing::UnitTest::GetInstance()::instance>) at lib/gtest_1.7.0/src/gtest.cc:3929
#13 0x0000000000404633 in RUN_ALL_TESTS () at lib/gtest_1.7.0/include/gtest/gtest.h:2288
#14 0x00000000004045ce in main (argc=1, argv=0x7fffffffe228) at lib/gtest_1.7.0/src/gtest_main.cc:37

 This happens

        // Occasionally, we have to switch blocks.
        if (unlikely(next_loc_ >= cur_block_end_))
          result = move_to_next_block(len);
        return (void*)result;
      }

See Ben print

(gdb) print result
$1 = 0x7fffb70e6092 ""
(gdb) print *result
$2 = 0 '\000'
(gdb) frame 1
#1  0x0000000000404a6e in stan::memory::stack_alloc::move_to_next_block (this=0x7fffffffdd50, len=65534) at src/stan/memory/stack_alloc.hpp:109
109                 throw std::bad_alloc();
(gdb) print blocks_.back()
$3 = (char *&) @0x64f608: 0x0
(gdb) print newsize
$6 = 2147483648
(gdb) print len
$7 = 65534
(gdb) print blocks_.size()
$8 = 16
(gdb) print cur_block_
$9 = 15
(gdb) print sizes_[cur_block_]
$11 = (unsigned long &) @0x64f7e8: 0

Maybe we should fix this FIXME?

      // FIXME: enforce alignment
      // big fun to inline, but only called twice
      inline char* eight_byte_aligned_malloc(size_t size) {

Ben

[Bob Carpenter]

This is the problem with doc --- it gets out of date. As you can
see in the body of eight_byte_aligned_malloc(), the alignment
is enforced by the throw after the is_aligned() check.

- Bob

On Mar 4, 2014, at 5:02 AM, Ben Goodrich <goodri...@gmail.com> wrote:
> ...

[Bob Carpenter]

This is helpful.

The test's failing when it tries to allocate a 2GB block.
Is that somehow prohibited by this program? Can you test
something that just mallocs something this size and see
if it works?

The loop allocates blocks of 1...100K, or a total of
5,000,050,000 bytes. And it'll actually need a bit more
than that in the end because it has to squeeze everything
in evenly.

- Bob

[Bob Carpenter]

[Ben Goodrich]

On Tuesday, March 4, 2014 8:19:14 AM UTC-5, Bob Carpenter wrote:

This is helpful.  

The test's failing when it tries to allocate a 2GB block.
Is that somehow prohibited by this program?  Can you test
something that just mallocs something this size and see
if it works?

Ah, I figured it out. Not a bug.

I couple days ago I configured that tab to limit the memory of a process to 2GB when I was trying to investigate that memory leak that I emailed you about. Then I forgot I was using that same tab when I was trying to do the unit tests.

That said, we need to keep all individual tests below 2GB (at least with clang++) because the most basic tier of availability on the Columbia cluster is limited to 2GB per process. There are hundreds of cores available for that purpose and we can basically do 1 core per unit test. If you need more memory, you have to wait for one of the much fewer number of big memory slots to become available.

Ben