博客

redis环境变量配置_一招提速30ms，解密58同镇推荐业务之动态日志级别配置实践…

  • Post author:
  • Post category:其他

导语

最近在做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+。

f15f319f438c5ac9626855abe5fab3c9.png

红框部分下降30ms+

配置步骤

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

  1. 线上部署机器环境分组
  2. 不同组设置不同日志级别
  3. 设置环境变量
  4. 程序中读取环境变量
  5. 程序中设置全局日志级别

配置流程图如下：

b494870e484d54c3ace7d803b8a0ac8d.png

配置流程图

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

具体配置

机器分组配置

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

47ee6e59af2bd4a162bacea799cb0d55.png

分组管理页面

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

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

d3a7e69af3f0dfaf1bcab12eed6fe407.png

新建页面

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

环境变量配置

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

5557cd0812b052c7b029624214e224cb.png

配置分组页面

环境变量名可随意命名，为了见名知意，我们这里设置环境变量名为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点后的某一时刻突增，如下图：

a35d97eb33d8f66815e17029026f691c.png

调用方超时量页面

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

70e802afa134de4303a2d89e675f09a3.png

SCF日志

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

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

f113a2687ee0348c6c999959730f0c31.png

监控页面

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

1) 服务应用重启(Error级别分组(组2))

2) Info级别分组(组1)服务节点从线上摘除，并不重启

3) 增大新生代、老生代等JVM参数重新上线(首先保证服务可用)

4) 登录Info级别容器后台查看堆栈信息或GC信息等等

排查时，用以下命令

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

或

jstat -gc pid

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

689823c6aee2fb1abd6870f801182cf7.png

堆栈日志

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

1) 用log4j2或Slf4j日志框架替换log4j。

2) 注意定义日志变量时加入static声明，或在打印日志配置中设置缓冲区

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

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

top

显示如下：

996db089c735e05a3b8257b798c7dded.png

top页面

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

jstat –gccause pid

显示如下：

b2a5e6e60d1aba82a9a4ec402f28b28c.png

jstat页面

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

jmap –heap pid

显示如下：

4982845df2d90e4c9ac3fc0472e918d7.png

jmap页面

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

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

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

751118ed7061616664668422c55a0012.png

mat页面

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

8bc9009ff0e7b57a75d8339b93e035e2.png

by outgoing references页面

点击Leak Suspects时，如下图：

06f42226f7aa297558ad780937a2e812.png

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

public LoadingCache>> contentVecCache = CacheBuilder.newBuilder()            .maximumSize(40000)            .expireAfterWrite(2, TimeUnit.HOURS)            .build(new CacheLoader>>() {                @Override                public Map> load(String key) {                    String itmeId = key.split("_")[0];                    int dataSource = Integer.valueOf(key.split("_")[1]);                    Map> map = new HashMap<>();                    List titleVec = wordEmbeddingService.getContentEmbedding(itmeId, dataSource, EmbedContentType.TITLE);                    map.put("title", titleVec);                    List 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-流量智能部。

关注【58技术】微信公众号，掌握更多优质一手干货

09ec13e016fa432945332c5eb7766246.png