[jira] [Commented] (HBASE-5312) Closed parent region present in Hlog.lastSeqWritten
[
https://issues.apache.org/jira/browse/HBASE-5312?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=14269213#comment-14269213
]
Cosmin Lehene commented on HBASE-5312:
--
[~jeason], [~ram_krish], [~apurtell] can we close this?
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
Labels: delete
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-0456520,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
[jira] [Commented] (HBASE-5312) Closed parent region present in Hlog.lastSeqWritten
[
https://issues.apache.org/jira/browse/HBASE-5312?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=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
[jira] [Commented] (HBASE-5312) Closed parent region present in Hlog.lastSeqWritten
[
https://issues.apache.org/jira/browse/HBASE-5312?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13230334#comment-13230334
]
ramkrishna.s.vasudevan commented on HBASE-5312:
---
@Todd/Jimmy
Do you feel HBASE-5568 solves the problem for your scenario also? If so we can
close this issue i feel?
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-0456520,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
[jira] [Commented] (HBASE-5312) Closed parent region present in Hlog.lastSeqWritten
[
https://issues.apache.org/jira/browse/HBASE-5312?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13229005#comment-13229005
]
chunhui shen commented on HBASE-5312:
-
@ram
We also see the same wrong log{code} 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
{code}
But I'm not sure the cause is also the same.
Could you use the patch of HBASE-5569, and try again?
In our case for HBASE-5569, I'm sure the cause is that we concurrently call
region.flushcach().
For this issue, is there any possibility concurrently calling
region.flushcach() or region.internalFlushcache(). If so, that's the reason.
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-0456520,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
[jira] [Commented] (HBASE-5312) Closed parent region present in Hlog.lastSeqWritten
[
https://issues.apache.org/jira/browse/HBASE-5312?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13229012#comment-13229012
]
ramkrishna.s.vasudevan commented on HBASE-5312:
---
@Jimmy/Todd
Want to take a look at the patch in HBASE-5569 ?
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-0456520,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
[jira] [Commented] (HBASE-5312) Closed parent region present in Hlog.lastSeqWritten
[
https://issues.apache.org/jira/browse/HBASE-5312?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13229011#comment-13229011
]
ramkrishna.s.vasudevan commented on HBASE-5312:
---
@Chunhui
Thanks for your explantion. Now in your latest patch you avoid two flushes
happening in parallel if it comes through flush case.
Yes in our case there was an explicit split call also that happened which will
do one more flush.
Very good analysis. Excellent !!.
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-0456520,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
[jira] [Commented] (HBASE-5312) Closed parent region present in Hlog.lastSeqWritten
[
https://issues.apache.org/jira/browse/HBASE-5312?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13205580#comment-13205580
]
ramkrishna.s.vasudevan commented on HBASE-5312:
---
+1 on adding logs but need to ensure we don't slow down the hlog append and
flush flow.
By the way Jimmy, you have any suspects in this issue?
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-0456520,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
[jira] [Commented] (HBASE-5312) Closed parent region present in Hlog.lastSeqWritten
[
https://issues.apache.org/jira/browse/HBASE-5312?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13205596#comment-13205596
]
Jimmy Xiang commented on HBASE-5312:
I checked the lock mechanism and it looks fine. If it is not a bug in java
reentrant lock, I suspect the region is removed from the online regions list
before it is properly closed, either during region spliting, or region closing.
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-0456520,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
[jira] [Commented] (HBASE-5312) Closed parent region present in Hlog.lastSeqWritten
[
https://issues.apache.org/jira/browse/HBASE-5312?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13204455#comment-13204455
]
ramkrishna.s.vasudevan commented on HBASE-5312:
---
We have tried to reproduce this bug in different ways. But still unclear.
May be i will check the defect HBASE-3481 to see if it helps.
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-0456520,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
[jira] [Commented] (HBASE-5312) Closed parent region present in Hlog.lastSeqWritten
[
https://issues.apache.org/jira/browse/HBASE-5312?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13205214#comment-13205214
]
Jimmy Xiang commented on HBASE-5312:
Have anyone seen this issue on 0.92 release? Could we add some logging so that
we will have some clue when it happens again?
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-0456520,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
[jira] [Commented] (HBASE-5312) Closed parent region present in Hlog.lastSeqWritten
[
https://issues.apache.org/jira/browse/HBASE-5312?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13204313#comment-13204313
]
Todd Lipcon commented on HBASE-5312:
This bug has been around a while, see:
https://issues.apache.org/jira/browse/HBASE-3481?focusedCommentId=12987965page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-12987965
We also experienced it on a customer cluster this week.
Any leads on this, Ram?
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-0456520,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
[jira] [Commented] (HBASE-5312) Closed parent region present in Hlog.lastSeqWritten
[
https://issues.apache.org/jira/browse/HBASE-5312?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13197606#comment-13197606
]
ramkrishna.s.vasudevan commented on HBASE-5312:
---
HBASE-5225 is not present in this version .
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-0456520,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
