hbase-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Jean-Daniel Cryans (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (HBASE-3741) OpenRegionHandler and CloseRegionHandler are possibly racing
Date Tue, 05 Apr 2011 23:50:05 GMT

    [ https://issues.apache.org/jira/browse/HBASE-3741?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13016184#comment-13016184
] 

Jean-Daniel Cryans commented on HBASE-3741:
-------------------------------------------

I created HBASE-3742 for the issue where the master didn't do anything about the region being
closed at the end.

> OpenRegionHandler and CloseRegionHandler are possibly racing
> ------------------------------------------------------------
>
>                 Key: HBASE-3741
>                 URL: https://issues.apache.org/jira/browse/HBASE-3741
>             Project: HBase
>          Issue Type: Bug
>    Affects Versions: 0.90.1
>            Reporter: Jean-Daniel Cryans
>            Priority: Blocker
>             Fix For: 0.90.3
>
>
> This is a serious issue about a race between regions being opened and closed in region
servers. We had this situation where the master tried to unassign a region for balancing,
failed, force unassigned it, force assigned it somewhere else, failed to open it on another
region server (took too long), and then reassigned it back to the original region server.
A few seconds later, the region server processed the first closed and the region was left
unassigned.
> This is from the master log:
> {quote}
> 11-04-05 15:11:17,758 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Sent CLOSE
to serverName=sv4borg42,60020,1300920459477, load=(requests=187, regions=574, usedHeap=3918,
maxHeap=6973) for region stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:12:10,021 INFO org.apache.hadoop.hbase.master.AssignmentManager: Regions
in transition timed out:  stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
state=PENDING_CLOSE, ts=1302041477758
> 2011-04-05 15:12:10,021 INFO org.apache.hadoop.hbase.master.AssignmentManager: Region
has been PENDING_CLOSE for too long, running forced unassign again on region=stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> ...
> 2011-04-05 15:14:45,783 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Forcing
OFFLINE; was=stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
state=CLOSED, ts=1302041685733
> 2011-04-05 15:14:45,783 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: master:60000-0x42ec2cece810b68
Creating (or updating) unassigned node for 1470298961 with OFFLINE state
> ...
> 2011-04-05 15:14:45,885 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Using
pre-existing plan for region stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961;
plan=hri=stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961,
src=sv4borg42,60020,1300920459477, dest=sv4borg40,60020,1302041218196
> 2011-04-05 15:14:45,885 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Assigning
region stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
to sv4borg40,60020,1302041218196
> 2011-04-05 15:15:39,410 INFO org.apache.hadoop.hbase.master.AssignmentManager: Regions
in transition timed out:  stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
state=PENDING_OPEN, ts=1302041700944
> 2011-04-05 15:15:39,410 INFO org.apache.hadoop.hbase.master.AssignmentManager: Region
has been PENDING_OPEN for too long, reassigning region=stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:15:39,410 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Forcing
OFFLINE; was=stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
state=PENDING_OPEN, ts=1302041700944
> ...
> 2011-04-05 15:15:39,410 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: No previous
transition plan was found (or we are ignoring an existing plan) for stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
so generated a random one; hri=stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961,
src=, dest=sv4borg42,60020,1300920459477; 19 (online=19, exclude=null) available servers
> 2011-04-05 15:15:39,410 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Assigning
region stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
to sv4borg42,60020,1300920459477
> 2011-04-05 15:15:40,951 DEBUG org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher: master:60000-0x42ec2cece810b68
Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/prodjobs/unassigned/1470298961
> 2011-04-05 15:15:40,952 DEBUG org.apache.hadoop.hbase.zookeeper.ZKUtil: master:60000-0x42ec2cece810b68
Retrieved 93 byte(s) of data from znode /prodjobs/unassigned/1470298961 and set watcher; region=stumbles_by_userid2,'����穗���6,1266566087256,
server=sv4borg42,60020,1300920459477, state=RS_ZK_REGION_OPENED
> 2011-04-05 15:15:40,952 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Handling
transition=RS_ZK_REGION_OPENED, server=sv4borg42,60020,1300920459477, region=1470298961
> 2011-04-05 15:15:42,222 DEBUG org.apache.hadoop.hbase.master.handler.OpenedRegionHandler:
Handling OPENED event for 1470298961; deleting unassigned node
> ...
> 2011-04-05 15:15:55,812 DEBUG org.apache.hadoop.hbase.zookeeper.ZKUtil: master:60000-0x42ec2cece810b68
Retrieved 93 byte(s) of data from znode /prodjobs/unassigned/1470298961 and set watcher; region=stumbles_by_userid2,'����穗���6,1266566087256,
server=sv4borg42,60020,1300920459477, state=RS_ZK_REGION_CLOSING
> 2011-04-05 15:15:55,812 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Handling
new unassigned node: /prodjobs/unassigned/1470298961 (region=stumbles_by_userid2,'����穗���6,1266566087256,
server=sv4borg42,60020,1300920459477, state=RS_ZK_REGION_CLOSING)
> 2011-04-05 15:15:55,812 DEBUG org.apache.hadoop.hbase.master.AssignmentManager: Handling
transition=RS_ZK_REGION_CLOSING, server=sv4borg42,60020,1300920459477, region=1470298961
> 2011-04-05 15:15:55,812 WARN org.apache.hadoop.hbase.master.AssignmentManager: Received
CLOSING for region 1470298961 from server sv4borg42,60020,1300920459477 but region was in
 the state null and not in expected PENDING_CLOSE or CLOSING states
> {quote}
> And from sv4borg42:
> {quote}
> 2011-04-05 15:09:58,755 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: Received
close region: stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:11:17,757 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: Received
close region: stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:12:10,021 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: Received
close region: stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:14:45,675 DEBUG org.apache.hadoop.hbase.regionserver.handler.CloseRegionHandler:
Processing close of stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:14:45,700 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961:
disabling compactions & flushes
> 2011-04-05 15:14:45,701 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Updates disabled
for region stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:14:45,701 INFO org.apache.hadoop.hbase.regionserver.HRegion: Closed stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:14:45,758 DEBUG org.apache.hadoop.hbase.regionserver.handler.CloseRegionHandler:
Closed region stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:15:39,410 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: Received
request to open region: stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:15:39,410 DEBUG org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
Processing open of stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:15:39,486 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Opening region:
REGION => {NAME => 'stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256',
STARTKEY => '\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6', ENDKEY =>
'\x00'\x9AU\x7F\xFF\xFE\xEBQ\xB0\xC3\xEF\x00Jr\xF2', ENCODED => 1470298961, TABLE =>
...
> 2011-04-05 15:15:39,487 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Instantiated
stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:15:40,399 INFO org.apache.hadoop.hbase.regionserver.HRegion: Onlined stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961;
next sequenceid=37627407247
> 2011-04-05 15:15:40,488 INFO org.apache.hadoop.hbase.catalog.MetaEditor: Updated row
stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
in region .META.,,1 with server=sv4borg42:60020, startcode=1300920459477
> 2011-04-05 15:15:40,582 DEBUG org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler:
Opened stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:15:55,776 DEBUG org.apache.hadoop.hbase.regionserver.handler.CloseRegionHandler:
Processing close of stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:15:55,809 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961:
disabling compactions & flushes
> 2011-04-05 15:15:55,809 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Updates disabled
for region stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:15:55,809 INFO org.apache.hadoop.hbase.regionserver.HRegion: Closed stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:15:55,842 DEBUG org.apache.hadoop.hbase.regionserver.handler.CloseRegionHandler:
Closed region stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:15:55,943 DEBUG org.apache.hadoop.hbase.regionserver.handler.CloseRegionHandler:
Processing close of stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
> 2011-04-05 15:15:55,943 WARN org.apache.hadoop.hbase.regionserver.handler.CloseRegionHandler:
Received CLOSE for region stumbles_by_userid2,\x00'\x8E\xE8\x7F\xFF\xFE\xE7\xA9\x97\xFC\xDF\x01\x10\xCC6,1266566087256.1470298961
but currently not serving
> {quote}

--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira

Mime
View raw message