[转帖]多线程下使用htable，当region server挂了client端重试很长时间_Tomcat, WebLogic及J2EE讨论区_Weblogic技术|Tuxedo技术|中间件技术|Oracle论坛|JAVA论坛|Linux/Unix技术|hadoop论坛

总帖数

每页帖数

1/1页

返回列表

发起投票

查看: 3042 | 回复: 0

主题： [转帖]多线程下使用htable，当region server挂了client端重试很长时间

white

注册用户

等级：少校
经验：1327
发帖：305
精华：0
注册：2011-7-21
状态：离线
发送短消息息给white

加好友发送短消息息给white

发消息

发表于：

2015-3-18 17:58:15 | [全部帖] [楼主帖]

楼主

今天遇到一个问题，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)方法，里面具体分为四步:

将所有请求按region server分组
发送请求
收集返回结果，准备重试
识别错误信息（deleteCachedLocation方法中会删除返回失败结果的rs缓存），准备重试，跳到4.1进行重试
返回结果在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。

getConnection调用中对相同addr, protocol, ticket, rpcTimeout的线程会复用一个connection，以提高性能
通过hbase.client.ipc.pool.size可以设置PoolMap connections的大小，一定程序上能提高并行度。这里的PoolMap是PoolType.RoundRobin类型，对相同的ConnectionId每次调用返回不同的connection。
setupIOstreams()方法作用是调用setupConnection()连接到Region Servier服务器，设置IO流。接着发送文件头到服务器，然后启动连接线程接收服务器数据。要注意的是这两个方法都是同步的。
在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设置的小一点也可以减少重试的时间。

--转自