nlog4j problems under load

[Norval Hope <nr...@gmail.com>]

Hi,

I am in the final stages of preparing a release that builds on top of
ApacheDS, and consequently must use an slf4j compliant logging library so I
used nlog4j 1.2.25 (as AD does).

I have a requirement to have separate appenders created dynamically at
runtime and adopted the approach shown in the small attached test/config
files, which was:
  1. to have a template appender copied every time a new appender is
required
  2. have a stub logger used only so that I can discover the template
appender when I need it (as the template appender is in this loggers
appender list in the .properties config file)
  3. to dynamically create a logger intended to send output to the
dynamically created appender only (additivity is false and no other logger
knows about each particular appender instance).

This all works fine under normal load, but noted some problems under heavy
logging load so I wrote the stand alone test to investigate.

Running the test with 2 threads and no delay ("java nlog4jtest.NLog4jTest 2
0") causing problems immediately on a dual core laptop running windows xp:
  1. log messages from one logger appear against appenders to which they are
not linked
  2. partial log messages are evident, where headers are missing etc.
Using a delay of 5 milliseconds improved the situation but still both
problems were evident.

On a single cpu windows box running xp, "java nlog4jtest.NLog4jTest 10 0"
also evidenced both problems too.

I know I'm making use of a bespoke approach here, so I'm hoping I'm doing
something wrong in my implementation or breaking some contract I'm not aware
of. I basically can't ship with logging in this state and can't migrate to
logback due to LGPL license, which is a problem for the ApacheDS
project too.

Any expert advice about alternative implementation approaches or how to best
approach debugging would be greatly appreciated.

Many Thanks,
Norval

Re: nlog4j problems under load

[Norval Hope <nr...@gmail.com>]

Ok, you were right - the shared Layout was the root of both evils. As they
say, never argue with the master!

I am attaching the reworked testcase which now works in case it's of any
interest to anyone. I was also hoping someone more knowledgeable may wade in
and tell me if there is a better way to achieve what I want without having
to clone/substitute values into the logging property settings (I ended up
reusing the Layout illegally originally because I couldn't work out what I
should do instead - all the interesting lower-level methods seemed to be
package private).

But at any rate, everything is working seemlessly now so thanks very much
for your help ... and any further advice if there are improvements you
suggest I make.

Re: nlog4j problems under load

[Norval Hope <nr...@gmail.com>]

Ok thanks. I'll try to work out how to clone the layout then and retest.

My gut feeling is that would explain the half-messages etc but I'm not
certain that explains why messages end up in the wrong log files (i.e. are
seemingly routed to the wrong appenders). At any rate I'll try and fix that
and see how I go from there.

Thanks again.

Re: nlog4j problems under load

[Ceki Gulcu <ce...@qos.ch>]

Norval,

It looks like you are sharing layout between various appender instances. Layouts 
are not meant to be shared. There should be a distinct layout instance for each 
appender. By the way, the usage problem is not NLOG4J specific, it would also 
occur under log4j or logback for that matter.

HTH,

Norval Hope wrote:
> Hi,
>  
> I am in the final stages of preparing a release that builds on top of 
> ApacheDS, and consequently must use an slf4j compliant logging library 
> so I used nlog4j 1.2.25 (as AD does).
>  
> I have a requirement to have separate appenders created dynamically at 
> runtime and adopted the approach shown in the small attached test/config 
> files, which was:
>   1. to have a template appender copied every time a new appender is 
> required
>   2. have a stub logger used only so that I can discover the template 
> appender when I need it (as the template appender is in this loggers 
> appender list in the .properties config file)
>   3. to dynamically create a logger intended to send output to the 
> dynamically created appender only (additivity is false and no other 
> logger knows about each particular appender instance).
>  
> This all works fine under normal load, but noted some problems under 
> heavy logging load so I wrote the stand alone test to investigate.
>  
> Running the test with 2 threads and no delay ("java 
> nlog4jtest.NLog4jTest 2 0") causing problems immediately on a dual core 
> laptop running windows xp:
>   1. log messages from one logger appear against appenders to which they 
> are not linked
>   2. partial log messages are evident, where headers are missing etc.
> Using a delay of 5 milliseconds improved the situation but still both 
> problems were evident.
>  
> On a single cpu windows box running xp, "java nlog4jtest.NLog4jTest 10 
> 0" also evidenced both problems too.
>  
> I know I'm making use of a bespoke approach here, so I'm hoping I'm 
> doing something wrong in my implementation or breaking some contract I'm 
> not aware of. I basically can't ship with logging in this state and 
> can't migrate to logback due to LGPL license, which is a problem for the 
> ApacheDS project too.
>  
> Any expert advice about alternative implementation approaches or how to 
> best approach debugging would be greatly appreciated.
>  
> Many Thanks,
> Norval

-- 
Ceki Gülcü
Logback: The reliable, generic, fast and flexible logging framework for Java.
http://logback.qos.ch

Re: nlog4j problems under load

[Norval Hope <nr...@gmail.com>]

Hi Emmanuel,

Sorry for my long absence from the list, have been working very hard towards
an imminent release for a number of months now and have had to get extremely
focussed on my maximum priorities.

One todo I have over the next few months (or should I say hopefully some
time this year) is to sync up my stuff with the latest ApacheDS 1.5 code,
which I delayed as I'll have to rework all of my dynamic schema stuff (and I
think there was another repository restructure too - which will make things
difficult too). Hope it's all been going well!

Re LogBack, I haven't investigated as it isn't a workable option for me due
to LGPL license - which I presume is also blocking its use by you guys too.
Hence I thought I'd appeal to the experts (I doubt there is a bigger logging
expert in the Java world then Ceki!), and failing that look into debugging
and fixing myself. I cc'd the ApacheDS dev list just because I thought the
issue may be of interest as another user of nlog4j - even though my
particular requirements on the logging aren't key to the current codebase
directly.

