Win32 std::bad_alloc during make testall1

[tkelman]

ref #10394 (comment)

When run one at a time via something like include("test/choosetests.jl"); testlist, net_on = choosetests(); for i in testlist; try Base.runtests(i, 1); catch; end; end, all tests pass in this configuration at b8aa30d. However running standard make testall1 results in (also note the really awful performance)

    JULIA test/all
     * linalg1              in 114.59 seconds
     * linalg2              in  95.28 seconds
     * linalg3              in  40.11 seconds
     * linalg4              in  14.75 seconds
     * linalg/lapack        in   6.95 seconds
     * linalg/triangular    in 1028.06 seconds
     * linalg/tridiag       in  31.62 seconds
     * linalg/bidiag        in  49.95 seconds
     * linalg/diagonal      in  36.07 seconds
     * linalg/pinv          in  29.31 seconds
     * linalg/givens        in  18.50 seconds
     * linalg/cholesky      in  78.32 seconds
     * linalg/lu            in  51.09 seconds
     * linalg/symmetric     in  52.06 seconds
     * linalg/arnoldi       in  78.38 seconds
     * core                 in 283.12 seconds
     * keywordargs          in  36.12 seconds
     * numbers              in 1103.33 seconds
     * strings              in 471.06 seconds
     * dates                in 1203.63 seconds
     * dict                 in 176.02 seconds
     * hashing
This application has requested the Runtime to terminate it in an unusual way.
Please contact the application's support team for more information.
terminate called after throwing an instance of 'std::bad_alloc'
  what():  std::bad_alloc
Makefile:9: recipe for target 'all' failed
make[1]: *** [all] Error 3
Makefile:492: recipe for target 'testall1' failed
make: *** [testall1] Error 2

If I do make test with 3 simultaneous workers, I get the same exception at a different place.

    JULIA test/all
        From worker 4:       * linalg3              in  77.08 seconds
        From worker 4:       * linalg4              in  18.90 seconds
        From worker 4:       * linalg/lapack        in  12.60 seconds
        From worker 3:       * linalg2              in 150.06 seconds
        From worker 3:       * linalg/tridiag       in  18.33 seconds
        From worker 2:       * linalg1              in 205.75 seconds
        From worker 3:       * linalg/bidiag        in  56.38 seconds
        From worker 2:       * linalg/diagonal      in  34.59 seconds
        From worker 3:       * linalg/pinv          in  33.00 seconds
        From worker 2:       * linalg/givens        in  17.79 seconds
        From worker 2:       * linalg/lu            in  46.05 seconds
        From worker 2:       * linalg/symmetric     in  34.39 seconds
        From worker 3:       * linalg/cholesky      in 123.67 seconds
        From worker 2:       * linalg/arnoldi       in  62.23 seconds
        From worker 2:       * keywordargs          in  22.07 seconds
        From worker 3:       * core                 in 179.23 seconds
        From worker 3:       * strings              in 314.78 seconds
        From worker 2:       * numbers              in 766.31 seconds
        From worker 2:       * dict                 in 130.68 seconds
        From worker 4:       * linalg/triangular    in 1496.39 seconds
        From worker 4:       * remote               in   4.32 seconds
        From worker 2:       * hashing              in 312.99 seconds
        From worker 4:       * iobuffer             in  28.52 seconds
        From worker 2:       * staged               in  21.23 seconds
        From worker 2:       * tuple                in  39.91 seconds
        From worker 3:       * dates                in 904.55 seconds
        From worker 3:       * reduce               in 111.45 seconds
        From worker 3:       * reducedim            in 251.95 seconds
        From worker 4:       * arrayops             in 714.60 seconds
        From worker 4:       * intfuncs             in  56.20 seconds
        From worker 4:       * simdloop             in  48.57 seconds
        From worker 3:       * random               in 377.39 seconds
        From worker 4:       * blas                 in  93.34 seconds
        From worker 3:       * sparse               in 769.23 seconds
        From worker 3:       * copy                 in  41.79 seconds

This application has requested the Runtime to terminate it in an unusual way.
Please contact the application's support team for more information.
terminate called after throwing an instance of 'std::bad_alloc'
  what():  std::bad_alloc
        From worker 3:       * math                Worker 3 terminated.
ERROR (unhandled task failure): readcb: connection reset by peer (ECONNRESET)
 in yieldto at .\task.jl:19
 in wait at <invalid> (repeats 2 times)
 in wait_full at <invalid>
 in remotecall_fetch at .\multi.jl:670
 in remotecall_fetch at .\multi.jl:675
 in anonymous at .\task.jl:1390
        From worker 4:       * bitarray             in 822.41 seconds
        From worker 2:       * subarray             in 2596.30 seconds
