SLF4J你一些不知道的附加功能

目录

 

SLF4J extensions

Profilers

Extended Logger

Event Logging

---

SLF4J extensions

slf4j官方提供了一些附加功能，这些功能都在slf4j-ext.jar 中提供，这些附加功能主要包括:

• Profiler 分析器：可以阶段性的记录日志，并打印出各个阶段所耗费的时间，可用于性能分析之类的；
• Extended logger 扩展日志：提供entry和exit方法，可以在方法开始和结束时使用，打印记录使用过扩展日志的方法，以及方法的出入参数；
• Event Logger 事件日志：提供异步日志支持，通过MDC进行参数传递，实现异部线程之间日志参数的传递，如记录全局traceId,请求ip等；
• Logging added with Java Agent 代理日志添加：支持Java Agent代理做切面日志。

Profilers

Example: Using the profiler:

public class BasicProfilerDemo {
 
   public static void main(String[] args) {
     // create a profiler called "BASIC"
     Profiler profiler = new Profiler("BASIC");
     profiler.start("A");
     doA();
 
     profiler.start("B");
     doB();
     
     profiler.start("OTHER");
     doOther();
     profiler.stop().print();
   }
}

Running the above example will output the following output.

+ Profiler [BASIC]
|-- elapsed time                      [A]   220.487 milliseconds.
|-- elapsed time                      [B]  2499.866 milliseconds.
|-- elapsed time                  [OTHER]  3300.745 milliseconds.
|-- Total                         [BASIC]  6022.568 milliseconds.

Example2: Profiler nesting

public class NestedProfilerDemo {
 
  public static void main(String[] args) {
     // create a profiler called "DEMO"
     Profiler profiler = new Profiler("DEMO");
    
     // register this profiler in the thread context's profiler registry
     ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance();
     profiler.registerWith(profilerRegistry);
    
     // start a stopwatch called "RANDOM"
     profiler.start("RANDOM");
     RandomIntegerArrayGenerator riaGenerator = new RandomIntegerArrayGenerator();
     int n = 1000*1000;
     int[] randomArray = riaGenerator.generate(n);
     
     // create and start a nested profiler called "SORT_AND_PRUNE"
     // By virtue of its parent-child relationship with the "DEMO"
     // profiler, and the previous registration of the parent profiler, 
     // this nested profiler will be automatically registered
     // with the thread context's profiler registry
     profiler.startNested(SortAndPruneComposites.NESTED_PROFILER_NAME);
     
     SortAndPruneComposites pruner = new SortAndPruneComposites(randomArray);
     pruner.sortAndPruneComposites();
     
     // stop and print the "DEMO" printer
     profiler.stop().print();
   }
}

public class SortAndPruneComposites {
 
  static String NESTED_PROFILER_NAME = "SORT_AND_PRUNE";
    
  final int[] originalArray;
  final int originalArrayLength;
   
  public SortAndPruneComposites(int[] randomArray) {
    this.originalArray = randomArray;
    this.originalArrayLength = randomArray.length;
   
  }
   
  public int[] sortAndPruneComposites() {
    // retrieve previously registered profiler named "SORT_AND_PRUNE"
    ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance();
    Profiler sortProfiler = profilerRegistry.get(NESTED_PROFILER_NAME);

    // start a new stopwatch called SORT
    sortProfiler.start("SORT");
    int[] sortedArray = sort();
    // start a new stopwatch called PRUNE_COMPOSITES
    sortProfiler.start("PRUNE_COMPOSITES");
    int result[] = pruneComposites(sortedArray);
    
    return result;
  }
}

result:

+ Profiler [DEMO]
|-- elapsed time                 [RANDOM]    70.524 milliseconds.
|---+ Profiler [SORT_AND_PRUNE]
    |-- elapsed time                   [SORT]   665.281 milliseconds.
    |-- elapsed time       [PRUNE_COMPOSITES]  5695.515 milliseconds.
    |-- Subtotal             [SORT_AND_PRUNE]  6360.866 milliseconds.
|-- elapsed time         [SORT_AND_PRUNE]  6360.866 milliseconds.
|-- Total                          [DEMO]  6433.922 milliseconds.

Extended Logger

