betweenGo

Brian Ploetz sent me this great unit test for threaded logging.  In it we are trying to find if a deadlock occurs.

import java.lang.management.ManagementFactory;
import java.lang.management.ThreadInfo;
import java.lang.management.ThreadMXBean;

import junit.framework.TestCase;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.apache.log4j.Appender;
import org.apache.log4j.Logger;

/**
 * Unit test for the ThrottlingFilter in a multi-threaded environment
 */
public class ThrottlingFilterThreadUTest extends TestCase {

  private static final Log logger = LogFactory.getLog(ThrottlingFilterThreadUTest.class);

  private static ThreadMXBean threadMXBean;

  @Override
  protected void setUp() throws Exception {
    super.setUp();
    threadMXBean = ManagementFactory.getThreadMXBean();
    logger.info("Thread contention monitoring supported: "
        + threadMXBean.isThreadContentionMonitoringSupported());
    logger.info("Thread contention monitoring enabled: "
        + threadMXBean.isThreadContentionMonitoringEnabled());
    threadMXBean.setThreadContentionMonitoringEnabled(true);
    logger.info("Thread contention monitoring enabled: "
        + threadMXBean.isThreadContentionMonitoringEnabled());
  }

  /**
   * Tests multiple threads using the same filter instance at the same time
   */
  public void testThreads() {
    Logger rootLogger = Logger.getRootLogger();
    assertNotNull(rootLogger);
    Appender fileAppender = rootLogger.getAppender("FILE");
    assertNotNull(fileAppender);
    ThrottlingFilter throttlingFilter = (ThrottlingFilter) fileAppender.getFilter();
    assertNotNull(throttlingFilter);

    ThreadGroup infoThreadGroup = new ThreadGroup("info-group");
    ThreadGroup errorThreadGroup = new ThreadGroup("error-group");
    Thread errorThread1 = new ErrorThread(errorThreadGroup, "error-thread-1");
    Thread infoThread1 = new InfoThread(infoThreadGroup, "info-thread-1");
    Thread errorThread2 = new ErrorThread(errorThreadGroup, "error-thread-2");
    Thread infoThread2 = new InfoThread(infoThreadGroup, "info-thread-2");
    infoThread1.start();
    errorThread1.start();
    errorThread2.start();
    infoThread2.start();

    while (true) {
      ThreadInfo[] threadInfos = threadMXBean.getThreadInfo(threadMXBean.getAllThreadIds());
      for (int i = 0; i < threadInfos.length; i++) {
        ThreadInfo threadInfo = threadInfos[i];
        if (threadInfo != null && threadInfo.getThreadState() == Thread.State.BLOCKED) {
          System.out.println("Thread '" + threadInfo.getThreadName()
              + "' is blocked on the monitor lock '" + threadInfo.getLockName()
              + "' held by thread '" + threadInfo.getLockOwnerName() + "'");
        }
      }

      if (!infoThread1.isAlive() && !errorThread1.isAlive() && !infoThread2.isAlive()
          && !errorThread2.isAlive())
        break;
    }
  }

  public static class ErrorThread extends Thread {

    private static final Log logger = LogFactory.getLog(ErrorThread.class);

    public ErrorThread(ThreadGroup tg, String name) {
      super(tg, name);
    }

    public void run() {
      for (int i = 0; i < 10; i++) {
        try {
          test(0);
        } catch (Exception e) {
          long start = System.currentTimeMillis();
          logger.error("Error!", e);
          long end = System.currentTimeMillis();
          System.out.println("Took " + (end-start) + "ms to log error");
        }
      }
    }

    // simulate large stack traces
    private void test(int i) {
      if (i >= 500)
        throw new RuntimeException("D'OH!");
      test(i+1);
    }
  }

  public static class InfoThread extends Thread {

    private static final Log logger = LogFactory.getLog(InfoThread.class);

    public InfoThread(ThreadGroup tg, String name) {
      super(tg, name);
    }

    public void run() {
      for (int i = 0; i < 100; i++) {
        logger.info("Hi!");
      }
    }
  }
}

The log4j.xml test file.

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/"
    debug="false">

    <!-- ================================= -->
    <!--           Appenders               -->
    <!-- ================================= -->

    <!-- A time/date based rolling file appender -->
    <appender name="FILE"
        class="org.apache.log4j.DailyRollingFileAppender">
        <param name="File" value="server.log" />
        <param name="Append" value="true" />

        <!-- Rollover at midnight each day -->
        <param name="DatePattern" value="'.'yyyy-MM-dd" />

        <layout class="org.apache.log4j.PatternLayout">
            <!-- The default pattern: Date Priority [Category] Message\n -->
            <param name="ConversionPattern" value="%d %-5p [%c] %m%n" />
        </layout>

        <filter class="com.betweengo.log4j.ThrottlingFilter">
          <param name="maxCountSameMessage" value="100"/>
          <param name="maxCountSavedMessages" value="100"/>
          <param name="waitInterval" value="60"/>
        </filter>
    </appender>

    <!-- ======================= -->
    <!-- Setup the Root category -->
    <!-- ======================= -->

    <root>
        <level value="INFO" />
        <appender-ref ref="FILE" />
    </root>

</log4j:configuration>

Related posts:

1. How to Log SQL on JBoss
2. Log4j levels
3. Static Import
4. Accessing JavaBean’s Getters and Setters
5. Sleep