Server端处理时间很长，Client发生SocketTimeoutException

Client端只有一个put请求，往server端写数据，server端处理时间过长，导致client端SocketTimeoutException

 

0.94版本

 

Client端发生异常SocketTimeoutException：

 

12/11/20 19:03:18 WARN client.HConnectionManager$HConnectionImplementation: Failed all from region=myLittleHBaseTable,,1353401128907.2879da4a2d609943473a2421520732cb., hostname=ubuntu, port=60020
java.util.concurrent.ExecutionException: java.net.SocketTimeoutException: Call to ubuntu/0:0:0:0:0:0:0:1:60020 failed on socket timeout exception: java.net.SocketTimeoutException: 60000 millis timeout while waiting for channel to be ready for read. ch : java.nio.channels.SocketChannel[connected local=/0:0:0:0:0:0:0:1:42426 remote=ubuntu/0:0:0:0:0:0:0:1:60020]
     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:1553)
     at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation.processBatch(HConnectionManager.java:1376)
     at org.apache.hadoop.hbase.client.HTable.flushCommits(HTable.java:937)
     at org.apache.hadoop.hbase.client.HTable.doPut(HTable.java:793)
     at org.apache.hadoop.hbase.client.HTable.put(HTable.java:768)
     at updateTest.put(updateTest.java:61)
     at updateTest.main(updateTest.java:96)
Caused by: java.net.SocketTimeoutException: Call to ubuntu/0:0:0:0:0:0:0:1:60020 failed on socket timeout exception: java.net.SocketTimeoutException: 60000 millis timeout while waiting for channel to be ready for read. ch : java.nio.channels.SocketChannel[connected local=/0:0:0:0:0:0:0:1:42426 remote=ubuntu/0:0:0:0:0:0:0:1:60020]
     at org.apache.hadoop.hbase.ipc.HBaseClient.wrapException(HBaseClient.java:960)
     at org.apache.hadoop.hbase.ipc.HBaseClient.call(HBaseClient.java:933)
     at org.apache.hadoop.hbase.ipc.WritableRpcEngine$Invoker.invoke(WritableRpcEngine.java:147)
     at $Proxy4.multi(Unknown Source)
     at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation$3$1.call(HConnectionManager.java:1353)
     at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation$3$1.call(HConnectionManager.java:1351)
     at org.apache.hadoop.hbase.client.ServerCallable.withoutRetries(ServerCallable.java:210)
     at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation$3.call(HConnectionManager.java:1360)
     at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation$3.call(HConnectionManager.java:1348)
     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)
Caused by: java.net.SocketTimeoutException: 60000 millis timeout while waiting for channel to be ready for read. ch : java.nio.channels.SocketChannel[connected local=/0:0:0:0:0:0:0:1:42426 remote=ubuntu/0:0:0:0:0:0:0:1:60020]
     at org.apache.hadoop.net.SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:164)
     at org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:155)
     at org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:128)
     at java.io.FilterInputStream.read(FilterInputStream.java:116)
     at java.io.FilterInputStream.read(FilterInputStream.java:116)
     at org.apache.hadoop.hbase.ipc.HBaseClient$Connection$PingInputStream.read(HBaseClient.java:318)
     at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
     at java.io.BufferedInputStream.read(BufferedInputStream.java:237)
     at java.io.DataInputStream.readInt(DataInputStream.java:370)
     at org.apache.hadoop.hbase.ipc.HBaseClient$Connection.receiveResponse(HBaseClient.java:578)
     at org.apache.hadoop.hbase.ipc.HBaseClient$Connection.run(HBaseClient.java:512)

 

 

 

HBaseClient的Connection一直在等待response，然后过了60000ms后，接收到SocketTimeoutException异常

 

 

    @Override

    public void run() {

      if (LOG .isDebugEnabled())

        LOG.debug(getName() + ": starting, having connections "

            + connections.size());

      try {

        while (waitForWork()) {//wait here for work - read or close connection

          receiveResponse();

        }

      } catch (Throwable t) {

        LOG.warn("Unexpected exception receiving call responses" , t);

        markClosed( new IOException("Unexpected exception receiving call responses" , t));

      }

      close();

      if (LOG .isDebugEnabled())

        LOG.debug(getName() + ": stopped, remaining connections "

            + connections.size());

    }

 

我们可以看到在receiveResponse里面不会close掉这个connection，会把call从calls队列里面remove掉，所以导致calls队列为空，但是接着会执行waitForWork 

 

 

    /* wait till someone signals us to start reading RPC response or

     * it is idle too long, it is marked as to be closed,

     * or the client is marked as not running.

     *

     * Return true if it is time to read a response; false otherwise.

     */

    @SuppressWarnings({ "ThrowableInstanceNeverThrown" })

    protected synchronized boolean waitForWork () {

      if (calls .isEmpty() && !shouldCloseConnection.get()  && running.get())  {

        long timeout = maxIdleTime -

              (System. currentTimeMillis()-lastActivity.get());

        if (timeout>0) {

          try {

            wait(timeout);

          } catch (InterruptedException ignored) {}

        }

      }

      if (!calls .isEmpty() && !shouldCloseConnection.get() && running.get()) {

        return true ;

      } else if (shouldCloseConnection.get()) {

        return false ;

      } else if (calls.isEmpty()) { // idle connection closed or stopped

        long timeout = maxIdleTime

            - (System. currentTimeMillis() - lastActivity.get());

        LOG.info("timeout " + timeout);

        markClosed( null);

        return false ;

      } else { // get stopped but there are still pending requests

        markClosed((IOException) new IOException().initCause(

            new InterruptedException()));

        return false ;

      }

    }

