Spark报错与日志问题查询姿势指南

一、各界面说明

1.1、查看YARN页面的driver日志

可以在右侧搜索框中填对应application号找到任务，然后点击对应的application号链接，如下图所示：

这样会进入该application的信息界面，“FinalStatus”显示了该application的最后状态，点击下方的“logs”按钮也会进入到driver日志界面，如下图所示：

对于driver日志而言，代码中的println()和show()等函数的输出，一般都在stdout里，大部分重要的报错信息都在stderr里。如果application跑的很慢，还可以通过gclog确认是否是因为driver遇到了Full GC，也可以进入stdout或stderr日志界面后，在浏览器地址栏中将“stdout”或“stderr”文字替换为“gclog”，回车后也可查看gclog信息。

在stdout与stderr中，着重搜索和看ERROR、Exception、Failed、Caused by等位置的报错信息，这四个位置都没什么内容再看WARN。

1.2、查看Spark UI

如果任务正在执行中，可以在yarn页面搜对应的application号来找到自己的任务，然后点击右侧的“Application Master”链接进入Spark UI界面，如果任务已完成，该链接会变成“history”，如下图所示：

（1）首先是“Jobs”界面，“Event Timeline”一栏可以显示各Executor的加入与回收；“Active Jobs”一栏指正在运行或等待运行的job；“Description”一列可以看到当前job执行的SQL语句或者代码所在行数，且有链接可点击进入包含的各stages界面；“Submitted”一列表示该job何时被提交给集群；“Duration”一列表示该job持续了多长时间；“Stages”一列显示了该job包含多少个stage，右侧的进度蓝条可以判断总共需要多少个task，完成了多少，同时有多少个task在并发running，如下图所示：

（2）第二个菜单是“Stages”界面，这里包含了所有stage的状态信息，显示的内容和“Jobs”菜单界面中类似，还多了一些内容，例如“Shuffle Read”列表示从上一个stage读取了多少数据量，“Shuffle Write”列表示该stage写入了多少数据量供下一个stage拉取，如下图所示：

如果有失败的stage，也会在“Failure Reason”一列显示出失败原因，如下图所示：

各stage的“Description”处有蓝色链接，可以点击进入该stage的详细信息界面，开头提到了该stage的总执行时长、本地化级别情况、输入数据量（容量/条数）、输出给下一个stage的数据量（容量/条数）、当前执行语句的DAG图等，如下图所示：

可以从DAG看到该stage经过了Hive表扫描、代码生成、shuffle（即Exchange节点）等过程，也指出了对应代码大致所在的行数。下面是metrics表格，包含执行完成的各task持续时间、调度延迟、反序列化时间、GC时间、结果序列化时间、获取结果时间、峰值内存、输入数据量、写出给下一个stage的数据量等，这些metrics信息是可以勾选和隐藏的，如下图所示：

当然该metric表格显示是存在小文件和数据倾斜情况的，后面会详细提到。下面比较重要的是Tasks表格，记录了该stage每一个task的执行情况，包括task id、属于哪次attempt、状态、本地化级别、所属Executor的ID、所在机器IP或域名、启动时间、持续时间、调度延迟等，失败的task也会显示原因，如下图所示：

‍

‍如果Tasks表格显示的失败原因还是不够详细，想看更完整的日志输出，可以点击“Host”列的stdout或stderr链接查看该task所在Executor的日志。依然是着重搜索和看ERROR、Exception、Failed、Caused by等位置的报错信息，这四个位置都没什么内容再看WARN。

‍

（3）“Storage”菜单在排查任务报错问题时使用的很少，主要是各RDD数据在内存或磁盘中的状态情况。

（4）“Environment”菜单显示了集群与该application的配置信息，如JDK版本、Scala版本、各Spark配置参数值（如driver内存）等。

（5）“Executors”界面显示了Driver与Executor的信息，“Jobs”和“Stages”菜单界面中显示的失败task也会记录在这里，所以也可以从该界面进入各节点的stdout与stderr查看报错日志，如下图所示：

