现象
用户汇报 Yarn 任务超时，排查发现 namenode 高延迟，有 30 秒以上的时间不响应任何请求。较差的情况有一分钟以上，发生的频率大概在 5 分钟左右一次。
failover controller 的 rpc timeout 超过 45 秒后会触发主备切换，也会延迟服务的恢复时间。由于没有监控告警，实际上问题可能会更严重些。
平均 RPC 队列时间：
分析原因
进程内存已经被同事调整过，分配 200G 内存，并设置 ParNew 为 16 G，加了一些优化的 GC 配置。虽然 namenode 有超过 5 亿个文件对象，内存压力比较大，但是还是不至于有这么大的阻塞问题。
通过 arthas 监控 rpc 调用：
monitor -c 5 org.apache.hadoop.hdfs.server.namenode.FSNamesystem getFileInfo -n 1000
发现每隔一段时间 rpc 调用次数为 0，按照问题发生时间排查 namenode 日志发现有如下记录：
2020-08-07 00:50:45,952 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: FSNamesystem read lock held for 37657 ms via java.lang.Thread.getStackTrace(Thread.java:1556) org.apache.hadoop.util.StringUtils.getStackTrace(StringUtils.java:945) org.apache.hadoop.hdfs.server.namenode.FSNamesystemLock.readUnlock(FSNamesystemLock.java:147) org.apache.hadoop.hdfs.server.namenode.FSNamesystem.readUnlock(FSNamesystem.java:1669) org.apache.hadoop.hdfs.server.namenode.ContentSummaryComputationContext.yield(ContentSummaryComputationContext.java:107) org.apache.hadoop.hdfs.server.namenode.INodeDirectory.computeDirectoryContentSummary(INodeDirectory.java:666) org.apache.hadoop.hdfs.server.namenode.INodeDirectory.computeContentSummary(INodeDirectory.java:629) org.apache.hadoop.hdfs.server.namenode.INodeDirectory.computeDirectoryContentSummary(INodeDirectory.java:643) org.apache.hadoop.hdfs.server.namenode.INodeDirectory.computeContentSummary(INodeDirectory.java:629) org.apache.hadoop.hdfs.server.namenode.INodeDirectory.computeDirectoryContentSummary(INodeDirectory.java:643) org.apache.hadoop.hdfs.server.namenode.INodeDirectory.computeContentSummary(INodeDirectory.java:629) org.apache.hadoop.hdfs.server.namenode.INode.computeAndConvertContentSummary(INode.java:510) org.apache.hadoop.hdfs.server.namenode.FSDirectory.getContentSummary(FSDirectory.java:2319) org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getContentSummary(FSNamesystem.java:4644) org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.getContentSummary(NameNodeRpcServer.java:1097) org.apache.hadoop.hdfs.server.namenode.AuthorizationProviderProxyClientProtocol.getContentSummary(AuthorizationProviderProxyClientProtocol.java:566) org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolServerSideTranslatorPB.getContentSummary(ClientNamenodeProtocolServerSideTranslatorPB.java:895) org.apache.hadoop.hdfs.protocol.proto.ClientNamenodeProtocolProtos$ClientNamenodeProtocol$2.callBlockingMethod(ClientNamenodeProtocolProtos.java) org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:617) org.apache.hadoop.ipc.RPC$Server.call(RPC.java:1073) org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2226) org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2222) java.security.AccessController.doPrivileged(Native Method) javax.security.auth.Subject.doAs(Subject.java:422) org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1917) org.apache.hadoop.ipc.Server$Handler.run(Server.java:2220) Number of suppressed read-lock reports: 0 Longest read-lock held interval: 37657
根据我们对 namenode 架构的理解，全局锁（FSNamesystemLock）读锁并行，写锁排他，某个 rpc handler 长时间持有写锁，必然会阻塞所有的 rpc 请求。
从日志可以看出 getContentSummary 是长时间持有锁的调用，客户端在执行 du 或者 count 命令时，rpc server 会执行这个函数。于是寻找 getContentSummary 执行时间过长的原因以及是谁执行了这个操作。
首先是确认在其他 Handler 阻塞的时候，唯一 RUNNABLE 的 hander 在执行什么：
"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)
然后依据堆栈信息，统计每一个函数执行的时间，发现 DefaultAuthorizationProvider.checkSubAccess 是最后一个阻塞时间接近总时间的函数。以下为源码：
/**
* Guarded by {@link FSNamesystem#readLock()}
*/
private void checkSubAccess(String user, Set<String> groups, INode inode,
int snapshotId, FsAction access, boolean ignoreEmptyDir)
throws AccessControlException {
if (inode == null || !inode.isDirectory()) {
return;
}
Stack<INodeDirectory> directories = new Stack<INodeDirectory>();
for (directories.push(inode.asDirectory()); !directories.isEmpty(); ) {
INodeDirectory d = directories.pop();
ReadOnlyList<INode> cList = d.getChildrenList(snapshotId);
if (!(cList.isEmpty() && ignoreEmptyDir)) {
check(user, groups, d, snapshotId, access);
}
for (INode child : cList) {
if (child.isDirectory()) {
directories.push(child.asDirectory());
}
}
}
}
可见此处递归遍历目录并检查权限，监控该方法的执行，多次执行时间超过 30 秒的，第三个参数 inode 的值都是 ******.db。
watch org.apache.hadoop.hdfs.server.namenode.DefaultAuthorizationProvider checkSubAccess '{params, returnObj}' '#cost>30000' -x 2 -n 1000
在 hdfs 上找到应的路径为 /**/*****.db。
同时在 hdfs-audit.log 中找到对应的调用：
2020-08-07 00:56:10,539 INFO FSNamesystem.audit: allowed=true ugi=*****@***** (auth:KERBEROS) ip=/**.**.154.117 cmd=contentSummary src=/**/*****.db dst=null perm=null proto=rpc
为了验证结论，我们使用这个普通用户执行了多次 count，均出现 rpc 阻塞情况。
查看 count 的结果发现该目录下的目录数接近 200 万，文件数 2000 多万，线上监控 org.apache.hadoop.hdfs.server.namenode.DefaultAuthorizationProvider.check 函数平均调用的时间接近 0.02 毫秒，正常情况下仅目录遍历的时间就在 30 秒以上。
后续通过 ip route 命令禁止了 **.**.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 权限的目录。
以上是所有的我能想到的问题，细节很多，见怪不怪。