如何找到Hive提交的SQL相对应的Yarn程序的applicationId

最近的工作是利用Hive做数据仓库的ETL转换，大致方式是将ETL转换逻辑写在一个hsql文件中，脚本当中都是简单的SQL语句，不包含判断、循环等存储过程中才有的写法，仅仅支持一些简单的变量替换，比如当前账期等。然后通过一个通用的shell脚本来执行hsql文件。该脚本是主要是调用了hive -f 来执行hsql文件中的SQL语句的，当然hive命令会通过--hivevar选项定义变量将当前账期等数值传进去供SQL使用。

简单说下环境信息，目前使用的大数据平台版本是HDP 3.1.0.0-78，Hive版本是3.1.0，而Tez版本是0.9.1。Hive 3.X系列的新特性主要包括：

执行引擎不再支持mr，取而代之的是tez或者spark（在HDP平台默认是tez）；

不再支持胖客户端Hive CLI，被beeline取代（目前通过hive命令执行sql实际还是调用的beeline去连接hiveserver2服务）；

默认建表支持ACID语义；

支持LLAP，即Live Long and Process，相当于内存计算，极大地优化了性能（该特性实际从Hive 2.X开始支持）；

言归正传，回到本文的主题，比如Hive在运行过程中报错了，我们需要在Yarn上找到对应的application的日志以便定位问题，前提是需要知道Yarn程序对应的applicationId，但是beeline的输出信息中是没有applicationId的，那么如何找到Hive提交的SQL相对应的Yarn程序的applicationId呢？主要有以下几个步骤：

我们通过shell脚本提交hsql文件时实际是通过beeline向hiveserver2服务提交hsql文件中的SQL语句，我们的shell脚本会将beeline的屏幕输出信息同时重定向到日志文件中，这个就是我们的第一个步骤的日志。我们找到这个日志文件，在其中搜索关键字"Completed executing command"，可以得到queryId，其中每个SQL语句对应1个queryId，因为我们的hsql脚本中有4个SQL语句，所以搜索出来的信息如下：

INFO : Completed executing command(queryId=hive_20200502095437_1e9bf52d-e590-4519-a6e1-9e2e4ae91158); Time taken: 0.755 seconds
INFO : Completed executing command(queryId=hive_20200502095816_888a7dba-4403-439d-a3a7-f6cdc280c18a); Time taken: 52.929 seconds
INFO : Completed executing command(queryId=hive_20200502100121_5752f019-a6e2-463c-b413-a80bbe518a5c); Time taken: 52.66 seconds
INFO : Completed executing command(queryId=hive_20200502100428_9d4b8955-b84c-40be-a605-9ce19b4b7773); Time taken: 26.463 seconds

找到对应的hiveserver2服务在哪台机器上。由于beeline是通过zookeeper随机连接一个hiveserver2服务，所以从上一步的日志中可以看到连接的是哪台机器上的hiveserver2服务。然后登录到该台主机，通过netstat和ps命令找到对应的hiveserver2进程，从ps命令输出的进程信息对应的命令行中，我们可以找到下面的参数。

-Dhive.log.dir=/var/log/hive -Dhive.log.file=hiveserver2.log

上面的参数说明了hiveserver2服务对应的日志名称和路径。这样我们就可以找到hiveserver2服务对应的日志，这是我们第二个步骤的日志。从这个日志里通过搜索关键字"callerId="，用上一步得到的真实的queryId替换（比如搜索"callerId=hive_20200502095816_888a7dba-4403-439d-a3a7-f6cdc280c18a"）。我们将上面的4个queryId逐一用前述的关键字搜索，得到信息如下：

2020-05-02T10:00:30,440 INFO [Thread-536694]: client.TezClient (:()) - Submitting dag to TezSession, sessionName=HIVE-315802e2-f6e4-499d-a707-4d3057180abd, applicationId=application_1588062934554_53656, dagName=create temporary table ngdwt.rpt_to_etc_...t (Stage-1), callerContext={ context=HIVE, callerType=HIVE_QUERY_ID, callerId=hive_20200502095816_888a7dba-4403-439d-a3a7-f6cdc280c18a }

2020-05-02T10:00:57,229 INFO [Thread-536729]: client.TezClient (:()) - Submitting dag to TezSession, sessionName=HIVE-315802e2-f6e4-499d-a707-4d3057180abd, applicationId=application_1588062934554_53656, dagName=create temporary table ngdwt.rpt_to_etc_...t (Stage-4), callerContext={ context=HIVE, callerType=HIVE_QUERY_ID, callerId=hive_20200502095816_888a7dba-4403-439d-a3a7-f6cdc280c18a }

