Performance concerns logging to multiple files

[Isabel Beltran <ib...@hotmail.com>]

In our project, a Web application running on WAS, we decided to use log4J to 
record statistics and performance data. We log to multiple files in a 
per-user basis. We have a logger per user and
we add a fileAppender programatically to that logger when every user logs-in 
to the application.

This approach is working quite well. The application have a need to control 
file closing when the user logs-off as the number of concurrent users is 
half the total registered users.  We decided to close the file when our 
already coded log4J wrapper class gets notified (by means of an 
HttpSessionBindingListener) when session gets invalidated or expire. But, as 
the methods closeFile and reset in FileAppender are protected, we thought 
that maybe we were not using Log4j properly.

I began to browse the discussion list in search of useful information 
relevant to what we are trying to achieve.

Now, I have serious doubts about our first approach. We *don´t* have the 
requirement to use an statistic file per user. We just decided to go that 
way because as we are not resource constraint but performance is indeed a 
big issue, we thought user requests will have better performance writing to 
multiple statistic files than to one just file, which sometimes could be a 
bottleneck.

Paul Smith in one of the threads recommended to use MDC to log the 
information in just one file and then filter it easily. Most of the 
recommendations goes that way. Could someone advice us if this is the right 
choice when we have 5000 registered users and half the number of concurrent 
users. Is this the best approach in terms of performance reasons?. In that 
case, Paul, could you please show me how to do it?.

Also, if we go on logging to multiple files, Which approach is best, have 
one logger and one fileAppender per user, as we have now, or just one logger 
and as many fileAppenders as users?. I also have read some recommendations 
going this last way.
I am not sure about it in terms of resources and performance. What takes 
more resources 2500 loggers or every user append going to the same unique 
logger, and then the whole bunch of fileAppenders get notified and filter 
the logging event?

Another concern we have, due to performance reasons could it be a good idea 
to log remotely through the socketAppender?. Has anybody benchmark it?.

Any help would be appreciated, thanks in advance,

Isabel



---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org

Re: Performance concerns logging to multiple files

[Paul Smith <ps...@aconex.com>]

>
> Paul Smith in one of the threads recommended to use MDC to log the  
> information in just one file and then filter it easily. Most of the  
> recommendations goes that way. Could someone advice us if this is  
> the right choice when we have 5000 registered users and half the  
> number of concurrent users. Is this the best approach in terms of  
> performance reasons?. In that case, Paul, could you please show me  
> how to do it?.

I'm exceptionally busy, so I apologise for the short response.  Here  
it is in psuedo-code (copied from our application, snipped for  
brevity to highlight the point).  All our servlets extend from one  
base class, so this service method is the first entry point for all  
requests on our web-application:

snippet from our log4j configuration file:

....
     <appender name="File"  
class="org.apache.log4j.DailyRollingFileAppender">
         <param name="File" value="${catalina.home}/logs/lhr.log" />
         <param name="Append" value="true" />
         <param name="DatePattern" value="'.'yyyy-MM-dd" />
         <layout class="org.apache.log4j.PatternLayout">
             <param name="ConversionPattern"
                 value="[%d{ISO8601} %-5p][%20.20c][%t][%X{IPAddress}] 
[%X{UserID}] %m%n"
                 />
         </layout>
     </appender>

You notice that in the pattern we output 2 MDC vars, IPAddress and  
UserID.  Here is how they are set & cleared:

     protected void service(HttpServletRequest req,  
HttpServletResponse resp) {
	.............
         MDC.remove("UserID");
         MDC.remove("IPAddress");
         MDC.put("IPAddress", req.getRemoteAddr());
         ...
         HttpSession session = req.getSession();
...
		Integer userId = (Integer) session.getAttribute("UserId");	
        MDC.put("UserID", userId);

     	try {
			..... // do web request
		}...


That's it.  All request and all it's associated logging events from  
any class touched as part of this request are now 'tagged' with the  
UserID and IPAddress. All the other classes that do any logging do  
not need to worry about context, because the current Thread has been  
'tagged' by the MDC.

It looks like this in the logs:

[2005-12-16 08:57:31,310 INFO ][he.AconexCacheLoader][http-8080- 
Processor4][192.168.0.242][28] get(fqn): fqn=/Preference/110,  
operation took 255ms

 From this I can see the IP address and the userid that generated  
this single log statement. If I want to correlate all logging events  
for a userid or IP Address range, one can just grep the logs (or use  
Chainsaw to filter)

I hope that helps,that's as much as I have time for right at this  
moment (working on 5 hours sleep at the moment).

Paul Smith