[
https://issues.apache.org/jira/browse/HBASE-5312?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13240340#comment-13240340
]
Jieshan Bean commented on HBASE-5312:
-------------------------------------
I'm afraid it's not the same issue with HBASE-5568. No concurrent flushing
happened when the edit with the sequenceId 20312224 added into Region
2acaf8e3acfd2e8a5825a1f6f0aca4a8. Though that problem may also happened in this
issue.
{noformat}
00:28:25,460 INFO org.apache.hadoop.hbase.regionserver.HRegion: Finished
memstore flush of ~153.9m for region
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. in
8444ms, sequenceid=20294110, compaction requested=true
00:28:25,460 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread:
Compaction requested for
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. because
regionserver20020.cacheFlusher; priority=2, compaction queue size=5835
00:30:35,328 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush
requested on
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
00:30:35,943 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started
memstore flush for
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8., current
region memstore size 129.5m
00:30:37,963 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing
memstore for region
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.,
flushing=true, writesEnabled=true
00:30:37,971 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush
requested on
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
00:30:37,971 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started
memstore flush for
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8., current
region memstore size 129.7m
00:30:47,907 INFO org.apache.hadoop.hbase.regionserver.Store: Renaming flushed
file at
hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/.tmp/5960455867013769207
to
hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/3682074154882687307
00:30:47,907 INFO org.apache.hadoop.hbase.regionserver.Store: Renaming flushed
file at
hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/.tmp/5960455867013769207
to
hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/3682074154882687307
00:30:49,241 INFO org.apache.hadoop.hbase.regionserver.Store: Added
hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/3682074154882687307,
entries=233841, sequenceid=20311822, memsize=129.5m, filesize=89.5m
00:30:49,242 INFO org.apache.hadoop.hbase.regionserver.HRegion: Finished
memstore flush of ~129.5m for region
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. in
13299ms, sequenceid=20311822, compaction requested=true
00:30:49,242 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread:
Compaction requested for
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. because
User-triggered split; priority=1, compaction queue size=5840
00:30:55,214 INFO org.apache.hadoop.hbase.regionserver.Store: Renaming flushed
file at
hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/.tmp/1755862026714756815
to
hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/973789709483406123
00:30:55,214 INFO org.apache.hadoop.hbase.regionserver.Store: Renaming flushed
file at
hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/.tmp/1755862026714756815
to
hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/973789709483406123
00:30:59,614 INFO org.apache.hadoop.hbase.regionserver.Store: Added
hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/973789709483406123,
entries=7537, sequenceid=20312223, memsize=4.2m, filesize=2.9m
00:30:59,787 INFO org.apache.hadoop.hbase.regionserver.HRegion: Finished
memstore flush of ~133.5m for region
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. in
21816ms, sequenceid=20312223, compaction requested=true
00:30:59,787 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread:
Compaction requested for
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. because
regionserver20020.cacheFlusher; priority=0, compaction queue size=5840
00:31:12,605 INFO org.apache.hadoop.hbase.regionserver.HRegion: Starting
compaction on region
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
00:31:12,607 INFO org.apache.hadoop.hbase.regionserver.HRegion: completed
compaction on region
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. after 0sec
00:31:12,607 INFO org.apache.hadoop.hbase.regionserver.SplitTransaction:
Starting split of region
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
00:31:13,694 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.:
disabling compactions & flushes
00:31:13,694 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Updates
disabled for region
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
00:31:13,718 INFO org.apache.hadoop.hbase.regionserver.HRegion: Closed
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
00:31:39,552 INFO org.apache.hadoop.hbase.catalog.MetaEditor: Offlined parent
region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. in
META
00:31:42,529 DEBUG org.apache.hadoop.hbase.regionserver.Store: loaded
hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/52ff3c7c6df6e0337876bbca29cee84a/value/973789709483406123.2acaf8e3acfd2e8a5825a1f6f0aca4a8,
isReference=true, isBulkLoadResult=false, seqid=20312224, majorCompaction=false
00:31:42,532 DEBUG org.apache.hadoop.hbase.regionserver.Store: loaded
hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/259d0c620c9105928e52713f4a5a252e/value/973789709483406123.2acaf8e3acfd2e8a5825a1f6f0aca4a8,
isReference=true, isBulkLoadResult=false, seqid=20312223, majorCompaction=false
00:31:42,575 INFO org.apache.hadoop.hbase.regionserver.CompactSplitThread:
Region split, META updated, and report to master.
Parent=Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.,
new regions:
Htable_UFDR_031,00332,1325809872607.259d0c620c9105928e52713f4a5a252e.,
Htable_UFDR_031,003732800093168-03594291912,1325809872607.52ff3c7c6df6e0337876bbca29cee84a..
Split took 29sec
00:34:48,061 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog: Found 1 hlogs
to remove out of total 4; oldest outstanding sequenceid is 20312224 from region
2acaf8e3acfd2e8a5825a1f6f0aca4a8
{noformat}
My doubt is:
>From the below log, we can see the sequenceId was 20312223. *So the sequenceId
>of 20312224 must be generated after this*:
{noformat}
00:30:59,787 INFO org.apache.hadoop.hbase.regionserver.HRegion: Finished
memstore flush of ~133.5m for region
Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. in
21816ms, sequenceid=20312223, compaction requested=true
{noformat}
Concurrent flush may cause the wrong memstoresize which is mentioned in
HBASE-5568(A edit larger than 20312223 could not be lost in this issue,
right?). I don't think any relationships with this issue.
Correct me if am wrong. Thank you.
> Closed parent region present in Hlog.lastSeqWritten
> ---------------------------------------------------
>
> Key: HBASE-5312
> URL: https://issues.apache.org/jira/browse/HBASE-5312
> Project: HBase
> Issue Type: Bug
> Affects Versions: 0.90.5
> Reporter: ramkrishna.s.vasudevan
> Fix For: 0.90.7
>
>
> This is in reference to the mail sent in the dev mailing list
> "Closed parent region present in Hlog.lastSeqWritten".
> The sceanrio described is
> We had a region that was split into two daughters. When the hlog roll tried
> to flush the region there was an entry in the HLog.lastSeqWritten that was
> not flushed or removed from the lastSeqWritten during the parent close.
> Because this flush was not happening subsequent flushes were getting blocked
> {code}
> 05:06:44,422 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: Too many
> hlogs: logs=122, maxlogs=32; forcing flush of 1 regions(s):
> 2acaf8e3acfd2e8a5825a1f6f0aca4a8
> 05:06:44,422 WARN org.apache.hadoop.hbase.regionserver.LogRoller: Failed
> to schedule flush of 2acaf8e3acfd2e8a5825a1f6f0aca4a8r=null,
> requester=null
> 05:10:48,666 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: Too many
> hlogs: logs=123, maxlogs=32; forcing flush of 1 regions(s):
> 2acaf8e3acfd2e8a5825a1f6f0aca4a8
> 05:10:48,666 WARN org.apache.hadoop.hbase.regionserver.LogRoller: Failed
> to schedule flush of 2acaf8e3acfd2e8a5825a1f6f0aca4a8r=null,
> requester=null
> 05:14:46,075 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: Too many
> hlogs: logs=124, maxlogs=32; forcing flush of 1 regions(s):
> 2acaf8e3acfd2e8a5825a1f6f0aca4a8
> 05:14:46,075 WARN org.apache.hadoop.hbase.regionserver.LogRoller: Failed
> to schedule flush of 2acaf8e3acfd2e8a5825a1f6f0aca4a8r=null,
> requester=null
> 05:15:41,584 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: Too many
> hlogs: logs=125, maxlogs=32; forcing flush of 1 regions(s):
> 2acaf8e3acfd2e8a5825a1f6f0aca4a8
> 05:15:41,584 WARN org.apache.hadoop.hbase.regionserver.LogRoller: Failed
> to schedule flush of 2acaf8e3acfd2e8a5825a1f6f0aca4a8r=null,
> {code}
> Lets see what happened for the region 2acaf8e3acfd2e8a5825a1f6f0aca4a8
> {code}
> 2012-01-06 00:30:55,214 INFO org.apache.hadoop.hbase.regionserver.Store:
> Renaming flushed file at
> hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/.tmp/1755862026714756815
> to
> hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/973789709483406123
> 2012-01-06 00:30:58,946 DEBUG org.apache.hadoop.hbase.regionserver.HRegion:
> Instantiated
> Htable_UFDR_016,049790700093168-04565200000,1325809837958.0ebe5bd7fcbc09ee074d5600b9d4e062.
> 2012-01-06 00:30:59,614 INFO org.apache.hadoop.hbase.regionserver.Store:
> Added
> hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/973789709483406123,
> entries=7537, sequenceid=20312223, memsize=4.2m, filesize=2.9m
> 2012-01-06 00:30:59,787 DEBUG org.apache.hadoop.hbase.regionserver.HRegion:
> Finished snapshotting, commencing flushing stores
> 2012-01-06 00:30:59,787 INFO org.apache.hadoop.hbase.regionserver.HRegion:
> Finished memstore flush of ~133.5m for region
> Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. in
> 21816ms, sequenceid=20312223, compaction requested=true
> 2012-01-06 00:30:59,787 DEBUG
> org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested
> for Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
> because regionserver20020.cacheFlusher; priority=0, compaction queue size=5840
> {code}
> A user triggered split has been issued to this region which can be seen in
> the above logs.
> The flushing of this region has resulted in a seq id 20312223.
> The region has been splitted and the parent region has been closed
> {code}
> 00:31:12,607 INFO org.apache.hadoop.hbase.regionserver.SplitTransaction:
> Starting split of region
> Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
> 00:31:13,694 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing
> Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.:
> disabling compactions & flushes
> 00:31:13,694 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Updates
> disabled for region
> Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
> 00:31:13,718 INFO org.apache.hadoop.hbase.regionserver.HRegion: Closed
> Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
> 00:31:39,552 INFO org.apache.hadoop.hbase.catalog.MetaEditor: Offlined parent
> region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
> in META
> 00:31:41,374 DEBUG org.apache.hadoop.hbase.regionserver.Store: loaded
> hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/259d0c620c9105928e52713f4a5a252e/value/239119195230239381.2acaf8e3acfd2e8a5825a1f6f0aca4a8,
> isReference=true, isBulkLoadResult=false, seqid=20201181,
> majorCompaction=false
> 2012-01-06 00:31:42,529 DEBUG org.apache.hadoop.hbase.regionserver.Store:
> loaded
> hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/52ff3c7c6df6e0337876bbca29cee84a/value/973789709483406123.2acaf8e3acfd2e8a5825a1f6f0aca4a8,
> isReference=true, isBulkLoadResult=false, seqid=20312224,
> majorCompaction=false
> 2012-01-06 00:31:42,532 DEBUG org.apache.hadoop.hbase.regionserver.Store:
> loaded
> hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/259d0c620c9105928e52713f4a5a252e/value/973789709483406123.2acaf8e3acfd2e8a5825a1f6f0aca4a8,
> isReference=true, isBulkLoadResult=false, seqid=20312223,
> majorCompaction=false
> INFO org.apache.hadoop.hbase.regionserver.CompactSplitThread: Region split,
> META updated, and report to master.
> Parent=Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.,
> new regions:
> Htable_UFDR_031,00332,1325809872607.259d0c620c9105928e52713f4a5a252e.,
> Htable_UFDR_031,003732800093168-03594291912,1325809872607.52ff3c7c6df6e0337876bbca29cee84a..
> Split took 29sec
> {code}
> In the above logs we can also see that the new daugher regions have the next
> seq id as 20312223 and 20312224.
> {code}
> DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog: Found 1 hlogs to remove
> out of total 4; oldest outstanding sequenceid is 20312224 from region
> 2acaf8e3acfd2e8a5825a1f6f0aca4a8
> {code}
> Now we see that the parent region which was clsoed has a seq id 20312224
> which is not flushed.
> So further flush are failing as the region is already removed from
> onlineRegionList.
> The doubt here is before the region could be closed, a put has arrived for
> this region. But due to some reason the flush has not happened for that. We
> tried to dig this, but not able to get this problem again.
> 0.90.5 version + few 0.90.6 patches ( before 0.90.6RC0)
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators:
https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
