解析Arthas協助排查線上skywalking不可用問題

2022-02-28 16:06:27

前言

首先描述下問題的背景，博主有個習慣，每天上下班的時候看下skywalking的trace頁面的error情況。但是某天突然發現生產環境skywalking頁面沒有任何資料了，頁面也沒有顯示任何的異常，有點慌，我們線上雖然沒有全面鋪開對接skywalking，但是也有十多個應用。看了應用agent端紀錄檔後，其實也不用太擔心，對應用毫無影響。大概情況就是這樣，但是問題還是要解決，下面就開始排查skywalking不可用的問題。

使用到的工具arthas

Arthas是阿里巴巴開源的一款線上診斷java應用程式的工具，是greys工具的升級版本，深受開發者喜愛。當你遇到以下類似問題而束手無策時，Arthas可以幫助你解決：

這個類從哪個 jar 包載入的？為什麼會報各種類相關的 Exception？
我改的程式碼為什麼沒有執行到？難道是我沒 commit？分支搞錯了？
遇到問題無法線上上 debug，難道只能通過加紀錄檔再重新發布嗎？
線上遇到某個使用者的資料處理有問題，但線上同樣無法 debug，線下無法重現！
是否有一個全域性視角來檢視系統的執行狀況？
有什麼辦法可以監控到JVM的實時執行狀態？
Arthas採用命令列互動模式，同時提供豐富的 Tab 自動補全功能，進一步方便進行問題的定位和診斷。

先定位問題一

檢視skywalking-oap-server.log的紀錄檔，發現會有一條異常瘋狂的在輸出，異常詳情如下：

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]

可以看到，上面的異常輸出的時間節點，以這種頻率在瘋狂的重新整理。通過異常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);
        }

問題一：

通過紀錄檔，初步定位是哪個系統的url太長，skywalking在註冊url資料時觸發elasticsearch針對索引id校驗的異常，而skywalking註冊失敗後會不斷的重試，所以才有了上面紀錄檔不斷刷的現象。

問題解決：

elasticsearch client在寫es前通過寫死的方式寫死了索引id的長度不能超過512位元組大小。也就是我們不能通過從ES側找解決方案了。回到異常的message，只能看到提示id太長，並沒有寫明id具體是什麼，這個異常提示其實是不合格的，博主覺得應該把id的具體內容丟擲來，問題就簡單了。因為異常沒有明確提示，系統又比較多，不能十多個系統依次關閉重啟來驗證到底是哪個系統的哪個url有問題。這個時候Arthas就派上用場了，在不重啟應用不開啟debug模式下，檢視範例中的屬性物件。下面通過Arthas找到具體的url。

從異常中得知，org.elasticsearch.action.index.IndexRequest這個類的validate方法觸發的，這個方法是沒有入參的，校驗的id屬性其實是物件本身的屬性，那麼我們使用Arthas的watch指令來看下這個範例id屬性。先介紹下watch的用法：

功能說明

讓你能方便的觀察到指定方法的呼叫情況。能觀察到的範圍為：返回值、丟擲異常、入參，通過編寫 OGNL 表示式進行對應變數的檢視。

引數說明

watch 的引數比較多，主要是因為它能在 4 個不同的場景觀察物件

引數名稱	引數說明
class-pattern	類名錶示式匹配
method-pattern	方法名錶示式匹配
express	觀察表示式
condition-express	條件表示式
[b]	在方法呼叫之前觀察
[e]	在方法異常之後觀察
[s]	在方法返回之後觀察
[f]	在方法結束之後(正常返回和異常返回)觀察
[E]	開啟正規表示式匹配，預設為萬用字元匹配
[x:]	指定輸出結果的屬性遍歷深度，預設為 1

從上面的用法說明結合異常資訊，我們得到了如下的指令指令碼：

watch org.elasticsearch.action.index.IndexRequest validate "target"

執行後，就看到了我們希望瞭解到的內容，如：

索引id的具體內容看到後，就好辦了。我們暫時把定位到的這個應用啟動指令碼中的的skywalking agent移除後（計劃後面重新設計下介面）重啟了下系統驗證下。果然瘋狂輸出的紀錄檔停住了，但是問題並沒完全解決，skywalking頁面上的資料還是沒有恢復。

定位問題二

skywalking資料儲存使用了elasticsearch，頁面沒有資料，很有可能是elasticsearch出問題了。檢視elasticsearch紀錄檔後，發現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的記憶體設定偏大了，GC時間太長，導致elasticsearch脫離服務了。elasticsearch所在主機的記憶體是8G的實際記憶體7.6G,剛開始設定了5G的堆記憶體大小，可能Full GC的時候耗時太久了。查詢elasticsearch官方檔案後，得到如下的jvm優化建議：

將最小堆大小（Xms）和最大堆大小（Xmx）設定為彼此相等。
Elasticsearch可用的堆越多，它可用於快取的記憶體就越多。但請注意，過多的堆可能會使您陷入長時間的垃圾收集暫停。
設定Xmx為不超過物理RAM的50％，以確保有足夠的物理RAM用於核心檔案系統快取。
不要設定Xmx為JVM用於壓縮物件指標（壓縮oops）的截止值之上; 確切的截止值變化但接近32 GB。

問題解決：

根據Xmx不超過物理RAM的50％上面的jvm優化建議。後面將Xms和Xmx都設定成了3G。然後先停掉skywalking（由於skywalking中會快取部分資料，如果直接先停ES，會報索引找不到的類似異常，這個大部分skywalking使用者應該有遇到過），清空skywalking快取目錄下的內容，如：

在重啟elasticsearch，接著啟動skywalking後頁面終於恢復了

結語

整個問題排查到解決大概花了半天時間，幸好一點也不影響線上應用的使用，這個要得益於skywalking的設計，不然就是大災難了。然後要感謝下Arthas的技術團隊，寫了這麼好用的一款產品並且開源了，如果沒有Arthas，這個問題真的不好定位，甚至一度想到了換掉elasticsearch，採用mysql來解決索引id過長的問題。Arthas真的是線上找問題的利器，博主在Arthas剛面世的時候就關注了，並且一直在公司推廣使用，在這裡再硬推一波。

以上就是解析Arthas協助排查線上skywalking不可用問題的詳細內容，更多關於Arthas排查線上skywalking不可用的資料請關注it145.com其它相關文章！