0810-invalidate metadata异常分析

作者：周鹏辉

本文描述了对CDH集群Impala在执行invalidatemetadata，出现“Errorcommunicatingwithimpalad:TSocketread0bytes”异常的分析过程和解决方法。

测试环境

CDH和CM版本：和

Impala版本：2.12.0

集群启用Kerbeos+OpenLDAP+Sentry

1.集群的Impala之前没有怎么使用，今天准备使用的时候，发现Hive中的很多Database和table信息没有同步，于是执行invalidatemetadata命令刷新全库和表的元数据。命令执行几分钟后发现client返回“Errorcommunicatingwithimpalad:TSocketread0bytes”异常。而执行showdatabases、usedatabase、selectcount(0)fromtable命令没有任何问题。具体报错如下图所示.

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

StartTime:2020-07-3009:21:33.391667000Time:2020-07-3109:09:58.217504000QueryType:DDLQueryState:FINISHEDQueryStatus:OKSqlStatement:invalidatemetadata

2.从cmsdn008的impalad和cmsmaster004的catalog日志中可以看到，invalidatemetadata在Catalog中卡住了，但是没有看到任何的error出现。

1）Impalad日志：

I073009:21:33.391970205126:962]Analyzingquery:invalidatemetadataI073109:08:56.366413205126:1456]Waitingforminimumcatalogobjectversion:307415currentversion:217571I073109:09:58.084523205126:1467]Updatedminimumcatalogobjectversion:307415

2）Catalog日志：

I073009:21:33.711993201492:1102]:307415I073109:08:42.864406201492:914]Loadingnativefunctionsfordatabase:258755_121

3.由于Catalog中暂时看不到更多有用信息，于是打开catalog的jstack后收集更多堆栈信息，登入CM-Configurations-Impala-StacksCollectionEnabled打开选项，打开catalog的jstack，无需重启服务。

4.再次执行invalidatemetadata语句，等待30分钟后，查看coordinator日志、catalog日志、以及catalog日志目录下的stack目录。

发现这个invalidatemetadataquery在catalog中被lock了，lock住的线程是在请求sentry权限的地方。

catalog日志目录下的stack目录的看到如下信息：

$_list_sentry_roles_by_group(:278)$_sentry_roles_by_group(:265)(:160)(:207)

5．查看当前SentryJVM的内存配置。具体方法如下：

CM-Sentry-instances-分别进入2台sentry服务-ResidentMemory-7天的图表

当前Sentry的JVM配置为8G，虽然上传的Sentry内存图表上没有显示出当前JVM不够的情况，但是根据官方文档的建议，当前HiveMetastore中的对象数量5000000+，于是尝试把Sentry内存增大到16GB。具体参考如下官方链接：

修改SentryJVM方法如下：

CM-Sentry-instances-Configuration-JavaHeapSizeofSentryServerinBytes。重启sentry后

再次执行invalidatemetadata，还是出现相同“Errorcommunicatingwithimpalad:TSocketread0bytes”异常。

6.通过以上分析，现在我们已经能够确定的是catalogd里的线程需要很长的时间（几乎一整天）才能从Sentry读取完整的权限信息。而catalogd同一时间只能有一个线程执行这个操作。所有的invalidatemetadata命令都堵在这个线程上。如果同时运行多个invalidatemetadata则后面的invalidatemetadata所需等待时间会更长。Catalogd里的这个线程是通过一个循环一次读取所有的角色的所有权限。这个线程慢的原因可能有：

1）Sentry进程慢

2）catalogd进程慢；

3）权限记录数太多；

通过提升了Sentry的堆空间设置还是没有效果。查看sentry日志，虽然有的时候list-privileges-by-role操作所需时间会超过2秒，但是大部分时间都在几十毫秒之内结束。因此我们应该可以排除原因1）。所以我们重点排查原因2）和3）。

对于原因2）：查看catalogd节点的CPU负载图表，以及catalogd堆空间使用情况。因为Catalogd需要分配堆空间内存接收、解析和存储权限记录。如果catalogd的堆空间不足的话很有可能会导致这个问题。

CatalogCPU负载图表：

Catalogd堆空间使用情况：

Catalogd堆空间配置：

以上图表显示Catalog负载和堆空间都正常。

对于原因3），通过分析HiveMetastore中的数量对象，在Sentry数据库里执行selectcount(0)查看以下几个表里的记录数，发现sentry的ROLES有3476个，PRIVILEGE有7071个，初步看起来非常像遇到了一个已知的Impala的问题IMPALA-8444[1]，过多的ROLES数量和每个ROLE的权限数量都会影响Impala性能。

7.进入集群的HiveMetastore，执行如下命令查看相关ROLES信息，集群确实存在很多GROUP、ROLES、PRIVILEGE。