ERROR: LoadError: ProcessExitedException()
 in yieldto at .\task.jl:19
 in wait at <invalid> (repeats 2 times)
 in wait_full at <invalid>
 in remotecall_fetch at .\multi.jl:670
 in remotecall_fetch at .\multi.jl:675
 in anonymous at .\task.jl:1390
while loading D:\cygwin64\home\Tony\julia32\test\runtests.jl, in expression starting on line 3

WARNING: Forcibly interrupting busy workers
Makefile:9: recipe for target 'all' failed
make[1]: *** [all] Error 1
Makefile:485: recipe for target 'test' failed
make: *** [test] Error 2

[vtjnash]

is this possible just an OOM exception coming from C++? any idea what the memory usage profile looks like by that point in the test?

[tkelman]

In task manager it's on the order of 500-600 MB, but it doesn't look like it's obviously exploding into hitting swap.

[vtjnash]

memory fragmentation could start to be a big issue at that size. if you have 3-4GB of memory in the machine, there's little reason (or ability) for the machine to use swap space, since the bigger problem is that the program is running out of virtual memory addresses

is that 500-600 MB total or per process?

[tkelman]

Per process. Gets to maybe 80% usage in the 3-workers case, but it's under 70% when doing make testall1

edit: machine has 6 gb total, background other junk I have running takes maybe half of that though

[vtjnash]

edit: machine has 6 gb total, background other junk I have running takes maybe half of that though

but since its x32 julia, it can only access up to 3 GB before it runs out of virtual address for that process. if llvm wants to allocate a big array, there may simply not be enough consecutive free addresses left to hand out

[tkelman]

Mis-remembered, I'm running make testall again now and it's at 800 MB, partway through dates.

Do we never free JIT-ed code? This hadn't really been an issue with LLVM 3.3 that I can remember, but presumably the memory layout of JIT-ed code is much different with MCJIT.

[vtjnash]

JIT code is probably a bit more expensive in LLVM 3.5 since it also comes with debug info. And no, we never free JIT code. It's pretty hard to analyze whether a particular function might have a pointer alive somewhere, so we don't bother. Generating the JIT code in the first place is pretty expensive, so the benefits of being able to free it eagerly are somewhat doubtful.

[tkelman]

the benefits of being able to free it eagerly are somewhat doubtful

Like not running out of memory in a long-running process?

edit: doesn't necessarily have to be freed eagerly of course, but some mechanism for stale code cleanup seems like it might be needed

[vtjnash]

the code is never really stale, since there is always the possibility it would be used again (for example, if you ran the same test again). but running a full coverage test suite isn't really a typical workload since it is doing a lot of one-off work, for the purpose of seeing if the code generation is correct, then moving on.

[tkelman]

True, the unit test suite is not a typical workload, but there's some major regression here. And I can reproduce the abysmal performance at least on a 32-bit Linux build, so this might not entirely be Windows-specific. make testall1 has been going for over an hour now and it's on subarray.

edit: see https://gist.github.com/tkelman/52e8849048b9e32abf7b - pretty old machine, but the performance is unacceptably worse on llvm 3.6.0 vs 3.3 for 32 bit. No bad_alloc, but not sure if running a 32 bit executable in 64 bit Linux behaves differently here than running a 32 bit executable in 64 bit Windows does.

[vtjnash]

what type of machine is this on? tests for me are getting much further and running faster, on a low-end 64-bit Atom (executing a cross-compiled julia on a smb mount inside cygwin):

