摘要： 在作业调度某次性能测试开展中，用例“一个工作流中存在100个有相互依赖关系的轻量job”运行异常，经过层层分析，最终发现是运行job的机器unable to create new native thread触发了spark2.0版本的一个bug，并通过修改了最大线程数最终完成了该用例测试执行。
1、案例介绍
在作业调度某次性能测试开展中，用例“一个工作流中存在100个有相互依赖关系的轻量job”运行异常，详情如下：在测试执行过程中，从portal前端任务调度/数据分析/查看运算元素界面，观察到部分job执行成功，少量job一直处于执行中状态（正常场景下单个job从提交到执行完毕大约耗时2分钟左右，这部分少量的job处于执行中的时间远大于2分钟），大部分job处于等待中状态。
100个job的依赖关系在作业调度界面的DAG图如下（看起来很复杂、很杂乱）：
梳理后的DAG图：
2、问题分析
发现用例执行异常后，便开展排查和分析的工作。首先要排除是测试人员误操作引起的非问题，排除误操作后方可对用例运行的日志进行系统分析。
2.1、排除测试人员误操作
用例执行的job是将数据从HDFS导入至HIVE库中的表，HDFS以及HIVE表虽然是通过脚本批量创建的，但是也不能排除误建的可能性。因此需要检查对应job执行过程中源文件与目标表是否存在且满足需求。
为了检查对应job执行过程中源文件与目标表是否存在且满足需求，则需查看job对应的配置信息，才确定job对应的源文件与目的表。在性能测试过程中，界面上很难查看单个job的配置信息，可以通过数据库查询。具体步骤略；
通过获取到的源数据的路径与目标表名称，检查HDFS上的文件与hive库中的表是否存在、类型是否满足测试需求等等，步骤略；
通过检查，确认ETL的源文件与目标表均存在，通过以上步骤排除测试人员的测试误操作，然后对用例执行过程中的日志文件进行分析。
2.2日志文件分析
进行日志文件分析前，必须了解用例执行过程中的应用服务的内部逻辑。内部逻辑步骤以及每个步骤关联的日志如下表：
| 逻辑步骤 | 对应日志文件及检查点 |
| 1、作业调度的server端接受前端job任务后，将任务放到zk指定目录下 | Server端日志 |
| 2、agent端定时去zk的目录下获取job任务。 | Agent端日志 |
| 3、agent获取到job任务后，将任务提交到yarn上。 | Yarn上accept的任务列表 |
| 4、yarn根据job指定的资源完成资源分配。 | Yarn上running的任务的资源分配日志 |
| 5、通过spark进行任务执行 | Executor的执行日志 |
| 6、完成任务执行后，agent回传执行情况至zk指定目录 | Agent端日志 |
| 7、server端定时去指定目录获取已经执行完毕的job信息，回传至前端显示。 | Server端日志 |
通过章节一中的案例介绍，前端界面上显示部分job已经处于运行中的状态，即agent端已经获取到了job，因此，我们直接跳至上表中的步骤3查看job是否提交至yarn上。
2.2.1、Yarn running列表查看
有两种方法可以查看yarn上的任务列表。1、通过vnc界面的查看。这种的方式比较直观。2、通过命令行进行查看，下面分别介绍这两种方法。
2.2.1.1 vnc查看yarn任务列表
使用vnc，首先要进行下载、安装，下载、安装步骤略。
完成安装后，需要输入访问的ip和用户名/密码方能登录（ip和用户名/密码为当前处于active节点的ip），在浏览器重输入链接：n1.dsj.migu.cn:50030/cluster。
链接并非一层不变的，其中n1.dsj.migu.cn为处于active的节点的主机别名。为了获取这个链接，首先我们需要查看namenode的状态。
1、查看namenode的状态命令： hdfshaadmin -getServiceState nn1。
其中nn1为namenode的名称，在hdfs-site.xml中进行配置。那怎么得到namenode的名称呢？
在linux界面输入：vim $HADOOP_HOME/etc/hadoop/hdfs-site.xml，如下图所示：
2、然后在该节点上，通过/etc/hosts文件可以查看处于active的节点的主机别名。如下图：
2.2.1.2 命令行查看
在linux命令行输入：yarn application –list，可以查看application相关信息
打开yarn的链接后，发现界面上显示运行中的job已经处于yarn的running列表中。因此，继续检查逻辑步骤4---yarn资源分配是否正常。
2.2.2 yarn资源分配检查
通过排查container的日志，可以查看资源分配以及使用的情况。同样有两种方式可以查看container的日志。1、通过vnc界面连接。2、linux的命令行，下面分别介绍这两种方式。
2.2.2.1 vnc查看yarn任务的资源分配
查看对应yarn上的running任务，发现执行中的任务在yarn上一直处于running状态，可知在调度界面上显示处于运行中的job已经提交到yarn上了。通过界面点击logs查看资源分配的日志，如下图中的“logs”。
2.2.2.2 命令行查看
通过命令行：yarn application –list可获取applicationId，然后在命令行上输入yarn logs -applicationId applicationId可查看对应执行序列号为applicationId的资源相关日志。
类似日志如下：
Container [pid=134663,containerID=container_1430287094897_0049_02_067966] is running beyond physical memory limits. Current usage: 1.0 GB of 1 GB physical memory used; 1.5 GB of 10 GB virtual memory used.
通过以上日志可以看出使用内存小于分配内存，说明内存资源没有出现问题。
通过步骤4未发现异常，继续检查步骤5---spark执行日志是否存在异常。
2.2.3 spark执行日志
接下来查看spark的执行日志，即executor的日志，查看是否存在异常。
正在运行的job可以通过点击界面上的日志链接查看日志。点击界面上的executor标题，选择处于卡顿状态的executor日志。查看spark运行executor的日志（可理解为线程），可以看到日志中报错。
百度spark的报错，发现此错误为spark2.0版本已有的bug，并在spark2.1版本中进行了修复。
继续分析是什么场景暴露了spark2.0版本的bug，查看一直处于运行中的job的日志中可以看到，报错java.lang.OutofMemoryError:unable to create new native thread。
对比日志出现的时间，可知java.lang.OutofMemoryError:unable to create new native thread触发了spark的报错。
2.2.4 java.lang.OutofMemoryError异常分析
关于java.lang.OutofMemoryError:unable to create new native thread的报错，这个异常问题的本质原因是用例在运行过程中创建了太多的线程，而能创建的线程数是有限制的，导致了异常的发生（百度）。总结了一下，可能的导致错误的原因有三个，具体如下：
- linux系统问题----在linux上每个用户能够创建的线程数量是有最大值的，最大值通过ulimate–a 命令行可以查看，不同的用户max user processes可能不同；
2.jvm内存配置问题----能创建的线程数的具体计算公式如下：
(MaxProcessMemory - JVMMemory - ReservedOsMemory) / (ThreadStackSize) = Number of threads
MaxProcessMemory 指的是一个进程的最大内存；
JVMMemory JVM内存
ReservedOsMemory 保留的操作系统内存
ThreadStackSize 线程栈的大小
你给JVM内存越多，那么你能创建的线程越少，越容易发生以上错误。
3、程序问题----程序内部有bug，导致创建大量不需要的线程或者线程没有及时回收，那么必须解决这个bug，修改参数是不能解决问题的，当然如果程序确实需要大量的线程，现有的设置不能达到要求，那么可以通过修改MaxProcessMemory，JVMMemory，ThreadStackSize这三个因素，来增加能创建的线程数；
验证是哪一种原因的影响，建议采用按照1、2、3点的顺序来排查。
3、修改验证
3.1 修改linux最大线程数
下面先进行问题1排查。Linux可创建线程的最大值可通过ulimate–a 命令行可以查看用户wangxin以及hadoop用户的最大线程数（wangxin的账号为portal前端登录的账号，也是spark上提交spark任务的用户，hadoop用户为基础平台内部创建线程时使用的用户），发现最大线程数为1024，在该用例运行过程中，很可能不够。因此，我们进行线程数的修改。
修改步骤如下：
1、使用root用户修改配置文件：/etc/security/limits.conf
增加如下内容
* softnproc65535
* hardnproc65535
“*”代表了所有用户
2、修改/etc/security/limits.d/90-nproc.con
将* softnproc 1024修改为：* softnproc65535
但须注意，修改系统的线程数后，很容易出现修改了却未生效的情况，需要通过重连会话、切换用户来检查修改是否生效。那么如何检查配置是否生效呢？
断开当前会话，重新连接，随意选择登陆用户，输入命令：ulimit–a，查看最大线程数是否为修改后的个数，如未生效，则为ssh配置的问题，需联系运维人员进行处理。
3.2 验证执行
完成修改后，将用例进行重新运行，未出现如上错误，证明确实是linux用户的最大线程数造成的问题。但是仍然有2个job未执行成功，分别对未执行成功的job进行配置检查以及日志分析。
1、对比异常的日志与正常执行的日志（推荐工具：beyond compare），可以看到异常的日志中未进行transload这个步骤，并对比其他的正常日志的日志，发现异常日志中totalRows为0，检查配置ETL_HY_DTHIVE_101所对应的源文件test000不存在，但是etl执行并不会报错，作业调度前端也显示成功，但是去执行的日志可以看到，日志逻辑与正常执行的逻辑不一样，并没进入spark执行，属于配置错误。
异常的job执行日志：
正常的执行日志：
2、job对应的配置编号为ETL_HY_DTHIVE_102的日志中提示，hive表下的文件Test000.txt未非列式文件。因此考虑是否是该配置对应的表有异常，因此手动进行hive，查看表的内容，提示hive表下的文件Test000.txt未非列式文件。猜测是测试人员在调试脚本或准备数据过程手动load过非列式文件，所以etl执行时出错。清空表，再执行job，job执行成功。
因此测试过程中，需要对构造的数据的边界数据进行重点检查，比如构造的数据为Test000.txt--Test099.txt，需要重点检查Test000、Test099的值。
4、测试工作方法积累
1、出错时，对比正确执行的日志可知哪一步开始出错；
2、在性能测试时检查数据抽样检查容易出错。可采用程序校验的方式进行数据库数据的批量检查，也可通过提前选用特殊的标记字段，通过数据库查询语句检查插入的数据条数。
扫一扫
1937
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