如果在Driver或对应Executor的stdout与stderr中没找到关键报错内容，除了查看GC日志，还可以看该节点的YARN Node Manager日志，点击左侧“Tools”菜单中的“Local logs”链接即可进入，记得提前复制好container号，如下图所示：

在Node Manager日志列表中，每小时都对应一个链接，点击任务出问题的那个小时的链接进去，搜索对应container号查找关于该container的报错信息，可以看到该例子中是因为OOM所以该container被YARN杀死，如下图所示：

（6）如果包含SQL逻辑，顶部会多出来一个“SQL”菜单，里面会有多个job组成的各query信息，可以点击失败query的“Description”列链接，会进入该query的详细DAG图与查询计划界面，也可以点Job ID链接回到对应Jobs菜单界面，如下图所示：

可以看到该query中读写了三个Hive表且显示了读到的数据量，其中两个表进行了shuffle和SortMergJoin，鼠标移动到对应蓝色节点还会显示细节信息如表名、涉及字段、表格式等。

在对应query信息界面的底部，还可以点击“Details”按钮查看该query的逻辑计划与物理计划，读懂这些执行计划需要对编译原理有基本的了解以及具有《SparkSQL内核剖析》涉及的源码理解基础，如下图所示：

（7）如果是Streaming实时任务，还会多出来一个“Streaming”菜单，可以查看各微批次（batch）的延迟等情况，一般常常会看“Scheduling Delay”，这一列如果大多是0ms到2ms左右，说明各批次处理没有明显的延迟，如果ms数较大则可能需要关注前面批次的调度延迟情况，如下图所示：

二、常见问题判断与解决方法

2.1、数据倾斜

在Spark application的执行过程中，会遇到时间很长的情况，其中一个可能性就是数据倾斜，判定数据倾斜的标准之一是上面提到过的“Stages”菜单中，对应stage的Description链接里的metrics表格，如下图所示：

可以看到在“Shuffle Read Size”或“Input Size”那一栏中，各task读取数据量的最小值、中位数、最大值等并不均匀，如果是更加极端的数据倾斜，“Duration”那一栏的最大执行时间也会很长。

数据倾斜的另一个现象是在application运行中，“Executors”菜单里Active状态的executor数量只有个别几个，大部分的executor都已经进入Dead状态，这是因为开启了Dynamic Allocation特性，executor只要空闲（idle）超过60秒就会被资源回收，如下图所示：

此时也可以看到Stages界面中正在执行的stage只有个别task在running，如下图所示：

这样的stage点击“Description”列的蓝色链接进去后，下方的“Tasks”表格中，处在running状态的个别task所读取的数据量（Shuffle Read或Input列）远比其他task大，如下图所示：

当然，数据倾斜有时还会伴随个别task所属的executor内存溢出的现象，如下图所示：

如果的确遇到了数据倾斜，可参考上面博客链接的第11点解决。如果自己集群的Spark版本在3.0以上，或者内部2.x版本合入了Intel的Adaptive Execution特性源码，并且确定造成数据倾斜的代码位置有join操作，则可以加上如下参数缓解：

第二个参数的原理可理解为将部分倾斜的Partition (判断标准为该Partition数据是所有Partition Shuffle Write中位数的N倍) 拿出来单独处理，即原本由一个Task 处理的倾斜Partition数据拆分成多个Task共同join后再union回其他partition的结果中，每个Task需处理的数据量减少，从而缓解了Partition的倾斜，如下图所示：

但是一般不建议使用该参数，因为没有从本质上解决倾斜问题，只是加大了并发度进行缓解，还容易因拆分出来的task数过多而导致driver OOM。

2.2、小文件过多

小文件过多的表现之一是各task读取的数据量远小于一个HDFS block即128M或256M，它也会导致任务执行的效率较低，极端情况甚至会导致HDFS Namenode内存压力大（因为每个HDFS文件在NM内存中的元信息都是150字节左右，过多数量的小文件会给NM维护这么多文件信息带来压力），如下图所示：

另一种判断标准是“Stages”菜单中，某个stage的进度蓝条上task数太多达到好几万的级别，用Input或Shuffle Read量除以task数后，每个task处理的数据量远小于128或256M，如下图所示：

