HBase
  1. HBase
  2. HBASE-5312

Closed parent region present in Hlog.lastSeqWritten

    Details

    • Type: Bug Bug
    • Status: Open
    • Priority: Major Major
    • Resolution: Unresolved
    • Affects Version/s: 0.90.5
    • Fix Version/s: 0.90.7
    • Component/s: None
    • Labels:
      None

      Description

      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

       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,
      
      

      Lets see what happened for the region 2acaf8e3acfd2e8a5825a1f6f0aca4a8

      2012-01-06 00:30:55,214 INFO org.apache.hadoop.hbase.regionserver.Store: Renaming flushed file at hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/.tmp/1755862026714756815 to hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/973789709483406123
      2012-01-06 00:30:58,946 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Instantiated Htable_UFDR_016,049790700093168-04565200000,1325809837958.0ebe5bd7fcbc09ee074d5600b9d4e062.
      2012-01-06 00:30:59,614 INFO org.apache.hadoop.hbase.regionserver.Store: Added hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/973789709483406123, entries=7537, sequenceid=20312223, memsize=4.2m, filesize=2.9m
      2012-01-06 00:30:59,787 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Finished snapshotting, commencing flushing stores
      2012-01-06 00:30:59,787 INFO org.apache.hadoop.hbase.regionserver.HRegion: Finished memstore flush of ~133.5m for region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. in 21816ms, sequenceid=20312223, compaction requested=true
      2012-01-06 00:30:59,787 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. because regionserver20020.cacheFlusher; priority=0, compaction queue size=5840
      
      

      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

      00:31:12,607 INFO org.apache.hadoop.hbase.regionserver.SplitTransaction: Starting split of region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
      00:31:13,694 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.: disabling compactions & flushes
      00:31:13,694 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Updates disabled for region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
      00:31:13,718 INFO org.apache.hadoop.hbase.regionserver.HRegion: Closed Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
      00:31:39,552 INFO org.apache.hadoop.hbase.catalog.MetaEditor: Offlined parent region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. in META
      00:31:41,374 DEBUG org.apache.hadoop.hbase.regionserver.Store: loaded hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/259d0c620c9105928e52713f4a5a252e/value/239119195230239381.2acaf8e3acfd2e8a5825a1f6f0aca4a8, isReference=true, isBulkLoadResult=false, seqid=20201181, majorCompaction=false
      
      
      2012-01-06 00:31:42,529 DEBUG org.apache.hadoop.hbase.regionserver.Store: loaded hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/52ff3c7c6df6e0337876bbca29cee84a/value/973789709483406123.2acaf8e3acfd2e8a5825a1f6f0aca4a8, isReference=true, isBulkLoadResult=false, seqid=20312224, majorCompaction=false
      
      2012-01-06 00:31:42,532 DEBUG org.apache.hadoop.hbase.regionserver.Store: loaded hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/259d0c620c9105928e52713f4a5a252e/value/973789709483406123.2acaf8e3acfd2e8a5825a1f6f0aca4a8, isReference=true, isBulkLoadResult=false, seqid=20312223, majorCompaction=false
      
      INFO org.apache.hadoop.hbase.regionserver.CompactSplitThread: Region split, META updated, and report to master. Parent=Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8., new regions: Htable_UFDR_031,00332,1325809872607.259d0c620c9105928e52713f4a5a252e., Htable_UFDR_031,003732800093168-03594291912,1325809872607.52ff3c7c6df6e0337876bbca29cee84a.. Split took 29sec
      
      

      In the above logs we can also see that the new daugher regions have the next seq id as 20312223 and 20312224.

      DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog: Found 1 hlogs to remove out of total 4; oldest outstanding sequenceid is 20312224 from region 2acaf8e3acfd2e8a5825a1f6f0aca4a8
      

      Now we see that the parent region which was clsoed has a seq id 20312224 which is not flushed.
      So further flush are failing as the region is already removed from onlineRegionList.
      The doubt here is before the region could be closed, a put has arrived for this region. But due to some reason the flush has not happened for that. We tried to dig this, but not able to get this problem again.
      0.90.5 version + few 0.90.6 patches ( before 0.90.6RC0)

        Issue Links

          Activity

          Hide
          ramkrishna.s.vasudevan added a comment -

          HBASE-5225 is not present in this version .

          Show
          ramkrishna.s.vasudevan added a comment - HBASE-5225 is not present in this version .
          Hide
          Todd Lipcon added a comment -

          This bug has been around a while, see:
          https://issues.apache.org/jira/browse/HBASE-3481?focusedCommentId=12987965&page=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?

          Show
          Todd Lipcon added a comment - This bug has been around a while, see: https://issues.apache.org/jira/browse/HBASE-3481?focusedCommentId=12987965&page=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?
          Hide
          ramkrishna.s.vasudevan added a comment -

          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.

          Show
          ramkrishna.s.vasudevan added a comment - 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.
          Hide
          Jimmy Xiang added a comment -

          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?

          Show
          Jimmy Xiang added a comment - 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?
          Hide
          ramkrishna.s.vasudevan added a comment -

          +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?

          Show
          ramkrishna.s.vasudevan added a comment - +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?
          Hide
          Jimmy Xiang added a comment -

          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.

          Show
          Jimmy Xiang added a comment - 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.
          Hide
          chunhui shen added a comment -

          @ram
          We also see the same wrong log

           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
          

          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.

          Show
          chunhui shen added a comment - @ram We also see the same wrong log 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 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.
          Hide
          ramkrishna.s.vasudevan added a comment -

          @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 !!.

          Show
          ramkrishna.s.vasudevan added a comment - @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 !!.
          Hide
          ramkrishna.s.vasudevan added a comment - - edited

          @Jimmy/Todd
          Want to take a look at the patch in HBASE-5568?
          Chunhui mistakenly used HBASE-5569.

          Show
          ramkrishna.s.vasudevan added a comment - - edited @Jimmy/Todd Want to take a look at the patch in HBASE-5568 ? Chunhui mistakenly used HBASE-5569 .
          Hide
          ramkrishna.s.vasudevan added a comment -

          @Todd/Jimmy
          Do you feel HBASE-5568 solves the problem for your scenario also? If so we can close this issue i feel?

          Show
          ramkrishna.s.vasudevan added a comment - @Todd/Jimmy Do you feel HBASE-5568 solves the problem for your scenario also? If so we can close this issue i feel?
          Hide
          Jieshan Bean added a comment -

          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.

          00:28:25,460 INFO org.apache.hadoop.hbase.regionserver.HRegion: Finished memstore flush of ~153.9m for region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. in 8444ms, sequenceid=20294110, compaction requested=true
          00:28:25,460 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. because regionserver20020.cacheFlusher; priority=2, compaction queue size=5835
          00:30:35,328 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
          00:30:35,943 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started memstore flush for Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8., current region memstore size 129.5m
          00:30:37,963 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8., flushing=true, writesEnabled=true
          00:30:37,971 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
          00:30:37,971 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started memstore flush for Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8., current region memstore size 129.7m
          00:30:47,907 INFO org.apache.hadoop.hbase.regionserver.Store: Renaming flushed file at hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/.tmp/5960455867013769207 to hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/3682074154882687307
          00:30:47,907 INFO org.apache.hadoop.hbase.regionserver.Store: Renaming flushed file at hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/.tmp/5960455867013769207 to hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/3682074154882687307
          00:30:49,241 INFO org.apache.hadoop.hbase.regionserver.Store: Added hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/3682074154882687307, entries=233841, sequenceid=20311822, memsize=129.5m, filesize=89.5m
          00:30:49,242 INFO org.apache.hadoop.hbase.regionserver.HRegion: Finished memstore flush of ~129.5m for region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. in 13299ms, sequenceid=20311822, compaction requested=true
          00:30:49,242 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. because User-triggered split; priority=1, compaction queue size=5840
          00:30:55,214 INFO org.apache.hadoop.hbase.regionserver.Store: Renaming flushed file at hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/.tmp/1755862026714756815 to hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/973789709483406123
          00:30:55,214 INFO org.apache.hadoop.hbase.regionserver.Store: Renaming flushed file at hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/.tmp/1755862026714756815 to hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/973789709483406123
          00:30:59,614 INFO org.apache.hadoop.hbase.regionserver.Store: Added hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/973789709483406123, entries=7537, sequenceid=20312223, memsize=4.2m, filesize=2.9m
          00:30:59,787 INFO org.apache.hadoop.hbase.regionserver.HRegion: Finished memstore flush of ~133.5m for region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. in 21816ms, sequenceid=20312223, compaction requested=true
          00:30:59,787 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. because regionserver20020.cacheFlusher; priority=0, compaction queue size=5840
          00:31:12,605 INFO org.apache.hadoop.hbase.regionserver.HRegion: Starting compaction on region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
          00:31:12,607 INFO org.apache.hadoop.hbase.regionserver.HRegion: completed compaction on region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. after 0sec
          00:31:12,607 INFO org.apache.hadoop.hbase.regionserver.SplitTransaction: Starting split of region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
          00:31:13,694 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.: disabling compactions & flushes
          00:31:13,694 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Updates disabled for region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
          00:31:13,718 INFO org.apache.hadoop.hbase.regionserver.HRegion: Closed Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.
          00:31:39,552 INFO org.apache.hadoop.hbase.catalog.MetaEditor: Offlined parent region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. in META
          00:31:42,529 DEBUG org.apache.hadoop.hbase.regionserver.Store: loaded hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/52ff3c7c6df6e0337876bbca29cee84a/value/973789709483406123.2acaf8e3acfd2e8a5825a1f6f0aca4a8, isReference=true, isBulkLoadResult=false, seqid=20312224, majorCompaction=false
          00:31:42,532 DEBUG org.apache.hadoop.hbase.regionserver.Store: loaded hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/259d0c620c9105928e52713f4a5a252e/value/973789709483406123.2acaf8e3acfd2e8a5825a1f6f0aca4a8, isReference=true, isBulkLoadResult=false, seqid=20312223, majorCompaction=false
          00:31:42,575 INFO org.apache.hadoop.hbase.regionserver.CompactSplitThread: Region split, META updated, and report to master. Parent=Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8., new regions: Htable_UFDR_031,00332,1325809872607.259d0c620c9105928e52713f4a5a252e., Htable_UFDR_031,003732800093168-03594291912,1325809872607.52ff3c7c6df6e0337876bbca29cee84a.. Split took 29sec
          00:34:48,061 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog: Found 1 hlogs to remove out of total 4; oldest outstanding sequenceid is 20312224 from region 2acaf8e3acfd2e8a5825a1f6f0aca4a8
          

          My doubt is:

          From the below log, we can see the sequenceId was 20312223. So the sequenceId of 20312224 must be generated after this:

          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
          

          Concurrent flush may cause the wrong memstoresize which is mentioned in HBASE-5568(A edit larger than 20312223 could not be lost in this issue, right?). I don't think any relationships with this issue.
          Correct me if am wrong. Thank you.

          Show
          Jieshan Bean added a comment - 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. 00:28:25,460 INFO org.apache.hadoop.hbase.regionserver.HRegion: Finished memstore flush of ~153.9m for region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. in 8444ms, sequenceid=20294110, compaction requested=true 00:28:25,460 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. because regionserver20020.cacheFlusher; priority=2, compaction queue size=5835 00:30:35,328 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. 00:30:35,943 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started memstore flush for Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8., current region memstore size 129.5m 00:30:37,963 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: NOT flushing memstore for region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8., flushing=true, writesEnabled=true 00:30:37,971 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Flush requested on Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. 00:30:37,971 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Started memstore flush for Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8., current region memstore size 129.7m 00:30:47,907 INFO org.apache.hadoop.hbase.regionserver.Store: Renaming flushed file at hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/.tmp/5960455867013769207 to hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/3682074154882687307 00:30:47,907 INFO org.apache.hadoop.hbase.regionserver.Store: Renaming flushed file at hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/.tmp/5960455867013769207 to hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/3682074154882687307 00:30:49,241 INFO org.apache.hadoop.hbase.regionserver.Store: Added hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/3682074154882687307, entries=233841, sequenceid=20311822, memsize=129.5m, filesize=89.5m 00:30:49,242 INFO org.apache.hadoop.hbase.regionserver.HRegion: Finished memstore flush of ~129.5m for region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. in 13299ms, sequenceid=20311822, compaction requested=true 00:30:49,242 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. because User-triggered split; priority=1, compaction queue size=5840 00:30:55,214 INFO org.apache.hadoop.hbase.regionserver.Store: Renaming flushed file at hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/.tmp/1755862026714756815 to hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/973789709483406123 00:30:55,214 INFO org.apache.hadoop.hbase.regionserver.Store: Renaming flushed file at hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/.tmp/1755862026714756815 to hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/973789709483406123 00:30:59,614 INFO org.apache.hadoop.hbase.regionserver.Store: Added hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/2acaf8e3acfd2e8a5825a1f6f0aca4a8/value/973789709483406123, entries=7537, sequenceid=20312223, memsize=4.2m, filesize=2.9m 00:30:59,787 INFO org.apache.hadoop.hbase.regionserver.HRegion: Finished memstore flush of ~133.5m for region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. in 21816ms, sequenceid=20312223, compaction requested=true 00:30:59,787 DEBUG org.apache.hadoop.hbase.regionserver.CompactSplitThread: Compaction requested for Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. because regionserver20020.cacheFlusher; priority=0, compaction queue size=5840 00:31:12,605 INFO org.apache.hadoop.hbase.regionserver.HRegion: Starting compaction on region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. 00:31:12,607 INFO org.apache.hadoop.hbase.regionserver.HRegion: completed compaction on region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. after 0sec 00:31:12,607 INFO org.apache.hadoop.hbase.regionserver.SplitTransaction: Starting split of region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. 00:31:13,694 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Closing Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8.: disabling compactions & flushes 00:31:13,694 DEBUG org.apache.hadoop.hbase.regionserver.HRegion: Updates disabled for region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. 00:31:13,718 INFO org.apache.hadoop.hbase.regionserver.HRegion: Closed Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. 00:31:39,552 INFO org.apache.hadoop.hbase.catalog.MetaEditor: Offlined parent region Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8. in META 00:31:42,529 DEBUG org.apache.hadoop.hbase.regionserver.Store: loaded hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/52ff3c7c6df6e0337876bbca29cee84a/value/973789709483406123.2acaf8e3acfd2e8a5825a1f6f0aca4a8, isReference=true, isBulkLoadResult=false, seqid=20312224, majorCompaction=false 00:31:42,532 DEBUG org.apache.hadoop.hbase.regionserver.Store: loaded hdfs://192.168.1.103:9000/hbase/Htable_UFDR_031/259d0c620c9105928e52713f4a5a252e/value/973789709483406123.2acaf8e3acfd2e8a5825a1f6f0aca4a8, isReference=true, isBulkLoadResult=false, seqid=20312223, majorCompaction=false 00:31:42,575 INFO org.apache.hadoop.hbase.regionserver.CompactSplitThread: Region split, META updated, and report to master. Parent=Htable_UFDR_031,00332,1325808823997.2acaf8e3acfd2e8a5825a1f6f0aca4a8., new regions: Htable_UFDR_031,00332,1325809872607.259d0c620c9105928e52713f4a5a252e., Htable_UFDR_031,003732800093168-03594291912,1325809872607.52ff3c7c6df6e0337876bbca29cee84a.. Split took 29sec 00:34:48,061 DEBUG org.apache.hadoop.hbase.regionserver.wal.HLog: Found 1 hlogs to remove out of total 4; oldest outstanding sequenceid is 20312224 from region 2acaf8e3acfd2e8a5825a1f6f0aca4a8 My doubt is: From the below log, we can see the sequenceId was 20312223. So the sequenceId of 20312224 must be generated after this : 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 Concurrent flush may cause the wrong memstoresize which is mentioned in HBASE-5568 (A edit larger than 20312223 could not be lost in this issue, right?). I don't think any relationships with this issue. Correct me if am wrong. Thank you.

            People

            • Assignee:
              Unassigned
              Reporter:
              ramkrishna.s.vasudevan
            • Votes:
              0 Vote for this issue
              Watchers:
              8 Start watching this issue

              Dates

              • Created:
                Updated:

                Development