在waitForWork 里面会计算timeout， （ long timeout = maxIdleTime -   (System. currentTimeMillis()-lastActivity.get()); ）这里的timeout得出来的结果为 负值，因为上次lastActivity的时间是在读取请求前运行的，中间一直等待server端的请求超过60000ms才超时接收到SocketTimeoutException异常才往下执行的，所以这里的 (System. currentTimeMillis()-lastActivity.get())是超过60000ms的，导致waitForWork会执行markClosed，close掉connection。

      } else if (calls.isEmpty()) { // idle connection closed or stopped

        markClosed(null);

        return false;

      }

    /* Receive a response.

     * Because only one receiver, so no synchronization on in.

     */

    protected void receiveResponse() {

      if (shouldCloseConnection.get()) {

        return;

      }

      touch();

      try {

        // See HBaseServer.Call.setResponse for where we write out the response.

        // It writes the call.id (int), a flag byte, then optionally the length

        // of the response (int) followed by data.

        // Read the call id.

        int id = in.readInt();

    }

    /** Update lastActivity with the current time. */

    protected void touch() {

      lastActivity.set(System.currentTimeMillis());

    }

client端关闭connection后，server端会抛出异常：

2012-11-20 20:54:46,825 WARN org.apache.hadoop.ipc.HBaseServer: (responseTooSlow): {"processingtimems":60370,"call":"multi(#size=1#myLittleHBaseTable,,1353401128907.2879da4a2d609943473a2421520732cb.{\"totalColumns\":1,\"families\":{\"myLittleFamily\":[{\"timestamp\":1353473626453,\"qualifier\":\"someQualifier\",\"vlen\":14}]},\"row\":\"myLittleRow1010001\"}#), rpc version=1, client version=29, methodsFingerPrint=-56040613","client":"0:0:0:0:0:0:0:1:42779","starttimems":1353473626452,"queuetimems":0,"class":"HRegionServer","responsesize":0,"method":"multi"}
2012-11-20 20:54:47,256 WARN org.apache.hadoop.ipc.HBaseServer: IPC Server listener on 60020: readAndProcess threw exception java.io.IOException: Connection reset by peer. Count of bytes read: 0
java.io.IOException: Connection reset by peer
        at sun.nio.ch.FileDispatcher.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:202)
        at sun.nio.ch.IOUtil.read(IOUtil.java:175)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:243)
        at org.apache.hadoop.hbase.ipc.HBaseServer.channelRead(HBaseServer.java:2119)
        at org.apache.hadoop.hbase.ipc.HBaseServer$Connection.readAndProcess(HBaseServer.java:1394)
        at org.apache.hadoop.hbase.ipc.HBaseServer$Listener.doRead(HBaseServer.java:956)
        at org.apache.hadoop.hbase.ipc.HBaseServer$Listener$Reader.doRunLoop(HBaseServer.java:745)
        at org.apache.hadoop.hbase.ipc.HBaseServer$Listener$Reader.run(HBaseServer.java:720)
        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)

2012-11-20 20:55:48,532 WARN org.apache.hadoop.ipc.HBaseServer: (responseTooSlow): {"processingtimems":60252,"call":"multi(#size=1#myLittleHBaseTable,,1353401128907.2879da4a2d609943473a2421520732cb.{\"totalColumns\":1,\"families\":{\"myLittleFamily\":[{\"timestamp\":1353473688277,\"qualifier\":\"someQualifier\",\"vlen\":14}]},\"row\":\"myLittleRow1010001\"}#), rpc version=1, client version=29, methodsFingerPrint=-56040613","client":"0:0:0:0:0:0:0:1:42785","starttimems":1353473688277,"queuetimems":0,"class":"HRegionServer","responsesize":0,"method":"multi"}
2012-11-20 20:55:48,548 WARN org.apache.hadoop.ipc.HBaseServer: IPC Server Responder, call multi(#size=1#myLittleHBaseTable,,1353401128907.2879da4a2d609943473a2421520732cb.{"totalColumns":1,"families":{"myLittleFamily":[{"timestamp":1353473688277,"qualifier":"someQualifier","vlen":14}]},"row":"myLittleRow1010001"}#), rpc version=1, client version=29, methodsFingerPrint=-56040613 from 0:0:0:0:0:0:0:1:42785: output error
2012-11-20 20:55:48,549 WARN org.apache.hadoop.ipc.HBaseServer: IPC Server handler 5 on 60020 caught a ClosedChannelException, this means that the server was processing a request but the client went away. The error message was: null

所以Server端的异常： Connection reset by peer，以及ClosedChannelException可能是因为server端处理时间过长，导致client端close掉connection，server端处理结束后再往client发送response时而出现。

还有的原因就是kill掉了client，server端处理结束后再往client发送response时而出现。