一褥伴、結(jié)論
為了提高看本文的效率召廷，我就先寫結(jié)論。如果對我發(fā)現(xiàn)這個問題的過程感興趣的閱讀目錄中的[問題發(fā)現(xiàn)]部分否淤。
服務(wù)器重啟時會有網(wǎng)絡(luò)對時的過程喉恋。如果程序依賴系統(tǒng)時間并把系統(tǒng)時間當作一個狀態(tài)來使用贴铜，在服務(wù)器重啟時可能會因為對時延時使得程序拿到錯誤的系統(tǒng)時間而引起程序錯誤。
二瀑晒、問題發(fā)現(xiàn)和解決
案發(fā)現(xiàn)場
某天S同學收到通知绍坝，由于某臺服務(wù)器有問題需要對其進行手動重啟。于是剛接手這個項目的S同學準備在低峰期在控制臺重啟服務(wù)器苔悦，由于不涉及到代碼的改動轩褐，只需要從注冊中心將節(jié)點摘除就可以重啟，重啟后服務(wù)會通過Supervisor自動啟動并重新注冊到注冊中心玖详。
于是S同學在當天低峰期的某一時刻14:48對這臺機器進行了重啟把介，并隔段時間看看監(jiān)控：重啟后只要CPU、內(nèi)存等單機指標正常蟋座，流量回歸正常水位拗踢，異常不增加，上游沒有明顯地抖動就算是重啟成功了向臀。
然而S同學雖然看到CPU巢墅、內(nèi)存、GC等系統(tǒng)打點正常券膀，但是請求量君纫、異常數(shù)和一些服務(wù)埋下的Trace打點都消失了。所幸業(yè)務(wù)方好像都沒有受到影響芹彬，S同學慌忙把這個節(jié)點從注冊中心摘除蓄髓，開始Debug。
現(xiàn)場分析
首先最直觀的一點：系統(tǒng)打點正常而業(yè)務(wù)打點缺失舒帮』岷龋基于這個現(xiàn)象開始查找這兩種打點之間有什么差異。通過扒Trace團隊的源碼(打點都是由接入了Trace團隊的jar包實現(xiàn)的)發(fā)現(xiàn)系統(tǒng)打點是將每個點發(fā)送到一個特定的MQ中由Trace服務(wù)對其進行消費玩郊，而業(yè)務(wù)打點是直接調(diào)Trace的接口進行打點肢执。
- 懷疑這臺機器是否能夠正常與Trace服務(wù)器通信
既然與Trace服務(wù)器的連接是通的，那應(yīng)該只有兩個原因
1. 根本沒有調(diào)用Trace服務(wù)器打點發(fā)到Trace服務(wù)器的
2. 點是錯誤的點瓦宜，不會被打出來
繼續(xù)啃了一晚上Trace的源碼蔚万，終于發(fā)現(xiàn)原因是前者，即根本沒有調(diào)用Trace服務(wù)器打點临庇。這個問題由于本地是完全沒有辦法復(fù)現(xiàn)的反璃，只能在線上已有的機器進行復(fù)現(xiàn)，所以只能使用arthas對進程的各個可以的方法進行watch假夺，所以花了一晚上的時間淮蜈。不過arthas再強也沒法像本地debug一樣，我們還是沒有辦法確定到底是為什么沒有調(diào)用Trace服務(wù)器打點已卷。（雖然服務(wù)已經(jīng)從注冊中心摘除梧田，但是它是有定時任務(wù)在跑的，所以依然會有一些業(yè)務(wù)打點）
陷入僵局
截至此時侧蘸，比較的線索已經(jīng)斷了裁眯，我們不做斷點debug得到每一個調(diào)用棧的參數(shù)的話，要確定為什么沒有調(diào)用Trace服務(wù)實在是太困難了讳癌，于是我們開始沒有目的地亂查穿稳。
S同學將某一時刻的dump文件下載到本地看了好一會，發(fā)現(xiàn)有Metric-Producer線程一直處于Waiting狀態(tài)晌坤，經(jīng)過詢問后發(fā)現(xiàn)這個Metric-Producer線程就是Trace用來生成打點的線程!
這里根據(jù)這個Trace的線程名相信大家也猜到了這個Trace的代碼實際上是進行異步打點的逢艘，Metric-Producer只是生成一些打點緩存到本地列表，真正打點是通過一個叫Metric-Consumer線程來進行的骤菠，它會將內(nèi)存中的Trace列表一次性調(diào)用Trace服務(wù)打出來它改。
根據(jù)這個棧S同學很快找到了代碼中對應(yīng)的地方，確實是ReentrantLock的一個Condition在await()商乎，它正在等待著某樣東西喚醒央拖。
至此，我們確定了確實是我們服務(wù)本身的問題鹉戚，因為Metric-Producer一直在等待爬泥，所以是因為服務(wù)中由于某些原因?qū)е耇race的點沒有生成導(dǎo)致的，但是是什么導(dǎo)致的崩瓤，我們已經(jīng)把arthas給玩遍了也沒有個結(jié)論袍啡，我們也先暫時封鎖現(xiàn)場，鳴金收兵了(當前時間22:37)却桶。
破案
第二天一到公司境输，S同學首先看一下昨天留下的問題。打開監(jiān)控看到的那一幕讓所有人都大跌眼鏡：昨晚22:53的時候業(yè)務(wù)打點居然出現(xiàn)了!
這意味著如果S同學昨晚要是晚半小時走的話颖系，就能看到打點奇跡般地出現(xiàn)了嗅剖，不過估計他會因此失眠一宿。
至此這個服務(wù)變得正常得不能再正常了嘁扼，打點正常信粮，系統(tǒng)指標正常，定時任務(wù)也能正常處理趁啸。如果想要繼續(xù)調(diào)查這個案件强缘，必須要讓它復(fù)現(xiàn)督惰，但是所有人都打賭即便現(xiàn)在重啟這臺服務(wù)器也不會再復(fù)現(xiàn)這個問題了，因為公司這么多服務(wù)沒有一個人反映過這個問題的旅掂，我們都認為這個現(xiàn)象是個發(fā)生概率極低極低的現(xiàn)象赏胚。
即便現(xiàn)在服務(wù)是如此的正常，S同學還是不太敢直接把服務(wù)直接注冊到注冊中心商虐，他決定再重啟一次觉阅，確實保證這是一個正常的服務(wù)才將它注冊到注冊中心。
于是S同學在14:12的時候又重啟了這臺服務(wù)器秘车，結(jié)果現(xiàn)實打了所有人的臉：這臺機器的業(yè)務(wù)打點又消失了典勇！
“穩(wěn)定復(fù)現(xiàn)!”
S同學又開始了積極排查，對他來說叮趴，今天的情況跟昨天相比有一點點不同割笙，昨天由于所有人都認為只是重啟而已，對這種事不以為意疫向，而今天則是第一時間發(fā)現(xiàn)了打點缺失的情況咳蔚。所以今天的日志是新鮮的，啟動日志不至于被浩浩蕩蕩的業(yè)務(wù)日志給淹沒搔驼。
S同學立刻將這臺機器從注冊中心摘除谈火，開始從啟動日志開始排查錯誤。
當S同學在日志文件中找到服務(wù)啟動日志的第一條時舌涨，差點激動得跳起來糯耍，心里暗喊破案了。當時太激動沒有截圖囊嘉，不過我可以將大概的日志打出來讓大伙看看:
2020-12-01 22:13:57.044 ERROR SQLLogFilter[worker-31]: [xxxx…xxx.xxxx.xxx.xxx] ## Failure ! sql context is quit, clientConnId=593119546 cRecv0,sSend0,sRecv0,cSend0, CLIENT_FAKE_AUTH unknown_user transId=q0 , quitTrace type=conn.das.send2client.broken
大家看到這個日志有沒有發(fā)現(xiàn)什么不尋常的地方呢温技？其實這個錯誤確實不是那么明顯，不過如果認真讀過標題和認真觀察我在上文把時間都加醋的同學應(yīng)該能發(fā)現(xiàn)這個日志的時間是不對的扭粱。不光時間不對舵鳞，還不對的很有規(guī)律，這個日志的時間剛好是真正的啟動時間+8h琢蛤。8h對某些程序員來說應(yīng)該是要比較敏感的蜓堕，這里就放一個公式吧，是我自己瞎寫的博其，這是我記住格林威治時間(GMT)的手段: CST + 8h = GMT
到這里套才，S同學開始猜想服務(wù)一開始拿到的時間其實是GMT，而后這個時間一定會變成正確的CST(畢竟如果不變回CST慕淡，我們其他的服務(wù)早出現(xiàn)時間不對的問題了)背伴。因此S同學大膽預(yù)測，在幾行之后，這個時間就會變成14:xx:xx傻寂。不一會兒這個命題就被證實了息尺。(這個截圖被留下了，因為被S同學發(fā)到了群里并提出他的時差說)
結(jié)論和證明
結(jié)論：當服務(wù)器重啟時崎逃，對時進程和服務(wù)進程并行進行掷倔。服務(wù)啟動時拿到的時間是GMT(格林威治時間)眉孩，而之后拿到的時間是CST(中國標準時間)个绍。Trace服務(wù)會將服務(wù)啟動時拿到的時間當作一個狀態(tài)進行后續(xù)的邏輯判斷，由于這個時間錯誤導(dǎo)致了后續(xù)的邏輯判斷錯誤浪汪。
通過啃源碼巴柿，S同學將出現(xiàn)邏輯錯誤的代碼扒出來了：
圖一：啟動時會將當前時間(22:xx)存到成員變量start中
圖二：打點時會用當前時間(14:xx)減去start與2000比較，這個邏輯在8消失內(nèi)一定是false死遭。不用去糾結(jié)后面兩個條件广恢，只要沒有成功打過點它們就都是false。
此時再回過頭來看之前的那張監(jiān)控圖呀潭，打點缺失的時間大概是8小時钉迷。繼續(xù)求證的辦法就是現(xiàn)在預(yù)言在晚上22:12左右，打點又會重新出現(xiàn)钠署，不過現(xiàn)在S同學用了更快的求證辦法糠聪。S同學在Supervisor啟動腳本開頭添加系統(tǒng)對時命令，即服務(wù)啟動前先強制對時再進行重啟谐鼎，結(jié)果可想而知舰蟆，服務(wù)和打點都好起來了。
后記
之前有個問題可能大家還有疑惑：為什么這么大個公司只有我出現(xiàn)了這個必現(xiàn)的問題呢狸棍？因為:
????1. 系統(tǒng)對時也是網(wǎng)絡(luò)對時身害，對時的時間會根據(jù)網(wǎng)絡(luò)延時的不同而不同。
????2. 一般不會做重啟操作草戈，平時的服務(wù)發(fā)布塌鸯，服務(wù)重啟都不是直接重啟機器的，所以我們這重啟機器數(shù)據(jù)極低頻的操作唐片。
????3. 公司全面上云后大部分服務(wù)已經(jīng)部署到docker中丙猬，系統(tǒng)對時是與宿主機的對時，由于是本地對時所以速度極快牵触，而我們這個服務(wù)剛好不是部署在docker的淮悼。
關(guān)于Trace打點丟失的問題，我之前畫了個時序圖揽思，幫助大家理解袜腥，如果看了以后也還不太明白的話不用糾結(jié)，這不是重點
中二的評價
S同學把這個現(xiàn)象和結(jié)果發(fā)給了運維的大佬，得到了這樣一個中二的評價
