log4j-core-its/src/test/java/org/apache/logging/log4j/FilterPerformanceComparison.java

/*
 * 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;

import java.util.Collections;
import java.util.HashMap;
import java.util.Map;

import org.apache.logging.log4j.categories.PerformanceTests;
import org.apache.logging.log4j.core.config.ConfigurationFactory;
import org.junit.After;
import org.junit.AfterClass;
import org.junit.BeforeClass;
import org.junit.Test;
import org.junit.experimental.categories.Category;
import org.slf4j.MDC;

/**
 *
 */
@Category(PerformanceTests.class)
public class FilterPerformanceComparison {

    private final Logger logger = LogManager.getLogger(FilterPerformanceComparison.class.getName());
    private final org.slf4j.Logger logbacklogger = org.slf4j.LoggerFactory.getLogger(FilterPerformanceComparison.class);


    // How many times should we try to log:
    private static final int COUNT = 10000000;
    private static final int THREADED_COUNT = 100000;
    private static final int WARMUP = 1000;

    private static final String CONFIG = "log4j2-perf-filter.xml";
    private static final String LOGBACK_CONFIG = "logback-perf-filter.xml";

    private static final String LOGBACK_CONF = "logback.configurationFile";

    @BeforeClass
    public static void setupClass() {
        System.setProperty(ConfigurationFactory.CONFIGURATION_FILE_PROPERTY, CONFIG);
        System.setProperty(LOGBACK_CONF, LOGBACK_CONFIG);
    }

    @AfterClass
    public static void cleanupClass() {
        System.clearProperty(ConfigurationFactory.CONFIGURATION_FILE_PROPERTY);
        System.clearProperty(LOGBACK_CONF);
    }

    @After
    public void after() {
        ThreadContext.clearAll();
    }

    @Test
    public void testPerformanceEmptyContext() throws Exception {
        testPerformance(Collections.<String, String>emptyMap());
    }

    @Test
    public void testPerformanceNonEmptyContext() throws Exception {
        testPerformance(createNonEmptyContextData());
    }

    private Map<String, String> createNonEmptyContextData() {
        final Map<String, String> context = new HashMap<>();
        context.put("user0", "Apache");
        context.put("user1", "Apache");
        return context;
    }

    private static void putContextData(final Map<String, String> contextData) {
        ThreadContext.putAll(contextData);
        for (final Map.Entry<String, String> entry : contextData.entrySet()) {
            MDC.put(entry.getKey(), entry.getValue());
        }
    }

    private void testPerformance(final Map<String, String> contextData) throws Exception {
        putContextData(contextData);
        Target.LOGBACK.timedLoop(logger, logbacklogger, WARMUP);
        Target.LOG4J2.timedLoop(logger, logbacklogger, WARMUP);

        System.out.println("Single-threaded Log4j 2.0, "
                + (contextData.isEmpty() ? "EMPTY context" : "NON-EMPTY context"));

        final long result3 = Target.LOG4J2.timedLoop(logger, logbacklogger, COUNT);
        System.out.println("Single-threaded Logback, "
                + (contextData.isEmpty() ? "EMPTY context" : "NON-EMPTY context"));

        final long result2 = Target.LOGBACK.timedLoop(logger, logbacklogger, COUNT);

        System.out.println("###############################################");
        System.out.println("Logback: " + result2);
        System.out.println("Log4j 2.0: " + result3);
        System.out.println("###############################################");
    }

    @Test
    public void testThreadsEmptyContext() throws Exception {
        testThreads(Collections.<String, String>emptyMap());
    }

    @Test
    public void testThreadsNonEmptyContext() throws Exception {
        testThreads(createNonEmptyContextData());
    }

    private void testThreads(final Map<String, String> contextData) throws Exception {
        System.out.println("Testing multithreading");
        final int threadedCount = COUNT; // THREADED_COUNT * threadCount < COUNT ? COUNT / threadCount : THREADED_COUNT;
        final int[] threadCounts = new int[] {1, 2, 5, 10, 20, 50};
        for (final int threadCount : threadCounts) {
            System.out.println("Testing " + threadCount + " threads, "
                    + (contextData.isEmpty() ? "EMPTY context" : "NON-EMPTY context"));
            final Worker[] workers = new Worker[threadCount];
            final long[] results = new long[threadCount];
            for (int i=0; i < threadCount; ++i) {
                workers[i] = new Worker(Target.LOG4J2, threadedCount, results, i, contextData);
            }
            for (int i=0; i < threadCount; ++i) {
                workers[i].start();
            }
            long total = 0;
            for (int i=0; i < threadCount; ++i) {
                workers[i].join();
                total += results[i];
            }
            final long result3 = total / threadCount;
            total = 0;
            for (int i=0; i < threadCount; ++i) {
                workers[i] = new Worker(Target.LOGBACK, threadedCount, results, i, contextData);
            }
            for (int i=0; i < threadCount; ++i) {
                workers[i].start();
            }
            for (int i=0; i < threadCount; ++i) {
                workers[i].join();
                total += results[i];
            }
            final long result2 = total / threadCount;
            System.out.println("###############################################");
            System.out.println("Logback: " + result2);
            System.out.println("Log4j 2.0: " + result3 );
            System.out.println("###############################################");
        }
    }

    private enum Target {
        LOGBACK {
            @Override
            long timedLoop(final Logger logger, final org.slf4j.Logger logbacklogger, final int loop) {
                final Integer j = Integer.valueOf(2);
                final long start = System.nanoTime();
                for (int i = 0; i < loop; i++) {
                    logbacklogger.debug("SEE IF THIS IS LOGGED {}.", j);
                }
                return (System.nanoTime() - start) / loop;
            }
        },

        LOG4J2 {
            @Override
            long timedLoop(final Logger logger, final org.slf4j.Logger logbacklogger, final int loop) {
                final Integer j = Integer.valueOf(2);
                final long start = System.nanoTime();
                for (int i = 0; i < loop; i++) {
                    logger.debug("SEE IF THIS IS LOGGED {}.", j);
                }
                return (System.nanoTime() - start) / loop;
            }
        };
        abstract long timedLoop(final Logger logger, final org.slf4j.Logger logbacklogger, final int loop);
    }

    private class Worker extends Thread {

        private final Target target;
        private final int count;
        private final long[] results;
        private final int index;
        private final Map<String, String> contextData;

        public Worker(final Target target, final int count, final long[] results, final int index,
                final Map<String, String> contextData) {
            this.target = target;
            this.count = count;
            this.results = results;
            this.index = index;
            this.contextData = contextData;
        }

        @Override
        public void run() {
            putContextData(contextData);
            results[index] = target.timedLoop(logger, logbacklogger, count);
        }
    }

}