|0810-invalidate metadata异常分析

作者：周鹏辉
文档编写目的
本文描述了对CDH集群Impala在执行invalidate metadata ，出现“Error communicating with impalad: TSocket read 0 bytes”异常的分析过程和解决方法。

测试环境

CDH和CM版本：CDH5.15.1和CM5.15.1
Impala版本：2.12.0
集群启用Kerbeos+OpenLDAP+Sentry
异常描述
1.集群的Impala之前没有怎么使用，今天准备使用的时候，发现Hive中的很多Database和table信息没有同步，于是执行invalidate metadata命令刷新全库和表的元数据。命令执行几分钟后发现client返回“Error communicating with impalad: TSocket read 0 bytes”异常。而执行show databases、 use database 、 select count(0) from table命令没有任何问题。具体报错如下图所示.

本文插图

异常分析
1.从profile可以看到这个query 运行在coordinator: cmsdn008 ，而且invalidate metadata执行了差不多一天的时间才得到返回。

本文插图

Start Time: 2020-07-30 09:21:33.391667000 End Time: 2020-07-31 09:09:58.217504000 Query Type: DDL Query State: FINISHED Query Status: OK Sql Statement: invalidate metadata
2. 从cmsdn008的impalad和cmsmaster004 的catalog日志中可以看到， invalidate metadata在Catalog中卡住了，但是没有看到任何的error出现。
1）Impalad 日志：
I0730 09:21:33.391970 205126 Frontend.java:962] Analyzing query: invalidate metadata I0731 09:08:56.366413 205126 impala-server.cc:1456] Waiting for minimum catalog object version: 307415 current version: 217571 I0731 09:09:58.084523 205126 impala-server.cc:1467] Updated minimum catalog object version: 307415
2）Catalog日志：
I0730 09:21:33.711993 201492 CatalogServiceCatalog.java:1102] Invalidating all metadata. Version: 307415 I0731 09:08:42.864406 201492 CatalogServiceCatalog.java:914] Loading native functions for database: 258755_121
3.由于Catalog中暂时看不到更多有用信息，于是打开catalog的jstack后收集更多堆栈信息，登入CM->Configurations->Impala->Stacks Collection Enabled 打开选项，打开catalog的jstack ，无需重启服务。

本文插图

4.再次执行invalidate metadata语句，等待30分钟后，查看coordinator日志、catalog日志、以及catalog日志目录下的stack目录。
发现这个invalidate metadata query在catalog中被lock了， lock住的线程是在请求sentry权限的地方。
catalog日志目录下的stack目录的catalogd.INFO.stacks看到如下信息：
at org.apache.sentry.provider.db.service.thrift.SentryPolicyService$Client.recv_list_sentry_roles_by_group(SentryPolicyService.java:278) at org.apache.sentry.provider.db.service.thrift.SentryPolicyService$Client.list_sentry_roles_by_group(SentryPolicyService.java:265) at org.apache.sentry.provider.db.service.thrift.SentryPolicyServiceClientDefaultImpl.listRolesByGroupName(SentryPolicyServiceClientDefaultImpl.java:160) at org.apache.sentry.provider.db.service.thrift.SentryPolicyServiceClientDefaultImpl.listRoles(SentryPolicyServiceClientDefaultImpl.java:207)

本文插图

5．查看当前Sentry JVM 的内存配置。具体方法如下：
CM-Sentry->instances->分别进入2台sentry服务->Resident Memory->7天的图表

本文插图

本文插图

当前Sentry的JVM配置为8G ，虽然上传的Sentry内存图表上没有显示出当前JVM 不够的情况，但是根据官方文档的建议，当前Hive Metastore中的对象数量5000000+ ，于是尝试把Sentry内存增大到16GB 。具体参考如下官方链接：
https://docs.cloudera.com/documentation/enterprise/5-15-x/topics/sg_sentry_before_you_install.html
修改Sentry JVM方法如下：
CM-Sentry->instances-> Configuration->Java Heap Size of Sentry Server in Bytes 。重启sentry后

本文插图

再次执行invalidate metadata ，还是出现相同“Error communicating with impalad: TSocket read 0 bytes”异常。

本文插图

