Package org.perf4j.log4j

Source Code of org.perf4j.log4j.AppenderTest$TestLoggingThread

/* Copyright (c) 2008-2009 HomeAway, Inc.
* All rights reserved.  http://www.perf4j.org
*
* Licensed 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.perf4j.log4j;

import junit.framework.TestCase;
import org.apache.commons.io.FileUtils;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;
import org.apache.log4j.xml.DOMConfigurator;
import org.perf4j.StopWatch;

import java.io.File;
import java.text.DateFormat;
import java.text.SimpleDateFormat;
import java.util.Scanner;
import java.util.concurrent.atomic.AtomicInteger;
import java.util.regex.Pattern;
import java.lang.reflect.Field;

/**
* This class tests the log4j appenders.
*/
public class AppenderTest extends TestCase {
    public void testAppenders() throws Exception {
        DOMConfigurator.configure(getClass().getResource("log4j.xml"));

        AsyncCoalescingStatisticsAppender appender =
                (AsyncCoalescingStatisticsAppender) Logger.getLogger(StopWatch.DEFAULT_LOGGER_NAME)
                        .getAppender("coalescingStatistics");

        //log from a bunch of threads
        TestLoggingThread[] testThreads = new TestLoggingThread[10];
        for (int i = 0; i < testThreads.length; i++) {
            testThreads[i] = new TestLoggingThread();
            testThreads[i].start();
        }

        for (TestLoggingThread testThread : testThreads) {
            testThread.join();
        }

        //close the output appender, which prevents us from returning until this method completes.
        appender.close();

        //simple verification ensures that the total number of logged messages is correct.
        //tagName  avg           min     max     std dev       count, which is group 1
        String regex = "tag\\d\\s*\\d+\\.\\d\\s*\\d+\\s*\\d+\\s*\\d+\\.\\d\\s*(\\d+)";
        Pattern statLinePattern = Pattern.compile(regex);
        Scanner scanner = new Scanner(new File("target/statisticsLog.log"));

        int totalCount = 0;
        while (scanner.findWithinHorizon(statLinePattern, 0) != null) {
            totalCount += Integer.parseInt(scanner.match().group(1));
        }
        assertEquals(testThreads.length * TestLoggingThread.STOP_WATCH_COUNT, totalCount);
    }
   
    // http://jira.codehaus.org/browse/PERFFORJ-21
    public void testAppendersTimesliceOver() throws Exception {
      // need to do immediateflush on the fileappender since close will not be called
        DOMConfigurator.configure(getClass().getResource("log4j-timeslicebug.xml"));

        AsyncCoalescingStatisticsAppender appender =
                (AsyncCoalescingStatisticsAppender) Logger.getLogger(StopWatch.DEFAULT_LOGGER_NAME)
                        .getAppender("coalescingStatistics");

        //log from a bunch of threads
        TestLoggingThread[] testThreads = new TestLoggingThread[10];
        for (int i = 0; i < testThreads.length; i++) {
            testThreads[i] = new TestLoggingThread();
            testThreads[i].start();
        }

        for (TestLoggingThread testThread : testThreads) {
            testThread.join();
        }
       
        // we should see all the logging after waiting this long
        Thread.sleep(2*appender.getTimeSlice());

        //simple verification ensures that the total number of logged messages is correct.
        //tagName  avg           min     max     std dev       count, which is group 1
        String regex = "tag\\d+\\s*\\d+\\.\\d\\s*\\d+\\s*\\d+\\s*\\d+\\.\\d\\s*(\\d+)";
        Pattern statLinePattern = Pattern.compile(regex);
        Scanner scanner = new Scanner(new File("target/statisticsLog-timeslicebug.log"));

        int totalCount = 0;
        while (scanner.findWithinHorizon(statLinePattern, 0) != null) {
            totalCount += Integer.parseInt(scanner.match().group(1));
        }
        assertEquals(testThreads.length * TestLoggingThread.STOP_WATCH_COUNT, totalCount);
    }

    //test for http://jira.codehaus.org/browse/PERFFORJ-22
    public void testFlushOnShutdown() throws Exception {
        DOMConfigurator.configure(getClass().getResource("log4j-shutdownbug.xml"));

        //make a bunch of logs, but not enough to go over the timeslice.
        for (int i = 0; i < 5; i++) {
            StopWatch stopWatch = new Log4JStopWatch("tag1");
            Thread.sleep(10 * i);
            stopWatch.stop();
        }

        //at this point none of the file appenders will have written anything because they haven't been flushed
        assertEquals("", FileUtils.readFileToString(new File("target/stats-shutdownbug.log")));
        assertEquals("", FileUtils.readFileToString(new File("target/graphs-shutdownbug.log")));

        //now, to simulate shutdown, get the async appender and run the shutdown hook. We need to use reflection
        //because the shutdown hook is private.
        AsyncCoalescingStatisticsAppender appender =
                (AsyncCoalescingStatisticsAppender) Logger.getLogger(StopWatch.DEFAULT_LOGGER_NAME)
                        .getAppender("coalescingStatistics");
        Field shutdownField = appender.getClass().getDeclaredField("shutdownHook");
        shutdownField.setAccessible(true);
        AsyncCoalescingStatisticsAppender.ShutdownHook shutdownHook = (AsyncCoalescingStatisticsAppender.ShutdownHook) shutdownField.get(appender);
        assertNotNull("shutdownHook should not be null", shutdownHook);
        assertNotNull("shutdownHook appender should not be null", shutdownHook.getAppender());
        shutdownHook.run();

        //now there should be data in the files
        assertFalse("".equals(FileUtils.readFileToString(new File("target/stats-shutdownbug.log"))));
        assertFalse("".equals(FileUtils.readFileToString(new File("target/graphs-shutdownbug.log"))));

        // closing should remove shutdown hook
        appender.close();

        // hard to test hook removal, but we set it to null at the same time, so we'll rely on that
        shutdownHook = (AsyncCoalescingStatisticsAppender.ShutdownHook) shutdownField.get(appender);
        assertNull("shutdownHook should be null", shutdownHook);
    }

