hbase-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "stack (JIRA)" <j...@apache.org>
Subject [jira] Commented: (HBASE-1046) Region assigned to two regionservers after split
Date Thu, 04 Dec 2008 21:16:46 GMT

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

stack commented on HBASE-1046:
------------------------------

Looking at code, I cannot see how opens would be processed after splits though evidence presented
above would indicate this is happening.  Here is full lifecycle of region listed above from
log Andrews sent:

{code}
2008-12-04 02:54:23,504 INFO org.apache.hadoop.hbase.master.RegionManager: assigning region
content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554 to server 10.30.94.32:60020
2008-12-04 02:54:26,831 INFO org.apache.hadoop.hbase.master.ServerManager: Received MSG_REPORT_PROCESS_OPEN:
content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554 from 10.30.94.32:60020
2008-12-04 02:54:29,875 INFO org.apache.hadoop.hbase.master.ServerManager: Received MSG_REPORT_PROCESS_OPEN:
content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554 from 10.30.94.32:60020
2008-12-04 02:54:32,882 INFO org.apache.hadoop.hbase.master.ServerManager: Received MSG_REPORT_PROCESS_OPEN:
content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554 from 10.30.94.32:60020
2008-12-04 02:54:35,905 INFO org.apache.hadoop.hbase.master.ServerManager: Received MSG_REPORT_PROCESS_OPEN:
content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554 from 10.30.94.32:60020
2008-12-04 02:54:38,924 INFO org.apache.hadoop.hbase.master.ServerManager: Received MSG_REPORT_OPEN:
content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554 from 10.30.94.32:60020
2008-12-04 02:54:38,925 INFO org.apache.hadoop.hbase.master.ProcessRegionOpen$1: content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554
open on 10.30.94.32:60020
2008-12-04 02:54:38,925 INFO org.apache.hadoop.hbase.master.ProcessRegionOpen$1: updating
row content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554 in region .META.,,1 with startcode
1228377259645 and server 10.30.94.32:60020
2008-12-04 11:17:39,549 INFO org.apache.hadoop.hbase.master.RegionManager: assigning region
content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554 to server 10.30.94.49:60020
2008-12-04 11:17:42,578 INFO org.apache.hadoop.hbase.master.ServerManager: Received MSG_REPORT_PROCESS_OPEN:
content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554 from 10.30.94.49:60020
2008-12-04 11:17:45,595 INFO org.apache.hadoop.hbase.master.ServerManager: Received MSG_REPORT_OPEN:
content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554 from 10.30.94.49:60020
2008-12-04 11:17:45,595 INFO org.apache.hadoop.hbase.master.ProcessRegionOpen$1: content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554
open on 10.30.94.49:60020
2008-12-04 11:17:45,595 INFO org.apache.hadoop.hbase.master.ProcessRegionOpen$1: updating
row content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554 in region .META.,,1 with startcode
1228396338736 and server 10.30.94.49:60020
2008-12-04 11:18:25,482 INFO org.apache.hadoop.hbase.master.RegionManager: assigning region
content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257 to server 10.30.94.54:60020
2008-12-04 11:18:28,501 INFO org.apache.hadoop.hbase.master.ServerManager: Received MSG_REPORT_PROCESS_OPEN:
content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257 from 10.30.94.54:60020
2008-12-04 11:18:28,501 INFO org.apache.hadoop.hbase.master.ServerManager: Received MSG_REPORT_OPEN:
content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257 from 10.30.94.54:60020
2008-12-04 11:18:28,503 INFO org.apache.hadoop.hbase.master.ProcessRegionOpen$1: content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257
open on 10.30.94.54:60020
2008-12-04 11:18:28,503 INFO org.apache.hadoop.hbase.master.ProcessRegionOpen$1: updating
row content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257 in region .META.,,1 with startcode
1228377257408 and server 10.30.94.54:60020
2008-12-04 11:18:30,538 INFO org.apache.hadoop.hbase.master.ServerManager: Received MSG_REPORT_SPLIT:
content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554: content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554
split; daughters: content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257, content,c528c8864e67a3addcb50587586dfe38,1228407504257
from 10.30.94.49:60020
2008-12-04 11:18:30,539 INFO org.apache.hadoop.hbase.master.RegionManager: assigning region
content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257 to server 10.30.94.49:60020
2008-12-04 11:18:33,548 INFO org.apache.hadoop.hbase.master.ServerManager: Received MSG_REPORT_PROCESS_OPEN:
content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257 from 10.30.94.49:60020
2008-12-04 11:18:33,549 INFO org.apache.hadoop.hbase.master.ServerManager: Received MSG_REPORT_OPEN:
content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257 from 10.30.94.49:60020
2008-12-04 11:18:33,550 INFO org.apache.hadoop.hbase.master.ProcessRegionOpen$1: content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257
open on 10.30.94.49:60020
2008-12-04 11:18:33,550 INFO org.apache.hadoop.hbase.master.ProcessRegionOpen$1: updating
row content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257 in region .META.,,1 with startcode
1228396338736 and server 10.30.94.49:60020
2008-12-04 11:19:25,439 INFO org.apache.hadoop.hbase.master.BaseScanner: Deleting region content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554
because daughter splits no longer hold references
{code}

