Jump to page: 1 2 3
Thread overview
High memory usage in vibe.d application
Jun 29, 2018
Anton Fediushin
Jun 29, 2018
Anton Fediushin
Jun 29, 2018
Radu
Jun 29, 2018
bauss
Jun 29, 2018
Anton Fediushin
Jun 29, 2018
rikki cattermole
Jun 29, 2018
Anton Fediushin
Jun 29, 2018
12345swordy
Jun 29, 2018
Anton Fediushin
Jun 29, 2018
Bauss
Jun 29, 2018
Anton Fediushin
Jun 30, 2018
Jacob Shtokolov
Jul 01, 2018
Anton Fediushin
Jul 01, 2018
Jacob Shtokolov
Jul 01, 2018
Anton Fediushin
Jul 01, 2018
crimaniak
Jul 01, 2018
Anton Fediushin
Jun 30, 2018
rikki cattermole
Jun 30, 2018
Anton Fediushin
Jun 30, 2018
rikki cattermole
Jun 29, 2018
Anton Fediushin
Jun 29, 2018
Anton Fediushin
Jun 29, 2018
bauss
Jun 29, 2018
Anton Fediushin
Jun 29, 2018
Daniel Kozak
Jun 29, 2018
Anton Fediushin
June 29, 2018
Hello, I'm looking for an advice on what I am doing wrong.

I have a vibe.d-based program, which connects to an audio stream and gets name of the song currently playing. For that, I wrote the following code:

```
@safe string nowPlaying(string url) {
	import vibe.core.stream;
	string r;
	url.requestHTTP(
		(scope req) {
			req.headers.addField("Icy-MetaData", "1");
		},
		(scope res) {
			auto metaint = res.headers.get("icy-metaint").to!int;
			auto buffer = new ubyte[metaint];
			res.bodyReader.read(buffer, IOMode.all);
			
			auto lengthBuff = new ubyte[1];
			res.bodyReader.read(lengthBuff, IOMode.all);

			auto dataBuffer = new ubyte[lengthBuff[0] * 16];
			res.bodyReader.read(dataBuffer, IOMode.all);
			r = dataBuffer.map!(a => a.to!char).split('\'').drop(1).front.array.idup;
		}
	);
	return r;
}
```

And I call it with a timer every 10 seconds:

```
string now_playing;
10.seconds.setTimer(() {
	now_playing = nowPlaying(stream);
}, true);
```

This code worked fine for 8 or so hours and then got killed by docker because of a limit of 64MB of RAM. I executed the same code on my machine and saw resident set size growing in real-time. Blaming GC (as people usually do) I changed the code to use std.experimental.allocator instead:

```
@safe string nowPlaying(string url) {
	import vibe.core.stream;
	import std.experimental.allocator;
	string r;
	url.requestHTTP(
		(scope req) {
			req.headers.addField("Icy-MetaData", "1");
		},
		(scope res) {
			auto metaint = res.headers.get("icy-metaint").to!int;
			auto buffer = theAllocator.makeArray!ubyte(metaint);
			scope(exit) theAllocator.dispose(buffer);
			res.bodyReader.read(buffer, IOMode.all);
			
			auto lengthBuffer = theAllocator.makeArray!ubyte(1);
			scope(exit) theAllocator.dispose(lengthBuffer);
			res.bodyReader.read(lengthBuffer, IOMode.all);

			auto dataBuffer = theAllocator.makeArray!ubyte(lengthBuffer[0] * 16);
			scope(exit) theAllocator.dispose(dataBuffer);
			res.bodyReader.read(dataBuffer, IOMode.all);

			r = dataBuffer.map!(a => a.to!char).split('\'').drop(1).front.array.idup;
		}
	);
	return r;
}
```

And somehow, it got *worse*. Now my program gets killed every 3 hours. How is that possible? Am I missing something?

Some screenshots of CPU/Memory usage:
1. These are metrics of a whole cluster, program is started at around 8:00 and gets killed after 16:00 https://imgur.com/a/IhHvOt4
2. These are metrics of an updated program which uses std.experimental.allocator. https://imgur.com/a/XBchJ7C

June 29, 2018
Almost forgot, there are two timers which call this function for two different streams.

Value of `metaint` is 16000, which means that only 16KB of memory are allocated for the `buffer`, then it reads another byte which contains length of the metadata / 16 and then it reads the metadata which is 100-200 bytes long.

This gives us... 16KiB per one nowPlaying() call. Why doesn't it free the memory?
June 29, 2018
On Friday, 29 June 2018 at 09:44:27 UTC, Anton Fediushin wrote:
> Almost forgot, there are two timers which call this function for two different streams.
>
> Value of `metaint` is 16000, which means that only 16KB of memory are allocated for the `buffer`, then it reads another byte which contains length of the metadata / 16 and then it reads the metadata which is 100-200 bytes long.
>
> This gives us... 16KiB per one nowPlaying() call. Why doesn't it free the memory?

