0817-6.3.3-Impala执行DDL慢问题分析报告
0817-6.3.3-Impala执行DDL慢问题分析报告
作者：余枫
问题描述
随着集群使用时间的增长，在Impala中执行DDL语句消耗的时间越来越长，排查该问题时进行测试，create一张表的耗时达到4-5s，drop一张表的时间5-10s，该问题影响了Impala的日常跑批工作。
问题分析过程
初次排查该问题时，通过创建一个测试表的方式，在日志中跟踪该表创建的整个流程，当SQL提交到Impala Daemon后，由于是DDL语句，会由Catalog接收到请求后去找Hive Metastore Server获取元数据，在查看Catalog日志时发现，整个create语句花了大概5s的时间，如下日志所示：
I0826 13:16:09.467458 27720 Frontend.java:1286] a94da42385ea3b67:75e09b7100000000] Analysis finished.
I0826 13:16:14.363976 27720 ImpaladCatalog.java:200] a94da42385ea3b67:75e09b7100000000] Adding: TABLE:default.testing version: 8227 size: 51
在查看Hive Metastore Server日志时发现，Hive Metastore Server很快就响应了Catalog的请求，但是却没有显示什么时间返回了操作结果，如下日志所示：
2020-08-26 13:16:09,515 INFO org.apache.hadoop.hive.metastore.HiveMetaStore: [pool-9-thread-160]: 171: create_table: Table(tableName:testing, dbName:default, owner:bdp_usr, ...
2020-08-26 13:16:09,840 INFO org.apache.hadoop.hive.common.FileUtils: [pool-9-thread-160]: Creating directory if it doesn't exist: hdfs://UATHA/user/hive/warehouse/testing
在Catalog获取到Hive Metastore Server返回的元数据后，会马上返回给Impala Daemon，通过Statestore同步元数据到所有的Impala Daemon，在下面的日志中可以看到广播元数据的操作和Catalog中执行完DDL语句的时间相差并不长，证明Statestore广播元数据的环节也并无问题，日志如下：
I0826 13:16:15.569249 27198 catalog-server.cc:611] Collected update: 1:TABLE:default.testing, version=8227, original size=51, compressed size=50
通过上面日志的分析结果，初步判断，执行DDL慢的主要时间是消耗在Hive Metastore Server内部，后续通过修改了Hive Metastore Server的日志级别来进一步确定耗时发生的具体环节。
在查看DEBUG级别的Hive Metastore Server日志时发现，问题主要出在Sentry上，Hive Metastore Server在创建/删除一个表或者数据库的时候都需要通知Sentry同步元数据。从下面的日志中可以看到Hive Metastore Server发出这个通知（Notifying sentry about Notification for CREATE_TABLE (id: 133299)）之后等了将近6秒才收到返回消息，这就是为什么DDL慢的原因。日志如下所示：
2020-08-27 13:11:54,991 DEBUG org.apache.hadoop.hive.ql.log.PerfLogger: [pool-9-thread-59]: <PERFLOG method=create_table_with_environment_context from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
...
2020-08-27 13:11:55,532 DEBUG org.apache.sentry.binding.metastore.SentrySyncHMSNotificationsPostEventListener: [pool-9-thread-59]: Notifying sentry about Notification for CREATE_TABLE (id: 133299)
2020-08-27 13:11:55,532 DEBUG org.apache.sentry.core.common.transport.SentryTransportPool: [pool-9-thread-59]: [1] obtained transport nyuatdn01:8038
2020-08-27 13:11:55,533 DEBUG org.apache.sentry.core.common.transport.SentryTransportPool: [pool-9-thread-59]: Currently 1 active connections, 9 idle connections
2020-08-27 13:11:55,533 DEBUG org.apache.sentry.core.common.transport.RetryClientInvocationHandler: [pool-9-thread-59]: Calling notifyHmsEvent
2020-08-27 13:11:55,533 DEBUG org.apache.thrift.transport.TSaslTransport: [pool-9-thread-59]: data length before wrap: 177
2020-08-27 13:11:55,533 DEBUG org.apache.thrift.transport.TSaslTransport: [pool-9-thread-59]: writing data length: 237
<----- 在此等待了将近6秒
2020-08-27 13:12:01,132 DEBUG org.apache.thrift.transport.TSaslTransport: [pool-9-thread-59]: CLIENT: reading data length: 129
2020-08-27 13:12:01,136 DEBUG org.apache.thrift.transport.TSaslTransport: [pool-9-thread-59]: data length after unwrap: 69
2020-08-27 13:12:01,136 DEBUG org.apache.sentry.binding.metastore.SentrySyncHMSNotificationsPostEventListener: [pool-9-thread-59]: Finished Notifying sentry about Notification for CREATE_TABLE (id: 133299)
2020-08-27 13:12:01,136 DEBUG org.apache.sentry.binding.metastore.SentrySyncHMSNotificationsPostEventListener: [pool-9-thread-59]: Latest processed event ID returned by the Sentry server: 133299
2020-08-27 13:12:01,136 DEBUG org.apache.sentry.core.common.transport.SentryTransportPool: [pool-9-thread-59]: [1] returning nyuatdn01:8038
2020-08-27 13:12:01,137 DEBUG org.apache.hadoop.hive.ql.log.PerfLogger: [pool-9-thread-59]: </PERFLOG method=create_table_with_environment_context start=1598505114991 end=1598505121136 duration=6145 from=org.apache.hadoop.hive.metastore.RetryingHMSHandler threadId=50 retryCount=0 error=false>
定位到Sentry服务的问题后，初步查看Sentry的日志发现，create table的平均时间为3.7s，但是同样的ddl上create database的平均时间只有14ms，日志如下：
2020-08-27 13:12:29,580 INFO org.apache.sentry.api.service.thrift.SentryMetrics: type=TIMER, name=org.apache.sentry.provider.db.service.persistent.HMSFollower.create_database, count=587, min=7.288829, max=82.173701, mean=14.025413855401405, stddev=0.17108183329537113, median=14.007352, p75=14.007352, p95=14.007352, p98=14.007352, p99=15.618253999999999, pXXX-XX-XXXX53999999999, mean_rate=0.003335984152712016, m1=0.0035923052762600865, m5=0.003874149637852582, m15=0.003536851393822959, rate_unit=events/second, duration_unit=milliseconds
2020-08-27 13:12:29,581 INFO org.apache.sentry.api.service.thrift.SentryMetrics: type=TIMER, name=org.apache.sentry.provider.db.service.persistent.HMSFollower.create_table, count=2436, min=8.204786, max=5710.664941999999, mean=3755.5881518186834, stddev=2296.0499299404587, median=5163.032873, p75=5163.032873, p95=5163.032873, p98=5163.032873, p99=5163.032873, p999=5163.032873, mean_rate=0.013844166161343525, m1=0.015050441350939393, m5=0.0072619687637006745, m15=0.01947849264485575, rate_unit=events/second, duration_unit=milliseconds
进一步查看Sentry的日志找到了之前执行测试的建表信息，日志中的两条消息的时间间隔正好与Hive Metastore Server里的耗时吻合。通过Support查看Sentry的代码确认，第二条消息是Sentry为新建的表添加owner权限之后马上打印的。而第一条消息是执行数据库操作的DataNucleus代码里记录的。这两条消息说明了时间都花在了数据库操作上。
上面的日志看到的Sentry日志里的指标值显示create/drop数据库并不慢的原因是因为这些操作是HMS的canary测试操作。这些操作因为没有owner所以不需要Sentry给它们赋予owner权限所以不用记录到数据库。而从Impala里发起的create/drop table操作都需要修改owner权限，而这些修改是在数据库上完成的，所以花费的时间比较长。
以上发现都表明这个问题的根源应该在Sentry的后台数据库上，后续将测试环境的Sentry元数据dump出来提供给了Support，Support在拿到Sentry的库后重现了DDL慢的问题，在测试集群的Sentry服务里配置项OWNER Privileges for Sentry Policy Database Objects（sentry.db.policy.store.owner.as.privilege）设置成了“ALL privileges with GRANT”。这意味着每当一个用户创建一个表的时候sentry都要往数据库里为这个用户添加这个表的owner权限。反之，删除一个表的时候sentry也要删除用户在这个表上的owner权限。在数据库dump里查看到用户bdp_usr有4000多条owner权限。在把sentry.db.policy.store.owner.as.privilege设置成NONE之后建表不到1秒钟即可完成。
问题处理结论
修改Sentry服务的配置项sentry.db.policy.store.owner.as.privilege为NONE，修改方式如下：
修改完成后保存配置按照提示重启服务即可。
总结
1.Owner权限是Sentry里的权限。这个功能打开之后，创建数据库或者表的用户自动获得这个对象上的owner权限。但是在HDFS上对应的目录还是属于hive用户。
2.Owner权限只存在于Sentry数据库中并被Sentry客户端在调用Sentry API的时候使用。与HDFS等都无关。在没有开启这个功能的情况下Sentry不会在创建数据库或者表的时候添加owner权限。也就是说对于新建的表或者数据库的owner都是空。Sentry通过判断其他权限比如CREATE/ALL/SELECT等判断用户是否可以对某个对象执行特定的操作。而在开启了这个功能之后，用户在建表或者数据库的时候自动获得owner权限，不需要额外授权就可以访问他自己创建的对象。