查看原文
其他

一招提速30ms,解密58同镇推荐业务之动态日志级别配置实践

杨春建 58技术 2022-03-15

导语

最近在做58同镇推荐数据响应时间优化,在代码重构方面做了很多工作的同时,思考了从日志方面优化响应时间的方法。希望我们的思路能够对大家有所启发。



背景

推荐场景下,服务的响应时间对用户体验至关重要,200ms以下返回推荐数据对于服务接口来说是一个挑战,一丝一毫的可优化点都值得思考并优化。
然而在后端算法不断迭代、增多的情况下,保证服务响应时间也是不得不面对的难题。从日志级别着手优化是折中的一种方法,有利有弊,存在不能复现某些特定场景下特定Imei的请求情况的可能,不过为防止这种情况,可以分组日志级别对待,这种取舍需要根据实际情况决定是否执行。带来的好处是明显的,最直接的体现就是响应时间加快。

场景

最近在做58同镇推荐数据响应时间优化,在代码重构方面做了很多工作的同时,思考了从日志方面优化响应时间的方法。结合58同镇内部SCF(Service Communication Framework)工程(不同于SpringBoot等原生Spring项目)、Log4j框架、JDK8实现线上环境业务日志级别控制。

SCF支持跨平台,具有高并发、高性能、高可靠性、并提供异步、多协议、事件驱动等。读者可以把SCF理解为一种SOA服务框架,类似Dubbo,也有Server端、Client端、Serializer序列化、Protocol传输协议等。

本文重点是想传达种配置思想,这种思想不局限于具体的日志框架、不局限于某种具体SOA框架,所以后文没有对SCF本身做过多的表述,而重点提到在这个大背景下的接口性能优化及问题排查。在服务响应时间优化方面,切实可行的方法很多。在推荐业务中,前期已经做了大量的响应时间优化工作,例如:

  1. 尽量少用JDK8中已经封装好的简易集合操作。例如Lamda表达式,优化后删除了程序中使用到的Lamda表达式,因为单元测试表明,Lamda表达式并没有通用的For循环省时。

  2. 对于所使用的第三方依赖库,需要了解响应性能情况。例如对象属性值拷贝时,用传统的对象Set、Get方法,比通用的Copy工具类(CGLib、反射等)用时更节省。

  3. CAP之间总是要做权衡,用户实时行为及时响应与延迟响应之间也要取舍。例如在推荐算法中,对于大数据量的算法模型实时数据计算改为离线计算,数据预先加载等。

  4. 直接从内存中取数据。例如服务接口中,涉及的黑白名单数据变动不是很频繁,数据量也不会太大,这种类型的数据可以通过Guava内存缓存在本地,过期时间可以根据业务调整,当数据过期时再从Redis中查询到最新的黑白名单数据,响应用时几乎0毫秒。

  5. 多线程的灵活运用,空间换时间。通过多线程全并发查询召回候选集、排序模型、融合模型,即通过空间换时间的方式来加快数据计算,对于响应超时的召回走兜底逻辑等。

  6. 编写代码时,方法命名不宜过长,且慎用以get开头,因为在直接使用框架调用此代码时可能会有问题。例如使用com.alibaba.fastjson.JSON. toJSONString(Object object)方法时要特别注意object对象中以get开头命名的方法。曾经线上使用时出现了服务接口被调用两次的情况,梳理代码时,发现显示的只调用了一次服务接口,可是日志记录显示服务接口被调用了两次,导致此问题的原因就是com.alibaba.fastjson.JSON. toJSONString(Object object)中会调用object中的以get开头的方法。

  7. 降低IO网络传输消耗,减少服务调用次数。在服务之间依赖调用时,尽量减小传输实体大小,减小序列化传输Size的大小,对于字段值占用过多字节的尽可能不传输,例如文章内容不传输,只传输文章id。对于同一个服务的多次调用改为一次调用等等。

当然,优化日志部分也是其中之一,如果来回修改代码中日志级别部分,然后再上线,这样操作会使人身心俱惫,且操作繁琐费时。日志级别可配置更利于修改或扩展。

同时,对于线上出现的诡异问题,提供种排查问题的思路。

服务优化后访问量耗时平均值下降30ms+。

红框部分下降30ms+


配置步骤

