hadoop中的一次集群任务执行超时问题查找过程

标签: hadoop 集群 任务 | 发表时间:2014-09-28 11:47 | 作者:brandNewUser
出处:http://www.iteye.com

 

 

问题背景

 

本次进行一个项目的重构,在某些活动数据量比较大的情况下,会偶尔出现1200s超时的情况,如下:

 

AttemptID:attempt_1410771599055_11709_m_000033_0 Timed out after 1200 secs

  

而hadoop会不断启动备份任务进行重试,重试也许成功,但失败的概率还是比较大:

 

 

 

经过分析,hadoop的任务都有个超时时间,使用下面的参数设置,表示1200s后如果没有进展,就会任务该任务超时,将其状态设置为FAILED。

 

-Dmapreduce.task.timeout=1200000

 

到底因为什么原因导致超时?为了继续分析这个问题,我们将这个参数设置得非常之大。

 

调整超时参数

 

将超时时间设置为24小时之后,发现任务不会FAILED,但是其执行了大概40多个小时,仍然还没有执行完成。

 

还好我们在任务执行过程中打了不少的log,以帮助分析问题。经过日志的分析,我们发现有下面的现象:

2014-09-22 00:17:29,005 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 77477) is collected! 
2014-09-22 00:17:29,005 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 77477) is collected! 
2014-09-22 00:17:29,005 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 77477) is collected! 
2014-09-22 01:17:29,054 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 120096) is collected!
2014-09-22 01:17:29,064 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 120096) is collected! 
2014-09-22 01:17:29,064 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 120096) is collected! 
2014-09-22 01:17:29,064 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 120096) is collected!
...
2014-09-22 01:17:36,590 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 164747) is collected! 
2014-09-22 01:17:36,590 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 164747) is collected! 
2014-09-22 01:17:36,590 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 164747) is collected! 
2014-09-22 01:17:36,590 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 164747) is collected! 
2014-09-22 02:17:36,674 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 158198) is collected!
2014-09-22 02:17:36,683 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 158198) is collected! 
2014-09-22 02:17:36,683 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 158198) is collected! 
2014-09-22 02:17:36,683 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 158198) is collected!
....
2014-09-22 02:17:40,888 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 203233) is collected! 
2014-09-22 02:17:40,888 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 203233) is collected! 
2014-09-22 02:17:40,888 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 203233) is collected! 
2014-09-22 03:17:40,925 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 79188) is collected!
2014-09-22 03:17:40,934 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 79188) is collected! 
2014-09-22 03:17:40,934 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 79188) is collected! 
2014-09-22 03:17:40,934 INFO [main] com.xxx.yo.phase1.Phase1Mapper: history(caid: 2000037, superid: 79188) is collected!

 

日志分析得出的结论便是,程序总会在某个时间点休息3600秒(大概1个小时),然后再执行一会儿,便又休息3600秒。

 

hadoop configuration中得出初步结论

 

我们在这1个小时对该java进程进行监控,发现该进程在此期间(jstack命令查看其日志),一直在一个点等待:

"main" prio=10 tid=0x000000000293f000 nid=0x1e06 runnable [0x0000000041b20000]
   java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:228)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:81)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