Trying to figure out what happed to host 32 around 11:17:39,549.  Log is at INFO but should
see server lease expired or MSG_REGION_CLOSE if they came in.

> Region assigned to two regionservers after split
> ------------------------------------------------
>
>                 Key: HBASE-1046
>                 URL: https://issues.apache.org/jira/browse/HBASE-1046
>             Project: Hadoop HBase
>          Issue Type: Bug
>          Components: regionserver
>            Reporter: Andrew Purtell
>            Priority: Blocker
>             Fix For: 0.19.0
>
>
> After reassignment of region split, scanners (mapred tasks) fail:
> org.apache.hadoop.hbase.client.RetriesExhaustedException: Trying to contact region server
10.30.94.49:60020 for region content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257, row 'c4e518dc579ca98bf97ea13d1f7c80fc',
but failed after 10 attempts.
> Exceptions:
> java.io.IOException: java.io.IOException: HStoreScanner failed construction
> 	at org.apache.hadoop.hbase.regionserver.StoreFileScanner.(StoreFileScanner.java:70)
> 	at org.apache.hadoop.hbase.regionserver.HStoreScanner.(HStoreScanner.java:84)
> 	at org.apache.hadoop.hbase.regionserver.HStore.getScanner(HStore.java:2113)
> 	at org.apache.hadoop.hbase.regionserver.HRegion$HScanner.(HRegion.java:1847)
> 	at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:1158)
> 	at org.apache.hadoop.hbase.regionserver.HRegionServer.openScanner(HRegionServer.java:1521)
> 	at sun.reflect.GeneratedMethodAccessor18.invoke(Unknown Source)
> 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> 	at java.lang.reflect.Method.invoke(Method.java:597)
> 	at org.apache.hadoop.hbase.ipc.HbaseRPC$Server.call(HbaseRPC.java:634)
> 	at org.apache.hadoop.ipc.Server$Handler.run(Server.java:888)
> Caused by: java.io.FileNotFoundException: File does not exist: hdfs://sjdc-atr-dc-1.atr.trendmicro.com:50000/data/hbase/content/1137747785/info/mapfiles/3405780294391796198/data
> 	at org.apache.hadoop.dfs.DistributedFileSystem.getFileStatus(DistributedFileSystem.java:394)
> 	at org.apache.hadoop.fs.FileSystem.getLength(FileSystem.java:695)
> 	at org.apache.hadoop.io.SequenceFile$Reader.(SequenceFile.java:1420)
> 	at org.apache.hadoop.io.SequenceFile$Reader.(SequenceFile.java:1415)
> 	at org.apache.hadoop.io.MapFile$Reader.createDataFileReader(MapFile.java:301)
> 	at org.apache.hadoop.hbase.io.HBaseMapFile$HBaseReader.createDataFileReader(HBaseMapFile.java:98)
> 	at org.apache.hadoop.io.MapFile$Reader.open(MapFile.java:283)
> 	at org.apache.hadoop.hbase.io.HBaseMapFile$HBaseReader.(HBaseMapFile.java:81)
> 	at org.apache.hadoop.hbase.io.BloomFilterMapFile$Reader.(BloomFilterMapFile.java:66)
> 	at org.apache.hadoop.hbase.io.HalfMapFileReader.(HalfMapFileReader.java:86)
> 	at org.apache.hadoop.hbase.regionserver.HStoreFile.getReader(HStoreFile.java:438)
> 	at org.apache.hadoop.hbase.regionserver.StoreFileScanner.openReaders(StoreFileScanner.java:96)
> 	at org.apache.hadoop.hbase.regionserver.StoreFileScanner.(StoreFileScanner.java:67)
> 	... 10 more
> According to the master the regions around this row are:
> content,c4580f7292ceb2f6c8d732d935302633,1228328680554  	10.30.94.50:60020  	693011073
	c4580f7292ceb2f6c8d732d935302633  	c4e518dc579ca98bf97ea13d1f7c80fc
