Hi Peter,

On 09/27/2012 03:07 PM, Peter Soetens wrote:
> Hi Mark,
>
> On Wed, Sep 26, 2012 at 8:45 AM, <m [dot] horsthuis [..] ...
> <mailto:m [dot] horsthuis [..] ...>> wrote:
>
> Hello,
>
> >> Also, one thing that I'm not sure about is that each component
> logs in the
> same category. Currently, each category is associated with a
> RTT::Port to
> send logging events. So, if different threads are logging in the same
> category, this mean that there's many threads writing to a single
> port. Does
> that make sense?
>
> > The structure of this approach matches the underlying
> log4j/log4cpp/log4cxx
> approach, good, bad or otherwise. It is very common to have multiple
> categories end up in one parent category which does the actual
> logging. For a
> multi-component system, even with each component logging to separate
> categories, the hierarchy may well lead to multiple components (hence
> threads) logging to the same port.
>
> > The standard approach that I originally proposed had a
> BufferPort attached
> to that port, and we ended up using a locking policy on that port
> IIRC. It
> might well have been for exactly this reason. Either way, the
> projects and
> customers I work with have logged literal terabytes of data with
> the v1
> implementation and we've not noticed any issues yet (that we know
> of! ;-).
>
> I had the same problem. The application crashes with segaults
> continiously,
> often within seconds. I added a mutex to the log_port in the
> category class
> and the crashes are gone. I don't think that this is the best
> solution but
> for me it works.
>
>
> Is this RTT 1.x or 2.x logging ?
>
> Peter
>
RTT/OCL 2.x logging (OCL::Logging)

Mark