- locked <0x00000006e243c3f0> (a sun.nio.ch.Util$2)
- locked <0x00000006e243c3e0> (a java.util.Collections$UnmodifiableSet)
- locked <0x00000006e243c1a0> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
at org.apache.hadoop.net.SocketIOWithTimeout$SelectorPool.select(SocketIOWithTimeout.java:335)
at org.apache.hadoop.net.SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:157)
at org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:161)
at org.apache.hadoop.hdfs.protocol.datatransfer.PacketReceiver.readChannelFully(PacketReceiver.java:258)
at org.apache.hadoop.hdfs.protocol.datatransfer.PacketReceiver.doReadFully(PacketReceiver.java:209)
at org.apache.hadoop.hdfs.protocol.datatransfer.PacketReceiver.doRead(PacketReceiver.java:171)
at org.apache.hadoop.hdfs.protocol.datatransfer.PacketReceiver.receiveNextPacket(PacketReceiver.java:102)
at org.apache.hadoop.hdfs.RemoteBlockReader2.readNextPacket(RemoteBlockReader2.java:170)
at org.apache.hadoop.hdfs.RemoteBlockReader2.read(RemoteBlockReader2.java:135)
- locked <0x00000006e12dcc78> (a org.apache.hadoop.hdfs.RemoteBlockReader2)
at org.apache.hadoop.hdfs.DFSInputStream$ByteArrayStrategy.doRead(DFSInputStream.java:642)
at org.apache.hadoop.hdfs.DFSInputStream.readBuffer(DFSInputStream.java:698)
- eliminated <0x00000006e12dcc18> (a org.apache.hadoop.hdfs.DFSInputStream)
at org.apache.hadoop.hdfs.DFSInputStream.readWithStrategy(DFSInputStream.java:752)
at org.apache.hadoop.hdfs.DFSInputStream.read(DFSInputStream.java:793)
- locked <0x00000006e12dcc18> (a org.apache.hadoop.hdfs.DFSInputStream)
at java.io.DataInputStream.read(DataInputStream.java:149)
at com.xxx.app.MzSequenceFile$PartInputStream.read(MzSequenceFile.java:451)
at org.apache.hadoop.io.compress.DecompressorStream.getCompressedData(DecompressorStream.java:159)
at org.apache.hadoop.io.compress.DecompressorStream.decompress(DecompressorStream.java:143)
at org.apache.hadoop.io.compress.DecompressorStream.read(DecompressorStream.java:85)
at java.io.DataInputStream.readFully(DataInputStream.java:195)
at org.apache.hadoop.io.Text.readFields(Text.java:292)
at org.apache.hadoop.io.serializer.WritableSerialization$WritableDeserializer.deserialize(WritableSerialization.java:71)
at org.apache.hadoop.io.serializer.WritableSerialization$WritableDeserializer.deserialize(WritableSerialization.java:42)
at com.xxx.app.MzSequenceFile$Reader.deserializeValue(MzSequenceFile.java:672)
at com.xxx.app.MzSequenceFile$Reader.next(MzSequenceFile.java:684)
at com.xxx.app.MzSequenceFile$Reader.next(MzSequenceFile.java:692)
at com.xxx.yo.io.CombineFileRawLogReader.streamNext(CombineFileRawLogReader.java:284)
at com.xxx.yo.io.CombineFileRawLogReader.next(CombineFileRawLogReader.java:342)
at com.xxx.yo.io.CampaignRawLogReader.next(CampaignRawLogReader.java:73)
at com.xxx.yo.io.CampaignRawLogReader.next(CampaignRawLogReader.java:23)
at org.apache.hadoop.mapred.MapTask$TrackedRecordReader.moveToNext(MapTask.java:197)
- locked <0x00000006e01dd3e0> (a org.apache.hadoop.mapred.MapTask$TrackedRecordReader)
at org.apache.hadoop.mapred.MapTask$TrackedRecordReader.next(MapTask.java:183)
- locked <0x00000006e01dd3e0> (a org.apache.hadoop.mapred.MapTask$TrackedRecordReader)
at org.apache.hadoop.mapred.MapRunner.run(MapRunner.java:52)
at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:429)
at org.apache.hadoop.mapred.MapTask.run(MapTask.java:341)
at org.apache.hadoop.mapred.YarnChild$2.run(YarnChild.java:162)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:415)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1491)

 

当时初步怀疑是JDK版本问题,Java NIO也确实存在着臭名昭著的epoll空轮询导致CPU100%问题,但这个bug在JDK6中的高版本就已经解决了,更何况我们使用的是1.7。而且我们通过top -p 进程id的方式查看其CPU占用率为0,排除了该bug。

 

经过日志的初步分析,发现3600s这个线索,从job的configuration中,初步查找出参数dfs.client.socket-timeout,单位毫秒。

-Ddfs.client.socket-timeout=3600000

 

试验性地将这个参数修改为60ms,可以看出出现超时的概率非常大,但会不断重试以继续:

 

2014-09-26 12:53:03,184 WARN [main] org.apache.hadoop.hdfs.DFSClient: Failed to connect to /192.168.7.22:50010 for block, add to deadNodes and continue.
 java.net.SocketTimeoutException: 60000 millis timeout while waiting for channel to be ready for read. ch : 
 java.nio.channels.SocketChannel[connected local=/192.168.7.17:22051 remote=/192.168.7.22:50010] 
 java.net.SocketTimeoutException: 60 millis timeout while waiting for channel to be ready for read. ch : 
 java.nio.channels.SocketChannel[connected local=/192.168.7.17:22051 remote=/192.168.7.22:50010]
