亚洲国产精品嫩草影院2_美丽人妻沦为公厕菜市场_99久久婷婷国产综合精品_国内揄拍自拍视频在线直播平台_免费观看在线视频一区

一、問題發(fā)現(xiàn)

我所負(fù)責(zé)的商城活動系統(tǒng)用于承接公司線上官方商城的營銷活動，最近突然收到凌晨0點(diǎn)的服務(wù)超時告警。

(相關(guān)資料圖)

營銷活動類的系統(tǒng)有如下特點(diǎn)：

營銷活動一般會0點(diǎn)開始，如紅包雨、大額優(yōu)惠券搶券等。日常營銷活動的機(jī)會刷新，如每日任務(wù)，每日簽到，每日抽獎機(jī)會的刷新等。

營銷活動的利益刺激會吸引大量真實(shí)用戶及黑產(chǎn)前來參與活動，所以流量在0點(diǎn)會迎來一波小高峰，也正因如此線上偶現(xiàn)的服務(wù)超時告警起初并未引起我的注意。但是接下來的幾天，每天的凌晨0點(diǎn)都會收到服務(wù)超時告警，這引起了我的警惕，決定一探究竟。

二、問題排查

首先通過公司的應(yīng)用監(jiān)控系統(tǒng)查看了0點(diǎn)前后每分鐘各接口的P95響應(yīng)時間。如下圖所示，接口響應(yīng)時間在0點(diǎn)時刻最高達(dá)到了8s。繼續(xù)查看鎖定耗時最高的接口為商品列表接口，下面就針對這個接口展開具體的排查。

2.1 排查思路

正式排查之前，先和大家分享下我對接口超時問題的排查思路。下圖是一個簡化的請求流程。

用戶向應(yīng)用發(fā)起請求應(yīng)用服務(wù)進(jìn)行邏輯處理應(yīng)用服務(wù)通過RPC調(diào)用下游應(yīng)用以及進(jìn)行數(shù)據(jù)庫的讀寫操作

服務(wù)超時可能是應(yīng)用服務(wù)自身慢導(dǎo)致，也可能下游依賴響應(yīng)慢導(dǎo)致。具體排查思路如下：

3.1.1下游依賴慢服務(wù)排查

（1）通過調(diào)用鏈技術(shù)定位下游依賴中的慢服務(wù)

調(diào)用鏈技術(shù)是實(shí)現(xiàn)系統(tǒng)可觀測性的重要保障，常見的開源方案有ziplin、pinpoint等。完整的調(diào)用鏈可以按時間正序記錄每一次下游依賴調(diào)用的耗時，如rpc服務(wù)調(diào)用、sql執(zhí)行耗時、redis訪問耗時等。因此使用調(diào)用鏈技術(shù)可以迅速定位到下游依賴的慢服務(wù)，如dubbo接口訪問超時、慢SQL等。但理想很豐滿，現(xiàn)實(shí)很骨感。由于調(diào)用鏈路信息的數(shù)量過大，想要收集全量的鏈路信息需要較高的存儲成本和計算資源。因此在技術(shù)落地時，通常都會采用抽樣的策略來收集鏈路信息。抽樣帶來的問題是請求鏈路信息的丟失或不完整。

（2）無調(diào)用鏈時的慢服務(wù)排查

如果調(diào)用鏈丟失或不完整，我們就要再結(jié)合其它手段進(jìn)行綜合定位了。

下游RPC服務(wù)響應(yīng)超時：如果是用Dubbo框架，在provider響應(yīng)超時時會打印timeout相關(guān)日志；如果公司提供應(yīng)用監(jiān)控，還可以查看下游服務(wù)P95響應(yīng)時間綜合判斷。

慢SQL：MySQL支持設(shè)置慢SQL閾值，超過該閾值會記錄下慢SQL；像我們常用的數(shù)據(jù)庫連接池Druid也可以通過配置打印慢SQL日志。如果確認(rèn)請求鏈路中存在慢SQL可以進(jìn)一步分析該SQL的執(zhí)行計劃，如果執(zhí)行計劃也沒有問題，再去確認(rèn)在慢SQL產(chǎn)生時mysql主機(jī)的系統(tǒng)負(fù)載。

下游依賴包含Redis、ES、Mongo等存儲服務(wù)時，慢服務(wù)的排查思路和慢SQL排查相似，在此不再贅述。

2.1.2應(yīng)用自身問題排查

（1）應(yīng)用邏輯耗時多

應(yīng)用邏輯耗時多比較常見，比如大量對象的序列化和反序列化，大量的反射應(yīng)用等。這類問題的排查通常要從分析源碼入手，編碼時應(yīng)該盡量避免。

（2）垃圾回收導(dǎo)致的停頓（stop the world）

垃圾回收會導(dǎo)致應(yīng)用的停頓，特別是發(fā)生Old GC或Full GC時，停頓明顯。不過也要看應(yīng)用選配的垃圾回收器和垃圾回收相關(guān)的配合，像CMS垃圾回收器通常可以保證較短的時間停頓，而Parallel Scavenge垃圾回收器則是追求更高的吞吐量，停頓時間會相對長一些。

通過JVM啟動參數(shù)-XX:+PrintGCDetails，我們可以打印詳細(xì)的GC日志，借此可以觀察到GC的類型、頻次和耗時。

（3）線程同步阻塞

線程同步，如果當(dāng)前持有鎖的線程長時間持有鎖，排隊(duì)的線程將一直處于blocked狀態(tài)，造成服務(wù)響應(yīng)超時?？梢酝ㄟ^jstack工具打印線程堆棧，查找是否有處于block狀態(tài)的線程。當(dāng)然jstack工具只能采集實(shí)時的線程堆棧信息，如果想要查看歷史堆棧信息一般需要通過Prometheus進(jìn)行收集處理。

2.2 排查過程

下面按照這個排查思路進(jìn)行排查。

2.2.1下游依賴慢服務(wù)排查

（1）通過調(diào)用鏈查看下游慢服務(wù)

首先到公司的應(yīng)用監(jiān)控平臺上，篩選出0點(diǎn)前后5min的調(diào)用鏈列表，然后按照鏈路耗時逆序排列，發(fā)現(xiàn)最大接口耗時7399ms。查看調(diào)用鏈詳情，發(fā)現(xiàn)下游依賴耗時都是ms級別。調(diào)用鏈因?yàn)槭浅闃硬杉?，可能存在鏈路信息丟失的情況，因此需要其他手段進(jìn)一步排查下游依賴服務(wù)。

（2）通過其他手段排查下游慢服務(wù)

接著我查看了0點(diǎn)前后的系統(tǒng)日志，并沒有發(fā)現(xiàn)dubbo調(diào)用超時的情況。然后通過公司的應(yīng)用監(jiān)控查看下游應(yīng)用P95響應(yīng)時間，如下圖，在0點(diǎn)時刻，下游的一些服務(wù)響應(yīng)時長確實(shí)會慢一些，最高的達(dá)到了1.45s，雖然對上游有一定影響，但不至于影響這么大。

（3）慢SQL排查

接下來是慢SQL的排查，我們系統(tǒng)的連接池使用的是阿里開源的druid，SQL執(zhí)行超過1s會打印慢SQL日志，查看日志中心也沒有發(fā)現(xiàn)慢SQL的蹤跡。

到現(xiàn)在，可以初步排除因下游依賴慢導(dǎo)致服務(wù)超時，我們繼續(xù)排查應(yīng)用自身問題。

2.2.2 應(yīng)用自身問題排查

（1）復(fù)雜耗時邏輯排查

首先查看了接口的源碼，整體邏輯比較簡單，通過dubbo調(diào)用下游商品系統(tǒng)獲取商品信息，本地再進(jìn)行商品信息的排序等簡單的處理。不存在復(fù)雜耗時邏輯問題。

（2）垃圾回收停頓排查