package com.test;

import org.slf4j.ext.XLogger;
import org.slf4j.ext.XLoggerFactory;

import java.util.Random;

public class TestService {
  private XLogger logger = XLoggerFactory.getXLogger(TestService.class
      .getName());

  private String[] messages = new String[] { "Hello, World",
      "Goodbye Cruel World", "You had me at hello" };

  private Random rand = new Random(1);

  public String retrieveMessage() {
    logger.entry();

    String testMsg = getMessage(getKey());

    logger.exit(testMsg);
    return testMsg;
  }

  public void exampleException() {
    logger.entry();
    try {
      String msg = messages[messages.length];
      logger.error("An exception should have been thrown");
    } catch (Exception ex) {
      logger.catching(ex);
    }
    logger.exit();
  }

  public String getMessage(int key) {
    logger.entry(key);

    String value = messages[key];

    logger.exit(value);
    return value;
  }

  private int getKey() {
    logger.entry();
    int key = rand.nextInt(messages.length);
    logger.exit(key);
    return key;
  }
}

package com.test;

public class App {
  public static void main( String[] args )    {
    TestService service = new TestService();
    service.retrieveMessage();
    service.retrieveMessage();
    service.exampleException();
  }
} 

xml

<?xml version='1.0' encoding='UTF-8'?>
<configuration>
  <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
    <filter class="ch.qos.logback.classic.filter.LevelFilter">
      <level>ERROR</level>
      <onMatch>ACCEPT</onMatch>
      <onMismatch>DENY</onMismatch>
    </filter>
    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>%d{HH:mm:ss.SSS} %-5level %class{36}:%L %M - %msg%n</Pattern>
    </layout>
  </appender>
  <appender name="log" class="ch.qos.logback.core.FileAppender">
    <File>target/test.log</File>
    <Append>false</Append>
    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>%d{HH:mm:ss.SSS} %-5level %class{36}:%L %M - %msg%n</Pattern>
    </layout>
  </appender>

  <root>
    <level value="trace" />
    <appender-ref ref="log" />
  </root>
</configuration>

result:

00:07:57.725 TRACE com.test.TestService:22 retrieveMessage - entry
00:07:57.738 TRACE com.test.TestService:57 getKey - entry
00:07:57.739 TRACE com.test.TestService:59 getKey - exit with (0)
00:07:57.741 TRACE com.test.TestService:47 getMessage - entry with (0)
00:07:57.741 TRACE com.test.TestService:51 getMessage - exit with (Hello, World)
00:07:57.742 TRACE com.test.TestService:26 retrieveMessage - exit with (Hello, World)
00:07:57.742 TRACE com.test.TestService:22 retrieveMessage - entry
00:07:57.742 TRACE com.test.TestService:57 getKey - entry
00:07:57.743 TRACE com.test.TestService:59 getKey - exit with (1)
00:07:57.745 TRACE com.test.TestService:47 getMessage - entry with (1)
00:07:57.745 TRACE com.test.TestService:51 getMessage - exit with (Goodbye Cruel World)
00:07:57.746 TRACE com.test.TestService:26 retrieveMessage - exit with (Goodbye Cruel World)
00:07:57.746 TRACE com.test.TestService:32 exampleException - entry
00:07:57.750 ERROR com.test.TestService:40 exampleException - catching
java.lang.ArrayIndexOutOfBoundsException: 3
  at com.test.TestService.exampleException(TestService.java:35)
  at com.test.AppTest.testApp(AppTest.java:39)
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
  at java.lang.reflect.Method.invoke(Method.java:585)
  at junit.framework.TestCase.runTest(TestCase.java:154)
  at junit.framework.TestCase.runBare(TestCase.java:127)
  at junit.framework.TestResult$1.protect(TestResult.java:106)
  at junit.framework.TestResult.runProtected(TestResult.java:124)
  at junit.framework.TestResult.run(TestResult.java:109)
  at junit.framework.TestCase.run(TestCase.java:118)
  at junit.framework.TestSuite.runTest(TestSuite.java:208)
  at junit.framework.TestSuite.run(TestSuite.java:203)
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
  at java.lang.reflect.Method.invoke(Method.java:585)
  at org.apache.maven.surefire.junit.JUnitTestSet.execute(JUnitTestSet.java:213)
  at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140)
  at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127)
  at org.apache.maven.surefire.Surefire.run(Surefire.java:177)
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
  at java.lang.reflect.Method.invoke(Method.java:585)
  at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338)
  at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997)