julia@juliawin ~/juliamit/julia32
$ make testall1
    JULIA test/all
     * linalg1              in 544.80 seconds
     * linalg2              in 115.80 seconds
     * linalg3              in  63.38 seconds
     * linalg4              in  32.15 seconds
     * linalg/lapack        in   6.92 seconds
     * linalg/triangular    in 303.30 seconds
     * linalg/tridiag       in  10.45 seconds
     * linalg/bidiag        in  24.26 seconds
     * linalg/diagonal      in   8.92 seconds
     * linalg/pinv          in  69.52 seconds
     * linalg/givens        in  14.32 seconds
     * linalg/cholesky      in  34.08 seconds
     * linalg/lu            in  34.01 seconds
     * linalg/symmetric    d[1:2] = [-3.5788910700094694,-2.529985231766456]
 in  10.67 seconds
     * linalg/arnoldi       in  68.79 seconds
     * core                 in  62.18 seconds
     * keywordargs          in   5.85 seconds
     * numbers              in 235.06 seconds
     * strings              in  84.64 seconds
     * dates                in 274.36 seconds
     * dict                 in  45.35 seconds
     * hashing              in  28.80 seconds
     * remote               in   1.29 seconds
     * iobuffer             in   4.34 seconds
     * staged               in   2.46 seconds
     * arrayops             in 141.51 seconds
     * tuple                in   4.66 seconds
     * subarray             in 932.54 seconds
     * reduce               in  17.64 seconds
     * reducedim            in 113.76 seconds
     * random               in  59.52 seconds
     * intfuncs             in   3.54 seconds
     * simdloop             in   6.79 seconds
     * blas                 in   6.74 seconds
     * sparse               in 264.10 seconds
     * bitarray             in 300.42 seconds
     * copy                 in  11.92 seconds
     * math                 in  45.91 seconds
     * fastmath             in  17.31 seconds
     * functional           in   6.38 seconds
     * operators            in   0.83 seconds
     * path                 in   4.61 seconds
     * ccall                in  10.65 seconds
     * unicode              in  18.43 seconds
     * bigint               in  11.87 seconds
     * sorting              in 147.97 seconds
     * statistics           in  64.19 seconds
     * spawn                      [stdio passthrough ok]
 in  31.63 seconds
     * backtrace            in   0.60 seconds
     * priorityqueue        in   6.78 seconds
     * file                exception on 1: ERROR: LoadError: WindowsXP does not support soft symlinks
 in symlink at fs.jl:168
 in runtests at J:\julia32\test\testdefs.jl:77
 in anonymous at multi.jl:626
 in run_work_thunk at multi.jl:587
 in remotecall_fetch at multi.jl:675
 in anonymous at task.jl:1390
while loading J:\julia32\test\file.jl, in expression starting on line 17
ERROR: LoadError: LoadError: WindowsXP does not support soft symlinks
 in symlink at fs.jl:168
 in runtests at J:\julia32\test\testdefs.jl:77
 in anonymous at multi.jl:626
 in run_work_thunk at multi.jl:587
 in remotecall_fetch at multi.jl:675
 in anonymous at task.jl:1390
while loading J:\julia32\test\file.jl, in expression starting on line 17
while loading J:\julia32\test\runtests.jl, in expression starting on line 3

Makefile:9: recipe for target 'all' failed
make[1]: *** [all] Error 1
Makefile:492: recipe for target 'testall1' failed
make: *** [testall1] Error 2

[tkelman]

The Windows runs are on a Sandy Bridge i7-2630QM laptop from 2011. The Linux runs are on an older Penryn Core 2.

I've got the following in my Make.user, will try changing some of this to see if makes a difference:

override LLVM_VER = 3.6.0
override LLVM_ASSERTIONS = 1
override MARCH = i686
override JULIA_CPU_TARGET = pentium4

update: removed the MARCH and JULIA_CPU_TARGET and the results weren't much different. Granted I didn't rebuild LLVM without these flags, I guess I could try that.

[vtjnash]

oops, that explains it -- I had commented out the LLVM_VER in my Make.user file and forgot to put it back

[tkelman]

I do suspect this isn't Windows-specific, the LLVM-svn nightly 32 bit Linux buildbot shows similar awful performance and an OutOfMemoryError - http://buildbot.e.ip.saba.us:8010/builders/build_llvmsvn_nightly-x86/builds/416/steps/make%20testall/logs/stdio

[tkelman]

No change on llvm 3.6.1.

edit: Or 3.7.0.

[Keno]

Unfortunately, even with the memory problems fixed, this problem does not go away, so something else must be going on. The one thing that did not change is the amount of executable memory required, so maybe there's a problem with that memory allocator, rather than total memory allocation?

[Keno]

Indeed it seems like LLVM's memory allocator is blowing through virtual memory (without actually using it). Will see if I can fix that.

[Keno]

[Keno]

What's the linux/osx command for getting the amount of allocated virtual address space? I'd like to print this in the tests as well.

[yuyichao]

You can probably use the VmPeak or VmSize field of /proc/<pid>/status on linux.

[yuyichao]

Or ps -p <pid> -o "%z"

[Keno]

Fix pending as http://reviews.llvm.org/D15202.

[vtjnash]

All pages in the specified region must be within the same reserved region allocated when calling the VirtualAlloc or VirtualAllocEx function using MEM_RESERVE. The pages cannot span adjacent reserved regions that were allocated by separate calls to VirtualAlloc or VirtualAllocEx using MEM_RESERVE.

