Log4cpp support question in 2.x

I'm testing the log4cpp code in 2.x and I'm trying to understand how it works.

The only thing I think I don't understand is this snippet in the deployment
file (from http://orocos.org/wiki/rtt/rtt-20/real-time-logging/using-real-time-
logging):


  <struct name="LoggingService" type="OCL::logging::LoggingService">
    <struct name="Activity" type="PeriodicActivity">
      <simple name="Period" type="double"><value>0.5</value></simple>
      <simple name="Priority" type="short"><value>0</value></simple>
      <simple name="Scheduler" 
type="string"><value>ORO_SCHED_OTHER</value></simple>
    </struct>
 
    <simple name="AutoConf" type="boolean"><value>1</value></simple>
    <simple name="AutoStart" type="boolean"><value>1</value></simple>
 
    <struct name="Properties" type="PropertyBag">
      <struct name="Levels" type="PropertyBag">
        <simple name="org.orocos.ocl.logging.tests.TestComponent" 
                type="string"><value>info</value></simple>
      </struct>
 
      <struct name="Appenders" type="PropertyBag">
        <simple name="org.orocos.ocl.logging.tests.TestComponent" 
                type="string"><value>AppenderA</value></simple>
      </struct>
    </struct>
 
    <struct name="Peers" type="PropertyBag">
      <simple type="string"><value>AppenderA</value></simple>
    </struct> 
 
  </struct>


Why is the 'Appenders' struct necessary ? Can't we automatically route all
present categories to the present appenders ? Do I need to list each and every
category in the Appenders struct ?

A second question is how the deployment file mixes with the log4cpp config file.
For example, the appender's xml properties duplicate what is in the config file.
Which one takes precedence ?

Why did you make the LoggingService periodic ? It has no updateHook()...

Peter

Log4cpp support question in 2.x

On Nov 30, 2010, at 09:12 , Peter Soetens wrote:

> I'm testing the log4cpp code in 2.x and I'm trying to understand how it works.
>
> The only thing I think I don't understand is this snippet in the deployment
> file (from http://orocos.org/wiki/rtt/rtt-20/real-time-logging/using-real-time-
> logging):
>
> 
>  <struct name="LoggingService" type="OCL::logging::LoggingService">
>    <struct name="Activity" type="PeriodicActivity">
>      <simple name="Period" type="double"><value>0.5</value></simple>
>      <simple name="Priority" type="short"><value>0</value></simple>
>      <simple name="Scheduler" 
> type="string"><value>ORO_SCHED_OTHER</value></simple>
>    </struct>
> 
>    <simple name="AutoConf" type="boolean"><value>1</value></simple>
>    <simple name="AutoStart" type="boolean"><value>1</value></simple>
> 
>    <struct name="Properties" type="PropertyBag">
>      <struct name="Levels" type="PropertyBag">
>        <simple name="org.orocos.ocl.logging.tests.TestComponent" 
>                type="string"><value>info</value></simple>
>      </struct>
> 
>      <struct name="Appenders" type="PropertyBag">
>        <simple name="org.orocos.ocl.logging.tests.TestComponent" 
>                type="string"><value>AppenderA</value></simple>
>      </struct>
>    </struct>
> 
>    <struct name="Peers" type="PropertyBag">
>      <simple type="string"><value>AppenderA</value></simple>
>    </struct> 
> 
>  </struct>
>
>
> Why is the 'Appenders' struct necessary ? Can't we automatically route all
> present categories to the present appenders ? Do I need to list each and every
> category in the Appenders struct ?

No, you don't need to list all appenders. Our typical usage scenario is
- have all components use a category "components." + GetName()
- set the default logging level of category "components"
- set the logging level of any other category "components.XXX" as appropriate to get more/less logging
- attach one appender to category "components" (for us, it is to file)

You don't want to route all categories to all appenders. Here's an example why
- one appender to file, which all components use (as above)
- one appender to another file, which (say) a reporting only component uses
- one appender to another file, which (say) a different reporting only component uses

If you attached all categories to all/one of the appenders above, you'd mix up all the output. We regularly do the above to separate tracing statements (the "components.XXX" categories), from specific reporting output that we want to be able to post-process to plot, analyse, etc. At the very least, the reporting output is different from standard trace statements. We may also want to send the reporting data elsewhere, and not dump it to file locally (like the "components" appender does).

> A second question is how the deployment file mixes with the log4cpp config file.
> For example, the appender's xml properties duplicate what is in the config file.
> Which one takes precedence ?

For real-time logging, there is no log4cpp config file. It all comes from this XML properties. This is done as there is additional info in our XML than is present in the log4cpp config file (though IIRC it is not as much as we originally though it would be)

> Why did you make the LoggingService periodic ? It has no updateHook()...

You asked me to ... :-) ... it also centralizes certain things. The intent was to be able to manipulate the overall log4cpp categories and hierarachy using this service (eg from scripts, state machines).

I need to create a system example demonstrating one usage scenario of logging. Not enough hours in the day ... week ... month ...

HTH
S

Log4cpp support question in 2.x