    public void testOverflowHandling() throws Exception {
        Logger logger = Logger.getLogger("AppenderTest.overflowTest");
        AsyncCoalescingStatisticsAppender appender = new AsyncCoalescingStatisticsAppender();
        appender.setName("overflowTestAppender");
        appender.setTimeSlice(1000);
        appender.setQueueSize(2); //set low queue size so we overflow
        logger.addAppender(appender);
        logger.setAdditivity(false);
        logger.setLevel(Level.INFO);
        appender.activateOptions();

        for (int i = 0; i < 1000; i++) {
            StopWatch stopWatch = new StopWatch("testOverflow");
            Math.random(); //this should happen super fast, faster than the appender's Dispatcher thread can drain
            logger.info(stopWatch.stop());
        }

        //again close the appender
        appender.close();
        assertTrue("Expected some stop watch messages to get discarded", appender.getNumDiscardedMessages() > 0);
    }

    public void testCsvRenderer() throws Exception {
        DOMConfigurator.configure(getClass().getResource("log4jWCsv.xml"));

        Logger logger = Logger.getLogger("org.perf4j.CsvAppenderTest");

        for (int i = 0; i < 20; i++) {
            StopWatch stopWatch = new Log4JStopWatch(logger);
            Thread.sleep(i * 10);
            stopWatch.stop("csvTest");
        }

        //close the appender
        logger.getAppender("coalescingStatistics").close();

        //verify the statisticsLog.csv file
        DateFormat dateFormat = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss");
        for (Object line : FileUtils.readLines(new File("./target/statisticsLog.csv"))) {
            String[] values = line.toString().split(",");
            //first column is the tag
            assertEquals("\"csvTest\"", values[0]);
            //next 2 columns are the dates - ensure they can be parsed
            assertTrue(dateFormat.parse(values[1]).before(dateFormat.parse(values[2])));
            //next 3 columns are mean, min and max
            double mean = Double.parseDouble(values[3]);
            int min = Integer.parseInt(values[4]);
            int max = Integer.parseInt(values[5]);
            assertTrue(mean >= min && mean <= max);
            //next column is stddev - ust make sure it's parseable
            Double.parseDouble(values[6]);
            //next column is count
            assertTrue(Integer.parseInt(values[7]) < 20);
            //final column is TPS - just make sure it's parseable
            Double.parseDouble(values[8]);
        }

        //verify the pivotedStatisticsLog.csv file
        for (Object line : FileUtils.readLines(new File("./target/pivotedStatisticsLog.csv"))) {
            String[] values = line.toString().split(",");
            //first 2 columns are the dates - ensure they can be parsed
            assertTrue(dateFormat.parse(values[0]).before(dateFormat.parse(values[1])));
            //next column is mean, ensure it can be parsed
            Double.parseDouble(values[2]);
            //last column should be empty, so make sure last char on string is comma
            assertEquals(',', line.toString().charAt(line.toString().length() - 1));
        }
    }

    protected static class TestLoggingThread extends Thread {
        protected static final AtomicInteger index = new AtomicInteger();

        public static final int STOP_WATCH_COUNT = 20;

        public void run() {
            String loggingTag = "tag" + index.getAndIncrement();

            for (int i = 0; i < STOP_WATCH_COUNT; i++) {
                StopWatch stopWatch = new Log4JStopWatch(loggingTag);
                int sleepTime = (int) (Math.random() * 400);
                try { Thread.sleep(sleepTime); } catch (Exception e) { /*do nothing*/ }
                stopWatch.stop();
            }

            //this last sleep here seems necessary because otherwise Thread.join() above is returning before
            //we're really done.
            try { Thread.sleep(10); } catch (Exception e) { /*ignore*/ }
        }
    }
}
TOP

Related Classes of org.perf4j.log4j.AppenderTest$TestLoggingThread

TOP
Copyright © 2018 www.massapi.com. All rights reserved.
All source code are property of their respective owners. Java is a trademark of Sun Microsystems, Inc and owned by ORACLE Inc. Contact coftware#gmail.com.