You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@hbase.apache.org by "zhoushuaifeng (JIRA)" <ji...@apache.org> on 2011/04/26 09:12:03 UTC
[jira] [Created] (HBASE-3821) "NOT flushing memstore for region"
keep on printing for half an hour
"NOT flushing memstore for region" keep on printing for half an hour
---------------------------------------------------------------------
Key: HBASE-3821
URL: https://issues.apache.org/jira/browse/HBASE-3821
Project: HBase
Issue Type: Bug
Components: regionserver
Affects Versions: 0.90.1
Reporter: zhoushuaifeng
Fix For: 0.90.3
"NOT flushing memstore for region" keep on printing for half an hour in the regionserver. Then I restart hbase. I think there may be deadlock or cycling.
I know that when splitting region, it will doclose of region, and set writestate.writesEnabled = false and may run close preflush. This will make flush fail and print "NOT flushing memstore for region". But It should be finished after a while.
logs:
2011-04-18 16:28:27,960 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. because regionserver60020.cacheFlusher; priority=-1, compaction queue size=1
2011-04-18 16:28:30,171 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
2011-04-18 16:28:30,171 WARN org.apache.hadoop.hbase.regionserver.MemStoreFlusher: Region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. has too many store files; delaying flush up to 90000ms
2011-04-18 16:28:32,119 INFO org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogWriter: Using syncFs -- HDFS-200
2011-04-18 16:28:32,285 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: Roll /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124206693, entries=5226, filesize=255913736. New hlog /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124311822
2011-04-18 16:28:32,287 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog: Found 1 hlogs to remove out of total 2; oldest outstanding sequenceid is 11037 from region 031f37c9c23fcab17797b06b90205610
2011-04-18 16:28:32,288 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: moving old hlog file /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303123945481 whose highest sequenceid is 6052 to /hbase/.oldlogs/linux253%3A60020.1303123945481
2011-04-18 16:28:42,701 INFO org.apache.hadoop.hbase.regionserver.Store: Completed major compaction of 4 file(s), new file=hdfs://10.18.52.108:9000/hbase/ufdr/031f37c9c23fcab17797b06b90205610/value/4398465741579485290, size=281.4m; total size for store is 468.8m
2011-04-18 16:28:42,712 INFO org.apache.hadoop.hbase.regionserver.HRegion: completed compaction on region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. after 1mins, 40sec
2011-04-18 16:28:42,741 INFO org.apache.hadoop.hbase.regionserver.SplitTransaction: Starting split of region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
2011-04-18 16:28:42,770 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.: disabling compactions & flushes
2011-04-18 16:28:42,770 INFO org.apache.hadoop.hbase.regionserver.HRegion: Running close preflush of ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
2011-04-18 16:28:42,771 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started memstore flush for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., current region memstore size 105.6m
2011-04-18 16:28:42,818 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Finished snapshotting, commencing flushing stores
2011-04-18 16:28:42,846 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false ......
2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
Mon Apr 18 17:04:24 IST 2011 Starting regionserver on linux253 ulimit -n 1024
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (HBASE-3821) "NOT flushing memstore for region"
keep on printing for half an hour
Posted by "zhoushuaifeng (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-3821?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
zhoushuaifeng updated HBASE-3821:
---------------------------------
Attachment: HBase-3821 v2.txt
thanks J-D, below are the code may be changed to handle the problem.
{code:title=CompactSplitThread.java|borderStyle=solid}
try {
st.execute(this.server, this.server);
} catch (Exception e) {
try {
LOG.info("Running rollback of failed split of " +
parent.getRegionNameAsString() + "; " + e.getMessage());
st.rollback(this.server, this.server);
LOG.info("Successful rollback of failed split of " +
parent.getRegionNameAsString());
} catch (-Runtime-Exception ee) {
// If failed rollback, kill this server to avoid having a hole in table.
LOG.info("Failed rollback of failed split of " +
parent.getRegionNameAsString() + " -- aborting server", ee);
this.server.abort("Failed split");
}
return;{code}
Patch v2 include this change.
> "NOT flushing memstore for region" keep on printing for half an hour
> ---------------------------------------------------------------------
>
> Key: HBASE-3821
> URL: https://issues.apache.org/jira/browse/HBASE-3821
> Project: HBase
> Issue Type: Bug
> Components: regionserver
> Affects Versions: 0.90.1
> Reporter: zhoushuaifeng
> Fix For: 0.90.3
>
> Attachments: HBase-3821 v1.txt, HBase-3821 v2.txt
>
>
> "NOT flushing memstore for region" keep on printing for half an hour in the regionserver. Then I restart hbase. I think there may be deadlock or cycling.
> I know that when splitting region, it will doclose of region, and set writestate.writesEnabled = false and may run close preflush. This will make flush fail and print "NOT flushing memstore for region". But It should be finished after a while.
> logs:
> 2011-04-18 16:28:27,960 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. because regionserver60020.cacheFlusher; priority=-1, compaction queue size=1
> 2011-04-18 16:28:30,171 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:30,171 WARN org.apache.hadoop.hbase.regionserver.MemStoreFlusher: Region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. has too many store files; delaying flush up to 90000ms
> 2011-04-18 16:28:32,119 INFO org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogWriter: Using syncFs -- HDFS-200
> 2011-04-18 16:28:32,285 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: Roll /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124206693, entries=5226, filesize=255913736. New hlog /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124311822
> 2011-04-18 16:28:32,287 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog: Found 1 hlogs to remove out of total 2; oldest outstanding sequenceid is 11037 from region 031f37c9c23fcab17797b06b90205610
> 2011-04-18 16:28:32,288 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: moving old hlog file /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303123945481 whose highest sequenceid is 6052 to /hbase/.oldlogs/linux253%3A60020.1303123945481
> 2011-04-18 16:28:42,701 INFO org.apache.hadoop.hbase.regionserver.Store: Completed major compaction of 4 file(s), new file=hdfs://10.18.52.108:9000/hbase/ufdr/031f37c9c23fcab17797b06b90205610/value/4398465741579485290, size=281.4m; total size for store is 468.8m
> 2011-04-18 16:28:42,712 INFO org.apache.hadoop.hbase.regionserver.HRegion: completed compaction on region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. after 1mins, 40sec
> 2011-04-18 16:28:42,741 INFO org.apache.hadoop.hbase.regionserver.SplitTransaction: Starting split of region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,770 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.: disabling compactions & flushes
> 2011-04-18 16:28:42,770 INFO org.apache.hadoop.hbase.regionserver.HRegion: Running close preflush of ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,771 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started memstore flush for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., current region memstore size 105.6m
> 2011-04-18 16:28:42,818 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Finished snapshotting, commencing flushing stores
> 2011-04-18 16:28:42,846 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false ......
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> Mon Apr 18 17:04:24 IST 2011 Starting regionserver on linux253 ulimit -n 1024
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-3821) "NOT flushing memstore for region"
keep on printing for half an hour
Posted by "zhoushuaifeng (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-3821?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13025633#comment-13025633 ]
zhoushuaifeng commented on HBASE-3821:
--------------------------------------
here:
try {
LOG.info("Running rollback of failed split of " +
parent.getRegionNameAsString() + "; " + ioe.getMessage());
st.rollback(this.server);
LOG.info("Successful rollback of failed split of " +
parent.getRegionNameAsString());
} catch (RuntimeException e) {
// If failed rollback, kill this server to avoid having a hole in table.
LOG.info("Failed rollback of failed split of " +
parent.getRegionNameAsString() + " -- aborting server", e);
this.server.abort("Failed split");
}
May be we should cach IOException to abort server too?
> "NOT flushing memstore for region" keep on printing for half an hour
> ---------------------------------------------------------------------
>
> Key: HBASE-3821
> URL: https://issues.apache.org/jira/browse/HBASE-3821
> Project: HBase
> Issue Type: Bug
> Components: regionserver
> Affects Versions: 0.90.1
> Reporter: zhoushuaifeng
> Fix For: 0.90.3
>
> Attachments: HBase-3821 v1.txt
>
>
> "NOT flushing memstore for region" keep on printing for half an hour in the regionserver. Then I restart hbase. I think there may be deadlock or cycling.
> I know that when splitting region, it will doclose of region, and set writestate.writesEnabled = false and may run close preflush. This will make flush fail and print "NOT flushing memstore for region". But It should be finished after a while.
> logs:
> 2011-04-18 16:28:27,960 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. because regionserver60020.cacheFlusher; priority=-1, compaction queue size=1
> 2011-04-18 16:28:30,171 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:30,171 WARN org.apache.hadoop.hbase.regionserver.MemStoreFlusher: Region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. has too many store files; delaying flush up to 90000ms
> 2011-04-18 16:28:32,119 INFO org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogWriter: Using syncFs -- HDFS-200
> 2011-04-18 16:28:32,285 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: Roll /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124206693, entries=5226, filesize=255913736. New hlog /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124311822
> 2011-04-18 16:28:32,287 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog: Found 1 hlogs to remove out of total 2; oldest outstanding sequenceid is 11037 from region 031f37c9c23fcab17797b06b90205610
> 2011-04-18 16:28:32,288 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: moving old hlog file /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303123945481 whose highest sequenceid is 6052 to /hbase/.oldlogs/linux253%3A60020.1303123945481
> 2011-04-18 16:28:42,701 INFO org.apache.hadoop.hbase.regionserver.Store: Completed major compaction of 4 file(s), new file=hdfs://10.18.52.108:9000/hbase/ufdr/031f37c9c23fcab17797b06b90205610/value/4398465741579485290, size=281.4m; total size for store is 468.8m
> 2011-04-18 16:28:42,712 INFO org.apache.hadoop.hbase.regionserver.HRegion: completed compaction on region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. after 1mins, 40sec
> 2011-04-18 16:28:42,741 INFO org.apache.hadoop.hbase.regionserver.SplitTransaction: Starting split of region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,770 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.: disabling compactions & flushes
> 2011-04-18 16:28:42,770 INFO org.apache.hadoop.hbase.regionserver.HRegion: Running close preflush of ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,771 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started memstore flush for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., current region memstore size 105.6m
> 2011-04-18 16:28:42,818 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Finished snapshotting, commencing flushing stores
> 2011-04-18 16:28:42,846 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false ......
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> Mon Apr 18 17:04:24 IST 2011 Starting regionserver on linux253 ulimit -n 1024
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-3821) "NOT flushing memstore for region"
keep on printing for half an hour
Posted by "stack (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-3821?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13025363#comment-13025363 ]
stack commented on HBASE-3821:
------------------------------
Excellent digging Zhou! Yes.... if the preflush fails, we need to reset the work done by 'writestate.writesEnabled = false;' If you have a patch, that'd be great.
Was the fail to split a transitory error? Were you able to flush memory successfully later?
> "NOT flushing memstore for region" keep on printing for half an hour
> ---------------------------------------------------------------------
>
> Key: HBASE-3821
> URL: https://issues.apache.org/jira/browse/HBASE-3821
> Project: HBase
> Issue Type: Bug
> Components: regionserver
> Affects Versions: 0.90.1
> Reporter: zhoushuaifeng
> Fix For: 0.90.3
>
>
> "NOT flushing memstore for region" keep on printing for half an hour in the regionserver. Then I restart hbase. I think there may be deadlock or cycling.
> I know that when splitting region, it will doclose of region, and set writestate.writesEnabled = false and may run close preflush. This will make flush fail and print "NOT flushing memstore for region". But It should be finished after a while.
> logs:
> 2011-04-18 16:28:27,960 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. because regionserver60020.cacheFlusher; priority=-1, compaction queue size=1
> 2011-04-18 16:28:30,171 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:30,171 WARN org.apache.hadoop.hbase.regionserver.MemStoreFlusher: Region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. has too many store files; delaying flush up to 90000ms
> 2011-04-18 16:28:32,119 INFO org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogWriter: Using syncFs -- HDFS-200
> 2011-04-18 16:28:32,285 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: Roll /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124206693, entries=5226, filesize=255913736. New hlog /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124311822
> 2011-04-18 16:28:32,287 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog: Found 1 hlogs to remove out of total 2; oldest outstanding sequenceid is 11037 from region 031f37c9c23fcab17797b06b90205610
> 2011-04-18 16:28:32,288 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: moving old hlog file /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303123945481 whose highest sequenceid is 6052 to /hbase/.oldlogs/linux253%3A60020.1303123945481
> 2011-04-18 16:28:42,701 INFO org.apache.hadoop.hbase.regionserver.Store: Completed major compaction of 4 file(s), new file=hdfs://10.18.52.108:9000/hbase/ufdr/031f37c9c23fcab17797b06b90205610/value/4398465741579485290, size=281.4m; total size for store is 468.8m
> 2011-04-18 16:28:42,712 INFO org.apache.hadoop.hbase.regionserver.HRegion: completed compaction on region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. after 1mins, 40sec
> 2011-04-18 16:28:42,741 INFO org.apache.hadoop.hbase.regionserver.SplitTransaction: Starting split of region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,770 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.: disabling compactions & flushes
> 2011-04-18 16:28:42,770 INFO org.apache.hadoop.hbase.regionserver.HRegion: Running close preflush of ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,771 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started memstore flush for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., current region memstore size 105.6m
> 2011-04-18 16:28:42,818 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Finished snapshotting, commencing flushing stores
> 2011-04-18 16:28:42,846 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false ......
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> Mon Apr 18 17:04:24 IST 2011 Starting regionserver on linux253 ulimit -n 1024
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-3821) "NOT flushing memstore for region"
keep on printing for half an hour
Posted by "Jean-Daniel Cryans (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-3821?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13028533#comment-13028533 ]
Jean-Daniel Cryans commented on HBASE-3821:
-------------------------------------------
I agree, not handling the IOE is kinda weird because you end up with a CompactSplitThread that may have stopped while the rest of the RS could still be running.
@zhoushuaifeng, to paste code there's a special tag you can use, that last message is quite unreadable. Please refer to the wiki markup help (the yellow question mark button). Thanks!
> "NOT flushing memstore for region" keep on printing for half an hour
> ---------------------------------------------------------------------
>
> Key: HBASE-3821
> URL: https://issues.apache.org/jira/browse/HBASE-3821
> Project: HBase
> Issue Type: Bug
> Components: regionserver
> Affects Versions: 0.90.1
> Reporter: zhoushuaifeng
> Fix For: 0.90.3
>
> Attachments: HBase-3821 v1.txt
>
>
> "NOT flushing memstore for region" keep on printing for half an hour in the regionserver. Then I restart hbase. I think there may be deadlock or cycling.
> I know that when splitting region, it will doclose of region, and set writestate.writesEnabled = false and may run close preflush. This will make flush fail and print "NOT flushing memstore for region". But It should be finished after a while.
> logs:
> 2011-04-18 16:28:27,960 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. because regionserver60020.cacheFlusher; priority=-1, compaction queue size=1
> 2011-04-18 16:28:30,171 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:30,171 WARN org.apache.hadoop.hbase.regionserver.MemStoreFlusher: Region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. has too many store files; delaying flush up to 90000ms
> 2011-04-18 16:28:32,119 INFO org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogWriter: Using syncFs -- HDFS-200
> 2011-04-18 16:28:32,285 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: Roll /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124206693, entries=5226, filesize=255913736. New hlog /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124311822
> 2011-04-18 16:28:32,287 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog: Found 1 hlogs to remove out of total 2; oldest outstanding sequenceid is 11037 from region 031f37c9c23fcab17797b06b90205610
> 2011-04-18 16:28:32,288 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: moving old hlog file /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303123945481 whose highest sequenceid is 6052 to /hbase/.oldlogs/linux253%3A60020.1303123945481
> 2011-04-18 16:28:42,701 INFO org.apache.hadoop.hbase.regionserver.Store: Completed major compaction of 4 file(s), new file=hdfs://10.18.52.108:9000/hbase/ufdr/031f37c9c23fcab17797b06b90205610/value/4398465741579485290, size=281.4m; total size for store is 468.8m
> 2011-04-18 16:28:42,712 INFO org.apache.hadoop.hbase.regionserver.HRegion: completed compaction on region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. after 1mins, 40sec
> 2011-04-18 16:28:42,741 INFO org.apache.hadoop.hbase.regionserver.SplitTransaction: Starting split of region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,770 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.: disabling compactions & flushes
> 2011-04-18 16:28:42,770 INFO org.apache.hadoop.hbase.regionserver.HRegion: Running close preflush of ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,771 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started memstore flush for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., current region memstore size 105.6m
> 2011-04-18 16:28:42,818 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Finished snapshotting, commencing flushing stores
> 2011-04-18 16:28:42,846 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false ......
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> Mon Apr 18 17:04:24 IST 2011 Starting regionserver on linux253 ulimit -n 1024
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-3821) "NOT flushing memstore for region"
keep on printing for half an hour
Posted by "ramkrishna.s.vasudevan (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-3821?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13025594#comment-13025594 ]
ramkrishna.s.vasudevan commented on HBASE-3821:
-----------------------------------------------
I would like to add up to zhoushuaifeng analysis
Suppose the api cleanUpSplitDir() is throwing IOExceptin due to some DFS error
We try to roll back.
As part of rollback if we still get an DFS error then the exception is not handled.
We try to handle only RunTimeException and hence the exceptin gets propogated till the run method of the CompactSplitThread.
Here again the exception is not handled.
I think its better to handle this so that atleast the user comes to know about the exception.
> "NOT flushing memstore for region" keep on printing for half an hour
> ---------------------------------------------------------------------
>
> Key: HBASE-3821
> URL: https://issues.apache.org/jira/browse/HBASE-3821
> Project: HBase
> Issue Type: Bug
> Components: regionserver
> Affects Versions: 0.90.1
> Reporter: zhoushuaifeng
> Fix For: 0.90.3
>
> Attachments: HBase-3821 v1.txt
>
>
> "NOT flushing memstore for region" keep on printing for half an hour in the regionserver. Then I restart hbase. I think there may be deadlock or cycling.
> I know that when splitting region, it will doclose of region, and set writestate.writesEnabled = false and may run close preflush. This will make flush fail and print "NOT flushing memstore for region". But It should be finished after a while.
> logs:
> 2011-04-18 16:28:27,960 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. because regionserver60020.cacheFlusher; priority=-1, compaction queue size=1
> 2011-04-18 16:28:30,171 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:30,171 WARN org.apache.hadoop.hbase.regionserver.MemStoreFlusher: Region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. has too many store files; delaying flush up to 90000ms
> 2011-04-18 16:28:32,119 INFO org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogWriter: Using syncFs -- HDFS-200
> 2011-04-18 16:28:32,285 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: Roll /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124206693, entries=5226, filesize=255913736. New hlog /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124311822
> 2011-04-18 16:28:32,287 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog: Found 1 hlogs to remove out of total 2; oldest outstanding sequenceid is 11037 from region 031f37c9c23fcab17797b06b90205610
> 2011-04-18 16:28:32,288 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: moving old hlog file /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303123945481 whose highest sequenceid is 6052 to /hbase/.oldlogs/linux253%3A60020.1303123945481
> 2011-04-18 16:28:42,701 INFO org.apache.hadoop.hbase.regionserver.Store: Completed major compaction of 4 file(s), new file=hdfs://10.18.52.108:9000/hbase/ufdr/031f37c9c23fcab17797b06b90205610/value/4398465741579485290, size=281.4m; total size for store is 468.8m
> 2011-04-18 16:28:42,712 INFO org.apache.hadoop.hbase.regionserver.HRegion: completed compaction on region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. after 1mins, 40sec
> 2011-04-18 16:28:42,741 INFO org.apache.hadoop.hbase.regionserver.SplitTransaction: Starting split of region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,770 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.: disabling compactions & flushes
> 2011-04-18 16:28:42,770 INFO org.apache.hadoop.hbase.regionserver.HRegion: Running close preflush of ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,771 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started memstore flush for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., current region memstore size 105.6m
> 2011-04-18 16:28:42,818 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Finished snapshotting, commencing flushing stores
> 2011-04-18 16:28:42,846 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false ......
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> Mon Apr 18 17:04:24 IST 2011 Starting regionserver on linux253 ulimit -n 1024
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Resolved] (HBASE-3821) "NOT flushing memstore for region"
keep on printing for half an hour
Posted by "stack (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-3821?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
stack resolved HBASE-3821.
--------------------------
Resolution: Fixed
Assignee: zhoushuaifeng
Hadoop Flags: [Reviewed]
Committed branch and trunk. Small important fix (I see that in the compaction code above, it was using 'Exception' rather than 'RuntimeException' so this patch made the two catches match). Thanks for the patch Zhou. I added you as a contributor.
> "NOT flushing memstore for region" keep on printing for half an hour
> ---------------------------------------------------------------------
>
> Key: HBASE-3821
> URL: https://issues.apache.org/jira/browse/HBASE-3821
> Project: HBase
> Issue Type: Bug
> Components: regionserver
> Affects Versions: 0.90.1
> Reporter: zhoushuaifeng
> Assignee: zhoushuaifeng
> Fix For: 0.90.3
>
> Attachments: HBase-3821 v1.txt, HBase-3821 v2.txt
>
>
> "NOT flushing memstore for region" keep on printing for half an hour in the regionserver. Then I restart hbase. I think there may be deadlock or cycling.
> I know that when splitting region, it will doclose of region, and set writestate.writesEnabled = false and may run close preflush. This will make flush fail and print "NOT flushing memstore for region". But It should be finished after a while.
> logs:
> 2011-04-18 16:28:27,960 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. because regionserver60020.cacheFlusher; priority=-1, compaction queue size=1
> 2011-04-18 16:28:30,171 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:30,171 WARN org.apache.hadoop.hbase.regionserver.MemStoreFlusher: Region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. has too many store files; delaying flush up to 90000ms
> 2011-04-18 16:28:32,119 INFO org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogWriter: Using syncFs -- HDFS-200
> 2011-04-18 16:28:32,285 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: Roll /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124206693, entries=5226, filesize=255913736. New hlog /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124311822
> 2011-04-18 16:28:32,287 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog: Found 1 hlogs to remove out of total 2; oldest outstanding sequenceid is 11037 from region 031f37c9c23fcab17797b06b90205610
> 2011-04-18 16:28:32,288 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: moving old hlog file /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303123945481 whose highest sequenceid is 6052 to /hbase/.oldlogs/linux253%3A60020.1303123945481
> 2011-04-18 16:28:42,701 INFO org.apache.hadoop.hbase.regionserver.Store: Completed major compaction of 4 file(s), new file=hdfs://10.18.52.108:9000/hbase/ufdr/031f37c9c23fcab17797b06b90205610/value/4398465741579485290, size=281.4m; total size for store is 468.8m
> 2011-04-18 16:28:42,712 INFO org.apache.hadoop.hbase.regionserver.HRegion: completed compaction on region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. after 1mins, 40sec
> 2011-04-18 16:28:42,741 INFO org.apache.hadoop.hbase.regionserver.SplitTransaction: Starting split of region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,770 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.: disabling compactions & flushes
> 2011-04-18 16:28:42,770 INFO org.apache.hadoop.hbase.regionserver.HRegion: Running close preflush of ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,771 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started memstore flush for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., current region memstore size 105.6m
> 2011-04-18 16:28:42,818 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Finished snapshotting, commencing flushing stores
> 2011-04-18 16:28:42,846 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false ......
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> Mon Apr 18 17:04:24 IST 2011 Starting regionserver on linux253 ulimit -n 1024
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (HBASE-3821) "NOT flushing memstore for region"
keep on printing for half an hour
Posted by "zhoushuaifeng (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-3821?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
zhoushuaifeng updated HBASE-3821:
---------------------------------
Attachment: HBase-3821 v1.txt
I think there are several ways to fix it:
1, in the roll back handling , like this:
case CREATE_SPLIT_DIR:
+this.parent.writestate.writesEnabled = true;
cleanupSplitDir(fs, this.splitdir);
break;
2, catch ioException after doclose or preflush.
I think the first one is better. Do you think? And if there is anything else should be done?
The patch is the first way.
> "NOT flushing memstore for region" keep on printing for half an hour
> ---------------------------------------------------------------------
>
> Key: HBASE-3821
> URL: https://issues.apache.org/jira/browse/HBASE-3821
> Project: HBase
> Issue Type: Bug
> Components: regionserver
> Affects Versions: 0.90.1
> Reporter: zhoushuaifeng
> Fix For: 0.90.3
>
> Attachments: HBase-3821 v1.txt
>
>
> "NOT flushing memstore for region" keep on printing for half an hour in the regionserver. Then I restart hbase. I think there may be deadlock or cycling.
> I know that when splitting region, it will doclose of region, and set writestate.writesEnabled = false and may run close preflush. This will make flush fail and print "NOT flushing memstore for region". But It should be finished after a while.
> logs:
> 2011-04-18 16:28:27,960 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. because regionserver60020.cacheFlusher; priority=-1, compaction queue size=1
> 2011-04-18 16:28:30,171 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:30,171 WARN org.apache.hadoop.hbase.regionserver.MemStoreFlusher: Region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. has too many store files; delaying flush up to 90000ms
> 2011-04-18 16:28:32,119 INFO org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogWriter: Using syncFs -- HDFS-200
> 2011-04-18 16:28:32,285 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: Roll /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124206693, entries=5226, filesize=255913736. New hlog /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124311822
> 2011-04-18 16:28:32,287 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog: Found 1 hlogs to remove out of total 2; oldest outstanding sequenceid is 11037 from region 031f37c9c23fcab17797b06b90205610
> 2011-04-18 16:28:32,288 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: moving old hlog file /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303123945481 whose highest sequenceid is 6052 to /hbase/.oldlogs/linux253%3A60020.1303123945481
> 2011-04-18 16:28:42,701 INFO org.apache.hadoop.hbase.regionserver.Store: Completed major compaction of 4 file(s), new file=hdfs://10.18.52.108:9000/hbase/ufdr/031f37c9c23fcab17797b06b90205610/value/4398465741579485290, size=281.4m; total size for store is 468.8m
> 2011-04-18 16:28:42,712 INFO org.apache.hadoop.hbase.regionserver.HRegion: completed compaction on region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. after 1mins, 40sec
> 2011-04-18 16:28:42,741 INFO org.apache.hadoop.hbase.regionserver.SplitTransaction: Starting split of region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,770 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.: disabling compactions & flushes
> 2011-04-18 16:28:42,770 INFO org.apache.hadoop.hbase.regionserver.HRegion: Running close preflush of ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,771 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started memstore flush for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., current region memstore size 105.6m
> 2011-04-18 16:28:42,818 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Finished snapshotting, commencing flushing stores
> 2011-04-18 16:28:42,846 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false ......
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> Mon Apr 18 17:04:24 IST 2011 Starting regionserver on linux253 ulimit -n 1024
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-3821) "NOT flushing memstore for region"
keep on printing for half an hour
Posted by "zhoushuaifeng (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-3821?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13025103#comment-13025103 ]
zhoushuaifeng commented on HBASE-3821:
--------------------------------------
I think the problem is like this:
1, When split region, it will close parent region, and set writestate.writesEnabled = false:
private List<StoreFile> doClose(final boolean abort)
throws IOException {
synchronized (writestate) {
// Disable compacting and flushing by background threads for this
// region.
writestate.writesEnabled = false;
2, If the memstore is large enouth, preflush will happen:
if (!abort && !wasFlushing && worthPreFlushing()) {
LOG.info("Running close preflush of " + this.getRegionNameAsString());
internalFlushcache();
}
this.closing.set(true);
lock.writeLock().lock();
3, IOException happened, and preflushing failed, and closing parent failed:
createSplitDir(this.parent.getFilesystem(), this.splitdir);
this.journal.add(JournalEntry.CREATE_SPLIT_DIR);
List<StoreFile> hstoreFilesToSplit = this.parent.close(false); if (hstoreFilesToSplit == null) {
4, roll back split is calling, but split state stay in "CREATE_SPLIT_DIR", so , only clenupSplitDir will happen.
while (iterator.hasPrevious()) {
JournalEntry je = iterator.previous();
switch(je) {
case CREATE_SPLIT_DIR:
cleanupSplitDir(fs, this.splitdir);
break;
case CLOSED_PARENT_REGION:
5, what about writestate.writesEnabled? it stayed in false, no one handle it. So, even split is roll back, but no flush can success in parent region.
> "NOT flushing memstore for region" keep on printing for half an hour
> ---------------------------------------------------------------------
>
> Key: HBASE-3821
> URL: https://issues.apache.org/jira/browse/HBASE-3821
> Project: HBase
> Issue Type: Bug
> Components: regionserver
> Affects Versions: 0.90.1
> Reporter: zhoushuaifeng
> Fix For: 0.90.3
>
>
> "NOT flushing memstore for region" keep on printing for half an hour in the regionserver. Then I restart hbase. I think there may be deadlock or cycling.
> I know that when splitting region, it will doclose of region, and set writestate.writesEnabled = false and may run close preflush. This will make flush fail and print "NOT flushing memstore for region". But It should be finished after a while.
> logs:
> 2011-04-18 16:28:27,960 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. because regionserver60020.cacheFlusher; priority=-1, compaction queue size=1
> 2011-04-18 16:28:30,171 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:30,171 WARN org.apache.hadoop.hbase.regionserver.MemStoreFlusher: Region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. has too many store files; delaying flush up to 90000ms
> 2011-04-18 16:28:32,119 INFO org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogWriter: Using syncFs -- HDFS-200
> 2011-04-18 16:28:32,285 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: Roll /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124206693, entries=5226, filesize=255913736. New hlog /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124311822
> 2011-04-18 16:28:32,287 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog: Found 1 hlogs to remove out of total 2; oldest outstanding sequenceid is 11037 from region 031f37c9c23fcab17797b06b90205610
> 2011-04-18 16:28:32,288 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: moving old hlog file /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303123945481 whose highest sequenceid is 6052 to /hbase/.oldlogs/linux253%3A60020.1303123945481
> 2011-04-18 16:28:42,701 INFO org.apache.hadoop.hbase.regionserver.Store: Completed major compaction of 4 file(s), new file=hdfs://10.18.52.108:9000/hbase/ufdr/031f37c9c23fcab17797b06b90205610/value/4398465741579485290, size=281.4m; total size for store is 468.8m
> 2011-04-18 16:28:42,712 INFO org.apache.hadoop.hbase.regionserver.HRegion: completed compaction on region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. after 1mins, 40sec
> 2011-04-18 16:28:42,741 INFO org.apache.hadoop.hbase.regionserver.SplitTransaction: Starting split of region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,770 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.: disabling compactions & flushes
> 2011-04-18 16:28:42,770 INFO org.apache.hadoop.hbase.regionserver.HRegion: Running close preflush of ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,771 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started memstore flush for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., current region memstore size 105.6m
> 2011-04-18 16:28:42,818 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Finished snapshotting, commencing flushing stores
> 2011-04-18 16:28:42,846 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false ......
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> Mon Apr 18 17:04:24 IST 2011 Starting regionserver on linux253 ulimit -n 1024
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-3821) "NOT flushing memstore for region"
keep on printing for half an hour
Posted by "zhoushuaifeng (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-3821?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13025557#comment-13025557 ]
zhoushuaifeng commented on HBASE-3821:
--------------------------------------
Yes, the fail to split is a transitory error. It's able to flush memory successfully later.
> "NOT flushing memstore for region" keep on printing for half an hour
> ---------------------------------------------------------------------
>
> Key: HBASE-3821
> URL: https://issues.apache.org/jira/browse/HBASE-3821
> Project: HBase
> Issue Type: Bug
> Components: regionserver
> Affects Versions: 0.90.1
> Reporter: zhoushuaifeng
> Fix For: 0.90.3
>
> Attachments: HBase-3821 v1.txt
>
>
> "NOT flushing memstore for region" keep on printing for half an hour in the regionserver. Then I restart hbase. I think there may be deadlock or cycling.
> I know that when splitting region, it will doclose of region, and set writestate.writesEnabled = false and may run close preflush. This will make flush fail and print "NOT flushing memstore for region". But It should be finished after a while.
> logs:
> 2011-04-18 16:28:27,960 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. because regionserver60020.cacheFlusher; priority=-1, compaction queue size=1
> 2011-04-18 16:28:30,171 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:30,171 WARN org.apache.hadoop.hbase.regionserver.MemStoreFlusher: Region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. has too many store files; delaying flush up to 90000ms
> 2011-04-18 16:28:32,119 INFO org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogWriter: Using syncFs -- HDFS-200
> 2011-04-18 16:28:32,285 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: Roll /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124206693, entries=5226, filesize=255913736. New hlog /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124311822
> 2011-04-18 16:28:32,287 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog: Found 1 hlogs to remove out of total 2; oldest outstanding sequenceid is 11037 from region 031f37c9c23fcab17797b06b90205610
> 2011-04-18 16:28:32,288 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: moving old hlog file /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303123945481 whose highest sequenceid is 6052 to /hbase/.oldlogs/linux253%3A60020.1303123945481
> 2011-04-18 16:28:42,701 INFO org.apache.hadoop.hbase.regionserver.Store: Completed major compaction of 4 file(s), new file=hdfs://10.18.52.108:9000/hbase/ufdr/031f37c9c23fcab17797b06b90205610/value/4398465741579485290, size=281.4m; total size for store is 468.8m
> 2011-04-18 16:28:42,712 INFO org.apache.hadoop.hbase.regionserver.HRegion: completed compaction on region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. after 1mins, 40sec
> 2011-04-18 16:28:42,741 INFO org.apache.hadoop.hbase.regionserver.SplitTransaction: Starting split of region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,770 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.: disabling compactions & flushes
> 2011-04-18 16:28:42,770 INFO org.apache.hadoop.hbase.regionserver.HRegion: Running close preflush of ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,771 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started memstore flush for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., current region memstore size 105.6m
> 2011-04-18 16:28:42,818 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Finished snapshotting, commencing flushing stores
> 2011-04-18 16:28:42,846 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false ......
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> Mon Apr 18 17:04:24 IST 2011 Starting regionserver on linux253 ulimit -n 1024
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-3821) "NOT flushing memstore for region"
keep on printing for half an hour
Posted by "Hudson (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-3821?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13030226#comment-13030226 ]
Hudson commented on HBASE-3821:
-------------------------------
Integrated in HBase-TRUNK #1909 (See [https://builds.apache.org/hudson/job/HBase-TRUNK/1909/])
> "NOT flushing memstore for region" keep on printing for half an hour
> ---------------------------------------------------------------------
>
> Key: HBASE-3821
> URL: https://issues.apache.org/jira/browse/HBASE-3821
> Project: HBase
> Issue Type: Bug
> Components: regionserver
> Affects Versions: 0.90.1
> Reporter: zhoushuaifeng
> Assignee: zhoushuaifeng
> Fix For: 0.90.3
>
> Attachments: HBase-3821 v1.txt, HBase-3821 v2.txt
>
>
> "NOT flushing memstore for region" keep on printing for half an hour in the regionserver. Then I restart hbase. I think there may be deadlock or cycling.
> I know that when splitting region, it will doclose of region, and set writestate.writesEnabled = false and may run close preflush. This will make flush fail and print "NOT flushing memstore for region". But It should be finished after a while.
> logs:
> 2011-04-18 16:28:27,960 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. because regionserver60020.cacheFlusher; priority=-1, compaction queue size=1
> 2011-04-18 16:28:30,171 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:30,171 WARN org.apache.hadoop.hbase.regionserver.MemStoreFlusher: Region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. has too many store files; delaying flush up to 90000ms
> 2011-04-18 16:28:32,119 INFO org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogWriter: Using syncFs -- HDFS-200
> 2011-04-18 16:28:32,285 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: Roll /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124206693, entries=5226, filesize=255913736. New hlog /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303124311822
> 2011-04-18 16:28:32,287 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog: Found 1 hlogs to remove out of total 2; oldest outstanding sequenceid is 11037 from region 031f37c9c23fcab17797b06b90205610
> 2011-04-18 16:28:32,288 INFO org.apache.hadoop.hbase.regionserver.wal.HLog: moving old hlog file /hbase/.logs/linux253,60020,1303123943360/linux253%3A60020.1303123945481 whose highest sequenceid is 6052 to /hbase/.oldlogs/linux253%3A60020.1303123945481
> 2011-04-18 16:28:42,701 INFO org.apache.hadoop.hbase.regionserver.Store: Completed major compaction of 4 file(s), new file=hdfs://10.18.52.108:9000/hbase/ufdr/031f37c9c23fcab17797b06b90205610/value/4398465741579485290, size=281.4m; total size for store is 468.8m
> 2011-04-18 16:28:42,712 INFO org.apache.hadoop.hbase.regionserver.HRegion: completed compaction on region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610. after 1mins, 40sec
> 2011-04-18 16:28:42,741 INFO org.apache.hadoop.hbase.regionserver.SplitTransaction: Starting split of region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,770 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.: disabling compactions & flushes
> 2011-04-18 16:28:42,770 INFO org.apache.hadoop.hbase.regionserver.HRegion: Running close preflush of ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,771 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started memstore flush for ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., current region memstore size 105.6m
> 2011-04-18 16:28:42,818 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Finished snapshotting, commencing flushing stores
> 2011-04-18 16:28:42,846 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> 2011-04-18 16:28:42,849 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false ......
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610., flushing=false, writesEnabled=false
> 2011-04-18 17:04:08,803 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on ufdr,,1303124043153.031f37c9c23fcab17797b06b90205610.
> Mon Apr 18 17:04:24 IST 2011 Starting regionserver on linux253 ulimit -n 1024
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira