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

发布时间:2021-07-20 11:47:52 作者:chen
来源:亿速云 阅读:182

本篇内容主要讲解“如何利用 Arthas 解决启动  StandbyNameNode 加载 EditLog 慢的问题”,感兴趣的朋友不妨来看看。本文介绍的方法操作简单快捷,实用性强。下面就让小编来带大家学习“如何利用 Arthas 解决启动  StandbyNameNode 加载 EditLog 慢的问题”吧!

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

为了方便大家理解,大致说下 StandbyNamenode(以下简称 SNN)启动过程:

问题就出在第 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

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

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'

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

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' 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 解决启动  StandbyNameNode 加载 EditLog 慢的问题”有了更深的了解,不妨来实际操作一番吧!这里是亿速云网站,更多相关内容可以进入相关频道进行查询,关注我们,继续学习!

推荐阅读:
  1. 利用Arthas定位线上问题实例
  2. 利用php-fpm的慢日志定位故障

免责声明:本站发布的内容(图片、视频和文字)以原创、转载和分享为主,文章观点不代表本网站立场,如果涉及侵权请联系站长邮箱:is@yisu.com进行举报,并提供相关证据,一经查实,将立刻删除涉嫌侵权内容。

arthas

上一篇:Java线程池的实现方法

下一篇:怎么修改gazebo物理参数

相关阅读

您好,登录后才能下订单哦!

密码登录
登录注册
其他方式登录
点击 登录注册 即表示同意《亿速云用户服务条款》