Maybe use the https://dlang.org/phobos/std_experimental_allocator_mallocator.html instead of theAllocator as it defaults to GC.

Also, why you .idup the array? .array already creates a new one on the heap.
June 29, 2018
On Friday, 29 June 2018 at 10:21:24 UTC, Radu wrote:
> On Friday, 29 June 2018 at 09:44:27 UTC, Anton Fediushin wrote:
>> Almost forgot, there are two timers which call this function for two different streams.
>>
>> Value of `metaint` is 16000, which means that only 16KB of memory are allocated for the `buffer`, then it reads another byte which contains length of the metadata / 16 and then it reads the metadata which is 100-200 bytes long.
>>
>> This gives us... 16KiB per one nowPlaying() call. Why doesn't it free the memory?
>
> Maybe use the https://dlang.org/phobos/std_experimental_allocator_mallocator.html instead of theAllocator as it defaults to GC.
>
> Also, why you .idup the array? .array already creates a new one on the heap.

This.

Which kind of makes the usage of theAllocator useless.

I was going to suggest using @nogc too, because it would most likely be GC allocated memory that is taking up space.

I run multiple vibe.d applications and I have no issues with memory (Even with GC.)
June 29, 2018
On Friday, 29 June 2018 at 10:21:24 UTC, Radu wrote:
> On Friday, 29 June 2018 at 09:44:27 UTC, Anton Fediushin wrote:
>> Almost forgot, there are two timers which call this function for two different streams.
>>
>> Value of `metaint` is 16000, which means that only 16KB of memory are allocated for the `buffer`, then it reads another byte which contains length of the metadata / 16 and then it reads the metadata which is 100-200 bytes long.
>>
>> This gives us... 16KiB per one nowPlaying() call. Why doesn't it free the memory?
>
> Maybe use the https://dlang.org/phobos/std_experimental_allocator_mallocator.html instead of theAllocator as it defaults to GC.

Thanks, I'll try that.

>
> Also, why you .idup the array? .array already creates a new one on the heap.

It does, but it creates char[] and I need a string. I changed code a little bit to remove unnecessary `map` and `idup` too.

Code now:

```
@safe string nowPlaying(string url) {
	import vibe.core.stream;
	import std.experimental.allocator;
	import std.experimental.allocator.mallocator;
	import std.string;

	string r;
	url.requestHTTP(
		(scope req) {
			req.headers.addField("Icy-MetaData", "1");
		},
		(scope res) {
			RCIAllocator a = allocatorObject(Mallocator.instance);

			auto metaint = res.headers.get("icy-metaint").to!int;
			auto buffer = a.makeArray!ubyte(metaint);
			scope(exit) a.dispose(buffer);
			res.bodyReader.read(buffer, IOMode.all);

			auto lengthBuffer = a.makeArray!ubyte(1);
			scope(exit) a.dispose(lengthBuffer);
			res.bodyReader.read(lengthBuffer, IOMode.all);

			auto dataBuffer = a.makeArray!ubyte(lengthBuffer[0] * 16);
			scope(exit) a.dispose(dataBuffer);
			res.bodyReader.read(dataBuffer, IOMode.all);

			r = dataBuffer.split('\'').drop(1).front.array.assumeUTF;

			res.disconnect;
		}
	);
	return r;
}
```

I will deploy that and see if it changes anything.

June 29, 2018
On Friday, 29 June 2018 at 10:31:14 UTC, bauss wrote:
> On Friday, 29 June 2018 at 10:21:24 UTC, Radu wrote:
>> On Friday, 29 June 2018 at 09:44:27 UTC, Anton Fediushin wrote:
>>> Almost forgot, there are two timers which call this function for two different streams.
>>>
>>> Value of `metaint` is 16000, which means that only 16KB of memory are allocated for the `buffer`, then it reads another byte which contains length of the metadata / 16 and then it reads the metadata which is 100-200 bytes long.
>>>
>>> This gives us... 16KiB per one nowPlaying() call. Why doesn't it free the memory?
>>
>> Maybe use the https://dlang.org/phobos/std_experimental_allocator_mallocator.html instead of theAllocator as it defaults to GC.
>>
>> Also, why you .idup the array? .array already creates a new one on the heap.
>
> This.
>
> Which kind of makes the usage of theAllocator useless.

Indeed, because it uses GC by default my `theAllocator.dispose` did nothing, which basically made these two samples of code equal.

>
> I was going to suggest using @nogc too, because it would most likely be GC allocated memory that is taking up space.

It is GC's fault for sure, I built my program with profile-gc and it allocated a lot there. Question is, why doesn't it free this memory?

>
> I run multiple vibe.d applications and I have no issues with memory (Even with GC.)

Me neither, my other vibe.d project uses 7.5MB and that's it.


