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 Paul Duffy <pa...@cisco.com> on 2007/12/07 20:12:13 UTC
Sequence number for LoggingEvent
Folks,
Scenario is app running on multi core hardware at high clock rates.
Millisecond time resolution for LoggingEvent is not going to cut it.
Need a monotonically increasing sequence number in the LoggingEvent to
distinguish order for events occurring w/ the same time stamp. Rather
not go through a lot of twisted mumbo jumbo to accommodate what appears
to be a basic feature need. IMO this sequence number should be set in
the ctor along with the timestamp.
Thoughts?
Cheers
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
log4j 2.0 development (was Re: Sequence number for LoggingEvent)
Posted by Curt Arnold <ca...@apache.org>.
On Dec 9, 2007, at 11:55 AM, Jess Holle wrote:
> Paul Duffy wrote:
>>> For the big picture:
>>>
>>> log4j 2.0 intends to target Java 5 and later and follow modern
>>> concurrency best practices, but currently it is only a concept and
>>> some very early experimental code. While I'd love to flesh out
>>> the framework and energize a team to built it, keeping log4j 1.2
>>> running and getting log4cxx is taking all my open source cycles at
>>> the moment and nobody seems anxious to work on it.
>> Looks like we'll be modifying 1.2 then. Adding the sequence
>> number, compiling under 1.6, etc.
> We've not yet gotten to this point in our use of log4j, but may well
> soon as well -- i.e. to the point that we manage our own fork of 1.2.
>
> In our case this is not for sequence number initially (though that
> would be nice -- we use an AtomicLong to number our JMX
> notifications, for instance). Rather we may well need to make some
> substantive alterations to the synchronization strategy in log4j.
> Sure this may break things, but there comes a point where removing
> synch bottlenecks is more important than maintaining compatibility
> with stuff you're not using :-) On the flip side maintaining API
> compatibility with "typical" log4j call-site (vs. extension) usage
> is still critical from my standpoint in any case -- else you might
> as well switch logging frameworks entirely.
>
Right now the "definition" of log4j 2.0 is very open. The essential
aspects are:
a) redesigned for concurrency and modern best practices.
b) Targets Java 5 and later. Earlier JDK's can continue to use log4j
1.x.
b) finer grain concurrency minimizing locks currently used by log4j 1.x.
c) typical call-site compatibility, but not constrained to be
extension compatible with log4j 1.2 or rigorously compatible with
nuances of current log4j 1.2 behavior.
Anything that is released as a log4j 1.x must preserve very strict
compatibility with earlier log4j releases. log4j 1.3 was problematic
in that it wasn't strictly compatible with log4j 1.2 and didn't
address the concurrency issues so it wasn't a good fit with the log4j
2.0 goals. It also wasn't compelling enough to relabel it as log4j
2.0 and then have a log4j 3.0 that addressed the concurrency issues.
I've put some personal experiments on log4j 2.0 themes in the sandbox,
but they aren't binding on the community and the eventual log4j 2.0
development may or may not incorporate them. If you are motivated
enough to fork log4j 1.2 to work on the concurrency issues, then it
would be great if we could find a way that you could work inside the
community and in the open with others who share the same concerns.
I'd have little problem with setting up branches in the SVN for any
number of experiments that might lead to log4j 2.0. If a few failed
or were abandoned while other flourished, that is the nature of
experiments. The only problem would be code that was developed in
isolation from the community (for example, if you branched log4j,
redesigned a lot of things without discussion and presented it as a
completed work), then it would need to go through the incubator if the
community thought that it was worth the effort.
Any proposals for will be seriously considered. If you are
interested, I'd suggest that you reread previous log4j 2.0 threads and
ask any questions you have. I think we'd all like to see log4j 2.0
development moving, but it is going to be the people who are suffering
from log4j 1.x shortcomings who are going to be motivated to drive
log4j 2.0 development. I don't think anyone is picky about how it
happens other than it happens in the Apache way.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Sequence number for LoggingEvent
Posted by Paul Duffy <pa...@cisco.com>.
Jess Holle wrote:
> Paul Duffy wrote:
>>> For the big picture:
>>>
>>> log4j 2.0 intends to target Java 5 and later and follow modern
>>> concurrency best practices, but currently it is only a concept and
>>> some very early experimental code. While I'd love to flesh out the
>>> framework and energize a team to built it, keeping log4j 1.2 running
>>> and getting log4cxx is taking all my open source cycles at the
>>> moment and nobody seems anxious to work on it.
>> Looks like we'll be modifying 1.2 then. Adding the sequence number,
>> compiling under 1.6, etc.
> We've not yet gotten to this point in our use of log4j, but may well
> soon as well -- i.e. to the point that we manage our own fork of 1.2.
Seems several of us are heading this way.
>
> In our case this is not for sequence number initially (though that
> would be nice -- we use an AtomicLong to number our JMX notifications,
> for instance). Rather we may well need to make some substantive
> alterations to the synchronization strategy in log4j. Sure this may
> break things, but there comes a point where removing synch bottlenecks
> is more important than maintaining compatibility with stuff you're not
> using :-)
Absolutely.
> On the flip side maintaining API compatibility with "typical" log4j
> call-site (vs. extension) usage is still critical from my standpoint
> in any case -- else you might as well switch logging frameworks entirely.
Agreed
>
> --
> Jess Holle
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Sequence number for LoggingEvent
Posted by Jess Holle <je...@ptc.com>.
Paul Duffy wrote:
>> For the big picture:
>>
>> log4j 2.0 intends to target Java 5 and later and follow modern
>> concurrency best practices, but currently it is only a concept and
>> some very early experimental code. While I'd love to flesh out the
>> framework and energize a team to built it, keeping log4j 1.2 running
>> and getting log4cxx is taking all my open source cycles at the moment
>> and nobody seems anxious to work on it.
> Looks like we'll be modifying 1.2 then. Adding the sequence number,
> compiling under 1.6, etc.
We've not yet gotten to this point in our use of log4j, but may well
soon as well -- i.e. to the point that we manage our own fork of 1.2.
In our case this is not for sequence number initially (though that would
be nice -- we use an AtomicLong to number our JMX notifications, for
instance). Rather we may well need to make some substantive alterations
to the synchronization strategy in log4j. Sure this may break things,
but there comes a point where removing synch bottlenecks is more
important than maintaining compatibility with stuff you're not using
:-) On the flip side maintaining API compatibility with "typical" log4j
call-site (vs. extension) usage is still critical from my standpoint in
any case -- else you might as well switch logging frameworks entirely.
--
Jess Holle
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Sequence number for LoggingEvent
Posted by Paul Duffy <pa...@cisco.com>.
Curt Arnold wrote:
>
> On Dec 9, 2007, at 11:46 AM, Paul Duffy wrote:
>
>>
>>>
>>> The sequence number that was implemented in log4j 1.3 was
>>> problematic on several fronts. In the implementation in the last
>>> release, the same sequence number could be repeated since it wasn't
>>> guarded with a synchronization block. I believe that it was fixed
>>> in the SVN, but didn't make it into a release. Been a couple of
>>> years since we went round and round on it, but search the log4j-dev
>>> archives and Bugzilla for earlier discussions.
>>>
>>> There are a slew of things in log4j 1.2 that "don't cut it" for
>>> multi-core hence the desire to develop a log4j 2.0 that uses finer
>>> locking and only targets Java 5 and later. If you were targeting
>>> Java 5 and later, the most obvious approach would be use
>>> System.nanoTime, however log4j 1.2.x targets earlier JVMs.
>>
>> Understand the point re: Java 5. Sequence number in Java 1.5 would
>> be trivial...just use an AtomicLong, etc.
>> System.nanoTime probably needs to be done anyway, but its not a final
>> solution. A time stamp PLUS sequence number is required.
>>
>
> Do you have any thoughts on the scenario where multiple JVM's are
> sending LoggingEvents to a common destination. In that case, you
> could get an low-resolution order from looking at the timestamps
> (assuming clocks are in sync), but naively looking at sequence numbers
> could be very confusing if the values overlap. Guess you could start
> the sequence with a random number. Any idea of how JDK 1.4 logging
> seeds its sequence number? I definitely would reserve some value to
> indicate "no sequence number available".
The contract that the sequence number be monotonically increasing would
be for a single VM. We were not planing that it be applied across VMs.
>
>> Looks like we'll be modifying 1.2 then. Adding the sequence number,
>> compiling under 1.6, etc.
>>
>
> It would be great if you could submit your changes in a bug report so
> that it could be considered for inclusion or that at worst somebody
> with the same need does not need to reinvent the wheel.
K, we'll keep that in mind. Thanks
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Sequence number for LoggingEvent
Posted by Jess Holle <je...@ptc.com>.
Curt Arnold wrote:
> On Dec 9, 2007, at 11:46 AM, Paul Duffy wrote:
>>> The sequence number that was implemented in log4j 1.3 was
>>> problematic on several fronts. In the implementation in the last
>>> release, the same sequence number could be repeated since it wasn't
>>> guarded with a synchronization block. I believe that it was fixed
>>> in the SVN, but didn't make it into a release. Been a couple of
>>> years since we went round and round on it, but search the log4j-dev
>>> archives and Bugzilla for earlier discussions.
>>>
>>> There are a slew of things in log4j 1.2 that "don't cut it" for
>>> multi-core hence the desire to develop a log4j 2.0 that uses finer
>>> locking and only targets Java 5 and later. If you were targeting
>>> Java 5 and later, the most obvious approach would be use
>>> System.nanoTime, however log4j 1.2.x targets earlier JVMs.
>> Understand the point re: Java 5. Sequence number in Java 1.5 would
>> be trivial...just use an AtomicLong, etc.
>> System.nanoTime probably needs to be done anyway, but its not a final
>> solution. A time stamp PLUS sequence number is required.
> Do you have any thoughts on the scenario where multiple JVM's are
> sending LoggingEvents to a common destination. In that case, you
> could get an low-resolution order from looking at the timestamps
> (assuming clocks are in sync), but naively looking at sequence numbers
> could be very confusing if the values overlap. Guess you could start
> the sequence with a random number. Any idea of how JDK 1.4 logging
> seeds its sequence number? I definitely would reserve some value to
> indicate "no sequence number available".
In related constructs I've kept the sequence number as just a number
starting at 1, but used other multi-part ids for significant things that
I want to identify across JVMs -- where part of the id is a sequence
within a given JVM but the other portions are a best attempt at being
unique across JVMs via various mechanisms (e.g. in Java 5 you have
unofficial access to the process id and then you have hostname, JVM
start time, etc....)
--
Jess Holle
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Sequence number for LoggingEvent
Posted by Curt Arnold <ca...@apache.org>.
On Dec 9, 2007, at 11:46 AM, Paul Duffy wrote:
>
>>
>> The sequence number that was implemented in log4j 1.3 was
>> problematic on several fronts. In the implementation in the last
>> release, the same sequence number could be repeated since it wasn't
>> guarded with a synchronization block. I believe that it was fixed
>> in the SVN, but didn't make it into a release. Been a couple of
>> years since we went round and round on it, but search the log4j-dev
>> archives and Bugzilla for earlier discussions.
>>
>> There are a slew of things in log4j 1.2 that "don't cut it" for
>> multi-core hence the desire to develop a log4j 2.0 that uses finer
>> locking and only targets Java 5 and later. If you were targeting
>> Java 5 and later, the most obvious approach would be use
>> System.nanoTime, however log4j 1.2.x targets earlier JVMs.
>
> Understand the point re: Java 5. Sequence number in Java 1.5 would
> be trivial...just use an AtomicLong, etc.
> System.nanoTime probably needs to be done anyway, but its not a
> final solution. A time stamp PLUS sequence number is required.
>
Do you have any thoughts on the scenario where multiple JVM's are
sending LoggingEvents to a common destination. In that case, you
could get an low-resolution order from looking at the timestamps
(assuming clocks are in sync), but naively looking at sequence numbers
could be very confusing if the values overlap. Guess you could start
the sequence with a random number. Any idea of how JDK 1.4 logging
seeds its sequence number? I definitely would reserve some value to
indicate "no sequence number available".
> Looks like we'll be modifying 1.2 then. Adding the sequence number,
> compiling under 1.6, etc.
>
It would be great if you could submit your changes in a bug report so
that it could be considered for inclusion or that at worst somebody
with the same need does not need to reinvent the wheel.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Sequence number for LoggingEvent
Posted by Paul Duffy <pa...@cisco.com>.
>
> The sequence number that was implemented in log4j 1.3 was problematic
> on several fronts. In the implementation in the last release, the
> same sequence number could be repeated since it wasn't guarded with a
> synchronization block. I believe that it was fixed in the SVN, but
> didn't make it into a release. Been a couple of years since we went
> round and round on it, but search the log4j-dev archives and Bugzilla
> for earlier discussions.
>
> There are a slew of things in log4j 1.2 that "don't cut it" for
> multi-core hence the desire to develop a log4j 2.0 that uses finer
> locking and only targets Java 5 and later. If you were targeting
> Java 5 and later, the most obvious approach would be use
> System.nanoTime, however log4j 1.2.x targets earlier JVMs.
Understand the point re: Java 5. Sequence number in Java 1.5 would be
trivial...just use an AtomicLong, etc.
System.nanoTime probably needs to be done anyway, but its not a final
solution. A time stamp PLUS sequence number is required.
>
> One of the issues that needs to be considered is that the order of the
> logging calls and their order of processing by appenders can be
> substantially different since there are intervening synchronization
> blocks and being first to wait does not mean that you will be first to
> wake up.
Set the LoggingEvent sequence number at the same time the timestamp is
set...I believe during construction of the LoggingEvent.
> Using a RewriteAppender would suffer from this since it would only add
> its sequence number after the thread may have been blocked for a
> substantial time period. If you were to take this approach, you'd
> probably do just as well just numbering the entries through a custom
> layout or appender.
>
> There have been repeated "bugs"
> (http://issues.apache.org/bugzilla/show_bug.cgi?id=40303 for example)
> filed when the timestamp (same would happen even more so to sequence
> number) are not monotonically increasing in a log file. This is due
> to the potential for reordering between the creation of LoggingEvent
> and the eventual processing by the Appenders.
Understood. IMO it seems more correct that the timestamp be set as
close to the client code log.XXX(...) as possible.
Any reordering can be done later by the viewing application.
>
> For the big picture:
>
> log4j 2.0 intends to target Java 5 and later and follow modern
> concurrency best practices, but currently it is only a concept and
> some very early experimental code. While I'd love to flesh out the
> framework and energize a team to built it, keeping log4j 1.2 running
> and getting log4cxx is taking all my open source cycles at the moment
> and nobody seems anxious to work on it.
Looks like we'll be modifying 1.2 then. Adding the sequence number,
compiling under 1.6, etc.
Thanks
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: Sequence number for LoggingEvent
Posted by Curt Arnold <ca...@apache.org>.
On Dec 7, 2007, at 1:12 PM, Paul Duffy wrote:
> Folks,
>
> Scenario is app running on multi core hardware at high clock rates.
> Millisecond time resolution for LoggingEvent is not going to cut
> it. Need a monotonically increasing sequence number in the
> LoggingEvent to distinguish order for events occurring w/ the same
> time stamp. Rather not go through a lot of twisted mumbo jumbo to
> accommodate what appears to be a basic feature need. IMO this
> sequence number should be set in the ctor along with the timestamp.
>
> Thoughts?
>
> Cheers
>
The sequence number that was implemented in log4j 1.3 was problematic
on several fronts. In the implementation in the last release, the
same sequence number could be repeated since it wasn't guarded with a
synchronization block. I believe that it was fixed in the SVN, but
didn't make it into a release. Been a couple of years since we went
round and round on it, but search the log4j-dev archives and Bugzilla
for earlier discussions.
There are a slew of things in log4j 1.2 that "don't cut it" for multi-
core hence the desire to develop a log4j 2.0 that uses finer locking
and only targets Java 5 and later. If you were targeting Java 5 and
later, the most obvious approach would be use System.nanoTime, however
log4j 1.2.x targets earlier JVMs.
One of the issues that needs to be considered is that the order of the
logging calls and their order of processing by appenders can be
substantially different since there are intervening synchronization
blocks and being first to wait does not mean that you will be first to
wake up. Using a RewriteAppender would suffer from this since it would
only add its sequence number after the thread may have been blocked
for a substantial time period. If you were to take this approach,
you'd probably do just as well just numbering the entries through a
custom layout or appender.
There have been repeated "bugs" (http://issues.apache.org/bugzilla/show_bug.cgi?id=40303
for example) filed when the timestamp (same would happen even more
so to sequence number) are not monotonically increasing in a log
file. This is due to the potential for reordering between the
creation of LoggingEvent and the eventual processing by the Appenders.
For the big picture:
log4j 2.0 intends to target Java 5 and later and follow modern
concurrency best practices, but currently it is only a concept and
some very early experimental code. While I'd love to flesh out the
framework and energize a team to built it, keeping log4j 1.2 running
and getting log4cxx is taking all my open source cycles at the moment
and nobody seems anxious to work on it.
log4j 1.3 is dead. It didn't address key concurrency issues and
wasn't binary compatible with log4j 1.2.
log4j 1.2 is in maintenance and many users are many versions back. It
is more effective to add a new feature in an companion so that users
who are running log4j 1.2.8 or so because that is hard wired into
their app server can have the new feature. Sequence number would
likely need to be done in the core log4j and would need changes to
LoggingEvent, the layouts, SocketAppender, database appenders,
corresponding changes to Chainsaw to be as ubiquitous as timeStamp. A
pretty big set of changes to work into the tail end of series and
would only benefit those who could upgrade to 1.2.17 or so. Would
still suffer from the cosmetic reordering problem from Bug 40303.
Anything done on log4j 1.2 would then force log4j 2.0 to follow, so it
would be much better to spend that effort on log4j 2.0 and do it right.
You seem to have an immediate need and adding sequenceNumber or any
alternative finely grained alternative isn't going to happen quickly
enough to be useful to you. Your have a couple of options that will
work depending on your priorities. If you are trying to follow the
order of logging calls and are understand that order in log files
might be ordered slightly differently, then you could pass a custom
message object instead of a string that captured a sequence number or
nano time at its construction, something that resolves to:
logger.info(new MyMessage("Hello, World"));
You could either then have its .toString() message include the
sequence number or use a custom layout that understands your object
and can extract the sequence number or nanoTime. You'd likely want to
avoid creating your message object when the level was disabled, you
can see an example of using a static helper class to create custom
message objects in the LogMF class (http://svn.apache.org/repos/asf/logging/log4j/companions/extras/trunk/src/main/java/org/apache/log4j/LogMF.java
) in the extras. Something like:
MyHelper.info(logger, "Hello, World");
that resolves to:
void info(final Logger logger, Object msg) {
if (logger.isInfoEnabled()) {
forcedLog(logger, Level.INFO, new MyMessage(msg));
}
}
If just want to document the order of processing by the appender, then
a custom layout would work.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org