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 Curt Arnold <ca...@apache.org> on 2005/01/10 06:23:52 UTC
Re: LoggingEvent.sequenceCount
I haven't worked any more on this, but I do intend to do so. I thought
that I would at least give a heads up that this issue isn't dead.
The current approach has a couple of drawbacks: it incurs a
synchronization for every dispatched message, it adds a sequenceCount
to the LoggingEvent which breaks serialization compatibility with 1.2.x
and might be mis-interpreted as a reliable means to detect dropped
messages, and would report as equal serializations of the same object
in different states (discussed later).
Since LoggingEvents have a short lifetime, the values of
Object.hashCode (which I believe are similar to memory addresses) may
repeat and likely in an implementation dependent fashion.
The approach that seems most reliable to me is to implement
LoggingEvent.equals as a real value comparison and create a
corresponding LoggingEvent.hashCode. That would avoid synchronization
tax on every logging request and would only cost the callers of
LoggingEvent.equals and LoggingEvent.hashCode. The implementation
would need to be start enough so that a cloned through serialization
object would compare equal to the original and that
prepareForDeferredProcessing would not effect either equals or
hashCode.
There would be at least two cases where the approaches give observably
results. If distinct logging event with content and timestamp were
received the current approach would report the messages as distinct
while the new approach would report the messages as equal. This would
only occur in tight loops like:
for (int i = 0; i < 20; i++) {
logger.info("Hello, world");
}
The current approach would see that as twenty distinct messages while
the new approach would see all messages within the same millisecond as
identical.
The other scenario is that the current approach sees all deserialized
copies of the same original object instance as identical. log4j 1.3
adds setter methods to LoggingEvent that are used by Filters to change
the message and other aspects of the logging event. If a message is
sent using the SocketAppender both before and after Filter processing,
with the current approach the messages would be seen as identical even
though the message content, level and other aspects could be radically
different.
My attack plan would be to first add unit tests that should check the
essential features on any acceptable approach and should be passed by
the current implementation, all the equals contract test cases (equals
to self, equals to null), comparison to deserialized clone, hashCode
invariant after prepareForDeferredProcessing. Then I would try to
flesh out the implementation and corresponding tests for the value
comparison implementation and report back to the list before
proceeding.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: LoggingEvent.sequenceCount
Posted by Endre Stølsvik <En...@Stolsvik.com>.
|
| > Remember the within-a-millisecond criteria, the
| >no-two-"persons"-can-have-the-same-birthday-while-within-one "garbage
| >generation" criteria, and add on to that the from the same logger
| >criteria, the same level criteria, and possibly also with the same message
| >criteria. You're rather far from the birtday paradox now, I feel.
| >
| >But still, it -could- happen. It just seems rather unlikely.
|
| We don't know for sure.
But you still allow the -global synchronization- to generate a
LoggingEvent?
|
| >Look up a couple of UUID/GUID algorithms. This is actually what you're
| >after, isn't it? Preferrably w/o synchronization hits.
|
| Any references?
Some "random" hits: Google: UUID
http://java.sun.com/j2se/1.5.0/docs/api/java/util/UUID.html
http://www.ossp.org/pkg/lib/uuid/
" UUIDs are 128 bit numbers which are intended to have a high likelihood
of uniqueness over space and time and are computationally difficult to
guess. They are globally unique identifiers which can be locally generated
without contacting a global registration authority. UUIDs are intended as
unique identifiers for both mass tagging objects with an extremely short
lifetime and to reliably identifying very persistent objects across a
network. "
http://www.doomdark.org/doomdark/proj/jug/
Java UUID Generator - JUG.
http://searchwebservices.techtarget.com/sDefinition/0,,sid26_gci805876,00.html
Google: Universally Unique Identifyer
http://www.auditmypc.com/acronym/UUID.asp
http://www.govtalk.gov.uk/gdsc/html/frames/GloballyUniqueIdentifier-0-2-Draft.htm
This is the currently suggested standard:
http://www.ietf.org/internet-drafts/draft-mealling-uuid-urn-05.txt
.. or you could use a webservice for all LoggingEvents generated:
http://kruithof.xs4all.nl/uuid/uuidgen
;-D
My point is that to generate such an "UUID", the systemIdentityHashcode in
addition to the milliseconds would be a very good starting point.
You must take into account that the LoggingEvent object would have to
actually get out of JVM scope, AND garbage collected, AND the address
would have to be reused for a LoggingEvent object, -within- one
millisecond, for a crash to occur.
Add the Thread Id (or its hashcode). Add the message string hash. Add
the level. You're now pretty much there.. Then shove in a pseudo-random 64
bit number from a ThreadLocal Random generator, and even you will have to
admit that the possibility of a collision is .. well .. zero.
I believe that an "UUID" consisting of ..
1) systemIdentityHashcode of LoggingEvent object on construction
2) hash of message String
3) systemIdentityHashcode of message String object on construction
4) current millis
5) Thread Id
., would be -way- more than enough. The hash of the message string is
maybe "quite expensive" to calculate. However, you now have a Rather
Unique Identifier (RUI) -without- the -global- multithreaded,
multicontended synch hit.
Endre
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: LoggingEvent.sequenceCount
Posted by Ceki Gülcü <ce...@qos.ch>.
At 02:50 PM 1/17/2005, Endre Stølsvik wrote:
>Java GC generally takes more than 1 millisecond from start to finish, was
>my point. This goes even if it is incremental: the GC'ing of the single
>object, or dozens of objects might go very fast, but the time it takes
>from start to finish (where the "adress" again is available) would "most
>probably" take more than a milli.
>
>In addition, it would have to be -a LoggingEvent object- that was produced
>with this specific address for a collision to happen.
You may be right. Nevertheless, the above is based on your conjectures
about how the GC behaves or should behave. In the absence of facts, we
cannot base an important part of the log4j framework on
speculation.
>|
>| Who can guarantee that no two events in a group of N+M events will not have
>| the same address? After all, the probability of any two persons having the
>| same birthday in a randomly chosen group of 23 persons is higher than 50%.
>| Yes, there are 365+1 possible birth dates but only a few people are needed
>| to produce a collision. (The Birthday Paradox)
>
>The birthday paradox does not apply here, as I've understood it.
Do not consider garbage collection as something that happens every
other blue moon. Depending on the algorithm used, the JVM may be
garbage collecting constantly, perhaps thousands of times every
millisecond.
See for example:
http://www-106.ibm.com/developerworks/java/library/j-jtp11253/
> Remember the within-a-millisecond criteria, the
>no-two-"persons"-can-have-the-same-birthday-while-within-one "garbage
>generation" criteria, and add on to that the from the same logger
>criteria, the same level criteria, and possibly also with the same message
>criteria. You're rather far from the birtday paradox now, I feel.
>
>But still, it -could- happen. It just seems rather unlikely.
We don't know for sure.
>Look up a couple of UUID/GUID algorithms. This is actually what you're
>after, isn't it? Preferrably w/o synchronization hits.
Any references?
>Endre.
--
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: LoggingEvent.sequenceCount
Posted by Endre Stølsvik <En...@Stolsvik.com>.
|
| >Rip away all the setters, incl. the private ones, make it totally
| >immutable (it's just a immutable "value object"), letting it have -one-
| >constructor taking all the arguments, take away all synch penalties on
| >construction, and optionally also make a utility Builder. Nice.
| >
| >The possibility for reusing all System.hashCodes within one millisecond
| >seems to me -extremely- close to zero: To have this happen, one would need
| >GC inbetween the instantiations, and having GC take -under- one
| >millisecond, in addition to hitting the same "address" on the two
| >instantiations, just seems plainly impossible.
|
| I have no idea about the algorithm Java uses to allocate memory. The
| probability of hitting the same address between allocations could be non
| negligible maybe even quite high. Consider the sequence:
|
| - allocate logging event 1
| - allocate logging event 2
| ...
| - allocate logging event N
| - garbage collect logging events 1, 2, .. N
| - allocate logging event N+1
| - allocate logging event N+2
| ...
| - allocate logging event N+M
|
| ...
|
| All this can easily happen in the space of 1 millisecond.
Java GC generally takes more than 1 millisecond from start to finish, was
my point. This goes even if it is incremental: the GC'ing of the single
object, or dozens of objects might go very fast, but the time it takes
from start to finish (where the "adress" again is available) would "most
probably" take more than a milli.
In addition, it would have to be -a LoggingEvent object- that was produced
with this specific address for a collision to happen.
|
| Who can guarantee that no two events in a group of N+M events will not have
| the same address? After all, the probability of any two persons having the
| same birthday in a randomly chosen group of 23 persons is higher than 50%.
| Yes, there are 365+1 possible birth dates but only a few people are needed
| to produce a collision. (The Birthday Paradox)
The birthday paradox does not apply here, as I've understood it.
Remember the within-a-millisecond criteria, the
no-two-"persons"-can-have-the-same-birthday-while-within-one "garbage
generation" criteria, and add on to that the from the same logger
criteria, the same level criteria, and possibly also with the same message
criteria. You're rather far from the birtday paradox now, I feel.
But still, it -could- happen. It just seems rather unlikely.
Look up a couple of UUID/GUID algorithms. This is actually what you're
after, isn't it? Preferrably w/o synchronization hits.
Endre.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: LoggingEvent.sequenceCount
Posted by Ceki Gülcü <ce...@qos.ch>.
At 05:00 PM 1/11/2005, Endre Stølsvik wrote:
>Curt, good points!
>
>On Mon, 10 Jan 2005, Curt Arnold wrote:
>
>|
>| > When logging an event, we should not build two objects
>| > (LoggingEventBuilder+LoggingEvent) instead of the current one
>| > (LoggingEvent).
>| >
>|
>| In that high volume use and reentrant code, it might be best to
>| continue to use a special constructor, but that might be made package
>| private so it can only be used within log4j.
>
>I don't see the reason for this: String has both a constructor, and a
>Builder. Why couldn't LoggingEvent also have this? I do agree with Ceki
>here - two objects should most definately not be needed when simply
>wanting to make a new LoggingEvent object. But if you -have- to do it
>incrementally, then a utiltiy-style Builder is nice. Another approach is
>of course simply to set temp variables (its only four, isn't it?), and
>finally, when you actually want to instantiate the LoggingEvent, then do
>so with the variables - the Builder is really very very simple.
I doubt the builder can be "very very simple" because the LoggingEvent
class contains a dozen fields, and its instances can be persisted and later
read back. Internally log4j components do not see any difference between an
event created 1 nanosecond ago and one persisted 3 months ago and just
recently de-serialized. The job of LoggingEvent class is to mask the
differences in its life cycle. Its not such a trivial class.
>Rip away all the setters, incl. the private ones, make it totally
>immutable (it's just a immutable "value object"), letting it have -one-
>constructor taking all the arguments, take away all synch penalties on
>construction, and optionally also make a utility Builder. Nice.
>
>The possibility for reusing all System.hashCodes within one millisecond
>seems to me -extremely- close to zero: To have this happen, one would need
>GC inbetween the instantiations, and having GC take -under- one
>millisecond, in addition to hitting the same "address" on the two
>instantiations, just seems plainly impossible.
I have no idea about the algorithm Java uses to allocate memory. The
probability of hitting the same address between allocations could be non
negligible maybe even quite high. Consider the sequence:
- allocate logging event 1
- allocate logging event 2
...
- allocate logging event N
- garbage collect logging events 1, 2, .. N
- allocate logging event N+1
- allocate logging event N+2
...
- allocate logging event N+M
...
All this can easily happen in the space of 1 millisecond.
Who can guarantee that no two events in a group of N+M events will not have
the same address? After all, the probability of any two persons having the
same birthday in a randomly chosen group of 23 persons is higher than 50%.
Yes, there are 365+1 possible birth dates but only a few people are needed
to produce a collision. (The Birthday Paradox)
>Endre
--
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: LoggingEvent.sequenceCount
Posted by Endre Stølsvik <En...@Stolsvik.com>.
Curt, good points!
On Mon, 10 Jan 2005, Curt Arnold wrote:
|
| > When logging an event, we should not build two objects
| > (LoggingEventBuilder+LoggingEvent) instead of the current one
| > (LoggingEvent).
| >
|
| In that high volume use and reentrant code, it might be best to
| continue to use a special constructor, but that might be made package
| private so it can only be used within log4j.
I don't see the reason for this: String has both a constructor, and a
Builder. Why couldn't LoggingEvent also have this? I do agree with Ceki
here - two objects should most definately not be needed when simply
wanting to make a new LoggingEvent object. But if you -have- to do it
incrementally, then a utiltiy-style Builder is nice. Another approach is
of course simply to set temp variables (its only four, isn't it?), and
finally, when you actually want to instantiate the LoggingEvent, then do
so with the variables - the Builder is really very very simple.
Rip away all the setters, incl. the private ones, make it totally
immutable (it's just a immutable "value object"), letting it have -one-
constructor taking all the arguments, take away all synch penalties on
construction, and optionally also make a utility Builder. Nice.
The possibility for reusing all System.hashCodes within one millisecond
seems to me -extremely- close to zero: To have this happen, one would need
GC inbetween the instantiations, and having GC take -under- one
millisecond, in addition to hitting the same "address" on the two
instantiations, just seems plainly impossible. If you also check for
message equality (potentially by storing the String's System.hashCode in
the same way as the LoggingEvent itself), and equality of level and
logger's String-representation of category, you'd -really- be pretty
certain that an "equal()" LoggingEvent really is the same LoggingEvent.
The last one might not be necessary.
Endre
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: LoggingEvent.sequenceCount
Posted by Curt Arnold <ca...@apache.org>.
On Jan 10, 2005, at 4:34 PM, Ceki Gülcü wrote:
> At 11:01 PM 1/10/2005, Curt Arnold wrote:
>
>> In the original message, I outlined two approaches and their
>> perceived drawbacks. One was just replacing sequenceCount with the
>> value of super.hashCode. This would likely work okay, but the
>> short-lifetime of LoggingEvent's might result in recurring values for
>> hashCode and that would have to be investigated.
>
> The hashCode is also computed over the timestamp. I'd expect the
> following version to give entirely satisfactory results.
>
> public int hashCode() {
> return (int)((timeStamp & 0xFFFFFFFF) ^ (eventId));
> }
>
>
>> My favored approach in that message was a full value comparison
>> implementation of equals and hashCode. I had not expected the
>> requirement that identical but distinct logging messages not compare
>> as equal. To address that short-coming, you could still add the
>> eventID and use that in a full value comparison implementation of
>> equals.
>
> If we pool LoggingEvent objects then successive events will have the
> same address and hence the same eventId.
>
> I am not 100% sure about the safety of eventId=super.hashCode(). With
> hundreds of events created and GCed every millisecond, the probability
> of two events having the same eventId seems non-negligible. We'd need
> to check for more fields in LoggingEvent.equals() but I guess that's
> exactly what you are suggesting. :-)
>
>> It may be adequate for equals and hashCode to only check the
>> timestamp, event id and message text. I think it would be very very
>> rare that two messages in the wild would have duplicate values for
>> all three, and if they did having Chainsaw drop one as a duplicate
>> would not be a significant issue.
>
> Except if we pool LoggingEvent objects
>
Object pooling was a was an beneficial optimization for early JVM's,
but I believe that the current accepted wisdom is that object pooling
for modern JVM's is generally detrimental. The next to last paragraph
end of item 4 on Effective Java has these quotes:
Conversely, avoiding object creation by maintaining your own object
pool is a bad idea unless the objects in the pool are extremely
heavyweight. A prototypical example... database connection. ..
Generally speaking, however maintaining your own object pools clutters
up your code, increases memory footprint and harms performance.
If I remember correctly, a large part of the rework of Xerces-J 1 to
create Xerces-J 2 was to eliminate memory pools which were added to
increase performance at the time, but slowed the application down on
later JVM's.
>> I'll take a stab at just the Builder rework. Do you have any
>> objections to my committing it if it seems pretty straightforward and
>> passes all the tests?
>
>
> No objections as long as the Category.forcedLog method remains
> unchanged.
Shouldn't be a problem.
> When logging an event, we should not build two objects
> (LoggingEventBuilder+LoggingEvent) instead of the current one
> (LoggingEvent).
>
In that high volume use and reentrant code, it might be best to
continue to use a special constructor, but that might be made package
private so it can only be used within log4j.
> Have you considered adding support for LoggingEvent object pooling?
See previous quotes.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: LoggingEvent.sequenceCount
Posted by Ceki Gülcü <ce...@qos.ch>.
At 11:01 PM 1/10/2005, Curt Arnold wrote:
>In the original message, I outlined two approaches and their perceived
>drawbacks. One was just replacing sequenceCount with the value of
>super.hashCode. This would likely work okay, but the short-lifetime of
>LoggingEvent's might result in recurring values for hashCode and that
>would have to be investigated.
The hashCode is also computed over the timestamp. I'd expect the following
version to give entirely satisfactory results.
public int hashCode() {
return (int)((timeStamp & 0xFFFFFFFF) ^ (eventId));
}
>My favored approach in that message was a full value comparison
>implementation of equals and hashCode. I had not expected the requirement
>that identical but distinct logging messages not compare as equal. To
>address that short-coming, you could still add the eventID and use that in
>a full value comparison implementation of equals.
If we pool LoggingEvent objects then successive events will have the same
address and hence the same eventId.
I am not 100% sure about the safety of eventId=super.hashCode(). With
hundreds of events created and GCed every millisecond, the probability of
two events having the same eventId seems non-negligible. We'd need to check
for more fields in LoggingEvent.equals() but I guess that's exactly what
you are suggesting. :-)
>It may be adequate for equals and hashCode to only check the timestamp,
>event id and message text. I think it would be very very rare that two
>messages in the wild would have duplicate values for all three, and if
>they did having Chainsaw drop one as a duplicate would not be a
>significant issue.
Except if we pool LoggingEvent objects
>I'll take a stab at just the Builder rework. Do you have any objections
>to my committing it if it seems pretty straightforward and passes all the
>tests?
No objections as long as the Category.forcedLog method remains unchanged.
When logging an event, we should not build two objects
(LoggingEventBuilder+LoggingEvent) instead of the current one (LoggingEvent).
Have you considered adding support for LoggingEvent object pooling?
--
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: LoggingEvent.sequenceCount
Posted by Curt Arnold <ca...@houston.rr.com>.
On Jan 10, 2005, at 3:05 PM, Ceki Gülcü wrote:
>
>> Two logging events that are identical in all other respects would
>> have a high likelihood of having distinct values for eventID and
>> acquiring the hash code would not incur an synchronization lock.
>
>
> So, "all" you are suggesting is to replace
>
> class LoggingEvent {
> long sequenceNumber;
> ...
>
> LoggingEvent(...) {
> ...
> sequenceNumber = sequenceCount++;
> }
> }
>
> with
>
> class LoggingEvent {
> int eventID ;
> ...
>
> LoggingEvent(...) {
> ...
> eventID = super.hashCode();
> }
>
> eventID replacing sequenceNumber. The existing implementations of
> equals() and hashCode() would remain the same. Correct?
>
In the original message, I outlined two approaches and their perceived
drawbacks. One was just replacing sequenceCount with the value of
super.hashCode. This would likely work okay, but the short-lifetime of
LoggingEvent's might result in recurring values for hashCode and that
would have to be investigated.
My favored approach in that message was a full value comparison
implementation of equals and hashCode. I had not expected the
requirement that identical but distinct logging messages not compare as
equal. To address that short-coming, you could still add the eventID
and use that in a full value comparison implementation of equals.
It may be adequate for equals and hashCode to only check the timestamp,
event id and message text. I think it would be very very rare that two
messages in the wild would have duplicate values for all three, and if
they did having Chainsaw drop one as a duplicate would not be a
significant issue.
>
> EventDetailLayout.java
> log4j-1.3/src/java/org/apache/log4j/chainsaw/layout line 196
> LayoutEditorPane.java
> log4j-1.3/src/java/org/apache/log4j/chainsaw/layout line 186
> DBReceiverJob.java log4j-1.3/src/java/org/apache/log4j/db line 98
> LogFilePatternReceiver.java
> log4j-1.3/src/java/org/apache/log4j/varia
> UtilLoggingXMLDecoder.java
> log4j-1.3/src/java/org/apache/log4j/xml line 380
> XMLDecoder.java
> log4j-1.3/src/java/org/apache/log4j/xml line 386
> PatternParserTest.java
> log4j-1.3/tests/src/java/org/apache/log4j/pattern line 57
>
Apparently you did a "clean" before building. For some reason, those
files didn't get recompiled when I did my ultra quick test and only
PatternParserTest got recompiled. They do all seem to be trying to
build a new LoggingEvent instead of modifying an existing one.
>
>> From that usage and your comments, it appears that your intent was
>> not to allow filters to modify messages (which was my mistaken guess
>> at the justification), but to provide an incremental "construction"
>> mechanism instead of passing all the arguments in the constructor.
>
> That is correct.
>
>> A much better approach to this would be to add a LoggingEventBuilder
>> (or LoggingEventFactory) class that would serve the same role as
>> StringBuffer does for String. The code in PatternParserTest would
>> look like:
>>
>> LoggingEventBuilder builder = new LoggingEventBuilder();
>> builder.setLogger(logger);
>> builder.setTimeStamp(now);
>> builder.setLevel(Level.INFO);
>> builder.setMessage("msg 1");
>> LoggingEvent event = builder.newInstance();
>>
>> Advantages of the approach:
>>
>> Violations of invariants (like an LoggingEvent must have a level) can
>> raise exceptions in the newInstance call. The other approach would
>> allow you to pass a LoggingEvent without a level which would likely
>> cause problems in the processing.
>
> Good point.
>
>> Multiple objects that are slightly different can be created by
>> repeated invocations of newInstance.
>
> Yes? How so?
>
LoggingEventBuilder builder = new LoggingEventBuilder();
builder.setLogger(logger);
builder.setTimeStamp(now);
builder.setLevel(Level.INFO);
builder.setMessage("msg 1");
LoggingEvent event = builder.newInstance();
builder.setMessage("msg 2");
LoggingEvent event2 = builder.newInstance();
>> Member variables can be marked as final.
>>
>> I assume that part of you motivation is to simplify the calling
>> signatures of the constructors. Instead of a zero-parameter
>> constructor, this pattern could be implemented with a one-parameter
>> constructor.
>>
>> public class LoggingEvent {
>> public LoggingEvent(final LoggingEventBuilder builder) {
>> ...
>> }
>> ...
>> }
>>
>> public class LoggingEventBuilder {
>> public LoggingEvent newInstance() {
>> return new LoggingEvent(builder);
>> }
>> }
>>
>> This technique allows new fields to be added to the LoggingEvent
>> without changing the signature of the LoggingEvent constructor.
>
> Sounds good.
>
I'll take a stab at just the Builder rework. Do you have any
objections to my committing it if it seems pretty straightforward and
passes all the tests?
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: LoggingEvent.sequenceCount
Posted by Ceki Gülcü <ce...@qos.ch>.
At 08:54 PM 1/10/2005, Curt Arnold wrote:
>What I was suggesting as a potential approach (with the drawbacks
>mentioned), is the value of hashCode at the time of creation could be
>obtained and stored as a distinct member that would be be used to
>distinguish objects that are identical in value in all other respects.
>That is replacing:
>
>LoggingEvent() {
>...
> synchronized(LoggingEvent.class) {
> sequenceNumber = sequenceCount++;
> }
>}
>
>with
>
>LoggingEvent() {
>...
> eventID = super.hashCode();
>}
I see. That could work quite well.
>Two logging events that are identical in all other respects would have a
>high likelihood of having distinct values for eventID and acquiring the
>hash code would not incur an synchronization lock.
So, "all" you are suggesting is to replace
class LoggingEvent {
long sequenceNumber;
...
LoggingEvent(...) {
...
sequenceNumber = sequenceCount++;
}
}
with
class LoggingEvent {
int eventID ;
...
LoggingEvent(...) {
...
eventID = super.hashCode();
}
eventID replacing sequenceNumber. The existing implementations of equals()
and hashCode() would remain the same. Correct?
>I missed that most of the setters are protected by checks that they
>haven't been set previously. setSequenceNumber and setTimestamp don't
>have those protections. setRenderedMessage looks like it could be used to
>override the creation message if the original message hadn't been rendered.
>
>I did an experiment by changing all the mutator classes to private
>access. The only thing that broke was PatternParserTest which used:
>
> event = new LoggingEvent();
> event.setLogger(logger);
> event.setTimeStamp(now);
> event.setLevel(Level.INFO);
> event.setMessage("msg 1");
>
>to construct an LoggingEvent, changing it to:
>
>
> event = new LoggingEvent(logger.getClass().toString(), logger, now,
> Level.INFO, "msg 1", null);
>
>compiled and all tests passed.
On my side changing setLevel to private breaks the following:
EventDetailLayout.java log4j-1.3/src/java/org/apache/log4j/chainsaw/layout
line 196
LayoutEditorPane.java log4j-1.3/src/java/org/apache/log4j/chainsaw/layout
line 186
DBReceiverJob.java log4j-1.3/src/java/org/apache/log4j/db line 98
LogFilePatternReceiver.java log4j-1.3/src/java/org/apache/log4j/varia
UtilLoggingXMLDecoder.java log4j-1.3/src/java/org/apache/log4j/xml
line 380
XMLDecoder.java log4j-1.3/src/java/org/apache/log4j/xml
line 386
PatternParserTest.java log4j-1.3/tests/src/java/org/apache/log4j/pattern
line 57
> From that usage and your comments, it appears that your intent was not to
> allow filters to modify messages (which was my mistaken guess at the
> justification), but to provide an incremental "construction" mechanism
> instead of passing all the arguments in the constructor.
That is correct.
>A much better approach to this would be to add a LoggingEventBuilder (or
>LoggingEventFactory) class that would serve the same role as StringBuffer
>does for String. The code in PatternParserTest would look like:
>
>LoggingEventBuilder builder = new LoggingEventBuilder();
>builder.setLogger(logger);
>builder.setTimeStamp(now);
>builder.setLevel(Level.INFO);
>builder.setMessage("msg 1");
>LoggingEvent event = builder.newInstance();
>
>Advantages of the approach:
>
>Violations of invariants (like an LoggingEvent must have a level) can
>raise exceptions in the newInstance call. The other approach would allow
>you to pass a LoggingEvent without a level which would likely cause
>problems in the processing.
Good point.
>Multiple objects that are slightly different can be created by repeated
>invocations of newInstance.
Yes? How so?
>Member variables can be marked as final.
>
>I assume that part of you motivation is to simplify the calling signatures
>of the constructors. Instead of a zero-parameter constructor, this
>pattern could be implemented with a one-parameter constructor.
>
>public class LoggingEvent {
> public LoggingEvent(final LoggingEventBuilder builder) {
> ...
> }
>...
>}
>
>public class LoggingEventBuilder {
> public LoggingEvent newInstance() {
> return new LoggingEvent(builder);
> }
>}
>
>This technique allows new fields to be added to the LoggingEvent without
>changing the signature of the LoggingEvent constructor.
Sounds good.
--
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: LoggingEvent.sequenceCount
Posted by Curt Arnold <ca...@apache.org>.
On Jan 10, 2005, at 12:33 PM, Ceki Gülcü wrote:
> At 05:43 PM 1/10/2005, Curt Arnold wrote:
>
>> I said Object.hashCode, the underlying implementation if you had
>> called super.hashCode() within logging event. It has similar
>> characteristics to a memory address,
>
> Yes, the Object.hashCode implementation is computed over the object's
> addres. However, two equal objects *must* return the same hashcode. In
> particular, two successive deserializations of the same event *must*
> return the same hashcode. Object.hashCode does not respect this
> fundamental constraint.
...
>
> Isn't this a self-defeating argument? If Object.hashCode can be used
> to check for equality, you might as well implement the equals() method
> as:
>
> class LoggingEvent {
>
> public boolean equals(Object r) {
> return this == r;
> }
> }
>
What I was suggesting as a potential approach (with the drawbacks
mentioned), is the value of hashCode at the time of creation could be
obtained and stored as a distinct member that would be be used to
distinguish objects that are identical in value in all other respects.
That is replacing:
LoggingEvent() {
...
synchronized(LoggingEvent.class) {
sequenceNumber = sequenceCount++;
}
}
with
LoggingEvent() {
...
eventID = super.hashCode();
}
Two logging events that are identical in all other respects would have
a high likelihood of having distinct values for eventID and acquiring
the hash code would not incur an synchronization lock.
>> I'd love to hear your thoughts behind adding the setMessage and other
>> mutators to LoggingEvent. It is generally a very good thing for
>> objects to be immutable since you can eliminate a score of potential
>> synchronization problems. In log4j 1.3, LoggingEvent's have become
>> mutable which means that we have to think about scenarios like a
>> LoggingEvent gets placed in an AsynchAppender then gets modified in a
>> filter. The AsyncAppender may or may not see the new message. It is
>> usually much easier to prevent synchronization issues by designing
>> immutable objects than to ensure that mutable but non synchronized
>> classes are used correctly.
>
> In 1.3, LoggingEvents are still immutable. Just have a look at its
> setter methods. The only mutable part is the LoggingEvent 'properties'
> member field. (The sequence number is mutable but that's just an
> omission. I'll correct it shortly.)
>
I missed that most of the setters are protected by checks that they
haven't been set previously. setSequenceNumber and setTimestamp don't
have those protections. setRenderedMessage looks like it could be used
to override the creation message if the original message hadn't been
rendered.
I did an experiment by changing all the mutator classes to private
access. The only thing that broke was PatternParserTest which used:
event = new LoggingEvent();
event.setLogger(logger);
event.setTimeStamp(now);
event.setLevel(Level.INFO);
event.setMessage("msg 1");
to construct an LoggingEvent, changing it to:
event = new LoggingEvent(logger.getClass().toString(), logger,
now, Level.INFO, "msg 1", null);
compiled and all tests passed.
From that usage and your comments, it appears that your intent was not
to allow filters to modify messages (which was my mistaken guess at the
justification), but to provide an incremental "construction" mechanism
instead of passing all the arguments in the constructor.
A much better approach to this would be to add a LoggingEventBuilder
(or LoggingEventFactory) class that would serve the same role as
StringBuffer does for String. The code in PatternParserTest would look
like:
LoggingEventBuilder builder = new LoggingEventBuilder();
builder.setLogger(logger);
builder.setTimeStamp(now);
builder.setLevel(Level.INFO);
builder.setMessage("msg 1");
LoggingEvent event = builder.newInstance();
Advantages of the approach:
Violations of invariants (like an LoggingEvent must have a level) can
raise exceptions in the newInstance call. The other approach would
allow you to pass a LoggingEvent without a level which would likely
cause problems in the processing.
Multiple objects that are slightly different can be created by repeated
invocations of newInstance.
Member variables can be marked as final.
I assume that part of you motivation is to simplify the calling
signatures of the constructors. Instead of a zero-parameter
constructor, this pattern could be implemented with a one-parameter
constructor.
public class LoggingEvent {
public LoggingEvent(final LoggingEventBuilder builder) {
...
}
...
}
public class LoggingEventBuilder {
public LoggingEvent newInstance() {
return new LoggingEvent(builder);
}
}
This technique allows new fields to be added to the LoggingEvent
without changing the signature of the LoggingEvent constructor.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: LoggingEvent.sequenceCount
Posted by Ceki Gülcü <ce...@qos.ch>.
At 05:43 PM 1/10/2005, Curt Arnold wrote:
>I said Object.hashCode, the underlying implementation if you had called
>super.hashCode() within logging event. It has similar characteristics to
>a memory address,
Yes, the Object.hashCode implementation is computed over the object's
addres. However, two equal objects *must* return the same hashcode. In
particular, two successive deserializations of the same event *must* return
the same hashcode. Object.hashCode does not respect this fundamental
constraint.
>it would be highly unlikely that two objects that exist at the same time
>would have the same Object.hashCode and that could be used as an identifier.
Unless the objects are pooled. We don't do that currently but might in the
future. In any case, Object.equals() is not an acceptable implementation
for us, as explained above.
>However, since LoggingEvents are typically short lived, you might see the
>same hashCode repeat for successive LoggingEvents, at least the
>probabiility of a collision would much higher. However, I guess it would
>be unlikely that they would repeat between garbage collections.
There are no guarantees about that (no repetitions between gcs).
>I don't think any of the performance tests attempt to dispatch logging
>requests from multiple threads. It might be good to add some so the cost
>of the sync lock could be determined.
+1
>>>The implementation would need to be start enough so that a cloned
>>>through serialization object would compare equal to the original and
>>>that prepareForDeferredProcessing would not effect either equals or hashCode.
>>>
>>>There would be at least two cases where the approaches give observably
>>>results. If distinct logging event with content and timestamp were
>>>received the current approach would report the messages as distinct
>>>while the new approach would report the messages as equal. This would
>>>only occur in tight loops like:
>>>
>>>for (int i = 0; i < 20; i++) {
>>> logger.info("Hello, world");
>>>}
>>>
>>>The current approach would see that as twenty distinct messages while
>>>the new approach would see all messages within the same millisecond as
>>>identical.
>>
>>Hence the necessity for a sequence counter.
>
>I didn't think this scenario would be a requirement. However if it is, it
>might be addressed by something other than a sequence counter
>(Object.hashCode might be sufficient for this use).
Isn't this a self-defeating argument? If Object.hashCode can be used to
check for equality, you might as well implement the equals() method as:
class LoggingEvent {
public boolean equals(Object r) {
return this == r;
}
}
>I'd love to hear your thoughts behind adding the setMessage and other
>mutators to LoggingEvent. It is generally a very good thing for objects
>to be immutable since you can eliminate a score of potential
>synchronization problems. In log4j 1.3, LoggingEvent's have become
>mutable which means that we have to think about scenarios like a
>LoggingEvent gets placed in an AsynchAppender then gets modified in a
>filter. The AsyncAppender may or may not see the new message. It is
>usually much easier to prevent synchronization issues by designing
>immutable objects than to ensure that mutable but non synchronized classes
>are used correctly.
In 1.3, LoggingEvents are still immutable. Just have a look at its setter
methods. The only mutable part is the LoggingEvent 'properties' member
field. (The sequence number is mutable but that's just an omission. I'll
correct it shortly.)
--
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: LoggingEvent.sequenceCount
Posted by Curt Arnold <ca...@apache.org>.
On Jan 10, 2005, at 6:36 AM, Ceki Gülcü wrote:
> At 06:23 AM 1/10/2005, Curt Arnold wrote:
>> I haven't worked any more on this, but I do intend to do so. I
>> thought that I would at least give a heads up that this issue isn't
>> dead.
>>
>> The current approach has a couple of drawbacks:
>
>> it incurs a synchronization for every dispatched message,
>
> yes
>
>> it adds a sequenceCount to the LoggingEvent which breaks
>> serialization compatibility with 1.2.x
>
> true, but once 1.3 is released, probably no one will care.
>
>> and might be mis-interpreted as a reliable means to detect dropped
>> messages,
>
> This is a lopsided argument, lying beyond the realm of the rational,
> which I find quite disturbing. It has been brought to the table
> before. I have given 3 solid reasons why no rational being could ever
> use it for missing message detection. If required, we can go over them
> again. See also
> http://marc.theaimsgroup.com/?l=log4j-dev&m=110442953800184&w=2
Everything so far has been a summary for those who come in late. I've
had users who have asked for a per-appender sequence count, it doesn't
strike me as far-fetched that could be temporarily mislead by the
current name but that could be addressed by renaming the field or
appropriate JavaDocs.
>
>> and would report as equal serializations of the same object in
>> different states (discussed later).
>
> true, but exactly the same can be said about the implementation which
> inspects each LoggingEvent field one by one. Presumably, even that
> implementation will first compare events for address equality. In the
> current log4j processing chain the same LoggingEvent instance can be
> modified as it is handled by different appenders.
The same thing could not be said about a value comparison. Successive
deserializations would have different object identities, so they would
not return at the "if == other" check, they would only return true if
they were field-by-field equal which they would not be since they could
have different messages.
>
>> Since LoggingEvents have a short lifetime, the values of
>> Object.hashCode (which I believe are similar to memory addresses) may
>> repeat and likely in an implementation dependent fashion.
>
> I don't understand what you are trying to say. In any case, the
> current LoggingEvent.hashCode implementation is damn near ideal.
>
I said Object.hashCode, the underlying implementation if you had called
super.hashCode() within logging event. It has similar characteristics
to a memory address, it would be highly unlikely that two objects that
exist at the same time would have the same Object.hashCode and that
could be used as an identifier. However, since LoggingEvents are
typically short lived, you might see the same hashCode repeat for
successive LoggingEvents, at least the probabiility of a collision
would much higher. However, I guess it would be unlikely that they
would repeat between garbage collections.
>> The approach that seems most reliable to me is to implement
>> LoggingEvent.equals as a real value comparison and create a
>> corresponding LoggingEvent.hashCode. That would avoid
>> synchronization tax on every logging request and would only cost the
>> callers of LoggingEvent.equals and LoggingEvent.hashCode.
>
> Point well taken. The tradeoff between the creation cost for everyone
> and the cost for the callers of LoggingEvent.equals and
> LoggingEvent.hashCode should be considered with care.
I don't think any of the performance tests attempt to dispatch logging
requests from multiple threads. It might be good to add some so the
cost of the sync lock could be determined.
>
>> The implementation would need to be start enough so that a cloned
>> through serialization object would compare equal to the original and
>> that prepareForDeferredProcessing would not effect either equals or
>> hashCode.
>>
>> There would be at least two cases where the approaches give
>> observably results. If distinct logging event with content and
>> timestamp were received the current approach would report the
>> messages as distinct while the new approach would report the messages
>> as equal. This would only occur in tight loops like:
>>
>> for (int i = 0; i < 20; i++) {
>> logger.info("Hello, world");
>> }
>>
>> The current approach would see that as twenty distinct messages while
>> the new approach would see all messages within the same millisecond
>> as identical.
>
> Hence the necessity for a sequence counter.
I didn't think this scenario would be a requirement. However if it is,
it might be addressed by something other than a sequence counter
(Object.hashCode might be sufficient for this use).
>
>> The other scenario is that the current approach sees all deserialized
>> copies of the same original object instance as identical.
>
> Yes, that is the intended behavior.
>> log4j 1.3 adds setter methods to LoggingEvent that are used by
>> Filters to change the message and other aspects of the logging event.
>> If a message is sent using the SocketAppender both before and after
>> Filter processing, with the current approach the messages would be
>> seen as identical even though the message content, level and other
>> aspects could be radically different.
>
> As mentioned above, that's the risk we take by allowing
> post-processing by filters.
>
I'd love to hear your thoughts behind adding the setMessage and other
mutators to LoggingEvent. It is generally a very good thing for
objects to be immutable since you can eliminate a score of potential
synchronization problems. In log4j 1.3, LoggingEvent's have become
mutable which means that we have to think about scenarios like a
LoggingEvent gets placed in an AsynchAppender then gets modified in a
filter. The AsyncAppender may or may not see the new message. It is
usually much easier to prevent synchronization issues by designing
immutable objects than to ensure that mutable but non synchronized
classes are used correctly.
>> My attack plan would be to first add unit tests that should check the
>> essential features on any acceptable approach and should be passed by
>> the current implementation, all the equals contract test cases
>> (equals to self, equals to null), comparison to deserialized clone,
>> hashCode invariant after prepareForDeferredProcessing. Then I would
>> try to flesh out the implementation and corresponding tests for the
>> value comparison implementation and report back to the list before
>> proceeding.
>
> Test cases. Mmmmmm.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
Re: LoggingEvent.sequenceCount
Posted by Ceki Gülcü <ce...@qos.ch>.
At 06:23 AM 1/10/2005, Curt Arnold wrote:
>I haven't worked any more on this, but I do intend to do so. I thought
>that I would at least give a heads up that this issue isn't dead.
>
>The current approach has a couple of drawbacks:
>it incurs a synchronization for every dispatched message,
yes
>it adds a sequenceCount to the LoggingEvent which breaks serialization
>compatibility with 1.2.x
true, but once 1.3 is released, probably no one will care.
> and might be mis-interpreted as a reliable means to detect dropped
> messages,
This is a lopsided argument, lying beyond the realm of the rational, which
I find quite disturbing. It has been brought to the table before. I have
given 3 solid reasons why no rational being could ever use it for missing
message detection. If required, we can go over them again. See also
http://marc.theaimsgroup.com/?l=log4j-dev&m=110442953800184&w=2
>and would report as equal serializations of the same object in different
>states (discussed later).
true, but exactly the same can be said about the implementation which
inspects each LoggingEvent field one by one. Presumably, even that
implementation will first compare events for address equality. In the
current log4j processing chain the same LoggingEvent instance can be
modified as it is handled by different appenders.
>Since LoggingEvents have a short lifetime, the values of Object.hashCode
>(which I believe are similar to memory addresses) may repeat and likely in
>an implementation dependent fashion.
I don't understand what you are trying to say. In any case, the current
LoggingEvent.hashCode implementation is damn near ideal.
>The approach that seems most reliable to me is to implement
>LoggingEvent.equals as a real value comparison and create a corresponding
>LoggingEvent.hashCode. That would avoid synchronization tax on every
>logging request and would only cost the callers of LoggingEvent.equals and
>LoggingEvent.hashCode.
Point well taken. The tradeoff between the creation cost for everyone and
the cost for the callers of LoggingEvent.equals and LoggingEvent.hashCode
should be considered with care.
>The implementation would need to be start enough so that a cloned through
>serialization object would compare equal to the original and that
>prepareForDeferredProcessing would not effect either equals or hashCode.
>
>There would be at least two cases where the approaches give observably
>results. If distinct logging event with content and timestamp were
>received the current approach would report the messages as distinct while
>the new approach would report the messages as equal. This would only
>occur in tight loops like:
>
>for (int i = 0; i < 20; i++) {
> logger.info("Hello, world");
>}
>
>The current approach would see that as twenty distinct messages while the
>new approach would see all messages within the same millisecond as identical.
Hence the necessity for a sequence counter.
>The other scenario is that the current approach sees all deserialized
>copies of the same original object instance as identical.
Yes, that is the intended behavior.
>log4j 1.3 adds setter methods to LoggingEvent that are used by Filters to
>change the message and other aspects of the logging event. If a message
>is sent using the SocketAppender both before and after Filter processing,
>with the current approach the messages would be seen as identical even
>though the message content, level and other aspects could be radically
>different.
As mentioned above, that's the risk we take by allowing post-processing by
filters.
>My attack plan would be to first add unit tests that should check the
>essential features on any acceptable approach and should be passed by the
>current implementation, all the equals contract test cases (equals to
>self, equals to null), comparison to deserialized clone, hashCode
>invariant after prepareForDeferredProcessing. Then I would try to flesh
>out the implementation and corresponding tests for the value comparison
>implementation and report back to the list before proceeding.
Test cases. Mmmmmm.
--
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