You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by rp...@apache.org on 2014/07/29 18:23:30 UTC
svn commit: r1614404 - in /logging/log4j/log4j2/trunk:
log4j-core/src/main/java/org/apache/logging/log4j/core/async/
log4j-core/src/main/java/org/apache/logging/log4j/core/impl/
log4j-core/src/test/java/org/apache/logging/log4j/core/ log4j-core/src/tes...
Author: rpopma
Date: Tue Jul 29 16:23:29 2014
New Revision: 1614404
URL: http://svn.apache.org/r1614404
Log:
LOG4J2-744 Avoid unnecessary Clock calls when TimestampMessage is logged
Added:
logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/TimestampMessageTest.java (with props)
logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTimestampMessageTest.java (with props)
logging/log4j/log4j2/trunk/log4j-core/src/test/resources/log4j2-744.xml (with props)
Modified:
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java
logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/Log4jLogEvent.java
logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java
logging/log4j/log4j2/trunk/src/changes/changes.xml
Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java?rev=1614404&r1=1614403&r2=1614404&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java (original)
+++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java Tue Jul 29 16:23:29 2014
@@ -33,6 +33,7 @@ import org.apache.logging.log4j.core.uti
import org.apache.logging.log4j.core.util.Loader;
import org.apache.logging.log4j.message.Message;
import org.apache.logging.log4j.message.MessageFactory;
+import org.apache.logging.log4j.message.TimestampMessage;
import org.apache.logging.log4j.status.StatusLogger;
import com.lmax.disruptor.BlockingWaitStrategy;
@@ -270,7 +271,9 @@ public class AsyncLogger extends Logger
// System.currentTimeMillis());
// CoarseCachedClock: 20% faster than system clock, 16ms gaps
// CachedClock: 10% faster than system clock, smaller gaps
- clock.currentTimeMillis());
+ // LOG4J2-744 avoid calling clock altogether if message has the timestamp
+ message instanceof TimestampMessage ? ((TimestampMessage) message).getTimestamp() :
+ clock.currentTimeMillis());
// LOG4J2-639: catch NPE if disruptor field was set to null after our check above
try {
Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java?rev=1614404&r1=1614403&r2=1614404&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java (original)
+++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java Tue Jul 29 16:23:29 2014
@@ -30,7 +30,6 @@ import org.apache.logging.log4j.core.imp
import org.apache.logging.log4j.core.lookup.StrSubstitutor;
import org.apache.logging.log4j.message.Message;
import org.apache.logging.log4j.message.SimpleMessage;
-import org.apache.logging.log4j.message.TimestampMessage;
import org.apache.logging.log4j.util.Strings;
import com.lmax.disruptor.EventFactory;
@@ -201,10 +200,6 @@ public class RingBufferLogEvent implemen
@Override
public long getTimeMillis() {
- final Message msg = getMessage();
- if (msg instanceof TimestampMessage) { // LOG4J2-455
- return ((TimestampMessage) msg).getTimestamp();
- }
return currentTimeMillis;
}
Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/Log4jLogEvent.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/Log4jLogEvent.java?rev=1614404&r1=1614403&r2=1614404&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/Log4jLogEvent.java (original)
+++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/Log4jLogEvent.java Tue Jul 29 16:23:29 2014
@@ -98,7 +98,11 @@ public class Log4jLogEvent implements Lo
this(loggerName, marker, loggerFQCN, level, message, t,
createMap(properties),
ThreadContext.getDepth() == 0 ? null : ThreadContext.cloneStack(), null,
- null, clock.currentTimeMillis()); // LOG4J2-628 use log4j.Clock for timestamps
+ null,
+ // LOG4J2-628 use log4j.Clock for timestamps
+ // LOG4J2-744 unless TimestampMessage already has one
+ message instanceof TimestampMessage ? ((TimestampMessage) message).getTimestamp() :
+ clock.currentTimeMillis());
}
/**
Added: logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/TimestampMessageTest.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/TimestampMessageTest.java?rev=1614404&view=auto
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/TimestampMessageTest.java (added)
+++ logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/TimestampMessageTest.java Tue Jul 29 16:23:29 2014
@@ -0,0 +1,93 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache license, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the license for the specific language governing permissions and
+ * limitations under the license.
+ */
+package org.apache.logging.log4j.core;
+
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.core.util.Clock;
+import org.apache.logging.log4j.core.util.ClockFactory;
+import org.apache.logging.log4j.core.util.Constants;
+import org.apache.logging.log4j.junit.InitialLoggerContext;
+import org.apache.logging.log4j.message.SimpleMessage;
+import org.apache.logging.log4j.message.TimestampMessage;
+import org.apache.logging.log4j.test.appender.ListAppender;
+import org.apache.logging.log4j.util.Strings;
+import org.junit.*;
+
+import java.util.List;
+
+import static org.junit.Assert.*;
+
+/**
+ * Confirms that if you log a {@link TimestampMessage} then there are no unnecessary calls to {@link Clock}.
+ * <p/>
+ * See LOG4J2-744.
+ */
+public class TimestampMessageTest {
+ private ListAppender app;
+
+ @ClassRule
+ public static InitialLoggerContext context = new InitialLoggerContext("log4j2-744.xml");
+
+ @BeforeClass
+ public static void beforeClass() {
+ System.setProperty(ClockFactory.PROPERTY_NAME, PoisonClock.class.getName());
+ }
+
+ @Before
+ public void setUp() throws Exception {
+ this.app = context.getListAppender("List").clear();
+ }
+
+ @AfterClass
+ public static void afterClass() {
+ System.setProperty(Constants.LOG4J_CONTEXT_SELECTOR, Strings.EMPTY);
+ System.setProperty(ClockFactory.PROPERTY_NAME, Strings.EMPTY);
+ }
+
+ @Test
+ public void testTimestampMessage() {
+ final Logger log = context.getLogger("TimestampMessageTest");
+ log.info(new TimeMsg("Message with embedded timestamp", 123456789000L));
+ final List<String> msgs = app.getMessages();
+ assertNotNull(msgs);
+ assertEquals(1, msgs.size());
+ final String NL = System.getProperty("line.separator");
+ assertEquals("123456789000 Message with embedded timestamp" + NL, msgs.get(0));
+ }
+
+ public static class PoisonClock implements Clock {
+ @Override
+ public long currentTimeMillis() {
+ throw new RuntimeException("This should not have been called");
+ }
+ }
+
+ static class TimeMsg extends SimpleMessage implements TimestampMessage {
+ private static final long serialVersionUID = 1L;
+ private final long timestamp;
+
+ public TimeMsg(final String msg, final long timestamp) {
+ super(msg);
+ this.timestamp = timestamp;
+ }
+
+ @Override
+ public long getTimestamp() {
+ return timestamp;
+ }
+ }
+}
Propchange: logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/TimestampMessageTest.java
------------------------------------------------------------------------------
svn:eol-style = native
Added: logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTimestampMessageTest.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTimestampMessageTest.java?rev=1614404&view=auto
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTimestampMessageTest.java (added)
+++ logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTimestampMessageTest.java Tue Jul 29 16:23:29 2014
@@ -0,0 +1,101 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache license, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the license for the specific language governing permissions and
+ * limitations under the license.
+ */
+package org.apache.logging.log4j.core.async;
+
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.core.LifeCycle;
+import org.apache.logging.log4j.core.config.ConfigurationFactory;
+import org.apache.logging.log4j.core.util.Clock;
+import org.apache.logging.log4j.core.util.ClockFactory;
+import org.apache.logging.log4j.core.util.Constants;
+import org.apache.logging.log4j.message.SimpleMessage;
+import org.apache.logging.log4j.message.TimestampMessage;
+import org.apache.logging.log4j.util.Strings;
+import org.junit.AfterClass;
+import org.junit.BeforeClass;
+import org.junit.Test;
+
+import java.io.BufferedReader;
+import java.io.File;
+import java.io.FileReader;
+
+import static org.junit.Assert.*;
+
+/**
+ * Confirms that if you log a {@link TimestampMessage} then there are no unnecessary calls to {@link Clock}.
+ * <p/>
+ * See LOG4J2-744.
+ */
+public class AsyncLoggerTimestampMessageTest {
+
+ @BeforeClass
+ public static void beforeClass() {
+ System.setProperty(Constants.LOG4J_CONTEXT_SELECTOR,
+ AsyncLoggerContextSelector.class.getName());
+ System.setProperty(ConfigurationFactory.CONFIGURATION_FILE_PROPERTY,
+ "AsyncLoggerTimestampMessageTest.xml");
+ System.setProperty(ClockFactory.PROPERTY_NAME,
+ PoisonClock.class.getName());
+ }
+
+ @AfterClass
+ public static void afterClass() {
+ System.setProperty(Constants.LOG4J_CONTEXT_SELECTOR, Strings.EMPTY);
+ System.setProperty(ClockFactory.PROPERTY_NAME, Strings.EMPTY);
+ }
+
+ @Test
+ public void testAsyncLogWritesToLog() throws Exception {
+
+ final File f = new File("target", "AsyncLoggerTimestampMessageTest.log");
+ // System.out.println(f.getAbsolutePath());
+ f.delete();
+ final Logger log = LogManager.getLogger("com.foo.Bar");
+ log.info(new TimeMsg("Async logger msg with embedded timestamp", 123456789000L));
+ ((LifeCycle) LogManager.getContext()).stop(); // stop async thread
+
+ final BufferedReader reader = new BufferedReader(new FileReader(f));
+ final String line1 = reader.readLine();
+ reader.close();
+ f.delete();
+ assertNotNull(line1);
+ assertTrue("line1 correct", line1.equals("123456789000 Async logger msg with embedded timestamp"));
+ }
+
+ public static class PoisonClock implements Clock {
+ @Override
+ public long currentTimeMillis() {
+ throw new RuntimeException("This should not have been called");
+ }
+ }
+
+ static class TimeMsg extends SimpleMessage implements TimestampMessage {
+ private static final long serialVersionUID = 1L;
+ private final long timestamp;
+
+ public TimeMsg(final String msg, final long timestamp) {
+ super(msg);
+ this.timestamp = timestamp;
+ }
+
+ @Override
+ public long getTimestamp() {
+ return timestamp;
+ }
+ }
+}
Propchange: logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTimestampMessageTest.java
------------------------------------------------------------------------------
svn:eol-style = native
Modified: logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java?rev=1614404&r1=1614403&r2=1614404&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java (original)
+++ logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java Tue Jul 29 16:23:29 2014
@@ -34,7 +34,6 @@ import org.apache.logging.log4j.core.Log
import org.apache.logging.log4j.core.impl.ThrowableProxy;
import org.apache.logging.log4j.message.Message;
import org.apache.logging.log4j.message.SimpleMessage;
-import org.apache.logging.log4j.message.TimestampMessage;
import org.apache.logging.log4j.spi.MutableThreadContextStack;
import org.junit.Test;
@@ -102,61 +101,6 @@ public class RingBufferLogEventTest {
assertEquals(123, evt.getTimeMillis());
}
- static class TimeMsg implements Message, TimestampMessage {
- private static final long serialVersionUID = -2038413535672337079L;
- private final String msg;
- private final long timestamp;
-
- public TimeMsg(final String msg, final long timestamp) {
- this.msg = msg;
- this.timestamp = timestamp;
- }
-
- @Override
- public long getTimestamp() {
- return timestamp;
- }
-
- @Override
- public String getFormattedMessage() {
- return msg;
- }
-
- @Override
- public String getFormat() {
- return null;
- }
-
- @Override
- public Object[] getParameters() {
- return null;
- }
-
- @Override
- public Throwable getThrowable() {
- return null;
- }
- }
-
- @Test
- public void testGetMillisReturnsMsgTimestampForTimestampMessage() {
- final RingBufferLogEvent evt = new RingBufferLogEvent();
- final String loggerName = null;
- final Marker marker = null;
- final String fqcn = null;
- final Level level = null;
- final Message data = new TimeMsg("", 567);
- final Throwable t = null;
- final Map<String, String> map = null;
- final ContextStack contextStack = null;
- final String threadName = null;
- final StackTraceElement location = null;
- final long currentTimeMillis = 123;
- evt.setValues(null, loggerName, marker, fqcn, level, data, t, map,
- contextStack, threadName, location, currentTimeMillis);
- assertEquals(567, evt.getTimeMillis());
- }
-
@Test
public void testSerializationDeserialization() throws IOException, ClassNotFoundException {
final RingBufferLogEvent evt = new RingBufferLogEvent();
Added: logging/log4j/log4j2/trunk/log4j-core/src/test/resources/log4j2-744.xml
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/test/resources/log4j2-744.xml?rev=1614404&view=auto
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-core/src/test/resources/log4j2-744.xml (added)
+++ logging/log4j/log4j2/trunk/log4j-core/src/test/resources/log4j2-744.xml Tue Jul 29 16:23:29 2014
@@ -0,0 +1,31 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<!--
+ Licensed to the Apache Software Foundation (ASF) under one or more
+ contributor license agreements. See the NOTICE file distributed with
+ this work for additional information regarding copyright ownership.
+ The ASF licenses this file to You under the Apache License, Version 2.0
+ (the "License"); you may not use this file except in compliance with
+ the License. You may obtain a copy of the License at
+
+ http://www.apache.org/licenses/LICENSE-2.0
+
+ Unless required by applicable law or agreed to in writing, software
+ distributed under the License is distributed on an "AS IS" BASIS,
+ WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ See the License for the specific language governing permissions and
+ limitations under the License.
+
+-->
+<!-- https://issues.apache.org/jira/browse/LOG4J2-744 -->
+<Configuration status="OFF">
+ <Appenders>
+ <List name="List">
+ <PatternLayout pattern="%d{UNIX_MILLIS} %msg%n" />
+ </List>
+ </Appenders>
+ <Loggers>
+ <Root level="TRACE">
+ <AppenderRef ref="List" />
+ </Root>
+ </Loggers>
+</Configuration>
\ No newline at end of file
Propchange: logging/log4j/log4j2/trunk/log4j-core/src/test/resources/log4j2-744.xml
------------------------------------------------------------------------------
svn:eol-style = native
Modified: logging/log4j/log4j2/trunk/src/changes/changes.xml
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/changes/changes.xml?rev=1614404&r1=1614403&r2=1614404&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/src/changes/changes.xml (original)
+++ logging/log4j/log4j2/trunk/src/changes/changes.xml Tue Jul 29 16:23:29 2014
@@ -22,6 +22,9 @@
</properties>
<body>
<release version="2.0.1" date="2014-mm-dd" description="?">
+ <action issue="LOG4J2-744" dev="rpopma" type="fix" due-to="Scott Harrington">
+ Avoid unnecessary Clock calls when TimestampMessage is logged.
+ </action>
<action issue="LOG4J2-704" dev="rpopma" type="fix">
Improved error message if configuration file not found.
</action>