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

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'

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`](https://www.oschina.net/action/GoToLink?url=http%3A%2F%2Fcbdp-online1.sdns.financial.cloud%3A8480%2FgetJournal%3Fjid%3Dhdfs-ha%26%3BsegmentTxId%3D213700%26storageInfo%3D-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11%26inProgressOk%3Dtrue)`' 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，至此找到了罪魁祸首。

结论：

经分析发现在在开启 Kerberos 的情况下，JournalNode 侧响应 getEditLog 接口调用时会进入方法 isValidRequestor，此时会去解析 SecondNameNode 的 hostName，据此搜索对应的 principal
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 倍

参考链接：https://my.oschina.net/u/3874284/blog/4763265

利用 Arthas 解决启动 HDFS StandbyNameNode 加载 EditLog 慢的问题相关推荐

利用 Arthas 解决启动 StandbyNameNode 加载 EditLog 慢的问题
作者 | yhf20071 [Arthas 官方社区正在举行征文活动,参加即有奖品拿~点击投稿] 公司新搭 HDFS 集群,namenode做ha,但是在启动 StandbyNamenode 节点的时 ...
解决eclipse环境下maven项目tomcat启动，未加载到项目的问题
解决eclipse环境下maven项目tomcat启动,未加载到项目的问题参考文章: (1)解决eclipse环境下maven项目tomcat启动,未加载到项目的问题 (2)https://www. ...
如何利用微信小游戏的分包加载机制突破4M代码包体积限制
相信大家度过了一个不错的端午假期,在端午前夕,即6月15日晚上,微信小游戏宣布支持分包加载功能,白鹭引擎在端午节后第一天正式支持分包加载机制.在正式向开发者介绍如何使用前,我先为各位解读一下我对微信提 ...
完美解决IIS 服务器无法加载应用程序 '/LM/W3SVC/1/ROOT'。错误是 '没有注册类别
完美解决IIS 服务器无法加载应用程序 '/LM/W3SVC/1/ROOT'.错误是 '没有注册类别现象: 浏览ASP页面提示 500内部错误事件查看器中: [ ...
web项目的启动时文件加载顺序
web项目的启动时文件加载顺序转自:http://www.cnblogs.com/yw-ah/p/5751509.html 一. 1.启动一个WEB项目,WEB容器会先去读取它的配置文件web.xm ...
阵列卡服务器启动不到pe桌面,制作启动u盘加载阵列卡驱动无法安装怎么办
制作启动u盘加载阵列卡驱动无法安装怎么办?安装服务器时碰到没有阵列卡驱动无法安装的问题大家应该都碰到过.之前一次安装2003碰到没阵列卡驱动,解决的办法比较土,上网下了张别人做好的集成了raid驱动的 ...
利用Crowbar抓取网页异步加载的内容 [Python俱乐部]
利用Crowbar抓取网页异步加载的内容 [Python俱乐部] 利用Crowbar抓取网页异步加载的内容 [Python俱乐部] 利用Crowbar抓取网页异步加载的内容在做 Web 信息提取.数 ...
Linux内核启动及文件系统加载过程
当u-boot开始执行bootcmd命令,就进入linux内核启动阶段与 u-boot 类似,普通 Linux 内核的启动过程也可以分为两个阶段,但针对压缩了的内核如 uImage 就要包括内核自解 ...
利用 JQuery的load函数动态加载页面
利用JQuery的load函数动态加载页面 JQuery有好多Ajax函数,其中load是用来动态加载一个页面的内容到指定的dom元素上. 我们来做个例子: 做一个上下(左右)结构的页面,其中下左部分 ...

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

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