6.通过以上分析，现在我们已经能够确定的是catalogd里的线程需要很长的时间（几乎一整天）才能从Sentry读取完整的权限信息。而catalogd同一时间只能有一个线程执行这个操作。所有的invalidate metadata命令都堵在这个线程上。如果同时运行多个invalidate metadata则后面的invalidate metadata所需等待时间会更长。 Catalogd里的这个线程是通过一个循环一次读取所有的角色的所有权限。这个线程慢的原因可能有：
1）Sentry进程慢
2）catalogd进程慢；
3）权限记录数太多；
通过提升了Sentry的堆空间设置还是没有效果。查看sentry日志，虽然有的时候list-privileges-by-role操作所需时间会超过2秒，但是大部分时间都在几十毫秒之内结束。因此我们应该可以排除原因1）。所以我们重点排查原因2）和3）。
对于原因2）：查看catalogd节点的CPU负载图表，以及catalogd堆空间使用情况。因为Catalogd需要分配堆空间内存接收、解析和存储权限记录。如果catalogd的堆空间不足的话很有可能会导致这个问题。
Catalog CPU负载图表：

本文插图

本文插图

Catalogd堆空间使用情况：

本文插图

本文插图

Catalogd堆空间配置：

本文插图

以上图表显示Catalog负载和堆空间都正常。
对于原因3），通过分析Hive Metastore中的数量对象，在Sentry数据库里执行select count(0)查看以下几个表里的记录数，发现sentry的ROLES有3476个， PRIVILEGE有7071个，初步看起来非常像遇到了一个已知的Impala的问题IMPALA-8444[1] ，过多的ROLES数量和每个ROLE的权限数量都会影响Impala性能。
https://issues.apache.org/jira/browse/IMPALA-8444
7.进入集群的Hive Metastore ，执行如下命令查看相关ROLES信息，集群确实存在很多GROUP 、ROLES、PRIVILEGE 。
use hive; select count(0) from DBS; select count(0) from TBLS; select count(0) from PARTITIONS; select count(0) from COLUMNS_V2; use sentry; select count(0) from SENTRY_DB_PRIVILEGE; select count(0) from SENTRY_GROUP; select count(0) from SENTRY_ROLE; select count(0) from SENTRY_ROLE_DB_PRIVILEGE_MAP; select count(0) from AUTHZ_PATH; select count(0) from AUTHZ_PATHS_MAPPING;

本文插图

本文插图

8.结合此环境和以往catalogd日志看， 8月7日执行的“invalidate metadata”一共用了38分钟[1] ， 6月28日的时候一次“invalidate metadata”还只需要1分钟左右的时间，甚至7月3日还有一次只花了两分钟[2] 。而在这时间段内，这套集群并没有发生权限记录大量增加、产生了大量的数据库/表等记录。而IMPALA-8444 的bug是在权限多的时候coordiantor从本地缓存里读取权限变慢。而我们的问题是发生在catalogd里刷新Sentry权限的线程里的,所以也可以排除IMPALA-8444的 bug 。
[1]：
I0807 14:55:31.398396 42252 CatalogServiceCatalog.java:1102] Invalidating all metadata. Version: 325110 I0807 15:33:12.382388 42252 CatalogServiceCatalog.java:914] Loading native functions for database: 258755_121 ... I0807 15:33:25.740027 42252 CatalogServiceCatalog.java:1170] Invalidated all metadata.
【|0810-invalidate metadata异常分析】[2]：
I0703 17:35:36.040768 187180 CatalogServiceCatalog.java:1102] Invalidating all metadata. Version: 3630496 I0703 17:36:38.161551 187180 CatalogServiceCatalog.java:1170] Invalidated all metadata.
9. 通过进一步查看源码， Catalogd里有一个线程池用来从Sentry刷新权限。默认情况下catalogd每隔60秒向这个线程池发起一个刷新权限的请求。但是这个线程池里只有一个线程。如果这个线程超过60秒才结束的话，新的请求就会等待。这样一来有可能造成请求堆积。等到invalidate metadata发起这个请求的时候前面已经有很多排队的请求所以会等待很长的时间。这也是为什么从日志里看到刚启动catalogd的时候invalidate metadata很快，越往后面等待的时间就越长。具体源码分析如下：
1）Catalogd里刷新Sentry权限的代码可以在GitHub上找到：
https://github.com/cloudera/Impala/blob/cdh5-2.12.0_5.15.1/fe/src/main/java/org/apache/impala/util/SentryProxy.java

本文插图

2）我们可以看到用于刷新Sentry权限的线程池里只有一个线程：
62 // Used to periodically poll the Sentry Service and updates the catalog with any 63 // changes. 64 private final ScheduledExecutorService policyReader_ = 65 Executors.newScheduledThreadPool(1);

本文插图

