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

Posted on by

前言

首先描述下問題的背景，博主有個習慣，每天上下班的時候看下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不可用的資料請關註WalkonNet其它相關文章！

推薦閱讀：