多线程下使用htable,当region server挂了client端重试很长时间

今天遇到一个问题,hbase集群(版本是hbase 0.94.5)中有一台Region Server由于硬件问题宕机,但是往这台RS机器写数据的应用程序不停的重试了近40分钟才重试成功。按说,在正常情况下,hbase几分钟最多十几分钟能转移挂掉的RS机器上的数据,应用程序很快就能发现问题,不用重试40分钟这么久。

1. master日志

查看master日志,发现从17:20发现test032034.cm1这台机器有问题,经过spilt log等操作,到17:38分这台机器上的region已经重新分配到了其他机器上。

2013-06-05 17:20:24,014 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: based on AM, current region=.META.,,1.1028785192 is on server=test036024.cm1,30020,1370358473264 server being checked: test032034.cm1,30020,1370358473360
……
2013-06-05 17:38:11,570 INFO org.apache.hadoop.hbase.master.handler.ServerShutdownHandler: Reassigning 49 region(s) that test032034.cm1,30020,1370358473360 was carrying (skipping 0 regions(s) that are already in transition)
……
2013-06-05 17:38:14,614 INFO org.apache.hadoop.hbase.master.handler.ServerShutdownHandler: Finished processing of shutdown of test032034.cm1,30020,1370358473360

2. 应用程序异常log

由于暂时无法查看到挂掉的机器上Region Server的日志。应用程序抛出的异常信息如下:

2013-06-05 18:08:39,371 INFO org.apache.hadoop.ipc.HBaseRPC: Problem connecting to server: test032034.cm1/10.10.32.34:30020
2013-06-05 18:09:01,375 INFO org.apache.hadoop.ipc.HBaseRPC: Problem connecting to server: test032034.cm1/10.10.32.34:30020
2013-06-05 18:09:23,382 INFO org.apache.hadoop.ipc.HBaseRPC: Problem connecting to server: test032034.cm1/10.10.32.34:30020
2013-06-05 18:09:23,382 WARN org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation: Failed all from region=msgtable,024:,1370375054809.534a50ac1d7215fc3df442da9c234fb8., hostname=test032034.cm1, port=30020
java.util.concurrent.ExecutionException: java.net.SocketTimeoutException: 20000 millis timeout while waiting for channel to be ready for connect. ch : java.nio.channels.SocketChannel[connection-pending remote=test032034.cm1/10.10.32.34:30020]
at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:222)
at java.util.concurrent.FutureTask.get(FutureTask.java:83)
at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation
.processBatchCallback(HConnectionManager.java:1566)
at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation
.processBatch(HConnectionManager.java:1418)
at org.apache.hadoop.hbase.client.HTable.batch(HTable.java:730)
at com.auction.dump.instant.queue.HBaseTableQueue.batchPut(HBaseTableQueue.java:59)
at com.auction.dump.instant.loader.MessageQueueWriter.handler(MessageQueueWriter.java:54)
at com.auction.dump.instant.loader.ProcessThread.doProcess(ProcessThread.java:160)
at com.auction.dump.instant.loader.ProcessThread.run(ProcessThread.java:90)
Caused by: java.net.SocketTimeoutException: 20000 millis timeout while waiting for channel to be ready for connect. ch : java.nio.channels.SocketChannel[connection-pending remote=test032034.cm1/10.10.32.34:30020]
at org.apache.hadoop.net.SocketIOWithTimeout.connect(SocketIOWithTimeout.java:214)
at org.apache.hadoop.net.NetUtils.connect(NetUtils.java:523)
at org.apache.hadoop.net.NetUtils.connect(NetUtils.java:488)
at org.apache.hadoop.hbase.ipc.HBaseClient$Connection.setupConnection(HBaseClient.java:390)
at org.apache.hadoop.hbase.ipc.HBaseClient$Connection.setupIOstreams(HBaseClient.java:436)
at org.apache.hadoop.hbase.ipc.HBaseClient.getConnection(HBaseClient.java:1124)
at org.apache.hadoop.hbase.ipc.HBaseClient.call(HBaseClient.java:974)
at org.apache.hadoop.hbase.ipc.WritableRpcEngine$Invoker.invoke(WritableRpcEngine.java:86)
at $Proxy13.getProtocolVersion(Unknown Source)
at org.apache.hadoop.hbase.ipc.WritableRpcEngine.getProxy(WritableRpcEngine.java:138)
at org.apache.hadoop.hbase.ipc.HBaseRPC.waitForProxy(HBaseRPC.java:208)
at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation
.getHRegionConnection(HConnectionManager.java:1335)
at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation
.getHRegionConnection(HConnectionManager.java:1294)
at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation
.getHRegionConnection(HConnectionManager.java:1281)
at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation$3$1
.connect(HConnectionManager.java:1399)
at org.apache.hadoop.hbase.client.ServerCallable.withoutRetries(ServerCallable.java:209)
at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation$3
.call(HConnectionManager.java:1402)
at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation$3
.call(HConnectionManager.java:1390)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
以上的log信息去除了一些不相关的内容。

