readall(echo hello) leaks memory on master and 0.3

[StefanKarpinski]

The following program leaks memory on 0.3 and 0.4 to varying degrees:

while true
    readall(`echo hello`)
    gc() # <= with or without this
end

On 0.3 without the gc() call is the worst – memory usage grows to 1.2 GB on my machine in a couple of minutes. If you put the gc() call in then it's much better – indicating that the memory pressure isn't being felt as it should – but there's still a gradual leak. On 0.4 things are better – and memory pressure is felt as it should be even without gc() – but there is still a slow leak.

[yuyichao]

Could this be related to #9767?

I would be quite surprized if the GC doesn't free the memory it owns.

[JeffBezanson]

We malloc libuv handles, which are very very small but with lots of them it might matter?

[vtjnash]

what OS have you tested this on?

[yuyichao]

On 0.4 Linux running

for i in 1:1000000
       readall(`echo hello`)
       i % 1000 == 0 && println(i)
end

I could see a linear memory usage increase of the julia process (measured with resident size with no swap) ~ 220 bytes per iteration.

[StefanKarpinski]

Also on OS X.

[vtjnash]

after running this for 75000 loops, then canceling with ^C, the most interesting thing I seemed to get was:

julia> ^D
Assertion failed: (uv__stream_fd(stream) >= 0), function uv_shutdown, file src/unix/stream.c, line 1166.

signal (6): Abort trap: 6
__pthread_kill at /usr/lib/system/libsystem_kernel.dylib (unknown line)
Abort trap: 6
/home/me$ 

for reference, on OS X, the size of the malloc objects is:

julia> Int(Base._sizeof_uv_process)
104

julia> Int(Base._sizeof_uv_named_pipe)
240

after 10-20 minutes of running the test on 0.4 OS X, my machine exhibits behavior on the order of yuyichao's results (200-600 bytes/loop) after accomplishing ~50_000 loops. but that's only a net change of 30 MB and is not approaching nowhere near 1.2 GB.

[yuyichao]

A much faster way to get the memory leak is

function f(n)
    for i in 1:n
        fd = open("a")
        readall(fd)
        close(fd)
        i % 1000 == 0 && println(i)
    end
end

Edit: where "a" is an empty file.

[yuyichao]

After all this might still be GC related.

julia> function f1(n)
       for i in 1:n
       fd = open("a")
       close(fd)
       i % 1000 == 0 && println(i)
       end
       end
f1 (generic function with 1 method)

julia> function f2(n)
       for i in 1:n
       fd = open("a")
       close(fd)
       finalize(fd)
       i % 1000 == 0 && println(i)
       end
       end
f2 (generic function with 1 method)

f1 "leaks" memory while f2 doesn't.

[StefanKarpinski]

@vtjnash, note that the 1.2 GB is on release-0.3. On master, Julia feels the memory pressure as it should so the leak is relatively slow (but still present).

[hayd]

I think this was closed unintentionally, @yuyichao's comment said this "does not fix #11814". Github just saw the last two words.

[yuyichao]

@hayd You are totally right... Thanks for catching this....

The worse part is that I don't even get a notification for accidentally doing that since it's my own action.....

[yuyichao]

The memory leak I saw (which is very likely the one @StefanKarpinski saw but I cannot say for sure) appears to be not IO related.

It is reproducible with the following script. The problem goes away if no finalizer is installed or finalizer is manually run. The size of the leak changes if the size of the array changes so I think the array is somehow not free'd. The issue also goes away if I call gc() during every println.

close2(s) = nothing

function f1(n)
    for i in 1:n
        s = zeros(UInt8, 152)
        finalizer(s, close2)
        # finalize(s)
        i % 10000 == 0 && println(i)
    end
end

f1(6000_000)

sleep(3)

@carnaval When I looked at gc.c, the biggest difference I've noticed between manually and automatically run finalizer is that the gc schedule the finalizer in a to_finalize list, which makes them escape the (next?) marking.

Would this cause them to be promoted to the old gen and takes much longer to be free'd? (Although even then the memory pressure should probably trigger a full collection?)
Can the to_finalize list be flush right after the GC or should there be some marking trick to make sure the finalized objects can be free'd as soon as they are finalized?

P.S. if the script remind you about iostream.jl that's not a coincident. =)

[yuyichao]

I should mention that the size of the three finalizer arrays are reasonable although some of them has a pretty big max. This (and the fact that they can be free'd with a full GC) is why I suspect that to_finalize is messing up with the generational stuff.

(gdb) p finalizer_list
$1 = {len = 2, max = 30720, items = 0x1250910, _space = {0x7ffdf4c619f0, 
    0x7ffdf3cd24f0, 0x7ffdf4c61bd0, 0x7ffdf3cd24f0, 0x7ffdf4c61c30, 
    0x7ffdf3cd24f0, 0x7ffdf45ebb90, 0x7ffdf49c98f0, 0x7ffdf45ebc70, 
    0x7ffdf49c98f0, 0x7ffdf45ebd50, 0x7ffdf49c98f0, 0x7ffdf45ebe30, 
    0x7ffdf49c98f0, 0x7ffdf45ebf10, 0x7ffdf49c98f0, 0x7ffdf4d08010, 
    0x7ffdf49c98f0, 0x7ffdf4d080f0, 0x7ffdf49c98f0, 0x7ffdf4d081d0, 
    0x7ffdf49c98f0, 0x7ffdf4d082b0, 0x7ffdf49c98f0, 0x7ffdf4d08390, 
    0x7ffdf49c98f0, 0x7ffdf4d08470, 0x7ffdf49c98f0, 0x7ffdf4d08550}}
(gdb) p finalizer_list_marked 
$2 = {len = 6, max = 8, items = 0x1089460, _space = {0x0 <repeats 29 times>}}
(gdb) p to_finalize 
$3 = {len = 11554, max = 30720, items = 0x128c920, _space = {0x7ffdf45ebb90, 
    0x7ffdf49c98f0, 0x7ffdf45ebc70, 0x7ffdf49c98f0, 0x7ffdf4f438f0, 
    0x7ffdf49c98f0, 0x7ffdf4f43810, 0x7ffdf49c98f0, 0x7ffdf4f43730, 
    0x7ffdf49c98f0, 0x7ffdf4f43650, 0x7ffdf49c98f0, 0x7ffdf4f43570, 
    0x7ffdf49c98f0, 0x7ffdf4f43490, 0x7ffdf49c98f0, 0x7ffdf4f433b0, 
    0x7ffdf49c98f0, 0x7ffdf4f432d0, 0x7ffdf49c98f0, 0x7ffdf4f431f0, 
    0x7ffdf49c98f0, 0x7ffdf4f43110, 0x7ffdf49c98f0, 0x7ffdf4f43030, 
    0x7ffdf49c98f0, 0x7ffdf4f42f50, 0x7ffdf49c98f0, 0x7ffdf4f42e70}}

Edit: The GDB session above was captrued when it has run ~3000_000 iterations.

[ScottPJones]

Isn't println() I/O related?

[yuyichao]

@carnaval And I think it is generational related. The leak disappears when I disable generational collection with #11358. (Second issue helped by #11358 =) ...)

[StefanKarpinski]

There may be two leaks in that case since there was no generation GC on 0.3.

[yuyichao]

In another word, the issue I see cannot possibly be the issue that affects 0.3 ....

Edit: @StefanKarpinski Your comment pops up right when I type Ctrl-Enter to submit mine....

[yuyichao]

Disabling generational GC makes @StefanKarpinski original example worse although it's hard to tell anything from that since the GC might just be not as good as freeing memory in general when generational stuff is disabled.

[yuyichao]

@StefanKarpinski Can you check if you can still reproduce this? My minimum example above is currently still leaking (fixed by #13993) but I couldn't reproduce the leak with your code anymore. (I'm printing Sys.maxrss() every 1000 iterations and the number is a constant for a million iterations).

[StefanKarpinski]

Yes, this seems to be solved.