引用
2011-11-09 07:35:45,911 INFO org.apache.hadoop.hbase.regionserver.HRegion: Blocking updates for 'IPC Server handler 32 on 60020' on
region xxx,333-2395000000032117,1320773734010.9a7ae39b5a42ccfa1fa6118aa8f79195.: memstore size 128.0m is >= than blocking 128.0m size
region xxx,333-2395000000032117,1320773734010.9a7ae39b5a42ccfa1fa6118aa8f79195.: memstore size 128.0m is >= than blocking 128.0m size
我们知道每次put时会检查当前的memstore大小,当大于flush值的一个系数时(系数默认为2倍),就会block住这次写请求,并提交一个flush任务。但是很奇怪的是,用户此时再也不能往这个region写数据了,并在大约10多个小时以后又神奇地自然恢复了。
原因是什么呢?
经过一番检查,发现了hbase的一个bug,我们准备修改后提交到社区,不过因为实在太有趣了,体现了分布式事务的很有趣特征,所以先在此分享一下原因吧。
这个问题是由以下四个事件共同组成的,我把代码简单化后作如下整理:
1 put:
- put{
- checkResources{
- while (this.memstoreSize.get() > this.blockingMemStoreSize) {
- if(flushRequested==true)
- continue;
- flushRequested = true;
- flushQueue.add(this);
- }
- ...
- }
- ...
- }
2 memstoreFlusher:
- while(!serverstop){
- task = flushQueue.poll();
- if(task == null)
- continue;
- if(closing)
- continue;
- try{
- if(closed)
- continue;
- if(flush(task))
- continue;
- else
- break;
- }finally{
- flushRequested = false;
- }
- }
3 split:
- ...
- closing = true;
- closed = true;
- ...
4 rollback:
- ...
- closing = false;
- closed = false;
- ...
故障还原:当该region执行一次flush时,flushRequested被put线程置为了true,并push一个flush任务。然后memstoreFlusher检查到该任务时,刚好split开始进行,进行到了CLOSED_PARENT_REGION那一步,处于closing状态,于是memstoreflusher跳过任务,但在这里,memstoreflusher仍然报告该任务完成了,于是flush队列被清空。
但split在执行splitStoreFiles时,因为hdfs的问题失败了(具体原因是namenode在close一个文件的时候失败,不停地retry并超时),此时split开始执行回滚,即该region恢复到split之前的状态,于是我们发现该region又重新onlined。
虽然split在rollback的时候会将closing和closed状态置回来,但因为flush队列己然被清空了,于是陷入以下循环:
- put数据的线程,发现需要flush,但flushRequested为true,说明还有flush任务没完成,于是继续等待,并不会提交flush任务
- memstoreFlush的线程,每次取flushQueue都为空,于是循环等待put线程提交flush任务,因此写数据就被block住了
以上悲催的情况将一直持续,直到迎来cleanOldLogs任务。因为cleanOldLogs会每小时执行一次,它会将最早的.logs目录下的文件移到.oldlogs目录下,但移之前先检查该文件中所有的数据是否己经flush到磁盘了,如果还没有就将该region执行一次flush。所以在经过n小时以后,.logs终于滚动到了用户之前卡住的那一段,这时就强制执行flush任务,因此flushQueue队列就不为空了,死循环被打破。系统也就自愈了。