利用 Arthas 解决启动 StandbyNameNode 加载 EditLog 慢的问题

缺乏、安全感 2022-12-25 05:50 131阅读 0赞

作者 | yhf20071

**【Arthas 官方社区正在举行征文活动，参加即有奖品拿~[点击投稿][Link 1]】**

公司新搭 HDFS 集群，namenode做ha，但是在启动 StandbyNamenode 节点的时候出现奇怪的现象：空集群加载 Editlog 很慢，每次重启几乎耗时都在二三十分钟

为了方便大家理解，大致说下 StandbyNamenode（以下简称 SNN）启动过程：

*  SNN 启动时，如果本地没有 FSImage会去 ANN（ActiveNamenode）拉取 FSImage
 *  如果本地有 FSImage，则会根据 transactionId 去 JournalNode 拉取 gap 的 editlog，在本地做合并

问题就出在第 2 步，在从 JournalNode 拉取 EditLog 过程中出现固定 15s 延迟。一般来说，空集群几乎没有操作， editlog 不会太大，不应该出现每次从 JournalNode 拉取 EditLog 都耗费 15s 的时间，日志如下（为了方便观察截取部分日志）：

2020-11-04 18:27:27,577 INFO namenode.RedundantEditLogInputStream (RedundantEditLogInputStream.java:nextOp(177)) - Fast-forwarding stream 'http://cbdp-online1.sdns.fin ancial.cloud:8480/getJournal?jid=hdfs-ha&segmentTxId=213656&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgressOk=true' to transaction ID 184269 2020-11-04 18:27:42,582 INFO namenode.FSEditLogLoader (FSEditLogLoader.java:loadEditRecords(289)) - replaying edit log: 1/44 transactions completed. (2%) 2020-11-04 18:27:42,583 INFO namenode.FSImage (FSEditLogLoader.java:loadFSEdits(162)) - Edits file http://cbdp-online1.sdns.financial.cloud:8480/getJournal?jid=hdfs-ha &segmentTxId=213656&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgressOk=true, http://cbdp-online2.sdns.financial.cloud:8 480/getJournal?jid=hdfs-ha&segmentTxId=213656&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgressOk=true, http://cbdp-onli ne3.sdns.financial.cloud:8480/getJournal?jid=hdfs-ha&segmentTxId=213656&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgres sOk=true of size 5981 edits # 44 loaded in 15 seconds
    
    ......
    
    2020-11-04 18:27:42,583 INFO namenode.RedundantEditLogInputStream (RedundantEditLogInputStream.java:nextOp(177)) - Fast-forwarding stream 'http://cbdp-online1.sdns.financial.cloud:8480/getJournal?jid=hdfs-ha&;segmentTxId=213700&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgressOk=true' to transaction ID 184269 2020-11-04 18:27:57,588 INFO namenode.FSEditLogLoader (FSEditLogLoader.java:loadEditRecords(289)) - replaying edit log: 1/53 transactions completed. (2%) 2020-11-04 18:27:57,589 INFO namenode.FSImage (FSEditLogLoader.java:loadFSEdits(162)) - Edits file http://cbdp-online1.sdns.financial.cloud:8480/getJournal?jid=hdfs-ha&;segmentTxId=213700&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgressOk=true, http://cbdp-online2.sdns.financial.cloud:8480/getJournal?jid=hdfs-ha&;segmentTxId=213700&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgressOk=true, http://cbdp-online3.sdns.financial.cloud:8480/getJournal?jid=hdfs-ha&;segmentTxId=213700&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgressOk=true of size 7088 edits # 53 loaded in 15 seconds

### 1.首先通过日志初步定位代码，粗略定位耗时方法 ###

trace org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader loadFSEdits

### 2.上面的结果只能确定大致耗时方法块，不能精确定位实际耗时方法，如果要精确定位，需要一层一层展开，其中还涉及回调函数、native 函数；为了可以更方便的定位代码，我们先执行 profiler start，观察下耗时函数调用 ###

`profiler start/stop`

![1.png][]

### 3.继续追踪函数 ###

trace org.apache.hadoop.hdfs.server.namenode.EditLogFileInputStream$URLLog$1 run

### 4.因为过程中涉及了 jdk 函数追踪，我们需要设置 options unsafe true ###

trace --skipJDKMethods false sun.net.www.http.HttpClient parseHTTPHeader

trace --skipJDKMethods false java.net.SocketInputStream socktRead '#cost > 10000'

![2.jpeg][]

### 5.我们最后通过调用栈确认代码执行路径 ###

stack *SocketInputStream socketRead "#cost > 10000"

发现由于 StandbyNameNode 的网络读取数据造成阻塞，到此已经碰到 native 函数，在 java 层面已经没有有效方法进行分析。

这时我看到 StandbyNameNode 的日志：

`2020-11-04 18:27:42,583 INFO namenode.RedundantEditLogInputStream (RedundantEditLogInputStream.java:nextOp(177)) - Fast-forwarding stream '`[`http://cbdp-online1.sdns.financial.cloud:8480/getJournal?jid=hdfs-ha&;segmentTxId=213700&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgressOk=true`][http_cbdp-online1.sdns.financial.cloud_8480_getJournal_jid_hdfs-ha_segmentTxId_213700_storageInfo_-64_3A272699407_3A1603893889358_3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11_inProgressOk_true]`' to transaction ID 184269`

同时想起了 @赫炎 提出的思路，有可能是在 JournalNode 端读取 EditLog 文件的时候有阻塞。

### 6.我们在 JournalNode 侧追踪代码调用耗时 ###

trace --skipJDKMethods false org.apache.hadoop.hdfs.qjournal.server.GetJournalEditServlet doGet '#cost > 10000'

发现在调用 `java.net.InetSocketAddress.getHostName` 处耗时 15s，至此找到了罪魁祸首。

### 结论： ###

1.  经分析发现在在开启 Kerberos 的情况下，JournalNode 侧响应 getEditLog 接口调用时会进入方法 isValidRequestor，此时会去解析 SecondNameNode 的 hostName，据此搜索对应的 principal
2.  dns 域名解析服务不能获取 SecondNameNode 的默认地址 0.0.0.0:9868，也即不能解析 0.0.0.0 的 hostName，此处超时 15s 返回，这样每次通过 URLLog 获取 JournalNode的EditLog 时，总会有额外耗时 15s，导致 SNN 加载 EditLog 变慢。

为了验证猜想，在每个 JournalNode 节点 hosts 文件配置 0.0.0.0 0.0.0.0，重启 SNN，速度提升了 20 倍

不得不说，Arthas 作为动态追踪调试 java 进程的神器，真的很方便开发人员定位问题。赞一个！

[Link 1]: http://alibabacloud.mikecrm.com/9khcRrs
[1.png]: /images/20221120/dbd7d2f1ff564d478ab598f79c105a67.png
[2.jpeg]: /images/20221120/bfc6ed2191ed48d2a1aa9c7d990f65c3.png
[http_cbdp-online1.sdns.financial.cloud_8480_getJournal_jid_hdfs-ha_segmentTxId_213700_storageInfo_-64_3A272699407_3A1603893889358_3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11_inProgressOk_true]: http://cbdp-online1.sdns.financial.cloud:8480/getJournal?jid=hdfs-ha&;segmentTxId=213700&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgressOk=true