On Tuesday 30 November 2010 15:23:23 S Roderick wrote:
> On Nov 30, 2010, at 09:12 , Peter Soetens wrote:
> > I'm testing the log4cpp code in 2.x and I'm trying to understand how it
> > works.
> >
> > The only thing I think I don't understand is this snippet in the
> > deployment file (from
> > http://orocos.org/wiki/rtt/rtt-20/real-time-logging/using-real-time-
> > logging):
> >
> > 
> > 
> >  <struct name="LoggingService" type="OCL::logging::LoggingService">
> >  
> >    <struct name="Activity" type="PeriodicActivity">
> >    
> >      <simple name="Period" type="double"><value>0.5</value></simple>
> >      <simple name="Priority" type="short"><value>0</value></simple>
> >      <simple name="Scheduler"
> > 
> > type="string"><value>ORO_SCHED_OTHER</value></simple>
> > 
> >    </struct>
> >    
> >    <simple name="AutoConf" type="boolean"><value>1</value></simple>
> >    <simple name="AutoStart" type="boolean"><value>1</value></simple>
> >    
> >    <struct name="Properties" type="PropertyBag">
> >    
> >      <struct name="Levels" type="PropertyBag">
> >      
> >        <simple name="org.orocos.ocl.logging.tests.TestComponent"
> >        
> >                type="string"><value>info</value></simple>
> >      
> >      </struct>
> >      
> >      <struct name="Appenders" type="PropertyBag">
> >      
> >        <simple name="org.orocos.ocl.logging.tests.TestComponent"
> >        
> >                type="string"><value>AppenderA</value></simple>
> >      
> >      </struct>
> >    
> >    </struct>
> >    
> >    <struct name="Peers" type="PropertyBag">
> >    
> >      <simple type="string"><value>AppenderA</value></simple>
> >    
> >    </struct>
> >  
> >  </struct>
> > 
> >
> >
> > Why is the 'Appenders' struct necessary ? Can't we automatically route
> > all present categories to the present appenders ? Do I need to list each
> > and every category in the Appenders struct ?
>
> No, you don't need to list all appenders. Our typical usage scenario is
> - have all components use a category "components." + GetName()
> - set the default logging level of category "components"
> - set the logging level of any other category "components.XXX" as
> appropriate to get more/less logging - attach one appender to category
> "components" (for us, it is to file)
>
> You don't want to route all categories to all appenders. Here's an example
> why - one appender to file, which all components use (as above)
> - one appender to another file, which (say) a reporting only component uses
> - one appender to another file, which (say) a different reporting only
> component uses
>
> If you attached all categories to all/one of the appenders above, you'd mix
> up all the output. We regularly do the above to separate tracing
> statements (the "components.XXX" categories), from specific reporting
> output that we want to be able to post-process to plot, analyse, etc. At
> the very least, the reporting output is different from standard trace
> statements. We may also want to send the reporting data elsewhere, and not
> dump it to file locally (like the "components" appender does).

Now I understand. We might need an inkscape drawing or two to clear this
usage scenario up.

>
> > A second question is how the deployment file mixes with the log4cpp
> > config file. For example, the appender's xml properties duplicate what
> > is in the config file. Which one takes precedence ?
>
> For real-time logging, there is no log4cpp config file. It all comes from
> this XML properties. This is done as there is additional info in our XML
> than is present in the log4cpp config file (though IIRC it is not as much
> as we originally though it would be)

Ok.

I have fixed&tested the logging framework on master and it works. I heard the
ros people were using some neat GUI to watch the log files. There are many for
log4j, with which our pattern layout files are compatible but I couldn't find
any that suits our needs. Suggestions ?

We should also start to think about distributing the logging such that one
appender can catch the logs of the whole application. This would require a
typekit and transport(s) for the log4cpp event. (longer term feature though).

Peter

Log4cpp support question in 2.x

On Nov 30, 2010, at 11:09 , Peter Soetens wrote:

> On Tuesday 30 November 2010 15:23:23 S Roderick wrote:
>> On Nov 30, 2010, at 09:12 , Peter Soetens wrote:
>>> I'm testing the log4cpp code in 2.x and I'm trying to understand how it
>>> works.
>>>
>>> The only thing I think I don't understand is this snippet in the
>>> deployment file (from
>>> http://orocos.org/wiki/rtt/rtt-20/real-time-logging/using-real-time-
>>> logging):
>>>
>>> 
>>> 
>>> <struct name="LoggingService" type="OCL::logging::LoggingService">
>>> 
>>>   <struct name="Activity" type="PeriodicActivity">
>>> 
>>>     <simple name="Period" type="double"><value>0.5</value></simple>
>>>     <simple name="Priority" type="short"><value>0</value></simple>
>>>     <simple name="Scheduler"
>>> 
>>> type="string"><value>ORO_SCHED_OTHER</value></simple>
>>> 
>>>   </struct>
>>> 
>>>   <simple name="AutoConf" type="boolean"><value>1</value></simple>
>>>   <simple name="AutoStart" type="boolean"><value>1</value></simple>
>>> 
>>>   <struct name="Properties" type="PropertyBag">
>>> 
>>>     <struct name="Levels" type="PropertyBag">
>>> 
>>>       <simple name="org.orocos.ocl.logging.tests.TestComponent"
>>> 
>>>               type="string"><value>info</value></simple>
>>> 
>>>     </struct>
>>> 
>>>     <struct name="Appenders" type="PropertyBag">
>>> 
>>>       <simple name="org.orocos.ocl.logging.tests.TestComponent"
>>> 
>>>               type="string"><value>AppenderA</value></simple>
>>> 
>>>     </struct>
>>> 
>>>   </struct>
>>> 
>>>   <struct name="Peers" type="PropertyBag">
>>> 
>>>     <simple type="string"><value>AppenderA</value></simple>
>>> 
>>>   </struct>
>>> 
>>> </struct>
>>> 
>>>
>>>
>>> Why is the 'Appenders' struct necessary ? Can't we automatically route
>>> all present categories to the present appenders ? Do I need to list each
>>> and every category in the Appenders struct ?
>>
>> No, you don't need to list all appenders. Our typical usage scenario is
>> - have all components use a category "components." + GetName()
>> - set the default logging level of category "components"
>> - set the logging level of any other category "components.XXX" as
>> appropriate to get more/less logging - attach one appender to category
>> "components" (for us, it is to file)
>>
>> You don't want to route all categories to all appenders. Here's an example
>> why - one appender to file, which all components use (as above)
>> - one appender to another file, which (say) a reporting only component uses
>> - one appender to another file, which (say) a different reporting only
>> component uses
>>
>> If you attached all categories to all/one of the appenders above, you'd mix
>> up all the output. We regularly do the above to separate tracing
>> statements (the "components.XXX" categories), from specific reporting
>> output that we want to be able to post-process to plot, analyse, etc. At
>> the very least, the reporting output is different from standard trace
>> statements. We may also want to send the reporting data elsewhere, and not
>> dump it to file locally (like the "components" appender does).
>
> Now I understand. We might need an inkscape drawing or two to clear this
> usage scenario up.