程序从2013-06-05 17:34:10开始抛出这样的异常,一直到2013-06-05 18:12:42分才恢复正常,共经过了38分钟。从这个log中可以看到应用程序一直在连挂掉的那台RS机器。

还可以看到一个有趣的现象:每打印3次的rpc连接错误“org.apache.hadoop.ipc.HBaseRPC: Problem connecting to server:”后会出现“HConnectionImplementation: Failed all from region=”的异常。

3. 原因分析

看了下应用程序的代码,发现是个多线程程序,有29个线程会写msgtable表,还有其他线程写uic表。考虑到htable不是线程安全的,在每个线程中new了一个htable,通过batch put的方式往hbase的两张表写入数据。在和同事道凡,叶重一起看了hbase的源代码后,定位了原因。 整个batch put操作的请求过程是这样的:

(3.1) client端调用htable.batch(putList)批量写入数据到hbase

(3.2) 调用HTable的Object[] batch(final List<? extends Row> actions)方法

(3.3) 调用HConnectionImplementation的processBatch(List<? extends Row> list,final byte[] tableName,ExecutorService pool, Object[] results)方法

(3.4) 调用HConnectionImplementation的processBatchCallback(List<? extends Row> list,byte[] tableName,ExecutorService pool,Object[] results,Batch.Callback callback)方法,里面具体分为四步:

  1. 将所有请求按region server分组
  2. 发送请求
  3. 收集返回结果,准备重试
  4. 识别错误信息(deleteCachedLocation方法中会删除返回失败结果的rs缓存),准备重试,跳到4.1进行重试
  5. 返回结果在result数据中或者抛出异常RetriesExhaustedWithDetailsException

(3.5) 在4.2步会调用HConnectionImplementation的createCallable方法中的callable.withoutRetries()

(3.6) 调用ServerCallable的withoutRetries方法,其中有个connect(false);注意:connect方法在第5步已经被重写

(3.7) 调用HConnectionImplementation的getHRegionConnection(final String hostname, final int port,final InetSocketAddress isa, final boolean master)。

(3.8) 调用HBaseRPC的waitForProxy。在一个while(true)循环中调用rpcClient.getProxy(protocol, clientVersion, addr, conf, rpcTimeout);接着调用Invoker的invoke方法。这里的rpcTimeout默认是60秒(可通过hbase.rpc.timeout设置)。

(3.9) 调用WritableRpcEngine.getProxy和invoke方法

(3.10) 调用HBaseClient中的call和getConnection。

  1. getConnection调用中对相同addr, protocol, ticket, rpcTimeout的线程会复用一个connection,以提高性能
  2. 通过hbase.client.ipc.pool.size可以设置PoolMap connections的大小,一定程序上能提高并行度。这里的PoolMap是PoolType.RoundRobin类型,对相同的ConnectionId每次调用返回不同的connection。
  3. setupIOstreams()方法作用是调用setupConnection()连接到Region Servier服务器,设置IO流。接着发送文件头到服务器,然后启动连接线程接收服务器数据。要注意的是这两个方法都是同步的。
  4. 在setupConnection()中会调用NetUtils.connect(this.socket, remoteId.getAddress(), getSocketTimeout(conf))连接RS服务器。这个地方的超时时间是20s(可通过ipc.socket.timeout设置)。如果超过20s,会调用SocketIOWithTimeout抛出异常“java.net.SocketTimeoutException: 20000 millis timeout while waiting for channel to be ready for connect. ch ”。

可以看到:在第8步中会一直等到超时时间超过60s才会退出循环。而第10.4步的调用超时是20s,所以在第8步中会调用60/20=3次才会退出循环。这也就能解释了,为什么我们在程序异常log里面观察到的“每打印3次的rpc连接错误后出现一次SocketTimeoutException”

4. 总结

通过上面的分析,根本原因是多线程下使用htable,对同一个Region Server会有一个connectLock锁(在第7步),导致并行的调用变成了串行。而由于hbase.rpc.timeout=60000ms,而ipc.socket.timeout=20000ms,会导致每次调用重试三次。这样,29个线程调用花的时间是 29x3x20s=29min。再加上程序中还有其他的线程也往这个region server上写数据了,总共的重试时间加起来就是半个多小时了。

解决方法:通过减少hbase对象的数量能减少重试的时间。

另外看了下HTablePool的代码(详见HTablePool的使用和源码分析),发现其内部采用了ConcurrentLinkedQueue来保存htable,只是为了做到在多线程下的线程安全,但是仍然会遇到这个问题,因为pool中的htable之间仍然会共享连接,内部请求还是串行的。在使用HTablePool的时候可以将size设置的小一点也可以减少重试的时间。

发表评论

电子邮件地址不会被公开。 必填项已用*标注