云梯集群FileNotFound灵异事件追查始末

FROM：http://luoli523.com/blog/2012/12/27/yun-ti-ji-qun-filenotfoundling-yi-shi-jian-zhui-cha-shi-mo/

集群最近出现了一个非常诡异的现象，问题的表象如下：

2012-12-04 01:23:30,225 INFO org.apache.hadoop.ipc.Server: IPC Server handler 32 on 9001, call submitJob(job_201211151327_2801259) from 172.24.208.67:52961: error: java.io.FileNotFoundException: File does not exist: hdfs://hdpnn:9000/home/hadoop/cluster-data/mapred/system/job_201211151327_2801259/job.xml
java.io.FileNotFoundException: File does not exist: hdfs://hdpnn:9000/home/hadoop/cluster-data/mapred/system/job_201211151327_2801259/job.xml
        at org.apache.hadoop.hdfs.DistributedFileSystem.getFileStatus(DistributedFileSystem.java:483)
        at org.apache.hadoop.mapred.JobInProgress.<init>(JobInProgress.java:303)
        at org.apache.hadoop.mapred.JobTracker.submitJob(JobTracker.java:3120)
        at org.apache.hadoop.mapred.JobTracker.submitJob(JobTracker.java:3084)
        at sun.reflect.GeneratedMethodAccessor54.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:481)
        at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1147)

从异常日志上来看，好象是说在提交job的时候，由于某个文件不存在，导致job提交失败。但深入调查发现：报不存在的那个文件，实际上早就存在了。有的时候，那个文件可能是几个星期前就已经写入到HDFS上了，却在某个时间发生这种问题。表现出来的现象就是这种File Not Found Exception。

从经验上来看，很有可能是由于同步问题导致，但令我们百思不得其解的是：如果是同步问题造成，那么可以解释刚创建的文件马上去getFileInfo会出现类似的现象，但无法解释很久以前就存在的文件还会报这种错误。这个问题在我们的集群上隐藏了很长时间，岁素想尽了各种办法都没有找到最终的原因，只能让失败的job重跑。更令人崩溃的是，重跑能重现的概率极低，导致我们线下模拟变得非常的困难。 不过功夫不负有心人，经过非常非常苦逼的各种蛛丝马迹的分析和模拟，终于找到了底层最终的原因。

疑惑：

这个bug是一个同步问题的bug，简单的说就是：namenode中所有对文件系统进行访问（读/写）都是加锁了，不修改namespace操作的加读 锁（getListing, getBlockLocations等），修改namespace结构的加读锁（mkdir，rename，create，delete等），唯一的一个 没有就是getFileInfo。之前怀疑就是因为这个同步问题造成的上述问题，但所有的表象中，最后剩下一个现象一直没法得到很合理的解释，那就是：

-rw-rw-rw-  10 jiangxiaohui cug-admin    8302325 2012-11-15 13:34 /home/hadoop/cluster-data/mapred/system/shared_cache/3ec34669545c607f549b291ddd490d4f_jython.jar

报文件不存在的这个文件，实际上在很早的时候就已经在HDFS的DistributedCache目录中了，job初始化的时候没有修改过，所以即使是同步问题，也无法解释很早就存在的文件为何get不到info。

另外由于这个问题在测试环境中一直没有找到稳定重现的办法，所以之前的调查只能说怀疑跟这个地方有关，但无法下绝对的结论。

重现：

经过对所有出现类似这种现象的日志进行观察，发现很大部分出现都是在对 /home/hadoop/cluster-data/mapred/system/shared_cache 这个目录下的文件进行getFileInfo的时候出现的，这个目录是云梯上的DistributedCache目录，他的特点是：

1. 对该目录下的文件 进行ls操作非常的频繁；
2. 在这个目录下进行getFileInfo的时候，随时可能还有其他的进程往这个目录里增删文件或者目录。

同时基于对某天出错时间点前后的 mapred/system目录以及mapred/system/shared_cache目录的audit log进行观察发现，虽然没有对3ec34669545c607f549b291ddd490d4f_jython.jar这个文件的修改操作，但那段时 间有比较频繁的对shared_cache目录下文件的增删操作。基于上述特点，我写了两个job尝试重现这种现象：

1. 在实验集群上创建一个文件： /home/hadoop/cluster-data/mapred/system/shared_cache/3ec34669545c607f549b291ddd490d4f_jython.jar
2. jobA：并行跑540个map，在map中循环不断的对这个文件进行getFileInfo操作（while true），其他什么都不干
3. jobB：并行跑100个map，在map中不停的对mapred/system目录以及mapred/system/shared_cache目录进行文件的增删操作，循环往复。
   两个job都没有动过3ec34669545c607f549b291ddd490d4f_jython.jar文件，但运行一段时间后，问题重现了。

分析原因：

重现以后，进一步跟踪，终于找到了深层次最终根本的原因。

namenode内部的namespace目录树结构是由一个一个的Inode组成，如果是目录，那么目录下的子INode是用一个children数组 保存的，所以要对一个目录下的某个文件进行getFileInfo操作，实际上就是找到那个目录的INode，并对该INode下的children数组 进行二分查找。出现问题的情况原因是： 由于getFileInfo没有加directory的读锁，导致在getFileInfo的时候，当对children数组进行二分查找时，并不是一个 排他的查找，有可能在查找的过程中，children数组内的内容以及发生了变化，可能多了一个或多个child，也可能少了几个，这样当 getFileInfo找到某个文件在children数组中的index，并尝试去get(idx)时，这两个操作之间如果发生了children变 化，同时该变化还导致了该文件在children中的index发生了变化，或者向上述日志一样直接就数组越界，就有可能造成getFileInfo的返 回不准确。

解决：

找到了深层次的原因，解决起来就比较好办了，patch修改如下：

PS:patch的修改是基于淘宝云梯集群的代码，并不一定适用于其他base版本。需要特别提出的是：我们的hadoop版本处于性能的原因做了很多的优化，性能提升的同时也带来了一些寻常集群没有碰到过的问题，如果你的集群用的是CDH3,甚至CDH4的版本，里面namenode内部仍然用的是全局锁，性能虽然不高（相对而言），但通常不会出现这种问题

问过facebook的同行，他们同样存在这个问题，只不过他们的提交作业场景跟我们不太一样，所以发生的频率没我们这么高，上个月他们fix了这个问题，我们的代码也在上个月fix了这个问题（http://reviewboard.dev.sd.aliyun.com/ReviewBoard/r/68258/），我用fix后的版本再次运行job，再也没有出现过上述现象。​

转载请注明：爱开源 » 云梯集群FileNotFound灵异事件追查始末