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.access.net;
015
016import java.io.IOException;
017import java.io.ObjectOutputStream;
018
019import ch.qos.logback.access.spi.IAccessEvent;
020import junit.framework.TestCase;
021import ch.qos.logback.access.dummy.DummyAccessEventBuilder;
022
023public class SerializationPerfTest extends TestCase {
024
025    ObjectOutputStream oos;
026
027    int loopNumber = 10000;
028    int resetFrequency = 100;
029    int pauseFrequency = 10;
030    long pauseLengthInMillis = 20;
031
032    public void setUp() throws Exception {
033        super.setUp();
034        oos = new ObjectOutputStream(new NOPOutputStream());
035
036    }
037
038    public void tearDown() throws Exception {
039        super.tearDown();
040        oos.close();
041        oos = null;
042    }
043
044    public void test1() throws Exception {
045        // first run for just in time compiler
046        int resetCounter = 0;
047        int pauseCounter = 0;
048        for (int i = 0; i < loopNumber; i++) {
049            try {
050                IAccessEvent ae = DummyAccessEventBuilder.buildNewAccessEvent();
051                // average time for the next method: 5000 nanos
052                ae.prepareForDeferredProcessing();
053                oos.writeObject(ae);
054                oos.flush();
055                if (++resetCounter >= resetFrequency) {
056                    oos.reset();
057                    resetCounter = 0;
058                }
059                if (++pauseCounter >= pauseFrequency) {
060                    Thread.sleep(pauseLengthInMillis);
061                    pauseCounter = 0;
062                }
063
064            } catch (IOException ex) {
065                fail(ex.getMessage());
066            }
067        }
068
069        // second run
070        Long t1;
071        Long t2;
072        Long total = 0L;
073        resetCounter = 0;
074        pauseCounter = 0;
075        // System.out.println("Beginning mesured run");
076        for (int i = 0; i < loopNumber; i++) {
077            try {
078                IAccessEvent ae = DummyAccessEventBuilder.buildNewAccessEvent();
079                t1 = System.nanoTime();
080                // average length of the next method: 4000 nanos
081                ae.prepareForDeferredProcessing();
082                oos.writeObject(ae);
083                oos.flush();
084                t2 = System.nanoTime();
085                total += (t2 - t1);
086                if (++resetCounter >= resetFrequency) {
087                    oos.reset();
088                    resetCounter = 0;
089                }
090                if (++pauseCounter >= pauseFrequency) {
091                    Thread.sleep(pauseLengthInMillis);
092                    pauseCounter = 0;
093                }
094            } catch (IOException ex) {
095                fail(ex.getMessage());
096            }
097        }
098
099        total /= (1000);// nanos -> micros
100        System.out.println("Loop done : average time = " + total / loopNumber + " microsecs after " + loopNumber + " writes.");
101        // average time: 26-30 microsec = 0.030 millis
102    }
103
104}