SpringCloud 日志在壓測(cè)中的二三事
如何拆分響應(yīng)時(shí)間？
如何啟用 Access Logs？
Nginx Ingress Access Log
Reactor Netty Access Log
springBoot Access Log
如何拆分響應(yīng)時(shí)間？
如何啟用 Access Logs？
Nginx Ingress Access Log
Reactor Netty Access Log
springBoot Access Log
如何提高日志性能？
怎么配置異步日志？
如何拆分響應(yīng)時(shí)間？
在性能分析中，響應(yīng)時(shí)間的拆分通常是一個(gè)分析起點(diǎn)。因?yàn)樵谛阅軋?chǎng)景中，不管是什么原因，只要系統(tǒng)達(dá)到了瓶頸，再接著增加壓力，肯定會(huì)導(dǎo)致響應(yīng)時(shí)間的上升，直到超時(shí)為止。在判斷了瓶頸之后，我們需要找到問(wèn)題出現(xiàn)在什么地方。在壓力工具上看到的響應(yīng)時(shí)間，都是經(jīng)過(guò)了后端的每一個(gè)系統(tǒng)的。那么，當(dāng)響應(yīng)時(shí)間變長(zhǎng)，我們就要知道，它在哪個(gè)階段時(shí)間變長(zhǎng)了,我們看下這張圖。
SpringCloud 一般是這樣的架構(gòu)，拆分時(shí)間應(yīng)該是比較清楚：
jmeter
ingress
gateway
service
cache
DB
首先我們需要查看 Nginx-Ingress 上的時(shí)間，日志里就可以通過(guò)配置 request_t ime、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
最后兩列中，前面是請(qǐng)求時(shí)間的 8.659 s，后面是后端響應(yīng)時(shí)間的 8.660 s。
同時(shí)我們可以去 gateway 查看 Reactor Netty 消耗的時(shí)間：
10.100.79.126 - - [23/Feb/2021:13:52:14 +0800] "POST /mall-order/order/generateOrder HTTP/1.1" 500 133 8201 52 ms
最后一列中，耗時(shí) 52 ms。
最后，我們?cè)俚礁鱾€(gè) SpringBoot Service上去看時(shí)間：
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
請(qǐng)求時(shí)間消耗了 504 ms，響應(yīng)時(shí)間消耗了 502 ms。
在這個(gè)例子中，主要說(shuō)明了響應(yīng)時(shí)間怎么一步步拆。當(dāng)然，如果你是下面這種情況的話，再一個(gè)個(gè)拆就比較辛苦了，可以換另一種方式。
服務(wù)A
服務(wù)B
服務(wù)C
服務(wù)D
服務(wù)E
知道每個(gè)系統(tǒng)消耗了多長(zhǎng)時(shí)間，那么我們可以借助鏈路監(jiān)控工具來(lái)拆分時(shí)間了。比如像這樣來(lái)拆分：
從 User 開始，每個(gè)服務(wù)之間的調(diào)用時(shí)間，都需要看看時(shí)間消耗的監(jiān)控。這就是時(shí)間拆分的一種方式。其實(shí)不管我們用什么樣的工具來(lái)監(jiān)控，最終我們想得到的無(wú)非是每個(gè)環(huán)節(jié)消耗了多長(zhǎng)時(shí)間。用日志也好，用鏈路監(jiān)控工具也好，甚至抓包都可以。
如何啟用 Access Logs？
Nginx Ingress Access Log
這里需要我們?cè)?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
字段說(shuō)明如下：
$remote_addr - 發(fā)起請(qǐng)求的客戶端 IP 地址。這里記錄的 IP 地址并不一定是真實(shí)用戶客戶機(jī)的 IP 地址，它可能是私網(wǎng)客戶端的公網(wǎng)映射地址或代理服務(wù)器地址。
$remote_user - 遠(yuǎn)程客戶端用戶名稱，用于記錄瀏覽者進(jìn)行身份驗(yàn)證時(shí)提供的名字，如登錄百度的用戶名 zuozewei，如果沒(méi)有登錄就是空白。
[$time_local] - 收到請(qǐng)求的時(shí)間（訪問(wèn)的時(shí)間與時(shí)區(qū)，比如18/Jul/2018:17:00:01 +0800，時(shí)間信息最后的 "+0800" 表示服務(wù)器所處時(shí)區(qū)位于 UTC 之后的8小時(shí)）
“$request” - 來(lái)自客戶端的請(qǐng)求行（請(qǐng)求的 URI 和 HTTP 協(xié)議，這是整個(gè) PV 日志記錄中最有用的信息，記錄服務(wù)器收到一個(gè)什么樣的請(qǐng)求）
$status - 服務(wù)器返回客戶端的狀態(tài)碼，比如成功是 200。
$body_bytes_sent - 發(fā)送給客戶端的文件主體內(nèi)容的大小，不包括響應(yīng)頭的大小（可以將日志每條記錄中的這個(gè)值累加起來(lái)以粗略估計(jì)服務(wù)器吞吐量）
“$http_referer” - 記錄從哪個(gè)頁(yè)面鏈接訪問(wèn)過(guò)來(lái)的（請(qǐng)求頭 Referer 的內(nèi)容 ）
“$http_user_agent” - 客戶端瀏覽器信息（請(qǐng)求頭User-Agent的內(nèi)容 ）
"$ http_x_forwarded_for"- 客戶端的真實(shí)ip，通常web服務(wù)器放在反向代理的后面，這樣就不能獲取到客戶的IP地址了，通過(guò) $remote_add拿到的IP地址是反向代理服務(wù)器的iP地址。反向代理服務(wù)器在轉(zhuǎn)發(fā)請(qǐng)求的 http 頭信息中，可以增加 x_forwarded_for** 信息，用以記錄原有客戶端的IP地址和原來(lái)客戶端的請(qǐng)求的服務(wù)器地址。
$request_time - 整個(gè)請(qǐng)求的總時(shí)間，以秒為單位（包括接收客戶端請(qǐng)求數(shù)據(jù)的時(shí)間、后端程序響應(yīng)的時(shí)間、發(fā)送響應(yīng)數(shù)據(jù)給客戶端的時(shí)間(不包含寫日志的時(shí)間)）
$upstream_response_time - 請(qǐng)求過(guò)程中，upstream 的響應(yīng)時(shí)間,以秒為單位（向后端建立連接開始到接受完數(shù)據(jù)然后關(guān)閉連接為止的時(shí)間）
得到的日志如下：
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
Reactor Netty Access Log
Spring-cloud-gateway 是基于 webflux 的應(yīng)用，所以要啟用 Reactor Netty 訪問(wèn)日志，需要設(shè)置 -Dreactor.netty.http.server.accessLogEnabled=true。
注意：
它必須是 Java System 屬性，而不是 SpringBoot 屬性。
我們可以將日志記錄系統(tǒng)配置為具有單獨(dú)的訪問(wèn)日志文件。以下示例創(chuàng)建一個(gè) Logback 配置：
得到的日志如下：
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 源碼我們可以理解其是怎么實(shí)現(xiàn)的：
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 方法直接通過(guò) logger 輸出日志，其日志格式為 COMMON_LOG_FORMAT({} - {} [{}] "{} {} {}" {} {} {} {} ms)，分別是address, user, zonedDateTime, method, uri, protocol, status, contentLength, port, duration.
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
字段說(shuō)明如下：
%h - 發(fā)起請(qǐng)求的客戶端 IP 地址。這里記錄的 IP 地址并不一定是真實(shí)用戶客戶機(jī)的 IP 地址，它可能是私網(wǎng)客戶端的公網(wǎng)映射地址或代理服務(wù)器地址。
%l - 客戶機(jī)的 RFC 1413 標(biāo)識(shí) ( 參考 ) ，只有實(shí)現(xiàn)了 RFC 1413 規(guī)范的客戶端，才能提供此信息。
%u - 遠(yuǎn)程客戶端用戶名稱，用于記錄瀏覽者進(jìn)行身份驗(yàn)證時(shí)提供的名字，如登錄百度的用戶名 zuozewei，如果沒(méi)有登錄就是空白。
%t - 收到請(qǐng)求的時(shí)間（訪問(wèn)的時(shí)間與時(shí)區(qū)，比如18/Jul/2018:17:00:01 +0800，時(shí)間信息最后的 "+0800" 表示服務(wù)器所處時(shí)區(qū)位于 UTC 之后的8小時(shí)）
%{X-Real_IP}i - 客戶端的真實(shí)ip
%r - 來(lái)自客戶端的請(qǐng)求行（請(qǐng)求的 URI 和 HTTP 協(xié)議，這是整個(gè) PV 日志記錄中最有用的信息，記錄服務(wù)器收到一個(gè)什么樣的請(qǐng)求）
%>s - 服務(wù)器返回客戶端的狀態(tài)碼，比如成功是 200。
%b - 發(fā)送給客戶端的文件主體內(nèi)容的大小，不包括響應(yīng)頭的大小（可以將日志每條記錄中的這個(gè)值累加起來(lái)以粗略估計(jì)服務(wù)器吞吐量）
%{Referer}i - 記錄從哪個(gè)頁(yè)面鏈接訪問(wèn)過(guò)來(lái)的（請(qǐng)求頭Referer的內(nèi)容 ）
%D - 處理請(qǐng)求的時(shí)間，以毫秒為單位
%F - 客戶端瀏覽器信息提交響應(yīng)的時(shí)間，以毫秒為單位
得到的日志如下：
[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
如何提高日志性能？
主要通過(guò)以下兩個(gè)方面：
提高日志輸出到文件 LEVEL 級(jí)別
壓測(cè)的過(guò)程中可以把業(yè)務(wù)日志級(jí)別調(diào)整到 error
通過(guò)異步輸出日志減少磁盤IO提高性能
怎么配置異步日志？
SpringBoot 應(yīng)用自帶 Logback 和 slf4j 的依賴，所以重點(diǎn)放在編寫配置文件上，需要引入什么依賴，日志依賴沖突統(tǒng)統(tǒng)都不需要我們管了。logback 框架會(huì)默認(rèn)加載 classpath 下命名為 logback-spring 或 logback 的配置文件。將所有日志都存儲(chǔ)在一個(gè)文件中文件大小也隨著應(yīng)用的運(yùn)行越來(lái)越大并且不好排查問(wèn)題，正確的做法應(yīng)該是將 error 日志和其他日志分開，并且不同級(jí)別的日志根據(jù)時(shí)間段進(jìn)行記錄存儲(chǔ)。
舉例說(shuō)明：
部分標(biāo)簽說(shuō)明：
name 屬性指定 appender 命名
class 屬性指定輸出策略，通常有兩種，控制臺(tái)輸出和文件輸出，文件輸出就是將日志進(jìn)行一個(gè)持久化。ConsoleAppender 將日志輸出到控制臺(tái)
生成的日志如下所示：
[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
之前的日志配置方式是基于同步的，每次日志輸出到文件都會(huì)進(jìn)行一次磁盤IO。采用異步寫日志的方式而不讓此次寫日志發(fā)生磁盤IO，阻塞線程從而造成不必要的性能損耗。異步輸出日志的方式很簡(jiǎn)單，添加一個(gè)基于異步寫日志的 appender，并指向原先配置的 appender 即可。
如下：
相關(guān)資料：
https://github.com/zuozewei/blog-example/tree/master/Performance-testing/03-performance-monitoring/springcloud-log
參考資料：
[1]：nginx-configmap-resource
[2]：Reactor Netty Access Logs
[3]：聊聊reactor-netty的AccessLog
[4]：《性能測(cè)試實(shí)戰(zhàn)30講》
Spring Cloud 壓力測(cè)試 自動(dòng)化測(cè)試
版權(quán)聲明：本文內(nèi)容由網(wǎng)絡(luò)用戶投稿，版權(quán)歸原作者所有，本站不擁有其著作權(quán)，亦不承擔(dān)相應(yīng)法律責(zé)任。如果您發(fā)現(xiàn)本站中有涉嫌抄襲或描述失實(shí)的內(nèi)容，請(qǐng)聯(lián)系我們jiasou666@gmail.com 處理，核實(shí)后本網(wǎng)站將在24小時(shí)內(nèi)刪除侵權(quán)內(nèi)容。
版權(quán)聲明：本文內(nèi)容由網(wǎng)絡(luò)用戶投稿，版權(quán)歸原作者所有，本站不擁有其著作權(quán)，亦不承擔(dān)相應(yīng)法律責(zé)任。如果您發(fā)現(xiàn)本站中有涉嫌抄襲或描述失實(shí)的內(nèi)容，請(qǐng)聯(lián)系我們jiasou666@gmail.com 處理，核實(shí)后本網(wǎng)站將在24小時(shí)內(nèi)刪除侵權(quán)內(nèi)容。
相關(guān)文章
