...
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 中找到对应的调用：
...
所有的时间都会被认为是 countSummay contentSummay 的执行时间，所有这个调用时间很长，但是不会阻塞别的操作。
最初我监控的是 org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getContentSummary，发现很多长时间函数调用，所以没有能够定位到具体的调用。
从另一个角度来说，平均 RPC 调用处理时长 这个数据其实并不太能可靠的反应 namenode 的运行状况，单个类型的 rpc 调用的处理时长更能反应问题。处理时间 这个数据其实并不太能可靠的显示 namenode 的运行状况，单个类型的 rpc 调用的处理时长更能反映问题。
另外，checkPermission 的操作是在递归目录计数之前，而 hdfs audit 中的这一条日志在所有的操作完成之后才会输出，也就是日志中的时间会在阻塞发生之后很久，所以不能根据 checkPermission 的时间点定位到相关的操作。
最后一点是，管理员用户在 contentSummay 时会跳过 checkPermission，所以我最开始用管理员用户执行 count，没有发现问题。参见：
我们的线上集群是启用 sentry 的，SentryAuthorizationInfo 这部分也有一个读写锁，默认同步一次的间隔为 500 ms，在大目录递归权限检查时，性能损耗会大于不启用 sentry 权限的目录。
以上是所有的我能想到的问题，细节很多，见怪不怪。