有时小文件多造成的task数过多，会导致driver full gc从而导致Spark UI网页打不开从而看不到Stages情况，因为driver内存有限且负责spark ui的metrics信息状态维护，如下图所示：

在遇到小文件时，如果自己集群的Spark版本在3.0以上，或者内部2.x版本合入了Intel的Adaptive Execution特性源码，可以加上下面的参数来缓解：

如果自己集群的Spark版本不支持上述参数，也可以在SQL的select语句位置加入强制重分区Hint，重分区数即repartition()中的数字根据任务落地的数据量而定，尽量让每个落地文件大小在256M或128M左右，如下所示：

小文件过多也可能导致内存溢出，因为用于读取每一个文件的reader对象，Spark都会在内存中生成一个1M大小的缓冲区，下面截图来自《SparkSQL内核剖析》：

2.3、笛卡尔积/数据量膨胀

依然是“Stages”菜单中，对应stage的Description链接进入后，下方有个各executor对应task运行情况的表格，如果输入的数据量（容量与Records数）远比输出数据量小，再看DAG图里有涉及到join操作，那就说明左右表join的字段中可能有重复值，发生了笛卡尔积/数据量膨胀：

另一个可能迹象的位置是对应stage的Description链接里的metrics表格中，如果shuffle write的记录数远大于shuffle read的记录数，也说明join的字段值可能有重复，交错关联导致数据量膨胀了：

如果确实遇到了该现象导致任务变慢，可以参考第二章开头的博客链接第24点来解决。

2.4、内存溢出（OOM）

如果数据量很大、数据倾斜、并发度不合理、代码逻辑不合理等原因，导致Driver或者Executor的内存不够，就会出现下图所示的OOM错误：

首先要确认是Driver还是Executor端OOM，也就是OOM的报错内容是在哪个节点的stdout或stderr看到的，那就是哪个节点OOM。如果遇到了可以参考第二章开头的博客链接第12点来解决。

如果是driver端OOM或内存压力大，还有一个判断方法是Spark UI页面打开十分缓慢，因为代码的解析、相关对象的序列化、广播变量、Spark UI的进度状态维护都是在driver进行，此时如果查看driver的GC日志，往往可能发生了Full GC。

关于Spark会报OOM的深层原因，下图摘自《SparkSQL内核剖析》：

2.5、YARN队列资源不足

当application跑的比较慢时，除了前面提到的数据倾斜、数据量膨胀、小文件过多等原因，还可能是同一个YARN队列中正在执行的application太多，或某个application不够优化占据过多资源堵塞了其他application。进入yarn UI后，点击左侧的“scheduler”，然后ctrl+f搜索自己的系统队列，如下图所示：

如果自己队列显示为黄色、或已使用的资源中，内存或CPU核数其中一项已经达到最小资源阈值（Min Resource）、或最小资源非常小，说明自己队列中当前时刻的资源不足，可以点击左上角的RUNNING进入正运行的application界面，在右边的search框中搜索自己队列名然后回车，看看正在运行的各application里“Allocated CPU vcores”和“Allocated Memory MB”这两列，哪个任务有点大，还可以从“name”列看到任务名，与伙伴确认可以被杀掉的application，杀死后释放资源并让任务责任人优化代码与调参，如下图所示：

第二种迹象是，driver的stderr等日志中有如下的未申请到资源的内容：

第三种迹象，如果spark ui的job或stages界面中，正在运行的job或stage只有少数task在长时间running，并且进入该stage的description链接后，观察Metrics与Tasks表格并未发现有某个task数据量巨大的数据倾斜现象，说明暂时申请不到更多的executor来更高并发的运行多个task，如下图所示：

第四种迹象，如果发现任务本身长时间没有实际执行起来，在application的详情界面中看到下图中Node列没有指定IP或域名的现象，说明此时没有启动Application Master，大概率也是yarn队列没资源了：

此时再去看driver日志，大概率会出现下面这种“Accepted”字样的内容，这代表集群已经接受了这个application的提交，但是一直没有分配到资源：