解析Arthas協(xié)助排查線上skywalking不可用問題
前言
首先描述下問題的背景,博主有個習(xí)慣,每天上下班的時候看下skywalking的trace頁面的error情況。但是某天突然發(fā)現(xiàn)生產(chǎn)環(huán)境skywalking頁面沒有任何數(shù)據(jù)了,頁面也沒有顯示任何的異常,有點慌,我們線上雖然沒有全面鋪開對接skywalking,但是也有十多個應(yīng)用??戳藨?yīng)用agent端日志后,其實也不用太擔(dān)心,對應(yīng)用毫無影響。大概情況就是這樣,但是問題還是要解決,下面就開始排查skywalking不可用的問題。
使用到的工具arthas
Arthas是阿里巴巴開源的一款在線診斷java應(yīng)用程序的工具,是greys工具的升級版本,深受開發(fā)者喜愛。當(dāng)你遇到以下類似問題而束手無策時,Arthas可以幫助你解決:
- 這個類從哪個 jar 包加載的?為什么會報各種類相關(guān)的 Exception?
- 我改的代碼為什么沒有執(zhí)行到?難道是我沒 commit?分支搞錯了?
- 遇到問題無法在線上 debug,難道只能通過加日志再重新發(fā)布嗎?
- 線上遇到某個用戶的數(shù)據(jù)處理有問題,但線上同樣無法 debug,線下無法重現(xiàn)!
- 是否有一個全局視角來查看系統(tǒng)的運行狀況?
- 有什么辦法可以監(jiān)控到JVM的實時運行狀態(tài)?
- Arthas采用命令行交互模式,同時提供豐富的 Tab 自動補全功能,進一步方便進行問題的定位和診斷。
先定位問題一
查看skywalking-oap-server.log的日志,發(fā)現(xiàn)會有一條異常瘋狂的在輸出,異常詳情如下:
2019-03-01 09:12:11,578 - org.apache.skywalking.oap.server.core.register.worker.RegisterPersistentWorker -3264081149 [DataCarrier.IndicatorPersistentWorker.endpoint_inventory.Consumser.0.Thread] ERROR [] - Validation Failed: 1: id is too long, must be no longer than 512 bytes but was: 684; org.elasticsearch.action.ActionRequestValidationException: Validation Failed: 1: id is too long, must be no longer than 512 bytes but was: 684; at org.elasticsearch.action.ValidateActions.addValidationError(ValidateActions.java:26) ~[elasticsearch-6.3.2.jar:6.3.2] at org.elasticsearch.action.index.IndexRequest.validate(IndexRequest.java:183) ~[elasticsearch-6.3.2.jar:6.3.2] at org.elasticsearch.client.RestHighLevelClient.performRequest(RestHighLevelClient.java:515) ~[elasticsearch-rest-high-level-client-6.3.2.jar:6.3.2] at org.elasticsearch.client.RestHighLevelClient.performRequestAndParseEntity(RestHighLevelClient.java:508) ~[elasticsearch-rest-high-level-client-6.3.2.jar:6.3.2] at org.elasticsearch.client.RestHighLevelClient.index(RestHighLevelClient.java:348) ~[elasticsearch-rest-high-level-client-6.3.2.jar:6.3.2] at org.apache.skywalking.oap.server.library.client.elasticsearch.ElasticSearchClient.forceInsert(ElasticSearchClient.java:141) ~[library-client-6.0.0-alpha.jar:6.0.0-alpha] at org.apache.skywalking.oap.server.storage.plugin.elasticsearch.base.RegisterEsDAO.forceInsert(RegisterEsDAO.java:66) ~[storage-elasticsearch-plugin-6.0.0-alpha.jar:6.0.0-alpha] at org.apache.skywalking.oap.server.core.register.worker.RegisterPersistentWorker.lambda$onWork$0(RegisterPersistentWorker.java:83) ~[server-core-6.0.0-alpha.jar:6.0.0-alpha] at java.util.HashMap$Values.forEach(HashMap.java:981) [?:1.8.0_201] at org.apache.skywalking.oap.server.core.register.worker.RegisterPersistentWorker.onWork(RegisterPersistentWorker.java:74) [server-core-6.0.0-alpha.jar:6.0.0-alpha] at org.apache.skywalking.oap.server.core.register.worker.RegisterPersistentWorker.access$100(RegisterPersistentWorker.java:35) [server-core-6.0.0-alpha.jar:6.0.0-alpha] at org.apache.skywalking.oap.server.core.register.worker.RegisterPersistentWorker$PersistentConsumer.consume(RegisterPersistentWorker.java:120) [server-core-6.0.0-alpha.jar:6.0.0-alpha] at org.apache.skywalking.apm.commons.datacarrier.consumer.ConsumerThread.consume(ConsumerThread.java:101) [apm-datacarrier-6.0.0-alpha.jar:6.0.0-alpha] at org.apache.skywalking.apm.commons.datacarrier.consumer.ConsumerThread.run(ConsumerThread.java:68) [apm-datacarrier-6.0.0-alpha.jar:6.0.0-alpha] 2019-03-01 09:12:11,627 - org.apache.skywalking.oap.server.core.register.worker.RegisterPersistentWorker -3264081198 [DataCarrier.IndicatorPersistentWorker.endpoint_inventory.Consumser.0.Thread] ERROR [] - Validation Failed: 1: id is too long, must be no longer than 512 bytes but was: 684; org.elasticsearch.action.ActionRequestValidationException: Validation Failed: 1: id is too long, must be no longer than 512 bytes but was: 684; at org.elasticsearch.action.ValidateActions.addValidationError(ValidateActions.java:26) ~[elasticsearch-6.3.2.jar:6.3.2] at org.elasticsearch.action.index.IndexRequest.validate(IndexRequest.java:183) ~[elasticsearch-6.3.2.jar:6.3.2] at org.elasticsearch.client.RestHighLevelClient.performRequest(RestHighLevelClient.java:515) ~[elasticsearch-rest-high-level-client-6.3.2.jar:6.3.2] at org.elasticsearch.client.RestHighLevelClient.performRequestAndParseEntity(RestHighLevelClient.java:508) ~[elasticsearch-rest-high-level-client-6.3.2.jar:6.3.2] at org.elasticsearch.client.RestHighLevelClient.index(RestHighLevelClient.java:348) ~[elasticsearch-rest-high-level-client-6.3.2.jar:6.3.2] at org.apache.skywalking.oap.server.library.client.elasticsearch.ElasticSearchClient.forceInsert(ElasticSearchClient.java:141) ~[library-client-6.0.0-alpha.jar:6.0.0-alpha] at org.apache.skywalking.oap.server.storage.plugin.elasticsearch.base.RegisterEsDAO.forceInsert(RegisterEsDAO.java:66) ~[storage-elasticsearch-plugin-6.0.0-alpha.jar:6.0.0-alpha] at org.apache.skywalking.oap.server.core.register.worker.RegisterPersistentWorker.lambda$onWork$0(RegisterPersistentWorker.java:83) ~[server-core-6.0.0-alpha.jar:6.0.0-alpha] at java.util.HashMap$Values.forEach(HashMap.java:981) [?:1.8.0_201] at org.apache.skywalking.oap.server.core.register.worker.RegisterPersistentWorker.onWork(RegisterPersistentWorker.java:74) [server-core-6.0.0-alpha.jar:6.0.0-alpha] at org.apache.skywalking.oap.server.core.register.worker.RegisterPersistentWorker.access$100(RegisterPersistentWorker.java:35) [server-core-6.0.0-alpha.jar:6.0.0-alpha] at org.apache.skywalking.oap.server.core.register.worker.RegisterPersistentWorker$PersistentConsumer.consume(RegisterPersistentWorker.java:120) [server-core-6.0.0-alpha.jar:6.0.0-alpha] at org.apache.skywalking.apm.commons.datacarrier.consumer.ConsumerThread.consume(ConsumerThread.java:101) [apm-datacarrier-6.0.0-alpha.jar:6.0.0-alpha] at org.apache.skywalking.apm.commons.datacarrier.consumer.ConsumerThread.run(ConsumerThread.java:68) [apm-datacarrier-6.0.0-alpha.jar:6.0.0-alpha]
可以看到,上面的異常輸出的時間節(jié)點,以這種頻率在瘋狂的刷新。通過異常message,得知到是因為skywalking在寫elasticsearch時,索引的id太長了。下面是elasticsearch的源碼:
if (id != null && id.getBytes(StandardCharsets.UTF_8).length > 512) { validationException = addValidationError("id is too long, must be no longer than 512 bytes but was: " + id.getBytes(StandardCharsets.UTF_8).length, validationException); }
問題一:
通過日志,初步定位是哪個系統(tǒng)的url太長,skywalking在注冊url數(shù)據(jù)時觸發(fā)elasticsearch針對索引id校驗的異常,而skywalking注冊失敗后會不斷的重試,所以才有了上面日志不斷刷的現(xiàn)象。
問題解決:
elasticsearch client在寫es前通過硬編碼的方式寫死了索引id的長度不能超過512字節(jié)大小。也就是我們不能通過從ES側(cè)找解決方案了?;氐疆惓5膍essage,只能看到提示id太長,并沒有寫明id具體是什么,這個異常提示其實是不合格的,博主覺得應(yīng)該把id的具體內(nèi)容拋出來,問題就簡單了。因為異常沒有明確提示,系統(tǒng)又比較多,不能十多個系統(tǒng)依次關(guān)閉重啟來驗證到底是哪個系統(tǒng)的哪個url有問題。這個時候Arthas就派上用場了,在不重啟應(yīng)用不開啟debug模式下,查看實例中的屬性對象。下面通過Arthas找到具體的url。
從異常中得知,org.elasticsearch.action.index.IndexRequest這個類的validate方法觸發(fā)的,這個方法是沒有入?yún)⒌?,校驗的id屬性其實是對象本身的屬性,那么我們使用Arthas的watch指令來看下這個實例id屬性。先介紹下watch的用法:
功能說明
讓你能方便的觀察到指定方法的調(diào)用情況。能觀察到的范圍為:返回值、拋出異常、入?yún)?,通過編寫 OGNL 表達式進行對應(yīng)變量的查看。
參數(shù)說明
watch 的參數(shù)比較多,主要是因為它能在 4 個不同的場景觀察對象
參數(shù)名稱 | 參數(shù)說明 |
---|---|
class-pattern | 類名表達式匹配 |
method-pattern | 方法名表達式匹配 |
express | 觀察表達式 |
condition-express | 條件表達式 |
[b] | 在方法調(diào)用之前觀察 |
[e] | 在方法異常之后觀察 |
[s] | 在方法返回之后觀察 |
[f] | 在方法結(jié)束之后(正常返回和異常返回)觀察 |
[E] | 開啟正則表達式匹配,默認(rèn)為通配符匹配 |
[x:] | 指定輸出結(jié)果的屬性遍歷深度,默認(rèn)為 1 |
從上面的用法說明結(jié)合異常信息,我們得到了如下的指令腳本:
watch org.elasticsearch.action.index.IndexRequest validate "target"
執(zhí)行后,就看到了我們希望了解到的內(nèi)容,如:
索引id的具體內(nèi)容看到后,就好辦了。我們暫時把定位到的這個應(yīng)用啟動腳本中的的skywalking agent移除后(計劃后面重新設(shè)計下接口)重啟了下系統(tǒng)驗證下。果然瘋狂輸出的日志停住了,但是問題并沒完全解決,skywalking頁面上的數(shù)據(jù)還是沒有恢復(fù)。
定位問題二
skywalking數(shù)據(jù)存儲使用了elasticsearch,頁面沒有數(shù)據(jù),很有可能是elasticsearch出問題了。查看elasticsearch日志后,發(fā)現(xiàn)elasticsearch正在瘋狂的GC,日志如:
: 139939K->3479K(153344K), 0.0285655 secs] 473293K->336991K(5225856K), 0.0286918 secs] [Times: user=0.05 sys=0.00, real=0.03 secs] 2019-02-28T20:05:38.276+0800: 3216940.387: Total time for which application threads were stopped: 0.0301495 seconds, Stopping threads took: 0.0001549 seconds 2019-02-28T20:05:38.535+0800: 3216940.646: [GC (Allocation Failure) 2019-02-28T20:05:38.535+0800: 3216940.646: [ParNew Desired survivor size 8716288 bytes, new threshold 6 (max 6) - age 1: 1220136 bytes, 1220136 total - age 2: 158496 bytes, 1378632 total - age 3: 88200 bytes, 1466832 total - age 4: 46240 bytes, 1513072 total - age 5: 126584 bytes, 1639656 total - age 6: 159224 bytes, 1798880 total : 139799K->3295K(153344K), 0.0261667 secs] 473311K->336837K(5225856K), 0.0263158 secs] [Times: user=0.06 sys=0.00, real=0.03 secs] 2019-02-28T20:05:38.562+0800: 3216940.673: Total time for which application threads were stopped: 0.0276971 seconds, Stopping threads took: 0.0001030 seconds 2019-02-28T20:05:38.901+0800: 3216941.012: [GC (Allocation Failure) 2019-02-28T20:05:38.901+0800: 3216941.012: [ParNew Desired survivor size 8716288 bytes, new threshold 6 (max 6)
問題二:
查詢后得知,elasticsearch的內(nèi)存配置偏大了,GC時間太長,導(dǎo)致elasticsearch脫離服務(wù)了。elasticsearch所在主機的內(nèi)存是8G的實際內(nèi)存7.6G,剛開始配置了5G的堆內(nèi)存大小,可能Full GC的時候耗時太久了。查詢elasticsearch官方文檔后,得到如下的jvm優(yōu)化建議:
- 將最小堆大?。?code>Xms)和最大堆大?。?code>Xmx)設(shè)置為彼此相等。
- Elasticsearch可用的堆越多,它可用于緩存的內(nèi)存就越多。但請注意,過多的堆可能會使您陷入長時間的垃圾收集暫停。
- 設(shè)置
Xmx
為不超過物理RAM的50%,以確保有足夠的物理RAM用于內(nèi)核文件系統(tǒng)緩存。 不要設(shè)置
Xmx
為JVM用于壓縮對象指針(壓縮oops)的截止值之上; 確切的截止值變化但接近32 GB。
問題解決:
根據(jù)Xmx
不超過物理RAM的50%上面的jvm優(yōu)化建議。后面將Xms和Xmx都設(shè)置成了3G。然后先停掉skywalking(由于skywalking中會緩存部分?jǐn)?shù)據(jù),如果直接先停ES,會報索引找不到的類似異常,這個大部分skywalking用戶應(yīng)該有遇到過),清空skywalking緩存目錄下的內(nèi)容,如:
在重啟elasticsearch,接著啟動skywalking后頁面終于恢復(fù)了
結(jié)語
整個問題排查到解決大概花了半天時間,幸好一點也不影響線上應(yīng)用的使用,這個要得益于skywalking的設(shè)計,不然就是大災(zāi)難了。然后要感謝下Arthas的技術(shù)團隊,寫了這么好用的一款產(chǎn)品并且開源了,如果沒有Arthas,這個問題真的不好定位,甚至一度想到了換掉elasticsearch,采用mysql來解決索引id過長的問題。Arthas真的是線上找問題的利器,博主在Arthas剛面世的時候就關(guān)注了,并且一直在公司推廣使用,在這里再硬推一波。
以上就是解析Arthas協(xié)助排查線上skywalking不可用問題的詳細(xì)內(nèi)容,更多關(guān)于Arthas排查線上skywalking不可用的資料請關(guān)注腳本之家其它相關(guān)文章!
- Skywalking-agent調(diào)試說明以trace-ignore為例
- SpringCloudGateway使用Skywalking時日志打印traceId解析
- Apache?SkyWalking?修復(fù)TTL?timer?失效bug詳解
- Apache?SkyWalking?監(jiān)控?MySQL?Server?實戰(zhàn)解析
- 全鏈路監(jiān)控平臺Pinpoint?SkyWalking?Zipkin選型對比
- skywalking源碼解析javaAgent工具ByteBuddy應(yīng)用
- skywalking分布式服務(wù)調(diào)用鏈路追蹤APM應(yīng)用監(jiān)控
- skywalking容器化部署docker鏡像構(gòu)建k8s從測試到可用
- python抓取skywalking中超過2s的告警接口
相關(guān)文章
Java中使用數(shù)組實現(xiàn)棧數(shù)據(jù)結(jié)構(gòu)實例
這篇文章主要介紹了Java中使用數(shù)組實現(xiàn)棧數(shù)據(jù)結(jié)構(gòu)實例,本文先是講解了實現(xiàn)棧至少應(yīng)該包括以下幾個方法等知識,然后給出代碼實例,需要的朋友可以參考下2015-01-01java 判斷一個數(shù)是否為2的整數(shù)次冪方法
今天小編就為大家分享一篇java 判斷一個數(shù)是否為2的整數(shù)次冪方法,具有很好的參考價值,希望對大家有所幫助。一起跟隨小編過來看看吧2018-07-07java(jdk)環(huán)境變量配置(XP、win7、win8)圖文教程詳解
對于初學(xué)java的同學(xué)來說,第一件事不是寫hello world,而是搭建好java開發(fā)環(huán)境,下載jdk,安裝,配置環(huán)境變量。這些操作在xp、win7、win8不同的操作系統(tǒng)里面配置不太一樣,下面通過本文給大家介紹如何在上面不同操作系統(tǒng)下配置2017-03-03Spring定時任務(wù)使用及如何使用郵件監(jiān)控服務(wù)器
這篇文章主要介紹了Spring定時任務(wù)使用及如何使用郵件監(jiān)控服務(wù)器,文中通過示例代碼介紹的非常詳細(xì),對大家的學(xué)習(xí)或者工作具有一定的參考學(xué)習(xí)價值,需要的朋友可以參考下2019-07-07java開發(fā)ExecutorService監(jiān)控實現(xiàn)示例詳解
這篇文章主要為大家介紹了java開發(fā)ExecutorService監(jiān)控實現(xiàn)示例詳解,有需要的朋友可以借鑒參考下,希望能夠有所幫助,祝大家多多進步,早日升職加薪2023-07-07SpringMVC 中HttpMessageConverter簡介和Http請求415 的問題
本文介紹且記錄如何解決在SpringMVC 中遇到415 Unsupported Media Type 的問題,并且順便介紹Spring MVC的HTTP請求信息轉(zhuǎn)換器HttpMessageConverter2016-07-07