网关性能优化(二) - log4j2异步模型提升服务性能

一. 背景：

webgate (网关服务)作为中台的组件之一，也是web组件的入口， 那么webgate稳定性如何、性能如何既是平台所关注的，也是使用者所关心的。近日对webgate服务进行了性能和稳定性压测。在压测过程中发现关于log4j影响服务性能，并得以解决。

二.结论先行：

webgate在使用log4j2异步模型后，服务的性能由原来的 700QPS 提升到 1000QPS。提升性能42%。 所以lo4j2的异步性能是绝佳的。

看图说话：

通过webbench并发180，持续访问 100秒 压测通过网关来路由访问demoapp/greeting 接口。

webgate在使用log4j2 同步模型时的性能

webgate在使用log4j2 异步模型后的性能

服务器性能监控：CPU 使用率70% 堆内存 使用800M（分别做了2小时，12小时的压测 图是2小时的效果图 ，期间gc正常、无fullgc发生）

看了结论，大家应该会有疑问，是如何发现服务慢，又是如何定位到log4j导致服务慢的问题。OK我们慢慢道来。

三.过程：

首先说压测准备：（这个很重要）

选择 网络、磁盘、CPU、内存 符合其服务压测的标准

• 网络，在内网进行压测所以网络瓶颈可忽略
• CPU 16核 内存 16G

2. 在网络 磁盘 CPU 内存满足服务的要求下，对于一个基于TCP协议传输的服务，系统内核参数的优化必不可少。

好在测试的同学提供的机器很给力（内核参数进行了优化，Tcp连接快速释放，端口数调大）

3. 服务部署图谱: 部署了一个网关实例(Tomcat), 部署了四个Demoapp服务实例 (本质是四个Nginx服务,避免因demoapp的性能影响网关压测)

4. tomcat[apache-tomcat-8.5.34] conf/server.xml优化：

5.Jvm设置： (这些参数设置有其关联性，需要根据具体的服务进行设置 感兴趣自行google)

-Xms4G -Xmx4G -Xmn800M -XX:PermSize=512M -XX:MaxPermSize=512M -XX:SurvivorRatio=8 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:ParallelCMSThreads=3 -XX:+CMSScavengeBeforeRemark -XX:+CMSParallelRemarkEnabled -XX:CMSInitiatingOccupancyFraction=70 -XX:+ScavengeBeforeFullGC -XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=3 -XX:+CMSClassUnloadingEnabled -XX:+CMSPermGenSweepingEnabled

6.启动Jvisualvm监控工具：

连接网关服务，监控系统资源(线程、cpu、内存等，当然这些都可以通过jdk提供的java命令去查看，它的好处在于可视化)

接下来开始压测

开始压测，QPS 只有600+ ，加到并发量 会更慢 [zuul 官方数据上万qps、性能损耗有点大，怀疑有问题。Webgate是基于zuul1实现]。

1.查看系统资源：

发现CPU正常（排除死循环，或计算型导致慢） IO 正常 内存正常（无内存、栈溢出） 查看网卡流量（网络正常）

2.查看fullGc：无fullGc产生

3.排除外部依赖原因：直接压测demoapp nginx提供的demoapp服务单机性能在7000qps

猜测：那可能是webgate中的服务阻塞、等待了。(这里可以通过jstack看堆栈信息，关注线程状态为BLOCKED、TIMED_WAITING的线程)

期间把webgate怀疑的损耗性能的方法进行了日志统一打印：发现并发大的时候各个环节耗时均有增长。数据结构如图：

4.利用可视化工具Jvisualvm 查看的 CPU快照信息，发现问题。

看第一行，org.apache.logging.log4j…….. 是不是很亲切 它花的CPU时间Number One。

疑问：日志打印耗时最长，这个不太正常

再看第二行
java.util.concurrent.LinkedBlockingQueue.poll() 队列轮询方法，它花的CPU时间 Number Two (后边会介绍)

咱们先看log4j继续跟进 通过反向跟踪 ，看是哪些方法调用了：

均是服务正常调用，然后调用打印了日志。

疑问：我们使用的是Log4j2,为什么log还会耗时最长呢？

看官方数据：

1. Log4j2 在log界号称性能第一，我们来看官方性能报告：

2.再看 sync vs aysnc logger

3.看完第二个图似乎有了答案。（来确认下我们服务使用的Log4j2的模式 – Log4j2-sync）

[有些事知道，跟去实践完全是两回事]

只知道log4j2号称性能第一，不知道它通过异步实现了高性能；只知道异步实现了高性能，殊不知它有两个模块asynclogger 和 asyncappender两个部分都实现了异步化，且可以灵活 的分模块异步和全异步。 更重要的是asynclogger异步方式 和asyncappender 异步方式不一样。Asynclogger使用的是LMAX Disruptor技术进行异步化，asyncappender 使用的是Java的ArrayBlockingQueue进行异步化。

扯远了，回正题。

4.查阅了log4j2的官方文档(一定要官方的)

https://logging.apache.org/log4j/2.x/manual/async.html

文中对异步log4j介绍的很详细 异步的几种方式的使用，性能，使用权衡（优缺点）这个需要仔细读

按照官方的介绍，在webgate上进行了实践。

Log4j2：loggers all async 全异步化后，进行压测，看图说话：

跃居第一位的是什么？

是不是很熟悉
java.util.concurrent.LinkedBlockingQueue.poll() log异步化前压测时的Number Two。

原来的org.apache.logging.log4j… 不见了。

说明一个问题：耗时最长的不是log4j2了，说明log4j2异步优化生效了。原来的Number Two 跃升为第一位 在期望中。

接下来我们看：
java.util.concurrent.LinkedBlockingQueue.poll()的方法调用链，看图说话：

Tomcat的线程池 请求轮询。[连接数是不是开的少了，线下证实了这个想法是正确的]

我们再看此时耗时第二位：

java.util.concurrent.locks.ReentrantLock.lock() – 重入锁

追踪其方法的调用链，看图说话：

这里分两部分看：

第一部分 com.lmax.disruptor.. 是什么？ Log4j2 异步使用的框架[日志打印的是不是多？] 追踪方法调用链

初步结论：所有日志打印均是路由的核心类日志打印，应该是日志打印的多导致的，暂没有证实。[鉴权、限流、熔断、负载均衡、http转发]

第二部分 org.apache.http.pool.. 是什么？ http连接池[webgate的核心http请求转发,情理之中？]

初步结论：跟综进去 发现是zuul路由，正常。

之前关于连接池的使用在这里踩过坑 ，那是 网关性能优化(一) – http连接池优化提升服务性能^_^

四.最后小结下

1、服务优化涉及方方面面，这里只是冰山一角，以此篇献给大家。重要的是思路不是结果。性能优化最重要的是发现问题，定位问题，关于解决方案可以有一大堆。

2、关于log4j2使用的几点建议：

1）log4j2的全异步模型性能在log界Number One。

2）使用了log4j2异步，日志中一定要有全链路唯一ID 主要是能把一次请求串起来。要不然异步后，根本没法根据日志去定位问题

3）没有最好的，只有最合适的。Log4j2 对服务来说亦是。可根据服务的业务选择最合适的。详细参考官方 log4j2使用权衡（优缺点）