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] [Created] (HBASE-3741) OpenRegionHandler and CloseRegionHandler are possibly racing
Date Tue, 05 Apr 2011 23:48:06 GMT
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