Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: 0.90.0
    • Fix Version/s: 0.90.1, 0.90.2
    • Component/s: regionserver
    • Labels:
      None

      Description

      I recently updated production data to use HBase 0.90.0.
      Now I'm periodically seeing:

      [10/02/11 17:23:27] 30076066 [mpactionChecker] ERROR nServer$MajorCompactionChecker - Caught exception
      java.lang.NullPointerException
      at org.apache.hadoop.hbase.regionserver.Store.isMajorCompaction(Store.java:832)
      at org.apache.hadoop.hbase.regionserver.Store.isMajorCompaction(Store.java:810)
      at org.apache.hadoop.hbase.regionserver.HRegion.isMajorCompaction(HRegion.java:2800)
      at org.apache.hadoop.hbase.regionserver.HRegionServer$MajorCompactionChecker.chore(HRegionServer.java:1047)
      at org.apache.hadoop.hbase.Chore.run(Chore.java:66)

      The only negative effect is that this is interrupting compactions from happening. But that is pretty serious and this might be a sign of data corruption?

      Maybe it's just my data, but this task should at least involve improving the handling to catch the NPE and still iterate through the other onlineRegions that might compact without error. The MajorCompactionChecker.chore() method only catches IOExceptions and so this NPE breaks out of that loop.

        Activity

        Hide
        Hudson added a comment -

        Integrated in HBase-TRUNK #1745 (See https://hudson.apache.org/hudson/job/HBase-TRUNK/1745/)

        Show
        Hudson added a comment - Integrated in HBase-TRUNK #1745 (See https://hudson.apache.org/hudson/job/HBase-TRUNK/1745/ )
        ryan rawson made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Resolution Fixed [ 1 ]
        Hide
        ryan rawson added a comment -

        fixed in both trunk & branch.

        Show
        ryan rawson added a comment - fixed in both trunk & branch.
        Hide
        ryan rawson added a comment -

        ttl logic is a little backwards from what one might expect.

        I need a unit test here and then commit. it will become part of 0.90.1.

        Show
        ryan rawson added a comment - ttl logic is a little backwards from what one might expect. I need a unit test here and then commit. it will become part of 0.90.1.
        Hide
        James Kennedy added a comment -

        duh, yep i get it. Just crossed a wire somewhere.

        Show
        James Kennedy added a comment - duh, yep i get it. Just crossed a wire somewhere.
        Hide
        ryan rawson added a comment -

        the logic is:

        (this.ttl == HConstants.FOREVER || oldest < this.ttl)) {

        so if we set oldest to MAX_VALUE then it will never be smaller than this.ttl which is set to 'length of time in ms an edit should live'. Therefore it would be in the range from 1 -> MAX_VALUE, and by setting oldest to MIN_VALUE this branch will ALWAYS be true and prefer to major compact a single file.

        Make sense?

        Show
        ryan rawson added a comment - the logic is: (this.ttl == HConstants.FOREVER || oldest < this.ttl)) { so if we set oldest to MAX_VALUE then it will never be smaller than this.ttl which is set to 'length of time in ms an edit should live'. Therefore it would be in the range from 1 -> MAX_VALUE, and by setting oldest to MIN_VALUE this branch will ALWAYS be true and prefer to major compact a single file. Make sense?
        Hide
        James Kennedy added a comment -

        Why choose Long.MIN_VALUE? Wouldn't Long.MAX_VALUE encourage a major compaction and get pre-0.90.0 StoreFile's out of the picture sooner?

        Show
        James Kennedy added a comment - Why choose Long.MIN_VALUE? Wouldn't Long.MAX_VALUE encourage a major compaction and get pre-0.90.0 StoreFile's out of the picture sooner?
        James Kennedy made changes -
        Assignee James Kennedy [ jk-public@troove.net ] ryan rawson [ ryanobjc ]
        stack made changes -
        Attachment 3524.txt [ 12470921 ]
        Hide
        stack added a comment -

        Here is a patch that does what Ryan has pasted into comment. +1 on commit. Hard to add a test for this.

        Show
        stack added a comment - Here is a patch that does what Ryan has pasted into comment. +1 on commit. Hard to add a test for this.
        Hide
        James Kennedy added a comment -

        So that .meta file with DATA LOSS is definitely old (2010-05-20).
        Looking back over old logs i realized that DATA LOSS WARN has been there for a while.
        So probably that is a separate issue from this CompactionChecker problem.
        Guess I'll just delete the file in HDFS.

        So, it looks like my data is stable now after the forced compactions. I didn't have to apply the patch in production code to stop the NPEs.

        I'm still concerned about how this happened to some regions and not others since all were left up long enough to get to that NPE point which only prevented the first post-0.90.0 upgrade full compactions for 8 out of 50 tables. Maybe the other 42 were updated as part of the initial startup process...

        Show
        James Kennedy added a comment - So that .meta file with DATA LOSS is definitely old (2010-05-20). Looking back over old logs i realized that DATA LOSS WARN has been there for a while. So probably that is a separate issue from this CompactionChecker problem. Guess I'll just delete the file in HDFS. So, it looks like my data is stable now after the forced compactions. I didn't have to apply the patch in production code to stop the NPEs. I'm still concerned about how this happened to some regions and not others since all were left up long enough to get to that NPE point which only prevented the first post-0.90.0 upgrade full compactions for 8 out of 50 tables. Maybe the other 42 were updated as part of the initial startup process...
        James Kennedy made changes -
        Assignee James Kennedy [ jk-public@troove.net ]
        ryan rawson made changes -
        Field Original Value New Value
        Fix Version/s 0.90.1 [ 12315548 ]
        Affects Version/s 0.90.0 [ 12313607 ]
        Priority Major [ 3 ] Blocker [ 1 ]
        Component/s regionserver [ 12312139 ]
        Hide
        James Kennedy added a comment -

        > What is the creation time of your empty file? When is it from? Maybe it's old?

        Let me re-reproduce these issues from scratch tomorrow morning.

        Show
        James Kennedy added a comment - > What is the creation time of your empty file? When is it from? Maybe it's old? Let me re-reproduce these issues from scratch tomorrow morning.
        Hide
        ryan rawson added a comment -

        compaction is "optional", meaning if it fails no data is lost, so you
        should probably be fine.

        Older versions of the code did not write out time tracker data and
        that is why your older files were giving you npes.

        Show
        ryan rawson added a comment - compaction is "optional", meaning if it fails no data is lost, so you should probably be fine. Older versions of the code did not write out time tracker data and that is why your older files were giving you npes.
        Hide
        James Kennedy added a comment -

        This patch obviously stops the npe and allows compaction checking to follow through.

        Furthermore I added a log output line that indicates when/what stores have .timeRangeTracker == null when encountered. It seemed that 7 or 8 tables (out of 50) had this problem and when i forced their major compaction from the hbase shell they stopped reporting the error.

        So it looks like the major compactions created new stores with timeRangeTracker properly.

        I'm still concerned though about how this happened in the first place and I need to do some thorough testing of the data to ensure nothing was lost.

        Ryan, in your opinion do you think this data is likely to have survived corruption?

        And thanks for your speedy help.

        Show
        James Kennedy added a comment - This patch obviously stops the npe and allows compaction checking to follow through. Furthermore I added a log output line that indicates when/what stores have .timeRangeTracker == null when encountered. It seemed that 7 or 8 tables (out of 50) had this problem and when i forced their major compaction from the hbase shell they stopped reporting the error. So it looks like the major compactions created new stores with timeRangeTracker properly. I'm still concerned though about how this happened in the first place and I need to do some thorough testing of the data to ensure nothing was lost. Ryan, in your opinion do you think this data is likely to have survived corruption? And thanks for your speedy help.
        Hide
        ryan rawson added a comment -

        try this patch:

        diff --git a/src/main/java/org/apache/hadoop/hbase/regionserver/Store.java b/src/main/java/org/apache/hadoop/hbase/regionserver/Store.java
        index d7e3ce3..519111a 100644
        — a/src/main/java/org/apache/hadoop/hbase/regionserver/Store.java
        +++ b/src/main/java/org/apache/hadoop/hbase/regionserver/Store.java
        @@ -829,7 +829,10 @@ public class Store implements HeapSize {
        if (filesToCompact.size() == 1) {
        // Single file
        StoreFile sf = filesToCompact.get(0);

        • long oldest = now - sf.getReader().timeRangeTracker.minimumTimestamp;
          + long oldest =
          + (sf.getReader().timeRangeTracker == null) ?
          + Long.MIN_VALUE :
          + now - sf.getReader().timeRangeTracker.minimumTimestamp;
          if (sf.isMajorCompaction() &&
          (this.ttl == HConstants.FOREVER || oldest < this.ttl)) {
          if (LOG.isDebugEnabled()) {

        no test yet! doh!

        Show
        ryan rawson added a comment - try this patch: diff --git a/src/main/java/org/apache/hadoop/hbase/regionserver/Store.java b/src/main/java/org/apache/hadoop/hbase/regionserver/Store.java index d7e3ce3..519111a 100644 — a/src/main/java/org/apache/hadoop/hbase/regionserver/Store.java +++ b/src/main/java/org/apache/hadoop/hbase/regionserver/Store.java @@ -829,7 +829,10 @@ public class Store implements HeapSize { if (filesToCompact.size() == 1) { // Single file StoreFile sf = filesToCompact.get(0); long oldest = now - sf.getReader().timeRangeTracker.minimumTimestamp; + long oldest = + (sf.getReader().timeRangeTracker == null) ? + Long.MIN_VALUE : + now - sf.getReader().timeRangeTracker.minimumTimestamp; if (sf.isMajorCompaction() && (this.ttl == HConstants.FOREVER || oldest < this.ttl)) { if (LOG.isDebugEnabled()) { no test yet! doh!
        Hide
        ryan rawson added a comment -

        the issue is that if the hfile does not have timerangeBytes, this code doesn't trigger:

        (StoreFile.java)
        if (timerangeBytes != null)

        { this.reader.timeRangeTracker = new TimeRangeTracker(); Writables.copyWritable(timerangeBytes, this.reader.timeRangeTracker); }

        And timeRangeTracker remains null.

        But this code doesnt check for null:

        (Store.java)
        832 long oldest = now - sf.getReader().timeRangeTracker.minimumTimestamp;

        if timeRangeTracker is null, we should probably use Integer.MIN_VALUE for minimumTimestamp.

        What is the creation time of your empty file? When is it from? Maybe it's old?

        Show
        ryan rawson added a comment - the issue is that if the hfile does not have timerangeBytes, this code doesn't trigger: (StoreFile.java) if (timerangeBytes != null) { this.reader.timeRangeTracker = new TimeRangeTracker(); Writables.copyWritable(timerangeBytes, this.reader.timeRangeTracker); } And timeRangeTracker remains null. But this code doesnt check for null: (Store.java) 832 long oldest = now - sf.getReader().timeRangeTracker.minimumTimestamp; if timeRangeTracker is null, we should probably use Integer.MIN_VALUE for minimumTimestamp. What is the creation time of your empty file? When is it from? Maybe it's old?
        Hide
        James Kennedy added a comment -

        Thanks. I'm in a bit of a pickle. Though I tested all upgrades on QA and test data, this issue has only cropped up on a production deploy. Since our production app appeared to be running smoothly we gave it a +1 and there is already new user data in there. I'm wondering if I should revert to older data anyway (some user data loss) until this corruption is handled...

        Shouldn't 0.90.0 automatically upgrade old data?

        Show
        James Kennedy added a comment - Thanks. I'm in a bit of a pickle. Though I tested all upgrades on QA and test data, this issue has only cropped up on a production deploy. Since our production app appeared to be running smoothly we gave it a +1 and there is already new user data in there. I'm wondering if I should revert to older data anyway (some user data loss) until this corruption is handled... Shouldn't 0.90.0 automatically upgrade old data?
        Hide
        ryan rawson added a comment -

        Old files causing new code to break it seems. Good job tracking it down!

        Show
        ryan rawson added a comment - Old files causing new code to break it seems. Good job tracking it down!
        Hide
        James Kennedy added a comment -

        I found this in the hbase.log:

        [10/02/11 18:37:29] 44386 [1297391814420-0] WARN adoop.hbase.regionserver.Store - Skipping hdfs://localhost:7701/hbase/.META./1028785192/info/2685681686584745388 because its empty. HBASE-646 DATA LOSS?

        So perhaps this issue is a symptom of corrupt meta data. HOW can I fix this!?

        Show
        James Kennedy added a comment - I found this in the hbase.log: [10/02/11 18:37:29] 44386 [1297391814420-0] WARN adoop.hbase.regionserver.Store - Skipping hdfs://localhost:7701/hbase/.META./1028785192/info/2685681686584745388 because its empty. HBASE-646 DATA LOSS? So perhaps this issue is a symptom of corrupt meta data. HOW can I fix this!?
        Hide
        James Kennedy added a comment -

        Did some more debugging and got a little more intel: What's null on that line is sf.getReader().timeRangeTracker.

        It seems to be consistently null for many if not all tables. Anyone know how this could happen?

        Show
        James Kennedy added a comment - Did some more debugging and got a little more intel: What's null on that line is sf.getReader().timeRangeTracker. It seems to be consistently null for many if not all tables. Anyone know how this could happen?
        James Kennedy created issue -

          People

          • Assignee:
            ryan rawson
            Reporter:
            James Kennedy
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development