Spark CallerContext源码分析与远程debug

最近为了治理集群中部分Spark任务造成的小文件过多，从而导致机器IO数和使用率过高的现象，看到社区中的issue：SPARK-16757，提到了Spark在yarn模式下启动Client、ApplicationMaster、Task等时，会通过反射调用注册Hadoop那边的CallerContext，从而在rm-audit.log中额外打印提交的Spark Client信息；并在hdfs-audit.log中除操作类型和涉及HDFS目录外，额外打印Spark类型、application号、stage号、task号等信息，便于更快定位到是什么任务写入什么HDFS目录导致的，如下图所示：

一、相关源码机制

1.1、Spark源码

在Client.scala中，可以看到在提交application时，会new一个CallerContext对象并调用反射机制进行Hadoop那边的CallerContext注册，如下图所示：

在ApplicationMaster.scala的runImpl()和Task.scala的run()中也是类似的，如下图所示：

进入CallerContext定义的地方，在Utils.scala中，可以看到审计日志中的CallerContext是在这里拼接字符串生成的，如下图所示：

上面Client、ApplicationMaster和Task中，new CallerContext之后还调用了setCurrentContext()，该函数的定义也在Utils.scala中，如下图所示：

可以看到就是这里使用了反射机制，调用Hadoop那边的CallerContext函数。再看看这个反射调用成立的条件，上面的if条件中的CallerContext.callerContextSupported，如下图所示：

可以看到这里会从Configuration对象中获取参数hadoop.caller.context.enabled的值，如果它为true并且反射机制可以找到Hadoop中的CallerContext类，就返回true。所以该参数的值是从conf传入的，看看它是如何形成的，如下图所示：

可以看到conf对象是从newConfiguration()函数中产生的，如下图所示：

也就是说虽然这个参数是Hadoop方面的参数，但也是可以在spark的配置中配置的，看下SparkHadoopUtil.newConfiguration()的实现：

这里还调用了appendS3AndSparkHadoopConfigurations()函数，从函数字面意思已经知道Hadoop的一些参数是在里面加入的了，来看这个函数里的实现：

除了可以设置亚马逊云s3的一些参数外，后面调用了appendSparkHadoopConfigs()函数，最终就是这个函数里面可以通过Spark设置Hadoop中的参数，可以看到必须加上“spark.hadoop.”前缀来传参，因为appendSparkHadoopConfigs()的实现中会读取这个前缀并用substring()函数截掉，只保留后面的内容。因此为了把hadoop.caller.context.enabled设置为true，需要传入spark.hadoop.hadoop.caller.context.enabled。

1.2、Hadoop源码

HDFS写入文件完成会调用completeFile()函数，里面会调用logAuditEvent()函数，如下图所示：

该logAuditEvent()会调用同名不同参的logAuditEvent()方法，如下图所示：

可以看到，这里同样会再调用一层同名重载函数，再看看这个重载logAuditEvent()的实现：

好家伙，里面还有一层同名函数调用，会遍历配置文件中指定的HdfsAuditLogger，调用这些Logger的logAuditEvent()。HDFS的审计日志写入在没有额外配置的情况下，默认会调用FSNamesystem.java中的DefaultAuditLogger类（可参考：https://cloud.tencent.com/developer/article/1357831），它也是HdfsAuditLogger这个抽象类的继承子类。在DefaultAuditLogger中的logAuditEvent()函数中，终于看到了最终的日志内容字符串拼接，如下所示：

我们需要的CallerContext信息在下面部分，如下所示：

可以看到这里也有个条件判断，需要isCallerContextEnabled为true并且传给它的CallerContext不为空，才会拼接“callerContext=”的这部分内容。来看看isCallerContextEnabled为true需要什么，如下图所示：

也就是说它会去找Hadoop配置里的参数值，看变量名的字面意思已经猜到是什么了，点过去看看：

果然就是hadoop.caller.context.enabled，默认值为false。所以默认hdfs-audit.log中只会显示到“proto=”部分的内容，后面的“callerContext=”内容默认不会写进去。也要把它设置为true才行。

二、远程debug

对issue和相关源码的原理大致了解清楚后，就知道要加什么样的参数、呈现出来的日志内容大概会是什么样了。所以先来远程debug一下Client端。

2.1、Client端

在IDEA的“Run”->“Edit Configurations”菜单中，点击左上角的加号添加“Remote JVM Debug”，然后写上安装好Spark目录的客户端机器的IP、调试端口，选择默认的Attach模式就好，如下图所示：

保存debug设置后，要在Spark源码中自己理解的重点位置处加上断点，在上面第一节源码解析时就已经加上了。

然后登录远程Spark客户端机器，用如下命令启动SparkSQL任务、加上CallerContext参数和debug参数：

spark-sql --master yarn --deploy-mode client -f devGroupBy.sql \
--conf spark.hadoop.hadoop.caller.context.enabled=true \
--driver-java-options "-agentlib:jdwp=transport=dt_socket,server=y,suspend=y,address=5010"

因为任务以yarn-client模式提交，driver就在客户端提交机器上，所以是在driver的JVM参数中加入debug参数，这里“driver-java-options”后面的一串参数就是从上面IDEA的debug配置命令一栏复制出来的，但是要注意把“suspend”改为y，否则远程driver进程不会暂停下来监听本地IDEA的attach请求。

用上面命令行启动SparkSQL任务后，会看到该任务在监听5010端口上的debug连接，如下所示：

这时去IDEA界面上方找到debug选项按钮，选择刚才配好的客户端远程debug设置，并点击右侧的小虫子按钮，启动远程debug，如下所示：

这样IDEA会去attach远程客户端的5010端口，debug连接会建立并弹出debug菜单栏，如下图所示：

然后远程机器上的SparkSQL任务就开始运行了，在appendSparkHadoopConfigs()处会接收到命令行--conf中传入的参数，如下图所示：

执行到Client.scala处的断点也会暂停，可以用左下角红框的“step over”按钮接着执行下一步，如下图所示：

这样会执行到Utils.scala中创建CallerContext的逻辑处，因为是Client端才提交application，所以还不会有stage号、task号等，如下图所示：

一路点击Step Over按钮下去，可以看到prepareContext()函数中，针对Client端的CallerContext字符串拼接好了，如下图所示：

接着Step Over下去，会到达setCurrentContext()处的if条件判断与反射调用的位置，可以用左下角debug工具栏中红框处的计算器来计算一下if条件判断的值，肯定为true，如下图所示：

而且也可以看到通过反射调用了Hadoop那边的CallerContext相关方法。所以最终在rm-audit.log中，是可以看到该CallerContext的信息的，这里用了之前调试的截图，如下所示：

2.2、ApplicationMaster端

因为是yarn上运行，ApplicationMaster在另一台机器上，所以不能在客户端提交机上debug，需要先启动SparkSQL任务，看AM临时分配在哪台机器上，然后临时修改IDEA中debug配置里的IP后，再进行attach连接。远程调试AM需要在任务提交命令行中加另一个参数，如下所示：

spark-sql --master yarn --deploy-mode client -f devGroupBy.sql \
--conf spark.hadoop.hadoop.caller.context.enabled=true \
--conf spark.yarn.am.extraJavaOptions="-agentlib:jdwp=transport=dt_socket,server=y,suspend=y,address=5010"

提交任务后，根据driver日志中提到的applicathon号，立刻去yarn ui上查看该application的AM在哪台机器上，先搜到自己的application：

然后点击左侧红框的application号链接，就会进入到该application的综合信息界面，最下方有Attempt ID那一栏，其中有一个叫“Node”的列，里面显示的IP或域名就是AM所在的机器，如下图所示：

知道AM所在机器后，马上去IDEA的debug设置菜单里新建一个debug配置，填上该机器的IP或域名，如下图所示：

保存后立刻选择新设好的AM debug配置，然后点击启动debug按钮：

然后就同样进入到了和上面Client端debug中类似的执行流程，最后产生的CallerContext拼接字符串是下面这个样子的：

2.3、Executor端

提交SparkSQL任务时，需要加上针对Executor的JVM调试参数，如下所示：

spark-sql --master yarn --deploy-mode client -f devGroupBy.sql \
--conf spark.hadoop.hadoop.caller.context.enabled=true \
--conf spark.executor.extraJavaOptions="-agentlib:jdwp=transport=dt_socket,server=y,suspend=y,address=5010"

因为众多Task也运行在yarn集群内的其他机器上，所以也需要临时看一下Executor被分配到了哪些机器上。任务启动且在日志中看到application号后，去对应的spark ui页面，在“Executors”菜单界面里的“Executor ID”那一列可以看到有哪些Executor，如下图所示：

随便找一个Executor的IP或域名，还和上面2.2节中ApplicationMaster调试时那样，在IDEA的debug配置里修改一下机器地址，然后开启debug。可以看到Executor端生成的关于Task的CallerContext是下图这个样子的，包含了Job ID、Stage ID与Stage attempt ID、Task ID与Task attempt ID等：

三、遇到的意外

从上面的debug结果来看，无论是从Client、ApplicationMaster还是Task层面，都成功识别到了hadoop.caller.context.enabled这个参数，并调用反射向Hadoop注册CallerContext。照理说hdfs-audit.log也应该会出现issue中提到的CallerContext相关内容，但是任务执行结束后并没有搜到。经过定位后，发现因为我们对HDFS源码进行了修改定制，使用了另一个版本的Hadoop，并没有和yarn的Hadoop在一起，所以HDFS实际没有收到Spark传递的spark.hadoop.hadoop.caller.context.enabled参数。

在HDFS所在的另一个Hadoop目录中的core-site.xml中手动加上这个参数：

<property>
       <name>hadoop.caller.context.enabled</name>
       <value>true</value>
</property>

顺便跟着HDFS内部版本升级，重启NameNode服务后：

#在$HADOOP_HOME/sbin下
hadoop-daemon.sh stop namenode
#用jps命令确认NameNode进程已不存在之后
hadoop-daemon.sh start namenode

再按一开始的命令提交Spark任务，就可以在hdfs-audit.log中看到CallerContext相关内容了，如下图所示：

如果YARN和HDFS是用同一个Hadoop版本目录配置的，在Spark配置中加入spark.hadoop.hadoop.caller.context.enabled时，rm-audit.log和hdfs-audit.log中应该都是会出现CallerContext内容的。