[rsyslog] memory alloc problems - any advise?

[Rainer Gerhards]

The promised stats. I used GNU's malloc_stats() and malloc_trim().

I queried stats every 5 seconds (lines with # are my comments):

#Right after startup:
Arena 0:
system bytes     =     245760
in use bytes     =     244624
Total (incl. mmap):
system bytes     =    4247552
in use bytes     =    4246416
max mmap regions =          1
max mmap bytes   =    4001792

#First burst:
Arena 0:
system bytes     =  108318720
in use bytes     =  107797520
Arena 1:
system bytes     =   67661824
in use bytes     =   18954784
Total (incl. mmap):
system bytes     =  179982336
in use bytes     =  130754096
max mmap regions =          1
max mmap bytes   =    4001792

#processing...
Arena 0:
system bytes     =  143970304
in use bytes     =   93414224
Arena 1:
system bytes     =   91770880
in use bytes     =       2336
Arena 2:
system bytes     =  106659840
in use bytes     =       2336
Total (incl. mmap):
system bytes     =  346402816
in use bytes     =   97420688
max mmap regions =          1
max mmap bytes   =    4001792

#idle
Arena 0:
system bytes     =  143970304
in use bytes     =     255248
Arena 1:
system bytes     =   91770880
in use bytes     =       2288
Arena 2:
system bytes     =  106659840
in use bytes     =       2288
Total (incl. mmap):
system bytes     =  346402816
in use bytes     =    4261616
max mmap regions =          1
max mmap bytes   =    4001792

#second burst - so it looks like the memory is reused (good!)
Arena 0:
system bytes     =  143970304
in use bytes     =  102348464
Arena 1:
system bytes     =   91770880
in use bytes     =   14172352
Arena 2:
system bytes     =  106659840
in use bytes     =       3840
Total (incl. mmap):
system bytes     =  346402816
in use bytes     =  120526448
max mmap regions =          1
max mmap bytes   =    4001792

# first and second burst were equal, same messages, same amount of them.
# Still not all allocs are re-used (they must have been identical, too). 
# As it looks > 50% were not reused...
Arena 0:
system bytes     =  206884864
in use bytes     =  206110592
Arena 1:
system bytes     =   91770880
in use bytes     =       2336
Arena 2:
system bytes     =  162009088
in use bytes     =       2400
Total (incl. mmap):
system bytes     =  464666624
in use bytes     =  210117120
max mmap regions =          1
max mmap bytes   =    4001792

#idle again
Arena 0:
system bytes     =  206884864
in use bytes     =     256000
Arena 1:
system bytes     =   91770880
in use bytes     =       3456
Arena 2:
system bytes     =  162009088
in use bytes     =       2352
Total (incl. mmap):
system bytes     =  464666624
in use bytes     =    4263600
max mmap regions =          1
max mmap bytes   =    4001792

# still idle 
Arena 0:
system bytes     =  206884864
in use bytes     =     256000
Arena 1:
system bytes     =   91770880
in use bytes     =       3456
Arena 2:
system bytes     =  162009088
in use bytes     =       2352
Total (incl. mmap):
system bytes     =  464666624
in use bytes     =    4263600
max mmap regions =          1
max mmap bytes   =    4001792

# still idle
Arena 0:
system bytes     =  206884864
in use bytes     =     256000
Arena 1:
system bytes     =   91770880
in use bytes     =       3456
Arena 2:
system bytes     =  162009088
in use bytes     =       2352
Total (incl. mmap):
system bytes     =  464666624
in use bytes     =    4263600
max mmap regions =          1
max mmap bytes   =    4001792

# I did a malloc_trim() every 10th stat counter and here it happens.
# The number still look the same, but in the OS system monitor, I see freed
# memory (and it actually is freed if I look at how the system then
performs).
# So it looks like only the virtual address space was kept?
malloc trim (1)!
Arena 0:
system bytes     =  206884864
in use bytes     =     256000
Arena 1:
system bytes     =   91770880
in use bytes     =       3456
Arena 2:
system bytes     =  162009088
in use bytes     =       2352
Total (incl. mmap):
system bytes     =  464666624
in use bytes     =    4263600
max mmap regions =          1
max mmap bytes   =    4001792

# no activity, so it remains at this level...
Arena 0:
system bytes     =  206884864
in use bytes     =     256000
Arena 1:
system bytes     =   91770880
in use bytes     =       3456
Arena 2:
system bytes     =  162009088
in use bytes     =       2352
Total (incl. mmap):
system bytes     =  464666624
in use bytes     =    4263600
max mmap regions =          1
max mmap bytes   =    4001792

With that information, I'll probably better turn to a GNU mailing list. Still
I wonder if someone here has an opinion. If so, please let me know. For the
time being, it looks like I need to do some period malloc_trim() calls...

Rainer

> -----Original Message-----
> From: rsyslog-bounces at lists.adiscon.com [mailto:rsyslog-
> bounces at lists.adiscon.com] On Behalf Of Rainer Gerhards
> Sent: Friday, June 19, 2009 6:36 PM
> To: rsyslog-users
> Subject: Re: [rsyslog] memory alloc problems - any advise?
> 
> > -----Original Message-----
> > From: rsyslog-bounces at lists.adiscon.com [mailto:rsyslog-
> > bounces at lists.adiscon.com] On Behalf Of RB
> > Sent: Friday, June 19, 2009 6:27 PM
> > To: rsyslog-users
> > Subject: Re: [rsyslog] memory alloc problems - any advise?
> >
> > On Fri, Jun 19, 2009 at 10:14, Rainer Gerhards<rgerhards at hq.adiscon.com>
> > wrote:
> > > What is surprising is that the memory is not given back to the OS when
> the
> > > data has been processed. Well... I know that some data blocks may still
> be
> > > held and thus prevent giving memory back. But that should be solved
when
> a
> > > few new messages come in. Still, nothing changes in that scenario. What
> > > puzzles me even more is that when I start a new burst of messages (I
send
> > > around one million each), it looks like almost only new memory is
> obtained
> > > from the OS for them. At least here I had expected that the allocator
> would
> > > re-use what was already claimed.
> >
> > Can you clarify what you mean by "not given back to the OS"?  Do you
> > mean that the RSS of rsyslog remains the same, or that the system
> > 'free' memory does not go back up, or something else entirely?  I'm
> > wondering if you're seeing caching effects.
> 
> Rss remains the same, looks like sbrk() is not called. I poked somemore
> around, and it looks like I need to do a malloc_trim() call in glibc to
solve
> this issue. Will post some stats soon...
> 
> Rainer
> _______________________________________________
> rsyslog mailing list
> http://lists.adiscon.net/mailman/listinfo/rsyslog
> http://www.rsyslog.com