Repository: logging-log4j2 Updated Branches: refs/heads/master e20ac291a -> b1255cfd5
LOG4J2-840, LOG4J2-841: Migrate JdbcHyperSqlAppender and JdbcH2Appender performance test from JUnit to log4j-perf Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/b1255cfd Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/b1255cfd Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/b1255cfd Branch: refs/heads/master Commit: b1255cfd5ddfacd2bde7dd89604598fcbfcc6ec4 Parents: e20ac29 Author: rpopma <[email protected]> Authored: Sat Sep 20 17:25:08 2014 +0900 Committer: rpopma <[email protected]> Committed: Sat Sep 20 17:25:08 2014 +0900 ---------------------------------------------------------------------- .../db/jdbc/AbstractJdbcAppenderTest.java | 39 ---- log4j-perf/pom.xml | 10 +- .../log4j/perf/jmh/JdbcAppenderBenchmark.java | 204 +++++++++++++++++++ .../src/main/resources/log4j2-jdbc-appender.xml | 58 ++++++ src/changes/changes.xml | 6 + 5 files changed, 277 insertions(+), 40 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b1255cfd/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/db/jdbc/AbstractJdbcAppenderTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/db/jdbc/AbstractJdbcAppenderTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/db/jdbc/AbstractJdbcAppenderTest.java index 4ffb63b..17dac28 100644 --- a/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/db/jdbc/AbstractJdbcAppenderTest.java +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/appender/db/jdbc/AbstractJdbcAppenderTest.java @@ -28,7 +28,6 @@ import javax.sql.DataSource; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; -import org.apache.logging.log4j.categories.PerformanceTests; import org.apache.logging.log4j.core.Appender; import org.apache.logging.log4j.core.LoggerContext; import org.apache.logging.log4j.core.config.ConfigurationFactory; @@ -39,7 +38,6 @@ import org.easymock.IAnswer; import org.h2.util.IOUtils; import org.junit.After; import org.junit.Test; -import org.junit.experimental.categories.Category; import org.mockejb.jndi.MockContextFactory; import static org.easymock.EasyMock.*; @@ -219,41 +217,4 @@ public abstract class AbstractJdbcAppenderTest { assertFalse("There should not be three rows.", resultSet.next()); } - - @Test - @Category(PerformanceTests.class) - public void testPerformanceOfAppenderWith1000Events() throws Exception { - this.setUp("fmLogEntry", "log4j2-" + this.databaseType + "-factory-method.xml"); - - final RuntimeException exception = new RuntimeException("Hello, world!"); - - final Logger logger = LogManager.getLogger(this.getClass().getName() + - ".testPerformanceOfAppenderWith1000Events"); - logger.info("This is a warm-up message."); - - System.out.println("Starting a performance test for JDBC Appender for " + this.databaseType + '.'); - - final long start = System.nanoTime(); - - for(int i = 0; i < 1000; i++) { - if (i % 25 == 0) { - logger.warn("This is an exception message.", exception); - } else { - logger.info("This is an info message."); - } - } - - final long elapsed = System.nanoTime() - start; - final long elapsedMilli = elapsed / 1000000; - - final Statement statement = this.connection.createStatement(ResultSet.TYPE_SCROLL_INSENSITIVE, - ResultSet.CONCUR_READ_ONLY); - final ResultSet resultSet = statement.executeQuery("SELECT * FROM fmLogEntry ORDER BY id"); - - resultSet.last(); - assertEquals("The number of records is not correct.", 1001, resultSet.getRow()); - - System.out.println("Wrote 1,000 log events in " + elapsed + " nanoseconds (" + elapsedMilli + - " milliseconds) for " + this.databaseType + '.'); - } } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b1255cfd/log4j-perf/pom.xml ---------------------------------------------------------------------- diff --git a/log4j-perf/pom.xml b/log4j-perf/pom.xml index 112ffd3..3dc7aee 100644 --- a/log4j-perf/pom.xml +++ b/log4j-perf/pom.xml @@ -80,7 +80,15 @@ <dependency> <groupId>com.lmax</groupId> <artifactId>disruptor</artifactId> - <version>${disruptor.version}</version> + </dependency> + <!-- Embedded JDBC drivers for database appender tests --> + <dependency> + <groupId>org.hsqldb</groupId> + <artifactId>hsqldb</artifactId> + </dependency> + <dependency> + <groupId>com.h2database</groupId> + <artifactId>h2</artifactId> </dependency> </dependencies> http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b1255cfd/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/JdbcAppenderBenchmark.java ---------------------------------------------------------------------- diff --git a/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/JdbcAppenderBenchmark.java b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/JdbcAppenderBenchmark.java new file mode 100644 index 0000000..0f58298 --- /dev/null +++ b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/JdbcAppenderBenchmark.java @@ -0,0 +1,204 @@ +/* + * 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.sql.Connection; +import java.sql.DriverManager; +import java.sql.SQLException; +import java.sql.Statement; +import java.util.concurrent.TimeUnit; + +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.core.LoggerContext; +import org.apache.logging.log4j.core.appender.db.jdbc.JdbcAppender; +import org.apache.logging.log4j.core.config.ConfigurationFactory; +import org.apache.logging.log4j.core.config.DefaultConfiguration; +import org.apache.logging.log4j.core.util.Closer; +import org.apache.logging.log4j.status.StatusLogger; +import org.openjdk.jmh.annotations.BenchmarkMode; +import org.openjdk.jmh.annotations.GenerateMicroBenchmark; +import org.openjdk.jmh.annotations.Mode; +import org.openjdk.jmh.annotations.OutputTimeUnit; +import org.openjdk.jmh.annotations.Scope; +import org.openjdk.jmh.annotations.Setup; +import org.openjdk.jmh.annotations.State; +import org.openjdk.jmh.annotations.TearDown; +import org.openjdk.jmh.logic.BlackHole; + +/** + * Tests the overhead of a number of JDBC Appenders. + */ +// ============================== HOW TO RUN THIS TEST: ==================================== +// +// java -jar log4j-perf/target/microbenchmarks.jar ".*JdbcAppenderBenchmark.*" -f 1 -wi 5 -i 5 +// +// Usage help: +// java -jar log4j-perf/target/microbenchmarks.jar -help +// +@State(Scope.Thread) +public class JdbcAppenderBenchmark { + private Logger loggerH2; + private Logger loggerHSQLDB; + private Connection connectionHSQLDB; + private Connection connectionH2; + private final RuntimeException exception = new RuntimeException("Hello, world!"); + + @Setup + public void setup() throws Exception { + connectionHSQLDB = getConnectionHSQLDB(); + connectionH2 = getConnectionH2(); + createTable(connectionHSQLDB, toCreateTableSqlStringHQLDB("fmLogEntry")); + createTable(connectionH2, toCreateTableSqlStringH2("fmLogEntry")); + + System.setProperty(ConfigurationFactory.CONFIGURATION_FILE_PROPERTY, "log4j2-jdbc-appender.xml"); + final LoggerContext context = (LoggerContext) LogManager.getContext(false); + if (context.getConfiguration() instanceof DefaultConfiguration) { + context.reconfigure(); + } + StatusLogger.getLogger().reset(); + loggerH2 = LogManager.getLogger("H2Logger"); + loggerHSQLDB = LogManager.getLogger("HSQLDBLogger"); + } + + @BenchmarkMode(Mode.Throughput) + @OutputTimeUnit(TimeUnit.SECONDS) + @GenerateMicroBenchmark + public void testThroughputH2Message(final BlackHole bh) { + loggerH2.info("Test message"); + } + + @BenchmarkMode(Mode.Throughput) + @OutputTimeUnit(TimeUnit.SECONDS) + @GenerateMicroBenchmark + public void testThroughputH2Exception(final BlackHole bh) { + loggerH2.warn("Test message", exception); + } + + @BenchmarkMode(Mode.SampleTime) + @OutputTimeUnit(TimeUnit.MICROSECONDS) + @GenerateMicroBenchmark + public void testResponseTimeH2Message(final BlackHole bh) { + loggerH2.info("Test message"); + } + + @BenchmarkMode(Mode.SampleTime) + @OutputTimeUnit(TimeUnit.MICROSECONDS) + @GenerateMicroBenchmark + public void testResponseTimeH2Exception(final BlackHole bh) { + loggerH2.warn("Test message", exception); + } + + @BenchmarkMode(Mode.Throughput) + @OutputTimeUnit(TimeUnit.SECONDS) + @GenerateMicroBenchmark + public void testThroughputHSQLDBMessage(final BlackHole bh) { + loggerHSQLDB.info("Test message"); + } + + @BenchmarkMode(Mode.Throughput) + @OutputTimeUnit(TimeUnit.SECONDS) + @GenerateMicroBenchmark + public void testThroughputHSQLDBException(final BlackHole bh) { + loggerHSQLDB.warn("Test message", exception); + } + + @BenchmarkMode(Mode.SampleTime) + @OutputTimeUnit(TimeUnit.MICROSECONDS) + @GenerateMicroBenchmark + public void testResponseTimeHSQLDBMessage(final BlackHole bh) { + loggerHSQLDB.info("Test message"); + } + + @BenchmarkMode(Mode.SampleTime) + @OutputTimeUnit(TimeUnit.MICROSECONDS) + @GenerateMicroBenchmark + public void testResponseTimeHSQLDBException(final BlackHole bh) { + loggerHSQLDB.warn("Test message", exception); + } + + @TearDown + public void tearDown() throws SQLException { + final LoggerContext context = (LoggerContext) LogManager.getContext(false); + try { + ((JdbcAppender) context.getConfiguration().getAppender("H2Appender")).getManager().release(); + ((JdbcAppender) context.getConfiguration().getAppender("HSQLDBAppender")).getManager().release(); + } finally { + System.clearProperty(ConfigurationFactory.CONFIGURATION_FILE_PROPERTY); + // context.reconfigure(); + // StatusLogger.getLogger().reset(); + + Statement statement = null; + try { + statement = connectionHSQLDB.createStatement(); + statement.execute("SHUTDOWN"); + } catch (SQLException ignore) { + // ignore + } finally { + Closer.closeSilently(statement); + Closer.closeSilently(connectionHSQLDB); + } + try { + statement = connectionH2.createStatement(); + statement.execute("SHUTDOWN"); + } catch (SQLException ignore) { + // ignore + } finally { + Closer.closeSilently(statement); + Closer.closeSilently(connectionH2); + } + } + } + + private void createTable(Connection connection, String createSQL) throws SQLException { + final Statement statement = connection.createStatement(); + try { + statement.executeUpdate(createSQL); + } finally { + statement.close(); + } + } + + private String toCreateTableSqlStringH2(final String tableName) { + return "CREATE TABLE " + tableName + " ( " + + "id INTEGER IDENTITY, eventDate DATETIME, literalColumn VARCHAR(255), level NVARCHAR(10), " + + "logger NVARCHAR(255), message VARCHAR(1024), exception NCLOB" + " )"; + } + + private String toCreateTableSqlStringHQLDB(final String tableName) { + return "CREATE TABLE " + tableName + " ( " + + "id INTEGER IDENTITY, eventDate DATETIME, literalColumn VARCHAR(255), level VARCHAR(10), " + + "logger VARCHAR(255), message VARCHAR(1024), exception CLOB" + " )"; + } + + /** + * Referred from log4j2-jdbc-appender.xml. + */ + public static Connection getConnectionH2() throws Exception { + Class.forName("org.h2.Driver"); + return DriverManager.getConnection("jdbc:h2:mem:Log4j", "sa", ""); + } + + /** + * Referred from log4j2-jdbc-appender.xml. + */ + public static Connection getConnectionHSQLDB() throws Exception { + Class.forName("org.hsqldb.jdbcDriver"); + return DriverManager.getConnection("jdbc:hsqldb:mem:Log4j", "sa", ""); + } +} http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b1255cfd/log4j-perf/src/main/resources/log4j2-jdbc-appender.xml ---------------------------------------------------------------------- diff --git a/log4j-perf/src/main/resources/log4j2-jdbc-appender.xml b/log4j-perf/src/main/resources/log4j2-jdbc-appender.xml new file mode 100644 index 0000000..7cb574e --- /dev/null +++ b/log4j-perf/src/main/resources/log4j2-jdbc-appender.xml @@ -0,0 +1,58 @@ +<?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. +--> +<Configuration status="OFF"> + + <Appenders> + <Console name="STDOUT"> + <PatternLayout pattern="%C{1.} %m %level MDC%X%n"/> + </Console> + <Jdbc name="H2Appender" tableName="fmLogEntry" ignoreExceptions="false"> + <ConnectionFactory class="org.apache.logging.log4j.perf.jmh.JdbcAppenderBenchmark" + method="getConnectionH2" /> + <Column name="eventDate" isEventTimestamp="true" /> + <Column name="literalColumn" literal="'Some Other Literal Value'" /> + <Column name="level" pattern="%level" /> + <Column name="logger" pattern="%logger" /> + <Column name="message" pattern="%message" isUnicode="false" /> + <Column name="exception" pattern="%ex{full}" isClob="true" /> + </Jdbc> + <Jdbc name="HSQLDBAppender" tableName="fmLogEntry" ignoreExceptions="false"> + <ConnectionFactory class="org.apache.logging.log4j.perf.jmh.JdbcAppenderBenchmark" + method="getConnectionHSQLDB" /> + <Column name="eventDate" isEventTimestamp="true" /> + <Column name="literalColumn" literal="'Some Other Literal Value'" /> + <Column name="level" pattern="%level" /> + <Column name="logger" pattern="%logger" /> + <Column name="message" pattern="%message" isUnicode="false" /> + <Column name="exception" pattern="%ex{full}" isClob="true" /> + </Jdbc> + </Appenders> + + <Loggers> + <Logger name="H2Logger" level="debug" additivity="false"> + <AppenderRef ref="H2Appender" /> + </Logger> + <Logger name="HSQLDBLogger" level="debug" additivity="false"> + <AppenderRef ref="HSQLDBAppender" /> + </Logger> + + <Root level="fatal"> + <AppenderRef ref="STDOUT"/> + </Root> + </Loggers> +</Configuration> http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b1255cfd/src/changes/changes.xml ---------------------------------------------------------------------- diff --git a/src/changes/changes.xml b/src/changes/changes.xml index 8455cf6..d237157 100644 --- a/src/changes/changes.xml +++ b/src/changes/changes.xml @@ -24,6 +24,12 @@ </properties> <body> <release version="2.1" date="2014-??-??" description="Bug fixes and enhancements"> + <action issue="LOG4J2-841" dev="rpopma" type="fix"> + Migrate JdbcHyperSqlAppenderTest#testPerformanceOfAppenderWith1000Events() to log4j-perf. + </action> + <action issue="LOG4J2-840" dev="rpopma" type="fix"> + Migrate JdbcH2AppenderTest#testPerformanceOfAppenderWith1000Events() to log4j-perf. + </action> <action issue="LOG4J2-830" dev="rpopma" type="fix"> Respect external interrupt signal to allow application shutdown after joining AsyncAppender thread. </action>