配置步骤大概分为以下几步:

  1.  线上部署机器环境分组

  2. 不同组设置不同日志级别

  3. 设置环境变量

  4. 程序中读取环境变量

  5. 程序中设置全局日志级别

配置流程图如下:

配置流程图

我们可以配置更多组来更细化日志配置,这里配置了两个组,来解决重点关心的响应时间问题。如果您更关心Debug级别日志,当然也可以配置对应级别的分组。


具体配置

机器分组配置

在云管理平台分组管理中点击新建,如下图中建立了两个分组:

分组管理页面

这样做只是为了做环境区分,任何的部署平台都能够做到环境隔离,例如TeamCity等。这里用的是公司内部的云平台。

点击上图的新建按钮后弹出页面如下图: 

新建页面

当然了,我们也可以不依赖这个页面,而是自己指定把变量存储在某个文件中,然后把这个文件放置在某个服务器的某个路径下,在程序中,我们只需要把变量值读取出来就可以。或者通过中间DB(Redis、Mongodb等)存储,再从程序中读出。


环境变量配置

在实例管理中点击配置分组,并点击高级设置环境变量,例如logLevel

配置分组页面

环境变量名可随意命名,为了见名知意,我们这里设置环境变量名为logLevel,值为INFO,程序中会赋默认值,防止读取变量值为空时的空指针问题。


程序部分配置

主要Java代码如下:

1) 读取环境变量

String logLevel = System.getenv("logLevel");

这里我们通过JDK自带的工具包获得环境变量值,如果此值是存储到某服务器的某个指定目录下或通过中间DB(Redis、Mongodb等)存储的,那程序中读取时,按相应的读取程序编写即可。


2) 设置全局日志级别

import org.apache.log4j.Level;import org.apache.log4j.LogManager;import org.apache.log4j.Logger;LogManager.getRootLogger().setLevel(realLevel);

 不同的日志框架设置全局日志级别时的代码可能不同,需要区别对待。

3) 日志打印

import org.slf4j.Logger;import org.slf4j.LoggerFactory;private static Logger log = LoggerFactory.getLogger(xxx.class);

这里需要注意,推荐Slf4j框架的日志打印,在log4j的上面加上Slf4j,将要输出的日志提前格式化成一个字符串。加入Slf4j后可以发现的是日志的输出分成两步了,因为执行log.info时,会首先对要输出的内容进行格式化,将其格式化成一个String,所以不会发生死锁。并不推荐以下方式的日志打印:

import org.apache.log4j.Logger;private static Logger logger = Logger.getLogger(xxx.class);

这种方式可能会出现Locked死锁问题,线上环境也确实出现了这种导致服务不可用的情况,文章后面会提到。


问题排查

通过后台输出日志可以看出,日志级别的配置是成功的。可以做到分组配置日志级别。这样就可以在不修改代码的情况下按情况配置日志级别,按需查看日志及线上问题排查。

当用到日志时,统一日志规范很重要,在线上部署的情况下,看似容易的日志打印也会出现怪异的线上问题,并导致服务接口不可用。例如某天线上服务接口超时量在9点后的某一时刻突增,如下图:

调用方超时量页面

对于这种情况,先入为主的想法可能是SCF服务框架(类似Dubbo)本身有问题了,看后台日志,也确实如此:

SCF日志

从中看出并发超时TimeoutException异常,不过我们还看不出是哪里导致的框架超时问题。

再细看监控平台发现是FullGC的问题导致服务超时量增多:

监控页面

为了锁定是什么原因导致的FullGC问题并及时保证线上可用,主要从以下方面入手:

1) 服务应用重启(Error级别分组(组2))
2) Info级别分组(组1)服务节点从线上摘除,并不重启
3) 增大新生代、老生代等JVM参数重新上线(首先保证服务可用)
4) 登录Info级别容器后台查看堆栈信息或GC信息等等

排查时,用以下命令

jstack -l pid >> /tmp/1.log


jstat -gc pid


*注意:确认部署容器是否有jstack或jstat操作命令,及是否有相关目录操作权限。打印出线上环境的堆栈信息,如下图:

堆栈日志

从中可以看到Locked字样,可以锁定是因为日志框架的死锁问题导致服务不可用。感兴趣的读者可以了解log4j的死锁问题,可以看出这并不是咱们配置日志分组导致的问题,而是log4j框架本身就存在这种死锁问题,使用时需要特别注意。相应的解决方法一般有两方面:

1) 用log4j2或Slf4j日志框架替换log4j。
2) 注意定义日志变量时加入static声明,或在打印日志配置中设置缓冲区
<appender name="MyLog" class="org.apache.log4j.DailyRollingFileAppender"><param name="File" value="/data/logs/feeds/log_info.log" /><param name="encoding" value="UTF-8" /><param name="DatePattern" value="'.'yyyy.MM.dd" /><param name="Append" value="true" /><param name="BufferSize" value="8192" /><param name="ImmediateFlush" value="false" /><param name="BufferedIO" value="true" />

线上日志有死锁问题,那奇怪了,之前也用log4j日志框架,为什么之前没出现这个问题?具体程序中是什么原因导致的死锁问题呢?

首先,我们用Top命令查看CPU信息等

top

显示如下:

top页面

可以看出线上CPU的占用率特别高,用命令查看GC情况

jstat –gccause pid

显示如下:

jstat页面

从中可以看出YGC特别的频繁,用命令打印堆栈信息

jmap –heap pid

显示如下:

jmap页面

可以看出新生代、老生代等配置及使用情况,用命令:

jmap -dump:live,format=b,file=/opt/heap2.bin pid

导出dump文件,并sz命令到本地。通过MAT(Eclipse Memory Analyzer)工具分析出可以看出某个class占用过多:

mat页面

至此锁定到具体代码,点击by outgoing references后显示如下:

by outgoing references页面

点击Leak Suspects时,如下图:

可以看出,在使用Guava缓存时,可能有内存泄漏的情况发生,具体看代码再结合具体业务场景,发现Guava缓存的设置有问题。

public LoadingCache<String, Map<String, List<Double>>> contentVecCache = CacheBuilder.newBuilder()            .maximumSize(40000)            .expireAfterWrite(2, TimeUnit.HOURS)            .build(new CacheLoader<String, Map<String, List<Double>>>() {                @Override                public Map<String, List<Double>> load(String key) {                    String itmeId = key.split("_")[0]; int dataSource = Integer.valueOf(key.split("_")[1]);                    Map<String, List<Double>> map = new HashMap<>();                   List<Double> titleVec = wordEmbeddingService.getContentEmbedding(itmeId, dataSource, EmbedContentType.TITLE);                    map.put("title", titleVec);                    List<Double> keywordVec = wordEmbeddingService.getContentEmbedding(itmeId, dataSource, EmbedContentType.KEYWORD);                    map.put("keyword", keywordVec);                    return map;                } });

缓存的Key数量,还有过期时间配置要结合具体业务、具体的硬件配置来定,不可盲目追求高性能而存入大量数据至撑爆硬件资源。至此,排查出具体哪里出现的问题。


经验总结

1. 部署后,线上环境推荐业务对外SCF服务接口的平均响应时间大概下降了30ms,服务超时量也有明显下降。服务响应时间优化是持续迭代的过程,任何的可优化点都值得思考是否可行,是否还能更优,响应时间下降5ms、10ms都是胜利。
2. 这种配置思想不止于Log4j框架的日志,对于LogBook等任何日志框架一样适用,只需要通过程序设置全局日志级别即可。这种配置思想中,环境变量的配置并不局限于某个具体系统,可以把环境变量配置在任何可以通过程序读取到的地方,当然为了响应时间考虑可以优先考虑内存形数据库等。

3. 遇到线上问题,沉着、冷静应对是必须的,把恢复线上稳定摆在第一位,然后在追踪问题根源,抽丝剥茧,最终把问题解决并尽量防止再发生。

4. 建议线上环境用Slf4j日志框架,可防止日志死锁问题。从项目一开始,日志框架的选择就要慎之又慎,防止后面更改日志框架时成本过高。

5. 对于其它部门线上环境日志级别如何区分配置也有现实参考意义,从日志层面着手优化也是切实可行的思考方向。


参考文献

1、 https://blog.csdn.net/zl378837964/article/details/84884934

2、 https://yq.aliyun.com/articles/271448


作者简介

杨春建,Java高级开发工程师,现就职于58 SLG-流量智能部。


END


开奖啦!!!


恭喜“封刀看海”同学获得2020年官方正品单向历!

祝福新的一年一切顺利,开心快乐!



您可能也对以下帖子感兴趣

文章有问题?点此查看未经处理的缓存