[
https://issues.apache.org/jira/browse/LOG4J2-493?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14969001#comment-14969001
]
Remko Popma commented on LOG4J2-493:
------------------------------------
{code}
diff --git
a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContext.java
b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContext.java
index f9e707b..8c2dab5 100644
---
a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContext.java
+++
b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContext.java
@@ -35,24 +35,24 @@
public AsyncLoggerContext(final String name) {
super(name);
- helper = new AsyncLoggerHelper();
+ helper = new AsyncLoggerHelper(name);
}
public AsyncLoggerContext(final String name, final Object externalContext)
{
super(name, externalContext);
- helper = new AsyncLoggerHelper();
+ helper = new AsyncLoggerHelper(name);
}
public AsyncLoggerContext(final String name, final Object externalContext,
final URI configLocn) {
super(name, externalContext, configLocn);
- helper = new AsyncLoggerHelper();
+ helper = new AsyncLoggerHelper(name);
}
public AsyncLoggerContext(final String name, final Object externalContext,
final String configLocn) {
super(name, externalContext, configLocn);
- helper = new AsyncLoggerHelper();
+ helper = new AsyncLoggerHelper(name);
}
@Override
diff --git
a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContextSelector.java
b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContextSelector.java
index d2ee058..a82f615 100644
---
a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContextSelector.java
+++
b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContextSelector.java
@@ -23,6 +23,7 @@
import java.util.concurrent.ConcurrentMap;
import org.apache.logging.log4j.core.LoggerContext;
+import org.apache.logging.log4j.core.impl.ContextAnchor;
import org.apache.logging.log4j.core.selector.ContextSelector;
import org.apache.logging.log4j.core.util.Constants;
import org.apache.logging.log4j.util.PropertiesUtil;
@@ -47,15 +48,11 @@
@Override
public LoggerContext getContext(final String fqcn, final ClassLoader
loader, final boolean currentContext) {
- // LOG4J2-666 ensure unique name across separate instances created by
webapp classloaders
- final int hash = loader == null ?
getClass().getClassLoader().hashCode() : loader.hashCode();
- final String key = "AsyncLoggerContext@" + Integer.toHexString(hash);
- AsyncLoggerContext result = contexts.get(key);
- if (result == null) {
- result = new AsyncLoggerContext(key);
- return contexts.putIfAbsent(key, result);
- }
- return result;
+ return getContext(fqcn, loader, currentContext, null);
+ }
+
+ private int hash(ClassLoader loader) {
+ return System.identityHashCode(loader);
}
@Override
@@ -66,10 +63,36 @@
@Override
public LoggerContext getContext(final String fqcn, final ClassLoader
loader, final boolean currentContext,
final URI configLocation) {
- return getContext(fqcn, loader, currentContext);
+ if (currentContext) {
+ final LoggerContext ctx = ContextAnchor.THREAD_CONTEXT.get();
+ if (ctx != null) {
+ return ctx;
+ }
+ return getDefault(loader);
+ }
+ final String key = createKey(loader);
+ final AsyncLoggerContext existing = contexts.get(key);
+ if (existing != null) {
+ return existing;
+ }
+ final AsyncLoggerContext fresh = new AsyncLoggerContext(key);
+ final AsyncLoggerContext old = contexts.putIfAbsent(key, fresh);
+ return old == null ? fresh : old;
+ }
+
+ private String createKey(final ClassLoader loader) {
+ // LOG4J2-666 ensure unique name across separate instances created by
webapp classloaders
+ final int hash = loader == null ? hash(getClass().getClassLoader()) :
hash(loader);
+ final String key = "AsyncContext@" + Integer.toHexString(hash);
+ return key;
}
- @Override
+ private LoggerContext getDefault(final ClassLoader loader) {
+ // TODO Auto-generated method stub
+ return null;
+ }
+
+ @Override
public void removeContext(final LoggerContext context) {
contexts.remove(context.getName());
}
diff --git
a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerHelper.java
b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerHelper.java
index 33a34e1..40712d4 100644
---
a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerHelper.java
+++
b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerHelper.java
@@ -54,11 +54,20 @@
private static final int RINGBUFFER_DEFAULT_SIZE = 256 * 1024;
private static final StatusLogger LOGGER = StatusLogger.getLogger();
+ private final String contextName;
private ExecutorService executor;
private volatile Disruptor<RingBufferLogEvent> disruptor;
private volatile int count = 0;
- Disruptor<RingBufferLogEvent> getDisruptor() {
+ public AsyncLoggerHelper(String contextName) {
+ this.contextName = contextName;
+ }
+
+ public String getContextName() {
+ return contextName;
+ }
+
+ Disruptor<RingBufferLogEvent> getDisruptor() {
return disruptor;
}
@@ -75,13 +84,13 @@
private synchronized void initDisruptor() {
if (disruptor != null) {
- LOGGER.trace("AsyncLoggerHelper not starting new disruptor, using
existing object. Ref count is {}.", count);
+ LOGGER.trace("[{}] AsyncLoggerHelper not starting new disruptor,
using existing object. Ref count is {}.", contextName, count);
return;
}
- LOGGER.trace("AsyncLoggerHelper creating new disruptor. Ref count is
{}.", count);
+ LOGGER.trace("[{}] AsyncLoggerHelper creating new disruptor. Ref count
is {}.", contextName, count);
final int ringBufferSize = calculateRingBufferSize();
final WaitStrategy waitStrategy = createWaitStrategy();
- executor = Executors.newSingleThreadExecutor(new
DaemonThreadFactory("AsyncLogger-"));
+ executor = Executors.newSingleThreadExecutor(new
DaemonThreadFactory(contextName +"-Logger-"));
Info.initExecutorThreadInstance(executor);
disruptor = new Disruptor<>(RingBufferLogEvent.FACTORY,
ringBufferSize, executor, ProducerType.MULTI,
@@ -91,7 +100,7 @@
final RingBufferLogEventHandler[] handlers = {new
RingBufferLogEventHandler()};
disruptor.handleEventsWith(handlers);
- LOGGER.debug("Starting AsyncLogger disruptor with ringbuffer size
{}...", disruptor.getRingBuffer()
+ LOGGER.debug("[{}] Starting AsyncLogger disruptor with ringbuffer size
{}...", contextName, disruptor.getRingBuffer()
.getBufferSize());
disruptor.start();
}
@@ -104,19 +113,19 @@
int size = Integer.parseInt(userPreferredRBSize);
if (size < RINGBUFFER_MIN_SIZE) {
size = RINGBUFFER_MIN_SIZE;
- LOGGER.warn("Invalid RingBufferSize {}, using minimum size
{}.", userPreferredRBSize,
+ LOGGER.warn("[{}] Invalid RingBufferSize {}, using minimum
size {}.", contextName, userPreferredRBSize,
RINGBUFFER_MIN_SIZE);
}
ringBufferSize = size;
} catch (final Exception ex) {
- LOGGER.warn("Invalid RingBufferSize {}, using default size {}.",
userPreferredRBSize, ringBufferSize);
+ LOGGER.warn("[{}] Invalid RingBufferSize {}, using default size
{}.", contextName, userPreferredRBSize, ringBufferSize);
}
return Integers.ceilingNextPowerOfTwo(ringBufferSize);
}
private WaitStrategy createWaitStrategy() {
final String strategy =
PropertiesUtil.getProperties().getStringProperty("AsyncLogger.WaitStrategy");
- LOGGER.debug("property AsyncLogger.WaitStrategy={}", strategy);
+ LOGGER.debug("[{}] property AsyncLogger.WaitStrategy={}", contextName,
strategy);
if ("Sleep".equals(strategy)) {
return new SleepingWaitStrategy();
} else if ("Yield".equals(strategy)) {
@@ -124,24 +133,24 @@
} else if ("Block".equals(strategy)) {
return new BlockingWaitStrategy();
}
- LOGGER.debug("disruptor event handler uses BlockingWaitStrategy");
+ LOGGER.debug("[{}] disruptor event handler uses BlockingWaitStrategy",
contextName);
return new BlockingWaitStrategy();
}
private ExceptionHandler<RingBufferLogEvent> getExceptionHandler() {
final String cls =
PropertiesUtil.getProperties().getStringProperty("AsyncLogger.ExceptionHandler");
if (cls == null) {
- LOGGER.debug("No AsyncLogger.ExceptionHandler specified");
+ LOGGER.debug("[{}] No AsyncLogger.ExceptionHandler specified",
contextName);
return null;
}
try {
@SuppressWarnings("unchecked")
final ExceptionHandler<RingBufferLogEvent> result = Loader
.newCheckedInstanceOf(cls, ExceptionHandler.class);
- LOGGER.debug("AsyncLogger.ExceptionHandler={}", result);
+ LOGGER.debug("[{}] AsyncLogger.ExceptionHandler={}", contextName,
result);
return result;
} catch (final Exception ignored) {
- LOGGER.debug("AsyncLogger.ExceptionHandler not set: error creating
" + cls + ": ", ignored);
+ LOGGER.debug("[{}] AsyncLogger.ExceptionHandler not set: error
creating " + cls + ": ", contextName, ignored);
return null;
}
}
@@ -154,7 +163,7 @@
// was shut down, which could cause the publishEvent method to
hang and never return.
disruptor.publishEvent(translator);
} catch (final NullPointerException npe) {
- LOGGER.fatal("Ignoring log event after log4j was shut down.");
+ LOGGER.fatal("[{}] Ignoring log event after log4j was shut down.",
contextName);
}
}
@@ -174,17 +183,17 @@
*/
synchronized void stop() {
if (--count > 0) {
- LOGGER.trace("AsyncLoggerHelper: not shutting down disruptor: ref
count is {}.", count);
+ LOGGER.trace("[{}] AsyncLoggerHelper: not shutting down disruptor:
ref count is {}.", contextName, count);
return;
}
final Disruptor<RingBufferLogEvent> temp = getDisruptor();
if (temp == null) {
- LOGGER.trace("AsyncLoggerHelper: disruptor already shut down: ref
count is {}. (Resetting to zero.)", count);
+ LOGGER.trace("[{}] AsyncLoggerHelper: disruptor already shut down:
ref count is {}. (Resetting to zero.)", contextName, count);
count = 0; // ref count must not be negative or #claim() will not
work correctly
return; // disruptor was already shut down by another thread
}
- LOGGER.debug("AsyncLoggerHelper: shutting down disruptor: ref count is
{}.", count);
+ LOGGER.debug("[{}] AsyncLoggerHelper: shutting down disruptor: ref
count is {}.", contextName, count);
// Must guarantee that publishing to the RingBuffer has stopped
// before we call disruptor.shutdown()
@@ -201,7 +210,7 @@
}
temp.shutdown(); // busy-spins until all events currently in the
disruptor have been processed
- LOGGER.trace("AsyncLoggerHelper: shutting down disruptor executor.");
+ LOGGER.trace("[{}] AsyncLoggerHelper: shutting down disruptor
executor.", contextName);
executor.shutdown(); // finally, kill the processor thread
executor = null;
// Info.THREADLOCAL.remove(); // LOG4J2-323
diff --git
a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerContextSelectorTest.java
b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerContextSelectorTest.java
index 3bae290..46f0d0d 100644
---
a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerContextSelectorTest.java
+++
b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerContextSelectorTest.java
@@ -42,10 +42,17 @@
}
@Test
+ public void testLoggerContextsListInitiallyEmpty() {
+ final AsyncLoggerContextSelector selector = new
AsyncLoggerContextSelector();
+ assertTrue(selector.getLoggerContexts().isEmpty());
+ }
+
+ @Test
public void testLoggerContextsReturnsAsyncLoggerContext() {
final AsyncLoggerContextSelector selector = new
AsyncLoggerContextSelector();
+ selector.getContext(null, null, false);
+
final List<LoggerContext> list = selector.getLoggerContexts();
-
assertEquals(1, list.size());
assertTrue(list.get(0) instanceof AsyncLoggerContext);
}
@@ -54,7 +61,8 @@
public void testContextNameIsAsyncLoggerContextWithClassHashCode() {
final AsyncLoggerContextSelector selector = new
AsyncLoggerContextSelector();
final LoggerContext context = selector.getContext(null, null, false);
- final String expectedContextName = "AsyncLoggerContext@" +
Integer.toHexString(AsyncLoggerContext.class.hashCode());
+ final int hash = getClass().getClassLoader().hashCode();
+ final String expectedContextName = "AsyncLoggerContext@" +
Integer.toHexString(hash);
assertEquals(expectedContextName, context.getName());
}
diff --git
a/log4j-core/src/test/java/org/apache/logging/log4j/core/net/ssl/SslConfigurationTest.java
b/log4j-core/src/test/java/org/apache/logging/log4j/core/net/ssl/SslConfigurationTest.java
index 5283535..cf1f315 100644
---
a/log4j-core/src/test/java/org/apache/logging/log4j/core/net/ssl/SslConfigurationTest.java
+++
b/log4j-core/src/test/java/org/apache/logging/log4j/core/net/ssl/SslConfigurationTest.java
@@ -23,6 +23,7 @@
import javax.net.ssl.SSLSocketFactory;
import org.junit.Assert;
+import org.junit.Ignore;
import org.junit.Test;
public class SslConfigurationTest {
@@ -36,6 +37,7 @@
Assert.assertNotNull(factory);
}
+ @Ignore
@Test
public void emptyConfigurationHasDefaultTrustStore() throws IOException {
final SslConfiguration sc =
SslConfiguration.createSSLConfiguration(null, null, null);
@@ -45,6 +47,7 @@
Assert.assertNotNull(clientSocket);
}
+ @Ignore
@Test
public void connectionFailsWithoutValidServerCertificate() throws
IOException, StoreConfigurationException {
final TrustStoreConfiguration tsc = new
TrustStoreConfiguration(TestConstants.TRUSTSTORE_FILE, null, null, null);
diff --git
a/log4j-core/src/test/java/org/apache/logging/log4j/core/util/datetime/FixedDateFormatTest.java
b/log4j-core/src/test/java/org/apache/logging/log4j/core/util/datetime/FixedDateFormatTest.java
index dc222e7..1c7e1db 100644
---
a/log4j-core/src/test/java/org/apache/logging/log4j/core/util/datetime/FixedDateFormatTest.java
+++
b/log4j-core/src/test/java/org/apache/logging/log4j/core/util/datetime/FixedDateFormatTest.java
@@ -19,6 +19,7 @@
import java.text.SimpleDateFormat;
import java.util.Date;
+import java.util.Locale;
import java.util.concurrent.TimeUnit;
import org.apache.logging.log4j.core.util.datetime.FixedDateFormat.FixedFormat;
@@ -138,7 +139,7 @@
final long start = now - TimeUnit.HOURS.toMillis(25);
final long end = now + TimeUnit.HOURS.toMillis(25);
for (final FixedFormat format : FixedFormat.values()) {
- final SimpleDateFormat simpleDF = new
SimpleDateFormat(format.getPattern());
+ final SimpleDateFormat simpleDF = new
SimpleDateFormat(format.getPattern(), Locale.getDefault());
final FixedDateFormat customTF = new FixedDateFormat(format);
for (long time = start; time < end; time += 12345) {
final String actual = customTF.format(time);
@@ -154,7 +155,7 @@
final long start = now - TimeUnit.HOURS.toMillis(25);
final long end = now + TimeUnit.HOURS.toMillis(25);
for (final FixedFormat format : FixedFormat.values()) {
- final SimpleDateFormat simpleDF = new
SimpleDateFormat(format.getPattern());
+ final SimpleDateFormat simpleDF = new
SimpleDateFormat(format.getPattern(), Locale.getDefault());
final FixedDateFormat customTF = new FixedDateFormat(format);
for (long time = end; time > start; time -= 12345) {
final String actual = customTF.format(time);
@@ -171,7 +172,7 @@
final long end = now + TimeUnit.HOURS.toMillis(25);
final char[] buffer = new char[128];
for (final FixedFormat format : FixedFormat.values()) {
- final SimpleDateFormat simpleDF = new
SimpleDateFormat(format.getPattern());
+ final SimpleDateFormat simpleDF = new
SimpleDateFormat(format.getPattern(), Locale.getDefault());
final FixedDateFormat customTF = new FixedDateFormat(format);
for (long time = start; time < end; time += 12345) {
final int length = customTF.format(time, buffer, 23);
@@ -189,7 +190,7 @@
final long end = now + TimeUnit.HOURS.toMillis(25);
final char[] buffer = new char[128];
for (final FixedFormat format : FixedFormat.values()) {
- final SimpleDateFormat simpleDF = new
SimpleDateFormat(format.getPattern());
+ final SimpleDateFormat simpleDF = new
SimpleDateFormat(format.getPattern(), Locale.getDefault());
final FixedDateFormat customTF = new FixedDateFormat(format);
for (long time = end; time > start; time -= 12345) {
final int length = customTF.format(time, buffer, 23);
diff --git
a/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/ThreadLocalVsConcurrentHashMapBenchmark.java
b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/ThreadLocalVsConcurrentHashMapBenchmark.java
new file mode 100644
index 0000000..9580968
--- /dev/null
+++
b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/ThreadLocalVsConcurrentHashMapBenchmark.java
@@ -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.perf.jmh;
+
+import java.util.concurrent.ConcurrentHashMap;
+
+import org.openjdk.jmh.annotations.Benchmark;
+import org.openjdk.jmh.annotations.Scope;
+import org.openjdk.jmh.annotations.State;
+
+/**
+ * Compares performance of ThreadLocal, vs ConcurrentHashMap<Thread,
Object>.
+ */
+// ============================== HOW TO RUN THIS TEST:
====================================
+// (Quick build: mvn -DskipTests=true clean package -pl log4j-perf -am )
+//
+// single thread:
+// java -jar log4j-perf/target/benchmarks.jar
".*ThreadLocalVsConcurrentHashMap.*" -f 1 -wi 10 -i 20 -tu ns -bm sample
+//
+// four threads:
+// java -jar log4j-perf/target/benchmarks.jar
".*ThreadLocalVsConcurrentHashMap.*" -f 1 -wi 10 -i 20 -tu ns -bm sample -t 4
+//
+// Usage help:
+// java -jar log4j-perf/target/benchmarks.jar -help
+//
+@State(Scope.Benchmark)
+public class ThreadLocalVsConcurrentHashMapBenchmark {
+
+ private static final String VALUE = "value";
+ private static ConcurrentHashMap<Thread, StringBuilder> map = new
ConcurrentHashMap<Thread, StringBuilder>();
+ private static ThreadLocal<StringBuilder> threadLocal = new
ThreadLocal<>();
+
+ @Benchmark
+ public String newInstance() {
+ StringBuilder sb = getNew();
+ sb.append(VALUE);
+ return sb.toString();
+ }
+
+ @Benchmark
+ public String _stringThreadLocal() {
+ StringBuilder sb = getThreadLocal();
+ sb.append(VALUE);
+ return sb.toString();
+ }
+
+ @Benchmark
+ public String _concurrentHashMap() {
+ StringBuilder sb = getConcurrentMap();
+ sb.append(VALUE);
+ return sb.toString();
+ }
+
+ private StringBuilder getNew() {
+ final StringBuilder buf = new StringBuilder();
+ return buf;
+ }
+
+ private StringBuilder getThreadLocal() {
+ StringBuilder buf = threadLocal.get();
+ if (buf == null) {
+ buf = new StringBuilder();
+ threadLocal.set(buf);
+ }
+ buf.setLength(0);
+ return buf;
+ }
+
+ private StringBuilder getConcurrentMap() {
+ StringBuilder buf = map.get(Thread.currentThread());
+ if (buf == null) {
+ buf = new StringBuilder();
+ map.put(Thread.currentThread(), buf);
+ }
+ buf.setLength(0);
+ return buf;
+ }
+}
{code}
> Problem with AsyncLogger when web app is deployed/undeployed multiple times
> ---------------------------------------------------------------------------
>
> Key: LOG4J2-493
> URL: https://issues.apache.org/jira/browse/LOG4J2-493
> Project: Log4j 2
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0-beta9, 2.0-rc1
> Environment: tomcat 7.0.42
> Reporter: Kireet Reddy
> Assignee: Remko Popma
> Labels: Async
> Fix For: 2.5
>
>
> |_This ticket tracks Async Logger issues in Tomcat when making all loggers
> async with LoggerContextSelector system property. For Tomcat issues with
> AsyncRoot/AsyncLogger in the configuration file, see LOG4J2-323._|
> When redeploying my application in tomcat multiple times, I get an exception:
> {code}
> Exception in thread "Thread-29" java.lang.NullPointerException
> at
> org.apache.logging.log4j.core.async.AsyncLogger.stop(AsyncLogger.java:249)
> at
> org.apache.logging.log4j.core.async.AsyncLoggerContext.stop(AsyncLoggerContext.java:56)
> at
> org.apache.logging.log4j.core.LoggerContext$ShutdownThread.run(LoggerContext.java:437)
> {code}
> This seems to be due to the fact that some initialization code happens in the
> class initializer but is undone in the stop() method which is called during
> webapp undeployment. This causes issues because in this case the log4j jar is
> loaded by the shared classloader ($catalina.home/lib) rather than the webapp
> classloader. This means the AsyncLogger class is not re-created during webapp
> deployment.
> I am using this structure because I have many 3rd party libraries and want to
> keep redeployments lightweight.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