June 29, 2018
On 29/06/2018 11:09 PM, Anton Fediushin wrote:
> It is GC's fault for sure, I built my program with profile-gc and it allocated a lot there. Question is, why doesn't it free this memory?

Probably doesn't know that it should deallocate so eagerly.
A GC.collect(); call may help.
June 29, 2018
On Friday, 29 June 2018 at 11:01:41 UTC, Anton Fediushin wrote:
> On Friday, 29 June 2018 at 10:21:24 UTC, Radu wrote:
>> On Friday, 29 June 2018 at 09:44:27 UTC, Anton Fediushin wrote:
>>> Almost forgot, there are two timers which call this function for two different streams.
>>>
>>> Value of `metaint` is 16000, which means that only 16KB of memory are allocated for the `buffer`, then it reads another byte which contains length of the metadata / 16 and then it reads the metadata which is 100-200 bytes long.
>>>
>>> This gives us... 16KiB per one nowPlaying() call. Why doesn't it free the memory?
>>
>> Maybe use the https://dlang.org/phobos/std_experimental_allocator_mallocator.html instead of theAllocator as it defaults to GC.
>
> Thanks, I'll try that.
> ...
> I will deploy that and see if it changes anything.

It did! Memory usage went down to 7MiB yet it still grows slightly. I'll monitor if it changes in a couple of hours but it is much better.

Thank you a lot, Radu. It turns out that theAllocator is so tricky.
June 29, 2018
On Friday, 29 June 2018 at 11:24:14 UTC, Anton Fediushin wrote:
> On Friday, 29 June 2018 at 11:01:41 UTC, Anton Fediushin wrote:
>> On Friday, 29 June 2018 at 10:21:24 UTC, Radu wrote:
>>> On Friday, 29 June 2018 at 09:44:27 UTC, Anton Fediushin wrote:
>>>> Almost forgot, there are two timers which call this function for two different streams.
>>>>
>>>> Value of `metaint` is 16000, which means that only 16KB of memory are allocated for the `buffer`, then it reads another byte which contains length of the metadata / 16 and then it reads the metadata which is 100-200 bytes long.
>>>>
>>>> This gives us... 16KiB per one nowPlaying() call. Why doesn't it free the memory?
>>>
>>> Maybe use the https://dlang.org/phobos/std_experimental_allocator_mallocator.html instead of theAllocator as it defaults to GC.
>>
>> Thanks, I'll try that.
>> ...
>> I will deploy that and see if it changes anything.
>
> It did! Memory usage went down to 7MiB yet it still grows slightly. I'll monitor if it changes in a couple of hours but it is much better.
>
> Thank you a lot, Radu. It turns out that theAllocator is so tricky.

Again you could do @nogc and see what memory is possibly allocated by the GC and perhaps that way you can see what memory the GC is holding on to.

non-GC memory should be freed right away and those there shouldn't be a leak from that.
June 29, 2018
On Friday, 29 June 2018 at 11:42:18 UTC, bauss wrote:
> On Friday, 29 June 2018 at 11:24:14 UTC, Anton Fediushin wrote:
>> On Friday, 29 June 2018 at 11:01:41 UTC, Anton Fediushin wrote:
>>> On Friday, 29 June 2018 at 10:21:24 UTC, Radu wrote:
>>>> On Friday, 29 June 2018 at 09:44:27 UTC, Anton Fediushin wrote:
>>>>> Almost forgot, there are two timers which call this function for two different streams.
>>>>>
>>>>> Value of `metaint` is 16000, which means that only 16KB of memory are allocated for the `buffer`, then it reads another byte which contains length of the metadata / 16 and then it reads the metadata which is 100-200 bytes long.
>>>>>
>>>>> This gives us... 16KiB per one nowPlaying() call. Why doesn't it free the memory?
>>>>
>>>> Maybe use the https://dlang.org/phobos/std_experimental_allocator_mallocator.html instead of theAllocator as it defaults to GC.
>>>
>>> Thanks, I'll try that.
>>> ...
>>> I will deploy that and see if it changes anything.
>>
>> It did! Memory usage went down to 7MiB yet it still grows slightly. I'll monitor if it changes in a couple of hours but it is much better.
>>
>> Thank you a lot, Radu. It turns out that theAllocator is so tricky.
>
> Again you could do @nogc and see what memory is possibly allocated by the GC and perhaps that way you can see what memory the GC is holding on to.

@nogc tells nothing new, just an error on every single line because neither `res.bodyReader.read` nor Mallocator's functions are marked as @nogc.

Compiling with dmd's `-vgc` flag shows nothing but the last line.

>
> non-GC memory should be freed right away and those there shouldn't be a leak from that.

Using Mallocator instead of theAllocator improved the situation, but it still leaks for some reason. After 2 hours it went from 7MiB to 18MiB.

I will compile it with profile-gc again and look for the possible cause of that, maybe I'll try valgrind too.


« First   ‹ Prev
1 2 3