Table of Contents
现象
用户汇报 Yarn 任务超时，排查发现 namenode 高延迟，有 30 秒以上的时间不响应任何请求。较差的情况有一分钟以上，发生的频率大概在 5 分钟左右一次。
failover controller 的 rpc timeout 超过 45 秒后会触发主备切换，也会延迟服务的恢复时间。由于监控告警，问题可能会更严重些。秒后会触发主备切换，也会延迟服务的恢复时间。由于没有监控告警，实际上问题可能会更严重些。
平均 RPC 队列和处理时间：队列时间：
分析原因
进程内存已经被同事调整过，分配 200G 内存，并设置 ParNew 为 16 G，加了一些优化的 GC 配置。虽然 namenode 有超过 5 亿个文件对象，内存压力比较大，但是还是不至于有这么大的阻塞问题。
...
从日志可以看出 getContentSummary 是长时间持有锁的调用，客户端在执行 du 或者 count 命令时，rpc server 会执行这个函数。于是寻找 getContentSummary 执行时间过长的原因以及是谁执行了这个操作。
首先是确认在其他 Handler 阻塞的时候，唯一 RUNNING 阻塞的时候，唯一 RUNNABLE 的 hander 在执行什么：
| Code Block |
|---|
"IPC Server handler 70 on 8020" Id=295 cpuUsage=97% RUNNABLE
at java.lang.StringBuilder.append(StringBuilder.java:136)
at org.apache.sentry.hdfs.SentryAuthorizationProvider.addToACLMap(SentryAuthorizationProvider.java:361)
at org.apache.sentry.hdfs.SentryAuthorizationProvider.getAclFeature(SentryAuthorizationProvider.java:340)
at org.apache.hadoop.hdfs.server.namenode.INodeWithAdditionalFields.getAclFeature(INodeWithAdditionalFields.java:233)
at org.apache.hadoop.hdfs.server.namenode.DefaultAuthorizationProvider.check(DefaultAuthorizationProvider.java:252)
at org.apache.hadoop.hdfs.server.namenode.DefaultAuthorizationProvider.checkSubAccess(DefaultAuthorizationProvider.java:223)
at org.apache.hadoop.hdfs.server.namenode.DefaultAuthorizationProvider.checkPermission(DefaultAuthorizationProvider.java:171)
at org.apache.sentry.hdfs.SentryAuthorizationProvider.checkPermission(SentryAuthorizationProvider.java:178)
at org.apache.hadoop.hdfs.server.namenode.FSPermissionChecker.checkPermission(FSPermissionChecker.java:152)
at org.apache.hadoop.hdfs.server.namenode.FSDirectory.checkPermission(FSDirectory.java:3770)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkPermission(FSNamesystem.java:6758)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkPermission(FSNamesystem.java:6749)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getContentSummary(FSNamesystem.java:4642)
at org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.getContentSummary(NameNodeRpcServer.java:1097)
at org.apache.hadoop.hdfs.server.namenode.AuthorizationProviderProxyClientProtocol.getContentSummary(AuthorizationProviderProxyClientProtocol.java:566)
at org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolServerSideTranslatorPB.getContentSummary(ClientNamenodeProtocolServerSideTranslatorPB.java:895)
at org.apache.hadoop.hdfs.protocol.proto.ClientNamenodeProtocolProtos$ClientNamenodeProtocol$2.callBlockingMethod(ClientNamenodeProtocolProtos.java)
at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:617)
at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:1073)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2226)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2222)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:422)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1917)
at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2220) |
...
| Code Block |
|---|
watch org.apache.hadoop.hdfs.server.namenode.DefaultAuthorizationProvider checkSubAccess '{params, returnObj}' '#cost>30000' -x 2 -n 1000 |
在 hdfs 上对找到应的路径为 上找到对应的路径为 /**/*****.db。
同时在 hdfs-audit.log 中找到对应的调用：
...
查看 count 的结果发现该目录下的目录数接近 200 万，文件数 2000 多万，线上监控 org.apache.hadoop.hdfs.server.namenode.DefaultAuthorizationProvider.check 函数平均调用的时间接近 0.02 毫秒，正常情况下仅目录遍历的时间就在 30 秒以上。
后续通过 ip route 命令禁止了这个节点访问 namenode 节点，不再出现 rpc 阻塞的问题。命令禁止了 **.**.154.117 这个点访问 namenode 节点，不再出现 rpc 阻塞的问题。
记录一下看到的细节
其实排查的过程并不是很顺利，断断续续看了两天，很耗费时间，有些想法还是得记录下：
count 是一个很常用的操作，实际上不是每一次 count 都会引发 rpc 阻塞：
首先，count 的操作是经过优化的，如果 count 的文件数过大，count 的过程中会多次获取和释放锁。
hdfs 有两个参数：dfs.content-summary.limit 和 dfs.content-summary.sleep-microsec，前者是定义每一次 lock 和 unlock 的过程中最多的数目，后者定义是 unlock 到下一次 lock 的间隔时间。
所有的时间都会被认为是 contentSummay 的执行时间，所有这个调用时间很长，但是不会阻塞别的操作。
最初我监控的是 org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getContentSummary，发现很多长时间函数调用，所以没有能够定位到具体的调用。
从另一个角度来说，平均 RPC 处理时间 这个数据其实并不太能可靠的显示 namenode 的运行状况，单个类型的 rpc 调用的处理时长更能反映问题。
另外，checkPermission 的操作是在递归目录计数之前，而 hdfs audit 中的这一条日志在所有的操作完成之后才会输出，也就是日志中的时间会在阻塞发生之后很久，所以不能根据 checkPermission 的时间点定位到相关的操作。
最后一点是，管理员用户在 contentSummay 时会跳过 checkPermission，所以我最开始用管理员用户执行 count，没有发现问题。参见：
我们的线上集群是启用 sentry 的，SentryAuthorizationInfo 这部分也有一个读写锁，默认同步一次的间隔为 500 ms，在大目录递归权限检查时，性能损耗会大于不启用 sentry 权限的目录。
以上是所有的我能想到的问题，细节很多，见怪不怪。