3）下面是这个线程池启动的代码：
90 policyReader_.scheduleAtFixedRate(new PolicyReader(false), 0, 91 BackendConfig.INSTANCE.getSentryCatalogPollingFrequency(), 92 TimeUnit.SECONDS);

本文插图

4）scheduleAtFixedRate的意思是按照固定的时间间隔执行任务请求，具体参考如下链接：
https://docs.oracle.com/javase/7/docs/api/java/util/concurrent/ScheduledExecutorService.html#scheduleAtFixedRate(java.lang.Runnable,%20long,%20long,%20java.util.concurrent.TimeUnit)

本文插图

scheduleAtFixedRate的第三个参数
BackendConfig.INSTANCE.getSentryCatalogPollingFrequency()是执行任务的间隔时间。这个时间取的就是sentry_catalog_polling_frequency_s：
https://docs.oracle.com/javase/7/docs/api/java/util/concurrent/ScheduledExecutorService.html#scheduleAtFixedRate(java.lang.Runnable,%20long,%20long,%20java.util.concurrent.TimeUnit)

本文插图

5）关于scheduleAtFixedRate， Java的文档明确指出“If any execution of this task takes longer than its period, then subsequent executions may start late, but will not concurrently execute.” 。也就是说，如果每次在sentry_catalog_polling_frequency_s之内都不能读取完Sentry权限，那么就会出现这个线程池上的请求堆积。

本文插图

6.而之前在执行invalidate metadata的时候是堵在了第352行：
350 public void refresh(boolean resetVersions) throws ImpalaRuntimeException { 351 try { 352 policyReader_.submit(new PolicyReader(resetVersions)).get();

本文插图

这个refresh方法是由invalidate metadata触发的。如果之前堆积的请求没有被处理完，第352行就不会返回。堆积的请求数越多， invalidate metadata等待的时间也就越长。这也与我之前在catalogd的日志里看到的情况相符。
异常解决
1.通过对源码的分析，这个问题应该是catalogd里刷新Sentry权限的线程一次执行时间超过60秒从而导致请求堆积造成的。修改sentry_catalog_polling_frequency_s延长catalog刷新Sentry权限的间隔时间应该可以解决这个问题。延长catalogd刷新Sentry权限的间隔时间可以通过如下方式设置：
1）打开CM ，跳转到Clusters -> Impala service -> Configuration页面；
2）搜索Catalog Server Command Line Argument Advanced Configuration Snippet (Safety Valve) ，中文是“Catalog Server命令行参数安全阀”
3）添加如下一行设置间隔时间（单位为秒）：
--sentry_catalog_polling_frequency_s=120

本文插图

4）保存设置，重启服务。
2.修改sentry_catalog_polling_frequency_s并重启catalogd之后多次执行invalidate metadata都能够在两分钟左右结束[1]

本文插图

本文插图

[1]
I0812 11:41:35.292168 37717 CatalogServiceCatalog.java:1102] Invalidating all metadata. Version: 0 I0812 11:43:54.214588 37717 CatalogServiceCatalog.java:1170] Invalidated all metadata. I0812 14:56:17.126447 165882 CatalogServiceCatalog.java:1102] Invalidating all metadata. Version: 117246 I0812 14:59:34.897882 165882 CatalogServiceCatalog.java:1170] Invalidated all metadata. I0813 09:25:01.206566 166516 CatalogServiceCatalog.java:1102] Invalidating all metadata. Version: 224016 I0813 09:26:27.922058 166516 CatalogServiceCatalog.java:1170] Invalidated all metadata. I0813 09:34:53.493798 166516 CatalogServiceCatalog.java:1102] Invalidating all metadata. Version: 331262 I0813 09:36:25.652170 166516 CatalogServiceCatalog.java:1170] Invalidated all metadata. I0813 11:00:26.271862 229966 CatalogServiceCatalog.java:1102] Invalidating all metadata. Version: 438472 I0813 11:02:11.911428 229966 CatalogServiceCatalog.java:1170] Invalidated all metadata. I0813 11:04:42.961439 232969 CatalogServiceCatalog.java:1102] Invalidating all metadata. Version: 545797 I0813 11:06:14.652442 232969 CatalogServiceCatalog.java:1170] Invalidated all metadata.
问题总结
1.这个问题是因为Sentry里面ROLES和权限过多， 3000多个roles和7000多个权限，导致Catalogd里一个线程池用来从Sentry刷新权限时候需要的时间超过默认的60s 。默认情况下Catalogd每隔60秒向这个线程池发起一个刷新权限的请求。但是这个线程池里只有一个线程。如果这个线程超过60秒才结束的话，新的请求就会等待。这样一来有可能造成请求堆积。等到invalidate metadata发起这个请求的时候前面已经有很多排队的请求，所以会等待很长的时间。 Catalogd里一个线程池用来从Sentry刷新权限时候需要的时间由参数sentry_catalog_polling_frequency_s控制，我们把默认的60s提高到120s ，延长刷新权限的时间来解决解决。如果还不行的话再稍微延长一些但是不要太长，否则Sentry的权限变化不能及时地反映到Impala里。此外Impala对role的数量并没有要求或者建议。所以增加catalog刷新Sentry权限的间隔时间是最好的方案。
2.从CDH5.15.1版本的日志和jstack里我们都看不出来一次刷新权限需要多少时间以及是否会有刷新权限的请求堆积。我们通过分析代码推断出这个可能的原因, 然后修改参数sentry_catalog_polling_frequency_s是否有用以及120秒是否足够。之前出现过一天多时间才执行完invalidate metadata,所以我们推测前面impala堆积了大量刷新权限的请求。但是在CDH 5.16里我们就可以看到如下一次刷新权限需要多少时间以及是否会有刷新权限的请求堆积.如下是CDH5.16.2的Catalogs 的catalogd.INFO日志里看到刷新权限的信息：
I0824 21:10:18.379863 17582 SentryProxy.java:145] Refreshing Sentry policy took 87ms I0824 21:10:18.396092 17582 SentryProxy.java:145] Refreshing Sentry policy took 16ms

