Weird memleak when logging exception stacktraces

[tchaloupka]

I've found out by accident that many logged exception stackstraces leads to alarmingly large memory leak.

#!/usr/bin/env dub
/+ dub.sdl:
	name "memleak"
	dependency "vibe-d:core" version="~>0.8.4"
	subConfiguration "vibe-d:core" "libevent"
+/

import core.memory;
import std.stdio;
import std.experimental.logger;

import vibe.core.core; // comment this out to behave normally

void main()
{
	foreach (i; 0..1000)
	{
		try throw new Exception("some message");
		catch (Exception ex)
		{
			errorf("Error: %s", ex);
			//errorf("Error: %s", ex.msg);
		}
	}

	info("Done");
	GC.collect();
	GC.minimize();
	readln();
}

If I run this with dmd >= 2.081.0 the process is almost 500MB in memory.
GC.collect() and GC.minimize() doesn't matter.

If run with new vibe-core it's somewhat better at about 400MB in memory.

When just exception message is logged, process is at 6MB - what a difference.
Same when run ie with dmd-2.080.1 or without vibe-d.

As this behavior is visible only with vibe-d I picked it's issues list to report this.
Something changed between dmd-2.080.1 and dmd-2.081.0 which caused this in vibe-d or some conditional compilation in vibe-d is behind this?

Tested on fedora 28 x86_64 with multiple dmd versions and vibe-d-0.8.4.

[tchaloupka]

I've probably bisected the PR behind this using digger with

bad = https://github.com/dlang/phobos/pull/6700
good = https://github.com/dlang/phobos/pull/4941

And the winner is: dlang/druntime#2169
And due to it's change context it seems to be really connected with this.
But I don't have a clue what to do about that as it is somewhat triggered with vibe-d only.

@jacob-carlborg can you please provide some insight?

[tchaloupka]

Also note that when I tried to check the leaks using valgrind it seems to behave normally (memory is much lower) either with memcheck or massif tools.

[tchaloupka]

Also with dmd's profile-gc switch it doesn't seems to lead anywhere:

bytes allocated, allocations, type, function, file:line
          76000	           1000	object.Exception D main app.d:23
          32064	           1002	std.array.Appender!string.Appender.Data std.array.Appender!string.Appender.this /home/tcha/dlang/dmd-2.082.1/linux/bin64/../../src/phobos/std/array.d:2975
          16384	              1	eventcore.internal.consumablequeue.ConsumableQueue!(Tuple!(void function(long) nothrow @safe, long)).ConsumableQueue.Slot[] eventcore.internal.consumablequeue.ConsumableQueue!(Tuple!(void function(long) nothrow @safe, long)).ConsumableQueue.reserve ../../../.dub/packages/eventcore-0.8.36/eventcore/source/eventcore/internal/consumablequeue.d:46
           1200	              1	core.sys.linux.epoll.epoll_event[] eventcore.drivers.posix.epoll.EpollEventLoop.this ../../../.dub/packages/eventcore-0.8.36/eventcore/source/eventcore/drivers/posix/epoll.d:35
            848	              3	char[] std.path.buildPath!(const(char)[][]).buildPath /home/tcha/dlang/dmd-2.082.1/linux/bin64/../../src/phobos/std/path.d:1457
            448	             14	std.array.Appender!(string[]).Appender.Data std.array.Appender!(string[]).Appender.this /home/tcha/dlang/dmd-2.082.1/linux/bin64/../../src/phobos/std/array.d:2975
            392	              7	std.getopt.Option[] std.getopt.getoptImpl!().getoptImpl /home/tcha/dlang/dmd-2.082.1/linux/bin64/../../src/phobos/std/getopt.d:801
            280	              5	std.getopt.Option[] std.getopt.getoptImpl!(string, bool*).getoptImpl /home/tcha/dlang/dmd-2.082.1/linux/bin64/../../src/phobos/std/getopt.d:741
            256	              1	eventcore.internal.consumablequeue.ConsumableQueue!(void delegate(Handle!("event", Handle!("fd", ulong, 18446744073709551615LU), Handle(18446744073709551615LU))) nothrow @safe).ConsumableQueue.Slot[] eventcore.internal.consumablequeue.ConsumableQueue!(void delegate(Handle!("event", Handle!("fd", ulong, 18446744073709551615LU), Handle(18446744073709551615LU))) nothrow @safe).ConsumableQueue.reserve ../../../.dub/packages/eventcore-0.8.36/eventcore/source/eventcore/internal/consumablequeue.d:46
            249	              1	vibe.core.log.FileLogger vibe.core.log.initializeLogModule ../../../.dub/packages/vibe-core-1.4.3/vibe-core/source/vibe/core/log.d:772
            232	              1	eventcore.drivers.threadedfile.ThreadedFileEventDriver!(PosixEventDriverEvents!(EpollEventLoop, PosixEventDriverSockets!(EpollEventLoop))).ThreadedFileEventDriver eventcore.drivers.posix.driver.PosixEventDriver!(EpollEventLoop).PosixEventDriver.this ../../../.dub/packages/eventcore-0.8.36/eventcore/source/eventcore/drivers/posix/driver.d:75
            224	              2	vibe.core.sync.TaskCondition vibe.core.concurrency.VibedScheduler.newCondition ../../../.dub/packages/vibe-core-1.4.3/vibe-core/source/vibe/core/concurrency.d:1257
            200	              5	vibe.core.args.OptionInfo[] vibe.core.args.readOption!bool.readOption ../../../.dub/packages/vibe-core-1.4.3/vibe-core/source/vibe/core/args.d:58
            128	              2	eventcore.internal.consumablequeue.ConsumableQueue!(void delegate(Handle!("event", Handle!("fd", ulong, 18446744073709551615LU), Handle(18446744073709551615LU))) nothrow @safe).ConsumableQueue eventcore.drivers.posix.events.PosixEventDriverEvents!(EpollEventLoop, PosixEventDriverSockets!(EpollEventLoop)).PosixEventDriverEvents.createInternal ../../../.dub/packages/eventcore-0.8.36/eventcore/source/eventcore/drivers/posix/events.d:60
            112	              2	std.getopt.Option[] std.getopt.getoptImpl!(string, string*).getoptImpl /home/tcha/dlang/dmd-2.082.1/linux/bin64/../../src/phobos/std/getopt.d:741

Could't it be caused by some memory fragmentation?

[jacob-carlborg]

can you please provide some insight?

Hmm, that's interesting. I see that you're on Linux but my changes should not have affected Linux. I'll have a look.

[jacob-carlborg]

I had a quick look, I couldn't find anything obvious.

[tchaloupka]

I tried to remove all static this and shared static this from all included packages to eliminate their initialization with hope that import vibe.core.core won't trigger that behavior anymore and I could then selectively turn them back on, but no success there, still triggered by just import.. :(

After this I didn't understand why this should be triggered by vibe-d, so I tried testing more and found that it isn't!
Amount of "leaked" memory is related to the size of included library.

Tried for example with a pretty large

dependency "botan" version="~>1.12.10"

And went from 100MB with just eventcore to 1000MB.
LDC behaves the same.

But I should mention that it's ok in release.

So I guess that this should go to dmd issues after all...

[tchaloupka]

Moved it here: https://issues.dlang.org/show_bug.cgi?id=19322