00:07:57.750 TRACE com.test.TestService:42 exampleException - exit

Event Logging

使用EventLogging时MDC中可以填充一些信息，使用 EventLogger.logEvent(data) 可以被记录

下面例子在请求过滤器中将ipAddress,loginId,hostName,productName,locale,timeZone信息都全局存入了MDC中

Appender中日志格式通过%X{key}的方式可以打印出对应的值

import org.slf4j.MDC;
import org.apache.commons.lang.time.DateUtils;

import javax.servlet.Filter;
import javax.servlet.FilterConfig;
import javax.servlet.ServletException;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import javax.servlet.FilterChain;
import javax.servlet.http.HttpSession;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.Cookie;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
import java.util.TimeZone;

public class RequestFilter implements Filter
{
  private FilterConfig filterConfig;
  private static String TZ_NAME = "timezoneOffset";

  public void init(FilterConfig filterConfig) throws ServletException {
    this.filterConfig = filterConfig;
  }

  /**
   * Sample filter that populates the MDC on every request.
   */
  public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse,
                       FilterChain filterChain) throws IOException, ServletException {
    HttpServletRequest request = (HttpServletRequest)servletRequest;
    HttpServletResponse response = (HttpServletResponse)servletResponse;
    MDC.put("ipAddress", request.getRemoteAddr());
    HttpSession session = request.getSession(false);
    TimeZone timeZone = null;
    if (session != null) {
      // Something should set this after authentication completes
      String loginId = (String)session.getAttribute("LoginId");
      if (loginId != null) {
        MDC.put("loginId", loginId);
      }
      // This assumes there is some javascript on the user's page to create the cookie.
      if (session.getAttribute(TZ_NAME) == null) {
        if (request.getCookies() != null) {
          for (Cookie cookie : request.getCookies()) {
            if (TZ_NAME.equals(cookie.getName())) {
              int tzOffsetMinutes = Integer.parseInt(cookie.getValue());
              timeZone = TimeZone.getTimeZone("GMT");
              timeZone.setRawOffset((int)(tzOffsetMinutes * DateUtils.MILLIS_PER_MINUTE));
              request.getSession().setAttribute(TZ_NAME, tzOffsetMinutes);
              cookie.setMaxAge(0);
              response.addCookie(cookie);
            }
          }
        }
      }
    }
    MDC.put("hostname", servletRequest.getServerName());
    MDC.put("productName", filterConfig.getInitParameter("ProductName"));
    MDC.put("locale", servletRequest.getLocale().getDisplayName());
    if (timeZone == null) {
      timeZone = TimeZone.getDefault();
    }
    MDC.put("timezone", timeZone.getDisplayName());
    filterChain.doFilter(servletRequest, servletResponse);
    MDC.clear();
  }

  public void destroy() {
  }
} 

import org.slf4j.ext.EventData;
import org.slf4j.ext.EventLogger;

import java.util.Date;
import java.util.UUID;

public class MyApp {

  public String doFundsTransfer(Account toAccount, Account fromAccount, long amount) {
    toAccount.deposit(amount);
    fromAccount.withdraw(amount);
    EventData data = new EventData();
    data.setEventDateTime(new Date());
    data.setEventType("transfer");
    String confirm = UUID.randomUUID().toString();
    data.setEventId(confirm);
    data.put("toAccount", toAccount);
    data.put("fromAccount", fromAccount);
    data.put("amount", amount);
    EventLogger.logEvent(data);
    return confirm;
  }
}  

<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</Pattern>
    </layout>
  </appender>

  <appender name="events" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>%d{HH:mm:ss.SSS} %X - %msg%n</Pattern>
    </layout>
  </appender>

  <logger name="EventLogger" additivity="false">
    <level value="INFO"/>
    <appender appender-ref="events"/>
  </logger>

  <root level="DEBUG">
    <appender-ref ref="STDOUT" />
  </root>

</configuration>