https://msdn.microsoft.com/en-us/library/windows/desktop/aa366898(v=vs.85).aspx

[Keno]

So you're saying the merging to reduce syscall overhead is invalid?

[vtjnash]

yeah (on windows anyhow, posix doesn't say anything about it)

[Keno]

Ok, thanks, I'll update the patch accordingly.

[tkelman]

Confirmed fixed by llvm-3.7.1_2.patch, when it actually gets applied instead of eaten by a parallel-make race condition. I'm seeing the socket test hang locally (not every time though), but appveyor didn't on #14623 so that's probably a different issue.

[tkelman]

Reopening since #15632 brought this back. Now as

This application has requested the Runtime to terminate it in an unusual way.
Please contact the application's support team for more information.
terminate called after throwing an instance of 'std::bad_alloc'
  what():  std::bad_alloc

[tkelman]

needs retesting with #16777, hopefully fixed but we'll see

[tkelman]

I was briefly hitting a strange inference issue

$ JULIA_CPU_CORES=1 usr/bin/julia --precompiled=no --check-bounds=yes test/runtests.jl linalg
     * linalg/triangular     in 681.27 seconds, maxrss  586.73 MB
     * linalg/qr             in 145.35 seconds, maxrss  639.24 MB
     * linalg/dense          in  57.91 seconds, maxrss  663.07 MB
     * linalg/matmul         in 596.30 seconds, maxrss  706.56 MB
     * linalg/schur          in  11.42 seconds, maxrss  707.79 MB
     * linalg/special        in   3.39 seconds, maxrss  710.85 MB
     * linalg/eigen          in 100.33 seconds, maxrss  727.36 MB
     * linalg/bunchkaufman   in  76.35 seconds, maxrss  729.05 MB
     * linalg/svd            in  30.54 seconds, maxrss  730.35 MB
     * linalg/lapack         in  69.05 seconds, maxrss  746.10 MB
     * linalg/tridiag        in  34.31 seconds, maxrss  761.84 MB
     * linalg/bidiag         in  34.87 seconds, maxrss  773.97 MB
     * linalg/diagonal       in  75.30 seconds, maxrss  821.06 MB
     * linalg/pinv           in   9.09 seconds, maxrss  870.48 MB
     * linalg/givens         in  11.76 seconds, maxrss  870.48 MB
     * linalg/cholesky       in  36.77 seconds, maxrss  870.48 MB
     * linalg/lu            ERROR: LoadError: LoadError: return type Rational{BigInt} does not match inferred return type Any
 in error(::String) at .\error.jl:21
 in include_from_node1(::String) at .\loading.jl:426
 in macro expansion at .\util.jl:179 [inlined]
 in runtests(::String) at C:\cygwin64\home\Tony\julia32\test\testdefs.jl:7
 in (::Base.##299#300{##16#24,Tuple{String},Array{Any,1}})() at .\multi.jl:802
 in run_work_thunk(::Base.##299#300{##16#24,Tuple{String},Array{Any,1}}, ::Bool) at .\multi.jl:775
 in #remotecall_fetch#304(::Array{Any,1}, ::Function, ::Function, ::LocalProcess, ::String, ::Vararg{String,N}) at .\multi.jl:822
 in remotecall_fetch(::Function, ::LocalProcess, ::String, ::Vararg{String,N}) at .\multi.jl:822
 in #remotecall_fetch#306(::Array{Any,1}, ::Function, ::Function, ::Int32, ::String, ::Vararg{String,N}) at .\multi.jl:838
 in remotecall_fetch(::Function, ::Int32, ::String, ::Vararg{Any,N}) at .\multi.jl:838
 in macro expansion at C:\cygwin64\home\Tony\julia32\test\runtests.jl:44 [inlined]
 in (::##15#23{Array{Any,1},UInt32})() at .\task.jl:315
while loading C:\cygwin64\home\Tony\julia32\test\linalg/lu.jl, in expression starting on line 165
 in #remotecall_fetch#304(::Array{Any,1}, ::Function, ::Function, ::LocalProcess, ::String, ::Vararg{String,N}) at .\multi.jl:823
 in remotecall_fetch(::Function, ::LocalProcess, ::String, ::Vararg{String,N}) at .\multi.jl:822
 in #remotecall_fetch#306(::Array{Any,1}, ::Function, ::Function, ::Int32, ::String, ::Vararg{String,N}) at .\multi.jl:838
 in remotecall_fetch(::Function, ::Int32, ::String, ::Vararg{Any,N}) at .\multi.jl:838
 in macro expansion at C:\cygwin64\home\Tony\julia32\test\runtests.jl:44 [inlined]
 in (::##15#23{Array{Any,1},UInt32})() at .\task.jl:315
 in sync_end() at .\task.jl:281
 in macro expansion at .\task.jl:290 [inlined]
 in (::##11#19)() at C:\cygwin64\home\Tony\julia32\test\runtests.jl:37
 in cd(::##11#19, ::String) at .\file.jl:48
 in include_from_node1(::String) at .\loading.jl:426
 in process_options(::Base.JLOptions) at .\client.jl:266
 in _start() at .\client.jl:322
while loading C:\cygwin64\home\Tony\julia32\test\runtests.jl, in expression starting on line 26

but that seems fixed by some commits made within the last day.

make testall1 on win32 does not yet go through, at 7ad5eee

     * bigfloat              in   0.42 seconds, maxrss 2234.46 MB
     * sorting               in  73.68 seconds, maxrss 2234.46 MB
     * statistics
This application has requested the Runtime to terminate it in an unusual way.
Please contact the application's support team for more information.

signal (22): SIGABRT
while loading C:\cygwin64\home\Tony\julia32\test\statistics.jl, in expression starting on line 162
jl_cpu_wake at C:\cygwin64\home\Tony\julia32\usr\bin\libjulia.dll (unknown line)
unknown function (ip: 7615775F)
unknown function (ip: 7615BBDB)
unknown function (ip: 6FE615A7)
unknown function (ip: 6FE58BEF)
unknown function (ip: 6FECF870)
unknown function (ip: 6FE58BF4)
unknown function (ip: 6FEC882F)
unknown function (ip: 6FECF23B)
unknown function (ip: 27BC3FB7)
unknown function (ip: 0485D697)
unknown function (ip: 0485D84F)
unknown function (ip: 0485DBBF)
Allocations: 6585224299 (Pool: 6584913590; Big: 310709); GC: 12650
terminate called after throwing an instance of 'std::bad_alloc'
  what():  std::bad_alloc
make[1]: *** [Makefile:12: all] Error 3
make[1]: Leaving directory '/home/Tony/julia32/test'
make: *** [Makefile:575: testall1] Error 2

[yuyichao]

Does malloc with large size use VirtualAlloc on windows?

[yuyichao]

While testing #16777, I think we are "only" wasting a few hundred MB (~100MB for subarray test) of memory for code, which is usually less than 20-30% of the memory we use (10%-15% for a fresh subarray test run).

I also noticed that the max memory depends on the GC threshold a lot. @carnaval any update from your heap profiling? Any idea what's the partition of the total memory usage? (JIT, llvm malloc, GC aware malloc, GC bigobj, GC pool)?

[tkelman]

this seems to work again. yay.

[tkelman]

happening again

[tkelman]

since #18357 this doesn't happen with make testall1 but it does happen if you do JULIA_CPU_CORES=1 usr/bin/julia -g test/runtests.jl all or JULIA_CPU_CORES=1 usr/bin/julia-debug test/runtests.jl all

[tkelman]

With julia-debug, this worked up until some of the intermediate commits in #15779 at which julia-debug segfaulted on startup
c00785c
65c82ff
9cf506d
1fd7733
32826d4
6cb4c88
Ever since that PR, make testall1 with debug info enabled on win32 has run out of memory.

[KristofferC]

Seems stale, let's reopen if it happens again.

[joyceraraujo]

I got the same error message either with ATOM and VS Code when I try to solve a MILP with Cbc. How can I workaround this problem?
``
A s s e r t i o n f a i l e d !

P r o g r a m : C : \ U s e r s \ j o y c e . r a m o s - a r a u j o \ A p p
D a t a \ L o c a l \ J u l i a - 1 . 3 . 1 \ b i n \ j u l i a . e x e
F i l e : . . / . . / . . / . . / O s i / s r c / O s i / O s i P r e s o l v
e . c p p , L i n e 5 1 4

E x p r e s s i o n : s t a t u s ! = C o i n W a r m S t a r t B a s i s
: : a t U p p e r B o u n d | | o r i g i n a l M o d e l _ - > g e t C o l U p p e r ( ) [ i ] < o r i g i n a l M o d e l _ - > g e t I n f i n i t y (
)

This application has requested the Runtime to terminate it in an unusual way.
Please contact the application's support team for more information.

[Keno]

That is not the same issue. Your error message is an assertion failure inside the silver. I would recommend filing an issue with a reproducible example with the Cbc.jl package.