Agreed. That should be part of a system example of logging - outlining a basic usage scenario, along with usage documentation (not API doc's).

>>> A second question is how the deployment file mixes with the log4cpp
>>> config file. For example, the appender's xml properties duplicate what
>>> is in the config file. Which one takes precedence ?
>>
>> For real-time logging, there is no log4cpp config file. It all comes from
>> this XML properties. This is done as there is additional info in our XML
>> than is present in the log4cpp config file (though IIRC it is not as much
>> as we originally though it would be)
>
> Ok.
>
> I have fixed&tested the logging framework on master and it works. I heard the
> ros people were using some neat GUI to watch the log files. There are many for
> log4j, with which our pattern layout files are compatible but I couldn't find
> any that suits our needs. Suggestions ?

I'd be interested in knowing what they used ... no suggestions here. We face a similar dilemma.

> We should also start to think about distributing the logging such that one
> appender can catch the logs of the whole application. This would require a
> typekit and transport(s) for the log4cpp event. (longer term feature though).

I'll get right on that ... ;-)

Seriously, what do you mean "catch the logs of the whole application"? If you attach to the root category and leave the default additivity to true, then everything logged ends up at the root. There are technical reasons we can't attach a real-time logger to the root category right now, but I'm sure they can be overcome. Our approach of using "components.XXX" essentially allows us this already, doesn't it ...?

I'd be interested in what you think are near-term features/fixes needed, once you've used it a while. I've some ideas of what you might come up with ....
S

Log4cpp support question in 2.x

On Nov 30, 2010, at 11:19 , Stephen Roderick wrote:

> On Nov 30, 2010, at 11:09 , Peter Soetens wrote:
>
>> On Tuesday 30 November 2010 15:23:23 S Roderick wrote:
>>> On Nov 30, 2010, at 09:12 , Peter Soetens wrote:
>>>> I'm testing the log4cpp code in 2.x and I'm trying to understand how it
>>>> works.
>>>>
>>>> The only thing I think I don't understand is this snippet in the
>>>> deployment file (from
>>>> http://orocos.org/wiki/rtt/rtt-20/real-time-logging/using-real-time-
>>>> logging):
>>>>
>>>> 
>>>> 
>>>> <struct name="LoggingService" type="OCL::logging::LoggingService">
>>>> 
>>>>  <struct name="Activity" type="PeriodicActivity">
>>>> 
>>>>    <simple name="Period" type="double"><value>0.5</value></simple>
>>>>    <simple name="Priority" type="short"><value>0</value></simple>
>>>>    <simple name="Scheduler"
>>>> 
>>>> type="string"><value>ORO_SCHED_OTHER</value></simple>
>>>> 
>>>>  </struct>
>>>> 
>>>>  <simple name="AutoConf" type="boolean"><value>1</value></simple>
>>>>  <simple name="AutoStart" type="boolean"><value>1</value></simple>
>>>> 
>>>>  <struct name="Properties" type="PropertyBag">
>>>> 
>>>>    <struct name="Levels" type="PropertyBag">
>>>> 
>>>>      <simple name="org.orocos.ocl.logging.tests.TestComponent"
>>>> 
>>>>              type="string"><value>info</value></simple>
>>>> 
>>>>    </struct>
>>>> 
>>>>    <struct name="Appenders" type="PropertyBag">
>>>> 
>>>>      <simple name="org.orocos.ocl.logging.tests.TestComponent"
>>>> 
>>>>              type="string"><value>AppenderA</value></simple>
>>>> 
>>>>    </struct>
>>>> 
>>>>  </struct>
>>>> 
>>>>  <struct name="Peers" type="PropertyBag">
>>>> 
>>>>    <simple type="string"><value>AppenderA</value></simple>
>>>> 
>>>>  </struct>
>>>> 
>>>> </struct>
>>>> 
>>>>
>>>>
>>>> Why is the 'Appenders' struct necessary ? Can't we automatically route
>>>> all present categories to the present appenders ? Do I need to list each
>>>> and every category in the Appenders struct ?
>>>
>>> No, you don't need to list all appenders. Our typical usage scenario is
>>> - have all components use a category "components." + GetName()
>>> - set the default logging level of category "components"
>>> - set the logging level of any other category "components.XXX" as
>>> appropriate to get more/less logging - attach one appender to category
>>> "components" (for us, it is to file)
>>>
>>> You don't want to route all categories to all appenders. Here's an example
>>> why - one appender to file, which all components use (as above)
>>> - one appender to another file, which (say) a reporting only component uses
>>> - one appender to another file, which (say) a different reporting only
>>> component uses
>>>
>>> If you attached all categories to all/one of the appenders above, you'd mix
>>> up all the output. We regularly do the above to separate tracing
>>> statements (the "components.XXX" categories), from specific reporting
>>> output that we want to be able to post-process to plot, analyse, etc. At
>>> the very least, the reporting output is different from standard trace
>>> statements. We may also want to send the reporting data elsewhere, and not
>>> dump it to file locally (like the "components" appender does).
>>
>> Now I understand. We might need an inkscape drawing or two to clear this
>> usage scenario up.
>
> Agreed. That should be part of a system example of logging - outlining a basic usage scenario, along with usage documentation (not API doc's).
>
>>>> A second question is how the deployment file mixes with the log4cpp
>>>> config file. For example, the appender's xml properties duplicate what
>>>> is in the config file. Which one takes precedence ?
>>>
>>> For real-time logging, there is no log4cpp config file. It all comes from
>>> this XML properties. This is done as there is additional info in our XML
>>> than is present in the log4cpp config file (though IIRC it is not as much
>>> as we originally though it would be)
>>
>> Ok.
>>
>> I have fixed&tested the logging framework on master and it works. I heard the
>> ros people were using some neat GUI to watch the log files. There are many for
>> log4j, with which our pattern layout files are compatible but I couldn't find
>> any that suits our needs. Suggestions ?
>
> I'd be interested in knowing what they used ... no suggestions here. We face a similar dilemma.
>
>> We should also start to think about distributing the logging such that one
>> appender can catch the logs of the whole application. This would require a
>> typekit and transport(s) for the log4cpp event. (longer term feature though).
>
> I'll get right on that ... ;-)
>
> Seriously, what do you mean "catch the logs of the whole application"? If you attach to the root category and leave the default additivity to true, then everything logged ends up at the root. There are technical reasons we can't attach a real-time logger to the root category right now, but I'm sure they can be overcome. Our approach of using "components.XXX" essentially allows us this already, doesn't it ...?
>
> I'd be interested in what you think are near-term features/fixes needed, once you've used it a while. I've some ideas of what you might come up with ....

I will give you one warning here. We find it a _very delicate_ balance in setting the size of the logging buffer vs the TLSF memory pool size. You can't stay in real-time and let the memory pool grow (hence no MMAP and SBRK in TLSF), and you need enough of a buffer to keep up with the worst case logging event peak load. Our systems can easily generate several thousand logging events a second, and so we have a default buffer size of 1000 (attached to "components" category, so only one buffer), with the appender running periodically at the system control rate (400Hz) and popping up to 50 events a cycle (remember, we're still in v1). This consumes just under a 1MB memory pool by the time the buffer fills up.

Take note of that last point! TLSF memory is _not_ deallocated as the logging buffer fills. This is as each logging event in there is not "destroyed" (and hence associated TLSF strings deallocated) until that logging event is overwritten when the buffer rolls around. So for a 1000 element buffer, and say several hundred chars in a logging message (typical for us), you need about a 1MB TLSF memory pool just to store all the strings used when the buffer has been completely used, but is currently "empty" (ie you have used every element in the buffer, but you popped everything out of the buffer and so it is currently empty).

I'm interested if anyone has any workarounds to this ... the problem will be slightly different with v2, but it's still essentially a classic consumer, producer problem. And you know you have it wrong when your deployer throws a std::bad_alloc exception on you ... :-(
S

Log4cpp support question in 2.x

On 11/30/2010 05:28 PM, S Roderick wrote:
> On Nov 30, 2010, at 11:19 , Stephen Roderick wrote:
>
>> On Nov 30, 2010, at 11:09 , Peter Soetens wrote:
>>
>>> On Tuesday 30 November 2010 15:23:23 S Roderick wrote:
>>>> On Nov 30, 2010, at 09:12 , Peter Soetens wrote:
>>>>> I'm testing the log4cpp code in 2.x and I'm trying to understand how it
>>>>> works.
>>>>>
>>>>> The only thing I think I don't understand is this snippet in the
>>>>> deployment file (from
>>>>> http://orocos.org/wiki/rtt/rtt-20/real-time-logging/using-real-time-
>>>>> logging):
>>>>>
>>>>> 
>>>>>
>>>>> <struct name="LoggingService" type="OCL::logging::LoggingService">
>>>>>
>>>>>   <struct name="Activity" type="PeriodicActivity">
>>>>>
>>>>>     <simple name="Period" type="double"><value>0.5</value></simple>
>>>>>     <simple name="Priority" type="short"><value>0</value></simple>
>>>>>     <simple name="Scheduler"
>>>>>
>>>>> type="string"><value>ORO_SCHED_OTHER</value></simple>
>>>>>
>>>>>   </struct>
>>>>>
>>>>>   <simple name="AutoConf" type="boolean"><value>1</value></simple>
>>>>>   <simple name="AutoStart" type="boolean"><value>1</value></simple>
>>>>>
>>>>>   <struct name="Properties" type="PropertyBag">
>>>>>
>>>>>     <struct name="Levels" type="PropertyBag">
>>>>>
>>>>>       <simple name="org.orocos.ocl.logging.tests.TestComponent"
>>>>>
>>>>>               type="string"><value>info</value></simple>
>>>>>
>>>>>     </struct>
>>>>>
>>>>>     <struct name="Appenders" type="PropertyBag">
>>>>>
>>>>>       <simple name="org.orocos.ocl.logging.tests.TestComponent"
>>>>>
>>>>>               type="string"><value>AppenderA</value></simple>
>>>>>
>>>>>     </struct>
>>>>>
>>>>>   </struct>
>>>>>
>>>>>   <struct name="Peers" type="PropertyBag">
>>>>>
>>>>>     <simple type="string"><value>AppenderA</value></simple>
>>>>>
>>>>>   </struct>
>>>>>
>>>>> </struct>
>>>>>
>>>>>
>>>>>
>>>>> Why is the 'Appenders' struct necessary ? Can't we automatically route
>>>>> all present categories to the present appenders ? Do I need to list each
>>>>> and every category in the Appenders struct ?
>>>> No, you don't need to list all appenders. Our typical usage scenario is
>>>> - have all components use a category "components." + GetName()
>>>> - set the default logging level of category "components"
>>>> - set the logging level of any other category "components.XXX" as
>>>> appropriate to get more/less logging - attach one appender to category
>>>> "components" (for us, it is to file)
>>>>
>>>> You don't want to route all categories to all appenders. Here's an example
>>>> why - one appender to file, which all components use (as above)
>>>> - one appender to another file, which (say) a reporting only component uses
>>>> - one appender to another file, which (say) a different reporting only
>>>> component uses
>>>>
>>>> If you attached all categories to all/one of the appenders above, you'd mix
>>>> up all the output. We regularly do the above to separate tracing
>>>> statements (the "components.XXX" categories), from specific reporting
>>>> output that we want to be able to post-process to plot, analyse, etc. At
>>>> the very least, the reporting output is different from standard trace
>>>> statements. We may also want to send the reporting data elsewhere, and not
>>>> dump it to file locally (like the "components" appender does).
>>> Now I understand. We might need an inkscape drawing or two to clear this
>>> usage scenario up.
>> Agreed. That should be part of a system example of logging - outlining a basic usage scenario, along with usage documentation (not API doc's).
>>
>>>>> A second question is how the deployment file mixes with the log4cpp
>>>>> config file. For example, the appender's xml properties duplicate what
>>>>> is in the config file. Which one takes precedence ?
>>>> For real-time logging, there is no log4cpp config file. It all comes from
>>>> this XML properties. This is done as there is additional info in our XML
>>>> than is present in the log4cpp config file (though IIRC it is not as much
>>>> as we originally though it would be)
>>> Ok.
>>>
>>> I have fixed&tested the logging framework on master and it works. I heard the
>>> ros people were using some neat GUI to watch the log files. There are many for
>>> log4j, with which our pattern layout files are compatible but I couldn't find
>>> any that suits our needs. Suggestions ?
>> I'd be interested in knowing what they used ... no suggestions here. We face a similar dilemma.
>>
>>> We should also start to think about distributing the logging such that one
>>> appender can catch the logs of the whole application. This would require a
>>> typekit and transport(s) for the log4cpp event. (longer term feature though).
>> I'll get right on that ... ;-)
>>
>> Seriously, what do you mean "catch the logs of the whole application"? If you attach to the root category and leave the default additivity to true, then everything logged ends up at the root. There are technical reasons we can't attach a real-time logger to the root category right now, but I'm sure they can be overcome. Our approach of using "components.XXX" essentially allows us this already, doesn't it ...?
>>
>> I'd be interested in what you think are near-term features/fixes needed, once you've used it a while. I've some ideas of what you might come up with ....
> I will give you one warning here. We find it a _very delicate_ balance in setting the size of the logging buffer vs the TLSF memory pool size. You can't stay in real-time and let the memory pool grow (hence no MMAP and SBRK in TLSF), and you need enough of a buffer to keep up with the worst case logging event peak load. Our systems can easily generate several thousand logging events a second, and so we have a default buffer size of 1000 (attached to "components" category, so only one buffer), with the appender running periodically at the system control rate (400Hz) and popping up to 50 events a cycle (remember, we're still in v1). This consumes just under a 1MB memory pool by the time the buffer fills up.
>
> Take note of that last point! TLSF memory is _not_ deallocated as the logging buffer fills. This is as each logging event in there is not "destroyed" (and hence associated TLSF strings deallocated) until that logging event is overwritten when the buffer rolls around. So for a 1000 element buffer, and say several hundred chars in a logging message (typical for us), you need about a 1MB TLSF memory pool just to store all the strings used when the buffer has been completely used, but is currently "empty" (ie you have used every element in the buffer, but you popped everything out of the buffer and so it is currently empty).
>
> I'm interested if anyone has any workarounds to this ... the problem will be slightly different with v2, but it's still essentially a classic consumer, producer problem. And you know you have it wrong when your deployer throws a std::bad_alloc exception on you ... :-(
Just for my understanding: what kind of messages you output that
actually require sending that many strings ?

Wouldn't you be able to send the same information through normal ports
(i.e. having "debug" data structures) instead ?

Log4cpp support question in 2.x

On Nov 30, 2010, at 11:49 , Sylvain Joyeux wrote:

> On 11/30/2010 05:28 PM, S Roderick wrote:
>> On Nov 30, 2010, at 11:19 , Stephen Roderick wrote:
>>
>>> On Nov 30, 2010, at 11:09 , Peter Soetens wrote:
>>>
>>>> On Tuesday 30 November 2010 15:23:23 S Roderick wrote:
>>>>> On Nov 30, 2010, at 09:12 , Peter Soetens wrote:
>>>>>> I'm testing the log4cpp code in 2.x and I'm trying to understand how it
>>>>>> works.
>>>>>>
>>>>>> The only thing I think I don't understand is this snippet in the
>>>>>> deployment file (from
>>>>>> http://orocos.org/wiki/rtt/rtt-20/real-time-logging/using-real-time-
>>>>>> logging):
>>>>>>
>>>>>> 
>>>>>> 
>>>>>> <struct name="LoggingService" type="OCL::logging::LoggingService">
>>>>>> 
>>>>>>  <struct name="Activity" type="PeriodicActivity">
>>>>>> 
>>>>>>    <simple name="Period" type="double"><value>0.5</value></simple>
>>>>>>    <simple name="Priority" type="short"><value>0</value></simple>
>>>>>>    <simple name="Scheduler"
>>>>>> 
>>>>>> type="string"><value>ORO_SCHED_OTHER</value></simple>
>>>>>> 
>>>>>>  </struct>
>>>>>> 
>>>>>>  <simple name="AutoConf" type="boolean"><value>1</value></simple>
>>>>>>  <simple name="AutoStart" type="boolean"><value>1</value></simple>
>>>>>> 
>>>>>>  <struct name="Properties" type="PropertyBag">
>>>>>> 
>>>>>>    <struct name="Levels" type="PropertyBag">
>>>>>> 
>>>>>>      <simple name="org.orocos.ocl.logging.tests.TestComponent"
>>>>>> 
>>>>>>              type="string"><value>info</value></simple>
>>>>>> 
>>>>>>    </struct>
>>>>>> 
>>>>>>    <struct name="Appenders" type="PropertyBag">
>>>>>> 
>>>>>>      <simple name="org.orocos.ocl.logging.tests.TestComponent"
>>>>>> 
>>>>>>              type="string"><value>AppenderA</value></simple>
>>>>>> 
>>>>>>    </struct>
>>>>>> 
>>>>>>  </struct>
>>>>>> 
>>>>>>  <struct name="Peers" type="PropertyBag">
>>>>>> 
>>>>>>    <simple type="string"><value>AppenderA</value></simple>
>>>>>> 
>>>>>>  </struct>
>>>>>> 
>>>>>> </struct>
>>>>>> 
>>>>>>
>>>>>>
>>>>>> Why is the 'Appenders' struct necessary ? Can't we automatically route
>>>>>> all present categories to the present appenders ? Do I need to list each
>>>>>> and every category in the Appenders struct ?
>>>>> No, you don't need to list all appenders. Our typical usage scenario is
>>>>> - have all components use a category "components." + GetName()
>>>>> - set the default logging level of category "components"
>>>>> - set the logging level of any other category "components.XXX" as
>>>>> appropriate to get more/less logging - attach one appender to category
>>>>> "components" (for us, it is to file)
>>>>>
>>>>> You don't want to route all categories to all appenders. Here's an example
>>>>> why - one appender to file, which all components use (as above)
>>>>> - one appender to another file, which (say) a reporting only component uses
>>>>> - one appender to another file, which (say) a different reporting only
>>>>> component uses
>>>>>
>>>>> If you attached all categories to all/one of the appenders above, you'd mix
>>>>> up all the output. We regularly do the above to separate tracing
>>>>> statements (the "components.XXX" categories), from specific reporting
>>>>> output that we want to be able to post-process to plot, analyse, etc. At
>>>>> the very least, the reporting output is different from standard trace
>>>>> statements. We may also want to send the reporting data elsewhere, and not
>>>>> dump it to file locally (like the "components" appender does).
>>>> Now I understand. We might need an inkscape drawing or two to clear this
>>>> usage scenario up.
>>> Agreed. That should be part of a system example of logging - outlining a basic usage scenario, along with usage documentation (not API doc's).
>>>
>>>>>> A second question is how the deployment file mixes with the log4cpp
>>>>>> config file. For example, the appender's xml properties duplicate what
>>>>>> is in the config file. Which one takes precedence ?
>>>>> For real-time logging, there is no log4cpp config file. It all comes from
>>>>> this XML properties. This is done as there is additional info in our XML
>>>>> than is present in the log4cpp config file (though IIRC it is not as much
>>>>> as we originally though it would be)
>>>> Ok.
>>>>
>>>> I have fixed&tested the logging framework on master and it works. I heard the
>>>> ros people were using some neat GUI to watch the log files. There are many for
>>>> log4j, with which our pattern layout files are compatible but I couldn't find
>>>> any that suits our needs. Suggestions ?
>>> I'd be interested in knowing what they used ... no suggestions here. We face a similar dilemma.
>>>
>>>> We should also start to think about distributing the logging such that one
>>>> appender can catch the logs of the whole application. This would require a
>>>> typekit and transport(s) for the log4cpp event. (longer term feature though).
>>> I'll get right on that ... ;-)
>>>
>>> Seriously, what do you mean "catch the logs of the whole application"? If you attach to the root category and leave the default additivity to true, then everything logged ends up at the root. There are technical reasons we can't attach a real-time logger to the root category right now, but I'm sure they can be overcome. Our approach of using "components.XXX" essentially allows us this already, doesn't it ...?
>>>
>>> I'd be interested in what you think are near-term features/fixes needed, once you've used it a while. I've some ideas of what you might come up with ....
>> I will give you one warning here. We find it a _very delicate_ balance in setting the size of the logging buffer vs the TLSF memory pool size. You can't stay in real-time and let the memory pool grow (hence no MMAP and SBRK in TLSF), and you need enough of a buffer to keep up with the worst case logging event peak load. Our systems can easily generate several thousand logging events a second, and so we have a default buffer size of 1000 (attached to "components" category, so only one buffer), with the appender running periodically at the system control rate (400Hz) and popping up to 50 events a cycle (remember, we're still in v1). This consumes just under a 1MB memory pool by the time the buffer fills up.
>>
>> Take note of that last point! TLSF memory is _not_ deallocated as the logging buffer fills. This is as each logging event in there is not "destroyed" (and hence associated TLSF strings deallocated) until that logging event is overwritten when the buffer rolls around. So for a 1000 element buffer, and say several hundred chars in a logging message (typical for us), you need about a 1MB TLSF memory pool just to store all the strings used when the buffer has been completely used, but is currently "empty" (ie you have used every element in the buffer, but you popped everything out of the buffer and so it is currently empty).
>>
>> I'm interested if anyone has any workarounds to this ... the problem will be slightly different with v2, but it's still essentially a classic consumer, producer problem. And you know you have it wrong when your deployer throws a std::bad_alloc exception on you ... :-(
> Just for my understanding: what kind of messages you output that actually require sending that many strings ?

Trace information to debug new controllers, etc. Think of a compliance controller running at a few hundred Hz, outputting several pieces of data per cycle (and a KDL frame, for example, is 12 numbers at 10+ digit precision ...). Or some of our systems have several interacting components, each running at that same cycle rate. Doesn't take long to get 3 - 4000 messages per second ...

> Wouldn't you be able to send the same information through normal ports (i.e. having "debug" data structures) instead ?

Remember, data structures in v1 implies writing typekits manually, which makes Stephen an unhappy programmer ...
S

Log4cpp support question in 2.x

On 11/30/2010 06:12 PM, Stephen Roderick wrote:
>> Just for my understanding: what kind of messages you output that actually require sending that many strings ?
>
> Trace information to debug new controllers, etc. Think of a compliance controller running at a few hundred Hz, outputting several pieces of data per cycle (and a KDL frame, for example, is 12 numbers at 10+ digit precision ...). Or some of our systems have several interacting components, each running at that same cycle rate. Doesn't take long to get 3 - 4000 messages per second ...
>
>> Wouldn't you be able to send the same information through normal ports (i.e. having "debug" data structures) instead ?
>
> Remember, data structures in v1 implies writing typekits manually, which makes Stephen an unhappy programmer ...
Ah ... yes.

I do forget since oroGen is the first thing I wrote when I arrived at
DFKI :P

Log4cpp support question in 2.x

On Tuesday 30 November 2010 17:19:14 Stephen Roderick wrote:
> On Nov 30, 2010, at 11:09 , Peter Soetens wrote:
> > On Tuesday 30 November 2010 15:23:23 S Roderick wrote:
> >> On Nov 30, 2010, at 09:12 , Peter Soetens wrote:
> >>> I'm testing the log4cpp code in 2.x and I'm trying to understand how it
> >>> works.
> >>>
> >>> The only thing I think I don't understand is this snippet in the
> >>> deployment file (from
> >>> http://orocos.org/wiki/rtt/rtt-20/real-time-logging/using-real-time-
> >>> logging):
> >>>
> >>> 
> >>> 
> >>> <struct name="LoggingService" type="OCL::logging::LoggingService">
> >>> 
> >>>   <struct name="Activity" type="PeriodicActivity">
> >>>   
> >>>     <simple name="Period" type="double"><value>0.5</value></simple>
> >>>     <simple name="Priority" type="short"><value>0</value></simple>
> >>>     <simple name="Scheduler"
> >>> 
> >>> type="string"><value>ORO_SCHED_OTHER</value></simple>
> >>> 
> >>>   </struct>
> >>>   
> >>>   <simple name="AutoConf" type="boolean"><value>1</value></simple>
> >>>   <simple name="AutoStart" type="boolean"><value>1</value></simple>
> >>>   
> >>>   <struct name="Properties" type="PropertyBag">
> >>>   
> >>>     <struct name="Levels" type="PropertyBag">
> >>>     
> >>>       <simple name="org.orocos.ocl.logging.tests.TestComponent"
> >>>       
> >>>               type="string"><value>info</value></simple>
> >>>     
> >>>     </struct>
> >>>     
> >>>     <struct name="Appenders" type="PropertyBag">
> >>>     
> >>>       <simple name="org.orocos.ocl.logging.tests.TestComponent"
> >>>       
> >>>               type="string"><value>AppenderA</value></simple>
> >>>     
> >>>     </struct>
> >>>   
> >>>   </struct>
> >>>   
> >>>   <struct name="Peers" type="PropertyBag">
> >>>   
> >>>     <simple type="string"><value>AppenderA</value></simple>
> >>>   
> >>>   </struct>
> >>> 
> >>> </struct>
> >>> 
> >>>
> >>>
> >>> Why is the 'Appenders' struct necessary ? Can't we automatically route
> >>> all present categories to the present appenders ? Do I need to list
> >>> each and every category in the Appenders struct ?
> >>
> >> No, you don't need to list all appenders. Our typical usage scenario is
> >> - have all components use a category "components." + GetName()
> >> - set the default logging level of category "components"
> >> - set the logging level of any other category "components.XXX" as
> >> appropriate to get more/less logging - attach one appender to category
> >> "components" (for us, it is to file)
> >>
> >> You don't want to route all categories to all appenders. Here's an
> >> example why - one appender to file, which all components use (as above)
> >> - one appender to another file, which (say) a reporting only component
> >> uses - one appender to another file, which (say) a different reporting
> >> only component uses
> >>
> >> If you attached all categories to all/one of the appenders above, you'd
> >> mix up all the output. We regularly do the above to separate tracing
> >> statements (the "components.XXX" categories), from specific reporting
> >> output that we want to be able to post-process to plot, analyse, etc.
> >> At the very least, the reporting output is different from standard
> >> trace statements. We may also want to send the reporting data
> >> elsewhere, and not dump it to file locally (like the "components"
> >> appender does).
> >
> > Now I understand. We might need an inkscape drawing or two to clear this
> > usage scenario up.
>
> Agreed. That should be part of a system example of logging - outlining a
> basic usage scenario, along with usage documentation (not API doc's).
>
> >>> A second question is how the deployment file mixes with the log4cpp
> >>> config file. For example, the appender's xml properties duplicate what
> >>> is in the config file. Which one takes precedence ?
> >>
> >> For real-time logging, there is no log4cpp config file. It all comes
> >> from this XML properties. This is done as there is additional info in
> >> our XML than is present in the log4cpp config file (though IIRC it is
> >> not as much as we originally though it would be)
> >
> > Ok.
> >
> > I have fixed&tested the logging framework on master and it works. I heard
> > the ros people were using some neat GUI to watch the log files. There
> > are many for log4j, with which our pattern layout files are compatible
> > but I couldn't find any that suits our needs. Suggestions ?
>
> I'd be interested in knowing what they used ... no suggestions here. We
> face a similar dilemma.

I've been testing 'logsaw', an eclipse RCP... It kind-of works but throws
dialog boxes in your face.

>
> > We should also start to think about distributing the logging such that
> > one appender can catch the logs of the whole application. This would
> > require a typekit and transport(s) for the log4cpp event. (longer term
> > feature though).
>
> I'll get right on that ... ;-)
>
> Seriously, what do you mean "catch the logs of the whole application"?

The whole *distributed* application. We now only log what is in 1 process.

> If
> you attach to the root category and leave the default additivity to true,
> then everything logged ends up at the root. There are technical reasons we
> can't attach a real-time logger to the root category right now, but I'm
> sure they can be overcome. Our approach of using "components.XXX"
> essentially allows us this already, doesn't it ...?

Yes it does. I wasn't disputing that.

Peter

Log4cpp support question in 2.x

On Nov 30, 2010, at 11:26 , Peter Soetens wrote:

> On Tuesday 30 November 2010 17:19:14 Stephen Roderick wrote:
>> On Nov 30, 2010, at 11:09 , Peter Soetens wrote:
>>> On Tuesday 30 November 2010 15:23:23 S Roderick wrote:
>>>> On Nov 30, 2010, at 09:12 , Peter Soetens wrote:
>>>>> I'm testing the log4cpp code in 2.x and I'm trying to understand how it
>>>>> works.
>>>>>
>>>>> The only thing I think I don't understand is this snippet in the
>>>>> deployment file (from
>>>>> http://orocos.org/wiki/rtt/rtt-20/real-time-logging/using-real-time-
>>>>> logging):
>>>>>
>>>>> 
>>>>> 
>>>>> <struct name="LoggingService" type="OCL::logging::LoggingService">
>>>>> 
>>>>>  <struct name="Activity" type="PeriodicActivity">
>>>>> 
>>>>>    <simple name="Period" type="double"><value>0.5</value></simple>
>>>>>    <simple name="Priority" type="short"><value>0</value></simple>
>>>>>    <simple name="Scheduler"
>>>>> 
>>>>> type="string"><value>ORO_SCHED_OTHER</value></simple>
>>>>> 
>>>>>  </struct>
>>>>> 
>>>>>  <simple name="AutoConf" type="boolean"><value>1</value></simple>
>>>>>  <simple name="AutoStart" type="boolean"><value>1</value></simple>
>>>>> 
>>>>>  <struct name="Properties" type="PropertyBag">
>>>>> 
>>>>>    <struct name="Levels" type="PropertyBag">
>>>>> 
>>>>>      <simple name="org.orocos.ocl.logging.tests.TestComponent"
>>>>> 
>>>>>              type="string"><value>info</value></simple>
>>>>> 
>>>>>    </struct>
>>>>> 
>>>>>    <struct name="Appenders" type="PropertyBag">
>>>>> 
>>>>>      <simple name="org.orocos.ocl.logging.tests.TestComponent"
>>>>> 
>>>>>              type="string"><value>AppenderA</value></simple>
>>>>> 
>>>>>    </struct>
>>>>> 
>>>>>  </struct>
>>>>> 
>>>>>  <struct name="Peers" type="PropertyBag">
>>>>> 
>>>>>    <simple type="string"><value>AppenderA</value></simple>
>>>>> 
>>>>>  </struct>
>>>>> 
>>>>> </struct>
>>>>> 
>>>>>
>>>>>
>>>>> Why is the 'Appenders' struct necessary ? Can't we automatically route
>>>>> all present categories to the present appenders ? Do I need to list
>>>>> each and every category in the Appenders struct ?
>>>>
>>>> No, you don't need to list all appenders. Our typical usage scenario is
>>>> - have all components use a category "components." + GetName()
>>>> - set the default logging level of category "components"
>>>> - set the logging level of any other category "components.XXX" as
>>>> appropriate to get more/less logging - attach one appender to category
>>>> "components" (for us, it is to file)
>>>>
>>>> You don't want to route all categories to all appenders. Here's an
>>>> example why - one appender to file, which all components use (as above)
>>>> - one appender to another file, which (say) a reporting only component
>>>> uses - one appender to another file, which (say) a different reporting
>>>> only component uses
>>>>
>>>> If you attached all categories to all/one of the appenders above, you'd
>>>> mix up all the output. We regularly do the above to separate tracing
>>>> statements (the "components.XXX" categories), from specific reporting
>>>> output that we want to be able to post-process to plot, analyse, etc.
>>>> At the very least, the reporting output is different from standard
>>>> trace statements. We may also want to send the reporting data
>>>> elsewhere, and not dump it to file locally (like the "components"
>>>> appender does).
>>>
>>> Now I understand. We might need an inkscape drawing or two to clear this
>>> usage scenario up.
>>
>> Agreed. That should be part of a system example of logging - outlining a
>> basic usage scenario, along with usage documentation (not API doc's).
>>
>>>>> A second question is how the deployment file mixes with the log4cpp
>>>>> config file. For example, the appender's xml properties duplicate what
>>>>> is in the config file. Which one takes precedence ?
>>>>
>>>> For real-time logging, there is no log4cpp config file. It all comes
>>>> from this XML properties. This is done as there is additional info in
>>>> our XML than is present in the log4cpp config file (though IIRC it is
>>>> not as much as we originally though it would be)
>>>
>>> Ok.
>>>
>>> I have fixed&tested the logging framework on master and it works. I heard
>>> the ros people were using some neat GUI to watch the log files. There
>>> are many for log4j, with which our pattern layout files are compatible
>>> but I couldn't find any that suits our needs. Suggestions ?
>>
>> I'd be interested in knowing what they used ... no suggestions here. We
>> face a similar dilemma.
>
> I've been testing 'logsaw', an eclipse RCP... It kind-of works but throws
> dialog boxes in your face.

Not so much, on the "in your face" approach ... but thanks, will check it out.

>>>
>>> We should also start to think about distributing the logging such that
>>> one appender can catch the logs of the whole application. This would
>>> require a typekit and transport(s) for the log4cpp event. (longer term
>>> feature though).
>>
>> I'll get right on that ... ;-)
>>
>> Seriously, what do you mean "catch the logs of the whole application"?
>
> The whole *distributed* application. We now only log what is in 1 process.

Understood. Makes sense, and we can do that now I think if you use an appender(s) that knows to send events to one central place (if that is the solution you go for).

Currently the design doesn't support multiple appenders per category, which it should. This would allow for logging to local file _and_ sending to somewhere central (if you wanted that).
S

Log4cpp support question in 2.x

On Tuesday 30 November 2010 17:30:44 Stephen Roderick wrote:
> On Nov 30, 2010, at 11:26 , Peter Soetens wrote:
> > On Tuesday 30 November 2010 17:19:14 Stephen Roderick wrote:
> >> On Nov 30, 2010, at 11:09 , Peter Soetens wrote:
...
> >>
> >> Seriously, what do you mean "catch the logs of the whole application"?
> >
> > The whole *distributed* application. We now only log what is in 1
> > process.
>
> Understood. Makes sense, and we can do that now I think if you use an
> appender(s) that knows to send events to one central place (if that is the
> solution you go for).

I was thinking of routing all the output ports of the categories to a remote
appender's input port. Remember that v2.x ports are always real-time, even
when they go over CORBA (only the delivery itself is not real-time in that
case).

>
> Currently the design doesn't support multiple appenders per category, which
> it should. This would allow for logging to local file _and_ sending to
> somewhere central (if you wanted that).

In v2, every connection has its own dedicated buffer, so we can do both local
and remote appenders, ie, multiple appenders per category.

I see the appenders more as 'service plugins' for the LoggingService instead
of individual components. This would simplify the setup work / xml structure a
bit. On the other hand, having appenders as components gives you one thread
for each appender, which is a big advantage since they are doing (networked)
IO. So I'm not changing anything yet.

I have fixed the buffer size to '100', with non-periodic appenders (event
driven). We need to configure this with one of the properties of the
LoggingService component, for example, by providing the user a ConnPolicy
property he can fill in.

Peter

Log4cpp support question in 2.x

On Nov 30, 2010, at 15:13 , Peter Soetens wrote:

> On Tuesday 30 November 2010 17:30:44 Stephen Roderick wrote:
>> On Nov 30, 2010, at 11:26 , Peter Soetens wrote:
>>> On Tuesday 30 November 2010 17:19:14 Stephen Roderick wrote:
>>>> On Nov 30, 2010, at 11:09 , Peter Soetens wrote:
> ...
>>>>
>>>> Seriously, what do you mean "catch the logs of the whole application"?
>>>
>>> The whole *distributed* application. We now only log what is in 1
>>> process.
>>
>> Understood. Makes sense, and we can do that now I think if you use an
>> appender(s) that knows to send events to one central place (if that is the
>> solution you go for).
>
> I was thinking of routing all the output ports of the categories to a remote
> appender's input port. Remember that v2.x ports are always real-time, even
> when they go over CORBA (only the delivery itself is not real-time in that
> case).

I think I tried something like this in v1 and it blew up on me. Might have been operator error though ...

>> Currently the design doesn't support multiple appenders per category, which
>> it should. This would allow for logging to local file _and_ sending to
>> somewhere central (if you wanted that).
>
> In v2, every connection has its own dedicated buffer, so we can do both local
> and remote appenders, ie, multiple appenders per category.

It's just the data management part of this, per category, that is missing. Not a big deal.

> I see the appenders more as 'service plugins' for the LoggingService instead
> of individual components. This would simplify the setup work / xml structure a
> bit. On the other hand, having appenders as components gives you one thread
> for each appender, which is a big advantage since they are doing (networked)
> IO. So I'm not changing anything yet.

How do you attach an appender to a category then? And do it in a thread-safe fashion?

> I have fixed the buffer size to '100', with non-periodic appenders (event
> driven). We need to configure this with one of the properties of the
> LoggingService component, for example, by providing the user a ConnPolicy
> property he can fill in.

Whatever you want here is fine with me, just realize, I won't be testing any of it until we upgrade to v2. And that isn't happening for some months to come ...

Being able to configure some aspects of the Logging at runtime would be very useful, must admit.
S