网关性能优化 - log4j2异步模型提升服务性能
Posted 架构那些事儿
tags:
篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了网关性能优化 - 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优化：
<Executorname="tomcatThreadPool"namePrefix="catalina-exec-"maxThreads="500"minSpareThreads="30"maxIdleTime="60000"prestartminSpareThreads = "true"maxQueueSize = "100"/><Connector executor="tomcatThreadPool"port="8080"protocol="org.apache.coyote.http11.Http11Nio2Protocol"maxConnections="10000"enableLookups="false"acceptCount="2000"connectionTimeout="20000"redirectPort="8443"/>
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使用权衡（优缺点）
以上是关于网关性能优化 - log4j2异步模型提升服务性能的主要内容，如果未能解决你的问题，请参考以下文章