Re: [rsyslog] Out of memory

[David Lang]

On Thu, 19 Jan 2017, mostolog--- via rsyslog wrote:


Really interesting and instructive. Let me see if I understood properly:

Considering the below explanation, an idle (not going to receive more 
messages the next 7 days) imrelp rsyslog...shouldn't memory be freed 
from current 512MB usage in the near future?


remember that in your case, this is not the cause of the memory usage, you have 
a memory leak where the memory remains allocated.


normally this is a small amount of memory (and since the memory isn't used by by 
rsyslog, it can be paged out at no cost to the system)


David Lang

You mentioned forcing each 100.000 messages, but that's never gonna 
happen if we are still at 20k, and no more messages coming.


Regards


El 19/01/17 a las 11:16, Rainer Gerhards escribió:
2017-01-19 10:19 GMT+01:00 mostolog--- via rsyslog 
>:


with very few exceptions, rsyslog releases the memory as it
goes, there should not be any significant amount of memory
freed by rsyslog after it's been idle for a while.

But being idle for 15m should release memory from 512MB to a few
KB if they aren't used, isnt it?


Memory alloc is not as simple as it seems ;-)

First, clib does not always do a proper cleanup. I guess it seems not 
to consolidate free space in all cases. There is a clib call to force 
this, and rsyslog does it from time to time (I think every 100,000 
messages). We do not do it very frequently, because it is an expensive 
operation. Also note that memory is reusable internally, so even 
though it is not returned to the OS, further alloc requests inside 
rsyslog can use this memory and do so. Returning memory to the OS and 
re-claiming it is expensive. Thus you do want to keep some memory 
allocated but internally unused to avoid doing this operation too 
frequently.


Secondly, memory alloc from the OS is done by sbrk[1] IIRC. The 
important point is that we need to alloc and free memory in sequence. 
This means if you alloc 100MB, than alloc 1MB, you have the following 
memory layout


BASE
100MB
1MB

with the break at BASE+101MB. If you now free the 100MB chunk, you 
have this layout:


BASE
100MB free
1MB

if you want to return to the OS, you'd need to copy down the 1MB to 
immediatly after BASE, because otherwise you cannot reset the break to 
BASE+1MB. The allocator does not do this, it would totally wrek 
performance (note: that is not rsyslog specific, that is how the *C 
runtime* works). More importantly, it would mean all pointers to it 
would need to be updated. And the runtime does not know where these 
pointers are located. So it would not only costly, compaction is 
simply impossible. Let's assume we now alloc another 10 MB. Then we have


BASE
10MB
90MB free
1MB

because the allocator uses the free, but still allocated mem. Now, 
let's assume we free the 1MB chunk, we get:


BASE
10MB
91MB free

Now the free space is at the end of the data segment. So the alloc 
subsystem has the choice to reduce memory alloc from the OS. It may or 
may not dealloc. I don't know the exact rules, but the important thing 
is that the alloc system uses some heuristic (plus the call I 
mentioned) to decide if to dealloc. Let's assume it does. Then it 
reduceds the data segement size and we get to


BASE
10MB

effectively reducing rss by 91 MB.

IMHO the alloc system strongly works on the assumption that memory 
allocated (from the OS) but free internally does not really hurt, as 
it is just virtual address space, which, if actually unused, is paged 
out to disk once and then doesn't matter at all until it get's reused 
again.


OF COURSE if we have constantly growing memory, the app seems not to 
free some chunks, so the alloc system doesn't know they are free. This 
has nothing to do with what I explained. What I explained just means 
that an app may do proper free()'s, but the rss size doesn't reflect 
this. The typical (and often visible) effect of that is that the app 
grows to a certain size and then remains at it (no growth, no 
decrease). This is where, via the clib call, we force free.


There is one important point, though: if we have a memory block at the 
far end of the data segment, we cannot return mem to the OS until this 
block has been freed. In rsyslog, you typical see this if