Thanks,
Norval

Re: nlog4j problems under load

[Emmanuel Lecharny <el...@gmail.com>]

Hi Norval,

good to see that you are back !

I hope Ceki can help you on this, because I'm afraid we are not
exactly Log4j specialists on Directory project... What about Logback,
does it behave the same ?

Emmanuel

On 6/29/07, Norval Hope <nr...@gmail.com> wrote:
> Hi,
>
> I am in the final stages of preparing a release that builds on top of
> ApacheDS, and consequently must use an slf4j compliant logging library so I
> used nlog4j 1.2.25 (as AD does).
>
> I have a requirement to have separate appenders created dynamically at
> runtime and adopted the approach shown in the small attached test/config
> files, which was:
>   1. to have a template appender copied every time a new appender is
> required
>   2. have a stub logger used only so that I can discover the template
> appender when I need it (as the template appender is in this loggers
> appender list in the .properties config file)
>   3. to dynamically create a logger intended to send output to the
> dynamically created appender only (additivity is false and no other logger
> knows about each particular appender instance).
>
> This all works fine under normal load, but noted some problems under heavy
> logging load so I wrote the stand alone test to investigate.
>
> Running the test with 2 threads and no delay ("java nlog4jtest.NLog4jTest 2
> 0") causing problems immediately on a dual core laptop running windows xp:
>   1. log messages from one logger appear against appenders to which they are
> not linked
>   2. partial log messages are evident, where headers are missing etc.
> Using a delay of 5 milliseconds improved the situation but still both
> problems were evident.
>
> On a single cpu windows box running xp, "java nlog4jtest.NLog4jTest 10 0"
> also evidenced both problems too.
>
> I know I'm making use of a bespoke approach here, so I'm hoping I'm doing
> something wrong in my implementation or breaking some contract I'm not aware
> of. I basically can't ship with logging in this state and can't migrate to
> logback due to LGPL license, which is a problem for the ApacheDS project
> too.
>
> Any expert advice about alternative implementation approaches or how to best
> approach debugging would be greatly appreciated.
>
> Many Thanks,
> Norval
>


-- 
Regards,
Cordialement,
Emmanuel Lécharny
www.iktek.com