问题
近日，我对公司的某个存储服务进行了自动化性能测试框架的设计，该服务底层存储使用了 Redis+Mongodb。测试代码使用了 MongoDB 的 Java driver 对 MongoDB 进行了数据的读写。
测试期间，发现统计的读写性能总是与预期有很大差距，非常令人迷惑。起初以为是测试框架的设计或者 Redis 的问题，前前后后调试了很长时间仍然没有解决。
另外，在测试一开始时，Mongodb 的 Java driver 就会不停在控制台上输出 Debug 日志。对于这个问题，我很早就想解决，毕竟看起来确实很不爽。但由于时间的关系，并且自以为是的认为不会影响性能结果，也就在一直默默忍受。
最终，还是怀疑到了日志的头上。其实，动脚指头也能想到，日志的输出必定会对性能造成影响，因为每一条操作完成后都要输出到控制台，这也是需要时间损耗的，更何况是性能测试时的上千万条数据。
哎，只恨自己不灵光，关键还是太懒。
描述
如下图所示，程序运行时默认会有大量的 Debug 操作日志产生：
image.png
可以看到，基本每一条插入或查询操作都会在控制台输出 Debug 日志。当没有读写时，仍然会不断有 Mongodb 副本集的相关状态信息刷屏。
当读写结束后，又会产生有如下的日志：
image.png
如果长时间看到这些，真的会亮瞎人的眼睛。
原理
本人使用的驱动是 Mongo-java-driver-3.0.0.jar，用Eclipse定位到其日志相关部分：
image.png
我们知道，日志一般是通过 Logger 来输出的。此处，Logger有两种实现：SLF4JLogger 和 JULLogger 。其中：
- JULLogger 是 Java 自身的 java.util.logging.Logger
- SLF4JLogger 是更加流行的 org.slfj.logger
对于这二者的概念和区别大家可以自行谷歌百度之。
到底应该使用哪个实现呢，观察 Logger 类，可以看到如下成员：
private static final boolean USE_SLF4J = shouldUseSLF4J();
其表示类加载时，首先会调用 shouldUseSLF4j 方法。
shouldUseSLF4j 方法顾名思义，即是否使用 SLF4J 作为Logger的实现，代码如下：
private static boolean shouldUseSLF4J() {
try {
Class.forName("org.slf4j.LoggerFactory");
// Don't use SLF4J unless a logging implementation has been configured for it
Class.forName("org.slf4j.impl.StaticLoggerBinder");
return true;
} catch (ClassNotFoundException e) {
return false;
}
}
逻辑很简单：如果存在 SLF4J 的驱动就加载驱动，并返回 true，否则返回 false。
当然，最关键的还是getLogger函数：
public static Logger getLogger(final String suffix) {
notNull("suffix", suffix);
if (suffix.startsWith(".") || suffix.endsWith(".")) {
throw new IllegalArgumentException("The suffix can not start or end with a '.'");
}
String name = PREFIX + "." + suffix;
if (USE_SLF4J) {
return new SLF4JLogger(name);
} else {
return new JULLogger(name);
}
}
也就是说，如果你使用 SLF4J的驱动（如 Logback 或者 Log4j），则使用SLF4Logger，而不是用 Java 自带的 JULLogger 。
官方文档也说的也很清楚：
By default, logging is enabled via the popular SLF4J API. The use of SLF4J is optional; the driver will use SLF4J if the driver detects the presence of SLF4J in the classpath. Otherwise, the driver will fall back to JUL (java.util.logging).
只要你的 classpath 中有 SLF4J，就使用SLF4J 。
地址：http://mongodb.github.io/mongo-java-driver/3.0/driver/reference/management/logging/
解决
由于本人所测试的工程里使用了 Logback 作为 SLF4j 的实现，所以 mong-java-drivers 使用的 Logger 为 SLF4Logger。
此时，你肯定会想到， logback.xml 中的某些配置应该可以选择开启或关闭这种日志。
于是，查看了 mongo-java-drivers 的官方文档，发现有如下配置可以设定：
The driver uses the following logger names:
org.mongodb.driver: the root logger
cluster: for logs related to monitoring of the MongoDB servers to which the driver connects
connection: for logs related to connections and connection pools
protocol: for logs related to protocol message sent to and received from a MongoDB server
insert: for logs related to insert messages and responses
update: for logs related to update messages and responses
delete: for logs related to delete messages and responses
query: for logs related to query messages and responses
getmore: for logs related to getmore messages and responses
killcursor: for logs related to killcursor messages and responses
command: for logs related to command messages and responses
uri: for logs related to connection string parsing
management: for logs related to JMX
可以看到，org.mongodb.drive 是 root logger，其他为子logger。
为了方便测试，我们只需要将这些在 logback.xml 中关闭即可，关闭方法如下：
image.png
可以看到，这里将前面所有 logger 的 level 都设置成了 INFO。这样，就不再会输出前面的那些Debug日志了，当然高于Debug的任意级别都可以。
再次测试，一切正常，日志不再刷屏，本地性能测试统计结果也与预期相符了。
总结
这次分析的问题其实很简单，甚至根本就不需要专门写这篇文章。但还是想提醒下自己——不要自以为是，不要偷懒。
欢迎关注本人微信公众号：
爱你之心.jpg
网友评论