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 2004/09/22 21:13:29 UTC
Fix for deadlocks -- an easy fix for AppenderSkeleton
I tried using read-write locks and other techniques, which do indeed
work but are not really backwards compatible, but I think the best
solution I came up with is this: (you can refer to the diffs against CVS
as well)
1. While synchronized, check on the threshold
2. Call getRenderedMessage(), ignore the result
3. While synchronized, check if guard is set or closed
...then call append()
Since once closed, an appender is never opened
The trick with calling LoggingEvent.getRenderedMessage() early is that
it caches the rendered form of the message. This is something not
available in 1.2, but will work in 1.3.
There is some room for improvement. I still think using a write/read
lock would improve concurrency, but in those cases a different base
class (hierarchy) would be good.
Here is the result for those who can't view the attachment:
public abstract class AppenderSkeleton implements Appender, OptionHandler {
...
public void doAppend(LoggingEvent event) {
if (!canAppend(event))
return;
// Pre-render the message to prevent deadlock
event.getRenderedMessage();
doAppend0(event);
}
private synchronized void doAppend0(LoggingEvent event) {
if (closed) {
LogLog.error(
"Attempted to append to closed appender named [" + name + "].");
return;
}
try {
if (guard)
return;
guard = true;
append(event);
} finally {
guard = false;
}
}
private synchronized boolean canAppend(LoggingEvent event) {
if (!isAsSevereAsThreshold(event.getLevel())) {
return false;
}
Filter f = this.headFilter;
FILTER_LOOP:
while (f != null) {
switch (f.decide(event)) {
case Filter.DENY:
return false;
case Filter.ACCEPT:
break FILTER_LOOP;
case Filter.NEUTRAL:
f = f.getNext();
}
}
return true;
}
RE: Fix for deadlocks -- an easy fix for AppenderSkeleton
Posted by Elias Ross <er...@m-qube.com>.
On Sun, 2004-09-26 at 03:58, Ceki Gülcü wrote:
>
> How can you write events concurrently from two distinct threads to the
> same file and expect coherent output?
In the case of file output, you would want the files locked when you
were writing. But log4j is not just for writing to files, is it?
But let's say you were writing to two files (disks!), or to a database
which has a great deal of I/O latency, or through socket I/O. SNMP
traps. Etc. Say, what about opening up two e-mail server connections
and possibly doubling your throughput?
It works like this: (timeline)
1. Thread 1 sends a request, waits for ack
2. Thread 2 sends a request, waits for ack
3. Thread 1 receives ack
4. Thread 2 receives ack
(A less resource intensive approach would be to queue requests, send,
then wait for multiple acknowledgments. However, this is very difficult
to code correctly in practice.)
On Sun, 2004-09-26 at 10:34, Endre Stølsvik wrote:
> Another thing I think I understood from the mail-thread, is that the
> -rendering- of the messages are also done within the syncronization block.
> Again, I don't know whether this is true, as I haven't read the code there
> yet. But if this is true, I can't see the point: the rendering of the
> message can be done simultaneously on the two different CPUs in any
> regard, even if you'd like the actual appending to be synchronized. And
> this would increase logging throughput.
I think you have hit on the main point I've been trying to make. I
would expect that rendering would be concurrent. I know that probably
99.5% of how people call Log4J is like this:
Logger.debug("State: " + this);
And to optimize, many do this:
if (Logger.isDebugEnabled())
Logger.debug("State: " + this);
mainly so that the JVM doesn't construct a unneeded string if debug is
off.
However, let's suppose somebody naively does this (As I was led to do
last year before I found out this is bad news):
Logger.debug(this);
Or creates a parameterized logging object, say this:
class LogMessage {
int errorCode;
String message;
Object state;
}
and does this in one thread:
Logger.error(new LogMessage(12123, "Something", state)); [T1]
Then, assuming that you created a custom Renderer calls
"source.toString" (or you live with Object.toString), and perhaps the
object "source" looked something like this:
class MyState {
Collection connectionList =
Collections.synchronizedList(new FatList());
public String toString() {
return super.toString() + " c=" + c;
}
}
And suppose the collection class did this:
class FatList extends AbstractList {
Logger log = Logger.getLogger(FatList.class);
public Iterator iterator() {
log.debug("iterate: " + size());
// we're prone to deadlock, yay!
}
}
And your Thread 2 did this:
synchronized (connectionList) {
Iterator i = connectionList.iterator();
/// you know the routine...
}
It's not going to be pretty when you deploy this code on production.
This would be __highly dangerous__ if some person turned on debug,
especially if either lock was held long.
The lock order would someday turn out to be like this:
Thread 1: owns AppenderSkeleton, waiting for List
Thread 2: owns List, waiting for AppenderSkeleton.
I really think log4j is fine for how 99% of the people use it. And even
though locking is coarse, most people probably don't care. But, 5-10
years down the road, we're going to want to be using libraries that are
multi-processor and multi-threading conscientious. The log4j team
probably can't satisfy everyone and all goals, but I'd like to encourage
more attention in this area. Please.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
RE: Fix for deadlocks -- an easy fix for AppenderSkeleton
Posted by Endre Stølsvik <En...@Stolsvik.com>.
On Sun, 26 Sep 2004, Ceki Gülcü wrote:
| At 01:53 AM 9/23/2004, Elias Ross wrote:
|
| >Single lock strategy: (current one)
| >
| >Thread 1 --> Appender --> Database.insert
| >Thread 2 --> (wait)
| >
| >This tends to create bottlenecks if two threads are logging at the same
| >time.
| >
| >
| >Concurrent strategy:
| >
| >Thread 1 --> Appender --> Database.insert
| >Thread 2 --> Appender --> Database.insert
| >
| >This has an advantage on multiprocessor machines or when the database
| >can handle inserts simultaneously.
|
| How can you write events concurrently from two distinct threads to the
| same file and expect coherent output?
One must assume that the database knows how to handle syncronization,
which a database definately must!
Judging from the thread (-but I haven't read the code-), I think Elias
have a point: if the current implementation locks the Appender (or an
object "on the same level") while outputting, then there might be room for
improvement:
Lets construct an example: you have an dual-CPU box, running an
application using log4j extensively, and the log-receiving DB is on
another box, also dual-CPU. Then you could conceivably log two different
messages at the exact same time, using two different connections to the
database machine. On the database side, the two different processors read
from the two different connections, then close the connection, and the
log4j log-method will return, and everything will have been "totally
concurrent". Note that on the thread's way into the logging system
(deciding whether to log or not), the methods obviously will have to
synchronize on different elements, but this would just have to be to check
different ints and booleans - it might even suffice to use transient
variables here.
( How the database side handles the actual concurrency, and the
writing/updating to disk, is really out of the scope of the discussion.
However, here's an idea: each connection will cache the INSERT message to
ram (the two CPU's have different ram-sections, obviously), then do
dependency-analysis on other tables. The database will realize that it is
a simple insert, with no dependecies, and the caller requests "just do it
when you can", so it can just acknowledge the update, and release the
connection right away (if you do MySQL "low priority" inserts, this is
actually what can happen). It'll further stick the update's in a queue,
this step is obviously synchronized, and another thread will read from
this queue, also syncrhonized, and write to the transaction log first,
then yet another thread will later commit the changes to the actual
table-file (or whatever). However, the log4j-part of this scenario won't
be affected by the database's struggles with getting this to disk! )
Another more easily conceivable appender that would benefit from full
not-synchronzied appending-logic, is an UDP-appender (or
multicast-appender?), that just sends it's log-messages "out in the dark",
hoping that there are some receiver that picks them up. This could be done
without using synchronizatin on actual appender-part on the log4j side.
Things might (often) be received out-of-order, but this is no problem:
each thread will be in-order, and you'll also send the timestamp (from the
server) and the thread-name, in this UDP packet. One might also envision a
counter that ensures received order, which could either be an
unsynchronized ThreadLocal, or a appender-global, synchronized counter.
Another thing I think I understood from the mail-thread, is that the
-rendering- of the messages are also done within the syncronization block.
Again, I don't know whether this is true, as I haven't read the code there
yet. But if this is true, I can't see the point: the rendering of the
message can be done simultaneously on the two different CPUs in any
regard, even if you'd like the actual appending to be synchronized. And
this would increase logging throughput.
For the file-appender-case, the situation is slightly more complicated, of
course: this particular appender must either write its entire log-line in
one go (one write-method invocation), but it can be unsyncrhonized (as the
write method already is syncrhonzied), -or- one must syncrhonzie on the
"file itself" manually, while doing the multiple writes that the one
log-method invocation requires. But this is a particular specificity of
the file-appender, and not of appending in general.
Sorry if I've missed all the targets royally here.
Endre
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
RE: Fix for deadlocks -- an easy fix for AppenderSkeleton
Posted by Ceki Gülcü <ce...@qos.ch>.
At 01:53 AM 9/23/2004, Elias Ross wrote:
>Single lock strategy: (current one)
>
>Thread 1 --> Appender --> Database.insert
>Thread 2 --> (wait)
>
>This tends to create bottlenecks if two threads are logging at the same
>time.
>
>
>Concurrent strategy:
>
>Thread 1 --> Appender --> Database.insert
>Thread 2 --> Appender --> Database.insert
>
>This has an advantage on multiprocessor machines or when the database
>can handle inserts simultaneously.
How can you write events concurrently from two distinct threads to the
same file and expect coherent output?
--
Ceki Gülcü
For log4j documentation consider "The complete log4j manual"
ISBN: 2970036908 http://www.qos.ch/shop/products/clm_t.jsp
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
RE: Fix for deadlocks -- an easy fix for AppenderSkeleton
Posted by Elias Ross <er...@m-qube.com>.
On Wed, 2004-09-22 at 16:17, Paul Smith wrote:
> We have the AsyncAppender already, unless ConcurrentAppender does something
> different?
I suppose the main difference would be that you would be appending in
the same thread that you executed the log statement in. Each thread
would be writing to the database at the same time and would not be
waiting.
Here are three different ways to log events to the database from two
threads:
--> means call
Single lock strategy: (current one)
Thread 1 --> Appender --> Database.insert
Thread 2 --> (wait)
This tends to create bottlenecks if two threads are logging at the same
time.
Concurrent strategy:
Thread 1 --> Appender --> Database.insert
Thread 2 --> Appender --> Database.insert
This has an advantage on multiprocessor machines or when the database
can handle inserts simultaneously.
Asynchronous strategy:
Thread 1 --> Appender --> Enqueue Job
Thread 2 --> Appender --> Enqueue Job
Thread 3 --> dequeue Job --> Database.insert
This is good for when Thread 1 & 2 don't want to wait for the insert to
complete. Probably the same performance as the concurrent strategy,
except on multiprocessor machines. An additional thread (or threads)
are required.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
RE: Fix for deadlocks -- an easy fix for AppenderSkeleton
Posted by Paul Smith <ps...@aconex.com>.
> On Wed, 2004-09-22 at 14:42, Paul Smith wrote:
> > This would be worth attaching to a Bugzilla ticket so it can be
> > analysed properly without getting lost. If you could write a TestCase
> > that shows how the current implementation deadlocks, and how this one
> > does not, it will help tremendously.
> >
> > Thank you for your efforts.
> >
>
> There is already a test case for it in CVS.
>
> I'll attach my new changes and reopen the bug.
>
> I'm also thinking of writing a "ConcurrentAppender" which would allow
> multiple events to be processed at a time. This would be good for
> things such as logging to JDBC, JMS, e-mail, etc., where multiple events
> could happen simultaneously. Is there any interest in this?
We have the AsyncAppender already, unless ConcurrentAppender does something
different?
cheers,
Paul Smith
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
RE: Fix for deadlocks -- an easy fix for AppenderSkeleton
Posted by Elias Ross <er...@m-qube.com>.
On Wed, 2004-09-22 at 14:42, Paul Smith wrote:
> This would be worth attaching to a Bugzilla ticket so it can be
> analysed properly without getting lost. If you could write a TestCase
> that shows how the current implementation deadlocks, and how this one
> does not, it will help tremendously.
>
> Thank you for your efforts.
>
There is already a test case for it in CVS.
I'll attach my new changes and reopen the bug.
I'm also thinking of writing a "ConcurrentAppender" which would allow
multiple events to be processed at a time. This would be good for
things such as logging to JDBC, JMS, e-mail, etc., where multiple events
could happen simultaneously. Is there any interest in this?
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
RE: Fix for deadlocks -- an easy fix for AppenderSkeleton
Posted by Paul Smith <ps...@aconex.com>.
This would be worth attaching to a Bugzilla ticket so it can be analysed properly without getting lost. If you could write a TestCase that shows how the current implementation deadlocks, and how this one does not, it will help tremendously.
Thank you for your efforts.
cheers,
Paul Smith
> -----Original Message-----
> From: Elias Ross [mailto:eross@m-qube.com]
> Sent: Thursday, September 23, 2004 5:13 AM
> To: Log4J Developers List
> Subject: Fix for deadlocks -- an easy fix for AppenderSkeleton
>
>
>
> I tried using read-write locks and other techniques, which do indeed
> work but are not really backwards compatible, but I think the best
> solution I came up with is this: (you can refer to the diffs against CVS
> as well)
>
> 1. While synchronized, check on the threshold
> 2. Call getRenderedMessage(), ignore the result
> 3. While synchronized, check if guard is set or closed
> ...then call append()
>
> Since once closed, an appender is never opened
>
> The trick with calling LoggingEvent.getRenderedMessage() early is that
> it caches the rendered form of the message. This is something not
> available in 1.2, but will work in 1.3.
>
> There is some room for improvement. I still think using a write/read
> lock would improve concurrency, but in those cases a different base
> class (hierarchy) would be good.
>
> Here is the result for those who can't view the attachment:
>
> public abstract class AppenderSkeleton implements Appender,
> OptionHandler {
>
> ...
>
> public void doAppend(LoggingEvent event) {
> if (!canAppend(event))
> return;
> // Pre-render the message to prevent deadlock
> event.getRenderedMessage();
> doAppend0(event);
> }
>
> private synchronized void doAppend0(LoggingEvent event) {
> if (closed) {
> LogLog.error(
> "Attempted to append to closed appender named [" + name + "].");
> return;
> }
> try {
> if (guard)
> return;
> guard = true;
> append(event);
> } finally {
> guard = false;
> }
> }
>
> private synchronized boolean canAppend(LoggingEvent event) {
> if (!isAsSevereAsThreshold(event.getLevel())) {
> return false;
> }
> Filter f = this.headFilter;
>
> FILTER_LOOP:
> while (f != null) {
> switch (f.decide(event)) {
> case Filter.DENY:
> return false;
> case Filter.ACCEPT:
> break FILTER_LOOP;
> case Filter.NEUTRAL:
> f = f.getNext();
> }
> }
> return true;
> }
>
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org