hbase-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Ted Yu <yuzhih...@gmail.com>
Subject Re: Some regions never get online after a region server crashes
Date Sat, 04 Jun 2016 10:55:08 GMT
I think this sounds like a bug.

Search in HBase JIRA first. If there is no JIRA with the same symptom,
consider filing one.

Cheers

On Fri, Jun 3, 2016 at 1:10 AM, Shuai Lin <linshuai2012@gmail.com> wrote:

> Hi Ted,
>
> I'm kind of confused, so is this normal behaviour or a bug of hbase? For
> me it looks like a bug, should I fire a JIRA?
>
> Thanks,
>
> Shuai
>
> On Fri, May 27, 2016 at 8:02 PM, Ted Yu <yuzhihong@gmail.com> wrote:
>
>> There were 7 regions Master tried to close which were opening but not
>> yet served.
>>
>> d1c7f3f455f2529da82a2f713b5ee067 was one of them.
>>
>> On Fri, May 27, 2016 at 12:47 AM, Shuai Lin <linshuai2012@gmail.com>
>> wrote:
>>
>>> Here is the complete log on node6 between 13:10:47 and 13:11:47:
>>> http://paste.openstack.org/raw/505826/
>>>
>>> The master asked node6 to open several regions. Node6 opened the first 4
>>> very fast (within 1 seconsd) and got stuck at the 5th one. But there is no
>>> errors at that time.
>>>
>>> On Wed, May 25, 2016 at 10:12 PM, Ted Yu <yuzhihong@gmail.com> wrote:
>>>
>>>> In AssignmentManager#assign(), you should find:
>>>>
>>>>           // Send OPEN RPC. If it fails on a IOE or RemoteException,
>>>>           // regions will be assigned individually.
>>>>           long maxWaitTime = System.currentTimeMillis() +
>>>>             this.server.getConfiguration().
>>>>               getLong("hbase.regionserver.rpc.startup.waittime", 60000);
>>>>
>>>> BTW can you see what caused rs-node6 to not respond around 13:11:47 ?
>>>>
>>>> Cheers
>>>>
>>>> On Fri, May 20, 2016 at 6:20 AM, Shuai Lin <linshuai2012@gmail.com>
>>>> wrote:
>>>>
>>>>> Because of the "opening regions" rpc call sent by master to the region
>>>>> server node6 got timed out after 1 minutes?
>>>>>
>>>>> *RPC call was sent:*
>>>>>
>>>>> 2016-04-30 13:10:47,702 INFO org.apache.hadoop.hbase.master.AssignmentManager:
>>>>> Assigning 22 region(s) tors-node6.example.com,60020,1458723856883
>>>>>
>>>>> *After 1 minute:*
>>>>>
>>>>> 2016-04-30 13:11:47,780 INFO
>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Unable to communicate
>>>>> with rs-node6.example.com,60020,1458723856883 in order to assign
>>>>> regions, java.io.IOException: Call to
>>>>> rs-node6.example.com/172.16.6.6:60020 failed on local exception:
>>>>> org.apache.hadoop.hbase.ipc.CallTimeoutException: Call id=4,
>>>>> waitTime=60001, operationTimeout=60000 expired.
>>>>>
>>>>> 2016-04-30 13:11:47,783 DEBUG
>>>>> org.apache.hadoop.hbase.master.AssignmentManager: Force region state
>>>>> offline {d1c7f3f455f2529da82a2f713b5ee067 state=PENDING_OPEN,
>>>>> ts=1462021847743, server=rs-node6.example.com,60020,1458723856883}
>>>>>
>>>>>
>>>>> I have checked hbase source code, but don't find any specific timeout
>>>>> settings for "open region" rpc call I can use. So I guess the it's using
>>>>> the default "hbase.rpc.timeout", which defaults to 60secs. And since
there
>>>>> are 20+ regions being assigned to node6 almost at the same moment, node6
>>>>> gets overloaded and can't finish opening all of them within one minute.
>>>>>
>>>>> So this looks like a hbase bug to me (regions never get online when
>>>>> the region server failed to handle the OpenRegionRequest before the rpc
>>>>> timeout), am I right?
>>>>>
>>>>>
>>>>> On Fri, May 20, 2016 at 12:42 PM, Ted Yu <yuzhihong@gmail.com>
wrote:
>>>>>
>>>>>> Looks like region d1c7f3f455f2529da82a2f713b5ee067 received CLOSE
>>>>>> request
>>>>>> when it was opening, leading to RegionAlreadyInTransitionException.
>>>>>>
>>>>>> Was there any clue in master log why the close request was sent ?
>>>>>>
>>>>>> Cheers
>>>>>>
>>>>>> On Wed, May 4, 2016 at 8:02 PM, Shuai Lin <linshuai2012@gmail.com>
>>>>>> wrote:
>>>>>>
>>>>>> > Hi Ted,
>>>>>> >
>>>>>> > The hbase version is 1.0.0-cdh5.4.8, shipped with cloudera CDH
>>>>>> 5.4.8. The
>>>>>> > RS logs on node6 can be found here <
>>>>>> http://paste.openstack.org/raw/496174/
>>>>>> > >
>>>>>> >  .
>>>>>> >
>>>>>> > Thanks!
>>>>>> >
>>>>>> > Shuai
>>>>>> >
>>>>>> > On Thu, May 5, 2016 at 9:15 AM, Ted Yu <yuzhihong@gmail.com>
wrote:
>>>>>> >
>>>>>> > > Can you pastebin related server log w.r.t.
>>>>>> > d1c7f3f455f2529da82a2f713b5ee067
>>>>>> > > from rs-node6 ?
>>>>>> > >
>>>>>> > > Which release of hbase are you using ?
>>>>>> > >
>>>>>> > > Cheers
>>>>>> > >
>>>>>> > > On Wed, May 4, 2016 at 6:07 PM, Shuai Lin <linshuai2012@gmail.com
>>>>>> >
>>>>>> > wrote:
>>>>>> > >
>>>>>> > > > Hi list,
>>>>>> > > >
>>>>>> > > > Last weekend I got a region server crashed, but some
regions
>>>>>> never got
>>>>>> > > > online again on other RSes. I've gone through the
logs, and
>>>>>> here is the
>>>>>> > > > timeline about some of the events:
>>>>>> > > >
>>>>>> > > > * 13:03:50 on of the region server, rs-node7, died
because of a
>>>>>> disk
>>>>>> > > > failure. Master started to split rs-node7's WALs
>>>>>> > > >
>>>>>> > > >
>>>>>> > > > 2016-04-30 13:03:50,953 INFO
>>>>>> > > > org.apache.hadoop.hbase.master.handler.ServerShutdownHandler:
>>>>>> Splitting
>>>>>> > > > logs for rs-node7.example.com,60020,1458724695128
before
>>>>>> assignment;
>>>>>> > > > region
>>>>>> > > > count=133
>>>>>> > > > 2016-04-30 13:03:50,966 DEBUG
>>>>>> > > > org.apache.hadoop.hbase.master.SplitLogManager: Scheduling
>>>>>> batch of
>>>>>> > logs
>>>>>> > > to
>>>>>> > > > split
>>>>>> > > > 2016-04-30 13:03:50,966 INFO
>>>>>> > > > org.apache.hadoop.hbase.master.SplitLogManager: started
>>>>>> splitting 33
>>>>>> > logs
>>>>>> > > > in [hdfs://nameservice1/hbase/WALs/rs-node7.example.com
>>>>>> > > > ,60020,1458724695128-splitting]
>>>>>> > > > for [rs-node7.example.com,60020,1458724695128]
>>>>>> > > >
>>>>>> > > > * 13:10:47 WAL splits done, master began to re-assign
regions
>>>>>> > > >
>>>>>> > > > 2016-04-30 13:10:47,655 INFO
>>>>>> > > > org.apache.hadoop.hbase.master.handler.ServerShutdownHandler:
>>>>>> > Reassigning
>>>>>> > > > 133 region(s) that rs-node7.example.com,60020,1458724695128
was
>>>>>> > carrying
>>>>>> > > > (and 0 regions(s) that were opening on this server)
>>>>>> > > > 2016-04-30 13:10:47,665 INFO
>>>>>> > > > org.apache.hadoop.hbase.master.AssignmentManager:
Bulk
>>>>>> assigning 133
>>>>>> > > > region(s) across 6 server(s), round-robin=true
>>>>>> > > > 2016-04-30 13:10:47,667 INFO
>>>>>> > > > org.apache.hadoop.hbase.master.AssignmentManager:
Assigning 22
>>>>>> > region(s)
>>>>>> > > to
>>>>>> > > > rs-node1.example.com,60020,1458720625688
>>>>>> > > > 2016-04-30 13:10:47,667 INFO
>>>>>> > > > org.apache.hadoop.hbase.master.AssignmentManager:
Assigning 22
>>>>>> > region(s)
>>>>>> > > to
>>>>>> > > > rs-node2.example.com,60020,1458721110988
>>>>>> > > > 2016-04-30 13:10:47,667 INFO
>>>>>> > > > org.apache.hadoop.hbase.master.AssignmentManager:
Assigning 22
>>>>>> > region(s)
>>>>>> > > to
>>>>>> > > > rs-node3.example.com,60020,1458721713906
>>>>>> > > > 2016-04-30 13:10:47,679 INFO
>>>>>> > > > org.apache.hadoop.hbase.master.AssignmentManager:
Assigning 23
>>>>>> > region(s)
>>>>>> > > to
>>>>>> > > > rs-node4.example.com,60020,1458722335527
>>>>>> > > > 2016-04-30 13:10:47,691 INFO
>>>>>> > > > org.apache.hadoop.hbase.master.AssignmentManager:
Assigning 22
>>>>>> > region(s)
>>>>>> > > to
>>>>>> > > > rs-node5.example.com,60020,1458722992296
>>>>>> > > > 2016-04-30 13:10:47,702 INFO
>>>>>> > > > org.apache.hadoop.hbase.master.AssignmentManager:
Assigning 22
>>>>>> > region(s)
>>>>>> > > to
>>>>>> > > > rs-node6.example.com,60020,1458723856883
>>>>>> > > >
>>>>>> > > > * 13:11:47 the opening regions rpc sent by master
to region
>>>>>> servers
>>>>>> > timed
>>>>>> > > > out after 1 minutes
>>>>>> > > >
>>>>>> > > > 2016-04-30 13:11:47,780 INFO
>>>>>> > > > org.apache.hadoop.hbase.master.AssignmentManager:
Unable to
>>>>>> communicate
>>>>>> > > > with rs-node3.example.com,60020,1458721713906 in order
to
>>>>>> assign
>>>>>> > regions
>>>>>> > > > java.io.IOException: Call to
>>>>>> rs-node3.example.com/172.16.6.3:60020
>>>>>> > > failed
>>>>>> > > > on local exception:
>>>>>> org.apache.hadoop.hbase.ipc.CallTimeoutException:
>>>>>> > > Call
>>>>>> > > > id=4, waitTime=60001, operationTimeout=60000 expired.
>>>>>> > > > 2016-04-30 13:11:47,782 INFO
>>>>>> > > > org.apache.hadoop.hbase.master.GeneralBulkAssigner:
Failed
>>>>>> assigning 22
>>>>>> > > > regions to server rs-node6.example.com,60020,1458723856883,
>>>>>> > reassigning
>>>>>> > > > them
>>>>>> > > > 2016-04-30 13:11:47,782 INFO
>>>>>> > > > org.apache.hadoop.hbase.master.GeneralBulkAssigner:
Failed
>>>>>> assigning 23
>>>>>> > > > regions to server rs-node4.example.com,60020,1458722335527,
>>>>>> > reassigning
>>>>>> > > > them
>>>>>> > > > 2016-04-30 13:11:47,782 INFO
>>>>>> > > > org.apache.hadoop.hbase.master.GeneralBulkAssigner:
Failed
>>>>>> assigning 22
>>>>>> > > > regions to server rs-node3.example.com,60020,1458721713906,
>>>>>> > reassigning
>>>>>> > > > them
>>>>>> > > > 2016-04-30 13:11:47,783 DEBUG
>>>>>> > > > org.apache.hadoop.hbase.master.AssignmentManager:
Force region
>>>>>> state
>>>>>> > > > offline {a65660e421f114e93862194f7cc35644 state=OPENING,
>>>>>> > > ts=1462021907753,
>>>>>> > > > server=rs-node6.example.com,60020,1458723856883}
>>>>>> > > >
>>>>>> > > >
>>>>>> > > > * After that, part of the regions (40 out of 130 regions)
never
>>>>>> got
>>>>>> > > online,
>>>>>> > > > and the following lines were logged repeatly in master
log:
>>>>>> > > >
>>>>>> > > > 2016-04-30 13:12:37,188 DEBUG
>>>>>> > > > org.apache.hadoop.hbase.master.AssignmentManager:
update
>>>>>> > > > {d1c7f3f455f2529da82a2f713b5ee067 state=PENDING_OPEN,
>>>>>> ts=1462021957087,
>>>>>> > > > server=rs-node6.example.com,60020,1458723856883} the
timestamp.
>>>>>> > > > 2016-04-30 13:12:37,188 DEBUG
>>>>>> > > > org.apache.hadoop.hbase.master.AssignmentManager:
Region is
>>>>>> already in
>>>>>> > > > transition; waiting up to 10668ms
>>>>>> > > >
>>>>>> > > > $ grep 'AssignmentManager: update
>>>>>> {d1c7f3f455f2529da82a2f713b5ee067'
>>>>>> > > >
>>>>>> /var/log/hbase/hbase-cmf-hbase-MASTER-head.example.com.log.out.1|wc
-l
>>>>>> > > > 484
>>>>>> > > >
>>>>>> > > >
>>>>>> > > > I've searched in mailing list archive and hbase JIRA,
but
>>>>>> didn't find
>>>>>> > any
>>>>>> > > > similar situations like this one. The most similar
one is
>>>>>> HBASE-14407
>>>>>> > > > <https://issues.apache.org/jira/browse/HBASE-14407>
, but after
>>>>>> > reading
>>>>>> > > > its
>>>>>> > > > discussion I don't think that's the same problem.
>>>>>> > > >
>>>>>> > > > Anyone have a clue? Thanks!
>>>>>> > > >
>>>>>> > > > Regards,
>>>>>> > > > Shuai
>>>>>> > > >
>>>>>> > >
>>>>>> >
>>>>>>
>>>>>
>>>>>
>>>>
>>>
>>
>

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message