You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by Elias Ross <er...@m-qube.com> on 2005/01/20 17:48:51 UTC
Concurrency Appender Proposal
I am proposing creating a "shadow" package called
org.apache.log4j.concurrent that contains many of the same classes, such
as AppenderSkeleton, FileAppender, etc. but allows multiple threads to
append at the same time. Most of the inspiration for such a project
comes from work done by the java.util.concurrent team, who created
concurrent implementations for Map, List, etc., that created minimally
locked data-structures.
"Why is such a package needed?"
In today's world of hyper-threaded, multi-processor application servers,
inevitably there is a need (like any application server library) for a
scalable logging solution.
"Okay, but it's not like you're logging 100 times a second..."
Not necessarily. When diagnosing problems in a running server, one
often has to turn on and turn off logging, hopefully without disrupting
processing that is occurring on a live system.
It would also be a good basis for appenders that could greatly benefit
from concurrency, such as SNMP, JDBC, JMS appenders. There wouldn't be
any need to lock these as each thread. As each log event is relatively
expensive, concurrency would _greatly_ improve these classes, as one
thread would not need to hold a lock for 10-30 milliseconds, for
example.
Often times, a large amount of logging occurs during outage situations.
When a database hiccups, or a Servlet class fails (due to bugs), the
server tries to log 1000 times a second, causing unrelated threads to
block as well. Could log4j bring your server to its knees?
"Why not just use the Async appender?"
This would improve matters, but it does not allow for synchronous
logging of events or take advantage of multi-processors. A possible fix
for the latter problem would be creating a thread pool, which would have
to be tuned for the installation.
"Why not fix the existing appender classes?"
Unfortunately, there would be a lot of compatibility problems. Anybody
who extended an existing appender class in their own code expects
locking to behave in a particular way. (This is the "Inheritance breaks
encapsulation" anti-pattern.)
"Bloat!"
Probably wouldn't require more than a 1000 lines of code for the core
part. Obviously, it's more of a chore to get 1000 lines of such code
correct, but not impossible.
"Nobody would use it. Nobody cares. Why not create it yourself?"
I'm somebody, aren't I? I care.
I think the log4j project and its users would benefit with an integrated
solution, rather than one that comes from an unknown source such as
myself. Plus, log4j could itself leverage such a library.
In addition, it'd be another simple reason log4j beats
java.util.logging.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Concurrency Appender Proposal
Posted by Elias Ross <er...@m-qube.com>.
On Sat, 2005-01-22 at 10:41, Ceki Gülcü wrote:
> Hi Elias,
>
> I had a cursory look at the code. It looks pretty good.
>
> Although it may be my suggestion to begin with, comparing
...
That's what you asked for from your original...
You can run the other test you want.
Anyway, if you wanted results, they're are pretty much the same.
They're so much variation as it's sort of up the the whim of the thread
scheduler who wins.
[java] Appender class org.apache.log4j.concurrent.FileAppender
[java] Took 1630ms for 1000 logs * threads 5
[java] Appender class org.apache.log4j.FileAppender
[java] Took 1283ms for 1000 logs * threads 5
[java] Appender class org.apache.log4j.concurrent.FileAppender
[java] Took 1336ms for 1000 logs * threads 5
[java] Appender class org.apache.log4j.FileAppender
[java] Took 1566ms for 1000 logs * threads 5
[java] Appender class org.apache.log4j.concurrent.FileAppender
[java] Took 1183ms for 1000 logs * threads 5
[java] Appender class org.apache.log4j.FileAppender
[java] Took 1196ms for 1000 logs * threads 5
Not impressed? On a two CPU machine things look a little better for the
concurrent version:
[java] Appender class org.apache.log4j.FileAppender
[java] Took 24983ms for 100000 logs * threads 4
[java] Appender class org.apache.log4j.concurrent.FileAppender
[java] Took 23906ms for 100000 logs * threads 4
[java] Appender class org.apache.log4j.FileAppender
[java] Took 24613ms for 100000 logs * threads 4
[java] Appender class org.apache.log4j.concurrent.FileAppender
[java] Took 23080ms for 100000 logs * threads 4
[java] Appender class org.apache.log4j.FileAppender
[java] Took 24668ms for 100000 logs * threads 4
[java] Appender class org.apache.log4j.concurrent.FileAppender
[java] Took 23827ms for 100000 logs * threads 4
[java] Appender class org.apache.log4j.FileAppender
[java] Took 27243ms for 100000 logs * threads 4
[java] Appender class org.apache.log4j.concurrent.FileAppender
[java] Took 23172ms for 100000 logs * threads 4
That's about 10%, though what is designed to be used for instead is SNMP
traps, database logging, etc. As I said, most of the CPU is spent
formatting the message.
> Since the existing Layouts recycle the string buffer, in the single
> threaded case, I would expect the existing code to outperform your version
> which creates a new CharArrayWriter with each conversion. You seem to
> indicate that the performances are more or less on par.
I think they're par, if not better. A modern JVM is designed with lots
of temporary objects in mind.
Actually, reuse seems to be 10-15% worse. Feel free to play around with
the test I attached.
For new StringBuffer() 231
For reuse StringBuffer() 211
For new StringBuffer() 175
For reuse StringBuffer() 209
For new StringBuffer() 191
For reuse StringBuffer() 205
For new StringBuffer() 176
For reuse StringBuffer() 201
For new StringBuffer() 173
For reuse StringBuffer() 219
For new StringBuffer() 174
For reuse StringBuffer() 194
For new StringBuffer() 174
For reuse StringBuffer() 204
For new StringBuffer() 176
For reuse StringBuffer() 204
For new StringBuffer() 179
For reuse StringBuffer() 201
For new StringBuffer() 173
For reuse StringBuffer() 205
Re: Concurrency Appender Proposal
Posted by Curt Arnold <ca...@apache.org>.
On Jan 22, 2005, at 12:41 PM, Ceki Gülcü wrote:
> Do you have numbers comparing
>
> org.apache.log4j.WriterAppender wa = new
> org.apache.log4j.WriterAppender();
> wa.setWriter(w);
> new PerformanceTest(wa);
>
> with
>
> org.apache.log4j.concurrent.WriterAppender wa2 = new
> org.apache.log4j.concurrent.WriterAppender();
> wa2.setWriter(w);
> new PerformanceTest(wa2);
>
>
> Since the existing Layouts recycle the string buffer, in the single
> threaded case, I would expect the existing code to outperform your
> version which creates a new CharArrayWriter with each conversion. You
> seem to indicate that the performances are more or less on par.
>
I'm a little occupied with other things right now to contribute at the
moment, but thought I would throw a couple things out. I had hoped to
fabricate a reasonable multithreaded performance test for use in
addressing the sequenceCount issue. It seems that such a performance
test would be useful, if not essential, to evaluate these changes.
Layout.format(LoggingEvent) is not thread-safe due to the use of the
charArrayWriter member variable. However, that method is appears to be
a convenience wrapper for Layout.format(Writer, LoggingEvent) which
should be thread-safe. Layout.format(LoggingEvent) doesn't appear to
be used in a huge number of places and may be beneficial to remove
Layout.format(LoggingEvent) since the caller (typically an appender)
might be able to maintain its own CharArrayWriter with out introducing
additional synchronization issues.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Concurrency Appender Proposal
Posted by Ceki Gülcü <ce...@qos.ch>.
Hi Elias,
I had a cursory look at the code. It looks pretty good.
Although it may be my suggestion to begin with, comparing
ConcurrentAppender ca = new ConcurrentAppender() {
protected void append(LoggingEvent event) {
try { Thread.sleep(1); } catch (InterruptedException e) {}
}
protected void internalClose() {}
};
and
AppenderSkeleton as = new AppenderSkeleton() {
protected void append(LoggingEvent event) {
try { Thread.sleep(1); } catch (InterruptedException e) {}
}
public void close() {}
};
is meaningless.
Do you have numbers comparing
org.apache.log4j.WriterAppender wa = new
org.apache.log4j.WriterAppender();
wa.setWriter(w);
new PerformanceTest(wa);
with
org.apache.log4j.concurrent.WriterAppender wa2 = new
org.apache.log4j.concurrent.WriterAppender();
wa2.setWriter(w);
new PerformanceTest(wa2);
Since the existing Layouts recycle the string buffer, in the single
threaded case, I would expect the existing code to outperform your version
which creates a new CharArrayWriter with each conversion. You seem to
indicate that the performances are more or less on par.
At 06:42 PM 1/22/2005, Elias Ross wrote:
>Here are the files plus a patch to the pattern layout classes.
>(Modifying the layout classes to be thread-safe was a separate step.)
>
>It's still a bit rough around the edges, especially the javadoc. I
>pretty much copied/pasted the implementations of Writer and Console
>appender, with a few changes here and there.
>
>I use ThreadLocal in a few places, which is only available in JVM 1.2+
Using ThreadLocal for the guard is a bit confusing, but nifty nonetheless.
--
Ceki Gülcü
The complete log4j manual: http://www.qos.ch/log4j/
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Concurrency Appender Proposal
Posted by Elias Ross <er...@m-qube.com>.
On Sat, 2005-01-22 at 04:58, Ceki Gülcü wrote:
>
> Since what you are doing is not clear, your enthusiasm, although nice to
> see, is hard to share.
Here are the files plus a patch to the pattern layout classes.
(Modifying the layout classes to be thread-safe was a separate step.)
It's still a bit rough around the edges, especially the javadoc. I
pretty much copied/pasted the implementations of Writer and Console
appender, with a few changes here and there.
I use ThreadLocal in a few places, which is only available in JVM 1.2+
Re: Concurrency Appender Proposal
Posted by Ceki Gülcü <ce...@qos.ch>.
At 01:51 AM 1/22/2005, Elias Ross wrote:
>On Thu, 2005-01-20 at 10:12, Ceki Gülcü wrote:
> > Elias,
> >
> > Thank you for your proposal. Would it possible for you to backup your
> > proposal with prototype code? I'd be very interested in a comparative
> > study between an Appender using the current concurrency model and an
> > Appender following your improved model. A performance test involving
> > several threads would be quite appropriate.
> >
> > (Appender is an interface so one can easily swap implementations.)
> >
> > How does that sound?
>
>Sounds fantastic.
>
>I wrote some simple tests. Here's some of the code using the old
>interface and the new one.
>
> ConcurrentAppender ca = new ConcurrentAppender() {
> protected void append(LoggingEvent event) {
> try { Thread.sleep(1); } catch (InterruptedException e) {}
> }
> protected void internalClose() {}
> };
>
> AppenderSkeleton as = new AppenderSkeleton() {
> protected void append(LoggingEvent event) {
> try { Thread.sleep(1); } catch (InterruptedException e) {}
> }
> public void close() {}
> };
>
>Using 5 threads with 100 log statements, here's what I got (a
>representative sample):
>
> [java] AppenderSkeleton
> [java] Appender class org.apache.log4j.concurrent.PerformanceTest$2
> [java] Took 1066ms for 100 logs * threads 5
>
> [java] ConcurrentAppender
> [java] Appender class org.apache.log4j.concurrent.PerformanceTest$1
> [java] Took 288ms for 100 logs * threads 5
>
>It's about 3-4 times as efficient.
What do these results prove, that you can clobber the output 3-4 times
faster than outputting logs correctly? There are two side to this problem,
the performance side and the safety side. Maybe you have the required grasp
of both sides of the issue, but without the source code for what you have
done, it's hard to tell.
>Is there some place to put a patch?
Please send your code to this mailing list.
>I also wrote new ConsoleAppender, WriterAppender versions. They perform
>about the same as the old ones on a single processor machine, which
>isn't a surprising finding, but it's good to know they are just as fast.
>
>One thing I noticed was that Layouts were not thread-safe. Most of the
>code time is spent in that class *. I changed the PatternConverter
>class signature from:
>
> protected abstract void convert(LoggingEvent event);
>
>to:
>
> protected abstract void convert(StringBuffer sb, LoggingEvent event);
>
>and rewrote Layout in such a way that it is thread safe. Obviously,
>there would be compatibility issues, which is why I am thinking of
>creating a separate Layout class to be used in this way.
>
>* According to my last run 87% of the CPU time was spent formatting. So
>if you have 2 CPUs, 87% of the other CPU's time is waiting!
Since what you are doing is not clear, your enthusiasm, although nice to
see, is hard to share.
--
Ceki Gülcü
The complete log4j manual: http://www.qos.ch/log4j/
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Concurrency Appender Proposal
Posted by Elias Ross <er...@m-qube.com>.
Here's another interesting thing I got out of another tool I have that
measures thread contention.
This is comparing the concurrent versus non-concurrent WriterAppender
versions, doing the same test 10 times, each test 5 threads writing 1000
times each: (Code available if curious) (Single processor)
Concurrent
239 threads spent 3245 millis in java.io.FileWriter on line 251. Average: 13, Min: 0, Max: 66.
9 threads spent 1038 millis in java.io.FileWriter on line 252. Average: 115, Min: 0, Max: 327.
9 threads spent 103 millis in java.util.Vector on line 269. Average: 11, Min: 0, Max: 28.
3 threads spent 103 millis in java.util.Hashtable on line 332. Average: 34, Min: 0, Max: 58.
Non concurrent
344 threads spent 7692 millis in org.apache.log4j.WriterAppender on line 205. Average: 22, Min: 0, Max: 241.
2 threads spent 209 millis in java.lang.ref.Reference$Lock on line 40. Average: 104, Min: 0, Max: 185.
2 threads spent 183 millis in sun.misc.Launcher$AppClassLoader on line 588. Average: 91, Min: 0, Max: 92.
7 threads spent 55 millis in java.lang.ref.Reference$Lock on line 0. Average: 7, Min: 0, Max: 29.
The averages are the wait times for each. (I think the line numbers and
thread counts are bogus.)
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Concurrency Appender Proposal
Posted by Elias Ross <er...@m-qube.com>.
On Thu, 2005-01-20 at 10:12, Ceki Gülcü wrote:
> Elias,
>
> Thank you for your proposal. Would it possible for you to backup your
> proposal with prototype code? I'd be very interested in a comparative
> study between an Appender using the current concurrency model and an
> Appender following your improved model. A performance test involving
> several threads would be quite appropriate.
>
> (Appender is an interface so one can easily swap implementations.)
>
> How does that sound?
Sounds fantastic.
I wrote some simple tests. Here's some of the code using the old
interface and the new one.
ConcurrentAppender ca = new ConcurrentAppender() {
protected void append(LoggingEvent event) {
try { Thread.sleep(1); } catch (InterruptedException e) {}
}
protected void internalClose() {}
};
AppenderSkeleton as = new AppenderSkeleton() {
protected void append(LoggingEvent event) {
try { Thread.sleep(1); } catch (InterruptedException e) {}
}
public void close() {}
};
Using 5 threads with 100 log statements, here's what I got (a representative sample):
[java] AppenderSkeleton
[java] Appender class org.apache.log4j.concurrent.PerformanceTest$2
[java] Took 1066ms for 100 logs * threads 5
[java] ConcurrentAppender
[java] Appender class org.apache.log4j.concurrent.PerformanceTest$1
[java] Took 288ms for 100 logs * threads 5
It's about 3-4 times as efficient.
Is there some place to put a patch?
I also wrote new ConsoleAppender, WriterAppender versions. They perform
about the same as the old ones on a single processor machine, which
isn't a surprising finding, but it's good to know they are just as fast.
One thing I noticed was that Layouts were not thread-safe. Most of the
code time is spent in that class *. I changed the PatternConverter
class signature from:
protected abstract void convert(LoggingEvent event);
to:
protected abstract void convert(StringBuffer sb, LoggingEvent event);
and rewrote Layout in such a way that it is thread safe. Obviously,
there would be compatibility issues, which is why I am thinking of
creating a separate Layout class to be used in this way.
* According to my last run 87% of the CPU time was spent formatting. So
if you have 2 CPUs, 87% of the other CPU's time is waiting!
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Concurrency Appender Proposal
Posted by Ceki Gülcü <ce...@qos.ch>.
Elias,
Thank you for your proposal. Would it possible for you to backup your
proposal with prototype code? I'd be very interested in a comparative
study between an Appender using the current concurrency model and an
Appender following your improved model. A performance test involving
several threads would be quite appropriate.
(Appender is an interface so one can easily swap implementations.)
How does that sound?
For this comparative study, I'd suggest a fake appender with a 1
millisecond delay in its doAppend method. For example,
class FakeAppender implements Appender {
synchronized public void doAppend(LoggingEevent e) {
Thread.currentThread.sleep(1);
}
... stubs
}
At 05:48 PM 1/20/2005, Elias Ross wrote:
>I am proposing creating a "shadow" package called
>org.apache.log4j.concurrent that contains many of the same classes, such
>as AppenderSkeleton, FileAppender, etc. but allows multiple threads to
>append at the same time. Most of the inspiration for such a project
>comes from work done by the java.util.concurrent team, who created
>concurrent implementations for Map, List, etc., that created minimally
>locked data-structures.
>
>"Why is such a package needed?"
>
>In today's world of hyper-threaded, multi-processor application servers,
>inevitably there is a need (like any application server library) for a
>scalable logging solution.
>
>"Okay, but it's not like you're logging 100 times a second..."
>
>Not necessarily. When diagnosing problems in a running server, one
>often has to turn on and turn off logging, hopefully without disrupting
>processing that is occurring on a live system.
>
>It would also be a good basis for appenders that could greatly benefit
>from concurrency, such as SNMP, JDBC, JMS appenders. There wouldn't be
>any need to lock these as each thread. As each log event is relatively
>expensive, concurrency would _greatly_ improve these classes, as one
>thread would not need to hold a lock for 10-30 milliseconds, for
>example.
>
>Often times, a large amount of logging occurs during outage situations.
>When a database hiccups, or a Servlet class fails (due to bugs), the
>server tries to log 1000 times a second, causing unrelated threads to
>block as well. Could log4j bring your server to its knees?
>
>"Why not just use the Async appender?"
>
>This would improve matters, but it does not allow for synchronous
>logging of events or take advantage of multi-processors. A possible fix
>for the latter problem would be creating a thread pool, which would have
>to be tuned for the installation.
>
>"Why not fix the existing appender classes?"
>
>Unfortunately, there would be a lot of compatibility problems. Anybody
>who extended an existing appender class in their own code expects
>locking to behave in a particular way. (This is the "Inheritance breaks
>encapsulation" anti-pattern.)
>
>"Bloat!"
>
>Probably wouldn't require more than a 1000 lines of code for the core
>part. Obviously, it's more of a chore to get 1000 lines of such code
>correct, but not impossible.
>
>"Nobody would use it. Nobody cares. Why not create it yourself?"
>
>I'm somebody, aren't I? I care.
>
>I think the log4j project and its users would benefit with an integrated
>solution, rather than one that comes from an unknown source such as
>myself. Plus, log4j could itself leverage such a library.
>
>In addition, it'd be another simple reason log4j beats
>java.util.logging.
>
>
>
>---------------------------------------------------------------------
>To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>For additional commands, e-mail: log4j-dev-help@logging.apache.org
--
Ceki Gülcü
The complete log4j manual: http://www.qos.ch/log4j/
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org