And also, just checked - dfs.namenode.avoid.read.stale.datanode and
dfs.namenode.avoid.write.stale.datanode
are both true, and dfs.namenode.stale.datanode.interval is set to default
30000.
On Mon, Mar 23, 2015 at 10:03 AM Dejan Menges <dejan.men...@gmail.com>
wrote:
> Hi Nicolas,
>
> Please find log attached.
>
> As I see it now more clearly, it was trying to recover HDFS WALs from node
> that's dead:
>
> 2015-03-23 08:53:44,381 WARN org.apache.hadoop.hbase.util.FSHDFSUtils:
> Cannot recoverLease after trying for 900000ms
> (hbase.lease.recovery.timeout); continuing, but may be DATALOSS!!!;
> attempt=40 on
> file=hdfs://{my_hmaster_node}:8020/hbase/WALs/{node_i_intentionally_get_down_by_getting_network_down},60020,1426862900506-splitting/{node_i_intentionally_get_down_by_getting_network_down}%2C60020%2C1426862900506.1427096924508
> after 908210ms
>
> And as you can see from the log, it tried 40 times, what took it exactly
> 15 minutes.
>
> There's probably some parameter to tune to cut it of from 40 times / 15
> minutes to something more useful, as for 15 minutes we don't have our
> regions available, and HDFS have however replication factor 3.
>
> Googling, if I figure out what's this I will post it here. Will also
> appreciate if someone knows how to cut this down.
>
> Thanks,
>
> Dejan
>
> On Fri, Mar 20, 2015 at 3:49 PM Nicolas Liochon <nkey...@gmail.com> wrote:
>
>> The split is done by the region servers (the master coordinates). Is there
>> some interesting stuff in their logs?
>>
>> On Fri, Mar 20, 2015 at 3:38 PM, Dejan Menges <dejan.men...@gmail.com>
>> wrote:
>>
>> > With client issue was that it was retrying connecting to the same region
>> > servers even when they were reassigned. Lowering it down helped in this
>> > specific use case, but yes, we still want servers to reallocate quickly.
>> >
>> > What got me here:
>> >
>> > http://hbase.apache.org/book.html#mttr
>> >
>> > I basically set configuration exactly the same way as it's explained
>> here.
>> > *zookeeper.session.timeout* is (and was before) 60000 (one minute).
>> >
>> > So basically what happens is: - simulating network issues we had
>> recently).
>> > - After short time I see in HBase that my RegionServer is dead, and as
>> > total number of regions I see previous total minus number of regions
>> that
>> > were hosted on the node hosting RegionServer that just 'disappeared'.
>> > - In this point I want my clus
>> >
>> > - I have test cluster consisting of four nodes, every node being
>> DataNode
>> > and RegionServer.
>> > - I simulate network partition on one (connect to it through console and
>> > take network interface downter to recover as soon as possible, to start
>> > serving missing regions.
>> > - First thing I see in HMaster logs are:
>> >
>> > 2015-03-20 14:17:26,015 INFO
>> > org.apache.hadoop.hbase.zookeeper.RegionServerTracker: RegionServer
>> > ephemeral node deleted, processing expiration
>> > [{name_of_node_I_took_down},60020,1426860403261]
>> >
>> > 2015-03-20 14:17:26,067 INFO
>> > org.apache.hadoop.hbase.master.handler.ServerShutdownHandler: Splitting
>> > logs for {name_of_node_I_took_down},60020,1426860403261 before
>> assignment.
>> >
>> > 2015-03-20 14:17:26,105 INFO
>> > org.apache.hadoop.hbase.master.SplitLogManager: dead splitlog workers [
>> > {name_of_node_I_took_down},60020,1426860403261]
>> >
>> > 2015-03-20 14:17:26,107 INFO
>> > org.apache.hadoop.hbase.master.SplitLogManager: started splitting 1
>> logs in
>> > [hdfs://{fqdn_of_hmaster}:8020/hbase/WALs/{name_of_node_I_took_down}
>> > ,60020,1426860403261-splitting]
>> >
>> > 2015-03-20 14:17:26,150 INFO
>> > org.apache.hadoop.hbase.master.SplitLogManager: task
>> > /hbase/splitWAL/WALs%2F
>> > {name_of_node_I_took_down}%2C60020%2C1426860403261-splitting%2F
>> > {name_of_node_I_took_down}%252C60020%252C1426860403261.1426860404905
>> > acquired by {fqdn_of_another_live_hnode},60020,1426859445623
>> >
>> > 2015-03-20 14:17:26,182 INFO
>> > org.apache.hadoop.hbase.master.SplitLogManager: total tasks = 1
>> unassigned
>> > = 0 tasks={/hbase/splitWAL/WALs%2F{name_of_node_I_took_down}
>> >
>> > %2C60020%2C1426860403261-splitting%2F{name_of_node_I_took_
>> down}%252C60020%252C1426860403261.1426860404905=last_update
>> > = 1426861046182 last_version = 2 cur_worker_name =
>> > {fqdn_of_another_live_node},60020,1426859445623 status = in_progress
>> > incarnation = 0 resubmits = 0 batch = installed = 1 done = 0 error = 0}
>> >
>> > 2015-03-20 14:17:31,183 INFO
>> > org.apache.hadoop.hbase.master.SplitLogManager: total tasks = 1
>> unassigned
>> > = 0 tasks={/hbase/splitWAL/WALs%2F{name_of_node_I_took_down}
>> >
>> > %2C60020%2C1426860403261-splitting%2F{name_of_node_I_took_
>> down}%252C60020%252C1426860403261.1426860404905=last_update
>> > = 1426861046182 last_version = 2 cur_worker_name =
>> > {fqdn_of_another_live_node},60020,1426859445623 status = in_progress
>> > incarnation = 0 resubmits = 0 batch = installed = 1 done = 0 error = 0}
>> >
>> > 2015-03-20 14:17:36,184 INFO
>> > org.apache.hadoop.hbase.master.SplitLogManager: total tasks = 1
>> unassigned
>> > = 0 tasks={/hbase/splitWAL/WALs%2F{name_of_node_I_took_down}
>> >
>> > %2C60020%2C1426860403261-splitting%2F{name_of_node_I_took_
>> down}%252C60020%252C1426860403261.1426860404905=last_update
>> > = 1426861046182 last_version = 2 cur_worker_name =
>> > {fqdn_of_another_live_node},60020,1426859445623 status = in_progress
>> > incarnation = 0 resubmits = 0 batch = installed = 1 done = 0 error = 0}
>> >
>> > 2015-03-20 14:17:42,185 INFO
>> > org.apache.hadoop.hbase.master.SplitLogManager: total tasks = 1
>> unassigned
>> > = 0 tasks={/hbase/splitWAL/WALs%2F{name_of_node_I_took_down}
>> >
>> > %2C60020%2C1426860403261-splitting%2F{name_of_node_I_took_
>> down}%252C60020%252C1426860403261.1426860404905=last_update
>> > = 1426861046182 last_version = 2 cur_worker_name =
>> > {fqdn_of_another_live_node},60020,1426859445623 status = in_progress
>> > incarnation = 0 resubmits = 0 batch = installed = 1 done = 0 error = 0}
>> >
>> > 2015-03-20 14:17:48,184 INFO
>> > org.apache.hadoop.hbase.master.SplitLogManager: total tasks = 1
>> unassigned
>> > = 0 tasks={/hbase/splitWAL/WALs%2F{name_of_node_I_took_down}
>> >
>> > %2C60020%2C1426860403261-splitting%2F{name_of_node_I_took_
>> down}%252C60020%252C1426860403261.1426860404905=last_update
>> > = 1426861046182 last_version = 2 cur_worker_name =
>> > {fqdn_of_another_live_node},60020,1426859445623 status = in_progress
>> > incarnation = 0 resubmits = 0 batch = installed = 1 done = 0 error = 0}
>> > In the meantime, In hbase...out log I got this:
>> >
>> > ==> hbase-hbase-master-{fqdn_of_my_hmaster_node}.out <==
>> >
>> > java.io.IOException: Call to
>> > {name_of_node_I_took_down}/{ip_of_local_interface_I_took_down}:60020
>> > failed on local exception:
>> > org.apache.hadoop.hbase.ipc.RpcClient$CallTimeoutException: Call
>> > id=93152, waitTime=60044, rpcTimeout=60000
>> >
>> > at org.apache.hadoop.hbase.ipc.RpcClient.wrapException(RpcClien
>> t.java:1532)
>> >
>> > at org.apache.hadoop.hbase.ipc.RpcClient.call(RpcClient.java:1502)
>> >
>> > at
>> >
>> > org.apache.hadoop.hbase.ipc.RpcClient.callBlockingMethod(Rpc
>> Client.java:1684)
>> >
>> > at
>> >
>> > org.apache.hadoop.hbase.ipc.RpcClient$BlockingRpcChannelImplementati
>> on.callBlockingMethod(RpcClient.java:1737)
>> >
>> > at
>> >
>> > org.apache.hadoop.hbase.protobuf.generated.AdminProtos$AdminService$
>> BlockingStub.getRegionInfo(AdminProtos.java:20806)
>> >
>> > at
>> >
>> > org.apache.hadoop.hbase.client.HBaseAdmin.getCompactionState
>> (HBaseAdmin.java:2524)
>> >
>> > at
>> >
>> > org.apache.hadoop.hbase.generated.master.table_jsp._jspServi
>> ce(table_jsp.java:167)
>> >
>> > at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:98)
>> >
>> > at javax.servlet.http.HttpServlet.service(HttpServlet.java:770)
>> >
>> > at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder
>> .java:511)
>> >
>> > at
>> >
>> > org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilte
>> r(ServletHandler.java:1221)
>> >
>> > at
>> >
>> > org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFil
>> ter.doFilter(StaticUserWebFilter.java:109)
>> >
>> > at
>> >
>> > org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilte
>> r(ServletHandler.java:1212)
>> >
>> > at
>> >
>> > org.apache.hadoop.http.HttpServer$QuotingInputFilter.doFilte
>> r(HttpServer.java:1081)
>> >
>> > at
>> >
>> > org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilte
>> r(ServletHandler.java:1212)
>> >
>> > at org.apache.hadoop.http.NoCacheFilter.doFilter(NoCacheFilter.java:45)
>> >
>> > at
>> >
>> > org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilte
>> r(ServletHandler.java:1212)
>> >
>> > at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandl
>> er.java:399)
>> >
>> > at
>> > org.mortbay.jetty.security.SecurityHandler.handle(SecurityHa
>> ndler.java:216)
>> >
>> > at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandl
>> er.java:182)
>> >
>> > at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandl
>> er.java:766)
>> >
>> > at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.
>> java:450)
>> >
>> > at
>> >
>> > org.mortbay.jetty.handler.ContextHandlerCollection.handle(Co
>> ntextHandlerCollection.java:230)
>> >
>> > at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapp
>> er.java:152)
>> >
>> > at org.mortbay.jetty.Server.handle(Server.java:326)
>> >
>> > at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnectio
>> n.java:542)
>> >
>> > at
>> >
>> > org.mortbay.jetty.HttpConnection$RequestHandler.headerComple
>> te(HttpConnection.java:928)
>> >
>> > at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:549)
>> >
>> > at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:212)
>> >
>> > at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
>> >
>> > at
>> >
>> > org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEn
>> dPoint.java:410)
>> >
>> > at
>> >
>> > org.mortbay.thread.QueuedThreadPool$PoolThread.run(
>> QueuedThreadPool.java:582)
>> >
>> > Caused by: org.apache.hadoop.hbase.ipc.RpcClient$CallTimeoutException:
>> Call
>> > id=93152, waitTime=60044, rpcTimeout=60000
>> >
>> > at
>> >
>> > org.apache.hadoop.hbase.ipc.RpcClient$Connection.cleanupCall
>> s(RpcClient.java:1234)
>> >
>> > at
>> >
>> > org.apache.hadoop.hbase.ipc.RpcClient$Connection.readRespons
>> e(RpcClient.java:1171)
>> >
>> > at org.apache.hadoop.hbase.ipc.RpcClient$Connection.run(RpcClie
>> nt.java:751)
>> > Beside this same issue, please note that first message was at 2015-03-20
>> > 14:17:26,015. And then (we got to the point when it started transition):
>> >
>> > 2015-03-20 14:32:35,059 INFO
>> > org.apache.hadoop.hbase.master.SplitLogManager: task
>> > /hbase/splitWAL/WALs%2F
>> > {name_of_node_I_took_down}%2C60020%2C1426860403261-splitting%2F
>> > {name_of_node_I_took_down}%252C60020%252C1426860403261.1426860404905
>> > entered state: DONE {fqdn_of_new_live_node},60020,1426859445623
>> >
>> > 2015-03-20 14:32:35,109 INFO
>> > org.apache.hadoop.hbase.master.SplitLogManager: Done splitting
>> > /hbase/splitWAL/WALs%2F{name_of_node_I_took_down}
>> > %2C60020%2C1426860403261-splitting%2F{name_of_node_I_took_down}
>> > %252C60020%252C1426860403261.1426860404905
>> >
>> > 2015-03-20 14:32:35,190 INFO
>> > org.apache.hadoop.hbase.master.SplitLogManager: finished splitting
>> (more
>> > than or equal to) 9 bytes in 1 log files in
>> >
>> > [hdfs://{fqdn_of_my_hmaster_node}:8020/hbase/WALs/{name_of_
>> node_I_took_down},60020,1426860403261-splitting]
>> > in 909083ms
>> >
>> > 2015-03-20 14:32:35,191 INFO org.apache.hadoop.hbase.master
>> .RegionStates:
>> > Transitioned {0e7cc87a4ef6c47a779186f5bf79a01c state=OPEN,
>> > ts=1426860639088, server={name_of_node_I_took_down},60020,1426860403261}
>> to
>> > {0e7cc87a4ef6c47a779186f5bf79a01c state=OFFLINE, ts=1426861955191,
>> server=
>> > {name_of_node_I_took_down},60020,1426860403261}
>> >
>> > 2015-03-20 14:32:35,191 INFO org.apache.hadoop.hbase.master
>> .RegionStates:
>> > Offlined 0e7cc87a4ef6c47a779186f5bf79a01c from
>> {name_of_node_I_took_down}
>> > ,60020,1426860403261
>> >
>> > 2015-03-20 14:32:35,191 INFO org.apache.hadoop.hbase.master
>> .RegionStates:
>> > Transitioned {25ab6e7b42e36ddaa723d71be5954543 state=OPEN,
>> > ts=1426860641783, server={name_of_node_I_took_down},60020,1426860403261}
>> to
>> > {25ab6e7b42e36ddaa723d71be5954543 state=OFFLINE, ts=1426861955191,
>> server=
>> > {name_of_node_I_took_down},60020,1426860403261}
>> >
>> > 2015-03-20 14:32:35,191 INFO org.apache.hadoop.hbase.master
>> .RegionStates:
>> > Offlined 25ab6e7b42e36ddaa723d71be5954543 from
>> {name_of_node_I_took_down}
>> > ,60020,1426860403261
>> > At this point, note that it finished SplitLogManager task at 14:32:35
>> and
>> > started transitioning just after that. So this is 15 minutes that I'm
>> > talking about.
>> >
>> > What am I missing?
>> >
>> >
>> > On Fri, Mar 20, 2015 at 2:37 PM Nicolas Liochon <nkey...@gmail.com>
>> wrote:
>> >
>> > > You've changed the value of hbase.zookeeper.timeout to 15 minutes? A
>> very
>> > > reasonable target is 1 minute before relocating the regions. That's
>> the
>> > > default iirc. You can push it to 20s, but then gc-stopping-the-world
>> > > becomes more of an issue. 15 minutes is really a lot. The hdfs stale
>> mode
>> > > must always be used, with a lower timeout than the hbase one.
>> > >
>> > > Client side there should be nothing to do (excepted for advanced
>> stuff);
>> > at
>> > > each retry the client checks the location of the regions. If you lower
>> > the
>> > > number of retry the client will fail sooner, but usually you don't
>> want
>> > the
>> > > client to fail, you want the servers to reallocate quickly.
>> > >
>> > > On Fri, Mar 20, 2015 at 1:36 PM, Dejan Menges <dejan.men...@gmail.com
>> >
>> > > wrote:
>> > >
>> > > > Hi,
>> > > >
>> > > > Sorry for little bit late update, but managed to narrow it little
>> bit
>> > > down.
>> > > >
>> > > > We didn't update yet, as we are using Hortonworks distribution right
>> > now,
>> > > > and even if we update we will get 0.98.4. However, looks that issue
>> > here
>> > > > was in our use case and configuration (still looking into it).
>> > > >
>> > > > Basically, initially I saw that when one server goes down, we start
>> > > having
>> > > > performance issues in general, but it managed to be on our client
>> side,
>> > > due
>> > > > to caching, and clients were trying to reconnect to nodes that were
>> > > offline
>> > > > and later trying to get regions from those nodes too. This is
>> basically
>> > > why
>> > > > on server side I didn't manage to see anything in logs that would
>> be at
>> > > > least little bit interesting and point me into desired direction.
>> > > >
>> > > > Another question that popped up to me is - in case server is down
>> (and
>> > > with
>> > > > it DataNode and HRegionServer it was hosting) - what's optimal time
>> to
>> > > set
>> > > > for HMaster to consider server dead reassign regions somewhere
>> else, as
>> > > > this is another performance bottleneck we hit during inability to
>> > access
>> > > > regions? In our case it's configured to 15 minutes, and simple logic
>> > > tells
>> > > > me if you want it earlier then configure lower number of retries,
>> but
>> > > issue
>> > > > is as always in details, so not sure if anyone knows some better
>> math
>> > for
>> > > > this?
>> > > >
>> > > > And last question - is it possible to manually force HBase to
>> reassign
>> > > > regions? In this case, while HMaster is retrying to contact node
>> that's
>> > > > dead, it's impossible to force it using 'balancer' command.
>> > > >
>> > > > Thanks a lot!
>> > > >
>> > > > Dejan
>> > > >
>> > > > On Tue, Mar 17, 2015 at 9:37 AM Dejan Menges <
>> dejan.men...@gmail.com>
>> > > > wrote:
>> > > >
>> > > > > Hi,
>> > > > >
>> > > > > To be very honest - there's no particular reason why we stick to
>> this
>> > > > one,
>> > > > > beside just lack of time currently to go through upgrade process,
>> but
>> > > > looks
>> > > > > to me that's going to be next step.
>> > > > >
>> > > > > Had a crazy day, didn't have time to go through all logs again,
>> plus
>> > > one
>> > > > > of the machines (last one where we had this issue) is fully
>> > > reprovisioned
>> > > > > yesterday so I don't have logs from there anymore.
>> > > > >
>> > > > > Beside upgrading, what I will talk about today, can you just
>> point
>> > me
>> > > to
>> > > > > the specific RPC issue in 0.98.0? Thing is that we have some
>> strange
>> > > > > moments with RPC in this case, and just want to see if that's the
>> > same
>> > > > > thing (and we were even suspecting to RPC).
>> > > > >
>> > > > > Thanks a lot!
>> > > > > Dejan
>> > > > >
>> > > > > On Mon, Mar 16, 2015 at 9:32 PM, Andrew Purtell <
>> apurt...@apache.org
>> > >
>> > > > > wrote:
>> > > > >
>> > > > >> Is there a particular reason why you are using HBase 0.98.0? The
>> > > latest
>> > > > >> 0.98 release is 0.98.11. There's a known performance issue with
>> > 0.98.0
>> > > > >> pertaining to RPC that was fixed in later releases, you should
>> move
>> > up
>> > > > >> from
>> > > > >> 0.98.0. In addition hundreds of improvements and bug fixes have
>> gone
>> > > > into
>> > > > >> the ten releases since 0.98.0.
>> > > > >>
>> > > > >> On Mon, Mar 16, 2015 at 6:40 AM, Dejan Menges <
>> > dejan.men...@gmail.com
>> > > >
>> > > > >> wrote:
>> > > > >>
>> > > > >> > Hi All,
>> > > > >> >
>> > > > >> > We have a strange issue with HBase performance (overall cluster
>> > > > >> > performance) in case one of datanodes in the cluster
>> unexpectedly
>> > > goes
>> > > > >> > down.
>> > > > >> >
>> > > > >> > So scenario is like follows:
>> > > > >> > - Cluster works fine, it's stable.
>> > > > >> > - One DataNode unexpectedly goes down (PSU issue, network
>> issue,
>> > > > >> anything)
>> > > > >> > - Whole HBase cluster goes down (performance becomes so bad
>> that
>> > we
>> > > > >> have to
>> > > > >> > restart all RegionServers to get it back to life).
>> > > > >> >
>> > > > >> > Most funny and latest issue that happened was that we added new
>> > node
>> > > > to
>> > > > >> the
>> > > > >> > cluster (having 8 x 4T SATA disks) and we left just DataNode
>> > running
>> > > > on
>> > > > >> it
>> > > > >> > to give it couple of days to get some data. At some point in
>> time,
>> > > due
>> > > > >> to
>> > > > >> > hardware issue, server rebooted (twice during three hours) in
>> > moment
>> > > > >> when
>> > > > >> > it had maybe 5% of data it would have in a couple of days.
>> Nothing
>> > > > else
>> > > > >> > beside DataNode was running, and once it went down, it affected
>> > > > literary
>> > > > >> > everything, and restarting RegionServers in the end fixed it.
>> > > > >> >
>> > > > >> > We are using HBase 0.98.0 with Hadoop 2.4.0
>> > > > >> >
>> > > > >>
>> > > > >>
>> > > > >>
>> > > > >> --
>> > > > >> Best regards,
>> > > > >>
>> > > > >> - Andy
>> > > > >>
>> > > > >> Problems worthy of attack prove their worth by hitting back. -
>> Piet
>> > > Hein
>> > > > >> (via Tom White)
>> > > > >>
>> > > > >
>> > > > >
>> > > >
>> > >
>> >
>>
>