通過公司應(yīng)用監(jiān)控查看應(yīng)用的GC情況，發(fā)現(xiàn)0點(diǎn)前后沒有發(fā)生過full GC，也沒有發(fā)生過Old GC。垃圾回收停頓的因素也被排除。

（3）線程同步阻塞排查

通過公司應(yīng)用監(jiān)控查看是否存在同步阻塞線程，如下圖：

看到這里，終于有種天不負(fù)有心人的感覺了。從00:00:00開始一直到00:02:00，這兩分鐘里，出現(xiàn)了較多狀態(tài)為BLOCKED的線程，超時的接口大概率和這些blocked線程相關(guān)。我們只需要進(jìn)一步分析JVM堆棧信息即可真相大白。

我們隨機(jī)選取一臺比較有代表性的機(jī)器查看block堆棧信息，堆棧采集時間是2022-08-02 00:00:20。

// 日志打印操作，被線程catalina-exec-408阻塞"catalina-exec-99" Id=506 BLOCKED on org.apache.log4j.spi.RootLogger@15f368fa owned by "catalina-exec-408" Id=55204    at org.apache.log4j.Category.callAppenders(Category.java:204)    -  blocked on org.apache.log4j.spi.RootLogger@15f368fa    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF(Category.java:391)    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF$accessor$pRDvBPqB(Category.java)    at org.apache.log4j.Category$auxiliary$JhXHxvpc.call(Unknown Source)    at com.vivo.internet.trace.agent.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:46)    at org.apache.log4j.Category.forcedLog(Category.java)    at org.apache.log4j.Category.log(Category.java:856)    at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:324)    ...// 日志打印操作，被線程catalina-exec-408阻塞"catalina-exec-440" Id=55236 BLOCKED on org.apache.log4j.spi.RootLogger@15f368fa owned by "catalina-exec-408" Id=55204    at org.apache.log4j.Category.callAppenders(Category.java:204)    -  blocked on org.apache.log4j.spi.RootLogger@15f368fa    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF(Category.java:391)    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF$accessor$pRDvBPqB(Category.java)    at org.apache.log4j.Category$auxiliary$JhXHxvpc.call(Unknown Source)    at com.vivo.internet.trace.agent.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:46)    at org.apache.log4j.Category.forcedLog(Category.java)    at org.apache.log4j.Category.log(Category.java:856)    at org.slf4j.impl.Log4jLoggerAdapter.warn(Log4jLoggerAdapter.java:444)    ...// 日志打印操作，被線程catalina-exec-408阻塞"catalina-exec-416" Id=55212 BLOCKED on org.apache.log4j.spi.RootLogger@15f368fa owned by "catalina-exec-408" Id=55204    at org.apache.log4j.Category.callAppenders(Category.java:204)    -  blocked on org.apache.log4j.spi.RootLogger@15f368fa    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF(Category.java:391)    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF$accessor$pRDvBPqB(Category.java)    at org.apache.log4j.Category$auxiliary$JhXHxvpc.call(Unknown Source)    at com.vivo.internet.trace.agent.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:46)    at org.apache.log4j.Category.forcedLog(Category.java)    at org.apache.log4j.Category.log(Category.java:856)    at org.slf4j.impl.Log4jLoggerAdapter.warn(Log4jLoggerAdapter.java:444)    ...

通過堆棧信息可以分析出2點(diǎn)：

處于blocked狀態(tài)的線程都是日志打印所有的線程都是被線程名為“catalina-exec-408”阻塞

追蹤到這里，慢服務(wù)的表層原因就清楚了。被線程catalina-exec-408阻塞的線程，一直處于blocked狀態(tài)，導(dǎo)致服務(wù)響應(yīng)超時。

三、根因分析

表層原因找到以后，我們一起撥開層層迷霧，尋找真相背后的真相吧！

所有慢服務(wù)的線程都是在打印日志的時候被線程catalina-exec-408阻塞。那么線程catalina-exec-408在做什么呢？

