001/**
002 * Logback: the reliable, generic, fast and flexible logging framework.
003 * Copyright (C) 1999-2015, QOS.ch. All rights reserved.
004 *
005 * This program and the accompanying materials are dual-licensed under
006 * either the terms of the Eclipse Public License v1.0 as published by
007 * the Eclipse Foundation
008 *
009 *   or (per the licensee's choosing)
010 *
011 * under the terms of the GNU Lesser General Public License version 2.1
012 * as published by the Free Software Foundation.
013 */
014package ch.qos.logback.classic.spi;
015
016import static org.junit.Assert.assertTrue;
017import static org.junit.Assert.fail;
018
019import java.io.IOException;
020import java.io.ObjectOutputStream;
021
022import ch.qos.logback.core.testUtil.EnvUtilForTests;
023import org.junit.After;
024import org.junit.Before;
025import org.junit.Test;
026import org.slf4j.MDC;
027
028import ch.qos.logback.classic.net.NOPOutputStream;
029import ch.qos.logback.classic.net.testObjectBuilders.Builder;
030import ch.qos.logback.classic.net.testObjectBuilders.LoggingEventWithParametersBuilder;
031import ch.qos.logback.classic.net.testObjectBuilders.TrivialLoggingEventBuilder;
032import ch.qos.logback.core.CoreConstants;
033
034// As of logback 0.9.15, 
035//   average time  per logging event: 3979 nanoseconds
036//   size 545'648 bytes
037// 
038// Using LoggingEventDO
039// 
040//   average time  per logging event: 4052 nanoseconds
041//   average size=45,  with params, average size=136
042//
043// Using LoggerEventVO, with loggerName, and loggerContextRemoteView
044//   average time per logging event: 4034
045//   average size 57, with params, average size=148
046
047public class LoggingEventSerializationPerfTest {
048
049    static int LOOP_LEN = 10 * 1000;
050
051    NOPOutputStream noos = new NOPOutputStream();
052    ObjectOutputStream oos;
053
054    @Before
055    public void setUp() throws Exception {
056        MDC.clear();
057        oos = new ObjectOutputStream(noos);
058    }
059
060    @After
061    public void tearDown() throws Exception {
062    }
063
064    double doLoop(Builder<LoggingEvent> builder, int loopLen) {
065        long start = System.nanoTime();
066        int resetCounter = 0;
067        for (int i = 0; i < loopLen; i++) {
068            try {
069                ILoggingEvent le = builder.build(i);
070                oos.writeObject(LoggingEventVO.build(le));
071
072                oos.flush();
073                if (++resetCounter >= CoreConstants.OOS_RESET_FREQUENCY) {
074                    oos.reset();
075                    resetCounter = 0;
076                }
077
078            } catch (IOException ex) {
079                fail(ex.getMessage());
080            }
081        }
082        long end = System.nanoTime();
083        return (end - start) / (1.0d * loopLen);
084    }
085
086    @Test
087    public void testPerformance() {
088        if (EnvUtilForTests.isLinux()) {
089            return;
090        }
091        TrivialLoggingEventBuilder builder = new TrivialLoggingEventBuilder();
092
093        for (int i = 0; i < 3; i++) {
094            doLoop(builder, LOOP_LEN);
095            noos.reset();
096        }
097        double rt = doLoop(builder, LOOP_LEN);
098        System.out.println("average time per logging event " + rt + " nanoseconds");
099
100        long averageSize = (long) (noos.size() / (LOOP_LEN));
101        System.out.println("noos size " + noos.size() + " average size=" + averageSize);
102        double averageSizeLimit = 62.1;
103
104        assertTrue("average size " + averageSize + " should be less than " + averageSizeLimit, averageSizeLimit > averageSize);
105
106        // the reference was computed on Orion (Ceki's computer)
107        @SuppressWarnings("unused")
108        long referencePerf = 5000;
109        //BogoPerf.assertDuration(rt, referencePerf, CoreConstants.REFERENCE_BIPS);
110    }
111
112    @Test
113    public void testPerformanceWithParameters() {
114        if (EnvUtilForTests.isLinux()) {
115            return;
116        }
117        LoggingEventWithParametersBuilder builder = new LoggingEventWithParametersBuilder();
118
119        // warm up
120        for (int i = 0; i < 3; i++) {
121            doLoop(builder, LOOP_LEN);
122            noos.reset();
123        }
124        @SuppressWarnings("unused")
125        double rt = doLoop(builder, LOOP_LEN);
126        long averageSize = (long) (noos.size() / (LOOP_LEN));
127
128        System.out.println("noos size " + noos.size() + " average size=" + averageSize);
129
130        double averageSizeLimit = 160;
131        assertTrue("averageSize " + averageSize + " should be less than " + averageSizeLimit, averageSizeLimit > averageSize);
132
133        // the reference was computed on Orion (Ceki's computer)
134        @SuppressWarnings("unused")
135        long referencePerf = 7000;
136        //BogoPerf.assertDuration(rt, referencePerf, CoreConstants.REFERENCE_BIPS);
137    }
138}