Uploaded image for project: 'IMPALA'
  1. IMPALA
  2. IMPALA-4162

Extensive logging in HDFS NameNode during metadata load when dfs.namenode.acls.enabled=false

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: Impala 2.5.0
    • Fix Version/s: Impala 2.10.0
    • Component/s: Catalog
    • Labels:

      Description

      I noticed that during metadata loading or after running "invalidate metadata" is that there is an extensive amount of CPU spent and memory allocated

      org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(Object, Method, Object[])

      When I checked the NameNode log I found thousands of entries with the error message below

      2016-09-17 11:04:31,980 WARN org.apache.hadoop.security.UserGroupInformation: PriviledgedActionException as:impala (auth:SIMPLE) cause:org.apache.hadoop.hdfs.protocol.AclException: The ACL operation has been rejected.  Support for ACLs has been disabled by setting dfs.namenode.acls.enabled to false.
      2016-09-17 11:04:31,980 INFO org.apache.hadoop.ipc.Server: IPC Server handler 15 on 8020, call org.apache.hadoop.hdfs.protocol.ClientProtocol.getAclStatus from 10.17.193.6:54224 Call#15696 Retry#0: org.apache.hadoop.hdfs.protocol.AclException: The ACL operation has been rejected.  Support for ACLs has been disabled by setting dfs.namenode.acls.enabled to false.
      

      By default dfs.namenode.acls.enabled is false.

      When I enabled dfs.namenode.acls.enabled the warning and INFO messages stopped and metadata loading after "invalidate metadata" was 5-10% faster.

      This is the call stack for the exception

                              com.cloudera.impala.catalog.HdfsTable.getAvailableAccessLevel(FileSystem, Path)	1,020.475	814,602,776	3.494
                                 com.cloudera.impala.util.FsPermissionChecker.getPermissions(FileSystem, Path)	1,195.04	680,677,832	2.92
                                    org.apache.hadoop.hdfs.DistributedFileSystem.getAclStatus(Path)	1,546.947	541,678,944	2.323
                                       org.apache.hadoop.fs.FileSystemLinkResolver.resolve(FileSystem, Path)	1,546.947	541,678,944	2.323
                                          org.apache.hadoop.hdfs.DistributedFileSystem$41.doCall(Path)	1,546.947	541,678,944	2.323
                                             org.apache.hadoop.hdfs.DistributedFileSystem$41.doCall(Path)	1,546.947	541,678,944	2.323
                                                org.apache.hadoop.hdfs.DFSClient.getAclStatus(String)	1,675.657	506,929,328	2.174
                                                   com.sun.proxy.$Proxy14.getAclStatus(String)	1,770.424	468,924,760	2.011
                                                      org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(Object, Method, Object[])	1,770.424	468,924,760	2.011
                                                         org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(Method, Object[])	2,236	373,004,328	1.6
                                                            java.lang.reflect.Method.invoke(Object, Object[])	2,236	373,004,328	1.6
                                                               sun.reflect.DelegatingMethodAccessorImpl.invoke(Object, Object[])	2,236	373,004,328	1.6
                                                                  sun.reflect.GeneratedMethodAccessor11.invoke(Object, Object[])	2,236	373,004,328	1.6
                                                                     org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolTranslatorPB.getAclStatus(String)	2,236	373,004,328	1.6
                                                                        com.sun.proxy.$Proxy13.getAclStatus(RpcController, AclProtos$GetAclStatusRequestProto)	2,236	373,004,328	1.6
                                                                           org.apache.hadoop.ipc.ProtobufRpcEngine$Invoker.invoke(Object, Method, Object[])	2,236	373,004,328	1.6
                                                                              com.google.protobuf.ServiceException.<init>(Throwable)	2,514.783	338,254,552	1.451
                                                                                 java.lang.Exception.<init>(Throwable)	2,514.783	338,254,552	1.451
                                                                                    java.lang.Throwable.<init>(Throwable)	2,514.783	338,254,552	1.451
                                                                                       org.apache.hadoop.ipc.RemoteException.toString()	2,746.667	315,088,072	1.351
                                                                                          java.lang.StringBuilder.toString()	3,016	181,142,096	0.777
                                                                                             java.lang.String.<init>(char[], int, int)	3,016	181,142,096	0.777
                                                                                                java.util.Arrays.copyOfRange(char[], int, int)	3,016	181,142,096	0.777
                                                                                          java.lang.StringBuilder.append(String)	2,680	122,362,768	0.525
                                                                                             java.lang.AbstractStringBuilder.append(String)	2,680	122,362,768	0.525
                                                                                                java.lang.AbstractStringBuilder.ensureCapacityInternal(int)	2,680	122,362,768	0.525
                                                                                                   java.lang.AbstractStringBuilder.expandCapacity(int)	2,680	122,362,768	0.525
                                                                                                      java.util.Arrays.copyOf(char[], int)	2,680	122,362,768	0.525
      

      Query timeline with ACLs enabled

       Query Timeline: 30m55s
             - Start execution: 118.666us (118.666us)
             - Planning finished: 29m8s (29m8s)
      

      Query timeline with ACLs disable

          Query Timeline: 36m53s
             - Start execution: 116.024us (116.024us)
             - Planning finished: 34m46s (34m46s)
      

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                Unassigned
                Reporter:
                mmokhtar Mostafa Mokhtar
              • Votes:
                0 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: