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