env:
hbase,94.26
zookeeper,3.4.3
---------------
1.downed node
? this morning we found a regionserver(host-34) downed in our monitor.so we dived into the logs of hbase and found that in this host:
?
2016-02-29 00:50:36,799 INFO [regionserver60020-SendThread(host-04:2181)] ClientCnxn.java:1083 Client session timed out, have not heard from server in 60030ms for sessionid 0x4511b9
? ?that means during this period,the read timeout has been touched.
?
? this timeout is settled by this:
?
readtimeout=negotiatedtimeout(client[18000 by default in hbase],server[60000,90000]) * 2/3
? ?so it‘s set to 60 secs.(negotiatedtimeout=90 secs)
?
? and conn timeout:
?
conn timeout=negotiatedtimeout / host provider
? ?we have five nodes of a quorum,so it‘s set to 90/5=18 secs.
?
?
? after a few retries,(note:the start time of this connection was at 00:49:36)
?
host-34,hbase: 2016-02-29 00:50:36,799 INFO [regionserver60020-SendThread(host-04:2181)] ClientCnxn.java:1083 Client session timed out, have not heard from server in 60030ms for sessionid 0x4511b9 duration== 2016-02-29 00:50:44,540 INFO [regionserver60020-SendThread(host-07:2181)] ClientCnxn.java:966 Opening socket connection to server host-07/192.168.100.117:2181. Will not attempt to a uthenticate using SASL (Unable to locate a login configuration) … 2016-02-29 00:51:02,559 INFO [regionserver60020-SendThread(host-07:2181)] ClientCnxn.java:1083 Client session timed out, have not heard from server in **18790ms** for sessionid 0x4511b9 3876c000b, closing socket connection and attempting reconnect
? ?(the period time 18 secs is computed by above connectedtimeout.)
?
?
? a network paritition was shown here:
?
2016-02-29 00:50:40,499 WARN [regionserver60020-SendThread(host-05:2181)] ClientCnxn.java:1089 Session 0x4511b93876c000b for server null, unexpected error, closing socket connection and attempting reconnect java.net.NoRouteToHostException: No route to host at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:567) at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:350) at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1068)
?
?
? so then we dived into the last zk‘s log from the last request from hbase SendThread:
?
host-04,zookeeper: 2016-02-29 00:51:25,764 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@213] - Accepted socket connection from /192.168.100.147:58100 2016-02-29 00:51:25,765 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@831] - Client attempting to renew session 0x4511b93876c000b at /192.168.100.147:5 8100 2016-02-29 00:51:25,765 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:Learner@107] - Revalidating client: 0x4511b93876c000b 2016-02-29 00:51:25,766 [myid:2] - INFO [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@597] - Invalid session 0x4511b93876c000b for client /192.168.100.147:58100, probabl y expired 2016-02-29 00:51:25,766 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1000] - Closed socket connection for client /192.168.100.147:58100 which had session nid 0x4511b93876c000b
? ?untill here,the time period is for :51:25-49:36 ~ 110 secs >> 90 secs(timeout set above),so this session timeout was settled to expired.
?
? that means this session should be timeouted at this timestamp:
?
session touch time + negotiatedtimeout = expired timestamp = 49:36 + 90 secs ~ 51:06
? ?for sure,we found that in this zookeeper one line at this timestamp was present in front of us:
?
?
host-05,zookeeper: 2016-02-29 00:51:08,000 [myid:3] - INFO [SessionTracker:ZooKeeperServer@334] - Expiring session 0x4511b93876c000b, timeout of 90000ms exceeded
?
?
2.another node which reconnected successfully to zk during this timeout.
?
host-33,hbase:(so this hbase keep on running ) 2016-02-29 00:50:55,864 INFO [regionserver60020-SendThread(host-03:2181)] ClientCnxn.java:1207 Session establishment complete on server host-03/192.168.100.113:2181, sessionid = 0x4 0x4511b93876c000b
? ?it‘s printed at 50:55 << 51:06,so it keeps on running with happy.
?
?
3.conclusion
a.set the connect timeout the :one / hostproviderTH for all reconnect to all nodes in this quorum
b.as of case a,so the whole connected timeout + readtimeout will longer than the negotiatedtimeout:
?
read time-out =negotiaedtimeout * 2/ 3 read timeout + (negotiatedtimeout / host provider ) * Nr > negotiatedtimeout Nr = retried times
?so in for one extreme cases:
?
? if all nodes in zk‘s quorum are disconnectable,that will cause double time of negotiaredtimeout.
c.so based on b,why set the this mechanism ?
? if zk switch this solution:(this means the whole read and connect timeout are equals to negotiatedtimeout)
connecttimeout= (negotiateedtimeout- readtimeout) /hostprovider
? ?ie.
----------negotiatedtimeout------------------|
------connecttieout-------| retry1|retry2....|
? ?if some cases similar to here,u will lost chance to know what‘s wrong with hbase/zk,instead of showing :
retry connecting but timeout ,retry connecting but timeout....than the rs was shutdowned forcely ,that is it.
?
?
ref:
原文：http://leibnitz.iteye.com/blog/2279522