2020-05-02T10:03:22,043 INFO [Thread-537002]: client.TezClient (:()) - Submitting dag to TezSession, sessionName=HIVE-315802e2-f6e4-499d-a707-4d3057180abd, applicationId=application_1588062934554_53656, dagName=create temporary tabl...ov_in,a.statis_date (Stage-1), callerContext={ context=HIVE, callerType=HIVE_QUERY_ID, callerId=hive_20200502100121_5752f019-a6e2-463c-b413-a80bbe518a5c }

2020-05-02T10:07:39,627 INFO [Thread-537495]: client.TezClient (:()) - Submitting dag to TezSession, sessionName=HIVE-315802e2-f6e4-499d-a707-4d3057180abd, applicationId=application_1588062934554_53656, dagName=insert into ngdwt.rpt_to_etc_rece_d(re...t (Stage-1), callerContext={ context=HIVE, callerType=HIVE_QUERY_ID, callerId=hive_20200502100428_9d4b8955-b84c-40be-a605-9ce19b4b7773 }

可以看到第1个queryId用关键字"callerId="去搜索没有搜到信息，因为对应的第一个sql语句是ddl语句，不会向yarn提交程序（但是仅用""去搜索还是能搜到信息），后面第二个queryId搜索出来有2行，其他queryId只有1行。

可以看到这些queryId(hive命令输出信息)或者callerId(hiveserver2.log日志信息)对应的hive session和yarn application是同一个：
sessionName=HIVE-315802e2-f6e4-499d-a707-4d3057180abd
applicationId=application_1588062934554_53656

也就是说，同一个hsql文件中的不同SQL语句对应的是同一个hive session以及同一个yarn application.

来看下yarn web管理页面中该application的截图。

 

 

可以看到上面页面中的Name跟hiveserver2.log中的sessionName一致，Application Tags跟hiveserver2.log中的callerId（或者hive命令屏幕输出信息中的queryId）一致。

而yarn ui2中的程序信息如下：

  

找到了applicationId就比较好办了，可以通过下面的命令将yarn日志从hdfs下载到本地（待yarn程序执行完毕）
yarn logs -applicationId application_1588062934554_53656 > application_1588062934554_53656.log

然后可以对application_1588062934554_53656.log做进一步的分析。
比如用关键字"Container: container_"搜索并去重排序后得到9个container的信息：
Container: container_e46_1588062934554_53656_01_000001 on hadoop19_45454_1588385301489
Container: container_e46_1588062934554_53656_01_000002 on hadoop31_45454_1588385300882
Container: container_e46_1588062934554_53656_01_000003 on hadoop40_45454_1588385301059
Container: container_e46_1588062934554_53656_01_000004 on hadoop27_45454_1588385300739
Container: container_e46_1588062934554_53656_01_000006 on hadoop36_45454_1588385301268
Container: container_e46_1588062934554_53656_01_000007 on hadoop57_45454_1588385301076
Container: container_e46_1588062934554_53656_01_000008 on hadoop22_45454_1588385301501
Container: container_e46_1588062934554_53656_01_000009 on hadoop31_45454_1588385300882
Container: container_e46_1588062934554_53656_01_000010 on hadoop21_45454_1588385301473

上面是该application对用的所有container.

 

或者用关键字"Assigning container to task:"搜索得到任务分配信息，其中container_e46_1588062934554_53656_01_000001因为是applicationmaster没有任务分配信息，其他8个container都有任务分配信息，其中container_e46_1588062934554_53656_01_000008和container_e46_1588062934554_53656_01_000009有2条记录，但attempt不同，表示这2个container里的任务之前有失败的，分别进行了2次尝试。为了简洁起见，这里仅列出搜索出来的第一条记录：

2020-05-01 22:00:40,603 [INFO] [DelayedContainerManager] |rm.YarnTaskSchedulerService|: Assigning container to task: containerId=container_e46_1588062934554_53656_01_000002, task=attempt_1588062934554_53656_1_00_000000_0, containerHost=hadoop31:45454, containerPriority= 11, containerResources=, localityMatchType=RackLocal, matchedLocation=/default-rack, honorLocalityFlags=false, reusedContainer=false, delayedContainers=3

因为现在的Hive的执行引擎不再是mr，而是改成了tez，目前我对tez并不太熟悉，只是理解它为mr的升级版，在原来的map/reduce操作上增加了DAG，不同job之间的数据传递不必写到HDFS，而是类似数据流的方式，减少了中间环节，提升了效率。对于一个Tez程序，类似于MR程序的MRAppMaster和YarnChild进程，它会产生DAGAppMaster和TezChild进程，前者是master负责管理整个程序以及申请资源，后者是slave，负责执行具体的计算任务。