> content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257 	10.30.94.49:60020 	2031068422
	c4e518dc579ca98bf97ea13d1f7c80fc 	c528c8864e67a3addcb50587586dfe38
> On 10.30.94.49, just before the HStoreScanner exceptions begin:
> 2008-12-04 16:18:30,538 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: MSG_REGION_OPEN:
content,c528c8864e67a3addcb50587586dfe38,1228407504257
> 2008-12-04 16:18:30,539 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: MSG_REGION_OPEN:
content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257
> 2008-12-04 16:18:30,539 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: Worker:
MSG_REGION_OPEN: content,c528c8864e67a3addcb50587586dfe38,1228407504257
> 2008-12-04 16:18:30,633 INFO org.apache.hadoop.hbase.regionserver.HRegion: region content,c528c8864e67a3addcb50587586dfe38,1228407504257/1813242175
available
> 2008-12-04 16:18:30,633 INFO org.apache.hadoop.hbase.regionserver.HRegionServer: Worker:
MSG_REGION_OPEN: content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257
> 2008-12-04 16:18:30,725 INFO org.apache.hadoop.hbase.regionserver.HRegion: region content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257/2031068422
available
> 2008-12-04 16:18:36,659 INFO org.apache.hadoop.hbase.regionserver.HRegion: starting compaction
on region content,c528c8864e67a3addcb50587586dfe38,1228407504257
> 2008-12-04 16:18:36,673 ERROR org.apache.hadoop.hbase.regionserver.CompactSplitThread:
Compaction failed for region content,c528c8864e67a3addcb50587586dfe38,1228407504257
> java.lang.NullPointerException
>         at org.apache.hadoop.hbase.regionserver.HStore.compact(HStore.java:863)
>         at org.apache.hadoop.hbase.regionserver.HRegion.compactStores(HRegion.java:708)
>         at org.apache.hadoop.hbase.regionserver.HRegion.compactStores(HRegion.java:666)
>         at org.apache.hadoop.hbase.regionserver.CompactSplitThread.run(CompactSplitThread.java:87)
> 2008-12-04 16:18:36,689 INFO org.apache.hadoop.hbase.regionserver.HRegion: starting compaction
on region content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257
> 2008-12-04 16:18:36,691 ERROR org.apache.hadoop.hbase.regionserver.CompactSplitThread:
Compaction failed for region content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257
> java.lang.NullPointerException
>         at org.apache.hadoop.hbase.regionserver.HStore.compact(HStore.java:863)
>         at org.apache.hadoop.hbase.regionserver.HRegion.compactStores(HRegion.java:708)
>         at org.apache.hadoop.hbase.regionserver.HRegion.compactStores(HRegion.java:666)
>         at org.apache.hadoop.hbase.regionserver.CompactSplitThread.run(CompactSplitThread.java:87)
> This is the region history:
> content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257
>   Thu, 4 Dec 2008 11:18:33	open	Region opened on server : 10.30.94.49
>   Thu, 4 Dec 2008 11:18:30	assignment	Region assigned to server   10.30.94.49:60020
>   Thu, 4 Dec 2008 11:18:28	open	Region opened on server : 10.30.94.54:60020
>   Thu, 4 Dec 2008 11:18:25	assignment	Region assigned to server 10.30.94.54:60020
>   Thu, 4 Dec 2008 11:18:25	split	Region split from: content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554
> On 10.30.94.49:
> 2008-12-04 16:17:39,550 INFO org.apache.hadoop.hbase.regionserver.HRegionServer:
>  MSG_REGION_OPEN: content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554
> 2008-12-04 16:17:39,550 INFO org.apache.hadoop.hbase.regionserver.HRegionServer:
>  MSG_REGION_OPEN: content,61938ad11c92493c1aac82932651b873,1228317826934
> 2008-12-04 16:18:17,469 INFO org.apache.hadoop.hbase.regionserver.HRegion: starting compaction
on region content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554
> 2008-12-04 16:18:24,255 INFO org.apache.hadoop.hbase.regionserver.HRegion: compac
> tion completed on region content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554 in 6sec
> 2008-12-04 16:18:24,255 INFO org.apache.hadoop.hbase.regionserver.HRegion: Starting split
of region content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554
> 2008-12-04 16:18:24,258 INFO org.apache.hadoop.hbase.regionserver.HRegion: Closed content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554
> 2008-12-04 16:18:24,745 INFO org.apache.hadoop.hbase.regionserver.HRegion: region content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257/2031068422
available
> 2008-12-04 16:18:24,746 INFO org.apache.hadoop.hbase.regionserver.HRegion: Closed content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257
> 2008-12-04 16:18:25,051 INFO org.apache.hadoop.hbase.regionserver.HRegion: region content,c528c8864e67a3addcb50587586dfe38,1228407504257/1813242175
available
> 2008-12-04 16:18:25,052 INFO org.apache.hadoop.hbase.regionserver.HRegion: Closed content,c528c8864e67a3addcb50587586dfe38,1228407504257
> 2008-12-04 16:18:25,066 INFO org.apache.hadoop.hbase.regionserver.CompactSplitThread:
region split, META updated, and report to master all successful. Old region=
> REGION => {NAME => content,c4e518dc579ca98bf97ea13d1f7c80fc,1228328680554', STARTKEY
=> 'c4e518dc579ca98bf97ea13d1f7c80fc', ENDKEY => c56eb508be0009d04429b6977c
> 91a425', ENCODED => 1137747785, OFFLINE => true, SPLIT => true, TABLE =>
{{NAME => 'content', IS_ROOT => 'false', IS_META => 'false', FAMILIES => [{NAME
=> 'url', BLOOMFILTER => 'false', VERSIONS => '1', COMPRESSION => 'NONE', LENGTH
=> '2147483647', TTL => '2592000', IN_MEMORY => 'false', BLOCKCACHE => 'false'},
{NAME => 'info', BLOOMFILTER => 'false', VERSIONS => '1', COMPRESSION => 'NONE',
LENGTH => '2147483647', TTL => '2592000', IN_MEMORY => 'false', BLOCKCACHE =>
'false'}, {NAME => 'content', BLOOMFILTER => 'false', VERSIONS => '1', COMPRESSION
=> 'NONE', LENGTH => '2147483647', TTL => '2592000', IN_MEMORY => 'false', BLOCKCACHE
=> 'false'}]}}, new regions: content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257, content,c528c8864e67a3addcb50587586dfe38,1228407504257.
Split took 0sec
> On 10.30.94.54:
> 2008-12-04 16:18:25,681 INFO org.apache.hadoop.hbase.regionserver.HRegionServer:
>  Worker: MSG_REGION_OPEN: content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257
> 2008-12-04 16:18:25,681 INFO org.apache.hadoop.hbase.regionserver.HRegion: starting compaction
on region content,c528c8864e67a3addcb50587586dfe38,1228407504257
> 2008-12-04 16:18:25,867 INFO org.apache.hadoop.hbase.regionserver.HRegion: region content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257/2031068422
available
> 2008-12-04 16:18:32,951 INFO org.apache.hadoop.hbase.regionserver.HRegion: compaction
completed on region content,c528c8864e67a3addcb50587586dfe38,1228407504257 in 7sec
> 2008-12-04 16:18:32,951 INFO org.apache.hadoop.hbase.regionserver.HRegion: starting compaction
on region content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257
> 2008-12-04 16:18:35,882 INFO org.apache.hadoop.hbase.regionserver.HRegion: compaction
completed on region content,c4e518dc579ca98bf97ea13d1f7c80fc,1228407504257 in 2sec

-- 
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.


Mime
View raw message