MongoDb 的 Java driver 一直输出 Debug 日志的解决办法

问题

近日,我对公司的某个存储服务进行了自动化性能测试框架的设计,该服务底层存储使用了 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的任意级别都可以。

再次测试,一切正常,日志不再刷屏,本地性能测试统计结果也与预期相符了。

总结

这次分析的问题其实很简单,甚至根本就不需要专门写这篇文章。但还是想提醒下自己——不要自以为是,不要偷懒。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 217,657评论 6 505
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 92,889评论 3 394
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 164,057评论 0 354
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 58,509评论 1 293
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 67,562评论 6 392
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 51,443评论 1 302
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 40,251评论 3 418
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 39,129评论 0 276
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 45,561评论 1 314
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,779评论 3 335
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,902评论 1 348
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 35,621评论 5 345
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 41,220评论 3 328
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,838评论 0 22
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,971评论 1 269
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 48,025评论 2 370
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,843评论 2 354

推荐阅读更多精彩内容