Uploaded image for project: 'HBase'
  1. HBase
  2. HBASE-6852

SchemaMetrics.updateOnCacheHit costs too much while full scanning a table with all of its fields

    Details

    • Type: Improvement
    • Status: Closed
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: 0.94.0
    • Fix Version/s: 0.94.3
    • Component/s: metrics
    • Labels:
    • Hadoop Flags:
      Reviewed

      Description

      The SchemaMetrics.updateOnCacheHit costs too much while I am doing the full table scanning.
      Here is the top 5 hotspots within regionserver while full scanning a table: (Sorry for the less-well-format)

      CPU: Intel Westmere microarchitecture, speed 2.262e+06 MHz (estimated)
      Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 5000000
      samples % image name symbol name
      -------------------------------------------------------------------------------
      98447 13.4324 14033.jo void org.apache.hadoop.hbase.regionserver.metrics.SchemaMetrics.updateOnCacheHit(org.apache.hadoop.hbase.io.hfile.BlockType$BlockCategory, boolean)
      98447 100.000 14033.jo void org.apache.hadoop.hbase.regionserver.metrics.SchemaMetrics.updateOnCacheHit(org.apache.hadoop.hbase.io.hfile.BlockType$BlockCategory, boolean) [self]
      -------------------------------------------------------------------------------
      45814 6.2510 14033.jo int org.apache.hadoop.hbase.KeyValue$KeyComparator.compareRows(byte[], int, int, byte[], int, int)
      45814 100.000 14033.jo int org.apache.hadoop.hbase.KeyValue$KeyComparator.compareRows(byte[], int, int, byte[], int, int) [self]
      -------------------------------------------------------------------------------
      43523 5.9384 14033.jo boolean org.apache.hadoop.hbase.regionserver.StoreFileScanner.reseek(org.apache.hadoop.hbase.KeyValue)
      43523 100.000 14033.jo boolean org.apache.hadoop.hbase.regionserver.StoreFileScanner.reseek(org.apache.hadoop.hbase.KeyValue) [self]
      -------------------------------------------------------------------------------
      42548 5.8054 14033.jo int org.apache.hadoop.hbase.KeyValue$KeyComparator.compare(byte[], int, int, byte[], int, int)
      42548 100.000 14033.jo int org.apache.hadoop.hbase.KeyValue$KeyComparator.compare(byte[], int, int, byte[], int, int) [self]
      -------------------------------------------------------------------------------
      40572 5.5358 14033.jo int org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$BlockIndexReader.binarySearchNonRootIndex(byte[], int, int, java.nio.ByteBuffer, org.apache.hadoop.io.RawComparator)~1
      40572 100.000 14033.jo int org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$BlockIndexReader.binarySearchNonRootIndex(byte[], int, int, java.nio.ByteBuffer, org.apache.hadoop.io.RawComparator)~1 [self]

      1. 6852-0.94_2.patch
        8 kB
        Cheng Hao
      2. 6852-0.94_3.patch
        7 kB
        Cheng Hao
      3. 6852-0.94.txt
        7 kB
        Lars Hofhansl
      4. metrics_hotspots.png
        57 kB
        Cheng Hao
      5. onhitcache-trunk.patch
        7 kB
        Cheng Hao

        Activity

        Hide
        hcheng Cheng Hao added a comment -

        The fix will cache the metrics and flush every 2000 calls, or the HFileReader closed.

        Show
        hcheng Cheng Hao added a comment - The fix will cache the metrics and flush every 2000 calls, or the HFileReader closed.
        Hide
        hcheng Cheng Hao added a comment -

        After patch the fix, the oprofile shows the top 8 hotspots as:

        samples % image name app name symbol name
        -------------------------------------------------------------------------------
        59829 7.9422 17779.jo java int org.apache.hadoop.hbase.KeyValue$KeyComparator.compare(byte[], int, i
        nt, byte[], int, int)
        59829 100.000 17779.jo java int org.apache.hadoop.hbase.KeyValue$KeyComparator.compare(byte[], int,
        int, byte[], int, int) [self]
        -------------------------------------------------------------------------------
        28571 3.7927 17779.jo java int org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$BlockIndexReader.bin
        arySearchNonRootIndex(byte[], int, int, java.nio.ByteBuffer, org.apache.hadoop.io.RawComparator)
        28571 100.000 17779.jo java int org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$BlockIndexReader.b
        inarySearchNonRootIndex(byte[], int, int, java.nio.ByteBuffer, org.apache.hadoop.io.RawComparator) [self]
        -------------------------------------------------------------------------------
        19331 2.5662 17779.jo java org.apache.hadoop.hbase.regionserver.ScanQueryMatcher$MatchCode org.apach
        e.hadoop.hbase.regionserver.ScanQueryMatcher.match(org.apache.hadoop.hbase.KeyValue)
        19331 100.000 17779.jo java org.apache.hadoop.hbase.regionserver.ScanQueryMatcher$MatchCode org.apa
        che.hadoop.hbase.regionserver.ScanQueryMatcher.match(org.apache.hadoop.hbase.KeyValue) [self]
        -------------------------------------------------------------------------------
        19063 2.5306 17779.jo java void org.apache.hadoop.hbase.regionserver.StoreFileScanner.enforceSeek()
        19063 100.000 17779.jo java void org.apache.hadoop.hbase.regionserver.StoreFileScanner.enforceSeek(
        ) [self]
        -------------------------------------------------------------------------------
        1 0.0054 libjvm.so java Monitor::ILock(Thread*)
        1 0.0054 libjvm.so java ObjectMonitor::enter(Thread*)
        2 0.0107 libjvm.so java VMThread::loop()
        18642 99.9785 libjvm.so java StealTask::do_it(GCTaskManager*, unsigned int)
        18646 2.4752 libjvm.so java SpinPause
        18646 100.000 libjvm.so java SpinPause [self]
        -------------------------------------------------------------------------------
        15860 2.1054 17779.jo java byte[] org.apache.hadoop.hbase.KeyValue.createByteArray(byte[], int, int,
        byte[], int, int, byte[], int, int, long, org.apache.hadoop.hbase.KeyValue$Type, byte[], int, int)
        15860 100.000 17779.jo java byte[] org.apache.hadoop.hbase.KeyValue.createByteArray(byte[], int, in
        t, byte[], int, int, byte[], int, int, long, org.apache.hadoop.hbase.KeyValue$Type, byte[], int, int) [self]
        -------------------------------------------------------------------------------
        14754 1.9586 17779.jo java org.apache.hadoop.hbase.io.hfile.Cacheable org.apache.hadoop.hbase.io.hfi
        le.LruBlockCache.getBlock(org.apache.hadoop.hbase.io.hfile.BlockCacheKey, boolean)
        14754 100.000 17779.jo java org.apache.hadoop.hbase.io.hfile.Cacheable org.apache.hadoop.hbase.io.h
        file.LruBlockCache.getBlock(org.apache.hadoop.hbase.io.hfile.BlockCacheKey, boolean) [self]
        -------------------------------------------------------------------------------
        13068 1.7348 17779.jo java org.apache.hadoop.hbase.io.hfile.HFileBlock org.apache.hadoop.hbase.io.hf
        ile.HFileBlockIndex$BlockIndexReader.seekToDataBlock(byte[], int, int, org.apache.hadoop.hbase.io.hfile.HFileBlock, boolean, boolean, boolean
        )~2
        13068 100.000 17779.jo java org.apache.hadoop.hbase.io.hfile.HFileBlock org.apache.hadoop.hbase.io.
        hfile.HFileBlockIndex$BlockIndexReader.seekToDataBlock(byte[], int, int, org.apache.hadoop.hbase.io.hfile.HFileBlock, boolean, boolean, boole
        an)~2 [self]
        -------------------------------------------------------------------------------

        Show
        hcheng Cheng Hao added a comment - After patch the fix, the oprofile shows the top 8 hotspots as: samples % image name app name symbol name ------------------------------------------------------------------------------- 59829 7.9422 17779.jo java int org.apache.hadoop.hbase.KeyValue$KeyComparator.compare(byte[], int, i nt, byte[], int, int) 59829 100.000 17779.jo java int org.apache.hadoop.hbase.KeyValue$KeyComparator.compare(byte[], int, int, byte[], int, int) [self] ------------------------------------------------------------------------------- 28571 3.7927 17779.jo java int org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$BlockIndexReader.bin arySearchNonRootIndex(byte[], int, int, java.nio.ByteBuffer, org.apache.hadoop.io.RawComparator) 28571 100.000 17779.jo java int org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$BlockIndexReader.b inarySearchNonRootIndex(byte[], int, int, java.nio.ByteBuffer, org.apache.hadoop.io.RawComparator) [self] ------------------------------------------------------------------------------- 19331 2.5662 17779.jo java org.apache.hadoop.hbase.regionserver.ScanQueryMatcher$MatchCode org.apach e.hadoop.hbase.regionserver.ScanQueryMatcher.match(org.apache.hadoop.hbase.KeyValue) 19331 100.000 17779.jo java org.apache.hadoop.hbase.regionserver.ScanQueryMatcher$MatchCode org.apa che.hadoop.hbase.regionserver.ScanQueryMatcher.match(org.apache.hadoop.hbase.KeyValue) [self] ------------------------------------------------------------------------------- 19063 2.5306 17779.jo java void org.apache.hadoop.hbase.regionserver.StoreFileScanner.enforceSeek() 19063 100.000 17779.jo java void org.apache.hadoop.hbase.regionserver.StoreFileScanner.enforceSeek( ) [self] ------------------------------------------------------------------------------- 1 0.0054 libjvm.so java Monitor::ILock(Thread*) 1 0.0054 libjvm.so java ObjectMonitor::enter(Thread*) 2 0.0107 libjvm.so java VMThread::loop() 18642 99.9785 libjvm.so java StealTask::do_it(GCTaskManager*, unsigned int) 18646 2.4752 libjvm.so java SpinPause 18646 100.000 libjvm.so java SpinPause [self] ------------------------------------------------------------------------------- 15860 2.1054 17779.jo java byte[] org.apache.hadoop.hbase.KeyValue.createByteArray(byte[], int, int, byte[], int, int, byte[], int, int, long, org.apache.hadoop.hbase.KeyValue$Type, byte[], int, int) 15860 100.000 17779.jo java byte[] org.apache.hadoop.hbase.KeyValue.createByteArray(byte[], int, in t, byte[], int, int, byte[], int, int, long, org.apache.hadoop.hbase.KeyValue$Type, byte[], int, int) [self] ------------------------------------------------------------------------------- 14754 1.9586 17779.jo java org.apache.hadoop.hbase.io.hfile.Cacheable org.apache.hadoop.hbase.io.hfi le.LruBlockCache.getBlock(org.apache.hadoop.hbase.io.hfile.BlockCacheKey, boolean) 14754 100.000 17779.jo java org.apache.hadoop.hbase.io.hfile.Cacheable org.apache.hadoop.hbase.io.h file.LruBlockCache.getBlock(org.apache.hadoop.hbase.io.hfile.BlockCacheKey, boolean) [self] ------------------------------------------------------------------------------- 13068 1.7348 17779.jo java org.apache.hadoop.hbase.io.hfile.HFileBlock org.apache.hadoop.hbase.io.hf ile.HFileBlockIndex$BlockIndexReader.seekToDataBlock(byte[], int, int, org.apache.hadoop.hbase.io.hfile.HFileBlock, boolean, boolean, boolean )~2 13068 100.000 17779.jo java org.apache.hadoop.hbase.io.hfile.HFileBlock org.apache.hadoop.hbase.io. hfile.HFileBlockIndex$BlockIndexReader.seekToDataBlock(byte[], int, int, org.apache.hadoop.hbase.io.hfile.HFileBlock, boolean, boolean, boole an)~2 [self] -------------------------------------------------------------------------------
        Hide
        hadoopqa Hadoop QA added a comment -

        -1 overall. Here are the results of testing the latest attachment
        http://issues.apache.org/jira/secure/attachment/12545995/onhitcache-trunk.patch
        against trunk revision .

        +1 @author. The patch does not contain any @author tags.

        +1 tests included. The patch appears to include 3 new or modified tests.

        -1 patch. The patch command could not apply the patch.

        Console output: https://builds.apache.org/job/PreCommit-HBASE-Build/2911//console

        This message is automatically generated.

        Show
        hadoopqa Hadoop QA added a comment - -1 overall. Here are the results of testing the latest attachment http://issues.apache.org/jira/secure/attachment/12545995/onhitcache-trunk.patch against trunk revision . +1 @author. The patch does not contain any @author tags. +1 tests included. The patch appears to include 3 new or modified tests. -1 patch. The patch command could not apply the patch. Console output: https://builds.apache.org/job/PreCommit-HBASE-Build/2911//console This message is automatically generated.
        Hide
        stack stack added a comment -

        [~chenghao_sh] Is it 0.94.0 that you are running?

        Lars Hofhansl Did we fix these in later 0.94s?

        Show
        stack stack added a comment - [~chenghao_sh] Is it 0.94.0 that you are running? Lars Hofhansl Did we fix these in later 0.94s?
        Hide
        stack stack added a comment -

        It doesn't look like it (after taking a look).

        Show
        stack stack added a comment - It doesn't look like it (after taking a look).
        Hide
        hcheng Cheng Hao added a comment -

        yes, I ran the profiling in 0.94.0, but the patch is based on the trunk. it should also works for the later 0.94s.

        Show
        hcheng Cheng Hao added a comment - yes, I ran the profiling in 0.94.0, but the patch is based on the trunk. it should also works for the later 0.94s.
        Hide
        hcheng Cheng Hao added a comment -

        It's quite similar with https://issues.apache.org/jira/browse/HBASE-6603, but per my testing, the 6603 doesn't improve that much in my case (full scan a table), but this fix did improve the performance a lot (it's 10% time shorter totally).

        Show
        hcheng Cheng Hao added a comment - It's quite similar with https://issues.apache.org/jira/browse/HBASE-6603 , but per my testing, the 6603 doesn't improve that much in my case (full scan a table), but this fix did improve the performance a lot (it's 10% time shorter totally).
        Hide
        hcheng Cheng Hao added a comment -

        stack, do you mean I should submit the patch for 0.94 as well?

        Show
        hcheng Cheng Hao added a comment - stack, do you mean I should submit the patch for 0.94 as well?
        Hide
        stack stack added a comment -

        Patch looks good as does the change in the character of the pasted oprofile output.

        Did you look at adding a close to AbstractHFileReader that hfile v1 and v2 reader close could share? Would that make sense here?

        The THRESHOLD_METRICS_FLUSH = 2k seems arbitrary. Any reason why this number in particular?

        Nit is that the param name isCompaction is the name of a method that returns a boolean result.

        +1 on patch.

        Elliott Clark Mr. Metrics, want to take a look see at this one?

        Show
        stack stack added a comment - Patch looks good as does the change in the character of the pasted oprofile output. Did you look at adding a close to AbstractHFileReader that hfile v1 and v2 reader close could share? Would that make sense here? The THRESHOLD_METRICS_FLUSH = 2k seems arbitrary. Any reason why this number in particular? Nit is that the param name isCompaction is the name of a method that returns a boolean result. +1 on patch. Elliott Clark Mr. Metrics, want to take a look see at this one?
        Hide
        lhofhansl Lars Hofhansl added a comment -

        @Stack: No, this is a different issue. Didn't come up in my profiling since I only did cache path (so far).

        Good one Cheng.

        Show
        lhofhansl Lars Hofhansl added a comment - @Stack: No, this is a different issue. Didn't come up in my profiling since I only did cache path (so far). Good one Cheng.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Since 0.94.2. got delayed, pulling this in.

        Show
        lhofhansl Lars Hofhansl added a comment - Since 0.94.2. got delayed, pulling this in.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Wait. This is the cache hit path we're talking about. Didn't come up in my profiling at all.

        Show
        lhofhansl Lars Hofhansl added a comment - Wait. This is the cache hit path we're talking about. Didn't come up in my profiling at all.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        This is third time that metrics come up as a performance issue.
        Do we have to think about this generally? How perfect do these metrics have to be?

        (Assuming a 64 bit architecture) we could just use plain (not even volatile) longs and accept the fact that we'll miss some updates or overwrite others; the values would still be the right ballpark.

        Show
        lhofhansl Lars Hofhansl added a comment - This is third time that metrics come up as a performance issue. Do we have to think about this generally? How perfect do these metrics have to be? (Assuming a 64 bit architecture) we could just use plain (not even volatile) longs and accept the fact that we'll miss some updates or overwrite others; the values would still be the right ballpark.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        @Cheng: Even with this patch we're still updating an AtomicLong each time we get a cache hit, right? I had assumed that that was the slow part. Is it not?

        Show
        lhofhansl Lars Hofhansl added a comment - @Cheng: Even with this patch we're still updating an AtomicLong each time we get a cache hit, right? I had assumed that that was the slow part. Is it not?
        Hide
        hcheng Cheng Hao added a comment -

        @stack: it should make more sense if we put the close() into the AbastractHFileReader, but not sure if there any other concern, since the AbstractHFileReader doesn't have it.

        And for the THRESHOLD_METRICS_FLUSH = 2k, which I used during my testing, hope it's big enough for reducing the overhead, and less impact for getting the metrics snapshot timely. sorry, I may not able to give a good experiential number for it.

        @Lars: Yes, that's right, we're still updating an AtomicLong each time, but from profiling result, I didn't see the AtomicLong became the new hotspots, and the testing also did >10% saved in running time, which may means the overhead of AtomicLong could be ignored.

        Show
        hcheng Cheng Hao added a comment - @stack: it should make more sense if we put the close() into the AbastractHFileReader, but not sure if there any other concern, since the AbstractHFileReader doesn't have it. And for the THRESHOLD_METRICS_FLUSH = 2k, which I used during my testing, hope it's big enough for reducing the overhead, and less impact for getting the metrics snapshot timely. sorry, I may not able to give a good experiential number for it. @Lars: Yes, that's right, we're still updating an AtomicLong each time, but from profiling result, I didn't see the AtomicLong became the new hotspots, and the testing also did >10% saved in running time, which may means the overhead of AtomicLong could be ignored.
        Hide
        stack stack added a comment -

        Do we have to think about this generally? How perfect do these metrics have to be?

        In 0.94 we started recording way more than previous.

        I like your question on how perfect do they need to be. For metrics updated by 1 frequently, my quess is we could miss a few.

        Why we using atomic longs anyway and not cliffclick's high scale lib... its in our CLASSPATH...

        Show
        stack stack added a comment - Do we have to think about this generally? How perfect do these metrics have to be? In 0.94 we started recording way more than previous. I like your question on how perfect do they need to be. For metrics updated by 1 frequently, my quess is we could miss a few. Why we using atomic longs anyway and not cliffclick's high scale lib... its in our CLASSPATH...
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Interesting. Thanks Cheng. I wonder what causes the performance problem then. Is it the get/putIfAbsent of the ConcurrentMap we store the metrics in?

        I'd probably feel better if you set the threshold to 100 (instead of 2000) - you'd still reduce the time used there by 99%.

        Also looking at the places where updateOnCacheHit is called... We also increment an AtomicLong (cacheHits), which is never read (WTF). We should remove that counter while we're at it (even when AtomicLongs are not the problem).

        Show
        lhofhansl Lars Hofhansl added a comment - Interesting. Thanks Cheng. I wonder what causes the performance problem then. Is it the get/putIfAbsent of the ConcurrentMap we store the metrics in? I'd probably feel better if you set the threshold to 100 (instead of 2000) - you'd still reduce the time used there by 99%. Also looking at the places where updateOnCacheHit is called... We also increment an AtomicLong (cacheHits), which is never read (WTF). We should remove that counter while we're at it (even when AtomicLongs are not the problem).
        Hide
        xieliang007 Liang Xie added a comment -

        Hi Cheng, for running time, could you exclude the system resouce factor ? e.g. you ran the original version with many physical IOs, but reran the patched version without similar physical IO requests due to hitting OS page cache.
        In other words, could the reduced running time symptom be reproduced always, even you run patched version first, then rerun the original version ? It'd better if you can issue "echo 1 > /proc/sys/vm/drop_caches" to free pagecache between each test.

        Show
        xieliang007 Liang Xie added a comment - Hi Cheng, for running time, could you exclude the system resouce factor ? e.g. you ran the original version with many physical IOs, but reran the patched version without similar physical IO requests due to hitting OS page cache. In other words, could the reduced running time symptom be reproduced always, even you run patched version first, then rerun the original version ? It'd better if you can issue "echo 1 > /proc/sys/vm/drop_caches" to free pagecache between each test.
        Hide
        hcheng Cheng Hao added a comment -

        Lars, the only place to use the ConcurentMap in SchemaMetrics is tableAndFamilyToMetrics. in this patch, I pre-create an array of AtomicLong for all of the possible oncachehit metrics items, which will avoids the concurrent issue and easy to be indexed while accessing.

        Thanks stack and Lars for the suggestions, I will create another patch file instead.

        Show
        hcheng Cheng Hao added a comment - Lars, the only place to use the ConcurentMap in SchemaMetrics is tableAndFamilyToMetrics. in this patch, I pre-create an array of AtomicLong for all of the possible oncachehit metrics items, which will avoids the concurrent issue and easy to be indexed while accessing. Thanks stack and Lars for the suggestions, I will create another patch file instead.
        Hide
        hcheng Cheng Hao added a comment -

        Hi Liang, it's really good suggestion. Actually I didn't free the pagecache of OS before each launch. But I can try that later.

        In my tests, the table data was about 600GB within 4 machines, I guess the system cache may not impact the entire performance so much for a full table scanning.

        Show
        hcheng Cheng Hao added a comment - Hi Liang, it's really good suggestion. Actually I didn't free the pagecache of OS before each launch. But I can try that later. In my tests, the table data was about 600GB within 4 machines, I guess the system cache may not impact the entire performance so much for a full table scanning.
        Hide
        hcheng Cheng Hao added a comment -

        change the THRESHOLD_METRICS_FLUSH from 2000 to 100, per Lars' suggestion

        Show
        hcheng Cheng Hao added a comment - change the THRESHOLD_METRICS_FLUSH from 2000 to 100, per Lars' suggestion
        Hide
        hcheng Cheng Hao added a comment -

        I didn't remove the "cacheHits" in the HFileReaderV1 & V2, hope it's a good start to design a less overhead metrics framework.

        Show
        hcheng Cheng Hao added a comment - I didn't remove the "cacheHits" in the HFileReaderV1 & V2, hope it's a good start to design a less overhead metrics framework.
        Hide
        hadoopqa Hadoop QA added a comment -

        -1 overall. Here are the results of testing the latest attachment
        http://issues.apache.org/jira/secure/attachment/12546009/onhitcache-trunk.patch
        against trunk revision .

        +1 @author. The patch does not contain any @author tags.

        +1 tests included. The patch appears to include 3 new or modified tests.

        -1 patch. The patch command could not apply the patch.

        Console output: https://builds.apache.org/job/PreCommit-HBASE-Build/2913//console

        This message is automatically generated.

        Show
        hadoopqa Hadoop QA added a comment - -1 overall. Here are the results of testing the latest attachment http://issues.apache.org/jira/secure/attachment/12546009/onhitcache-trunk.patch against trunk revision . +1 @author. The patch does not contain any @author tags. +1 tests included. The patch appears to include 3 new or modified tests. -1 patch. The patch command could not apply the patch. Console output: https://builds.apache.org/job/PreCommit-HBASE-Build/2913//console This message is automatically generated.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Patch looks good. I'll remain sceptical about the real life impact, though. The expensive is taking out the memory barriers. As long as we use AtomicLong (or volatiles, or synchronized, or use ConcurrentMap) this is still going to happen.

        Lemme move this out to 0.94.3, so that we can performance test this a bit more.

        Show
        lhofhansl Lars Hofhansl added a comment - Patch looks good. I'll remain sceptical about the real life impact, though. The expensive is taking out the memory barriers. As long as we use AtomicLong (or volatiles, or synchronized, or use ConcurrentMap) this is still going to happen. Lemme move this out to 0.94.3, so that we can performance test this a bit more.
        Hide
        mikhail Mikhail Bautin added a comment -

        Lars Hofhansl: what are the other cases when metrics came up as performance issues?

        [~chenghao_sh]: you said that your dataset size was 600GB, and the total amount of block cache was presumably much smaller than that, which makes me think the workload should have been I/O-bound. What was the CPU utilization on your test? What was the disk throughput?

        Show
        mikhail Mikhail Bautin added a comment - Lars Hofhansl : what are the other cases when metrics came up as performance issues? [~chenghao_sh] : you said that your dataset size was 600GB, and the total amount of block cache was presumably much smaller than that, which makes me think the workload should have been I/O-bound. What was the CPU utilization on your test? What was the disk throughput?
        Hide
        tlipcon Todd Lipcon added a comment -

        I have a "full table scan in isolation" benchmark I've been working on. My benchmark currently disables metrics, so I haven't seen this, but I'll add a flag to it to enable metrics and see if I can reproduce. Since it runs in isolation it's easy to run under "perf stat" and get cycle counts, etc, out of it. Will report back next week.

        Show
        tlipcon Todd Lipcon added a comment - I have a "full table scan in isolation" benchmark I've been working on. My benchmark currently disables metrics, so I haven't seen this, but I'll add a flag to it to enable metrics and see if I can reproduce. Since it runs in isolation it's easy to run under "perf stat" and get cycle counts, etc, out of it. Will report back next week.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        HBASE-6603 was the other one. Turns out this is the 2nd time (not the 3rd). The other issue I found through profiling were not metric related.

        So I was thinking what we should generally do about this. The idea in this patch (using an array indexed by metric) is a good one. Can we generally do that? I.e.:

        1. we know the metric we wish to collect ahead of time
        2. Assign an index to each of them, and collect the value in an array
        3. Simply use long (not volatile, atomiclong, just long)
        4. Upon update or read we access the metric array by index

        That would eliminate the cost of the ConcurrentMap and of the AtomicXYZ, with the caveat that the metric are only an approximation, which at the very least will make testing much harder.
        Maybe we have exact and fuzzy metric and only use the fuzzy one on the hot code-paths.

        Show
        lhofhansl Lars Hofhansl added a comment - HBASE-6603 was the other one. Turns out this is the 2nd time (not the 3rd). The other issue I found through profiling were not metric related. So I was thinking what we should generally do about this. The idea in this patch (using an array indexed by metric) is a good one. Can we generally do that? I.e.: we know the metric we wish to collect ahead of time Assign an index to each of them, and collect the value in an array Simply use long (not volatile, atomiclong, just long) Upon update or read we access the metric array by index That would eliminate the cost of the ConcurrentMap and of the AtomicXYZ, with the caveat that the metric are only an approximation, which at the very least will make testing much harder. Maybe we have exact and fuzzy metric and only use the fuzzy one on the hot code-paths.
        Hide
        tlipcon Todd Lipcon added a comment -

        If using an array of longs, we'd get a ton of cache contention effects. Whatever we do should be cache-line padded to avoid this perf hole.

        Having a per-thread (ThreadLocal) metrics array isn't a bad way to go: no contention, can use non-volatile types, and can be stale-read during metrics snapshots by just iterating over all the threads.

        Show
        tlipcon Todd Lipcon added a comment - If using an array of longs, we'd get a ton of cache contention effects. Whatever we do should be cache-line padded to avoid this perf hole. Having a per-thread (ThreadLocal) metrics array isn't a bad way to go: no contention, can use non-volatile types, and can be stale-read during metrics snapshots by just iterating over all the threads.
        Hide
        stack stack added a comment -

        Perhaps use the cliffclick counter (if cost < volatile) and not have to do fuzzy?

        Show
        stack stack added a comment - Perhaps use the cliffclick counter (if cost < volatile) and not have to do fuzzy?
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Oh yeah, you mentioned cliffclick... Need to look at that.

        Show
        lhofhansl Lars Hofhansl added a comment - Oh yeah, you mentioned cliffclick... Need to look at that.
        Hide
        stack stack added a comment -

        Lars Hofhansl ....I made my comment before I saw Todd's suggestion

        Show
        stack stack added a comment - Lars Hofhansl ....I made my comment before I saw Todd's suggestion
        Hide
        eclark Elliott Clark added a comment -

        I think we should start doing more of what this patch does. Collect the values locally and then use a single call into the metrics sources to push the collected metrics. In addition I think that we should remove some of the lesser used dynamic metrics, and for other stop using the time varying rate.

        For the most part I think that will remove the cost of metrics getting too out of control. However I don't think that we should stop using AtomicLong/AtomicInt. From my understanding on most architectures the JVM will turn getAndIncrement into just one cpu instruction, rather than using compare and swap. So there's very little gained by sacrificing correctness.

        Show
        eclark Elliott Clark added a comment - I think we should start doing more of what this patch does. Collect the values locally and then use a single call into the metrics sources to push the collected metrics. In addition I think that we should remove some of the lesser used dynamic metrics, and for other stop using the time varying rate. For the most part I think that will remove the cost of metrics getting too out of control. However I don't think that we should stop using AtomicLong/AtomicInt. From my understanding on most architectures the JVM will turn getAndIncrement into just one cpu instruction, rather than using compare and swap. So there's very little gained by sacrificing correctness.
        Hide
        tlipcon Todd Lipcon added a comment -

        getAndIncrement into just one cpu instruction

        True, but it's a pretty expensive instruction, since it has to steal that cache line from whichever other core used it previously, and I believe acts as a full memory barrier as well (eg flushing write-combining buffers)

        The cliff click counter is effective but has more memory usage. Aggregating stuff locally and pushing to metrics seems ideal, but if we can't do that easily, then having the metrics per-thread and then occasionally grabbing them would work too. Memcached metrics work like that.

        Show
        tlipcon Todd Lipcon added a comment - getAndIncrement into just one cpu instruction True, but it's a pretty expensive instruction, since it has to steal that cache line from whichever other core used it previously, and I believe acts as a full memory barrier as well (eg flushing write-combining buffers) The cliff click counter is effective but has more memory usage. Aggregating stuff locally and pushing to metrics seems ideal, but if we can't do that easily, then having the metrics per-thread and then occasionally grabbing them would work too. Memcached metrics work like that.
        Hide
        eclark Elliott Clark added a comment -

        Aggregating stuff locally and pushing to metrics seems ideal

        With that comes a lot of book keeping and potential places to leak memory(if we use strong references) or to lose metrics data (if we use weak references). I'm not sure that the perf gain will be high enough to justify that.

        Since we already shim a lot to the metrics2 classes it seems like using the high-scale-lib counters to create conurrent versions of the MetricMutableCounter

        {Long|Int}

        would stop most cache contention pretty easily. For me these seem like the order of cost vs benefit:

        1. Aggregating metrics locally before pushing to the metrics system whenever possible
        2. Using the hashmap less (This is already happening in the metrics2 move over. See MasterMetricsSourceImpl for how known metrics are staying away from the hashmap)
        3. Changing metrics to use counters rather than time varying rate wherever possible (Lots less locking if we don't need to keep min/max)
        4. Create CliffClick versions of Counters and use them whenever there's concurrent access
        5. Look at ThreadLocal caches versions of metrics.
        Show
        eclark Elliott Clark added a comment - Aggregating stuff locally and pushing to metrics seems ideal With that comes a lot of book keeping and potential places to leak memory(if we use strong references) or to lose metrics data (if we use weak references). I'm not sure that the perf gain will be high enough to justify that. Since we already shim a lot to the metrics2 classes it seems like using the high-scale-lib counters to create conurrent versions of the MetricMutableCounter {Long|Int} would stop most cache contention pretty easily. For me these seem like the order of cost vs benefit: Aggregating metrics locally before pushing to the metrics system whenever possible Using the hashmap less (This is already happening in the metrics2 move over. See MasterMetricsSourceImpl for how known metrics are staying away from the hashmap) Changing metrics to use counters rather than time varying rate wherever possible (Lots less locking if we don't need to keep min/max) Create CliffClick versions of Counters and use them whenever there's concurrent access Look at ThreadLocal caches versions of metrics.
        Hide
        hcheng Cheng Hao added a comment -

        Cheng Hao: you said that your dataset size was 600GB, and the total amount of block cache was presumably much smaller than that, which makes me think the workload should have been I/O-bound. What was the CPU utilization on your test? What was the disk throughput?

        Actually it's the CPU-bound. and the utilization is more than 80%.

        I have 4 machines and each machine has 12 disks and 24 CPU cores.
        Besides, in order to make it more effective, I have splitted the regions twice, and then did the major compact, to be sure the data locality. After that, I ran the data scanning tests base on Hive query like "select count() from xxx";

        I am also curious if there any overheads of threads/syscalls switching (like during the IPC). PS: I did set the "hbase.client.scanner.caching" as 1000;

        Show
        hcheng Cheng Hao added a comment - Cheng Hao: you said that your dataset size was 600GB, and the total amount of block cache was presumably much smaller than that, which makes me think the workload should have been I/O-bound. What was the CPU utilization on your test? What was the disk throughput? Actually it's the CPU-bound. and the utilization is more than 80%. I have 4 machines and each machine has 12 disks and 24 CPU cores. Besides, in order to make it more effective, I have splitted the regions twice, and then did the major compact, to be sure the data locality. After that, I ran the data scanning tests base on Hive query like "select count() from xxx"; I am also curious if there any overheads of threads/syscalls switching (like during the IPC). PS: I did set the "hbase.client.scanner.caching" as 1000;
        Hide
        stack stack added a comment -

        So what is the feeling here? This is an improvement. Its a sketch of what we'd like to do longterm. It improves your performance Cheng Hao? I'm inclined to commit it.

        Show
        stack stack added a comment - So what is the feeling here? This is an improvement. Its a sketch of what we'd like to do longterm. It improves your performance Cheng Hao ? I'm inclined to commit it.
        Hide
        hcheng Cheng Hao added a comment -

        Hi, stack, the patch does improve the performance in my case, and for the AtomicLong stuff, maybe we could wait for the next generation of Metrics framework.

        Show
        hcheng Cheng Hao added a comment - Hi, stack, the patch does improve the performance in my case, and for the AtomicLong stuff, maybe we could wait for the next generation of Metrics framework.
        Hide
        lhofhansl Lars Hofhansl added a comment - - edited

        I still find it strange that still using AtomicLongs gives an improvement (because all that's different then is an access into a concurrent map) and that your test in fact was CPU bound. 10% improvement seems almost unbelievable, it makes me think there is something else at play.
        There's probably no harm in committing it (it's only slightly more complicated).

        Show
        lhofhansl Lars Hofhansl added a comment - - edited I still find it strange that still using AtomicLongs gives an improvement (because all that's different then is an access into a concurrent map) and that your test in fact was CPU bound. 10% improvement seems almost unbelievable, it makes me think there is something else at play. There's probably no harm in committing it (it's only slightly more complicated).
        Hide
        stack stack added a comment -

        OK. Will leave it for now. Will commit it if Elliott doesn't subsume this w/ his cliffclick counter.

        Show
        stack stack added a comment - OK. Will leave it for now. Will commit it if Elliott doesn't subsume this w/ his cliffclick counter.
        Hide
        chenghao Cheng Hao added a comment -

        I tested the AtomicLong, Counter, and normal function call, and the result as:
        with my laptop (Windows 7, 64 bit jdk 1.7,Core i5-2540M CPU @ 2.60GHz):
        AtomicTest: 1429ms,100000000
        AtomicTest: 1433ms,100000000
        AtomicTest: 1445ms,100000000
        CounterTest: 6659ms,100000000
        CounterTest: 6609ms,100000000
        CounterTest: 6486ms,100000000
        NormalTest(Function): 238ms,100000000
        NormalTest(Function): 237ms,100000000
        NormalTest(Function): 230ms,100000000

        With my server (Linux, 64 bit jdk 1.7, Intel(R) Xeon(R) CPU L5640 @ 2.27GHz)
        AtomicTest: 1344ms,100000000
        AtomicTest: 1220ms,100000000
        AtomicTest: 1085ms,100000000
        CounterTest: 1518ms,100000000
        CounterTest: 1438ms,100000000
        CounterTest: 1815ms,100000000
        NormalTest(Function): 94ms,100000000
        NormalTest(Function): 89ms,100000000
        NormalTest(Function): 89ms,100000000

        In both env, the Counter seems slower than the AtomicLong.

        Show
        chenghao Cheng Hao added a comment - I tested the AtomicLong, Counter, and normal function call, and the result as: with my laptop (Windows 7, 64 bit jdk 1.7,Core i5-2540M CPU @ 2.60GHz): AtomicTest: 1429ms,100000000 AtomicTest: 1433ms,100000000 AtomicTest: 1445ms,100000000 CounterTest: 6659ms,100000000 CounterTest: 6609ms,100000000 CounterTest: 6486ms,100000000 NormalTest(Function): 238ms,100000000 NormalTest(Function): 237ms,100000000 NormalTest(Function): 230ms,100000000 With my server (Linux, 64 bit jdk 1.7, Intel(R) Xeon(R) CPU L5640 @ 2.27GHz) AtomicTest: 1344ms,100000000 AtomicTest: 1220ms,100000000 AtomicTest: 1085ms,100000000 CounterTest: 1518ms,100000000 CounterTest: 1438ms,100000000 CounterTest: 1815ms,100000000 NormalTest(Function): 94ms,100000000 NormalTest(Function): 89ms,100000000 NormalTest(Function): 89ms,100000000 In both env, the Counter seems slower than the AtomicLong.
        Hide
        hadoopqa Hadoop QA added a comment -

        -1 overall. Here are the results of testing the latest attachment
        http://issues.apache.org/jira/secure/attachment/12548145/AtomicTest.java
        against trunk revision .

        +1 @author. The patch does not contain any @author tags.

        -1 tests included. The patch doesn't appear to include any new or modified tests.
        Please justify why no new tests are needed for this patch.
        Also please list what manual steps were performed to verify this patch.

        -1 patch. The patch command could not apply the patch.

        Console output: https://builds.apache.org/job/PreCommit-HBASE-Build/3018//console

        This message is automatically generated.

        Show
        hadoopqa Hadoop QA added a comment - -1 overall . Here are the results of testing the latest attachment http://issues.apache.org/jira/secure/attachment/12548145/AtomicTest.java against trunk revision . +1 @author . The patch does not contain any @author tags. -1 tests included . The patch doesn't appear to include any new or modified tests. Please justify why no new tests are needed for this patch. Also please list what manual steps were performed to verify this patch. -1 patch . The patch command could not apply the patch. Console output: https://builds.apache.org/job/PreCommit-HBASE-Build/3018//console This message is automatically generated.
        Hide
        chenghao Cheng Hao added a comment -

        I re-ran the scanning tests, with or without the patch attached, still, the patched version got 10% shorter in entire running time.
        The oprofile result of the un-patched version as (top 4):
        samples % image name symbol name
        -------------------------------------------------------------------------------
        54182 14.6977 23960.jo void org.apache.hadoop.hbase.regionserver.metrics.SchemaMetrics.incrNumericMetric(org.apache.hadoop.hbase.io.hfile.BlockType$BlockCategory, boolean, org.a
        pache.hadoop.hbase.regionserver.metrics.SchemaMetrics$BlockMetricType)
        54182 100.000 23960.jo void org.apache.hadoop.hbase.regionserver.metrics.SchemaMetrics.incrNumericMetric(org.apache.hadoop.hbase.io.hfile.BlockType$BlockCategory, boolean, org
        .apache.hadoop.hbase.regionserver.metrics.SchemaMetrics$BlockMetricType) [self]
        -------------------------------------------------------------------------------
        43949 11.9219 23960.jo int org.apache.hadoop.hbase.KeyValue$KeyComparator.compare(byte[], int, int, byte[], int, int)
        43949 100.000 23960.jo int org.apache.hadoop.hbase.KeyValue$KeyComparator.compare(byte[], int, int, byte[], int, int) [self]
        -------------------------------------------------------------------------------
        20725 5.6220 23960.jo int org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$BlockIndexReader.binarySearchNonRootIndex(byte[], int, int, java.nio.ByteBuffer, org.apache.hadoop.io
        .RawComparator)
        20725 100.000 23960.jo int org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$BlockIndexReader.binarySearchNonRootIndex(byte[], int, int, java.nio.ByteBuffer, org.apache.hadoop.io.RawComparator) [self]
        -------------------------------------------------------------------------------
        17554 4.7618 23960.jo org.apache.hadoop.hbase.io.hfile.HFileBlock org.apache.hadoop.hbase.io.hfile.HFileReaderV2.readBlock(long, long, boolean, boolean, boolean, org.apache.hadoop.hbase.io.hfile.BlockType)
        17554 100.000 23960.jo org.apache.hadoop.hbase.io.hfile.HFileBlock org.apache.hadoop.hbase.io.hfile.HFileReaderV2.readBlock(long, long, boolean, boolean, boolean, org.apache.hadoop.hbase.io.hfile.BlockType) [self]

        And the oprofile result for patched version as (Top 4):
        samples % image name symbol name
        -------------------------------------------------------------------------------
        53716 11.9679 3683.jo int org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$BlockIndexReader.binarySearchNonRootIndex(byte[], int, int, java.nio.ByteBuffer, org.apache.hadoop.io.RawComparator)
        53716 100.000 3683.jo int org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$BlockIndexReader.binarySearchNonRootIndex(byte[], int, int, java.nio.ByteBuffer, org.apache.hadoop.io.RawComparator) [self]
        -------------------------------------------------------------------------------
        34921 7.7804 3683.jo int org.apache.hadoop.hbase.KeyValue$KeyComparator.compare(byte[], int, int, byte[], int, int)
        34921 100.000 3683.jo int org.apache.hadoop.hbase.KeyValue$KeyComparator.compare(byte[], int, int, byte[], int, int) [self]
        -------------------------------------------------------------------------------
        31446 7.0061 3683.jo org.apache.hadoop.hbase.io.hfile.HFileBlock org.apache.hadoop.hbase.io.hfile.HFileReaderV2.readBlock(long, long, boolean, boolean, boolean, org.apache.hadoop.hbase.io.hfile.BlockType)
        31446 100.000 3683.jo org.apache.hadoop.hbase.io.hfile.HFileBlock org.apache.hadoop.hbase.io.hfile.HFileReaderV2.readBlock(long, long, boolean, boolean, boolean, org.apache.hadoop.hbase.io.hfile.BlockType) [self]
        -------------------------------------------------------------------------------
        20126 4.4841 3683.jo org.apache.hadoop.hbase.regionserver.ScanQueryMatcher$MatchCode org.apache.hadoop.hbase.regionserver.ScanQueryMatcher.match(org.apache.hadoop.hbase.KeyValue)
        20126 100.000 3683.jo org.apache.hadoop.hbase.regionserver.ScanQueryMatcher$MatchCode org.apache.hadoop.hbase.regionserver.ScanQueryMatcher.match(org.apache.hadoop.hbase.KeyValue) [self]

        Perhaps, the function call itself may costs too much, like the stacks poping / pushing etc. and the patch just reduces the un-necessary function calls.

        Show
        chenghao Cheng Hao added a comment - I re-ran the scanning tests, with or without the patch attached, still, the patched version got 10% shorter in entire running time. The oprofile result of the un-patched version as (top 4): samples % image name symbol name ------------------------------------------------------------------------------- 54182 14.6977 23960.jo void org.apache.hadoop.hbase.regionserver.metrics.SchemaMetrics.incrNumericMetric(org.apache.hadoop.hbase.io.hfile.BlockType$BlockCategory, boolean, org.a pache.hadoop.hbase.regionserver.metrics.SchemaMetrics$BlockMetricType) 54182 100.000 23960.jo void org.apache.hadoop.hbase.regionserver.metrics.SchemaMetrics.incrNumericMetric(org.apache.hadoop.hbase.io.hfile.BlockType$BlockCategory, boolean, org .apache.hadoop.hbase.regionserver.metrics.SchemaMetrics$BlockMetricType) [self] ------------------------------------------------------------------------------- 43949 11.9219 23960.jo int org.apache.hadoop.hbase.KeyValue$KeyComparator.compare(byte[], int, int, byte[], int, int) 43949 100.000 23960.jo int org.apache.hadoop.hbase.KeyValue$KeyComparator.compare(byte[], int, int, byte[], int, int) [self] ------------------------------------------------------------------------------- 20725 5.6220 23960.jo int org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$BlockIndexReader.binarySearchNonRootIndex(byte[], int, int, java.nio.ByteBuffer, org.apache.hadoop.io .RawComparator) 20725 100.000 23960.jo int org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$BlockIndexReader.binarySearchNonRootIndex(byte[], int, int, java.nio.ByteBuffer, org.apache.hadoop.io.RawComparator) [self] ------------------------------------------------------------------------------- 17554 4.7618 23960.jo org.apache.hadoop.hbase.io.hfile.HFileBlock org.apache.hadoop.hbase.io.hfile.HFileReaderV2.readBlock(long, long, boolean, boolean, boolean, org.apache.hadoop.hbase.io.hfile.BlockType) 17554 100.000 23960.jo org.apache.hadoop.hbase.io.hfile.HFileBlock org.apache.hadoop.hbase.io.hfile.HFileReaderV2.readBlock(long, long, boolean, boolean, boolean, org.apache.hadoop.hbase.io.hfile.BlockType) [self] And the oprofile result for patched version as (Top 4): samples % image name symbol name ------------------------------------------------------------------------------- 53716 11.9679 3683.jo int org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$BlockIndexReader.binarySearchNonRootIndex(byte[], int, int, java.nio.ByteBuffer, org.apache.hadoop.io.RawComparator) 53716 100.000 3683.jo int org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$BlockIndexReader.binarySearchNonRootIndex(byte[], int, int, java.nio.ByteBuffer, org.apache.hadoop.io.RawComparator) [self] ------------------------------------------------------------------------------- 34921 7.7804 3683.jo int org.apache.hadoop.hbase.KeyValue$KeyComparator.compare(byte[], int, int, byte[], int, int) 34921 100.000 3683.jo int org.apache.hadoop.hbase.KeyValue$KeyComparator.compare(byte[], int, int, byte[], int, int) [self] ------------------------------------------------------------------------------- 31446 7.0061 3683.jo org.apache.hadoop.hbase.io.hfile.HFileBlock org.apache.hadoop.hbase.io.hfile.HFileReaderV2.readBlock(long, long, boolean, boolean, boolean, org.apache.hadoop.hbase.io.hfile.BlockType) 31446 100.000 3683.jo org.apache.hadoop.hbase.io.hfile.HFileBlock org.apache.hadoop.hbase.io.hfile.HFileReaderV2.readBlock(long, long, boolean, boolean, boolean, org.apache.hadoop.hbase.io.hfile.BlockType) [self] ------------------------------------------------------------------------------- 20126 4.4841 3683.jo org.apache.hadoop.hbase.regionserver.ScanQueryMatcher$MatchCode org.apache.hadoop.hbase.regionserver.ScanQueryMatcher.match(org.apache.hadoop.hbase.KeyValue) 20126 100.000 3683.jo org.apache.hadoop.hbase.regionserver.ScanQueryMatcher$MatchCode org.apache.hadoop.hbase.regionserver.ScanQueryMatcher.match(org.apache.hadoop.hbase.KeyValue) [self] Perhaps, the function call itself may costs too much, like the stacks poping / pushing etc. and the patch just reduces the un-necessary function calls.
        Hide
        chenghao Cheng Hao added a comment -

        Sorry, please check the AtomicTest.java attached, to compare the performance of AtomicLong / Counter / Normal function call.

        Show
        chenghao Cheng Hao added a comment - Sorry, please check the AtomicTest.java attached, to compare the performance of AtomicLong / Counter / Normal function call.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Thanks Cheng. That microbenchmark might not cover the actual cost of a memory barriers when many different threads are running on different cores.

        It looks like the patch will be an improvement.

        It would still be great to know why updateOnCacheHit causes such a performance hit. If it is the ConcurrentMap access we should fix it there (with the lock-free array theme I mentioned above - maybe with the padding as Todd suggests, if needed). That would be a more general fix.
        What do you think, Cheng?

        @Todd: Re: ThreadLocal. We had a bunch of incidents a few years back at Salesforce where it turned out that accessing threadlocals is not free.

        Show
        lhofhansl Lars Hofhansl added a comment - Thanks Cheng. That microbenchmark might not cover the actual cost of a memory barriers when many different threads are running on different cores. It looks like the patch will be an improvement. It would still be great to know why updateOnCacheHit causes such a performance hit. If it is the ConcurrentMap access we should fix it there (with the lock-free array theme I mentioned above - maybe with the padding as Todd suggests, if needed). That would be a more general fix. What do you think, Cheng? @Todd: Re: ThreadLocal. We had a bunch of incidents a few years back at Salesforce where it turned out that accessing threadlocals is not free.
        Hide
        tlipcon Todd Lipcon added a comment -

        @Todd: Re: ThreadLocal. We had a bunch of incidents a few years back at Salesforce where it turned out that accessing threadlocals is not free.

        Agreed, it involves a lookup in a hashmap. But we could do that lookup once, and pass it through the whole scanner stack, etc, in some kind of "ScanContext" parameter. That would be helpful for a bunch of places where we currently use threadlocals (metrics, rpc call "cancellation" checks, tracing, etc)

        Show
        tlipcon Todd Lipcon added a comment - @Todd: Re: ThreadLocal. We had a bunch of incidents a few years back at Salesforce where it turned out that accessing threadlocals is not free. Agreed, it involves a lookup in a hashmap. But we could do that lookup once, and pass it through the whole scanner stack, etc, in some kind of "ScanContext" parameter. That would be helpful for a bunch of places where we currently use threadlocals (metrics, rpc call "cancellation" checks, tracing, etc)
        Hide
        chenghao Cheng Hao added a comment -

        Sample callgraph via visualvm, seems the bottleneck was the SechemaMetrics.incrNumericMetric() itself; and the Map is does another hotspot; does recursive calls take that high overhead? Interesting.

        Show
        chenghao Cheng Hao added a comment - Sample callgraph via visualvm, seems the bottleneck was the SechemaMetrics.incrNumericMetric() itself; and the Map is does another hotspot; does recursive calls take that high overhead? Interesting.
        Hide
        hadoopqa Hadoop QA added a comment -

        -1 overall. Here are the results of testing the latest attachment
        http://issues.apache.org/jira/secure/attachment/12549247/metrics_hotspots.png
        against trunk revision .

        +1 @author. The patch does not contain any @author tags.

        -1 tests included. The patch doesn't appear to include any new or modified tests.
        Please justify why no new tests are needed for this patch.
        Also please list what manual steps were performed to verify this patch.

        -1 patch. The patch command could not apply the patch.

        Console output: https://builds.apache.org/job/PreCommit-HBASE-Build/3055//console

        This message is automatically generated.

        Show
        hadoopqa Hadoop QA added a comment - -1 overall . Here are the results of testing the latest attachment http://issues.apache.org/jira/secure/attachment/12549247/metrics_hotspots.png against trunk revision . +1 @author . The patch does not contain any @author tags. -1 tests included . The patch doesn't appear to include any new or modified tests. Please justify why no new tests are needed for this patch. Also please list what manual steps were performed to verify this patch. -1 patch . The patch command could not apply the patch. Console output: https://builds.apache.org/job/PreCommit-HBASE-Build/3055//console This message is automatically generated.
        Hide
        chenghao Cheng Hao added a comment -

        Sorry, just read an article, the self time may not accurate in sampling result, as the modern JVM will optimize the function call as inlined.

        But from the sampling call graph, it may tells the ConcurrentHashMap.get() is one of the hotspots, and that may also explains why the patch reduced the overhead.

        Show
        chenghao Cheng Hao added a comment - Sorry, just read an article, the self time may not accurate in sampling result, as the modern JVM will optimize the function call as inlined. But from the sampling call graph, it may tells the ConcurrentHashMap.get() is one of the hotspots, and that may also explains why the patch reduced the overhead.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Thanks for all your work here Cheng.

        Show
        lhofhansl Lars Hofhansl added a comment - Thanks for all your work here Cheng.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Did a microbenchmark too.
        ConcurrentHashMap.get/putIfAbsent plus updating an atomiclong takes about twice as long as just updating an atomiclong (testing with 1 thread and 100 threads on a dual core machine).

        Show
        lhofhansl Lars Hofhansl added a comment - Did a microbenchmark too. ConcurrentHashMap.get/putIfAbsent plus updating an atomiclong takes about twice as long as just updating an atomiclong (testing with 1 thread and 100 threads on a dual core machine).
        Hide
        eclark Elliott Clark added a comment -

        HBASE-6410 removes most of the calls to concurrent hash maps. And it starts using the high scalability counter class.

        Show
        eclark Elliott Clark added a comment - HBASE-6410 removes most of the calls to concurrent hash maps. And it starts using the high scalability counter class.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        So we should probably not consider this for 0.94 then. And for 0.96 this is a non-issue, right?

        Show
        lhofhansl Lars Hofhansl added a comment - So we should probably not consider this for 0.94 then. And for 0.96 this is a non-issue, right?
        Hide
        eclark Elliott Clark added a comment -

        For 0.96 it's (hopefully) a non-issue.
        For 0.94 I think the perf gain might be worth applying this patch.

        Show
        eclark Elliott Clark added a comment - For 0.96 it's (hopefully) a non-issue. For 0.94 I think the perf gain might be worth applying this patch.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        0.94 patch. Also uses AtomicLongArray instead of AtomicLong[].

        Show
        lhofhansl Lars Hofhansl added a comment - 0.94 patch. Also uses AtomicLongArray instead of AtomicLong[].
        Hide
        stack stack added a comment -

        Patch looks good to me for 0.94

        Show
        stack stack added a comment - Patch looks good to me for 0.94
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Added you as a contributor, Cheng, and assigned to you.
        Going to commit this.

        Thanks for your perseverance Cheng

        Show
        lhofhansl Lars Hofhansl added a comment - Added you as a contributor, Cheng, and assigned to you. Going to commit this. Thanks for your perseverance Cheng
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Committed to 0.94. Thanks for the profiling work and the patch, Cheng!

        Show
        lhofhansl Lars Hofhansl added a comment - Committed to 0.94. Thanks for the profiling work and the patch, Cheng!
        Hide
        hudson Hudson added a comment -

        Integrated in HBase-0.94 #556 (See https://builds.apache.org/job/HBase-0.94/556/)
        HBASE-6852 SchemaMetrics.updateOnCacheHit costs too much while full scanning a table with all of its fields (Cheng Hao and LarsH) (Revision 1402392)

        Result = FAILURE
        larsh :
        Files :

        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java
        • /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/metrics/TestSchemaMetrics.java
        Show
        hudson Hudson added a comment - Integrated in HBase-0.94 #556 (See https://builds.apache.org/job/HBase-0.94/556/ ) HBASE-6852 SchemaMetrics.updateOnCacheHit costs too much while full scanning a table with all of its fields (Cheng Hao and LarsH) (Revision 1402392) Result = FAILURE larsh : Files : /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/metrics/TestSchemaMetrics.java
        Hide
        yuzhihong@gmail.com Ted Yu added a comment -

        There were 10 test failures in build 556 which might be related to this JIRA.

        Show
        yuzhihong@gmail.com Ted Yu added a comment - There were 10 test failures in build 556 which might be related to this JIRA.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        will check it out

        Show
        lhofhansl Lars Hofhansl added a comment - will check it out
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Yes, these test failures are definitely related. I am going to revert the patch, until we can fix all the tests.

        Show
        lhofhansl Lars Hofhansl added a comment - Yes, these test failures are definitely related. I am going to revert the patch, until we can fix all the tests.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        These are the failing tests (in case we do not get to this before jenkins removes the old run):
        org.apache.hadoop.hbase.io.hfile.TestScannerSelectionUsingTTL.testScannerSelection[2]
        org.apache.hadoop.hbase.io.hfile.TestScannerSelectionUsingTTL.testScannerSelection[3]
        org.apache.hadoop.hbase.io.hfile.TestScannerSelectionUsingTTL.testScannerSelection[4]
        org.apache.hadoop.hbase.io.hfile.TestScannerSelectionUsingTTL.testScannerSelection[5]
        org.apache.hadoop.hbase.regionserver.TestBlocksScanned.testBlocksScanned
        org.apache.hadoop.hbase.regionserver.TestStoreFile.testCacheOnWriteEvictOnClose
        org.apache.hadoop.hbase.regionserver.TestStoreFile.testBloomFilter
        org.apache.hadoop.hbase.regionserver.TestStoreFile.testDeleteFamilyBloomFilter
        org.apache.hadoop.hbase.regionserver.TestStoreFile.testBloomTypes
        org.apache.hadoop.hbase.regionserver.TestStoreFile.testBloomEdgeCases

        Show
        lhofhansl Lars Hofhansl added a comment - These are the failing tests (in case we do not get to this before jenkins removes the old run): org.apache.hadoop.hbase.io.hfile.TestScannerSelectionUsingTTL.testScannerSelection [2] org.apache.hadoop.hbase.io.hfile.TestScannerSelectionUsingTTL.testScannerSelection [3] org.apache.hadoop.hbase.io.hfile.TestScannerSelectionUsingTTL.testScannerSelection [4] org.apache.hadoop.hbase.io.hfile.TestScannerSelectionUsingTTL.testScannerSelection [5] org.apache.hadoop.hbase.regionserver.TestBlocksScanned.testBlocksScanned org.apache.hadoop.hbase.regionserver.TestStoreFile.testCacheOnWriteEvictOnClose org.apache.hadoop.hbase.regionserver.TestStoreFile.testBloomFilter org.apache.hadoop.hbase.regionserver.TestStoreFile.testDeleteFamilyBloomFilter org.apache.hadoop.hbase.regionserver.TestStoreFile.testBloomTypes org.apache.hadoop.hbase.regionserver.TestStoreFile.testBloomEdgeCases
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Reverted for now. I think I know what is happening (the metrics are just not flushed right away), but I have no time to look into this.

        Show
        lhofhansl Lars Hofhansl added a comment - Reverted for now. I think I know what is happening (the metrics are just not flushed right away), but I have no time to look into this.
        Hide
        hudson Hudson added a comment -

        Integrated in HBase-0.94 #557 (See https://builds.apache.org/job/HBase-0.94/557/)
        HBASE-6852 REVERT due to test failures. (Revision 1402588)

        Result = FAILURE
        larsh :
        Files :

        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java
        • /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/metrics/TestSchemaMetrics.java
        Show
        hudson Hudson added a comment - Integrated in HBase-0.94 #557 (See https://builds.apache.org/job/HBase-0.94/557/ ) HBASE-6852 REVERT due to test failures. (Revision 1402588) Result = FAILURE larsh : Files : /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/metrics/TestSchemaMetrics.java
        Hide
        lhofhansl Lars Hofhansl added a comment -

        There's a bug about the ALL_SCHEMA_METRIC is updated/flushed, which causes this.
        Cheng Hao If you could have a look that'd be cool

        Show
        lhofhansl Lars Hofhansl added a comment - There's a bug about the ALL_SCHEMA_METRIC is updated/flushed, which causes this. Cheng Hao If you could have a look that'd be cool
        Hide
        chenghao Cheng Hao added a comment -

        oh, sorry for that, I will resolve it asap.

        Show
        chenghao Cheng Hao added a comment - oh, sorry for that, I will resolve it asap.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        No problem. Thanks for providing a patch.

        The problem seems to be the ALL_SCHEMA_METRIC not always updated.
        (The flushing is definitely not correct... A call to flush won't flush the ALL_SCHEMA_METRIC, but even when I fixed that, the tests still failed).

        Show
        lhofhansl Lars Hofhansl added a comment - No problem. Thanks for providing a patch. The problem seems to be the ALL_SCHEMA_METRIC not always updated. (The flushing is definitely not correct... A call to flush won't flush the ALL_SCHEMA_METRIC, but even when I fixed that, the tests still failed).
        Hide
        chenghao Cheng Hao added a comment -

        Please take the 6852-0.94_2.patch

        Found a small bug while updating the "ALL_CATEGORY metrics" in the function
        "SchemaMetrics.incrNumericMetric(BlockCategory blockCategory,
        boolean isCompaction, BlockMetricType metricType, long amount)"

        And I also add the "flushMetrics()" in the function "SchemaMetrics.getMetricsSnapshot()"

        Now it passed the unit test in my local.

        Thank you.

        Show
        chenghao Cheng Hao added a comment - Please take the 6852-0.94_2.patch Found a small bug while updating the "ALL_CATEGORY metrics" in the function "SchemaMetrics.incrNumericMetric(BlockCategory blockCategory, boolean isCompaction, BlockMetricType metricType, long amount)" And I also add the "flushMetrics()" in the function "SchemaMetrics.getMetricsSnapshot()" Now it passed the unit test in my local. Thank you.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        I ran all the tests locally as well. All pass now. Committed to 0.94.
        Thanks for the patch and the fix Cheng!

        Show
        lhofhansl Lars Hofhansl added a comment - I ran all the tests locally as well. All pass now. Committed to 0.94. Thanks for the patch and the fix Cheng!
        Hide
        hudson Hudson added a comment -

        Integrated in HBase-0.94 #562 (See https://builds.apache.org/job/HBase-0.94/562/)
        HBASE-6852 SchemaMetrics.updateOnCacheHit costs too much while full scanning a table with all of its fields (Cheng Hao and LarsH) - REAPPLY (Revision 1404464)

        Result = FAILURE
        larsh :
        Files :

        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java
        • /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/metrics/TestSchemaMetrics.java
        Show
        hudson Hudson added a comment - Integrated in HBase-0.94 #562 (See https://builds.apache.org/job/HBase-0.94/562/ ) HBASE-6852 SchemaMetrics.updateOnCacheHit costs too much while full scanning a table with all of its fields (Cheng Hao and LarsH) - REAPPLY (Revision 1404464) Result = FAILURE larsh : Files : /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/metrics/TestSchemaMetrics.java
        Hide
        chenghao Cheng Hao added a comment -

        Still failed,

        And I can not open the URL "https://builds.apache.org/job/HBase-0.94/562/", not sure if there any problem for the build server.

        Show
        chenghao Cheng Hao added a comment - Still failed, And I can not open the URL "https://builds.apache.org/job/HBase-0.94/562/", not sure if there any problem for the build server.
        Hide
        yuzhihong@gmail.com Ted Yu added a comment -

        Test failure in hadoop.hbase.io.hfile.TestScannerSelectionUsingTTL is reproducible.

        Show
        yuzhihong@gmail.com Ted Yu added a comment - Test failure in hadoop.hbase.io.hfile.TestScannerSelectionUsingTTL is reproducible.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Not on my machine... Weird.

        Show
        lhofhansl Lars Hofhansl added a comment - Not on my machine... Weird.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        -------------------------------------------------------
        T E S T S
        -------------------------------------------------------
        Running org.apache.hadoop.hbase.io.hfile.TestScannerSelectionUsingTTL
        Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 14.642 sec

        Results :

        Tests run: 6, Failures: 0, Errors: 0, Skipped: 0

        Show
        lhofhansl Lars Hofhansl added a comment - ------------------------------------------------------- T E S T S ------------------------------------------------------- Running org.apache.hadoop.hbase.io.hfile.TestScannerSelectionUsingTTL Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 14.642 sec Results : Tests run: 6, Failures: 0, Errors: 0, Skipped: 0
        Hide
        zhihyu@ebaysf.com Ted Yu added a comment -

        Here is the environment where the test failed:

        $ uname -a
        Linux s0 2.6.38-11-generic #48-Ubuntu SMP Fri Jul 29 19:02:55 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux
        
        $ java -version
        java version "1.6.0_26"
        Java(TM) SE Runtime Environment (build 1.6.0_26-b03)
        Java HotSpot(TM) 64-Bit Server VM (build 20.1-b02, mixed mode)
        
        Show
        zhihyu@ebaysf.com Ted Yu added a comment - Here is the environment where the test failed: $ uname -a Linux s0 2.6.38-11- generic #48-Ubuntu SMP Fri Jul 29 19:02:55 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux $ java -version java version "1.6.0_26" Java(TM) SE Runtime Environment (build 1.6.0_26-b03) Java HotSpot(TM) 64-Bit Server VM (build 20.1-b02, mixed mode)
        Hide
        lhofhansl Lars Hofhansl added a comment -

        I triggered a new build. If that fails again, I am not sure what to do.
        I ran the test a lot of times locally and it always passes.

        Show
        lhofhansl Lars Hofhansl added a comment - I triggered a new build. If that fails again, I am not sure what to do. I ran the test a lot of times locally and it always passes.
        Hide
        zhihyu@ebaysf.com Ted Yu added a comment -

        The new build failed again.
        After reverting patch v2, TestScannerSelectionUsingTTL passed on the above mentioned platform.

        Show
        zhihyu@ebaysf.com Ted Yu added a comment - The new build failed again. After reverting patch v2, TestScannerSelectionUsingTTL passed on the above mentioned platform.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Does it fail locally on your machine Ted?
        I'm going to run the test on a different machine so that I can debug.
        If that is not fruitful, I'll revert the change again... Sigh

        Show
        lhofhansl Lars Hofhansl added a comment - Does it fail locally on your machine Ted? I'm going to run the test on a different machine so that I can debug. If that is not fruitful, I'll revert the change again... Sigh
        Hide
        zhihyu@ebaysf.com Ted Yu added a comment -

        I wasn't able to produce the test failure on MacBook.

        Show
        zhihyu@ebaysf.com Ted Yu added a comment - I wasn't able to produce the test failure on MacBook.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Also tried on some other machines (JDK7 and JDK6) it passes all the time.
        This is extremely disconcerting.

        Show
        lhofhansl Lars Hofhansl added a comment - Also tried on some other machines (JDK7 and JDK6) it passes all the time. This is extremely disconcerting.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Sorry, Cheng, I am probably going to have to roll this back again.

        Show
        lhofhansl Lars Hofhansl added a comment - Sorry, Cheng, I am probably going to have to roll this back again.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Reverted a 2nd time.

        Show
        lhofhansl Lars Hofhansl added a comment - Reverted a 2nd time.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Moving to 0.94.4.

        Cheng, looking at the patch, do you think it's possible due to the way we flush the metrics for the all schema metrics?

        Show
        lhofhansl Lars Hofhansl added a comment - Moving to 0.94.4. Cheng, looking at the patch, do you think it's possible due to the way we flush the metrics for the all schema metrics?
        Hide
        hudson Hudson added a comment -

        Integrated in HBase-0.94 #564 (See https://builds.apache.org/job/HBase-0.94/564/)
        HBASE-6852, REVERT again, due to unexplained test failures that only occur on the jenkins machines (Revision 1404691)

        Result = FAILURE
        larsh :
        Files :

        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java
        • /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/metrics/TestSchemaMetrics.java
        Show
        hudson Hudson added a comment - Integrated in HBase-0.94 #564 (See https://builds.apache.org/job/HBase-0.94/564/ ) HBASE-6852 , REVERT again, due to unexplained test failures that only occur on the jenkins machines (Revision 1404691) Result = FAILURE larsh : Files : /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/metrics/TestSchemaMetrics.java
        Hide
        chenghao Cheng Hao added a comment -

        Thanks Lars and Ted, I will try to reproduce the failure locally first, and then to see if any logical bug of the schema metrics flushing.

        Show
        chenghao Cheng Hao added a comment - Thanks Lars and Ted, I will try to reproduce the failure locally first, and then to see if any logical bug of the schema metrics flushing.
        Hide
        chenghao Cheng Hao added a comment -

        Lars, Ted,

        It did have a bug in the v2 patch, please take the 6852-0.94_3.patch; and it passed all of the metrics unit tests locally. Hopefully the weird failure won't happen again.

        Thanks

        Show
        chenghao Cheng Hao added a comment - Lars, Ted, It did have a bug in the v2 patch, please take the 6852-0.94_3.patch; and it passed all of the metrics unit tests locally. Hopefully the weird failure won't happen again. Thanks
        Hide
        yuzhihong@gmail.com Ted Yu added a comment -

        @Cheng:
        Thanks for your persistence.
        I will run patch v3 on Linux.

        Can you tell us more about the bug you found ?

        Show
        yuzhihong@gmail.com Ted Yu added a comment - @Cheng: Thanks for your persistence. I will run patch v3 on Linux. Can you tell us more about the bug you found ?
        Hide
        yuzhihong@gmail.com Ted Yu added a comment -

        I looped TestScannerSelectionUsingTTL 14 times on Linux and they passed.

        Looking at patch v3, updateOnCacheHit() and flushOnCacheHitMetrics() are checking this SchemaMetrics against ALL_SCHEMA_METRICS.
        I think patch v3 should be good to go.

        I am running patch v3 through test suite. Will report back if I see anomaly.

        Show
        yuzhihong@gmail.com Ted Yu added a comment - I looped TestScannerSelectionUsingTTL 14 times on Linux and they passed. Looking at patch v3, updateOnCacheHit() and flushOnCacheHitMetrics() are checking this SchemaMetrics against ALL_SCHEMA_METRICS. I think patch v3 should be good to go. I am running patch v3 through test suite. Will report back if I see anomaly.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Thanks Cheng and thanks Ted!

        Show
        lhofhansl Lars Hofhansl added a comment - Thanks Cheng and thanks Ted!
        Hide
        zhihyu@ebaysf.com Ted Yu added a comment -

        0.94 test suite passed with patch v3:

        Tests run: 1071, Failures: 0, Errors: 0, Skipped: 12
        
        [INFO] ------------------------------------------------------------------------
        [INFO] BUILD SUCCESS
        [INFO] ------------------------------------------------------------------------
        [INFO] Total time: 45:45.503s
        [INFO] Finished at: Fri Nov 02 10:30:09 PDT 2012
        

        @Lars:
        Are you going to commit ?

        Show
        zhihyu@ebaysf.com Ted Yu added a comment - 0.94 test suite passed with patch v3: Tests run: 1071, Failures: 0, Errors: 0, Skipped: 12 [INFO] ------------------------------------------------------------------------ [INFO] BUILD SUCCESS [INFO] ------------------------------------------------------------------------ [INFO] Total time: 45:45.503s [INFO] Finished at: Fri Nov 02 10:30:09 PDT 2012 @Lars: Are you going to commit ?
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Awesome... 3rd time's a charm

        Show
        lhofhansl Lars Hofhansl added a comment - Awesome... 3rd time's a charm
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Re-committed.
        Thanks again Cheng and Ted.

        Show
        lhofhansl Lars Hofhansl added a comment - Re-committed. Thanks again Cheng and Ted.
        Hide
        hudson Hudson added a comment -

        Integrated in HBase-0.94 #567 (See https://builds.apache.org/job/HBase-0.94/567/)
        HBASE-6852 RE-REAPPLY, Cheng worked tirelessly to fix the issues. (Revision 1405083)

        Result = FAILURE
        larsh :
        Files :

        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java
        Show
        hudson Hudson added a comment - Integrated in HBase-0.94 #567 (See https://builds.apache.org/job/HBase-0.94/567/ ) HBASE-6852 RE-REAPPLY, Cheng worked tirelessly to fix the issues. (Revision 1405083) Result = FAILURE larsh : Files : /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java
        Hide
        chenghao Cheng Hao added a comment -

        Ouch!Still failed,and I still couldn't access the build server.
        Any problem of the build server?

        Show
        chenghao Cheng Hao added a comment - Ouch!Still failed,and I still couldn't access the build server. Any problem of the build server?
        Hide
        zhihyu@ebaysf.com Ted Yu added a comment -

        @Cheng:
        The build failure might be due to other reasons.
        Check back in a day or two.

        Show
        zhihyu@ebaysf.com Ted Yu added a comment - @Cheng: The build failure might be due to other reasons. Check back in a day or two.
        Hide
        zhihyu@ebaysf.com Ted Yu added a comment -

        There was no related test failure in https://builds.apache.org/view/G-L/view/HBase/job/HBase-0.94/567/ where patch v3 went in.

        Show
        zhihyu@ebaysf.com Ted Yu added a comment - There was no related test failure in https://builds.apache.org/view/G-L/view/HBase/job/HBase-0.94/567/ where patch v3 went in.
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Yeah... Looks good! Thanks again Cheng.

        Hey, I was also wondering whether there a chance to do your profiling one more time with HBASE-6032 applied. In your last profiling run here (Oct 7th) HFileBlockIndex$BlockIndexReader.binarySearchNonRootIndex takes the top spot (after this patch). HBASE-6032 was applied on Oct 17th, I'm wondering whether that helped.

        If you're busy, that's fine too... You already spent a lot of time on this issue.

        Show
        lhofhansl Lars Hofhansl added a comment - Yeah... Looks good! Thanks again Cheng. Hey, I was also wondering whether there a chance to do your profiling one more time with HBASE-6032 applied. In your last profiling run here (Oct 7th) HFileBlockIndex$BlockIndexReader.binarySearchNonRootIndex takes the top spot (after this patch). HBASE-6032 was applied on Oct 17th, I'm wondering whether that helped. If you're busy, that's fine too... You already spent a lot of time on this issue.
        Hide
        hudson Hudson added a comment -

        Integrated in HBase-0.94-security-on-Hadoop-23 #9 (See https://builds.apache.org/job/HBase-0.94-security-on-Hadoop-23/9/)
        HBASE-6852 RE-REAPPLY, Cheng worked tirelessly to fix the issues. (Revision 1405083)
        HBASE-6852, REVERT again, due to unexplained test failures that only occur on the jenkins machines (Revision 1404691)
        HBASE-6852 SchemaMetrics.updateOnCacheHit costs too much while full scanning a table with all of its fields (Cheng Hao and LarsH) - REAPPLY (Revision 1404464)
        HBASE-6852 REVERT due to test failures. (Revision 1402588)
        HBASE-6852 SchemaMetrics.updateOnCacheHit costs too much while full scanning a table with all of its fields (Cheng Hao and LarsH) (Revision 1402392)

        Result = FAILURE
        larsh :
        Files :

        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java

        larsh :
        Files :

        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java
        • /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/metrics/TestSchemaMetrics.java

        larsh :
        Files :

        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java
        • /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/metrics/TestSchemaMetrics.java

        larsh :
        Files :

        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java
        • /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/metrics/TestSchemaMetrics.java

        larsh :
        Files :

        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java
        • /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java
        • /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/metrics/TestSchemaMetrics.java
        Show
        hudson Hudson added a comment - Integrated in HBase-0.94-security-on-Hadoop-23 #9 (See https://builds.apache.org/job/HBase-0.94-security-on-Hadoop-23/9/ ) HBASE-6852 RE-REAPPLY, Cheng worked tirelessly to fix the issues. (Revision 1405083) HBASE-6852 , REVERT again, due to unexplained test failures that only occur on the jenkins machines (Revision 1404691) HBASE-6852 SchemaMetrics.updateOnCacheHit costs too much while full scanning a table with all of its fields (Cheng Hao and LarsH) - REAPPLY (Revision 1404464) HBASE-6852 REVERT due to test failures. (Revision 1402588) HBASE-6852 SchemaMetrics.updateOnCacheHit costs too much while full scanning a table with all of its fields (Cheng Hao and LarsH) (Revision 1402392) Result = FAILURE larsh : Files : /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java larsh : Files : /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/metrics/TestSchemaMetrics.java larsh : Files : /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/metrics/TestSchemaMetrics.java larsh : Files : /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/metrics/TestSchemaMetrics.java larsh : Files : /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV1.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java /hbase/branches/0.94/src/main/java/org/apache/hadoop/hbase/regionserver/metrics/SchemaMetrics.java /hbase/branches/0.94/src/test/java/org/apache/hadoop/hbase/regionserver/metrics/TestSchemaMetrics.java
        Hide
        chenghao Cheng Hao added a comment -

        @Lars, thank you for the committing;
        The snapshot of 0.94 branch code improves about 17.7% for scanning in my case, and it's sure the HBASE-6032 helps a lot;
        Here is the new hotspots for RegionServer via OProfile:

        Hotspots
        CPU: Intel Westmere microarchitecture, speed 2.262e+06 MHz (estimated)
        Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 5000000
        samples  %        image name               symbol name
        183371   17.1144  4465.jo                  int org.apache.hadoop.hbase.KeyValue$KeyComparator.compare(byte[], int, int, byte[], int, int)
        63267     5.9049  4465.jo                  org.apache.hadoop.hbase.regionserver.ScanQueryMatcher$MatchCode org.apache.hadoop.hbase.regionserver.ScanQueryMatcher.match(org.apache.hadoop.hbase.KeyValue)
        59762     5.5777  4465.jo                  byte[] org.apache.hadoop.hbase.KeyValue.createByteArray(byte[], int, int, byte[], int, int, byte[], int, int, long, org.apache.hadoop.hbase.KeyValue$Type, byte[], int, int)
        50975     4.7576  4465.jo                  int org.apache.hadoop.hbase.io.hfile.HFileReaderV2$ScannerV2.blockSeek(byte[], int, int, boolean)
        50891     4.7498  4465.jo                  void org.apache.hadoop.hbase.regionserver.StoreFileScanner.enforceSeek()
        38257     3.5706  4465.jo                  jbyte_disjoint_arraycopy
        37973     3.5441  4465.jo                  boolean org.apache.hadoop.hbase.regionserver.KeyValueHeap.generalizedSeek(boolean, org.apache.hadoop.hbase.KeyValue, boolean, boolean)~1
        33978     3.1712  4465.jo                  void org.apache.hadoop.util.PureJavaCrc32C.update(byte[], int, int)
        
        Show
        chenghao Cheng Hao added a comment - @Lars, thank you for the committing; The snapshot of 0.94 branch code improves about 17.7% for scanning in my case, and it's sure the HBASE-6032 helps a lot; Here is the new hotspots for RegionServer via OProfile: Hotspots CPU: Intel Westmere microarchitecture, speed 2.262e+06 MHz (estimated) Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 5000000 samples % image name symbol name 183371 17.1144 4465.jo int org.apache.hadoop.hbase.KeyValue$KeyComparator.compare( byte [], int , int , byte [], int , int ) 63267 5.9049 4465.jo org.apache.hadoop.hbase.regionserver.ScanQueryMatcher$MatchCode org.apache.hadoop.hbase.regionserver.ScanQueryMatcher.match(org.apache.hadoop.hbase.KeyValue) 59762 5.5777 4465.jo byte [] org.apache.hadoop.hbase.KeyValue.createByteArray( byte [], int , int , byte [], int , int , byte [], int , int , long , org.apache.hadoop.hbase.KeyValue$Type, byte [], int , int ) 50975 4.7576 4465.jo int org.apache.hadoop.hbase.io.hfile.HFileReaderV2$ScannerV2.blockSeek( byte [], int , int , boolean ) 50891 4.7498 4465.jo void org.apache.hadoop.hbase.regionserver.StoreFileScanner.enforceSeek() 38257 3.5706 4465.jo jbyte_disjoint_arraycopy 37973 3.5441 4465.jo boolean org.apache.hadoop.hbase.regionserver.KeyValueHeap.generalizedSeek( boolean , org.apache.hadoop.hbase.KeyValue, boolean , boolean )~1 33978 3.1712 4465.jo void org.apache.hadoop.util.PureJavaCrc32C.update( byte [], int , int )
        Hide
        lhofhansl Lars Hofhansl added a comment -

        Thanks Cheng, this is very helpful!

        Show
        lhofhansl Lars Hofhansl added a comment - Thanks Cheng, this is very helpful!

          People

          • Assignee:
            hcheng Cheng Hao
            Reporter:
            hcheng Cheng Hao
          • Votes:
            0 Vote for this issue
            Watchers:
            15 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development