From 8e75f393b31c0ffae9a7187474efe382b5011601 Mon Sep 17 00:00:00 2001 From: Erick Erickson Date: Fri, 31 Aug 2018 20:39:05 -0700 Subject: [PATCH] SOLR-12055: Enable async logging by default --- solr/CHANGES.txt | 6 ++ solr/core/src/test-files/log4j2.xml | 12 +-- .../solr/handler/RequestLoggingTest.java | 2 - .../apache/solr/logging/TestLogWatcher.java | 74 +++++++++---------- solr/server/resources/log4j2-console.xml | 8 +- solr/server/resources/log4j2.xml | 30 ++++---- 6 files changed, 66 insertions(+), 66 deletions(-) diff --git a/solr/CHANGES.txt b/solr/CHANGES.txt index afa7b119a46..452dc039e4a 100644 --- a/solr/CHANGES.txt +++ b/solr/CHANGES.txt @@ -52,6 +52,12 @@ Upgrade Notes expanded from before to subsume those patterns previously handled by the "extract" contrib (Solr Cell / Tika). (David Smiley, Bar Rotstein) +* SOLR-12055: Enable async logging by default. This change improves throughput for logging. This opens + up a small window where log messages could possibly be lost. If this is unacceptable, switching back to synchronous + logging can be done by changing the log4j2.xml files, no internal Solr code changed to make async logging the default. + (Erick Erickson) + + New Features ---------------------- diff --git a/solr/core/src/test-files/log4j2.xml b/solr/core/src/test-files/log4j2.xml index 7d0ebf7a497..544784322d3 100644 --- a/solr/core/src/test-files/log4j2.xml +++ b/solr/core/src/test-files/log4j2.xml @@ -27,13 +27,13 @@ - - - - + + + + - + - + diff --git a/solr/core/src/test/org/apache/solr/handler/RequestLoggingTest.java b/solr/core/src/test/org/apache/solr/handler/RequestLoggingTest.java index 17b5429116e..0e8a7a9b64c 100644 --- a/solr/core/src/test/org/apache/solr/handler/RequestLoggingTest.java +++ b/solr/core/src/test/org/apache/solr/handler/RequestLoggingTest.java @@ -48,7 +48,6 @@ public class RequestLoggingTest extends SolrTestCaseJ4 { @Before public void setupAppender() { LoggerContext ctx = (LoggerContext) LogManager.getContext(false); - LoggerConfig config = ctx.getConfiguration().getLoggerConfig("RequestLoggingTest"); writer = new StringWriter(); appender = WriterAppender.createAppender( @@ -58,7 +57,6 @@ public class RequestLoggingTest extends SolrTestCaseJ4 { .build(), null, writer, "RequestLoggingTest", false, true); appender.start(); - } @Test diff --git a/solr/core/src/test/org/apache/solr/logging/TestLogWatcher.java b/solr/core/src/test/org/apache/solr/logging/TestLogWatcher.java index 6f7987f084f..9548363c893 100644 --- a/solr/core/src/test/org/apache/solr/logging/TestLogWatcher.java +++ b/solr/core/src/test/org/apache/solr/logging/TestLogWatcher.java @@ -16,6 +16,7 @@ */ package org.apache.solr.logging; +import org.apache.solr.SolrTestCaseJ4; import org.apache.solr.common.SolrDocument; import org.apache.solr.common.SolrDocumentList; import org.junit.Before; @@ -26,55 +27,50 @@ import org.slf4j.LoggerFactory; import java.lang.invoke.MethodHandles; import java.util.concurrent.atomic.AtomicBoolean; -import static org.junit.Assert.assertEquals; -import static org.junit.Assert.assertTrue; - -public class TestLogWatcher { +public class TestLogWatcher extends SolrTestCaseJ4 { private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); private LogWatcherConfig config; @Before - public void setUp() { - config = new LogWatcherConfig(true, null, null, 50); + public void before() { + config = new LogWatcherConfig(true, null, "INFO", 1); } + // Create several log watchers and ensure that new messages go to the new watcher. @Test public void testLog4jWatcher() { - LogWatcher watcher = LogWatcher.newRegisteredLogWatcher(config, null); + LogWatcher watcher = null; + int lim = random().nextInt(3) + 2; + for (int idx = 0; idx < lim; ++idx) { + String msg = "This is a test message: " + idx; + watcher = LogWatcher.newRegisteredLogWatcher(config, null); - assertEquals(watcher.getLastEvent(), -1); + // First ensure there's nothing in the new watcher. + assertEquals(-1, watcher.getLastEvent()); - log.warn("This is a test message"); - - assertTrue(watcher.getLastEvent() > -1); - - SolrDocumentList events = watcher.getHistory(-1, new AtomicBoolean()); - assertEquals(events.size(), 1); - - SolrDocument event = events.get(0); - assertEquals(event.get("logger"), "org.apache.solr.logging.TestLogWatcher"); - assertEquals(event.get("message"), "This is a test message"); + // Now log a message and ensure that the new watcher sees it. + log.warn(msg); + // Loop to give the logger time to process the async message and notify the new watcher. + boolean foundMsg = false; + long last = -1; + // In local testing this loop usually succeeds 1-2 tries. + for (int msgIdx = 0; msgIdx < 100; ++msgIdx) { + // Returns an empty (but non-null) list even if there are no messages yet. + SolrDocumentList events = watcher.getHistory(-1, new AtomicBoolean()); + for (SolrDocument doc : events) { + if (doc.get("message").equals(msg)) { + foundMsg = true; + break; + } + } + try { + Thread.sleep(10); + } catch (InterruptedException ie) { + ; + } + } + assertTrue("Should have found message " + msg + " in loop: " + idx, foundMsg); + } } - - // This seems weird to do the same thing twice, this is valid. We need to test whether listeners are replaced.... - @Test - public void testLog4jWatcherRepeat() { - LogWatcher watcher = LogWatcher.newRegisteredLogWatcher(config, null); - - assertEquals(watcher.getLastEvent(), -1); - - log.warn("This is a test message"); - - assertTrue(watcher.getLastEvent() > -1); - - SolrDocumentList events = watcher.getHistory(-1, new AtomicBoolean()); - assertEquals(events.size(), 1); - - SolrDocument event = events.get(0); - assertEquals(event.get("logger"), "org.apache.solr.logging.TestLogWatcher"); - assertEquals(event.get("message"), "This is a test message"); - - } - } diff --git a/solr/server/resources/log4j2-console.xml b/solr/server/resources/log4j2-console.xml index f32f4c142e2..698227b46d6 100644 --- a/solr/server/resources/log4j2-console.xml +++ b/solr/server/resources/log4j2-console.xml @@ -29,11 +29,11 @@ - - + + - + - + diff --git a/solr/server/resources/log4j2.xml b/solr/server/resources/log4j2.xml index 17bcf4c007a..d9c05d8b468 100644 --- a/solr/server/resources/log4j2.xml +++ b/solr/server/resources/log4j2.xml @@ -27,8 +27,8 @@ - @@ -41,10 +41,10 @@ - + - @@ -57,20 +57,20 @@ - + - - - - - - + + + + + + - - + + - +