a) old-style "last message repeated n times" is active
b) an infrequently written-to output stores a message object when 
queues are very full

c) no different messages are written to that output for a long time

What here is very probably that in b) a high memory address is used 
for that memory block. As due to c) we do not have any traffic, that 
high address is kept in use for hours, maybe days. Once a different 
message arrives at the output, the old object is processed and freed. 
This can result in a very sharp decrease of rss size, especially if 
the system has low load during such times. Let's assume this layout:

Re: [rsyslog] Out of memory

[Rainer Gerhards]

2017-01-23 15:30 GMT+01:00 Rainer Gerhards :

> 2017-01-23 15:26 GMT+01:00 mostolog--- via rsyslog <
> rsyslog@lists.adiscon.com>:
>
>>
>> Considering the below explanation, an idle (not going to receive
>>> more messages the next 7 days) imrelp rsyslog...shouldn't memory
>>> be freed from current 512MB usage in the near future?
>>>
>>>
>>> For the scenario I have described: no, as long as the high address
>>> memory block is allocated, nothing is freed. Not even after 70 days of
>>> idleness ;-)
>>>
>>>
>>> You mentioned forcing each 100.000 messages, but that's never
>>> gonna happen if we are still at 20k, and no more messages coming.
>>>
>>>
>>> right
>>>
>> Isn't that an undesired behavior?
>> A process should release unused/unneeded memory, shouldn't it? (Maybe not
>> "immediately", but sooner than "ever"!)
>>
>>
> That's a question you need to ask the GNU libc developers, if you really
> care for it. As I wrote, I just call a helper function, which in theory
> should never be needed to be called. So rsyslog is already doing more than
> what it is supposed to do. Plus, this example is totally theoretical. We
> use that function call since around 8 years, and never had a problem
> (remember that your case is an actual memory leak!). We very very very
> occasionally had problems in the years before we called the helper.
>

... and even if the helper would have been called in that scenario, nothing
would change. If high mem is still alloced (and it is of course if no new
processing happens), you cannot reduce the sbrk().

Rainer
___
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of 
sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE 
THAT.

Re: [rsyslog] Out of memory

[Rainer Gerhards]

2017-01-23 15:26 GMT+01:00 mostolog--- via rsyslog <
rsyslog@lists.adiscon.com>:

>
> Considering the below explanation, an idle (not going to receive
>> more messages the next 7 days) imrelp rsyslog...shouldn't memory
>> be freed from current 512MB usage in the near future?
>>
>>
>> For the scenario I have described: no, as long as the high address memory
>> block is allocated, nothing is freed. Not even after 70 days of idleness ;-)
>>
>>
>> You mentioned forcing each 100.000 messages, but that's never
>> gonna happen if we are still at 20k, and no more messages coming.
>>
>>
>> right
>>
> Isn't that an undesired behavior?
> A process should release unused/unneeded memory, shouldn't it? (Maybe not
> "immediately", but sooner than "ever"!)
>
>
That's a question you need to ask the GNU libc developers, if you really
care for it. As I wrote, I just call a helper function, which in theory
should never be needed to be called. So rsyslog is already doing more than
what it is supposed to do. Plus, this example is totally theoretical. We
use that function call since around 8 years, and never had a problem
(remember that your case is an actual memory leak!). We very very very
occasionally had problems in the years before we called the helper.

Rainer
___
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of 
sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE 
THAT.

Re: [rsyslog] Out of memory

[mostolog--- via rsyslog]

Considering the below explanation, an idle (not going to receive
more messages the next 7 days) imrelp rsyslog...shouldn't memory
be freed from current 512MB usage in the near future?


For the scenario I have described: no, as long as the high address 
memory block is allocated, nothing is freed. Not even after 70 days of 
idleness ;-)



You mentioned forcing each 100.000 messages, but that's never
gonna happen if we are still at 20k, and no more messages coming.


right

