SLF4J和Logback与Commons Logging和Lo
在编写程序的过程中，发现程序运行结果与预期不符，怎么办？当然是用System.out.println()打印出执行过程中的某些变量，观察每一步的结果与代码逻辑是否符合，然后有针对性地修改代码。
代码改好了怎么办？当然是删除没有用的System.out.println()语句了。
如果改代码又改出问题怎么办？再加上System.out.println()。
反复这么搞几次，很快大家就发现使用System.out.println()非常麻烦。
怎么办？
解决方法是使用日志。
那什么是日志？日志就是Logging，它的目的是为了取代System.out.println()。
输出日志，而不是用System.out.println()，有以下几个好处：
- 可以设置输出样式，避免自己每次都写"ERROR: " + var；
- 可以设置输出级别，禁止某些级别输出。例如，只输出错误日志；
- 可以被重定向到文件，这样可以在程序运行结束后查看日志；
- 可以按包名控制日志级别，只输出某些包打的日志；
- 可以……
总之就是好处很多啦。
提到日志，我们自然会想到SLF4J和Logback与Commons Logging和Log4j这两对好基友。
Commons Logging和Log4j
和Java标准库提供的日志不同，Commons Logging是一个第三方日志库，它是由Apache创建的日志模块。
Commons Logging的特色是，它可以挂接不同的日志系统，并通过配置文件指定挂接的日志系统。默认情况下，Commons Loggin自动搜索并使用Log4j（Log4j是另一个流行的日志系统），如果没有找到Log4j，再使用JDK Logging。
Commons Logging，可以作为“日志接口”来使用。而真正的“日志实现”可以使用Log4j。
SLF4J和Logback
前面介绍了Commons Logging和Log4j这一对好基友，它们一个负责充当日志API，一个负责实现日志底层，搭配使用非常便于开发。
有的童鞋可能还听说过SLF4J和Logback。这两个东东看上去也像日志，它们又是啥？
其实SLF4J类似于Commons Logging，也是一个日志接口，而Logback类似于Log4j，是一个日志的实现。
为什么有了Commons Logging和Log4j，又会蹦出来SLF4J和Logback？这是因为Java有着非常悠久的开源历史，不但OpenJDK本身是开源的，而且我们用到的第三方库，几乎全部都是开源的。开源生态丰富的一个特定就是，同一个功能，可以找到若干种互相竞争的开源库。
因为对Commons Logging的接口不满意，有人就搞了SLF4J。因为对Log4j的性能不满意，有人就搞了Logback。
我们先来看看SLF4J对Commons Logging的接口有何改进。在Commons Logging中，我们要打印日志，有时候得这么写
int score = 99;
p.setScore(score);
log.info("Set score " + score + " for Person " + p.getName() + " ok.");
拼字符串是一个非常麻烦的事情，所以SLF4J的日志接口改进成这样了：
int score = 99;
p.setScore(score);
logger.info("Set score {} for Person {} ok.", score, p.getName());
我们靠猜也能猜出来，SLF4J的日志接口传入的是一个带占位符的字符串，用后面的变量自动替换占位符，所以看起来更加自然。
如何使用SLF4J？它的接口实际上和Commons Logging几乎一模一样：
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
class Main {
final Logger logger = LoggerFactory.getLogger(getClass());
}
对比一下Commons Logging和SLF4J的接口：
| Commons Logging | SLF4J |
|---|---|
| org.apache.commons.logging.Log | org.slf4j.Logger |
| org.apache.commons.logging.LogFactory | org.slf4j.LoggerFactory |
不同之处就是Log变成了Logger，LogFactory变成了LoggerFactory。
从目前的趋势来看，越来越多的开源项目从Commons Logging加Log4j转向了SLF4J加Logback。
为什么越来越多的人使用SLF4J加Logback，而不用Commons Logging加Log4j呢？是驴子是马，拿出来溜溜，我们利用jmh做一下基准测试。
利用jmh测试SLF4J和Logback与Commons Logging和Log4j的性能
使用Maven搭建基准测试项目骨架
JMH官方推荐使用Maven来搭建基准测试的骨架,使用也很简单，使用如下命令来生成maven项目:
mvn archetype:generate \
-DinteractiveMode=false \
-DarchetypeGroupId=org.openjdk.jmh \
-DarchetypeArtifactId=jmh-java-benchmark-archetype \
-DgroupId=org.sample \
-DartifactId=test \
-Dversion=1.0
上面的maven命令使用了jmh-java-benchmark-archetype来生成java语言的基准测试骨架，如果使用其他语言可以将这个参数对应替换,所有可选参数参考 jmh ,生成的项目groupId是org.sample,artifaceId是test，执行完之后会在当前目录下生成一个test目录，切换到test目录下执行 mvn clean install 就会生成benchmarks.jar,再使用 java -jar benchmarks.jar 就可以执行基准测试了。
JMH参数配置
如果你想直接在已有maven项目中集成JMH，那也很简单,手动在POM文件中添加以下两个依赖就行了,
<dependency>
<groupId>org.openjdk.jmh</groupId>
<artifactId>jmh-core</artifactId>
<version>1.19</version>
</dependency>
<dependency>
<groupId>org.openjdk.jmh</groupId>
<artifactId>jmh-generator-annprocess</artifactId>
<version>1.19</version>
<scope>provided</scope>
</dependency>
从maven archetype插件生成的pom文件来看，这个工程使用了maven-shade-plugin来将所有的依赖打包到同一个jar包中,并在Manifest文件中配置了Main-Class属性，这样就能直接通过java -jar命令来执行了，其实通过maven-assembly-plugin也可以达到同样的效果,如下所示:
<plugin>
<artifactId>maven-assembly-plugin</artifactId>
<version>3.1.0</version>
<configuration>
<descriptorRefs>
<descriptorRef>jar-with-dependencies</descriptorRef>
</descriptorRefs>
<archive>
<manifest>
<mainClass>org.openjdk.jmh.Mainp</mainClass>
</manifest>
</archive>
</configuration>
<executions>
<execution>
<id>make-assembly</id> <!-- this is used for inheritance merges -->
<phase>package</phase> <!-- bind to the packaging phase -->
<goals>
<goal>single</goal>
</goals>
</execution>
</executions>
</plugin>
可以看到jar包的入口在 org.openjdk.jmh.Mainp 这个类，查看这个类的源码可以发现这个类会从 /META-INF/BenchmarkList 文件中读取基准测试列表。在工作中你可能经常听过别人说不要logger中使用字符串拼接来打印日志，而是使用占位符或者使用logger.isDebugEnable()语句来判断,这三种写法的性能差异到底有多大,我们就来测试一下。
本文出于演示的目的来讲解JMH的使用,直接使用了官方的例子，使用slf4j+logback的组合来打印日志,首先在POM文件中添加依赖:
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-api</artifactId>
<version>1.7.7</version>
</dependency>
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-classic</artifactId>
<version>1.0.11</version>
</dependency>
</pre>
在resources目录下添加logback.xml文件，如下所示:
<configuration>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%highlight(%d{HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n)</pattern>
</encoder>
</appender>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder><pattern>%msg%n</pattern></encoder>
</appender>
<root level="INFO">
<appender-ref ref="CONSOLE" />
</root>
</configuration>
在另一个项目的resources目录下添加log4j2.xml文件
<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
<Properties>
<!-- 定义日志格式 -->
<Property name="log.pattern">%d{MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36}%n%msg%n%n</Property>
<!-- 定义文件名变量 -->
<Property name="file.err.filename">log/err.log</Property>
<Property name="file.err.pattern">log/err.%i.log.gz</Property>
</Properties>
<!-- 定义Appender，即目的地 -->
<Appenders>
<!-- 定义输出到屏幕 -->
<Console name="console" target="SYSTEM_OUT">
<!-- 日志格式引用上面定义的log.pattern -->
<PatternLayout pattern="${log.pattern}" />
</Console>
<!-- 定义输出到文件,文件名引用上面定义的file.err.filename -->
<RollingFile name="err" bufferedIO="true" fileName="${file.err.filename}" filePattern="${file.err.pattern}">
<PatternLayout pattern="${log.pattern}" />
<Policies>
<!-- 根据文件大小自动切割日志 -->
<SizeBasedTriggeringPolicy size="1 MB" />
</Policies>
<!-- 保留最近10份 -->
<DefaultRolloverStrategy max="10" />
</RollingFile>
</Appenders>
<Loggers>
<Root level="info">
<!-- 对info级别的日志，输出到console -->
<AppenderRef ref="console" level="info" />
<!-- 对error级别的日志，输出到err，即上面定义的RollingFile -->
<AppenderRef ref="err" level="error" />
</Root>
</Loggers>
</Configuration>
接下来就在MyBenchmark类中写测试代码了,三个方法分别对应三种不同的打印日志的写法,如下所示:
import org.openjdk.jmh.annotations.Benchmark;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class MyBenchmark {
private static final Logger logger = LoggerFactory.getLogger(MyBenchmark.class);
@Benchmark
public void testVariableArguments() {
String x = "", y = "", z = "";
for (int i = 0; i < 100; i++) {
x += i;
y += i;
z += i;
logger.debug("Variable arguments {} {} {}", x, y, z);
}
}
@Benchmark
public void testIfDebugEnabled() {
String x = "", y = "", z = "";
for (int i = 0; i < 100; i++) {
x += i; y += i; z += i;
if (logger.isDebugEnabled())
logger.debug("If debug enabled {} {} {}", x, y, z);
}
}
}
import org.openjdk.jmh.annotations.Benchmark;
import org.apache.commons.logging.Log
import org.apache.commons.logging.LogFactory
public class MyBenchmark {
private static final Log log = LogFactory.getLog(MyBenchmark.class);
@Benchmark
public void testConcatenatingStrings() {
String x = "", y = "", z = "";
for (int i = 0; i < 100; i++) {
x += i; y += i; z += i;
log.debug("Concatenating strings " + x + y + z);
}
}
}
最后使用maven命令打包并执行:
$ mvn clean install
$ java -jar target/benchmarks.jar
最后三种不同写法的性能对比如下所示：
| 迭代次数 | 字符串拼接 | 占位符 | isDebugEnabled |
|---|---|---|---|
| Iteration 1 | 57108,635 ops/s | 97921,939 ops/s | 104993,368 ops/s |
| Iteration 2 | 58441,293 ops/s | 98036,051 ops/s | 104839,216 ops/s |
| Iteration 3 | 58231,243 ops/s | 97457,222 ops/s | 106601,803 ops/s |
| Iteration 4 | 58538,842 ops/s | 100861,562 ops/s | 104643,717 ops/s |
| Iteration 5 | 57297,787 ops/s | 100405,656 ops/s | 104706,503 ops/s |
| Iteration 6 | 57838,298 ops/s | 98912,545 ops/s | 105439,939 ops/s |
| Iteration 7 | 56645,371 ops/s | 100543,188 ops/s | 102893,089 ops/s |
| Iteration 8 | 56569,236 ops/s | 102239,005 ops/s | 104730,682 ops/s |
| Iteration 9 | 57349,754 ops/s | 94482,508 ops/s | 103492,227 ops/s |
| Iteration 10 | 56894,075 ops/s | 101405,938 ops/s | 106790,525 ops/s |
| Average | 57491,4534 ops/s | 99226,5614 ops/s | 104913,1069 ops/s |
最后的结果也很明显了,使用isDebugEnabled性能最佳,使用字符串拼接性能最差，使用占位符性能也还不错，但是占位符的代码可读性更好，因此在项目中推荐使用占位符打印日志。