at org.apache.hadoop.net.SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:164)
at org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:161)
at org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:131)
at org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:118)
at java.io.FilterInputStream.read(FilterInputStream.java:83)
at org.apache.hadoop.hdfs.protocolPB.PBHelper.vintPrefixed(PBHelper.java:1490)
at org.apache.hadoop.hdfs.RemoteBlockReader2.newBlockReader(RemoteBlockReader2.java:392)
at org.apache.hadoop.hdfs.BlockReaderFactory.newBlockReader(BlockReaderFactory.java:131)
at org.apache.hadoop.hdfs.DFSInputStream.getBlockReader(DFSInputStream.java:1108)
at org.apache.hadoop.hdfs.DFSInputStream.blockSeekTo(DFSInputStream.java:533)
at org.apache.hadoop.hdfs.DFSInputStream.readWithStrategy(DFSInputStream.java:749) 
at org.apache.hadoop.hdfs.DFSInputStream.read(DFSInputStream.java:793)
at org.apache.hadoop.hdfs.DFSInputStream.read(DFSInputStream.java:601)
at java.io.DataInputStream.readInt(DataInputStream.java:387)
at com.xxx.app.MzSequenceFile$Reader.init(MzSequenceFile.java:521)
at com.xxx.app.MzSequenceFile$Reader.<init>(MzSequenceFile.java:515)
at com.xxx.app.MzSequenceFile$Reader.<init>(MzSequenceFile.java:505)
at com.xxx.yo.io.CombineFileRawLogReader.<init>(CombineFileRawLogReader.java:146)
at com.xxx.yo.io.CampaignRawLogReader.next(CampaignRawLogReader.java:64)
at com.xxx.yo.io.CampaignRawLogReader.next(CampaignRawLogReader.java:22)
at org.apache.hadoop.mapred.MapTask$TrackedRecordReader.moveToNext(MapTask.java:197)
at org.apache.hadoop.mapred.MapTask$TrackedRecordReader.next(MapTask.java:183)
at org.apache.hadoop.mapred.MapRunner.run(MapRunner.java:52)
at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:429)
at org.apache.hadoop.mapred.MapTask.run(MapTask.java:341)
at org.apache.hadoop.mapred.YarnChild$2.run(YarnChild.java:162)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:415)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1491)
at org.apache.hadoop.mapred.YarnChild.main(YarnChild.java:157)

 

于是,最终将这个参数设置为60s,这其实也是集群最终默认的超时时间,由于之前一次不明就里的优化,导致了后续这些问题的发生,因此在调整参数时,一定要注意了解清楚该参数造成的影响。

 

简要分析的结论

 

在Mapper端读取HDFS上的文件时,可能由于网络原因(由于我们的Split切分地比较大,因此不可能做到完全数据本地化)导致读取数据超时,原来居然设置成1个小时,而任务的超时时间仅设置为20分钟,因此只要发生读取数据超时,就必然会引起任务超时。

 

通过这次分析过程,学到了很多查找问题的方式,包括通过现象分析规律,得到线索,最终查找问题的原因。快速测试,不能忽略哪怕一个小的Exception,不行就是分析hadoop的源码,掌握其运行时行为。

 

如果task tracker在一段时间(默认是10min,可以通过mapred.task.timeout属性值来设置,单位是毫秒)内一直没有收到它的进度报告,则把它标记为失效。

 

 



已有 0 人发表留言,猛击->> 这里<<-参与讨论


ITeye推荐



相关 [hadoop 集群 任务] 推荐:

hadoop中的一次集群任务执行超时问题查找过程

- - 开源软件 - ITeye博客
本次进行一个项目的重构,在某些活动数据量比较大的情况下,会偶尔出现1200s超时的情况,如下:. 而hadoop会不断启动备份任务进行重试,重试也许成功,但失败的概率还是比较大:. 经过分析,hadoop的任务都有个超时时间,使用下面的参数设置,表示1200s后如果没有进展,就会任务该任务超时,将其状态设置为FAILED.

Hadoop集群与Hadoop性能优化

