记一次DEBUG级别日志造成的误伤

偶遇问题

开发中发现项目中有个使用MongoTemplate查询mongo数据的代码运行异常缓慢,有多慢呢?数据总量为50W条,满足查询条件的条数为25W条,查询过程没有排序,有 OR 运算,查询时间需要40秒左右… 这个查询的确是超级慢了,如果换成mysql应该也就5秒左右吧。(项目基于springboot2.1.3,mongo依赖包版本3.8.2)。

走查代码后,没有发现明显异常的代码,代码就是下面这么简简单单的这一句:

1
List<JSONObject> list = mongoTemplate.find(query, JSONObject.class, COLLECTION);

代码看起来没有问题,看看后台日志,发现查询时后台疯狂打印出了很多如下的日志。

1
2
3
4
5
6
7
8
2019-04-11 02:20:27.483 DEBUG 1 --- [apr-8080-exec-2] EnableEncryptablePropertiesBeanFactoryPostProcessor : Application Event Raised: AfterLoadEvent
2019-04-11 02:20:27.483 DEBUG 1 --- [apr-8080-exec-2] EnableEncryptablePropertiesBeanFactoryPostProcessor : Application Event Raised: AfterLoadEvent
2019-04-11 02:20:27.483 DEBUG 1 --- [apr-8080-exec-2] EnableEncryptablePropertiesBeanFactoryPostProcessor : Application Event Raised: AfterConvertEvent
2019-04-11 02:20:27.483 DEBUG 1 --- [apr-8080-exec-2] EnableEncryptablePropertiesBeanFactoryPostProcessor : Application Event Raised: AfterConvertEvent
2019-04-11 02:20:27.483 DEBUG 1 --- [apr-8080-exec-2] EnableEncryptablePropertiesBeanFactoryPostProcessor : Application Event Raised: AfterLoadEvent
2019-04-11 02:20:27.483 DEBUG 1 --- [apr-8080-exec-2] EnableEncryptablePropertiesBeanFactoryPostProcessor : Application Event Raised: AfterLoadEvent
2019-04-11 02:20:27.483 DEBUG 1 --- [apr-8080-exec-2] EnableEncryptablePropertiesBeanFactoryPostProcessor : Application Event Raised: AfterConvertEvent
2019-04-11 02:20:27.483 DEBUG 1 --- [apr-8080-exec-2] EnableEncryptablePropertiesBeanFactoryPostProcessor : Application Event Raised: AfterConvertEvent

查找问题

通过上面日志显示的类名EnableEncryptablePropertiesBeanFactoryPostProcessor查询(下文简称PostProcessor,类名真的太长了),发现日志是加密工具jasypt打印的,具体代码位置见下图:

图1 打印日志代码

起初会以为是加密所致的问题,于是查看了jasypt加密原理,发现和mongo的查询没有半毛钱关系…

那么为什么mongo查询的时候会执行上图方法呢?继续观察PostProcessor类,发现上图方法实现自接口ApplicationListener,根据原理可知,实现了该接口的类就是一个观察者,当有ApplicationEvent事件发布的时候,ApplicationListener的实现类(观察者,即PostProcessor)就会执行onApplicationEvent方法。

有了上述原理支持,那么说明mongoTemplate查询的时候肯定是发布了ApplicationEvent事件了,于是跟踪了MongoTemplate方法执行,发现了MongoTemplate查询出数据后,将数据转换为指定类型(案列中为JSONObject.class)的前后,就会发送ApplicationEvent事件,分别是AfterLoadEventAfterConvertEvent,代码如下,图2是执行类型转换的调用,图3是执行类型转换。

图2 Mongo数据类型转换调用

图3 发布事件(onApplicationEvent获得事件并打印开头的日志)

现在知道日志是怎么打印出来的了,然而代码看起来好像也没有什么特别的地方(只是有点不明白为什么类型转换前后的信息要通过事件的方式发布)。但是,不要忘记了查出来的数据量是比较大的,大概是25W条,那么类型转换会执行25W次,日记会打印50W条,分别输出到控制台和日志文件,而springboot2默认的日志框架lockback默认为同步打印日志,这将是多么的疯狂和耗时的操作…

解决问题

原因找到了,解决办法就是将com.ulisesbocchioPostProcessor类所在的包)的日志级别从debug调到更高,Springboot在application.properties配置文件中添加如下配置即可:

1
logging.level.com.ulisesbocchio=warn

再次调试,发现查询缓慢的问题依然存在!上述的日志没有打印了,却发现系统将查询出的数据全部打印出来了… 25W条数据赤裸裸的打印到了控制台!于是查找打印日志的代码,原来是MongoTemplate查询完成后打印的,代码如下图(也不知道MongoTemplate怎么想的,不用trace级别)。

图4 MongoTemplate打印查询结果

因为开发时想看查询语句,所以将org.springframework.data.mongodb.core设置了debug级别,没想到会将所有数据打印出来… 解决方法同样是将日志级别调高即可。

1
logging.level.org.springframework.data.mongodb.core=warn

再次调试,问题解决,查询时间也从40秒变成了14秒左右。估计这个时间差不多就是MongoTemplate.find查询的耗时了。另外测试发现类型转换也会消耗一些时间,可以进一步优化,使用不转换类型的查询语句,查询出来的类型为Document,这样免去了Spring的转换,可以提高查询效率,经过测试,最终查询耗时为11.5秒左右,查询代码如下:

1
2
Iterable<Document> it = mongoTemplate.getCollection(COLLECTION)
.find(query.getQueryObject()).projection(query.getFieldsObject());
  1. mongoTemplate.getCollection获取collection,之后可以调用find方法。
  2. find调用后,还可以设置显示字段,mongo3以上设置字段使用projection方法,mongo3以下find方法可以传入2个参数,第二个参数就是字段信息。

结论

debug级别日志不要随意打,不是必须打印的日志都最好将日志级别调高,开发时可以将logging.level.root设置为debug,上线了一定要设置为infowarnerror之一。

参考