SpringCloud 日志在压测中的二三事
一、如何拆分响应时间？
在性能分析中，响应时间的拆分通常是一个分析起点。因为在性能场景中，不管是什么原因，只要系统达到了瓶颈，再接着增加压力，肯定会导致响应时间的上升，直到超时为止。在判断了瓶颈之后，我们需要找到问题出现在什么地方。在压力工具上看到的响应时间，都是经过了后端的每一个系统的。那么，当响应时间变长，我们就要知道，它在哪个阶段时间变长了,我们看下这张图。
SpringCloud 一般是这样的架构，拆分时间应该是比较清楚：
jmeteringressgatewayservicecacheDB
首先我们需要查看 Nginx-Ingress 上的时间，日志里就可以通过配置 request_time、upstream_response_time 得到日志如下信息：
172.16.106.116 - - [23/Feb/2021:13:52:21 +0800] "POST /mall-order/order/generateOrder HTTP/1.1" 499 0 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" "-" 8.659 8.660 复制代码
最后两列中，前面是请求时间的 8.659 s，后面是后端响应时间的 8.660 s。
同时我们可以去 gateway 查看 Reactor Netty 消耗的时间：
10.100.79.126 - - [23/Feb/2021:13:52:14 +0800] "POST /mall-order/order/generateOrder HTTP/1.1" 500 133 8201 52 ms 复制代码
最后一列中，耗时 52 ms。
最后，我们再到各个 SpringBoot Service上去看时间：
10.100.79.66 - - [23/Feb/2021:13:52:21 +0800] "POST /order/generateOrder HTTP/1.1" 500 144 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" 504 ms 502 ms 复制代码
请求时间消耗了 504 ms，响应时间消耗了 502 ms。
在这个例子中，主要说明了响应时间怎么一步步拆。当然，如果你是下面这种情况的话，再一个个拆就比较辛苦了，可以换另一种方式。
服务A服务B服务C服务D服务E
知道每个系统消耗了多长时间，那么我们可以借助链路监控工具来拆分时间了。比如像这样来拆分： 从 User 开始，每个服务之间的调用时间，都需要看看时间消耗的监控。这就是时间拆分的一种方式。其实不管我们用什么样的工具来监控，最终我们想得到的无非是每个环节消耗了多长时间。用日志也好，用链路监控工具也好，甚至抓包都可以。
二、如何启用 Access Logs？
1、Nginx Ingress Access Log
这里需要我们在 configmap 自定义 log-format 格式:
$remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer" "$http_user_agent" "$http_x_forwarded_for" $request_time $upstream_response_time 复制代码
字段说明如下：
$remote_addr- 发起请求的客户端 IP 地址。这里记录的 IP 地址并不一定是真实用户客户机的 IP 地址，它可能是私网客户端的公网映射地址或代理服务器地址。$remote_user- 远程客户端用户名称，用于记录浏览者进行身份验证时提供的名字，如登录百度的用户名zuozewei，如果没有登录就是空白。[$time_local]- 收到请求的时间（访问的时间与时区，比如18/Jul/2018:17:00:01 +0800，时间信息最后的"+0800"表示服务器所处时区位于 UTC 之后的8小时）“$request”- 来自客户端的请求行（请求的 URI 和 HTTP 协议，这是整个 PV 日志记录中最有用的信息，记录服务器收到一个什么样的请求）$status- 服务器返回客户端的状态码，比如成功是 200。$body_bytes_sent- 发送给客户端的文件主体内容的大小，不包括响应头的大小（可以将日志每条记录中的这个值累加起来以粗略估计服务器吞吐量）“$http_referer”- 记录从哪个页面链接访问过来的（请求头 Referer 的内容 ）“$http_user_agent”- 客户端浏览器信息（请求头User-Agent的内容 ）"$ http_x_forwarded_for"- 客户端的真实ip，通常web服务器放在反向代理的后面，这样就不能获取到客户的IP地址了，通过$remote_add拿到的IP地址是反向代理服务器的iP地址。反向代理服务器在转发请求的 http 头信息中，可以增加x_forwarded_for** 信息，用以记录原有客户端的IP地址和原来客户端的请求的服务器地址。$request_time- 整个请求的总时间，以秒为单位（包括接收客户端请求数据的时间、后端程序响应的时间、发送响应数据给客户端的时间(不包含写日志的时间)）$upstream_response_time- 请求过程中，upstream 的响应时间,以秒为单位（向后端建立连接开始到接受完数据然后关闭连接为止的时间）
得到的日志如下：
172.16.106.116 - - [23/Feb/2021:05:52:21 +0000] "POST /mall-order/order/generateOrder HTTP/1.1" 499 0 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" "-" 8.659 8.660 172.16.106.116 - - [23/Feb/2021:05:52:21 +0000] "POST /mall-order/order/generateOrder HTTP/1.1" 499 0 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" "-" 14.201 14.201 172.16.106.116 - - [23/Feb/2021:05:52:21 +0000] "POST /mall-order/order/generateOrder HTTP/1.1" 499 0 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" "-" 33.560 33.560 172.16.106.116 - - [23/Feb/2021:05:52:21 +0000] "POST /mall-order/order/generateOrder HTTP/1.1" 499 0 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" "-" 10.792 10.792 172.16.106.116 - - [23/Feb/2021:05:52:21 +0000] "POST /mall-order/order/generateOrder HTTP/1.1" 499 0 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" "-" 21.382 21.382 172.16.106.116 - - [23/Feb/2021:05:52:21 +0000] "POST /mall-order/order/generateOrder HTTP/1.1" 499 0 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" "-" 9.540 9.540 172.16.106.116 - - [23/Feb/2021:05:52:21 +0000] "POST /mall-order/order/generateOrder HTTP/1.1" 499 0 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" "-" 9.654 9.654 172.16.106.116 - - [23/Feb/2021:05:52:21 +0000] "POST /mall-order/order/generateOrder HTTP/1.1" 499 0 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" "-" 21.592 21.592 172.16.106.116 - - [23/Feb/2021:05:52:21 +0000] "POST /mall-order/order/generateOrder HTTP/1.1" 499 0 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" "-" 20.278 20.278 172.16.106.116 - - [23/Feb/2021:05:52:21 +0000] "POST /mall-order/order/generateOrder HTTP/1.1" 499 0 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" "-" 20.058 20.058 172.16.106.116 - - [23/Feb/2021:05:52:21 +0000] "POST /mall-order/order/generateOrder HTTP/1.1" 499 0 "-" "Apache-HttpClient/4.5.12 (Java/1.8.0_261)" "-" 8.943 8.943 复制代码
2、Reactor Netty Access Log
Spring-cloud-gateway 是基于 webflux 的应用，所以要启用 Reactor Netty 访问日志，需要设置 -Dreactor.netty.http.server.accessLogEnabled=true。
注意：
它必须是 Java System 属性，而不是 SpringBoot 属性。
我们可以将日志记录系统配置为具有单独的访问日志文件。以下示例创建一个 Logback 配置：
<appender name="accessLog" class="ch.qos.logback.core.FileAppender"> <file>access_log.log</file> <encoder> <pattern>%msg%n</pattern> </encoder> </appender> <appender name="async" class="ch.qos.logback.classic.AsyncAppender"> <appender-ref ref="accessLog" /> </appender> <logger name="reactor.netty.http.server.AccessLog" level="INFO" additivity="false"> <appender-ref ref="async"/> </logger> 复制代码
得到的日志如下：
10.100.79.126 - - [23/Feb/2021:11:02:09 +0800] "GET /mall-portal/home/content?pageNum=4&pageSize=1 HTTP/1.1" 200 3689 8201 16 ms 10.100.79.126 - - [23/Feb/2021:11:02:09 +0800] "GET /mall-member/sso/info HTTP/1.1" 200 648 8201 6 ms 10.100.79.126 - - [23/Feb/2021:11:02:09 +0800] "POST /mall-member/sso/login HTTP/1.1" 200 1103 8201 26 ms 10.100.79.126 - - [23/Feb/2021:11:02:09 +0800] "GET /mall-member/member/address/list HTTP/1.1" 200 278 8201 8 ms 10.100.79.126 - - [23/Feb/2021:11:02:09 +0800] "POST /mall-cart/cart/addNew HTTP/1.1" 200 46 8201 30 ms 10.100.79.126 - - [23/Feb/2021:11:02:09 +0800] "GET /mall-cart/cart/list HTTP/1.1" 200 2639 8201 13 ms 10.100.79.126 - - [23/Feb/2021:11:02:09 +0800] "POST /mall-cart/cart/addNew HTTP/1.1" 200 46 8201 25 ms 10.100.79.126 - - [23/Feb/2021:11:02:09 +0800] "GET /mall-order/order/detail/1732755 HTTP/1.1" 500 134 8201 15 ms 10.100.79.126 - - [23/Feb/2021:11:02:09 +0800] "GET /mall-portal/home/content?pageNum=4&pageSize=1 HTTP/1.1" 200 3689 8201 15 ms 复制代码
另外查看 reactor-netty-0.8.5.RELEASE-sources.jar!/reactor/netty/http/server/AccessLog.java 源码我们可以理解其是怎么实现的：
final class AccessLog { static final Logger log = Loggers.getLogger("reactor.netty.http.server.AccessLog"); static final DateTimeFormatter DATE_TIME_FORMATTER = DateTimeFormatter.ofPattern("dd/MMM/yyyy:HH:mm:ss Z", Locale.US); static final String COMMON_LOG_FORMAT = "{} - {} [{}] \"{} {} {}\" {} {} {} {} ms"; static final String MISSING = "-"; final String zonedDateTime; String address; CharSequence method; CharSequence uri; String protocol; String user = MISSING; CharSequence status; long contentLength; boolean chunked; long startTime = System.currentTimeMillis(); int port; AccessLog() { this.zonedDateTime = ZonedDateTime.now().format(DATE_TIME_FORMATTER); } AccessLog address(String address) { this.address = Objects.requireNonNull(address, "address"); return this; } AccessLog port(int port) { this.port = port; return this; } AccessLog method(CharSequence method) { this.method = Objects.requireNonNull(method, "method"); return this; } AccessLog uri(CharSequence uri) { this.uri = Objects.requireNonNull(uri, "uri"); return this; } AccessLog protocol(String protocol) { this.protocol = Objects.requireNonNull(protocol, "protocol"); return this; } AccessLog status(CharSequence status) { this.status = Objects.requireNonNull(status, "status"); return this; } AccessLog contentLength(long contentLength) { this.contentLength = contentLength; return this; } AccessLog increaseContentLength(long contentLength) { if (chunked) { this.contentLength += contentLength; } return this; } AccessLog chunked(boolean chunked) { this.chunked = chunked; return this; } long duration() { return System.currentTimeMillis() - startTime; } void log() { if (log.isInfoEnabled()) { log.info(COMMON_LOG_FORMAT, address, user, zonedDateTime, method, uri, protocol, status, (contentLength > -1 ? contentLength : MISSING), port, duration()); } } } 复制代码accessLog 的 log 方法直接通过 logger 输出日志，其日志格式为 COMMON_LOG_FORMAT({} - {} [{}] "{} {} {}" {} {} {} {} ms)，分别是address, user, zonedDateTime, method, uri, protocol, status, contentLength, port, duration.
3、SpringBoot Access Log
开启 Access Log 需要我们配置：
server: tomcat: basedir: /var/tmp background-processor-delay: 30 redirect-context-root: true uri-encoding: UTF-8 accesslog: enabled: true buffered: true directory: ./log file-date-format: .yyyy-MM-dd pattern: '%h %l %u %t "%r" %s %b "%{Referer}i" "%{User-Agent}i" %D ms %F ms' prefix: access_log rename-on-rotate: false request-attributes-enabled: false rotate: true suffix: .log 复制代码字段说明如下：
%h- 发起请求的客户端 IP 地址。这里记录的 IP 地址并不一定是真实用户客户机的 IP 地址，它可能是私网客户端的公网映射地址或代理服务器地址。%l- 客户机的 RFC 1413 标识 ( 参考 ) ，只有实现了 RFC 1413 规范的客户端，才能提供此信息。%u- 远程客户端用户名称，用于记录浏览者进行身份验证时提供的名字，如登录百度的用户名zuozewei，如果没有登录就是空白。%t- 收到请求的时间（访问的时间与时区，比如18/Jul/2018:17:00:01 +0800，时间信息最后的"+0800"表示服务器所处时区位于 UTC 之后的8小时）%{X-Real_IP}i- 客户端的真实ip%r- 来自客户端的请求行（请求的 URI 和 HTTP 协议，这是整个 PV 日志记录中最有用的信息，记录服务器收到一个什么样的请求）%>s- 服务器返回客户端的状态码，比如成功是 200。%b- 发送给客户端的文件主体内容的大小，不包括响应头的大小（可以将日志每条记录中的这个值累加起来以粗略估计服务器吞吐量）%{Referer}i- 记录从哪个页面链接访问过来的（请求头Referer的内容 ）%D- 处理请求的时间，以毫秒为单位%F- 客户端浏览器信息提交响应的时间，以毫秒为单位
得到的日志如下：
[root@svc-mall-admin-5dbb7467d8-q4wlq log]# ll total 1736 -rw-r--r-- 1 root root 23967 Feb 21 00:00 access_log.2021-02-20.log -rw-r--r-- 1 root root 668261 Feb 22 00:00 access_log.2021-02-21.log -rw-r--r-- 1 root root 673517 Feb 23 00:00 access_log.2021-02-22.log -rw-r--r-- 1 root root 385773 Feb 23 13:52 access_log.2021-02-23.log [root@svc-mall-admin-5dbb7467d8-q4wlq log]# tail -f access_log.2021-02-23.log 10.100.251.99 - - [23/Feb/2021:13:50:12 +0800] "GET /actuator/health HTTP/1.1" 200 845 "-" "ReactorNetty/0.9.7.RELEASE" 29 ms 29 ms 10.100.251.99 - - [23/Feb/2021:13:50:32 +0800] "GET /actuator/health HTTP/1.1" 200 845 "-" "ReactorNetty/0.9.7.RELEASE" 24 ms 23 ms 10.100.251.99 - - [23/Feb/2021:13:50:52 +0800] "GET /actuator/health HTTP/1.1" 200 845 "-" "ReactorNetty/0.9.7.RELEASE" 23 ms 23 ms 10.100.251.99 - - [23/Feb/2021:13:51:12 +0800] "GET /actuator/health HTTP/1.1" 200 845 "-" "ReactorNetty/0.9.7.RELEASE" 18 ms 18 ms 10.100.251.99 - - [23/Feb/2021:13:51:32 +0800] "GET /actuator/info HTTP/1.1" 200 12 "-" "ReactorNetty/0.9.7.RELEASE" 4 ms 4 ms 10.100.251.99 - - [23/Feb/2021:13:51:32 +0800] "GET /actuator/health HTTP/1.1" 200 845 "-" "ReactorNetty/0.9.7.RELEASE" 20 ms 20 ms 10.100.251.99 - - [23/Feb/2021:13:51:52 +0800] "GET /actuator/health HTTP/1.1" 200 845 "-" "ReactorNetty/0.9.7.RELEASE" 24 ms 24 ms 10.100.251.99 - - [23/Feb/2021:13:52:12 +0800] "GET /actuator/health HTTP/1.1" 200 845 "-" "ReactorNetty/0.9.7.RELEASE" 34 ms 34 ms 10.100.251.99 - - [23/Feb/2021:13:52:32 +0800] "GET /actuator/health HTTP/1.1" 200 845 "-" "ReactorNetty/0.9.7.RELEASE" 19 ms 19 ms 10.100.251.99 - - [23/Feb/2021:13:52:52 +0800] "GET /actuator/health HTTP/1.1" 200 845 "-" "ReactorNetty/0.9.7.RELEASE" 21 ms 20 ms 复制代码
三、如何提高日志性能？
主要通过以下两个方面：
提高日志输出到文件 LEVEL 级别
压测的过程中可以把业务日志级别调整到 error
通过异步输出日志减少磁盘IO提高性能
1、怎么配置异步日志？
SpringBoot 应用自带 Logback 和 slf4j 的依赖，所以重点放在编写配置文件上，需要引入什么依赖，日志依赖冲突统统都不需要我们管了。logback 框架会默认加载 classpath 下命名为 logback-spring 或 logback 的配置文件。将所有日志都存储在一个文件中文件大小也随着应用的运行越来越大并且不好排查问题，正确的做法应该是将 error 日志和其他日志分开，并且不同级别的日志根据时间段进行记录存储。
举例说明：
<?xml version="1.0" encoding="utf-8"?> <!DOCTYPE configuration> <configuration> <!--引用默认日志配置--> <include resource="org/springframework/boot/logging/logback/defaults.xml"/> <!--使用默认的控制台日志输出实现--> <include resource="org/springframework/boot/logging/logback/console-appender.xml"/> <!--应用名称--> <springProperty scope="context" name="APP_NAME" source="spring.application.name" defaultValue="springBoot"/> <!--日志文件保存路径--> <property name="LOG_FILE_PATH" value="${LOG_FILE:-${LOG_PATH:-${LOG_TEMP:-${java.io.tmpdir:-/tmp}}}/logs}"/> <!--日志输出到控制台--> <appender name="CONSOLE-LOG" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <pattern>[%d{yyyy-MM-dd' 'HH:mm:ss.sss}] [%C] [%t] [%L] [%-5p] %m%n</pattern> </layout> </appender> <!--收集除error级别以外的日志--> <appender name="INFO-LOG" class="ch.qos.logback.core.rolling.RollingFileAppender"> <filter class="ch.qos.logback.classic.filter.LevelFilter"> <level>ERROR</level> <onMatch>DENY</onMatch> <onMismatch>ACCEPT</onMismatch> </filter> <encoder> <!--设置为默认的文件日志格式--> <pattern>${FILE_LOG_PATTERN}</pattern> <charset>UTF-8</charset> </encoder> <!--滚动策略--> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <!--路径--> <fileNamePattern>${LOG_INFO_HOME}//%d.log</fileNamePattern> <maxHistory>30</maxHistory> </rollingPolicy> <!--滚动策略--> <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"> <!--设置路径及文件命名格式--> <fileNamePattern>${LOG_FILE_PATH}/info/${APP_NAME}-%d{yyyy-MM-dd}-%i.log</fileNamePattern> <!--设置日志文件大小，超过就重新生成文件，默认10M--> <maxFileSize>${LOG_FILE_MAX_SIZE:-10MB}</maxFileSize> <!--日志文件保留天数，默认30天--> <maxHistory>${LOG_FILE_MAX_HISTORY:-30}</maxHistory> </rollingPolicy> </appender> <!--ERROR日志输出到文件--> <appender name="FILE_ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender"> <!--只输出ERROR级别的日志--> <filter class="ch.qos.logback.classic.filter.LevelFilter"> <level>ERROR</level> <onMatch>ACCEPT</onMatch> <onMismatch>DENY</onMismatch> </filter> <encoder> <!--设置为默认的文件日志格式--> <pattern>${FILE_LOG_PATTERN}</pattern> <charset>UTF-8</charset> </encoder> <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"> <!--设置文件命名格式--> <fileNamePattern>${LOG_FILE_PATH}/error/${APP_NAME}-%d{yyyy-MM-dd}-%i.log</fileNamePattern> <!--设置日志文件大小，超过就重新生成文件，默认10M--> <maxFileSize>${LOG_FILE_MAX_SIZE:-10MB}</maxFileSize> <!--日志文件保留天数，默认30天--> <maxHistory>${LOG_FILE_MAX_HISTORY:-30}</maxHistory> </rollingPolicy> </appender> <root level="info"> <appender-ref ref="CONSOLE-LOG" /> <appender-ref ref="INFO-LOG" /> <appender-ref ref="ERROR-LOG" /> </root> </configuration> 复制代码部分标签说明：
<root>标签，必填标签，用来指定最基础的日志输出级别<appender-ref>标签，添加 append<append>标签，通过使用该标签指定日志的收集策略name 属性指定 appender 命名
class 属性指定输出策略，通常有两种，控制台输出和文件输出，文件输出就是将日志进行一个持久化。ConsoleAppender 将日志输出到控制台
<filter>标签，通过使用该标签指定过滤策略<level>标签指定过滤的类型<encoder>标签，使用该标签下的<pattern>标签指定日志输出格式<rollingPolicy>标签指定收集策略，比如基于时间进行收集<fileNamePattern>标签指定生成日志保存地址，通过这样配置已经实现了分类分天收集日志
生成的日志如下所示：
[root@svc-mall-admin-5dbb7467d8-q4wlq logs]# cd error/ [root@svc-mall-admin-5dbb7467d8-q4wlq error]# ll total 1520 -rw-r--r-- 1 root root 0 Feb 20 23:36 mall-admin-2021-02-20-0.log -rw-r--r-- 1 root root 501172 Feb 21 20:37 mall-admin-2021-02-21-0.log -rw-r--r-- 1 root root 34632 Feb 22 11:27 mall-admin-2021-02-22-0.log -rw-r--r-- 1 root root 1012807 Feb 23 06:25 mall-admin-2021-02-23-0.log 复制代码
之前的日志配置方式是基于同步的，每次日志输出到文件都会进行一次磁盘IO。采用异步写日志的方式而不让此次写日志发生磁盘IO，阻塞线程从而造成不必要的性能损耗。异步输出日志的方式很简单，添加一个基于异步写日志的 appender，并指向原先配置的 appender 即可。
如下：
<!-- 异步输出 --> <appender name="ASYNC-INFO" class="ch.qos.logback.classic.AsyncAppender"> <!-- 不丢失日志.默认的,如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 --> <discardingThreshold>0</discardingThreshold> <!-- 更改默认的队列的深度,该值会影响性能.默认值为256 --> <queueSize>256</queueSize> <!-- 添加附加的appender,最多只能添加一个 --> <appender-ref ref="INFO-LOG"/> </appender> <appender name="ASYNC-ERROR" class="ch.qos.logback.classic.AsyncAppender"> <!-- 不丢失日志.默认的,如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 --> <discardingThreshold>0</discardingThreshold> <!-- 更改默认的队列的深度,该值会影响性能.默认值为256 --> <queueSize>256</queueSize> <!-- 添加附加的appender,最多只能添加一个 --> <appender-ref ref="ERROR-LOG"/> </appender>
作者：zuozewei
链接：https://juejin.cn/post/7024789910259236871