可以發(fā)現(xiàn)，在00:00:18.858時刻，該線程在打印登錄態(tài)校驗(yàn)失敗的日志，也并無復(fù)雜的處理邏輯。難道是該線程打印日志慢，阻塞了其他線程嗎？帶著這個疑問，我開始深入日志框架的源碼尋找答案。

我們的項(xiàng)目使用的日志框架是slf4j + log4j。根據(jù)被阻塞的線程棧信息我們定位到這段代碼如下：

publicvoid callAppenders(LoggingEvent event) {  int writes = 0;  for(Category c = this; c != null; c=c.parent) {    // Protected against simultaneous call to addAppender, removeAppender,...    // 這是204行，加了sychronized    synchronized(c) {  if(c.aai != null) {    writes += c.aai.appendLoopOnAppenders(event);  }  if(!c.additive) {    break;  }    }  }  if(writes == 0) {    repository.emitNoAppenderWarning(this);  }}

可以看到堆棧信息中的204行是synchronized代碼塊，對其它線程造成阻塞的這是這塊代碼。那么synchronized代碼塊內(nèi)部邏輯是什么呢？為什么要執(zhí)行很久呢？下面是synchronized代碼塊中的核心邏輯：

public  int appendLoopOnAppenders(LoggingEvent event) {    int size = 0;    Appender appender;     if(appenderList != null) {      size = appenderList.size();      for(int i = 0; i < size; i++) {    appender = (Appender) appenderList.elementAt(i);    appender.doAppend(event);      }    }       return size;  }

可以看到，這塊邏輯就是將日志寫入所有配置的appender中。我們配置的appender有兩個，一個是console appender，也就是輸出到catalina.out文件。還有一個是按照公司日志中心采集要求，以Json格式輸出的appender。這里可以做出推斷，線程catalina-exec-408在將日志輸出到appender時耗時較多。

我很自然的開始懷疑當(dāng)時的機(jī)器負(fù)載，特別是IO負(fù)載可能會比較高，通過公司的機(jī)器監(jiān)控，我們查看了下相關(guān)指標(biāo)：

果然，從00:00:00開始，磁盤IO消耗持續(xù)彪高，到1分鐘20秒第一波高峰才結(jié)束，在00:00:20時刻，IO消耗達(dá)到峰值99.63%,接近100%。難怪應(yīng)用輸出一條日志都這么難！

到底是誰把IO資源消耗光了，消耗到幾乎骨頭都不剩？帶著疑問，我進(jìn)一步通過公司的機(jī)器監(jiān)控查看了主機(jī)快照：

發(fā)現(xiàn)在00:00:20時刻，tomcat用戶在執(zhí)行腳本/bin/sh /scripts/cutlog.sh，腳本在執(zhí)行命令cp catalina.out catalina.out-2022-08-02-00。IO消耗達(dá)到了109475612 bytes/s(約104MB/s) 。

事情就要水落石出了，我們繼續(xù)掘地三尺。運(yùn)維同學(xué)登陸到機(jī)器上，切換到tomcat用戶，查看定時任務(wù)列表（執(zhí)行crontab -l），得到結(jié)果如下：

00 00 * * * /bin/sh /scripts/cutlog.sh

正是快照中的腳本/bin/sh /scripts/cutlog.sh，每天0點(diǎn)執(zhí)行。具體的腳本內(nèi)容如下：

$ cat /scripts/cutlog.sh#!/bin/bashfiles=(  xxx)time=$(date +%F-%H)for file in ${files[@]}do  dir=$(dirname ${file})  filename=$(echo "xxx"|awk -F"/" "{print $NF}")  # 歸檔catalina.out日志并清空catalina.out當(dāng)前文件內(nèi)容  cd ${dir} && cp ${filename} ${filename}-${time} && > ${filename}done

我們從腳本中找到了高IO消耗的元兇，就是這個copy命令，目的是將catalina.out日志歸檔并將catalina.out日志文件清空。

這個正常的運(yùn)維腳本肯定是比較消耗 IO 資源的，執(zhí)行的時長受文件大小影響。運(yùn)維同學(xué)也幫忙看了下歸檔的日志大小：

[root@xxx:logdir]# du -sh *1.4G catalina.out2.6G catalina.out-2022-08-02-00

歸檔的文件大小有2.6 G，按照104MB/s估算，需要耗時25秒。也就是00:00:00到00:00:25期間，業(yè)務(wù)日志輸出都會比較緩慢，造成大量線程block，進(jìn)而導(dǎo)致接口響應(yīng)超時。

四、問題解決

定位到了問題的根因，就可以對癥下藥了。有幾個方案可以選擇：

4.1 生產(chǎn)環(huán)境不打印日志到console

消耗 IO資源的操作就是catalina.out日志的歸檔，如果不寫日志到該文件，是可以解決日志打印IO等待的問題的。但是像本地調(diào)試、壓測環(huán)境還是比較依賴console日志的，所以就需要根據(jù)不同環(huán)境來設(shè)置不同的console appender。目前l(fā)ogback、Log4j2已經(jīng)支持根據(jù)Spring profile來區(qū)別配置，我們用的Log4j還不支持。切換日志底層框架的成本也比較高，另外早期的公司中間件與Log4j日志框架強(qiáng)耦合，無法簡單切換，所以我們并沒有采用這個方案。

4.2 配置日志異步打印

Log4j提供了AsyncAppender用于支持異步日志打印，異步日志可以解決同步日志打印IO等待的問題，不會阻塞業(yè)務(wù)線程。

異步日志的副作用：

異步日志是在日志打印時，將event加入到buffer隊(duì)列中，buffer的大小默認(rèn)是128，支持配置。關(guān)于buffer滿了后有兩種處理策略。

（1）阻塞

當(dāng)屬性blocking設(shè)置為true時，使用阻塞策略，默認(rèn)是true。即buffer滿了后，同步等待，此時線程會阻塞，退變成同步日志。

（2）丟棄

如果blocking設(shè)置為false，在buffer滿了以后，會將該條日志丟棄。

4.3 最終方案

最終我們選擇了方案2，即配置日志異步打印。buffer隊(duì)列大小設(shè)置2048，考慮到部分日志丟失在業(yè)務(wù)上是可以接受的，因此犧牲了小部分可靠性換區(qū)更高的程序性能，將blocking設(shè)置為false。

4.4 小結(jié)

這次的問題排查經(jīng)歷，我收獲了幾點(diǎn)感悟，和大家分享一下：

1）要對線上告警保持敬畏之心

我們應(yīng)該敬畏每一個線上告警，重視每一條錯誤日志?，F(xiàn)實(shí)情況是大多數(shù)時候告警只是因?yàn)榫W(wǎng)絡(luò)抖動，短暫的突發(fā)流量等，是可以自行恢復(fù)的，這就像狼來了的故事一樣，讓我們放松了警惕，導(dǎo)致我們可能會錯過真正的問題，給系統(tǒng)帶來嚴(yán)重災(zāi)難，給業(yè)務(wù)帶來損失。

2）刨根問底

告警只是表象，我們需要搞清楚每個告警的表面原因和根本原因。比如這次的接口超時告警，只有分析出”copy文件耗盡磁盤IO，導(dǎo)致日志打印線程block“這個根本原因后，才能給出優(yōu)雅合理的解決方案。說起來簡單，實(shí)操起來可能會遇到很多困難，這要求我們有清晰的問題排查思路，有良好的的系統(tǒng)可觀測性建設(shè)，有扎實(shí)的技術(shù)基本功和不找到”真兇“永不放棄的決心。

最后希望我的這次問題排查經(jīng)歷能夠讓你有所收獲，有所啟發(fā)。我也將本文用到的超時問題排查思路整理成了流程圖，供大家參考。你有遇到過哪些線上故障呢？你的排查思路是怎樣的呢？歡迎留言交流討論。

標(biāo)簽：