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 chapters.appenders;
015
016import org.slf4j.Logger;
017
018import ch.qos.logback.classic.LoggerContext;
019import ch.qos.logback.classic.encoder.PatternLayoutEncoder;
020import ch.qos.logback.classic.spi.ILoggingEvent;
021import ch.qos.logback.core.FileAppender;
022import ch.qos.logback.core.encoder.EchoEncoder;
023
024public class IO extends Thread {
025    static String msgLong = "ABCDEGHIJKLMNOPQRSTUVWXYZabcdeghijklmnopqrstuvwxyz1234567890";
026    static String msgShort = "Hello";
027    static boolean scarceCPU;
028    static int numThreads;
029    static long l;
030    static boolean longMessage;
031    long len;
032    boolean buffered;
033    boolean immediateFlush;
034    Logger logger;
035    LoggerContext context;
036    double throughput;
037
038    public IO(boolean _buffered, boolean _immediateFlush, long _len) {
039        this.len = _len;
040        this.buffered = _buffered;
041        this.immediateFlush = _immediateFlush;
042        context = new LoggerContext();
043        logger = context.getLogger("logger-" + getName());
044
045        // A FileAppender is created according to the buffering and
046        // immediate flush setting of this IO instance.
047        FileAppender<ILoggingEvent> fa = new FileAppender<ILoggingEvent>();
048
049        if (longMessage) {
050            PatternLayoutEncoder pa = new PatternLayoutEncoder();
051            pa.setPattern("%r %5p %c [%t] - %m%n");
052            pa.setContext(context);
053            pa.start();
054            fa.setEncoder(pa);
055        } else {
056            fa.setEncoder(new EchoEncoder<ILoggingEvent>());
057        }
058
059        fa.setFile(getName() + ".log");
060        fa.setAppend(false);
061        fa.setContext(context);
062        fa.start();
063
064    }
065
066    public static void main(String[] argv) throws Exception {
067        if (argv.length != 4) {
068            usage("Wrong number of arguments.");
069        }
070
071        l = Integer.parseInt(argv[0]);
072        numThreads = Integer.parseInt(argv[1]);
073        scarceCPU = "true".equalsIgnoreCase(argv[2]);
074        longMessage = "long".equalsIgnoreCase(argv[3]);
075
076        // ----------------------------------------------------
077        // first test with unbuffered IO and immediate flushing
078        perfCase(false, true, l);
079
080        // ----------------------------------------------------
081        // Second test with unbuffered IO and no immediate flushing
082        perfCase(false, false, l);
083
084        // ----------------------------------------------------
085        // Third test with buffered IO and no immediate flushing
086        perfCase(true, false, l);
087
088        // There is no fourth test as buffered IO and immediate flushing
089        // do not make sense.
090    }
091
092    static void usage(String msg) {
093        System.err.println(msg);
094        System.err.println("Usage: java " + IO.class.getName() + " runLength numThreads scarceCPU (short|long)\n"
095                        + "   runLength (integer) the number of logs to generate perthread\n" + "   numThreads (integer) the number of threads.\n"
096                        + "   scarceCPU (boolean) if true an additional CPU intensive thread is created\n" + "   (short|long) length of log messages.");
097        System.exit(1);
098    }
099
100    static void perfCase(boolean buffered, boolean immediateFlush, long len) throws Exception {
101        IO[] threads = new IO[numThreads];
102        Counter counterThread = null;
103
104        if (scarceCPU) {
105            counterThread = new Counter();
106            counterThread.start();
107        }
108
109        // First create the threads
110        for (int i = 0; i < numThreads; i++) {
111            threads[i] = new IO(buffered, immediateFlush, len);
112        }
113
114        // then start them
115        for (int i = 0; i < numThreads; i++) {
116            threads[i].start();
117        }
118
119        // wait for them to processPriorToRemoval, compute the average throughput
120        double sum = 0;
121
122        for (int i = 0; i < numThreads; i++) {
123            threads[i].join();
124            sum += threads[i].throughput;
125        }
126
127        if (scarceCPU) {
128            // setting the interrupted field will cause counterThread to processPriorToRemoval
129            counterThread.interrupted = true;
130            counterThread.join();
131        }
132
133        System.out.println("On average throughput of " + (sum / numThreads) * 1000 + " logs per microsecond.");
134        System.out.println("------------------------------------------------");
135    }
136
137    public void run() {
138        String msg = msgShort;
139
140        if (longMessage) {
141            msg = msgLong;
142        }
143
144        long before = System.nanoTime();
145
146        for (int i = 0; i < len; i++) {
147            logger.debug(msg);
148        }
149
150        throughput = (len * 1.0) / (System.nanoTime() - before);
151        System.out.println(getName() + ", buffered: " + buffered + ", immediateFlush: " + immediateFlush + ", throughput: " + throughput
152                        + " logs per nanosecond.");
153    }
154}
155
156class Counter extends Thread {
157    public boolean interrupted = false;
158    public double counter = 0;
159
160    public void run() {
161        long before = System.nanoTime();
162
163        while (!interrupted) {
164            if (counter % 1000 == 0) {
165                Thread.yield();
166            }
167            counter += 1.0;
168        }
169
170        double tput = (counter * 1.0) / (System.nanoTime() - before);
171        System.out.println("Counter thread " + getName() + " incremented counter by " + tput + " per nanosecond.");
172    }
173}