- - 学着站在巨人的肩膀上
本文讲解一下Hadoop集群、Hadoop性能优化、Hadoop机架感知实现、Hadoop配置等,下面是有关这些命令的具体介绍. Hadoop性能优化:Hadoop机架感知实现及配置:分布式的集群通常包含非常多的机器,由于受到机架槽位和交换机网口的限制,通常大型的分布式集群都会跨好几个机架,由多个机架上的机器共同组成一个分布式集群.

[hadoop] 搭建自己的hadoop集群

- - CSDN博客系统运维推荐文章
       a>  五台centos6.2虚拟机,配置主机名、IP地址、yum源、.        b>  准备所需要的软件包. 2> 配置我自己的hadoop 集群.       a>  修改5台机器的hosts文件.       b>  配置master无密码登录slave,在master01和master02上执行以下命令:   .

Hadoop 集群基准测试

- - IT瘾-dev
生产环境中,如何对 Hadoop 集群进行 Benchmark Test. 本文将通过 Hadoop 自带的 Benchmark 测试程序:TestDFSIO 和 TeraSort,简单介绍如何进行 Hadoop 的读写 & 计算性能的压测. 回顾上篇文章: 认识多队列网卡中断绑定. (本文使用 2.6.0 的 hadoop 版本进行测试,基准测试被打包在测试程序 JAR 文件中,通过无参调用 bin/hadoop jar ./share/hadoop/mapreduce/xxx.jar 可以得到其列表 ).

[hadoop] 基于Hadoop集群的HBase集群的配置

- - CSDN博客系统运维推荐文章
       a> 已经配置完成的Hadoop集群.        b> 所需要的软件包. 2>  单独安装的ZooKeeper集群,不基于HBase集群管理.        a> 在master01上解压zookeeper-3.4.4.tar.gz.        b> 修改Zookeeper的配置文件.

hadoop集群环境的配置

- - ITeye博客
  之前说过,我们的hadoop集群已经搭建起来了,只是具体的步骤还没来得及整理,幸好今天又把流程走了一遍,真的是不做不晓得,一做才发现自己原来什么都忘记得差不多了,在此记录一下搭建hadoop集群的步骤,便于需要的时候看看.   这个配环境的过程真的是比较困难的,我今天搞了一天终于把自己的机器作为datanode连接上了master机器,我还是年前搞过一遍的呢,所以这个还是需要耐心+细心的.

腾讯TDW:大型Hadoop集群应用

- - 服务器运维与网站架构|Linux运维|X研究
PS:TDW是腾讯最大的离线数据处理平台. 本文主要从需求、挑战、方案和未来计划等方面,介绍了TDW在建设单个大规模集群中采取的JobTracker分散化和NameNode高可用两个优化方案. TDW(Tencent distributed Data Warehouse,腾讯分布式数据仓库)基于开源软件Hadoop和Hive进行构建,打破了传统数据仓库不能线性扩展、可控性差的局限,并且根据腾讯数据量大、计算复杂等特定情况进行了大量优化和改造.

【重要】hadoop集群默认配置和常用配置

- - 学着站在巨人的肩膀上
配置hadoop,主要是配置core-site.xml,hdfs-site.xml,mapred-site.xml三个配置文件,默认下来,这些配置文件都是空的,所以很难知道这些配置文件有哪些配置可以生效,上网找的配置可能因为各个hadoop版本不同,导致无法生效. 浏览更多的配置,有两个方法:. 1.选择相应版本的hadoop,下载解压后,搜索*.xml,找到core-default.xml,hdfs-default.xml,mapred-default.xml,这些就是默认配置,可以参考这些配置的说明和key,配置hadoop集群.

Hadoop集群安装&Hbase实验环境搭建

- - CSDN博客云计算推荐文章
1.安装ubuntu10.04操作系统. 安装成功后,系统也会有相应提示:. sudo vi /etc/inetd.conf并加入以下一行. sudo vi /etc/xinetd.conf并加入以下内容:. sudo vi /etc/xinetd.d/telnet并加入以下内容:. 重启机器或重启网络服务sudo /etc/init.d/xinetd restart.

分布式集群环境hadoop、hbase、zookeeper搭建(全)

- - CSDN博客云计算推荐文章
集群环境至少需要3个节点(也就是3台服务器设备):1个Master,2个Slave,节点之间局域网连接,可以相互ping通,下面举例说明,配置节点IP分配如下:. 三个节点均使用centos 6.3系统,为了便于维护,集群环境配置项最好使用相同用户名、用户密码、相同hadoop、hbase、zookeeper目录结构.