log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/LoggerConfigBenchmark.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.perf.jmh;

import java.util.concurrent.CopyOnWriteArraySet;
import java.util.concurrent.atomic.AtomicBoolean;
import java.util.concurrent.atomic.AtomicInteger;
import java.util.concurrent.locks.Condition;
import java.util.concurrent.locks.Lock;
import java.util.concurrent.locks.ReentrantLock;

import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.core.Filter;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.appender.AbstractAppender;
import org.apache.logging.log4j.core.config.AppenderControl;
import org.apache.logging.log4j.core.config.LoggerConfig;
import org.apache.logging.log4j.core.config.Property;
import org.apache.logging.log4j.core.impl.Log4jLogEvent;
import org.apache.logging.log4j.message.SimpleMessage;
import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.annotations.Scope;
import org.openjdk.jmh.annotations.Setup;
import org.openjdk.jmh.annotations.State;
import org.openjdk.jmh.infra.Blackhole;

// ============================== HOW TO RUN THIS TEST: ====================================
//
// In sampling mode (latency test):
// java -jar log4j-perf/target/benchmarks.jar ".*LoggerConfigBenchmark.*" -i 10 -f 1 -wi 5 -bm sample -tu ns
//
// Multi-threading test:
// java -jar benchmarks.jar ".*LoggerConfigBenchmark.*"  -i 10 -f 1 -wi 5 -bm sample -tu ns -t 4
//
// Usage help:
// java -jar log4j-perf/target/benchmarks.jar -help
//
@State(Scope.Benchmark)
public class LoggerConfigBenchmark {

    private final CopyOnWriteArraySet<AppenderControl> appenderSet = new CopyOnWriteArraySet<>();
    private volatile Filter filter;
    private final boolean additive = true;
    private final boolean includeLocation = true;
    private LoggerConfig parent;
    private final AtomicInteger counter = new AtomicInteger();
    private final AtomicBoolean shutdown = new AtomicBoolean(false);
    private final Lock shutdownLock = new ReentrantLock();
    private final Condition noLogEvents = shutdownLock.newCondition(); // should only be used when shutdown == true
    private final LogEvent LOGEVENT = createLogEventWithoutException();
    private final SimpleListAppender listAppender = new SimpleListAppender();

    private static class SimpleListAppender extends AbstractAppender {
        private static final long serialVersionUID = 1L;
        private final AtomicInteger count = new AtomicInteger();

        protected SimpleListAppender() {
            super("list", null, null, true, Property.EMPTY_ARRAY);
        }

        @Override
        public void append(final LogEvent event) {
            count.incrementAndGet();
        }

        public int size() {
            return count.get();
        }
    }

    @Setup
    public void setup() {

        listAppender.start();
        final AppenderControl control = new AppenderControl(listAppender, Level.ALL, null);
        appenderSet.add(control);
    }

    @Benchmark
    public void testBaseline(final Blackhole bh) {
    }

    private static LogEvent createLogEventWithoutException() {
        return new Log4jLogEvent("a.b.c", null, "a.b.c", Level.INFO, new SimpleMessage("abc"), null, null);
    }

    @Benchmark
    public int logWithCountersAndLock() {
        log(LOGEVENT);
        return listAppender.size();
    }

    @Benchmark
    public int logWithCountersNoLocks() {
        log2(LOGEVENT);
        return listAppender.size();
    }

    @Benchmark
    public int logWithoutCountersOrLocks() {
        log3(LOGEVENT);
        return listAppender.size();
    }

    @Benchmark
    public int logWithCountersRetryAfterReconfig() {
        log4WithCounterAndFlag(LOGEVENT);
        return listAppender.size();
    }

    /**
     * Logs an event.
     *
     * @param event The log event.
     */
    public void log(final LogEvent event) {
        beforeLogEvent();
        try {
            if (!isFiltered(event)) {
                processLogEvent(event);
            }
        } finally {
            afterLogEvent();
        }
    }

    /**
     * Logs an event.
     *
     * @param event The log event.
     */
    public void log2(final LogEvent event) {
        beforeLogEvent();
        try {
            if (!isFiltered(event)) {
                processLogEvent(event);
            }
        } finally {
            afterLogEvent2();
        }
    }

    /**
     * Logs an event.
     *
     * @param event The log event.
     */
    public void log3(final LogEvent event) {
        if (!isFiltered(event)) {
            processLogEvent(event);
        }
    }
    
    volatile LoggerConfigBenchmark loggerConfig = this;

    /**
     * Logs an event.
     *
     * @param event The log event.
     */
    public void log4WithCounterAndFlag(final LogEvent event) {
        LoggerConfigBenchmark local = loggerConfig;
        while (!local.beforeLogEventCheckCounterPositive()) {
            local = loggerConfig;
        }
        try {
            local.log3(event);
        } finally {
            local.afterLogEvent2();
        }
    }

    /**
     * Determine if the LogEvent should be processed or ignored.
     * 
     * @param event The LogEvent.
     * @return true if the LogEvent should be processed.
     */
    public boolean isFiltered(final LogEvent event) {
        return filter != null && filter.filter(event) == Filter.Result.DENY;
    }

    private void beforeLogEvent() {
        counter.incrementAndGet();
    }

    private boolean beforeLogEventCheckCounterPositive() {
        return counter.incrementAndGet() > 0;
    }

    private void afterLogEvent() {
        if (counter.decrementAndGet() == 0) {
            signalCompletionIfShutdown();
        }
    }

    private void signalCompletionIfShutdown() {
        final Lock lock = shutdownLock;
        lock.lock();
        try {
            if (shutdown.get()) {
                noLogEvents.signalAll();
            }
        } finally {
            lock.unlock();
        }
    }

    private void afterLogEvent2() {
        if (counter.decrementAndGet() == 0 && shutdown.get()) {
            signalCompletionIfShutdown();
        }
    }

    private void processLogEvent(final LogEvent event) {
        event.setIncludeLocation(isIncludeLocation());
        callAppenders(event);
        logParent(event);
    }

    public boolean isIncludeLocation() {
        return includeLocation;
    }

    private void logParent(final LogEvent event) {
        if (additive && parent != null) {
            parent.log(event);
        }
    }

    protected void callAppenders(final LogEvent event) {
        for (final AppenderControl control : appenderSet) {
            control.callAppender(event);
        }
    }

}