本文插图

3. 最开始执行invalidate metadata客户端出现的是“Error communicating with impalad: TSocket read 0 bytes”'' ，是因为Catalog刷新Sentry权限需要的时间超过默认的60,导致操作请求堆积，从而造成没有数据交换。没有数据交换所以触发了客户端与coordinator之间的TCP超时。
总结
在问题初步排查过程中，怀疑过是如下两个疑似的已知bug导致，但是在查看和分析日志后都排除。这里列出来，以供参考。
1.IMPALA-7729：此bug说明Sentry不区分roles大小写而Impala区分大小写从而导致角色匹配不上从而invalidate metadata永远跑不出来。而我们的问题是因为catalogd从Sentry读取权限用的时间太长造成的。修复IMPALA-7729并不能解决这个问题。而且使用hive用户登入impala ，然后执行SHOW ROLES并没有看到大写的role name存在。
https://issues.apache.org/jira/browse/IMPALA-7729
2.IMPALA-8444: IMPALA-8444是在权限多的时候coordiantor从本地缓存里读取权限变慢。而我们的问题是发生在catalogd里的。所以也可以排除。 IMPALA-8444在CDH6中已经修改。
https://issues.apache.org/jira/browse/IMPALA-8444
3. Catalogd和Sentry的JVM是会影响Impala刷新权限等操作.
1) Catalogd的JVM空间设置可以通过计算每一个表的metadata大小[1]推断出合适的值:
[1]:
How to calculate each table's metadata cache usage: ? 5KB (table object) + num of partitions * 2kB + num of files * 750B + num of file_blocks * 300B ? plus incremental column stats ''num of columns * num of partitions * 400B'' ? Besides the metadata cache, catalog also needs some working memory (when reload a table, or generate delta update, etc.). This depends on how many tables being refreshed concurrently. I don't have number yet, but give at least 2-3x of your largest table or 30% of the whole metadata cache. This also depends on how many table being updated concurrently.
2) Sentry的JVM空间设置就不太好判断了。因为这与具体的权限数量、对象数量、HDFS目录名的长度都有关系。而且如果触发了full snapshot的话还与full snapshot的数量有关系。一般来说Sentry的元数据数据库dump越大，所需要的内存空间会越多。但是二者是什么关系不好量化.
2) Sentry的JVM空间设置就不太好判断了。因为这与具体的权限数量、对象数量、HDFS目录名的长度都有关系。而且如果触发了full snapshot的话还与full snapshot的数量有关系。一般来说Sentry的元数据数据库dump越大，所需要的内存空间会越多。但是二者是什么关系不好量化.4. Catalogd里通过一个线程池从Sentry刷新权限，这个线程是通过一个循环一次读取所有的角色的所有权限。这个线程慢的原因可能有：
1）权限记录数太多；
2）catalogd进程慢；
3）Sentry进程慢。