Isn't that an undesired behavior?
A process should release unused/unneeded memory, shouldn't it? (Maybe 
not "immediately", but sooner than "ever"!)


___
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of 
sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE 
THAT.

Re: [rsyslog] Out of memory

[Rainer Gerhards]

forgotten reply for this one:

2017-01-19 18:28 GMT+01:00 mostolog--- via rsyslog <
rsyslog@lists.adiscon.com>:

> Really interesting and instructive. Let me see if I understood properly:
>
> Considering the below explanation, an idle (not going to receive more
> messages the next 7 days) imrelp rsyslog...shouldn't memory be freed from
> current 512MB usage in the near future?
>

For the scenario I have described: no, as long as the high address memory
block is allocated, nothing is freed. Not even after 70 days of idleness ;-)


>
> You mentioned forcing each 100.000 messages, but that's never gonna happen
> if we are still at 20k, and no more messages coming.
>

right

Rainer

>
> Regards
>
>
> El 19/01/17 a las 11:16, Rainer Gerhards escribió:
>
>> 2017-01-19 10:19 GMT+01:00 mostolog--- via rsyslog <
>> rsyslog@lists.adiscon.com >:
>>
>>
>> with very few exceptions, rsyslog releases the memory as it
>> goes, there should not be any significant amount of memory
>> freed by rsyslog after it's been idle for a while.
>>
>> But being idle for 15m should release memory from 512MB to a few
>> KB if they aren't used, isnt it?
>>
>>
>> Memory alloc is not as simple as it seems ;-)
>>
>> First, clib does not always do a proper cleanup. I guess it seems not to
>> consolidate free space in all cases. There is a clib call to force this,
>> and rsyslog does it from time to time (I think every 100,000 messages). We
>> do not do it very frequently, because it is an expensive operation. Also
>> note that memory is reusable internally, so even though it is not returned
>> to the OS, further alloc requests inside rsyslog can use this memory and do
>> so. Returning memory to the OS and re-claiming it is expensive. Thus you do
>> want to keep some memory allocated but internally unused to avoid doing
>> this operation too frequently.
>>
>> Secondly, memory alloc from the OS is done by sbrk[1] IIRC. The important
>> point is that we need to alloc and free memory in sequence. This means if
>> you alloc 100MB, than alloc 1MB, you have the following memory layout
>>
>> BASE
>> 100MB
>> 1MB
>>
>> with the break at BASE+101MB. If you now free the 100MB chunk, you have
>> this layout:
>>
>> BASE
>> 100MB free
>> 1MB
>>
>> if you want to return to the OS, you'd need to copy down the 1MB to
>> immediatly after BASE, because otherwise you cannot reset the break to
>> BASE+1MB. The allocator does not do this, it would totally wrek performance
>> (note: that is not rsyslog specific, that is how the *C runtime* works).
>> More importantly, it would mean all pointers to it would need to be
>> updated. And the runtime does not know where these pointers are located. So
>> it would not only costly, compaction is simply impossible. Let's assume we
>> now alloc another 10 MB. Then we have
>>
>> BASE
>> 10MB
>> 90MB free
>> 1MB
>>
>> because the allocator uses the free, but still allocated mem. Now, let's
>> assume we free the 1MB chunk, we get:
>>
>> BASE
>> 10MB
>> 91MB free
>>
>> Now the free space is at the end of the data segment. So the alloc
>> subsystem has the choice to reduce memory alloc from the OS. It may or may
>> not dealloc. I don't know the exact rules, but the important thing is that
>> the alloc system uses some heuristic (plus the call I mentioned) to decide
>> if to dealloc. Let's assume it does. Then it reduceds the data segement
>> size and we get to
>>
>> BASE
>> 10MB
>>
>> effectively reducing rss by 91 MB.
>>
>> IMHO the alloc system strongly works on the assumption that memory
>> allocated (from the OS) but free internally does not really hurt, as it is
>> just virtual address space, which, if actually unused, is paged out to disk
>> once and then doesn't matter at all until it get's reused again.
>>
>> OF COURSE if we have constantly growing memory, the app seems not to free
>> some chunks, so the alloc system doesn't know they are free. This has
>> nothing to do with what I explained. What I explained just means that an
>> app may do proper free()'s, but the rss size doesn't reflect this. The
>> typical (and often visible) effect of that is that the app grows to a
>> certain size and then remains at it (no growth, no decrease). This is
>> where, via the clib call, we force free.
>>
>> There is one important point, though: if we have a memory block at the
>> far end of the data segment, we cannot return mem to the OS until this
>> block has been freed. In rsyslog, you typical see this if
>>
>> a) old-style "last message repeated n times" is active
>> b) an infrequently written-to output stores a message object when queues
>> are very full
>> c) no different messages are written to that output for a long time
>>
>> What here is very probably that in b) a high memory address is used for
>> that memory block. As due to c) we do not have any traffic, that high
>> address is kept in use for hours, maybe days. Once a different message
>> arrives at the 

Re: [rsyslog] Out of memory

[Rainer Gerhards]

The valgrind log clearly shows a first class memory leak. Could you open a
github issue (if not already existing) and also link the valgrind report
there. I'll see that I can get to it asap, but not sure if I manage this
week.

If you could simplify your config but keep the problem, that would be great.

Rainer

2017-01-19 18:40 GMT+01:00 mostolog--- via rsyslog <
rsyslog@lists.adiscon.com>:

> Attached stats and valgrind logs. Let me know if I can do anything else.
>
> rsyslog was built with a few modules, debug and rtinst.
>
> Run:
>
>valgrind --tool=memcheck --log-file=/data/valgrind.log
>--show-possibly-lost=yes --track-origins=yes --trace-children=yes
>--leak-check=full --show-leak-kinds=all rsyslogd -n
>
> Receiving 100m/s for a few minutes
>
> With the following config:
>
>module(load="builtin:omfile")
>module(load="imrelp")
>module(load="impstats" log.file="/data/stats.log" interval="65")
>global(
>MaxMessageSize="32k"
>workDirectory="/data"
>parser.escapeControlCharactersOnReceive="off"
>)
>input(
> port="20514"
> type="imrelp"
> name="imrelp"
> ruleset="relp"
>)
>template(name="json" type="string" string="%$!%\n")
>template(name="index" type="string" string="%$.index%@%$.interval%")
>template(name="type" type="string" string="%$.type%")
>template(name="ts" type="string" string="%timestamp:::date-rfc3339%")
>ruleset(
> name="relp"
>queue.filename="relp"
>queue.maxdiskspace="1G"
>queue.SaveOnShutdown="on"
>#queue.lowwatermark
>#queue.highwatermark
>#queue.size
>queue.type="LinkedList"
> ) {
> set $.index="unknown";
> set $.type="unknown";
>set $.interval=$$now & ":" & $$hour;
> set $!host_forwarded=$hostname;
> set $!host_received=$$myhostname;
> set $!time_received=$timegenerated;
> set $@timestamp=exec_template("ts");
> #action(
> # name="elastic"
> # action.resumeRetryCount="-1"
> # action.reportsuspension="on"
> # type="omelasticsearch"
> # server="server"
> # serverport="9200"
> # searchIndex="index"
> # dynSearchIndex="on"
> # searchType="type"
> # dynSearchType="on"
> # template="json"
> #)
> action(
>name="tofile"
>type="omfile"
>file="/data/out.log"
>template="json"
> )
>}
>
>
> Regards
>
> ___
> rsyslog mailing list
> http://lists.adiscon.net/mailman/listinfo/rsyslog
> http://www.rsyslog.com/professional-services/
> What's up with rsyslog? Follow https://twitter.com/rgerhards
> NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad
> of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you
> DON'T LIKE THAT.
>
___
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of 
sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE 
THAT.