usehive;selectcount(0)fromDBS;selectcount(0)fromTBLS;selectcount(0)fromPARTITIONS;selectcount(0)fromCOLUMNS_V2;usesentry;selectcount(0)fromSENTRY_DB_PRIVILEGE;selectcount(0)fromSENTRY_GROUP;selectcount(0)fromSENTRY_ROLE;selectcount(0)fromSENTRY_ROLE_DB_PRIVILEGE_MAP;selectcount(0)fromAUTHZ_PATH;selectcount(0)fromAUTHZ_PATHS_MAPPING;

8.结合此环境和以往catalogd日志看，8月7日执行的“invalidatemetadata”一共用了38分钟[1]，6月28日的时候一次“invalidatemetadata”还只需要1分钟左右的时间，甚至7月3日还有一次只花了两分钟[2]。而在这时间段内，这套集群并没有发生权限记录大量增加、产生了大量的数据库/表等记录。而IMPALA-8444的bug是在权限多的时候coordiantor从本地缓存里读取权限变慢。而我们的问题是发生在catalogd里刷新Sentry权限的线程里的,所以也可以排除IMPALA-8444的bug。

[1]：

I080714:55:31.39839642252:1102]:325110I080715:33:12.38238842252:914]Loadingnativefunctionsfordatabase:258755_121I080715:33:25.7:1170]Invalidatedallmetadata.

[2]：

I070317:35:36.040768187180:1102]:3630496I070317:36:38.161551187180:1170]Invalidatedallmetadata.

9.通过进一步查看源码，Catalogd里有一个线程池用来从Sentry刷新权限。默认情况下catalogd每隔60秒向这个线程池发起一个刷新权限的请求。但是这个线程池里只有一个线程。如果这个线程超过60秒才结束的话，新的请求就会等待。这样一来有可能造成请求堆积。等到invalidatemetadata发起这个请求的时候前面已经有很多排队的请求所以会等待很长的时间。这也是为什么从日志里看到刚启动catalogd的时候invalidatemetadata很快，越往后面等待的时间就越长。具体源码分析如下：

1）Catalogd里刷新Sentry权限的代码可以在GitHub上找到：

2）我们可以看到用于刷新Sentry权限的线程池里只有一个线程：

62//UsedtoperiodicallypolltheSentryServiceandupdatesthecatalogwithany63//_=65(1);

3）下面是这个线程池启动的代码：

90policyReader_.scheduleAtFixedRate(newPolicyReader(false),0,91(),92);

4）scheduleAtFixedRate的意思是按照固定的时间间隔执行任务请求，具体参考如下链接：

(,%20long,%20long,%20)

scheduleAtFixedRate的第三个参数

()是执行任务的间隔时间。这个时间取的就是sentry_catalog_polling_frequency_s：

(,%20long,%20long,%20)

5）关于scheduleAtFixedRate，Java的文档明确指出“Ifanyexecutionofthistasktakeslongerthanitsperiod,thensubsequentexecutionsmaystartlate,butwillnotconcurrentlyexecute.”。也就是说，如果每次在sentry_catalog_polling_frequency_s之内都不能读取完Sentry权限，那么就会出现这个线程池上的请求堆积。

6.而之前在执行invalidatemetadata的时候是堵在了第352行：

350publicvoidrefresh(booleanresetVersions)throwsImpalaRuntimeException{351try{352policyReader_.submit(newPolicyReader(resetVersions)).get();

这个refresh方法是由invalidatemetadata触发的。如果之前堆积的请求没有被处理完，第352行就不会返回。堆积的请求数越多，invalidatemetadata等待的时间也就越长。这也与我之前在catalogd的日志里看到的情况相符。

1.通过对源码的分析，这个问题应该是catalogd里刷新Sentry权限的线程一次执行时间超过60秒从而导致请求堆积造成的。修改sentry_catalog_polling_frequency_s延长catalog刷新Sentry权限的间隔时间应该可以解决这个问题。延长catalogd刷新Sentry权限的间隔时间可以通过如下方式设置：

1）打开CM，跳转到Clusters-Impalaservice-Configuration页面；

2）搜索CatalogServerCommandLineArgumentAdvancedConfigurationSnippet(SafetyValve)，中文是“CatalogServer命令行参数安全阀”

3）添加如下一行设置间隔时间（单位为秒）：

--sentry_catalog_polling_frequency_s=120

4）保存设置，重启服务。

2.修改sentry_catalog_polling_frequency_s并重启catalogd之后多次执行invalidatemetadata都能够在两分钟左右结束[1]

[1]

I081211:41:35.29216837717:1102]:0I081211:43:54.21458837717:1170]:56:17.126447165882:1102]:117246I081214:59:34.897882165882:1170]:25:01.206566166516:1102]:224016I081309:26:27.922058166516:1170]:34:53.493798166516:1102]:331262I081309:36:25.652170166516:1170]:00:26.271862229966:1102]:438472I081311:02:11.911428229966:1170]:04:42.961439232969:1102]:545797I081311:06:14.652442232969:1170]Invalidatedallmetadata.

