You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by Mark Claassen <ma...@gmail.com> on 2012/03/27 15:30:06 UTC
Re: AccessLogValve enhancement
Ok. I am back working on this again.
>From the previous comments, I am not sure my efforts are going in the right
direction. However, I have a working implementation that uses the standard
logging mechanism now, while addressing some of the previous concerns.
I did a quick performance test, and it is true that the default mechanism
is quite a bit faster than the standard JULI logger. For this test, I just
modified the source code to write each log message 1000 times. The first
set of timings (in millis) is from the current AccessLogValve, and the
second set is using JULI.
AccessLogValve Elapsed Time: 8
AccessLogValve Elapsed Time: 19
AccessLogValve Elapsed Time: 63
AccessLogValve Elapsed Time: 6
AccessLogValve Elapsed Time: 7
AccessLogValve Elapsed Time: 8
INFO: AccessLogValve Elapsed Time: 830
INFO: AccessLogValve Elapsed Time: 1122
INFO: AccessLogValve Elapsed Time: 451
INFO: AccessLogValve Elapsed Time: 531
INFO: AccessLogValve Elapsed Time: 764
INFO: AccessLogValve Elapsed Time: 347
Granted, this certainly falls into the "Contrived micro-benchmark" realm.
A real test would involve lots of threads each writing very little. Also,
each thread would be doing a lot of other things, making the time spent in
the access logger less significant. However, even in the worse case, it
still only took a millis to write one message.
Honing my test case to test the speed of 1 single message (not just the
write, but the whole process of creating and then writing the message), I
got that it takes between 0 - 1 millis in the first case, and 0 - 2 millis
with JULI. Most messages took 1 millis for each. (I have a pretty old
machine I am testing on now.) I didn't test the speed of the file rolling
and such. Also, I have no idea which would perform better under a heavy
load.
I don't really have the facilities to do a realistic performance test.
However, I think something can be gleaned from the above results. Does
anyone have any advice or suggestions on what direction I should go? My
main goal is to have automatic deletion of old log files. This is
something I would imagine others would like as well, so I thought I would
present here instead of just doing something myself. I certainly do not
what to make anything more complicated to use / configure than it has to be.
I am considering 5 options:
1) I can add my "outputLoggerName" attribute, which will switch the valve
to use the JULI logger
2) I can create some sort of AccessLogWriter that the AccessLogValves will
delegate their writing to
- With 2 implementations, one being the current method and one being a
JULI implementation
- Potentially removing one in the future if performance is not an issue.
3) I can just add an attribute to the AccessLogValves to automatically
delete older files
4) I can just make my own private subclass to do what I want, and leave the
tomcat code unaltered
5) Scrap the current file writing implementation in the AccessLogValve and
go straight JULI
I would welcome any advice.
Thanks,
Mark
RE: AccessLogValve enhancement
Posted by Mark Claassen <ma...@donnell.com>.
Ok, I have some more time to work on this.
> Though the tricky part is to find out what to delete.
I was just using anything that started with the 'prefix'. This doesn't seem too bad to me since if you want to delete old files,
you just need to pick a good prefix. In my test case, I set the file format to have the minute and second in the file name. The
rolling worked perfectly.
> it is possible to use it to generate different directories for different dates.
This does put a damper on things. The valve could easily remember previous files, but files from previous executions would be
forgotten, which doesn't seem right to me. Reliably getting a list of files to delete in all situations seems like a pretty complex
task. However, if we force the idea of a good prefix selection, something similar could be done to what is in the patch code
already, it would just have to be recursive.
Then again, this is starting to have a few too many caveats. I had wondered about removing old files for a while, and had seen
other people ask this as well, so I thought a simple solution might be possible. However, now I am rethinking this.
Coming back to allowing the use of a standard logger. In my mini-benchmarks, it didn't seems like it made much of a difference time
wise; the time spent in the logger took between 1-2 millis on my server. This seems like it would be dwarfed by the time to
actually create and deliver the response.
Still, maybe this is a problem that most people have solved their own way already and people don't want to have solved again. I
don't want to make anything more complicated or harder to use. I can continue to work on this, but I am losing confidence that I
can come up with something that will be worth of adoption.
Comments?
-----Original Message-----
From: Konstantin Kolinko [mailto:knst.kolinko@gmail.com]
Sent: Thursday, March 29, 2012 4:44 PM
To: Tomcat Developers List
Subject: Re: AccessLogValve enhancement
2012/3/29 Mark Claassen <ma...@donnell.com>:
> After thinking about this some more, and deliberating on the subtle
> issues that were coming up, I decided to reduce the scope of my
> enhancement. I still like the idea of using a standard logger for this logging, but for now I thought I would focus more on my
specific problem. I wrote more about this in the issue.
> https://issues.apache.org/bugzilla/show_bug.cgi?id=52688
>
> Is this something that could be adopted in a future 7.0 release?
>
To delete or otherwise rotate (move, compress, e-mail, etc.) old files
- I think I would write a <Listener>,
or set up a shell script in cron.
When logger starts to write a new file it has to do so quickly, because it happens in a synchronized block.
Deleting is possible, because it is a quick operation as well. Though the tricky part is to find out what to delete. The files are
named by date and they are not created unless necessary. The date format is configurable. E.g. it is possible to use it to generate
different directories for different dates.
IIRC JRE's java.util.logging.FileHandler can be configured to keep n old files, but it uses different naming scheme.
Best regards,
Konstantin Kolinko
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org For additional commands, e-mail: dev-help@tomcat.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: AccessLogValve enhancement
Posted by Konstantin Kolinko <kn...@gmail.com>.
2012/3/29 Mark Claassen <ma...@donnell.com>:
> After thinking about this some more, and deliberating on the subtle issues that were coming up, I decided to reduce the scope of my
> enhancement. I still like the idea of using a standard logger for this logging, but for now I thought I would focus more on my
> specific problem. I wrote more about this in the issue.
> https://issues.apache.org/bugzilla/show_bug.cgi?id=52688
>
> Is this something that could be adopted in a future 7.0 release?
>
To delete or otherwise rotate (move, compress, e-mail, etc.) old files
- I think I would write a <Listener>,
or set up a shell script in cron.
When logger starts to write a new file it has to do so quickly,
because it happens in a synchronized block.
Deleting is possible, because it is a quick operation as well. Though
the tricky part is to find out what to delete. The files are named by
date and they are not created unless necessary. The date format is
configurable. E.g. it is possible to use it to generate different
directories for different dates.
IIRC JRE's java.util.logging.FileHandler can be configured to keep n
old files, but it uses different naming scheme.
Best regards,
Konstantin Kolinko
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
RE: AccessLogValve enhancement
Posted by Mark Claassen <ma...@donnell.com>.
After thinking about this some more, and deliberating on the subtle issues that were coming up, I decided to reduce the scope of my
enhancement. I still like the idea of using a standard logger for this logging, but for now I thought I would focus more on my
specific problem. I wrote more about this in the issue.
https://issues.apache.org/bugzilla/show_bug.cgi?id=52688
Is this something that could be adopted in a future 7.0 release?
-----Original Message-----
From: Mark Claassen [mailto:markclaassenx@gmail.com]
Sent: Tuesday, March 27, 2012 11:17 AM
To: Tomcat Developers List
Subject: Re: AccessLogValve enhancement
That improved my timings considerably. Instead of between 300 - 1100, they are between 100 - 330. However, they are still slower
than the current mechanism. (Although, I am not sure how much this benchmark is worth,
anyway.) I would imagine that the Async logger has lots of optimizations in it to handle the threading aspects; I wonder if it
would be better under load than the current mechanism?
This info is not going to catalina.out.
Other comments? Suggestions for direction:
1) I can add my "outputLoggerName" attribute, which will switch the valve to use the JULI logger
2) I can create some sort of AccessLogWriter that the AccessLogValves will delegate their writing to
- With 2 implementations, one being the current method and one being a JULI implementation
- Potentially removing one in the future if performance is not an issue.
3) I can just add an attribute to the AccessLogValves to automatically delete older files
4) I can just make my own private subclass to do what I want, and leave the tomcat code unaltered
5) Scrap the current file writing implementation in the AccessLogValve and go straight JULI
I would welcome any advice.
Mark
On Tue, Mar 27, 2012 at 9:46 AM, Konstantin Kolinko
<kn...@gmail.com>wrote:
> 2012/3/27 Mark Claassen <ma...@gmail.com>:
> >
> > I did a quick performance test, and it is true that the default
> > mechanism is quite a bit faster than the standard JULI logger. For
> > this test, I
> just
> > modified the source code to write each log message 1000 times. The
> > first set of timings (in millis) is from the current AccessLogValve,
> > and the second set is using JULI.
> >
> > AccessLogValve Elapsed Time: 8
> > AccessLogValve Elapsed Time: 19
> > AccessLogValve Elapsed Time: 63
> > AccessLogValve Elapsed Time: 6
> > AccessLogValve Elapsed Time: 7
> > AccessLogValve Elapsed Time: 8
> >
> > INFO: AccessLogValve Elapsed Time: 830
> > INFO: AccessLogValve Elapsed Time: 1122
> > INFO: AccessLogValve Elapsed Time: 451
> > INFO: AccessLogValve Elapsed Time: 531
> > INFO: AccessLogValve Elapsed Time: 764
> > INFO: AccessLogValve Elapsed Time: 347
> >
>
> 1. Try to configure JULI with org.apache.juli.AsyncFileHandler.
> It might show better numbers.
>
> (The usual FileHandler by default performs flush() after each log message).
>
> 2. Is the same printed to console? If yes then remove ConsoleHandler.
>
> Best regards,
> Konstantin Kolinko
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org For
> additional commands, e-mail: dev-help@tomcat.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: AccessLogValve enhancement
Posted by Mark Claassen <ma...@gmail.com>.
That improved my timings considerably. Instead of between 300 - 1100, they
are between 100 - 330. However, they are still slower than the current
mechanism. (Although, I am not sure how much this benchmark is worth,
anyway.) I would imagine that the Async logger has lots of optimizations
in it to handle the threading aspects; I wonder if it would be better under
load than the current mechanism?
This info is not going to catalina.out.
Other comments? Suggestions for direction:
1) I can add my "outputLoggerName" attribute, which will switch the valve
to use the JULI logger
2) I can create some sort of AccessLogWriter that the AccessLogValves will
delegate their writing to
- With 2 implementations, one being the current method and one being a
JULI implementation
- Potentially removing one in the future if performance is not an issue.
3) I can just add an attribute to the AccessLogValves to automatically
delete older files
4) I can just make my own private subclass to do what I want, and leave the
tomcat code unaltered
5) Scrap the current file writing implementation in the AccessLogValve and
go straight JULI
I would welcome any advice.
Mark
On Tue, Mar 27, 2012 at 9:46 AM, Konstantin Kolinko
<kn...@gmail.com>wrote:
> 2012/3/27 Mark Claassen <ma...@gmail.com>:
> >
> > I did a quick performance test, and it is true that the default mechanism
> > is quite a bit faster than the standard JULI logger. For this test, I
> just
> > modified the source code to write each log message 1000 times. The first
> > set of timings (in millis) is from the current AccessLogValve, and the
> > second set is using JULI.
> >
> > AccessLogValve Elapsed Time: 8
> > AccessLogValve Elapsed Time: 19
> > AccessLogValve Elapsed Time: 63
> > AccessLogValve Elapsed Time: 6
> > AccessLogValve Elapsed Time: 7
> > AccessLogValve Elapsed Time: 8
> >
> > INFO: AccessLogValve Elapsed Time: 830
> > INFO: AccessLogValve Elapsed Time: 1122
> > INFO: AccessLogValve Elapsed Time: 451
> > INFO: AccessLogValve Elapsed Time: 531
> > INFO: AccessLogValve Elapsed Time: 764
> > INFO: AccessLogValve Elapsed Time: 347
> >
>
> 1. Try to configure JULI with org.apache.juli.AsyncFileHandler.
> It might show better numbers.
>
> (The usual FileHandler by default performs flush() after each log message).
>
> 2. Is the same printed to console? If yes then remove ConsoleHandler.
>
> Best regards,
> Konstantin Kolinko
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: dev-help@tomcat.apache.org
>
>
Re: AccessLogValve enhancement
Posted by Konstantin Kolinko <kn...@gmail.com>.
2012/3/27 Mark Claassen <ma...@gmail.com>:
>
> I did a quick performance test, and it is true that the default mechanism
> is quite a bit faster than the standard JULI logger. For this test, I just
> modified the source code to write each log message 1000 times. The first
> set of timings (in millis) is from the current AccessLogValve, and the
> second set is using JULI.
>
> AccessLogValve Elapsed Time: 8
> AccessLogValve Elapsed Time: 19
> AccessLogValve Elapsed Time: 63
> AccessLogValve Elapsed Time: 6
> AccessLogValve Elapsed Time: 7
> AccessLogValve Elapsed Time: 8
>
> INFO: AccessLogValve Elapsed Time: 830
> INFO: AccessLogValve Elapsed Time: 1122
> INFO: AccessLogValve Elapsed Time: 451
> INFO: AccessLogValve Elapsed Time: 531
> INFO: AccessLogValve Elapsed Time: 764
> INFO: AccessLogValve Elapsed Time: 347
>
1. Try to configure JULI with org.apache.juli.AsyncFileHandler.
It might show better numbers.
(The usual FileHandler by default performs flush() after each log message).
2. Is the same printed to console? If yes then remove ConsoleHandler.
Best regards,
Konstantin Kolinko
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org