2011/10/7 Philippe Hamelin <philippe [dot] hamelin [..] ...>:
> 2011/10/7 Steven Bellens <steven [dot] bellens [..] ...>
>>
>> 2011/10/6 Philippe Hamelin <philippe [dot] hamelin [..] ...>:
>> > 2011/10/6 Steven Bellens <steven [dot] bellens [..] ...>
>> >>
>> >> 2011/10/6 Steven Bellens <steven [dot] bellens [..] ...>:
>> >> >
>> >> > http://bugs.orocos.org/show_bug.cgi?id=883
>> >> >
>> >> > --- Comment #7 from Steven Bellens <steven [dot] bellens [..] ...>
>> >> > 2011-10-06 15:33:08 CEST ---
>> >> > (In reply to comment #6)
>> >> >> (In reply to comment #5)
>> >> >> > (In reply to comment #4)
>> >> >> > > (In reply to comment #3)
>> >> >> > > [...]
>> >> >> > > >
>> >> >> > > > You'll have to recompile RTT with 'Debug' setting and re-run
>> >> >> > > > the
>> >> >> > > > gdb session.
>> >> >> > > > The values of the optimized out variables are necessary, and
>> >> >> > > > due
>> >> >> > > > to
>> >> >> > > > optimisation it may point at the wrong line of code causing
>> >> >> > > > the
>> >> >> > > > error.
>> >> >> > >
>> >> >> > > (gdb) info locals
>> >> >> > > tlsf = 0x628900
>> >> >> > > b = 0x62cc30
>> >> >> > > b2 = 0x62c7e0
>> >> >> > > next_b = 0x62c800
>> >> >> > > fl = 0
>> >> >> > > sl = 12
>> >> >> > > tmp_size = 16
>> >> >> > >
>> >> >> > >
>> >> >> > > >
>> >> >> > > > Also enable statistics as the others suggest to get the most
>> >> >> > > > data.
>> >> >> > >
>> >> >> > > Could you explain how I do that?
>> >> >> > >
>> >> >> >
>> >> >> > set the Cmake options OS_RT_MALLOC_DEBUG and OS_RT_MALLOC_STATS
>> >> >>
>> >> >> I set the OS_RT_MALLOC_DEBUG option (the other one was already
>> >> >> enabled), but it
>> >> >> doesn't change the output.
>> >> >>
>> >> >> >
>> >> >> > Is this issue still present ?
>> >> >>
>> >> >> Yes, still present.
>> >> >>
>> >> >> Steven
>> >> >
>> >> > OS details:
>> >> > Linux pma-09-032 2.6.40.4-5.fc15.x86_64 #1 SMP Tue Aug 30 14:38:32
>> >> > UTC
>> >> > 2011
>> >> > x86_64 x86_64 x86_64 GNU/Linux
>> >> >
>> >> > I put together a small example, which crashes here after about 10 -
>> >> > 20
>> >> > seconds:
>> >> >
>> >> > https://gitorious.org/rt-logging/rtlog_test
>> >> >
>> >> > Note that the time-to-crash does vary (sometimes a lot!), I didn't
>> >> > manage to
>> >> > find anything deterministic in that.
>> >>
>> >> Changing the logging statements to use
>> >>
>> >> logger->debug(RTT::rt_string
>> >>
>> >> instead of
>> >>
>> >> logger->getRTStream(log4cpp::Priority::INFO) <<
>> >>
>> >> Seems to solve the problem. I'm however using the latter because I want
>> >> to
>> >> output variables as well. So it looks like a problem in the getRTStream
>> >> and
>> >> subsequently the CategoryStream implementation?
>> >>
>> >
>> > This is strange because we use getRTStream everwhere in our application
>> > and
>> > we don't have this problem.
>>
>> Can you take a look at the example and check whether you get the crash as
>> well?
>>
>
> Your example doesn't link on my machine with Orocos 2.3.1. I'm not using ROS
> and it seems that log4cpp isn't include in the pkg-config file of
> ocl-logging. Also, I don't have the log4cxx appender in my version, but I
> modified the deployment script to use the OstreamAppender.
> You just have to put a try-catch in your updateHook to see that this is a
> std::bad_alloc exception (memory exhausted). What I suspect is that there's
> too much logging events in the queue so that the appender isn't able to
> manage them. There's a hardcoded buffer of 100 data in the appender input
> port. So, if the buffer is full you can easily exhaust the default real-time
> memory pool of 20 kb. Anyways, I must admit we should handle more cleanly
> this exception. To solve your problem, try to execute the deployer with this
> parameter:
>  --rtalloc-mem-size 200000
> With 200kb, I don't have std::bad_alloc exceptions anymore on my system.
> Indeed, after quitting I get the following stats:
> TLSF bytes allocated=200000 overhead=6384 max-used=58064
> currently-used=55520 still-allocated=49136
> As you can see, the maximum used memory is ~58kb, so this is the bare
> minimum you would need for your test case.

Thanks, Philippe, for this detailed analysis. I tested it on my real
application, and there I get max-used numbers around 48000, so my
problem is indeed a memory exhaust. I added an rtalloc-mem-size 100000
option and everything seems to be running fine now.

Thanks,

Steven

> Also, one thing that I'm not sure about is that each component logs in the
> same category. Currently, each category is associated with a RTT::Port to
> send logging events. So, if different threads are logging in the same
> category, this mean that there's many threads writing to a single port. Does
> that make sense?
> Philippe
>

On Oct 7, 2011, at 09:39 , Philippe Hamelin wrote:

> 2011/10/7 Steven Bellens <steven [dot] bellens [..] ...>
> 2011/10/6 Philippe Hamelin <philippe [dot] hamelin [..] ...>:
> > 2011/10/6 Steven Bellens <steven [dot] bellens [..] ...>
> >>
> >> 2011/10/6 Steven Bellens <steven [dot] bellens [..] ...>:
> >> >
> >> > http://bugs.orocos.org/show_bug.cgi?id=883
> >> >
> >> > --- Comment #7 from Steven Bellens <steven [dot] bellens [..] ...>
> >> > 2011-10-06 15:33:08 CEST ---
> >> > (In reply to comment #6)
> >> >> (In reply to comment #5)
> >> >> > (In reply to comment #4)
> >> >> > > (In reply to comment #3)
> >> >> > > [...]
> >> >> > > >
> >> >> > > > You'll have to recompile RTT with 'Debug' setting and re-run the
> >> >> > > > gdb session.
> >> >> > > > The values of the optimized out variables are necessary, and due
> >> >> > > > to
> >> >> > > > optimisation it may point at the wrong line of code causing the
> >> >> > > > error.
> >> >> > >
> >> >> > > (gdb) info locals
> >> >> > > tlsf = 0x628900
> >> >> > > b = 0x62cc30
> >> >> > > b2 = 0x62c7e0
> >> >> > > next_b = 0x62c800
> >> >> > > fl = 0
> >> >> > > sl = 12
> >> >> > > tmp_size = 16
> >> >> > >
> >> >> > >
> >> >> > > >
> >> >> > > > Also enable statistics as the others suggest to get the most
> >> >> > > > data.
> >> >> > >
> >> >> > > Could you explain how I do that?
> >> >> > >
> >> >> >
> >> >> > set the Cmake options OS_RT_MALLOC_DEBUG and OS_RT_MALLOC_STATS
> >> >>
> >> >> I set the OS_RT_MALLOC_DEBUG option (the other one was already
> >> >> enabled), but it
> >> >> doesn't change the output.
> >> >>
> >> >> >
> >> >> > Is this issue still present ?
> >> >>
> >> >> Yes, still present.
> >> >>
> >> >> Steven
> >> >
> >> > OS details:
> >> > Linux pma-09-032 2.6.40.4-5.fc15.x86_64 #1 SMP Tue Aug 30 14:38:32 UTC
> >> > 2011
> >> > x86_64 x86_64 x86_64 GNU/Linux
> >> >
> >> > I put together a small example, which crashes here after about 10 - 20
> >> > seconds:
> >> >
> >> > https://gitorious.org/rt-logging/rtlog_test
> >> >
> >> > Note that the time-to-crash does vary (sometimes a lot!), I didn't
> >> > manage to
> >> > find anything deterministic in that.
> >>
> >> Changing the logging statements to use
> >>
> >> logger->debug(RTT::rt_string
> >>
> >> instead of
> >>
> >> logger->getRTStream(log4cpp::Priority::INFO) <<
> >>
> >> Seems to solve the problem. I'm however using the latter because I want to
> >> output variables as well. So it looks like a problem in the getRTStream
> >> and
> >> subsequently the CategoryStream implementation?
> >>
> >
> > This is strange because we use getRTStream everwhere in our application and
> > we don't have this problem.
>
> Can you take a look at the example and check whether you get the crash as well?
>
>
> Your example doesn't link on my machine with Orocos 2.3.1. I'm not using ROS and it seems that log4cpp isn't include in the pkg-config file of ocl-logging. Also, I don't have the log4cxx appender in my version, but I modified the deployment script to use the OstreamAppender.
>
> You just have to put a try-catch in your updateHook to see that this is a std::bad_alloc exception (memory exhausted). What I suspect is that there's too much logging events in the queue so that the appender isn't able to manage them. There's a hardcoded buffer of 100 data in the appender input port. So, if the buffer is full you can easily exhaust the default real-time memory pool of 20 kb. Anyways, I must admit we should handle more cleanly this exception. To solve your problem, try to execute the deployer with this parameter:
>
> --rtalloc-mem-size 200000
>
> With 200kb, I don't have std::bad_alloc exceptions anymore on my system. Indeed, after quitting I get the following stats:
>
> TLSF bytes allocated=200000 overhead=6384 max-used=58064 currently-used=55520 still-allocated=49136

This is precisely why we output regular diagnostics on the memory pool state. It is incredibly easy to exhaust the pool without trying, particularly if you have things like buffers of RT strings floating around. We actually use buffers on the order of 20 MB in our (admittedly desktop based) systems, but we do log a _lot_ of data.

The fact that ~48k is still allocated might be worth looking into ...

One thing I should mention is that with a 100 element buffer, once the buffer has been filled once with logging data and had all the data removed and logged (ie the buffer is now "empty"), you are from then on carrying allocation for 100 "unused" RT strings around. So for a 20k buffer with ~6k of overhead, that means if your strings average 140 bytes or more, you exhaust the memory pool!! These "unused" RT strings occur as the elements in the buffer are not destroyed after they're popped, and so the memory hasn't been deallocated yet. It's only the next time that a particular element is used (ie when the buffer rolls over that element again) that the current memory is deallocated, and memory is allocated for the new string (ok, that simplifies it as it may not necessarily deallocate, it may reuse, but the point remains). So you basically have to budget for a buffer completely filled with allocated RT strings of whatever your maximum string length is. So say a 1000-char max logging line, and a 100 element buffer, then you need a memory pool of at least 1000 * 100 + 6k overhead = ~106k (even with max 200 char lines, you still need 26k, which is more than the default.

The above is mentioned in passing on the following page, but probably should be spelled out in more detail ...?

http://www.orocos.org/wiki/rtt/rtt-20/real-time-logging/using-real-time-...

> As you can see, the maximum used memory is ~58kb, so this is the bare minimum you would need for your test case.

The 20k default is way too low for anything but toy systems. I wonder if we should increase this?

> Also, one thing that I'm not sure about is that each component logs in the same category. Currently, each category is associated with a RTT::Port to send logging events. So, if different threads are logging in the same category, this mean that there's many threads writing to a single port. Does that make sense?

The structure of this approach matches the underlying log4j/log4cpp/log4cxx approach, good, bad or otherwise. It is very common to have multiple categories end up in one parent category which does the actual logging. For a multi-component system, even with each component logging to separate categories, the hierarchy may well lead to multiple components (hence threads) logging to the same port.

The standard approach that I originally proposed had a BufferPort attached to that port, and we ended up using a locking policy on that port IIRC. It might well have been for exactly this reason. Either way, the projects and customers I work with have logged literal terabytes of data with the v1 implementation and we've not noticed any issues yet (that we know of! ;-).
S

On Jul 27, 2011, at 13:46 , Philippe Hamelin wrote:

>
>
> Le mercredi 27 juillet 2011, S Roderick <kiwi [dot] net [..] ...> a écrit :
> > On Jul 27, 2011, at 04:50 , Steven Bellens wrote:
> >
> >>
> >> http://bugs.orocos.org/show_bug.cgi?id=883
> >>
> >> Summary: Real-time logging segfaults
> >> Product: Toolchain
> >> Version: master
> >> Platform: All
> >> OS/Version: All
> >> Status: NEW
> >> Severity: normal
> >> Priority: P3
> >> Component: RTT
> >> AssignedTo: orocos-dev [..] ...
> >> ReportedBy: steven [dot] bellens [..] ...
> >> CC: orocos-dev [..] ...
> >> Estimated Hours: 0.0
> >>
> >>
> >> Using the real-time logging service, I regularly get segfaults. GDB backtrace
> >> gives me:
> >>
> >> Program received signal SIGSEGV, Segmentation fault.
> >> [Switching to Thread 0x7fffadffb700 (LWP 21995)]
> >> 0x00007ffff7d56494 in malloc_ex (size=96, mem_pool=0x628900)
> >> at /home/u0063509/stacks/orocos_toolchain_ros/rtt/rtt/os/tlsf/tlsf.c:727
> >> 727 EXTRACT_BLOCK_HDR(b, tlsf, fl, sl);
> >> (gdb) bt
> >> #0 0x00007ffff7d56494 in malloc_ex (size=96, mem_pool=0x628900)
> >> at /home/u0063509/stacks/orocos_toolchain_ros/rtt/rtt/os/tlsf/tlsf.c:727
> >> #1 0x00007ffff7d56b9f in oro_rt_malloc (size=85)
> >> at /home/u0063509/stacks/orocos_toolchain_ros/rtt/rtt/os/tlsf/tlsf.c:634
> >
> > Most likely you've exhausted the memory pool. There are some functions to monitor the usage of a pool, suggest you add those in: get_used_size(), get_max_size()
>
> The allocator usually throws a std::bad_alloc exception when the memory is exhausted. This doesn't seems to be the case here.

We've found that to not be the case. Sometimes std::alloc, sometimes assert(). I don't remember what the fundamental cause of the assert() is ...

S