1.这个问题是因为Sentry里面ROLES和权限过多，3000多个roles和7000多个权限，导致Catalogd里一个线程池用来从Sentry刷新权限时候需要的时间超过默认的60s。默认情况下Catalogd每隔60秒向这个线程池发起一个刷新权限的请求。但是这个线程池里只有一个线程。如果这个线程超过60秒才结束的话，新的请求就会等待。这样一来有可能造成请求堆积。等到invalidatemetadata发起这个请求的时候前面已经有很多排队的请求，所以会等待很长的时间。Catalogd里一个线程池用来从Sentry刷新权限时候需要的时间由参数sentry_catalog_polling_frequency_s控制，我们把默认的60s提高到120s，延长刷新权限的时间来解决解决。如果还不行的话再稍微延长一些但是不要太长，否则Sentry的权限变化不能及时地反映到Impala里。此外Impala对role的数量并没有要求或者建议。所以增加catalog刷新Sentry权限的间隔时间是最好的方案。

2.从版本的日志和jstack里我们都看不出来一次刷新权限需要多少时间以及是否会有刷新权限的请求堆积。我们通过分析代码推断出这个可能的原因,然后修改参数sentry_catalog_polling_frequency_s是否有用以及120秒是否足够。之前出现过一天多时间才执行完invalidatemetadata,所以我们推测前面impala堆积了大量刷新权限的请求。但是在里我们就可以看到如下一次刷新权限需要多少时间以及是否会有刷新权限的请求堆积.如下是的Catalogs的日志里看到刷新权限的信息：

I082421:10:18.37986317582:145]RefreshingSentrypolicytook87msI082421:10:18.39609217582:145]RefreshingSentrypolicytook16ms

3.最开始执行invalidatemetadata客户端出现的是“Errorcommunicatingwithimpalad:TSocketread0bytes”"，是因为Catalog刷新Sentry权限需要的时间超过默认的60,导致操作请求堆积，从而造成没有数据交换。没有数据交换所以触发了客户端与coordinator之间的TCP超时。

总结

在问题初步排查过程中，怀疑过是如下两个疑似的已知bug导致，但是在查看和分析日志后都排除。这里列出来，以供参考。

1.IMPALA-7729：此bug说明Sentry不区分roles大小写而Impala区分大小写从而导致角色匹配不上从而invalidatemetadata永远跑不出来。而我们的问题是因为catalogd从Sentry读取权限用的时间太长造成的。修复IMPALA-7729并不能解决这个问题。而且使用hive用户登入impala，然后执行SHOWROLES并没有看到大写的rolename存在。

2.IMPALA-8444:IMPALA-8444是在权限多的时候coordiantor从本地缓存里读取权限变慢。而我们的问题是发生在catalogd里的。所以也可以排除。IMPALA-8444在CDH6中已经修改。

3.Catalogd和Sentry的JVM是会影响Impala刷新权限等操作.

1)Catalogd的JVM空间设置可以通过计算每一个表的metadata大小[1]推断出合适的值:

[1]:

Howtocalculateeachtable'smetadatacacheusage:•5KB(tableobject)+numofpartitions*2kB+numoffiles*750B+numoffile_blocks*300B•plusincrementalcolumnstats"numofcolumns*numofpartitions*400B"•Besidesthemetadatacache,catalogalsoneedssomeworkingmemory(whenreloadatable,orgeneratedeltaupdate,etc.).'thavenumberyet,butgiveatleast2-3xofyourlargesttableor30%

2)Sentry的JVM空间设置就不太好判断了。因为这与具体的权限数量、对象数量、HDFS目录名的长度都有关系。而且如果触发了fullsnapshot的话还与fullsnapshot的数量有关系。一般来说Sentry的元数据数据库dump越大，所需要的内存空间会越多。但是二者是什么关系不好量化.

2)Sentry的JVM空间设置就不太好判断了。因为这与具体的权限数量、对象数量、HDFS目录名的长度都有关系。而且如果触发了fullsnapshot的话还与fullsnapshot的数量有关系。一般来说Sentry的元数据数据库dump越大，所需要的内存空间会越多。但是二者是什么关系不好量化.4.Catalogd里通过一个线程池从Sentry刷新权限，这个线程是通过一个循环一次读取所有的角色的所有权限。这个线程慢的原因可能有：

1）权限记录数太多；

2）catalogd进程慢；

3）Sentry进程慢。