You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@hbase.apache.org by Josh Elser <el...@apache.org> on 2020/07/14 18:38:18 UTC
Re: HBase 2 slower than HBase 1?
Wow. Great stuff, Andrew!
Thank you for compiling and posting it all here. I can only imagine how
time-consuming this was.
On 6/26/20 1:57 PM, Andrew Purtell wrote:
> Hey Anoop, I opened https://issues.apache.org/jira/browse/HBASE-24637 and
> attached the patches and script used to make the comparison.
>
> On Fri, Jun 26, 2020 at 2:33 AM Anoop John <an...@gmail.com> wrote:
>
>> Great investigation Andy. Do you know any Jiras which made changes in SQM?
>> Would be great if you can attach your patch which tracks the scan flow. If
>> we have a Jira for this issue, can you pls attach?
>>
>> Anoop
>>
>> On Fri, Jun 26, 2020 at 1:56 AM Andrew Purtell <an...@gmail.com>
>> wrote:
>>
>>> Related, I think I found a bug in branch-1 where we don’t heartbeat in
>> the
>>> filter all case until we switch store files, so scanning a very large
>> store
>>> file might time out with client defaults. Remarking on this here so I
>> don’t
>>> forget to follow up.
>>>
>>>> On Jun 25, 2020, at 12:27 PM, Andrew Purtell <ap...@apache.org>
>>> wrote:
>>>>
>>>>
>>>> I repeated this test with pe --filterAll and the results were
>> revealing,
>>> at least for this case. I also patched in thread local hash map for
>> atomic
>>> counters that I could update from code paths in SQM, StoreScanner,
>>> HFileReader*, and HFileBlock. Because a RPC is processed by a single
>>> handler thread I could update counters and accumulate micro-timings via
>>> System#nanoTime() per RPC and dump them out of CallRunner in some new
>> trace
>>> logging. I spent a couple of days making sure the instrumentation was
>>> placed equivalently in both 1.6 and 2.2 code bases and was producing
>>> consistent results. I can provide these patches upon request.
>>>>
>>>> Again, test tables with one family and 1, 5, 10, 20, 50, and 100
>>> distinct column-qualifiers per row. After loading the table I made a
>>> snapshot and cloned the snapshot for testing, for both 1.6 and 2.2, so
>> both
>>> versions were tested using the exact same data files on HDFS. I also used
>>> the 1.6 version of PE for both, so the only change is on the server (1.6
>> vs
>>> 2.2 masters and regionservers).
>>>>
>>>> It appears a refactor to ScanQueryMatcher and friends has disabled the
>>> ability of filters to provide SKIP hints, which prevents us from
>> bypassing
>>> version checking (so some extra cost in SQM), and appears to disable an
>>> optimization that avoids reseeking, leading to a serious and proportional
>>> regression in reseek activity and time spent in that code path. So for
>>> queries that use filters, there can be a substantial regression.
>>>>
>>>> Other test cases that did not use filters did not show a regression.
>>>>
>>>> A test case where I used ROW_INDEX_V1 encoding showed an expected
>> modest
>>> proportional regression in seeking time, due to the fact it is optimized
>>> for point queries and not optimized for the full table scan case.
>>>>
>>>> I will come back here when I understand this better.
>>>>
>>>> Here are the results for the pe --filterAll case:
>>>>
>>>>
>>>> 1.6.0 c1 2.2.5 c1
>>>> 1.6.0 c5 2.2.5 c5
>>>> 1.6.0 c10 2.2.5 c10
>>>> 1.6.0 c20 2.2.5 c20
>>>> 1.6.0 c50 2.2.5 c50
>>>> 1.6.0 c100 2.2.5 c100
>>>> Counts
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> (better heartbeating)
>>>> (better heartbeating)
>>>> (better heartbeating)
>>>> (better heartbeating)
>>>> (better heartbeating)
>>>> rpcs 1 2 200% 2 6 300% 2 10
>>> 500% 3 17 567% 4 37 925% 8 72
>> 900%
>>>> block_reads 11507 11508 100% 57255 57257 100% 114471
>>> 114474 100% 230372 230377 100% 578292 578298 100% 1157955
>>> 1157963 100%
>>>> block_unpacks 11507 11508 100% 57255 57257 100% 114471
>>> 114474 100% 230372 230377 100% 578292 578298 100% 1157955
>>> 1157963 100%
>>>> seeker_next 10000000 10000000 100% 50000000
>>> 50000000 100% 100000000 100000000 100% 200000000
>>> 200000000 100% 500000000 500000000 100%
>>> 1000000000 1000000000 100%
>>>> store_next 10000000 9988268 100% 50000000 49940082
>>> 100% 100000000 99879401 100% 200000000
>>> 199766539 100% 500000000 499414653 100%
>>> 1000000000 998836518 100%
>>>> store_reseek 1 11733 > ! 2 59924 > ! 8
>>> 120607 > ! 6 233467 > ! 10 585357 > ! 8
>>> 1163490 > !
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> cells_matched 20000000 20000000 100% 60000000
>>> 60000000 100% 110000000 110000000 100% 210000000
>>> 210000000 100% 510000000 510000000 100%
>>> 1010000000 1010000000 100%
>>>> column_hint_include 10000000 10000000 100% 50000000
>>> 50000000 100% 100000000 100000000 100%
>>> 200000000 200000000 100% 500000000 500000000
>>> 100% 1000000000 1000000000 100%
>>>> filter_hint_skip 10000000 10000000 100% 50000000
>>> 50000000 100% 100000000 100000000 100%
>>> 200000000 200000000 100% 500000000 500000000
>>> 100% 1000000000 1000000000 100%
>>>> sqm_hint_done 9999999 9999999 100% 9999998 9999998 100% 9999998
>>> 9999998 100% 9999997 9999997 100% 9999996 9999996 100% 9999992
>>> 9999992 100%
>>>> sqm_hint_seek_next_col 1 0 0% 2 40000002
>>> > ! 2 90000002 > ! 3 190000003 > !
>>> 4 490000004 > ! 8 990000008 > !
>>>> sqm_hint_seek_next_row 0 10000000 > ! 2
>>> 10000000 > ! 0 10000000 > ! 0 10000000
>>> > ! 0 10000000 > ! 0 10000000 > !
>>>> sqm_hint_skip 10000000 0 0% 50000000 0
>>> 0% 100000000 0 0% 200000000 0 0%
>>> 500000000 0 0% 1000000000 0 0%
>>>> versions_hint_include_and_seek_next_col 0 0 0% 0
>>> 40000000 > ! 0 90000000 > ! 0
>>> 190000000 > ! 0 490000000 > ! 0
>> 990000000
>>> > !
>>>> versions_hint_include_and_seek_next_row 0 0 0% 0
>>> 10000000 > ! 0 10000000 > ! 0
>>> 10000000 > ! 0 10000000 > ! 0 10000000
>>> > !
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> Times
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> block_read_ms 174.12 215.96 124% 683.78 883.02 129% 1724.66
>>> 1937.87 112% 3199.93 3470.92 108% 7582.96 7941.45 105% 14701.52
>>> 16022.57 109%
>>>> block_unpack_ms 0.63 0.62 99% 2.35 2.35 100%
>>> 4.36 4.56 105% 9.10 8.30 91% 21.59 22.01 102%
>>> 40.97 40.93 100%
>>>> seeker_next_ms 1073.45 1053.51 98% 4452.52 4728.96 106%
>>> 9359.61 9706.06 104% 18879.28 18330.93 97% 47664.95
>>> 46404.26 97% 96511.83 92121.30 95%
>>>> store_next_ms 2651.11 2423.27 91% 12048.64 11398.63
>>> 95% 24833.68 23586.20 95% 48493.26 46574.38
>>> 96% 120786.00 115603.00 96% 240627.00
>>> 227945.00 95%
>>>> store_reseek_ms 2.71 62.17 2297% 10.93 233.67 2139%
>>> 10.88 401.88 3693% 13.98 783.18 5601% 22.26 1939.28 8714%
>>> 24.32 4065.25 16714%
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> Rows=10000000
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> ValueSize=20
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> BlockEncoding=FAST_DIFF
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> Compress=NONE
>>>> Filter=ALL
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> On Thu, Jun 11, 2020 at 5:08 PM Andrew Purtell <ap...@apache.org>
>>> wrote:
>>>>> I used PE to generate 10M row tables with one family with either 1,
>> 10,
>>> 20, 50, or 100 values per row (unique column-qualifiers). An increase in
>>> wall clock time was noticeable, for example:
>>>>>
>>>>> 1.6.0
>>>>>
>>>>> time ./bin/hbase pe --rows=5000000 --table=TestTable_f1_c20
>>> --columns=20 --nomapred scan 2
>>>>> real 1m20.179s
>>>>> user 0m45.470s
>>>>> sys 0m16.572s
>>>>>
>>>>> 2.2.5
>>>>>
>>>>> time ./bin/hbase pe --rows=5000000 --table=TestTable_f1_c20
>>> --columns=20 --nomapred scan 2
>>>>> real 1m31.016s
>>>>> user 0m48.658s
>>>>> sys 0m16.965s
>>>>>
>>>>> It didnt really make a difference if I used 1 thread or 4 or 10, the
>>> delta was about the same, proportionally. I picked two threads in the end
>>> so I'd have enough time to launch async-profiler twice in another shell,
>> to
>>> capture flamegraph and call tree output, respectively. async-profiler
>>> captured 10 seconds at steady state per test case. Upon first inspection
>>> what jumps out is an increasing proportion of CPU time spent in GC in
>> 2.2.5
>>> vs 1.6.0. The difference increases as the number of column families
>>> increase. There is little apparent difference at 1 column family, but a
>> 2x
>>> or more difference at 20 columns, and a 10x or more difference at 100
>>> columns, eyeballing the charts, flipping back and forth between browser
>>> windows. This seems more than coincidental but obviously calls for
>> capture
>>> and analysis of GC trace, with JFR. Will do that next.
>>>>>
>>>>> JVM: openjdk version "1.8.0_232" OpenJDK Runtime Environment (Zulu
>>> 8.42.0.21-CA-macosx) (build 1.8.0_232-b18) OpenJDK 64-Bit Server VM (Zulu
>>> 8.42.0.21-CA-macosx) (build 25.232-b18, mixed mode)
>>>>>
>>>>> Regionserver JVM flags: -Xms10g -Xmx10g -XX:+UseG1GC
>>> -XX:+AlwaysPreTouch -XX:+UseNUMA -XX:-UseBiasedLocking
>>> -XX:+ParallelRefProcEnabled
>>>>>
>>>>>
>>>>> On Thu, Jun 11, 2020 at 7:06 AM Jan Van Besien <ja...@ngdata.com>
>>> wrote:
>>>>>> This is promising, thanks a lot. Testing with hbase 2.2.5 shows an
>>>>>> improvement, but we're not there yet.
>>>>>>
>>>>>> As reported earlier, hbase 2.1.0 was about 60% slower than hbase
>> 1.2.0
>>>>>> in a test that simply scans all the regions in parallel without any
>>>>>> filter. A test with hbase 2.2.5 shows it to be about 40% slower than
>>>>>> 1.2.0. So that is better than 2.1.0, but still substantially slower
>>>>>> than what hbase 1.2.0 was.
>>>>>>
>>>>>> As before, I tested this both on a 3 node cluster as well as with a
>>>>>> unit test using HBaseTestingUtility. Both tests show very similar
>>>>>> relative differences.
>>>>>>
>>>>>> Jan
>>>>>>
>>>>>> On Thu, Jun 11, 2020 at 2:16 PM Anoop John <an...@gmail.com>
>>> wrote:
>>>>>>>
>>>>>>> In another mail thread Zheng Hu brought up an important Jra fix
>>>>>>> https://issues.apache.org/jira/browse/HBASE-21657
>>>>>>> Can u pls check with this once?
>>>>>>>
>>>>>>> Anoop
>>>>>>>
>>>>>>>
>>>>>>> On Tue, Jun 9, 2020 at 8:08 PM Jan Van Besien <ja...@ngdata.com>
>>> wrote:
>>>>>>>
>>>>>>>> On Sun, Jun 7, 2020 at 7:49 AM Anoop John <anoop.hbase@gmail.com
>>>
>>> wrote:
>>>>>>>>> As per the above configs, it looks like Bucket Cache is not
>>> being used.
>>>>>>>>> Only on heap LRU cache in use.
>>>>>>>>
>>>>>>>> True (but it is large enough to hold everything, so I don't think
>>> it
>>>>>>>> matters).
>>>>>>>>
>>>>>>>>> @Jan - Is it possible for you to test with off heap Bucket
>> Cache?
>>>>>>>> Config
>>>>>>>>> bucket cache off heap mode with size ~7.5 GB
>>>>>>>>
>>>>>>>> I did a quick test but it seems not to make a measurable
>>> difference.
>>>>>>>> If anything, it is actually slightly slower even. I see 100% hit
>>> ratio
>>>>>>>> in the L1
>>>>>>>> LruBlockCache and effectively also 100% in the L2 BucketCache
>> (hit
>>>>>>>> ratio is not yet at 100% but hits increase with every test and
>>> misses
>>>>>>>> do not).
>>>>>>>>
>>>>>>>> Given that the LruBlockCache was already large enough to cache
>> all
>>> the
>>>>>>>> data anyway, I did not expect this to help either, to be honest.
>>>>>>>>
>>>>>>>>> Do you have any DataBlockEncoding enabled on the CF?
>>>>>>>>
>>>>>>>> Yes, FAST_DIFF. But this is of course true in both the tests with
>>>>>>>> hbase2 and hbase1.
>>>>>>>>
>>>>>>>> Jan
>>>>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> Best regards,
>>>>> Andrew
>>>>>
>>>>> Words like orphans lost among the crosstalk, meaning torn from truth's
>>> decrepit hands
>>>>> - A23, Crosstalk
>>>>
>>>>
>>>> --
>>>> Best regards,
>>>> Andrew
>>>>
>>>> Words like orphans lost among the crosstalk, meaning torn from truth's
>>> decrepit hands
>>>> - A23, Crosstalk
>>>
>>
>
>
Re: HBase 2 slower than HBase 1?
Posted by ramkrishna vasudevan <ra...@gmail.com>.
Hi Bruno
Regarding the perf issue with more CPs you might be interested in seeing
this
https://issues.apache.org/jira/browse/HBASE-25277
Regards
Ram
On Thu, Nov 5, 2020 at 11:25 PM ramkrishna vasudevan <
ramkrishna.s.vasudevan@gmail.com> wrote:
> This is great information. Thanks Bruno. Keep us posted if you find
> anything more when you have your isolated tests done.
>
> Regards
> Ram
>
> On Thu, Nov 5, 2020 at 10:36 PM Bruno Dumon <br...@ngdata.com> wrote:
>
>> Hi Ram,
>>
>> Sorry I missed your question. Yes, we do use addColumns.
>>
>> Specifically, we also query the Phoenix existence marker, which is a
>> column
>> named "_0", which is typically the last column in the row (we query this
>> through custom scans, not through Phoenix). It does seem that reading the
>> last column in the row does have an extra impact compared to HBase 1.2.
>>
>> I have been trying to further pin down our performance issues in an
>> isolated test but I have not yet arrived at anything conclusive. I'll try
>> to look into it further next week.
>>
>> I did also notice that HBase 2.x spends some more time iterating over the
>> coprocessors, and we quite a few of those (19, some of those are from
>> Phoenix, then some endpoint coprocessors and quite some region observers).
>> We don't do anything in the pre/postScannerNext but still it consumes
>> quite
>> some time during scanning. Replacing all the region observer coprocessors
>> by a single one does have a nice effect, 15-20% improvement, though I
>> still
>> need to test with a wider variety of queries.
>>
>>
>> On Fri, Oct 30, 2020 at 2:46 PM ramkrishna vasudevan <
>> ramkrishna.s.vasudevan@gmail.com> wrote:
>>
>> > Hi Bruno/Jan
>> >
>> > Just a query here. I read your emails in this thread. One simple
>> question
>> > just to ensure if your tests were similar to Andrew's test. Did your
>> scan
>> > query have addColumns explicitly added covering all (or most of) the
>> > columns in the rows?
>> >
>> > Regards
>> > Ram
>> >
>> >
>> >
>> >
>> > On Wed, Jul 15, 2020 at 7:02 AM Andrew Purtell <ap...@apache.org>
>> > wrote:
>> >
>> > > This is a good finding, nice work!
>> > > I added a comment on HBASE-24742 that mentions HBASE-24637 on the off
>> > > chance they are related, although I suspect more changes are
>> implicated
>> > by
>> > > the 2.x regression.
>> > >
>> > > On Tue, Jul 14, 2020 at 5:53 PM Bharath Vissapragada <
>> > bharathv@apache.org>
>> > > wrote:
>> > >
>> > > > FYI, we filed this today
>> > > https://issues.apache.org/jira/browse/HBASE-24742
>> > > > .
>> > > > We ran into a similar regression when upgrading from 1.3 based
>> branch
>> > to
>> > > > 1.6 based branch. After some profiling and code analysis we narrowed
>> > down
>> > > > the code paths.
>> > > >
>> > > > On Tue, Jul 14, 2020 at 11:38 AM Josh Elser <el...@apache.org>
>> wrote:
>> > > >
>> > > > > Wow. Great stuff, Andrew!
>> > > > >
>> > > > > Thank you for compiling and posting it all here. I can only
>> imagine
>> > how
>> > > > > time-consuming this was.
>> > > > >
>> > > > > On 6/26/20 1:57 PM, Andrew Purtell wrote:
>> > > > > > Hey Anoop, I opened
>> > > https://issues.apache.org/jira/browse/HBASE-24637
>> > > > > and
>> > > > > > attached the patches and script used to make the comparison.
>> > > > > >
>> > > > > > On Fri, Jun 26, 2020 at 2:33 AM Anoop John <
>> anoop.hbase@gmail.com>
>> > > > > wrote:
>> > > > > >
>> > > > > >> Great investigation Andy. Do you know any Jiras which made
>> > changes
>> > > in
>> > > > > SQM?
>> > > > > >> Would be great if you can attach your patch which tracks the
>> scan
>> > > > > flow. If
>> > > > > >> we have a Jira for this issue, can you pls attach?
>> > > > > >>
>> > > > > >> Anoop
>> > > > > >>
>> > > > > >> On Fri, Jun 26, 2020 at 1:56 AM Andrew Purtell <
>> > > > > andrew.purtell@gmail.com>
>> > > > > >> wrote:
>> > > > > >>
>> > > > > >>> Related, I think I found a bug in branch-1 where we don’t
>> > heartbeat
>> > > > in
>> > > > > >> the
>> > > > > >>> filter all case until we switch store files, so scanning a
>> very
>> > > large
>> > > > > >> store
>> > > > > >>> file might time out with client defaults. Remarking on this
>> here
>> > > so I
>> > > > > >> don’t
>> > > > > >>> forget to follow up.
>> > > > > >>>
>> > > > > >>>> On Jun 25, 2020, at 12:27 PM, Andrew Purtell <
>> > apurtell@apache.org
>> > > >
>> > > > > >>> wrote:
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>> I repeated this test with pe --filterAll and the results were
>> > > > > >> revealing,
>> > > > > >>> at least for this case. I also patched in thread local hash
>> map
>> > for
>> > > > > >> atomic
>> > > > > >>> counters that I could update from code paths in SQM,
>> > StoreScanner,
>> > > > > >>> HFileReader*, and HFileBlock. Because a RPC is processed by a
>> > > single
>> > > > > >>> handler thread I could update counters and accumulate
>> > micro-timings
>> > > > via
>> > > > > >>> System#nanoTime() per RPC and dump them out of CallRunner in
>> some
>> > > new
>> > > > > >> trace
>> > > > > >>> logging. I spent a couple of days making sure the
>> instrumentation
>> > > was
>> > > > > >>> placed equivalently in both 1.6 and 2.2 code bases and was
>> > > producing
>> > > > > >>> consistent results. I can provide these patches upon request.
>> > > > > >>>>
>> > > > > >>>> Again, test tables with one family and 1, 5, 10, 20, 50, and
>> 100
>> > > > > >>> distinct column-qualifiers per row. After loading the table I
>> > made
>> > > a
>> > > > > >>> snapshot and cloned the snapshot for testing, for both 1.6 and
>> > 2.2,
>> > > > so
>> > > > > >> both
>> > > > > >>> versions were tested using the exact same data files on HDFS.
>> I
>> > > also
>> > > > > used
>> > > > > >>> the 1.6 version of PE for both, so the only change is on the
>> > server
>> > > > > (1.6
>> > > > > >> vs
>> > > > > >>> 2.2 masters and regionservers).
>> > > > > >>>>
>> > > > > >>>> It appears a refactor to ScanQueryMatcher and friends has
>> > disabled
>> > > > the
>> > > > > >>> ability of filters to provide SKIP hints, which prevents us
>> from
>> > > > > >> bypassing
>> > > > > >>> version checking (so some extra cost in SQM), and appears to
>> > > disable
>> > > > an
>> > > > > >>> optimization that avoids reseeking, leading to a serious and
>> > > > > proportional
>> > > > > >>> regression in reseek activity and time spent in that code
>> path.
>> > So
>> > > > for
>> > > > > >>> queries that use filters, there can be a substantial
>> regression.
>> > > > > >>>>
>> > > > > >>>> Other test cases that did not use filters did not show a
>> > > regression.
>> > > > > >>>>
>> > > > > >>>> A test case where I used ROW_INDEX_V1 encoding showed an
>> > expected
>> > > > > >> modest
>> > > > > >>> proportional regression in seeking time, due to the fact it is
>> > > > > optimized
>> > > > > >>> for point queries and not optimized for the full table scan
>> case.
>> > > > > >>>>
>> > > > > >>>> I will come back here when I understand this better.
>> > > > > >>>>
>> > > > > >>>> Here are the results for the pe --filterAll case:
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>> 1.6.0 c1 2.2.5 c1
>> > > > > >>>> 1.6.0 c5 2.2.5 c5
>> > > > > >>>> 1.6.0 c10 2.2.5 c10
>> > > > > >>>> 1.6.0 c20 2.2.5 c20
>> > > > > >>>> 1.6.0 c50 2.2.5 c50
>> > > > > >>>> 1.6.0 c100 2.2.5 c100
>> > > > > >>>> Counts
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>> (better heartbeating)
>> > > > > >>>> (better heartbeating)
>> > > > > >>>> (better heartbeating)
>> > > > > >>>> (better heartbeating)
>> > > > > >>>> (better heartbeating)
>> > > > > >>>> rpcs 1 2 200% 2 6 300% 2
>> 10
>> > > > > >>> 500% 3 17 567% 4 37 925% 8
>> > 72
>> > > > > >> 900%
>> > > > > >>>> block_reads 11507 11508 100% 57255 57257 100%
>> > > 114471
>> > > > > >>> 114474 100% 230372 230377 100% 578292 578298 100%
>> > > > 1157955
>> > > > > >>> 1157963 100%
>> > > > > >>>> block_unpacks 11507 11508 100% 57255 57257 100%
>> > > 114471
>> > > > > >>> 114474 100% 230372 230377 100% 578292 578298 100%
>> > > > 1157955
>> > > > > >>> 1157963 100%
>> > > > > >>>> seeker_next 10000000 10000000 100%
>> 50000000
>> > > > > >>> 50000000 100% 100000000 100000000 100%
>> > > > > 200000000
>> > > > > >>> 200000000 100% 500000000 500000000
>> > 100%
>> > > > > >>> 1000000000 1000000000 100%
>> > > > > >>>> store_next 10000000 9988268 100% 50000000
>> > > > 49940082
>> > > > > >>> 100% 100000000 99879401 100%
>> 200000000
>> > > > > >>> 199766539 100% 500000000 499414653 100%
>> > > > > >>> 1000000000 998836518 100%
>> > > > > >>>> store_reseek 1 11733 > ! 2 59924 > !
>> 8
>> > > > > >>> 120607 > ! 6 233467 > ! 10 585357 > !
>> > 8
>> > > > > >>> 1163490 > !
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>> cells_matched 20000000 20000000 100%
>> 60000000
>> > > > > >>> 60000000 100% 110000000 110000000 100%
>> > > > > 210000000
>> > > > > >>> 210000000 100% 510000000 510000000
>> > 100%
>> > > > > >>> 1010000000 1010000000 100%
>> > > > > >>>> column_hint_include 10000000 10000000 100%
>> > > > 50000000
>> > > > > >>> 50000000 100% 100000000 100000000
>> > 100%
>> > > > > >>> 200000000 200000000 100% 500000000
>> 500000000
>> > > > > >>> 100% 1000000000 1000000000 100%
>> > > > > >>>> filter_hint_skip 10000000 10000000 100%
>> > > > 50000000
>> > > > > >>> 50000000 100% 100000000 100000000
>> > 100%
>> > > > > >>> 200000000 200000000 100% 500000000
>> 500000000
>> > > > > >>> 100% 1000000000 1000000000 100%
>> > > > > >>>> sqm_hint_done 9999999 9999999 100% 9999998 9999998 100%
>> > > > 9999998
>> > > > > >>> 9999998 100% 9999997 9999997 100% 9999996 9999996 100%
>> > > > 9999992
>> > > > > >>> 9999992 100%
>> > > > > >>>> sqm_hint_seek_next_col 1 0 0% 2
>> > > > 40000002
>> > > > > >>> > ! 2 90000002 > ! 3
>> 190000003
>> > > > > > !
>> > > > > >>> 4 490000004 > ! 8 990000008 >
>> !
>> > > > > >>>> sqm_hint_seek_next_row 0 10000000 > !
>> 2
>> > > > > >>> 10000000 > ! 0 10000000 > ! 0
>> > > > > 10000000
>> > > > > >>> > ! 0 10000000 > ! 0
>> 10000000
>> > > > > > !
>> > > > > >>>> sqm_hint_skip 10000000 0 0% 50000000
>> 0
>> > > > > >>> 0% 100000000 0 0% 200000000 0
>> > > 0%
>> > > > > >>> 500000000 0 0% 1000000000 0 0%
>> > > > > >>>> versions_hint_include_and_seek_next_col 0 0
>> 0%
>> > > > > 0
>> > > > > >>> 40000000 > ! 0 90000000 > !
>> 0
>> > > > > >>> 190000000 > ! 0 490000000 > ! 0
>> > > > > >> 990000000
>> > > > > >>> > !
>> > > > > >>>> versions_hint_include_and_seek_next_row 0 0
>> 0%
>> > > > > 0
>> > > > > >>> 10000000 > ! 0 10000000 > !
>> 0
>> > > > > >>> 10000000 > ! 0 10000000 > ! 0
>> > > > > 10000000
>> > > > > >>> > !
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>> Times
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>> block_read_ms 174.12 215.96 124% 683.78 883.02 129%
>> > > > 1724.66
>> > > > > >>> 1937.87 112% 3199.93 3470.92 108% 7582.96 7941.45 105%
>> > > > > 14701.52
>> > > > > >>> 16022.57 109%
>> > > > > >>>> block_unpack_ms 0.63 0.62 99% 2.35 2.35
>> > 100%
>> > > > > >>> 4.36 4.56 105% 9.10 8.30 91% 21.59 22.01
>> > > 102%
>> > > > > >>> 40.97 40.93 100%
>> > > > > >>>> seeker_next_ms 1073.45 1053.51 98% 4452.52 4728.96
>> > 106%
>> > > > > >>> 9359.61 9706.06 104% 18879.28 18330.93 97%
>> > > > > 47664.95
>> > > > > >>> 46404.26 97% 96511.83 92121.30
>> 95%
>> > > > > >>>> store_next_ms 2651.11 2423.27 91% 12048.64
>> 11398.63
>> > > > > >>> 95% 24833.68 23586.20 95% 48493.26
>> > > > > 46574.38
>> > > > > >>> 96% 120786.00 115603.00 96% 240627.00
>> > > > > >>> 227945.00 95%
>> > > > > >>>> store_reseek_ms 2.71 62.17 2297% 10.93 233.67
>> > > 2139%
>> > > > > >>> 10.88 401.88 3693% 13.98 783.18 5601% 22.26
>> 1939.28
>> > > > 8714%
>> > > > > >>> 24.32 4065.25 16714%
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>> Rows=10000000
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>> ValueSize=20
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>> BlockEncoding=FAST_DIFF
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>> Compress=NONE
>> > > > > >>>> Filter=ALL
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>> On Thu, Jun 11, 2020 at 5:08 PM Andrew Purtell <
>> > > apurtell@apache.org
>> > > > >
>> > > > > >>> wrote:
>> > > > > >>>>> I used PE to generate 10M row tables with one family with
>> > either
>> > > 1,
>> > > > > >> 10,
>> > > > > >>> 20, 50, or 100 values per row (unique column-qualifiers). An
>> > > increase
>> > > > > in
>> > > > > >>> wall clock time was noticeable, for example:
>> > > > > >>>>>
>> > > > > >>>>> 1.6.0
>> > > > > >>>>>
>> > > > > >>>>> time ./bin/hbase pe --rows=5000000 --table=TestTable_f1_c20
>> > > > > >>> --columns=20 --nomapred scan 2
>> > > > > >>>>> real 1m20.179s
>> > > > > >>>>> user 0m45.470s
>> > > > > >>>>> sys 0m16.572s
>> > > > > >>>>>
>> > > > > >>>>> 2.2.5
>> > > > > >>>>>
>> > > > > >>>>> time ./bin/hbase pe --rows=5000000 --table=TestTable_f1_c20
>> > > > > >>> --columns=20 --nomapred scan 2
>> > > > > >>>>> real 1m31.016s
>> > > > > >>>>> user 0m48.658s
>> > > > > >>>>> sys 0m16.965s
>> > > > > >>>>>
>> > > > > >>>>> It didnt really make a difference if I used 1 thread or 4 or
>> > 10,
>> > > > the
>> > > > > >>> delta was about the same, proportionally. I picked two
>> threads in
>> > > the
>> > > > > end
>> > > > > >>> so I'd have enough time to launch async-profiler twice in
>> another
>> > > > > shell,
>> > > > > >> to
>> > > > > >>> capture flamegraph and call tree output, respectively.
>> > > async-profiler
>> > > > > >>> captured 10 seconds at steady state per test case. Upon first
>> > > > > inspection
>> > > > > >>> what jumps out is an increasing proportion of CPU time spent
>> in
>> > GC
>> > > in
>> > > > > >> 2.2.5
>> > > > > >>> vs 1.6.0. The difference increases as the number of column
>> > families
>> > > > > >>> increase. There is little apparent difference at 1 column
>> family,
>> > > > but a
>> > > > > >> 2x
>> > > > > >>> or more difference at 20 columns, and a 10x or more
>> difference at
>> > > 100
>> > > > > >>> columns, eyeballing the charts, flipping back and forth
>> between
>> > > > browser
>> > > > > >>> windows. This seems more than coincidental but obviously calls
>> > for
>> > > > > >> capture
>> > > > > >>> and analysis of GC trace, with JFR. Will do that next.
>> > > > > >>>>>
>> > > > > >>>>> JVM: openjdk version "1.8.0_232" OpenJDK Runtime Environment
>> > > (Zulu
>> > > > > >>> 8.42.0.21-CA-macosx) (build 1.8.0_232-b18) OpenJDK 64-Bit
>> Server
>> > VM
>> > > > > (Zulu
>> > > > > >>> 8.42.0.21-CA-macosx) (build 25.232-b18, mixed mode)
>> > > > > >>>>>
>> > > > > >>>>> Regionserver JVM flags: -Xms10g -Xmx10g -XX:+UseG1GC
>> > > > > >>> -XX:+AlwaysPreTouch -XX:+UseNUMA -XX:-UseBiasedLocking
>> > > > > >>> -XX:+ParallelRefProcEnabled
>> > > > > >>>>>
>> > > > > >>>>>
>> > > > > >>>>> On Thu, Jun 11, 2020 at 7:06 AM Jan Van Besien <
>> > janvb@ngdata.com
>> > > >
>> > > > > >>> wrote:
>> > > > > >>>>>> This is promising, thanks a lot. Testing with hbase 2.2.5
>> > shows
>> > > an
>> > > > > >>>>>> improvement, but we're not there yet.
>> > > > > >>>>>>
>> > > > > >>>>>> As reported earlier, hbase 2.1.0 was about 60% slower than
>> > hbase
>> > > > > >> 1.2.0
>> > > > > >>>>>> in a test that simply scans all the regions in parallel
>> > without
>> > > > any
>> > > > > >>>>>> filter. A test with hbase 2.2.5 shows it to be about 40%
>> > slower
>> > > > than
>> > > > > >>>>>> 1.2.0. So that is better than 2.1.0, but still
>> substantially
>> > > > slower
>> > > > > >>>>>> than what hbase 1.2.0 was.
>> > > > > >>>>>>
>> > > > > >>>>>> As before, I tested this both on a 3 node cluster as well
>> as
>> > > with
>> > > > a
>> > > > > >>>>>> unit test using HBaseTestingUtility. Both tests show very
>> > > similar
>> > > > > >>>>>> relative differences.
>> > > > > >>>>>>
>> > > > > >>>>>> Jan
>> > > > > >>>>>>
>> > > > > >>>>>> On Thu, Jun 11, 2020 at 2:16 PM Anoop John <
>> > > anoop.hbase@gmail.com
>> > > > >
>> > > > > >>> wrote:
>> > > > > >>>>>>>
>> > > > > >>>>>>> In another mail thread Zheng Hu brought up an important
>> Jra
>> > fix
>> > > > > >>>>>>> https://issues.apache.org/jira/browse/HBASE-21657
>> > > > > >>>>>>> Can u pls check with this once?
>> > > > > >>>>>>>
>> > > > > >>>>>>> Anoop
>> > > > > >>>>>>>
>> > > > > >>>>>>>
>> > > > > >>>>>>> On Tue, Jun 9, 2020 at 8:08 PM Jan Van Besien <
>> > > janvb@ngdata.com>
>> > > > > >>> wrote:
>> > > > > >>>>>>>
>> > > > > >>>>>>>> On Sun, Jun 7, 2020 at 7:49 AM Anoop John <
>> > > > anoop.hbase@gmail.com
>> > > > > >>>
>> > > > > >>> wrote:
>> > > > > >>>>>>>>> As per the above configs, it looks like Bucket Cache is
>> not
>> > > > > >>> being used.
>> > > > > >>>>>>>>> Only on heap LRU cache in use.
>> > > > > >>>>>>>>
>> > > > > >>>>>>>> True (but it is large enough to hold everything, so I
>> don't
>> > > > think
>> > > > > >>> it
>> > > > > >>>>>>>> matters).
>> > > > > >>>>>>>>
>> > > > > >>>>>>>>> @Jan - Is it possible for you to test with off heap
>> Bucket
>> > > > > >> Cache?
>> > > > > >>>>>>>> Config
>> > > > > >>>>>>>>> bucket cache off heap mode with size ~7.5 GB
>> > > > > >>>>>>>>
>> > > > > >>>>>>>> I did a quick test but it seems not to make a measurable
>> > > > > >>> difference.
>> > > > > >>>>>>>> If anything, it is actually slightly slower even. I see
>> 100%
>> > > hit
>> > > > > >>> ratio
>> > > > > >>>>>>>> in the L1
>> > > > > >>>>>>>> LruBlockCache and effectively also 100% in the L2
>> > BucketCache
>> > > > > >> (hit
>> > > > > >>>>>>>> ratio is not yet at 100% but hits increase with every
>> test
>> > and
>> > > > > >>> misses
>> > > > > >>>>>>>> do not).
>> > > > > >>>>>>>>
>> > > > > >>>>>>>> Given that the LruBlockCache was already large enough to
>> > cache
>> > > > > >> all
>> > > > > >>> the
>> > > > > >>>>>>>> data anyway, I did not expect this to help either, to be
>> > > honest.
>> > > > > >>>>>>>>
>> > > > > >>>>>>>>> Do you have any DataBlockEncoding enabled on the CF?
>> > > > > >>>>>>>>
>> > > > > >>>>>>>> Yes, FAST_DIFF. But this is of course true in both the
>> tests
>> > > > with
>> > > > > >>>>>>>> hbase2 and hbase1.
>> > > > > >>>>>>>>
>> > > > > >>>>>>>> Jan
>> > > > > >>>>>>>>
>> > > > > >>>>>
>> > > > > >>>>>
>> > > > > >>>>> --
>> > > > > >>>>> Best regards,
>> > > > > >>>>> Andrew
>> > > > > >>>>>
>> > > > > >>>>> Words like orphans lost among the crosstalk, meaning torn
>> from
>> > > > > truth's
>> > > > > >>> decrepit hands
>> > > > > >>>>> - A23, Crosstalk
>> > > > > >>>>
>> > > > > >>>>
>> > > > > >>>> --
>> > > > > >>>> Best regards,
>> > > > > >>>> Andrew
>> > > > > >>>>
>> > > > > >>>> Words like orphans lost among the crosstalk, meaning torn
>> from
>> > > > truth's
>> > > > > >>> decrepit hands
>> > > > > >>>> - A23, Crosstalk
>> > > > > >>>
>> > > > > >>
>> > > > > >
>> > > > > >
>> > > > >
>> > > >
>> > >
>> > >
>> > > --
>> > > Best regards,
>> > > Andrew
>> > >
>> > > Words like orphans lost among the crosstalk, meaning torn from truth's
>> > > decrepit hands
>> > > - A23, Crosstalk
>> > >
>> >
>>
>>
>> --
>> Bruno Dumon
>> NGDATA
>> http://www.ngdata.com/
>>
>
Re: HBase 2 slower than HBase 1?
Posted by ramkrishna vasudevan <ra...@gmail.com>.
This is great information. Thanks Bruno. Keep us posted if you find
anything more when you have your isolated tests done.
Regards
Ram
On Thu, Nov 5, 2020 at 10:36 PM Bruno Dumon <br...@ngdata.com> wrote:
> Hi Ram,
>
> Sorry I missed your question. Yes, we do use addColumns.
>
> Specifically, we also query the Phoenix existence marker, which is a column
> named "_0", which is typically the last column in the row (we query this
> through custom scans, not through Phoenix). It does seem that reading the
> last column in the row does have an extra impact compared to HBase 1.2.
>
> I have been trying to further pin down our performance issues in an
> isolated test but I have not yet arrived at anything conclusive. I'll try
> to look into it further next week.
>
> I did also notice that HBase 2.x spends some more time iterating over the
> coprocessors, and we quite a few of those (19, some of those are from
> Phoenix, then some endpoint coprocessors and quite some region observers).
> We don't do anything in the pre/postScannerNext but still it consumes quite
> some time during scanning. Replacing all the region observer coprocessors
> by a single one does have a nice effect, 15-20% improvement, though I still
> need to test with a wider variety of queries.
>
>
> On Fri, Oct 30, 2020 at 2:46 PM ramkrishna vasudevan <
> ramkrishna.s.vasudevan@gmail.com> wrote:
>
> > Hi Bruno/Jan
> >
> > Just a query here. I read your emails in this thread. One simple question
> > just to ensure if your tests were similar to Andrew's test. Did your scan
> > query have addColumns explicitly added covering all (or most of) the
> > columns in the rows?
> >
> > Regards
> > Ram
> >
> >
> >
> >
> > On Wed, Jul 15, 2020 at 7:02 AM Andrew Purtell <ap...@apache.org>
> > wrote:
> >
> > > This is a good finding, nice work!
> > > I added a comment on HBASE-24742 that mentions HBASE-24637 on the off
> > > chance they are related, although I suspect more changes are implicated
> > by
> > > the 2.x regression.
> > >
> > > On Tue, Jul 14, 2020 at 5:53 PM Bharath Vissapragada <
> > bharathv@apache.org>
> > > wrote:
> > >
> > > > FYI, we filed this today
> > > https://issues.apache.org/jira/browse/HBASE-24742
> > > > .
> > > > We ran into a similar regression when upgrading from 1.3 based branch
> > to
> > > > 1.6 based branch. After some profiling and code analysis we narrowed
> > down
> > > > the code paths.
> > > >
> > > > On Tue, Jul 14, 2020 at 11:38 AM Josh Elser <el...@apache.org>
> wrote:
> > > >
> > > > > Wow. Great stuff, Andrew!
> > > > >
> > > > > Thank you for compiling and posting it all here. I can only imagine
> > how
> > > > > time-consuming this was.
> > > > >
> > > > > On 6/26/20 1:57 PM, Andrew Purtell wrote:
> > > > > > Hey Anoop, I opened
> > > https://issues.apache.org/jira/browse/HBASE-24637
> > > > > and
> > > > > > attached the patches and script used to make the comparison.
> > > > > >
> > > > > > On Fri, Jun 26, 2020 at 2:33 AM Anoop John <
> anoop.hbase@gmail.com>
> > > > > wrote:
> > > > > >
> > > > > >> Great investigation Andy. Do you know any Jiras which made
> > changes
> > > in
> > > > > SQM?
> > > > > >> Would be great if you can attach your patch which tracks the
> scan
> > > > > flow. If
> > > > > >> we have a Jira for this issue, can you pls attach?
> > > > > >>
> > > > > >> Anoop
> > > > > >>
> > > > > >> On Fri, Jun 26, 2020 at 1:56 AM Andrew Purtell <
> > > > > andrew.purtell@gmail.com>
> > > > > >> wrote:
> > > > > >>
> > > > > >>> Related, I think I found a bug in branch-1 where we don’t
> > heartbeat
> > > > in
> > > > > >> the
> > > > > >>> filter all case until we switch store files, so scanning a very
> > > large
> > > > > >> store
> > > > > >>> file might time out with client defaults. Remarking on this
> here
> > > so I
> > > > > >> don’t
> > > > > >>> forget to follow up.
> > > > > >>>
> > > > > >>>> On Jun 25, 2020, at 12:27 PM, Andrew Purtell <
> > apurtell@apache.org
> > > >
> > > > > >>> wrote:
> > > > > >>>>
> > > > > >>>>
> > > > > >>>> I repeated this test with pe --filterAll and the results were
> > > > > >> revealing,
> > > > > >>> at least for this case. I also patched in thread local hash map
> > for
> > > > > >> atomic
> > > > > >>> counters that I could update from code paths in SQM,
> > StoreScanner,
> > > > > >>> HFileReader*, and HFileBlock. Because a RPC is processed by a
> > > single
> > > > > >>> handler thread I could update counters and accumulate
> > micro-timings
> > > > via
> > > > > >>> System#nanoTime() per RPC and dump them out of CallRunner in
> some
> > > new
> > > > > >> trace
> > > > > >>> logging. I spent a couple of days making sure the
> instrumentation
> > > was
> > > > > >>> placed equivalently in both 1.6 and 2.2 code bases and was
> > > producing
> > > > > >>> consistent results. I can provide these patches upon request.
> > > > > >>>>
> > > > > >>>> Again, test tables with one family and 1, 5, 10, 20, 50, and
> 100
> > > > > >>> distinct column-qualifiers per row. After loading the table I
> > made
> > > a
> > > > > >>> snapshot and cloned the snapshot for testing, for both 1.6 and
> > 2.2,
> > > > so
> > > > > >> both
> > > > > >>> versions were tested using the exact same data files on HDFS. I
> > > also
> > > > > used
> > > > > >>> the 1.6 version of PE for both, so the only change is on the
> > server
> > > > > (1.6
> > > > > >> vs
> > > > > >>> 2.2 masters and regionservers).
> > > > > >>>>
> > > > > >>>> It appears a refactor to ScanQueryMatcher and friends has
> > disabled
> > > > the
> > > > > >>> ability of filters to provide SKIP hints, which prevents us
> from
> > > > > >> bypassing
> > > > > >>> version checking (so some extra cost in SQM), and appears to
> > > disable
> > > > an
> > > > > >>> optimization that avoids reseeking, leading to a serious and
> > > > > proportional
> > > > > >>> regression in reseek activity and time spent in that code path.
> > So
> > > > for
> > > > > >>> queries that use filters, there can be a substantial
> regression.
> > > > > >>>>
> > > > > >>>> Other test cases that did not use filters did not show a
> > > regression.
> > > > > >>>>
> > > > > >>>> A test case where I used ROW_INDEX_V1 encoding showed an
> > expected
> > > > > >> modest
> > > > > >>> proportional regression in seeking time, due to the fact it is
> > > > > optimized
> > > > > >>> for point queries and not optimized for the full table scan
> case.
> > > > > >>>>
> > > > > >>>> I will come back here when I understand this better.
> > > > > >>>>
> > > > > >>>> Here are the results for the pe --filterAll case:
> > > > > >>>>
> > > > > >>>>
> > > > > >>>> 1.6.0 c1 2.2.5 c1
> > > > > >>>> 1.6.0 c5 2.2.5 c5
> > > > > >>>> 1.6.0 c10 2.2.5 c10
> > > > > >>>> 1.6.0 c20 2.2.5 c20
> > > > > >>>> 1.6.0 c50 2.2.5 c50
> > > > > >>>> 1.6.0 c100 2.2.5 c100
> > > > > >>>> Counts
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>> (better heartbeating)
> > > > > >>>> (better heartbeating)
> > > > > >>>> (better heartbeating)
> > > > > >>>> (better heartbeating)
> > > > > >>>> (better heartbeating)
> > > > > >>>> rpcs 1 2 200% 2 6 300% 2
> 10
> > > > > >>> 500% 3 17 567% 4 37 925% 8
> > 72
> > > > > >> 900%
> > > > > >>>> block_reads 11507 11508 100% 57255 57257 100%
> > > 114471
> > > > > >>> 114474 100% 230372 230377 100% 578292 578298 100%
> > > > 1157955
> > > > > >>> 1157963 100%
> > > > > >>>> block_unpacks 11507 11508 100% 57255 57257 100%
> > > 114471
> > > > > >>> 114474 100% 230372 230377 100% 578292 578298 100%
> > > > 1157955
> > > > > >>> 1157963 100%
> > > > > >>>> seeker_next 10000000 10000000 100% 50000000
> > > > > >>> 50000000 100% 100000000 100000000 100%
> > > > > 200000000
> > > > > >>> 200000000 100% 500000000 500000000
> > 100%
> > > > > >>> 1000000000 1000000000 100%
> > > > > >>>> store_next 10000000 9988268 100% 50000000
> > > > 49940082
> > > > > >>> 100% 100000000 99879401 100%
> 200000000
> > > > > >>> 199766539 100% 500000000 499414653 100%
> > > > > >>> 1000000000 998836518 100%
> > > > > >>>> store_reseek 1 11733 > ! 2 59924 > !
> 8
> > > > > >>> 120607 > ! 6 233467 > ! 10 585357 > !
> > 8
> > > > > >>> 1163490 > !
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>> cells_matched 20000000 20000000 100% 60000000
> > > > > >>> 60000000 100% 110000000 110000000 100%
> > > > > 210000000
> > > > > >>> 210000000 100% 510000000 510000000
> > 100%
> > > > > >>> 1010000000 1010000000 100%
> > > > > >>>> column_hint_include 10000000 10000000 100%
> > > > 50000000
> > > > > >>> 50000000 100% 100000000 100000000
> > 100%
> > > > > >>> 200000000 200000000 100% 500000000
> 500000000
> > > > > >>> 100% 1000000000 1000000000 100%
> > > > > >>>> filter_hint_skip 10000000 10000000 100%
> > > > 50000000
> > > > > >>> 50000000 100% 100000000 100000000
> > 100%
> > > > > >>> 200000000 200000000 100% 500000000
> 500000000
> > > > > >>> 100% 1000000000 1000000000 100%
> > > > > >>>> sqm_hint_done 9999999 9999999 100% 9999998 9999998 100%
> > > > 9999998
> > > > > >>> 9999998 100% 9999997 9999997 100% 9999996 9999996 100%
> > > > 9999992
> > > > > >>> 9999992 100%
> > > > > >>>> sqm_hint_seek_next_col 1 0 0% 2
> > > > 40000002
> > > > > >>> > ! 2 90000002 > ! 3
> 190000003
> > > > > > !
> > > > > >>> 4 490000004 > ! 8 990000008 > !
> > > > > >>>> sqm_hint_seek_next_row 0 10000000 > !
> 2
> > > > > >>> 10000000 > ! 0 10000000 > ! 0
> > > > > 10000000
> > > > > >>> > ! 0 10000000 > ! 0 10000000
> > > > > > !
> > > > > >>>> sqm_hint_skip 10000000 0 0% 50000000
> 0
> > > > > >>> 0% 100000000 0 0% 200000000 0
> > > 0%
> > > > > >>> 500000000 0 0% 1000000000 0 0%
> > > > > >>>> versions_hint_include_and_seek_next_col 0 0
> 0%
> > > > > 0
> > > > > >>> 40000000 > ! 0 90000000 > ! 0
> > > > > >>> 190000000 > ! 0 490000000 > ! 0
> > > > > >> 990000000
> > > > > >>> > !
> > > > > >>>> versions_hint_include_and_seek_next_row 0 0
> 0%
> > > > > 0
> > > > > >>> 10000000 > ! 0 10000000 > ! 0
> > > > > >>> 10000000 > ! 0 10000000 > ! 0
> > > > > 10000000
> > > > > >>> > !
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>> Times
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>> block_read_ms 174.12 215.96 124% 683.78 883.02 129%
> > > > 1724.66
> > > > > >>> 1937.87 112% 3199.93 3470.92 108% 7582.96 7941.45 105%
> > > > > 14701.52
> > > > > >>> 16022.57 109%
> > > > > >>>> block_unpack_ms 0.63 0.62 99% 2.35 2.35
> > 100%
> > > > > >>> 4.36 4.56 105% 9.10 8.30 91% 21.59 22.01
> > > 102%
> > > > > >>> 40.97 40.93 100%
> > > > > >>>> seeker_next_ms 1073.45 1053.51 98% 4452.52 4728.96
> > 106%
> > > > > >>> 9359.61 9706.06 104% 18879.28 18330.93 97%
> > > > > 47664.95
> > > > > >>> 46404.26 97% 96511.83 92121.30
> 95%
> > > > > >>>> store_next_ms 2651.11 2423.27 91% 12048.64 11398.63
> > > > > >>> 95% 24833.68 23586.20 95% 48493.26
> > > > > 46574.38
> > > > > >>> 96% 120786.00 115603.00 96% 240627.00
> > > > > >>> 227945.00 95%
> > > > > >>>> store_reseek_ms 2.71 62.17 2297% 10.93 233.67
> > > 2139%
> > > > > >>> 10.88 401.88 3693% 13.98 783.18 5601% 22.26
> 1939.28
> > > > 8714%
> > > > > >>> 24.32 4065.25 16714%
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>> Rows=10000000
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>> ValueSize=20
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>> BlockEncoding=FAST_DIFF
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>> Compress=NONE
> > > > > >>>> Filter=ALL
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>>
> > > > > >>>> On Thu, Jun 11, 2020 at 5:08 PM Andrew Purtell <
> > > apurtell@apache.org
> > > > >
> > > > > >>> wrote:
> > > > > >>>>> I used PE to generate 10M row tables with one family with
> > either
> > > 1,
> > > > > >> 10,
> > > > > >>> 20, 50, or 100 values per row (unique column-qualifiers). An
> > > increase
> > > > > in
> > > > > >>> wall clock time was noticeable, for example:
> > > > > >>>>>
> > > > > >>>>> 1.6.0
> > > > > >>>>>
> > > > > >>>>> time ./bin/hbase pe --rows=5000000 --table=TestTable_f1_c20
> > > > > >>> --columns=20 --nomapred scan 2
> > > > > >>>>> real 1m20.179s
> > > > > >>>>> user 0m45.470s
> > > > > >>>>> sys 0m16.572s
> > > > > >>>>>
> > > > > >>>>> 2.2.5
> > > > > >>>>>
> > > > > >>>>> time ./bin/hbase pe --rows=5000000 --table=TestTable_f1_c20
> > > > > >>> --columns=20 --nomapred scan 2
> > > > > >>>>> real 1m31.016s
> > > > > >>>>> user 0m48.658s
> > > > > >>>>> sys 0m16.965s
> > > > > >>>>>
> > > > > >>>>> It didnt really make a difference if I used 1 thread or 4 or
> > 10,
> > > > the
> > > > > >>> delta was about the same, proportionally. I picked two threads
> in
> > > the
> > > > > end
> > > > > >>> so I'd have enough time to launch async-profiler twice in
> another
> > > > > shell,
> > > > > >> to
> > > > > >>> capture flamegraph and call tree output, respectively.
> > > async-profiler
> > > > > >>> captured 10 seconds at steady state per test case. Upon first
> > > > > inspection
> > > > > >>> what jumps out is an increasing proportion of CPU time spent in
> > GC
> > > in
> > > > > >> 2.2.5
> > > > > >>> vs 1.6.0. The difference increases as the number of column
> > families
> > > > > >>> increase. There is little apparent difference at 1 column
> family,
> > > > but a
> > > > > >> 2x
> > > > > >>> or more difference at 20 columns, and a 10x or more difference
> at
> > > 100
> > > > > >>> columns, eyeballing the charts, flipping back and forth between
> > > > browser
> > > > > >>> windows. This seems more than coincidental but obviously calls
> > for
> > > > > >> capture
> > > > > >>> and analysis of GC trace, with JFR. Will do that next.
> > > > > >>>>>
> > > > > >>>>> JVM: openjdk version "1.8.0_232" OpenJDK Runtime Environment
> > > (Zulu
> > > > > >>> 8.42.0.21-CA-macosx) (build 1.8.0_232-b18) OpenJDK 64-Bit
> Server
> > VM
> > > > > (Zulu
> > > > > >>> 8.42.0.21-CA-macosx) (build 25.232-b18, mixed mode)
> > > > > >>>>>
> > > > > >>>>> Regionserver JVM flags: -Xms10g -Xmx10g -XX:+UseG1GC
> > > > > >>> -XX:+AlwaysPreTouch -XX:+UseNUMA -XX:-UseBiasedLocking
> > > > > >>> -XX:+ParallelRefProcEnabled
> > > > > >>>>>
> > > > > >>>>>
> > > > > >>>>> On Thu, Jun 11, 2020 at 7:06 AM Jan Van Besien <
> > janvb@ngdata.com
> > > >
> > > > > >>> wrote:
> > > > > >>>>>> This is promising, thanks a lot. Testing with hbase 2.2.5
> > shows
> > > an
> > > > > >>>>>> improvement, but we're not there yet.
> > > > > >>>>>>
> > > > > >>>>>> As reported earlier, hbase 2.1.0 was about 60% slower than
> > hbase
> > > > > >> 1.2.0
> > > > > >>>>>> in a test that simply scans all the regions in parallel
> > without
> > > > any
> > > > > >>>>>> filter. A test with hbase 2.2.5 shows it to be about 40%
> > slower
> > > > than
> > > > > >>>>>> 1.2.0. So that is better than 2.1.0, but still substantially
> > > > slower
> > > > > >>>>>> than what hbase 1.2.0 was.
> > > > > >>>>>>
> > > > > >>>>>> As before, I tested this both on a 3 node cluster as well as
> > > with
> > > > a
> > > > > >>>>>> unit test using HBaseTestingUtility. Both tests show very
> > > similar
> > > > > >>>>>> relative differences.
> > > > > >>>>>>
> > > > > >>>>>> Jan
> > > > > >>>>>>
> > > > > >>>>>> On Thu, Jun 11, 2020 at 2:16 PM Anoop John <
> > > anoop.hbase@gmail.com
> > > > >
> > > > > >>> wrote:
> > > > > >>>>>>>
> > > > > >>>>>>> In another mail thread Zheng Hu brought up an important Jra
> > fix
> > > > > >>>>>>> https://issues.apache.org/jira/browse/HBASE-21657
> > > > > >>>>>>> Can u pls check with this once?
> > > > > >>>>>>>
> > > > > >>>>>>> Anoop
> > > > > >>>>>>>
> > > > > >>>>>>>
> > > > > >>>>>>> On Tue, Jun 9, 2020 at 8:08 PM Jan Van Besien <
> > > janvb@ngdata.com>
> > > > > >>> wrote:
> > > > > >>>>>>>
> > > > > >>>>>>>> On Sun, Jun 7, 2020 at 7:49 AM Anoop John <
> > > > anoop.hbase@gmail.com
> > > > > >>>
> > > > > >>> wrote:
> > > > > >>>>>>>>> As per the above configs, it looks like Bucket Cache is
> not
> > > > > >>> being used.
> > > > > >>>>>>>>> Only on heap LRU cache in use.
> > > > > >>>>>>>>
> > > > > >>>>>>>> True (but it is large enough to hold everything, so I
> don't
> > > > think
> > > > > >>> it
> > > > > >>>>>>>> matters).
> > > > > >>>>>>>>
> > > > > >>>>>>>>> @Jan - Is it possible for you to test with off heap
> Bucket
> > > > > >> Cache?
> > > > > >>>>>>>> Config
> > > > > >>>>>>>>> bucket cache off heap mode with size ~7.5 GB
> > > > > >>>>>>>>
> > > > > >>>>>>>> I did a quick test but it seems not to make a measurable
> > > > > >>> difference.
> > > > > >>>>>>>> If anything, it is actually slightly slower even. I see
> 100%
> > > hit
> > > > > >>> ratio
> > > > > >>>>>>>> in the L1
> > > > > >>>>>>>> LruBlockCache and effectively also 100% in the L2
> > BucketCache
> > > > > >> (hit
> > > > > >>>>>>>> ratio is not yet at 100% but hits increase with every test
> > and
> > > > > >>> misses
> > > > > >>>>>>>> do not).
> > > > > >>>>>>>>
> > > > > >>>>>>>> Given that the LruBlockCache was already large enough to
> > cache
> > > > > >> all
> > > > > >>> the
> > > > > >>>>>>>> data anyway, I did not expect this to help either, to be
> > > honest.
> > > > > >>>>>>>>
> > > > > >>>>>>>>> Do you have any DataBlockEncoding enabled on the CF?
> > > > > >>>>>>>>
> > > > > >>>>>>>> Yes, FAST_DIFF. But this is of course true in both the
> tests
> > > > with
> > > > > >>>>>>>> hbase2 and hbase1.
> > > > > >>>>>>>>
> > > > > >>>>>>>> Jan
> > > > > >>>>>>>>
> > > > > >>>>>
> > > > > >>>>>
> > > > > >>>>> --
> > > > > >>>>> Best regards,
> > > > > >>>>> Andrew
> > > > > >>>>>
> > > > > >>>>> Words like orphans lost among the crosstalk, meaning torn
> from
> > > > > truth's
> > > > > >>> decrepit hands
> > > > > >>>>> - A23, Crosstalk
> > > > > >>>>
> > > > > >>>>
> > > > > >>>> --
> > > > > >>>> Best regards,
> > > > > >>>> Andrew
> > > > > >>>>
> > > > > >>>> Words like orphans lost among the crosstalk, meaning torn from
> > > > truth's
> > > > > >>> decrepit hands
> > > > > >>>> - A23, Crosstalk
> > > > > >>>
> > > > > >>
> > > > > >
> > > > > >
> > > > >
> > > >
> > >
> > >
> > > --
> > > Best regards,
> > > Andrew
> > >
> > > Words like orphans lost among the crosstalk, meaning torn from truth's
> > > decrepit hands
> > > - A23, Crosstalk
> > >
> >
>
>
> --
> Bruno Dumon
> NGDATA
> http://www.ngdata.com/
>
Re: HBase 2 slower than HBase 1?
Posted by Bruno Dumon <br...@ngdata.com>.
Hi Ram,
Sorry I missed your question. Yes, we do use addColumns.
Specifically, we also query the Phoenix existence marker, which is a column
named "_0", which is typically the last column in the row (we query this
through custom scans, not through Phoenix). It does seem that reading the
last column in the row does have an extra impact compared to HBase 1.2.
I have been trying to further pin down our performance issues in an
isolated test but I have not yet arrived at anything conclusive. I'll try
to look into it further next week.
I did also notice that HBase 2.x spends some more time iterating over the
coprocessors, and we quite a few of those (19, some of those are from
Phoenix, then some endpoint coprocessors and quite some region observers).
We don't do anything in the pre/postScannerNext but still it consumes quite
some time during scanning. Replacing all the region observer coprocessors
by a single one does have a nice effect, 15-20% improvement, though I still
need to test with a wider variety of queries.
On Fri, Oct 30, 2020 at 2:46 PM ramkrishna vasudevan <
ramkrishna.s.vasudevan@gmail.com> wrote:
> Hi Bruno/Jan
>
> Just a query here. I read your emails in this thread. One simple question
> just to ensure if your tests were similar to Andrew's test. Did your scan
> query have addColumns explicitly added covering all (or most of) the
> columns in the rows?
>
> Regards
> Ram
>
>
>
>
> On Wed, Jul 15, 2020 at 7:02 AM Andrew Purtell <ap...@apache.org>
> wrote:
>
> > This is a good finding, nice work!
> > I added a comment on HBASE-24742 that mentions HBASE-24637 on the off
> > chance they are related, although I suspect more changes are implicated
> by
> > the 2.x regression.
> >
> > On Tue, Jul 14, 2020 at 5:53 PM Bharath Vissapragada <
> bharathv@apache.org>
> > wrote:
> >
> > > FYI, we filed this today
> > https://issues.apache.org/jira/browse/HBASE-24742
> > > .
> > > We ran into a similar regression when upgrading from 1.3 based branch
> to
> > > 1.6 based branch. After some profiling and code analysis we narrowed
> down
> > > the code paths.
> > >
> > > On Tue, Jul 14, 2020 at 11:38 AM Josh Elser <el...@apache.org> wrote:
> > >
> > > > Wow. Great stuff, Andrew!
> > > >
> > > > Thank you for compiling and posting it all here. I can only imagine
> how
> > > > time-consuming this was.
> > > >
> > > > On 6/26/20 1:57 PM, Andrew Purtell wrote:
> > > > > Hey Anoop, I opened
> > https://issues.apache.org/jira/browse/HBASE-24637
> > > > and
> > > > > attached the patches and script used to make the comparison.
> > > > >
> > > > > On Fri, Jun 26, 2020 at 2:33 AM Anoop John <an...@gmail.com>
> > > > wrote:
> > > > >
> > > > >> Great investigation Andy. Do you know any Jiras which made
> changes
> > in
> > > > SQM?
> > > > >> Would be great if you can attach your patch which tracks the scan
> > > > flow. If
> > > > >> we have a Jira for this issue, can you pls attach?
> > > > >>
> > > > >> Anoop
> > > > >>
> > > > >> On Fri, Jun 26, 2020 at 1:56 AM Andrew Purtell <
> > > > andrew.purtell@gmail.com>
> > > > >> wrote:
> > > > >>
> > > > >>> Related, I think I found a bug in branch-1 where we don’t
> heartbeat
> > > in
> > > > >> the
> > > > >>> filter all case until we switch store files, so scanning a very
> > large
> > > > >> store
> > > > >>> file might time out with client defaults. Remarking on this here
> > so I
> > > > >> don’t
> > > > >>> forget to follow up.
> > > > >>>
> > > > >>>> On Jun 25, 2020, at 12:27 PM, Andrew Purtell <
> apurtell@apache.org
> > >
> > > > >>> wrote:
> > > > >>>>
> > > > >>>>
> > > > >>>> I repeated this test with pe --filterAll and the results were
> > > > >> revealing,
> > > > >>> at least for this case. I also patched in thread local hash map
> for
> > > > >> atomic
> > > > >>> counters that I could update from code paths in SQM,
> StoreScanner,
> > > > >>> HFileReader*, and HFileBlock. Because a RPC is processed by a
> > single
> > > > >>> handler thread I could update counters and accumulate
> micro-timings
> > > via
> > > > >>> System#nanoTime() per RPC and dump them out of CallRunner in some
> > new
> > > > >> trace
> > > > >>> logging. I spent a couple of days making sure the instrumentation
> > was
> > > > >>> placed equivalently in both 1.6 and 2.2 code bases and was
> > producing
> > > > >>> consistent results. I can provide these patches upon request.
> > > > >>>>
> > > > >>>> Again, test tables with one family and 1, 5, 10, 20, 50, and 100
> > > > >>> distinct column-qualifiers per row. After loading the table I
> made
> > a
> > > > >>> snapshot and cloned the snapshot for testing, for both 1.6 and
> 2.2,
> > > so
> > > > >> both
> > > > >>> versions were tested using the exact same data files on HDFS. I
> > also
> > > > used
> > > > >>> the 1.6 version of PE for both, so the only change is on the
> server
> > > > (1.6
> > > > >> vs
> > > > >>> 2.2 masters and regionservers).
> > > > >>>>
> > > > >>>> It appears a refactor to ScanQueryMatcher and friends has
> disabled
> > > the
> > > > >>> ability of filters to provide SKIP hints, which prevents us from
> > > > >> bypassing
> > > > >>> version checking (so some extra cost in SQM), and appears to
> > disable
> > > an
> > > > >>> optimization that avoids reseeking, leading to a serious and
> > > > proportional
> > > > >>> regression in reseek activity and time spent in that code path.
> So
> > > for
> > > > >>> queries that use filters, there can be a substantial regression.
> > > > >>>>
> > > > >>>> Other test cases that did not use filters did not show a
> > regression.
> > > > >>>>
> > > > >>>> A test case where I used ROW_INDEX_V1 encoding showed an
> expected
> > > > >> modest
> > > > >>> proportional regression in seeking time, due to the fact it is
> > > > optimized
> > > > >>> for point queries and not optimized for the full table scan case.
> > > > >>>>
> > > > >>>> I will come back here when I understand this better.
> > > > >>>>
> > > > >>>> Here are the results for the pe --filterAll case:
> > > > >>>>
> > > > >>>>
> > > > >>>> 1.6.0 c1 2.2.5 c1
> > > > >>>> 1.6.0 c5 2.2.5 c5
> > > > >>>> 1.6.0 c10 2.2.5 c10
> > > > >>>> 1.6.0 c20 2.2.5 c20
> > > > >>>> 1.6.0 c50 2.2.5 c50
> > > > >>>> 1.6.0 c100 2.2.5 c100
> > > > >>>> Counts
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>> (better heartbeating)
> > > > >>>> (better heartbeating)
> > > > >>>> (better heartbeating)
> > > > >>>> (better heartbeating)
> > > > >>>> (better heartbeating)
> > > > >>>> rpcs 1 2 200% 2 6 300% 2 10
> > > > >>> 500% 3 17 567% 4 37 925% 8
> 72
> > > > >> 900%
> > > > >>>> block_reads 11507 11508 100% 57255 57257 100%
> > 114471
> > > > >>> 114474 100% 230372 230377 100% 578292 578298 100%
> > > 1157955
> > > > >>> 1157963 100%
> > > > >>>> block_unpacks 11507 11508 100% 57255 57257 100%
> > 114471
> > > > >>> 114474 100% 230372 230377 100% 578292 578298 100%
> > > 1157955
> > > > >>> 1157963 100%
> > > > >>>> seeker_next 10000000 10000000 100% 50000000
> > > > >>> 50000000 100% 100000000 100000000 100%
> > > > 200000000
> > > > >>> 200000000 100% 500000000 500000000
> 100%
> > > > >>> 1000000000 1000000000 100%
> > > > >>>> store_next 10000000 9988268 100% 50000000
> > > 49940082
> > > > >>> 100% 100000000 99879401 100% 200000000
> > > > >>> 199766539 100% 500000000 499414653 100%
> > > > >>> 1000000000 998836518 100%
> > > > >>>> store_reseek 1 11733 > ! 2 59924 > ! 8
> > > > >>> 120607 > ! 6 233467 > ! 10 585357 > !
> 8
> > > > >>> 1163490 > !
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>> cells_matched 20000000 20000000 100% 60000000
> > > > >>> 60000000 100% 110000000 110000000 100%
> > > > 210000000
> > > > >>> 210000000 100% 510000000 510000000
> 100%
> > > > >>> 1010000000 1010000000 100%
> > > > >>>> column_hint_include 10000000 10000000 100%
> > > 50000000
> > > > >>> 50000000 100% 100000000 100000000
> 100%
> > > > >>> 200000000 200000000 100% 500000000 500000000
> > > > >>> 100% 1000000000 1000000000 100%
> > > > >>>> filter_hint_skip 10000000 10000000 100%
> > > 50000000
> > > > >>> 50000000 100% 100000000 100000000
> 100%
> > > > >>> 200000000 200000000 100% 500000000 500000000
> > > > >>> 100% 1000000000 1000000000 100%
> > > > >>>> sqm_hint_done 9999999 9999999 100% 9999998 9999998 100%
> > > 9999998
> > > > >>> 9999998 100% 9999997 9999997 100% 9999996 9999996 100%
> > > 9999992
> > > > >>> 9999992 100%
> > > > >>>> sqm_hint_seek_next_col 1 0 0% 2
> > > 40000002
> > > > >>> > ! 2 90000002 > ! 3 190000003
> > > > > !
> > > > >>> 4 490000004 > ! 8 990000008 > !
> > > > >>>> sqm_hint_seek_next_row 0 10000000 > ! 2
> > > > >>> 10000000 > ! 0 10000000 > ! 0
> > > > 10000000
> > > > >>> > ! 0 10000000 > ! 0 10000000
> > > > > !
> > > > >>>> sqm_hint_skip 10000000 0 0% 50000000 0
> > > > >>> 0% 100000000 0 0% 200000000 0
> > 0%
> > > > >>> 500000000 0 0% 1000000000 0 0%
> > > > >>>> versions_hint_include_and_seek_next_col 0 0 0%
> > > > 0
> > > > >>> 40000000 > ! 0 90000000 > ! 0
> > > > >>> 190000000 > ! 0 490000000 > ! 0
> > > > >> 990000000
> > > > >>> > !
> > > > >>>> versions_hint_include_and_seek_next_row 0 0 0%
> > > > 0
> > > > >>> 10000000 > ! 0 10000000 > ! 0
> > > > >>> 10000000 > ! 0 10000000 > ! 0
> > > > 10000000
> > > > >>> > !
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>> Times
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>> block_read_ms 174.12 215.96 124% 683.78 883.02 129%
> > > 1724.66
> > > > >>> 1937.87 112% 3199.93 3470.92 108% 7582.96 7941.45 105%
> > > > 14701.52
> > > > >>> 16022.57 109%
> > > > >>>> block_unpack_ms 0.63 0.62 99% 2.35 2.35
> 100%
> > > > >>> 4.36 4.56 105% 9.10 8.30 91% 21.59 22.01
> > 102%
> > > > >>> 40.97 40.93 100%
> > > > >>>> seeker_next_ms 1073.45 1053.51 98% 4452.52 4728.96
> 106%
> > > > >>> 9359.61 9706.06 104% 18879.28 18330.93 97%
> > > > 47664.95
> > > > >>> 46404.26 97% 96511.83 92121.30 95%
> > > > >>>> store_next_ms 2651.11 2423.27 91% 12048.64 11398.63
> > > > >>> 95% 24833.68 23586.20 95% 48493.26
> > > > 46574.38
> > > > >>> 96% 120786.00 115603.00 96% 240627.00
> > > > >>> 227945.00 95%
> > > > >>>> store_reseek_ms 2.71 62.17 2297% 10.93 233.67
> > 2139%
> > > > >>> 10.88 401.88 3693% 13.98 783.18 5601% 22.26 1939.28
> > > 8714%
> > > > >>> 24.32 4065.25 16714%
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>> Rows=10000000
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>> ValueSize=20
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>> BlockEncoding=FAST_DIFF
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>> Compress=NONE
> > > > >>>> Filter=ALL
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>>
> > > > >>>> On Thu, Jun 11, 2020 at 5:08 PM Andrew Purtell <
> > apurtell@apache.org
> > > >
> > > > >>> wrote:
> > > > >>>>> I used PE to generate 10M row tables with one family with
> either
> > 1,
> > > > >> 10,
> > > > >>> 20, 50, or 100 values per row (unique column-qualifiers). An
> > increase
> > > > in
> > > > >>> wall clock time was noticeable, for example:
> > > > >>>>>
> > > > >>>>> 1.6.0
> > > > >>>>>
> > > > >>>>> time ./bin/hbase pe --rows=5000000 --table=TestTable_f1_c20
> > > > >>> --columns=20 --nomapred scan 2
> > > > >>>>> real 1m20.179s
> > > > >>>>> user 0m45.470s
> > > > >>>>> sys 0m16.572s
> > > > >>>>>
> > > > >>>>> 2.2.5
> > > > >>>>>
> > > > >>>>> time ./bin/hbase pe --rows=5000000 --table=TestTable_f1_c20
> > > > >>> --columns=20 --nomapred scan 2
> > > > >>>>> real 1m31.016s
> > > > >>>>> user 0m48.658s
> > > > >>>>> sys 0m16.965s
> > > > >>>>>
> > > > >>>>> It didnt really make a difference if I used 1 thread or 4 or
> 10,
> > > the
> > > > >>> delta was about the same, proportionally. I picked two threads in
> > the
> > > > end
> > > > >>> so I'd have enough time to launch async-profiler twice in another
> > > > shell,
> > > > >> to
> > > > >>> capture flamegraph and call tree output, respectively.
> > async-profiler
> > > > >>> captured 10 seconds at steady state per test case. Upon first
> > > > inspection
> > > > >>> what jumps out is an increasing proportion of CPU time spent in
> GC
> > in
> > > > >> 2.2.5
> > > > >>> vs 1.6.0. The difference increases as the number of column
> families
> > > > >>> increase. There is little apparent difference at 1 column family,
> > > but a
> > > > >> 2x
> > > > >>> or more difference at 20 columns, and a 10x or more difference at
> > 100
> > > > >>> columns, eyeballing the charts, flipping back and forth between
> > > browser
> > > > >>> windows. This seems more than coincidental but obviously calls
> for
> > > > >> capture
> > > > >>> and analysis of GC trace, with JFR. Will do that next.
> > > > >>>>>
> > > > >>>>> JVM: openjdk version "1.8.0_232" OpenJDK Runtime Environment
> > (Zulu
> > > > >>> 8.42.0.21-CA-macosx) (build 1.8.0_232-b18) OpenJDK 64-Bit Server
> VM
> > > > (Zulu
> > > > >>> 8.42.0.21-CA-macosx) (build 25.232-b18, mixed mode)
> > > > >>>>>
> > > > >>>>> Regionserver JVM flags: -Xms10g -Xmx10g -XX:+UseG1GC
> > > > >>> -XX:+AlwaysPreTouch -XX:+UseNUMA -XX:-UseBiasedLocking
> > > > >>> -XX:+ParallelRefProcEnabled
> > > > >>>>>
> > > > >>>>>
> > > > >>>>> On Thu, Jun 11, 2020 at 7:06 AM Jan Van Besien <
> janvb@ngdata.com
> > >
> > > > >>> wrote:
> > > > >>>>>> This is promising, thanks a lot. Testing with hbase 2.2.5
> shows
> > an
> > > > >>>>>> improvement, but we're not there yet.
> > > > >>>>>>
> > > > >>>>>> As reported earlier, hbase 2.1.0 was about 60% slower than
> hbase
> > > > >> 1.2.0
> > > > >>>>>> in a test that simply scans all the regions in parallel
> without
> > > any
> > > > >>>>>> filter. A test with hbase 2.2.5 shows it to be about 40%
> slower
> > > than
> > > > >>>>>> 1.2.0. So that is better than 2.1.0, but still substantially
> > > slower
> > > > >>>>>> than what hbase 1.2.0 was.
> > > > >>>>>>
> > > > >>>>>> As before, I tested this both on a 3 node cluster as well as
> > with
> > > a
> > > > >>>>>> unit test using HBaseTestingUtility. Both tests show very
> > similar
> > > > >>>>>> relative differences.
> > > > >>>>>>
> > > > >>>>>> Jan
> > > > >>>>>>
> > > > >>>>>> On Thu, Jun 11, 2020 at 2:16 PM Anoop John <
> > anoop.hbase@gmail.com
> > > >
> > > > >>> wrote:
> > > > >>>>>>>
> > > > >>>>>>> In another mail thread Zheng Hu brought up an important Jra
> fix
> > > > >>>>>>> https://issues.apache.org/jira/browse/HBASE-21657
> > > > >>>>>>> Can u pls check with this once?
> > > > >>>>>>>
> > > > >>>>>>> Anoop
> > > > >>>>>>>
> > > > >>>>>>>
> > > > >>>>>>> On Tue, Jun 9, 2020 at 8:08 PM Jan Van Besien <
> > janvb@ngdata.com>
> > > > >>> wrote:
> > > > >>>>>>>
> > > > >>>>>>>> On Sun, Jun 7, 2020 at 7:49 AM Anoop John <
> > > anoop.hbase@gmail.com
> > > > >>>
> > > > >>> wrote:
> > > > >>>>>>>>> As per the above configs, it looks like Bucket Cache is not
> > > > >>> being used.
> > > > >>>>>>>>> Only on heap LRU cache in use.
> > > > >>>>>>>>
> > > > >>>>>>>> True (but it is large enough to hold everything, so I don't
> > > think
> > > > >>> it
> > > > >>>>>>>> matters).
> > > > >>>>>>>>
> > > > >>>>>>>>> @Jan - Is it possible for you to test with off heap Bucket
> > > > >> Cache?
> > > > >>>>>>>> Config
> > > > >>>>>>>>> bucket cache off heap mode with size ~7.5 GB
> > > > >>>>>>>>
> > > > >>>>>>>> I did a quick test but it seems not to make a measurable
> > > > >>> difference.
> > > > >>>>>>>> If anything, it is actually slightly slower even. I see 100%
> > hit
> > > > >>> ratio
> > > > >>>>>>>> in the L1
> > > > >>>>>>>> LruBlockCache and effectively also 100% in the L2
> BucketCache
> > > > >> (hit
> > > > >>>>>>>> ratio is not yet at 100% but hits increase with every test
> and
> > > > >>> misses
> > > > >>>>>>>> do not).
> > > > >>>>>>>>
> > > > >>>>>>>> Given that the LruBlockCache was already large enough to
> cache
> > > > >> all
> > > > >>> the
> > > > >>>>>>>> data anyway, I did not expect this to help either, to be
> > honest.
> > > > >>>>>>>>
> > > > >>>>>>>>> Do you have any DataBlockEncoding enabled on the CF?
> > > > >>>>>>>>
> > > > >>>>>>>> Yes, FAST_DIFF. But this is of course true in both the tests
> > > with
> > > > >>>>>>>> hbase2 and hbase1.
> > > > >>>>>>>>
> > > > >>>>>>>> Jan
> > > > >>>>>>>>
> > > > >>>>>
> > > > >>>>>
> > > > >>>>> --
> > > > >>>>> Best regards,
> > > > >>>>> Andrew
> > > > >>>>>
> > > > >>>>> Words like orphans lost among the crosstalk, meaning torn from
> > > > truth's
> > > > >>> decrepit hands
> > > > >>>>> - A23, Crosstalk
> > > > >>>>
> > > > >>>>
> > > > >>>> --
> > > > >>>> Best regards,
> > > > >>>> Andrew
> > > > >>>>
> > > > >>>> Words like orphans lost among the crosstalk, meaning torn from
> > > truth's
> > > > >>> decrepit hands
> > > > >>>> - A23, Crosstalk
> > > > >>>
> > > > >>
> > > > >
> > > > >
> > > >
> > >
> >
> >
> > --
> > Best regards,
> > Andrew
> >
> > Words like orphans lost among the crosstalk, meaning torn from truth's
> > decrepit hands
> > - A23, Crosstalk
> >
>
--
Bruno Dumon
NGDATA
http://www.ngdata.com/
Re: HBase 2 slower than HBase 1?
Posted by ramkrishna vasudevan <ra...@gmail.com>.
Hi Bruno/Jan
Just a query here. I read your emails in this thread. One simple question
just to ensure if your tests were similar to Andrew's test. Did your scan
query have addColumns explicitly added covering all (or most of) the
columns in the rows?
Regards
Ram
On Wed, Jul 15, 2020 at 7:02 AM Andrew Purtell <ap...@apache.org> wrote:
> This is a good finding, nice work!
> I added a comment on HBASE-24742 that mentions HBASE-24637 on the off
> chance they are related, although I suspect more changes are implicated by
> the 2.x regression.
>
> On Tue, Jul 14, 2020 at 5:53 PM Bharath Vissapragada <bh...@apache.org>
> wrote:
>
> > FYI, we filed this today
> https://issues.apache.org/jira/browse/HBASE-24742
> > .
> > We ran into a similar regression when upgrading from 1.3 based branch to
> > 1.6 based branch. After some profiling and code analysis we narrowed down
> > the code paths.
> >
> > On Tue, Jul 14, 2020 at 11:38 AM Josh Elser <el...@apache.org> wrote:
> >
> > > Wow. Great stuff, Andrew!
> > >
> > > Thank you for compiling and posting it all here. I can only imagine how
> > > time-consuming this was.
> > >
> > > On 6/26/20 1:57 PM, Andrew Purtell wrote:
> > > > Hey Anoop, I opened
> https://issues.apache.org/jira/browse/HBASE-24637
> > > and
> > > > attached the patches and script used to make the comparison.
> > > >
> > > > On Fri, Jun 26, 2020 at 2:33 AM Anoop John <an...@gmail.com>
> > > wrote:
> > > >
> > > >> Great investigation Andy. Do you know any Jiras which made changes
> in
> > > SQM?
> > > >> Would be great if you can attach your patch which tracks the scan
> > > flow. If
> > > >> we have a Jira for this issue, can you pls attach?
> > > >>
> > > >> Anoop
> > > >>
> > > >> On Fri, Jun 26, 2020 at 1:56 AM Andrew Purtell <
> > > andrew.purtell@gmail.com>
> > > >> wrote:
> > > >>
> > > >>> Related, I think I found a bug in branch-1 where we don’t heartbeat
> > in
> > > >> the
> > > >>> filter all case until we switch store files, so scanning a very
> large
> > > >> store
> > > >>> file might time out with client defaults. Remarking on this here
> so I
> > > >> don’t
> > > >>> forget to follow up.
> > > >>>
> > > >>>> On Jun 25, 2020, at 12:27 PM, Andrew Purtell <apurtell@apache.org
> >
> > > >>> wrote:
> > > >>>>
> > > >>>>
> > > >>>> I repeated this test with pe --filterAll and the results were
> > > >> revealing,
> > > >>> at least for this case. I also patched in thread local hash map for
> > > >> atomic
> > > >>> counters that I could update from code paths in SQM, StoreScanner,
> > > >>> HFileReader*, and HFileBlock. Because a RPC is processed by a
> single
> > > >>> handler thread I could update counters and accumulate micro-timings
> > via
> > > >>> System#nanoTime() per RPC and dump them out of CallRunner in some
> new
> > > >> trace
> > > >>> logging. I spent a couple of days making sure the instrumentation
> was
> > > >>> placed equivalently in both 1.6 and 2.2 code bases and was
> producing
> > > >>> consistent results. I can provide these patches upon request.
> > > >>>>
> > > >>>> Again, test tables with one family and 1, 5, 10, 20, 50, and 100
> > > >>> distinct column-qualifiers per row. After loading the table I made
> a
> > > >>> snapshot and cloned the snapshot for testing, for both 1.6 and 2.2,
> > so
> > > >> both
> > > >>> versions were tested using the exact same data files on HDFS. I
> also
> > > used
> > > >>> the 1.6 version of PE for both, so the only change is on the server
> > > (1.6
> > > >> vs
> > > >>> 2.2 masters and regionservers).
> > > >>>>
> > > >>>> It appears a refactor to ScanQueryMatcher and friends has disabled
> > the
> > > >>> ability of filters to provide SKIP hints, which prevents us from
> > > >> bypassing
> > > >>> version checking (so some extra cost in SQM), and appears to
> disable
> > an
> > > >>> optimization that avoids reseeking, leading to a serious and
> > > proportional
> > > >>> regression in reseek activity and time spent in that code path. So
> > for
> > > >>> queries that use filters, there can be a substantial regression.
> > > >>>>
> > > >>>> Other test cases that did not use filters did not show a
> regression.
> > > >>>>
> > > >>>> A test case where I used ROW_INDEX_V1 encoding showed an expected
> > > >> modest
> > > >>> proportional regression in seeking time, due to the fact it is
> > > optimized
> > > >>> for point queries and not optimized for the full table scan case.
> > > >>>>
> > > >>>> I will come back here when I understand this better.
> > > >>>>
> > > >>>> Here are the results for the pe --filterAll case:
> > > >>>>
> > > >>>>
> > > >>>> 1.6.0 c1 2.2.5 c1
> > > >>>> 1.6.0 c5 2.2.5 c5
> > > >>>> 1.6.0 c10 2.2.5 c10
> > > >>>> 1.6.0 c20 2.2.5 c20
> > > >>>> 1.6.0 c50 2.2.5 c50
> > > >>>> 1.6.0 c100 2.2.5 c100
> > > >>>> Counts
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>> (better heartbeating)
> > > >>>> (better heartbeating)
> > > >>>> (better heartbeating)
> > > >>>> (better heartbeating)
> > > >>>> (better heartbeating)
> > > >>>> rpcs 1 2 200% 2 6 300% 2 10
> > > >>> 500% 3 17 567% 4 37 925% 8 72
> > > >> 900%
> > > >>>> block_reads 11507 11508 100% 57255 57257 100%
> 114471
> > > >>> 114474 100% 230372 230377 100% 578292 578298 100%
> > 1157955
> > > >>> 1157963 100%
> > > >>>> block_unpacks 11507 11508 100% 57255 57257 100%
> 114471
> > > >>> 114474 100% 230372 230377 100% 578292 578298 100%
> > 1157955
> > > >>> 1157963 100%
> > > >>>> seeker_next 10000000 10000000 100% 50000000
> > > >>> 50000000 100% 100000000 100000000 100%
> > > 200000000
> > > >>> 200000000 100% 500000000 500000000 100%
> > > >>> 1000000000 1000000000 100%
> > > >>>> store_next 10000000 9988268 100% 50000000
> > 49940082
> > > >>> 100% 100000000 99879401 100% 200000000
> > > >>> 199766539 100% 500000000 499414653 100%
> > > >>> 1000000000 998836518 100%
> > > >>>> store_reseek 1 11733 > ! 2 59924 > ! 8
> > > >>> 120607 > ! 6 233467 > ! 10 585357 > ! 8
> > > >>> 1163490 > !
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>> cells_matched 20000000 20000000 100% 60000000
> > > >>> 60000000 100% 110000000 110000000 100%
> > > 210000000
> > > >>> 210000000 100% 510000000 510000000 100%
> > > >>> 1010000000 1010000000 100%
> > > >>>> column_hint_include 10000000 10000000 100%
> > 50000000
> > > >>> 50000000 100% 100000000 100000000 100%
> > > >>> 200000000 200000000 100% 500000000 500000000
> > > >>> 100% 1000000000 1000000000 100%
> > > >>>> filter_hint_skip 10000000 10000000 100%
> > 50000000
> > > >>> 50000000 100% 100000000 100000000 100%
> > > >>> 200000000 200000000 100% 500000000 500000000
> > > >>> 100% 1000000000 1000000000 100%
> > > >>>> sqm_hint_done 9999999 9999999 100% 9999998 9999998 100%
> > 9999998
> > > >>> 9999998 100% 9999997 9999997 100% 9999996 9999996 100%
> > 9999992
> > > >>> 9999992 100%
> > > >>>> sqm_hint_seek_next_col 1 0 0% 2
> > 40000002
> > > >>> > ! 2 90000002 > ! 3 190000003
> > > > !
> > > >>> 4 490000004 > ! 8 990000008 > !
> > > >>>> sqm_hint_seek_next_row 0 10000000 > ! 2
> > > >>> 10000000 > ! 0 10000000 > ! 0
> > > 10000000
> > > >>> > ! 0 10000000 > ! 0 10000000
> > > > !
> > > >>>> sqm_hint_skip 10000000 0 0% 50000000 0
> > > >>> 0% 100000000 0 0% 200000000 0
> 0%
> > > >>> 500000000 0 0% 1000000000 0 0%
> > > >>>> versions_hint_include_and_seek_next_col 0 0 0%
> > > 0
> > > >>> 40000000 > ! 0 90000000 > ! 0
> > > >>> 190000000 > ! 0 490000000 > ! 0
> > > >> 990000000
> > > >>> > !
> > > >>>> versions_hint_include_and_seek_next_row 0 0 0%
> > > 0
> > > >>> 10000000 > ! 0 10000000 > ! 0
> > > >>> 10000000 > ! 0 10000000 > ! 0
> > > 10000000
> > > >>> > !
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>> Times
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>> block_read_ms 174.12 215.96 124% 683.78 883.02 129%
> > 1724.66
> > > >>> 1937.87 112% 3199.93 3470.92 108% 7582.96 7941.45 105%
> > > 14701.52
> > > >>> 16022.57 109%
> > > >>>> block_unpack_ms 0.63 0.62 99% 2.35 2.35 100%
> > > >>> 4.36 4.56 105% 9.10 8.30 91% 21.59 22.01
> 102%
> > > >>> 40.97 40.93 100%
> > > >>>> seeker_next_ms 1073.45 1053.51 98% 4452.52 4728.96 106%
> > > >>> 9359.61 9706.06 104% 18879.28 18330.93 97%
> > > 47664.95
> > > >>> 46404.26 97% 96511.83 92121.30 95%
> > > >>>> store_next_ms 2651.11 2423.27 91% 12048.64 11398.63
> > > >>> 95% 24833.68 23586.20 95% 48493.26
> > > 46574.38
> > > >>> 96% 120786.00 115603.00 96% 240627.00
> > > >>> 227945.00 95%
> > > >>>> store_reseek_ms 2.71 62.17 2297% 10.93 233.67
> 2139%
> > > >>> 10.88 401.88 3693% 13.98 783.18 5601% 22.26 1939.28
> > 8714%
> > > >>> 24.32 4065.25 16714%
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>> Rows=10000000
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>> ValueSize=20
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>> BlockEncoding=FAST_DIFF
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>> Compress=NONE
> > > >>>> Filter=ALL
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>>
> > > >>>> On Thu, Jun 11, 2020 at 5:08 PM Andrew Purtell <
> apurtell@apache.org
> > >
> > > >>> wrote:
> > > >>>>> I used PE to generate 10M row tables with one family with either
> 1,
> > > >> 10,
> > > >>> 20, 50, or 100 values per row (unique column-qualifiers). An
> increase
> > > in
> > > >>> wall clock time was noticeable, for example:
> > > >>>>>
> > > >>>>> 1.6.0
> > > >>>>>
> > > >>>>> time ./bin/hbase pe --rows=5000000 --table=TestTable_f1_c20
> > > >>> --columns=20 --nomapred scan 2
> > > >>>>> real 1m20.179s
> > > >>>>> user 0m45.470s
> > > >>>>> sys 0m16.572s
> > > >>>>>
> > > >>>>> 2.2.5
> > > >>>>>
> > > >>>>> time ./bin/hbase pe --rows=5000000 --table=TestTable_f1_c20
> > > >>> --columns=20 --nomapred scan 2
> > > >>>>> real 1m31.016s
> > > >>>>> user 0m48.658s
> > > >>>>> sys 0m16.965s
> > > >>>>>
> > > >>>>> It didnt really make a difference if I used 1 thread or 4 or 10,
> > the
> > > >>> delta was about the same, proportionally. I picked two threads in
> the
> > > end
> > > >>> so I'd have enough time to launch async-profiler twice in another
> > > shell,
> > > >> to
> > > >>> capture flamegraph and call tree output, respectively.
> async-profiler
> > > >>> captured 10 seconds at steady state per test case. Upon first
> > > inspection
> > > >>> what jumps out is an increasing proportion of CPU time spent in GC
> in
> > > >> 2.2.5
> > > >>> vs 1.6.0. The difference increases as the number of column families
> > > >>> increase. There is little apparent difference at 1 column family,
> > but a
> > > >> 2x
> > > >>> or more difference at 20 columns, and a 10x or more difference at
> 100
> > > >>> columns, eyeballing the charts, flipping back and forth between
> > browser
> > > >>> windows. This seems more than coincidental but obviously calls for
> > > >> capture
> > > >>> and analysis of GC trace, with JFR. Will do that next.
> > > >>>>>
> > > >>>>> JVM: openjdk version "1.8.0_232" OpenJDK Runtime Environment
> (Zulu
> > > >>> 8.42.0.21-CA-macosx) (build 1.8.0_232-b18) OpenJDK 64-Bit Server VM
> > > (Zulu
> > > >>> 8.42.0.21-CA-macosx) (build 25.232-b18, mixed mode)
> > > >>>>>
> > > >>>>> Regionserver JVM flags: -Xms10g -Xmx10g -XX:+UseG1GC
> > > >>> -XX:+AlwaysPreTouch -XX:+UseNUMA -XX:-UseBiasedLocking
> > > >>> -XX:+ParallelRefProcEnabled
> > > >>>>>
> > > >>>>>
> > > >>>>> On Thu, Jun 11, 2020 at 7:06 AM Jan Van Besien <janvb@ngdata.com
> >
> > > >>> wrote:
> > > >>>>>> This is promising, thanks a lot. Testing with hbase 2.2.5 shows
> an
> > > >>>>>> improvement, but we're not there yet.
> > > >>>>>>
> > > >>>>>> As reported earlier, hbase 2.1.0 was about 60% slower than hbase
> > > >> 1.2.0
> > > >>>>>> in a test that simply scans all the regions in parallel without
> > any
> > > >>>>>> filter. A test with hbase 2.2.5 shows it to be about 40% slower
> > than
> > > >>>>>> 1.2.0. So that is better than 2.1.0, but still substantially
> > slower
> > > >>>>>> than what hbase 1.2.0 was.
> > > >>>>>>
> > > >>>>>> As before, I tested this both on a 3 node cluster as well as
> with
> > a
> > > >>>>>> unit test using HBaseTestingUtility. Both tests show very
> similar
> > > >>>>>> relative differences.
> > > >>>>>>
> > > >>>>>> Jan
> > > >>>>>>
> > > >>>>>> On Thu, Jun 11, 2020 at 2:16 PM Anoop John <
> anoop.hbase@gmail.com
> > >
> > > >>> wrote:
> > > >>>>>>>
> > > >>>>>>> In another mail thread Zheng Hu brought up an important Jra fix
> > > >>>>>>> https://issues.apache.org/jira/browse/HBASE-21657
> > > >>>>>>> Can u pls check with this once?
> > > >>>>>>>
> > > >>>>>>> Anoop
> > > >>>>>>>
> > > >>>>>>>
> > > >>>>>>> On Tue, Jun 9, 2020 at 8:08 PM Jan Van Besien <
> janvb@ngdata.com>
> > > >>> wrote:
> > > >>>>>>>
> > > >>>>>>>> On Sun, Jun 7, 2020 at 7:49 AM Anoop John <
> > anoop.hbase@gmail.com
> > > >>>
> > > >>> wrote:
> > > >>>>>>>>> As per the above configs, it looks like Bucket Cache is not
> > > >>> being used.
> > > >>>>>>>>> Only on heap LRU cache in use.
> > > >>>>>>>>
> > > >>>>>>>> True (but it is large enough to hold everything, so I don't
> > think
> > > >>> it
> > > >>>>>>>> matters).
> > > >>>>>>>>
> > > >>>>>>>>> @Jan - Is it possible for you to test with off heap Bucket
> > > >> Cache?
> > > >>>>>>>> Config
> > > >>>>>>>>> bucket cache off heap mode with size ~7.5 GB
> > > >>>>>>>>
> > > >>>>>>>> I did a quick test but it seems not to make a measurable
> > > >>> difference.
> > > >>>>>>>> If anything, it is actually slightly slower even. I see 100%
> hit
> > > >>> ratio
> > > >>>>>>>> in the L1
> > > >>>>>>>> LruBlockCache and effectively also 100% in the L2 BucketCache
> > > >> (hit
> > > >>>>>>>> ratio is not yet at 100% but hits increase with every test and
> > > >>> misses
> > > >>>>>>>> do not).
> > > >>>>>>>>
> > > >>>>>>>> Given that the LruBlockCache was already large enough to cache
> > > >> all
> > > >>> the
> > > >>>>>>>> data anyway, I did not expect this to help either, to be
> honest.
> > > >>>>>>>>
> > > >>>>>>>>> Do you have any DataBlockEncoding enabled on the CF?
> > > >>>>>>>>
> > > >>>>>>>> Yes, FAST_DIFF. But this is of course true in both the tests
> > with
> > > >>>>>>>> hbase2 and hbase1.
> > > >>>>>>>>
> > > >>>>>>>> Jan
> > > >>>>>>>>
> > > >>>>>
> > > >>>>>
> > > >>>>> --
> > > >>>>> Best regards,
> > > >>>>> Andrew
> > > >>>>>
> > > >>>>> Words like orphans lost among the crosstalk, meaning torn from
> > > truth's
> > > >>> decrepit hands
> > > >>>>> - A23, Crosstalk
> > > >>>>
> > > >>>>
> > > >>>> --
> > > >>>> Best regards,
> > > >>>> Andrew
> > > >>>>
> > > >>>> Words like orphans lost among the crosstalk, meaning torn from
> > truth's
> > > >>> decrepit hands
> > > >>>> - A23, Crosstalk
> > > >>>
> > > >>
> > > >
> > > >
> > >
> >
>
>
> --
> Best regards,
> Andrew
>
> Words like orphans lost among the crosstalk, meaning torn from truth's
> decrepit hands
> - A23, Crosstalk
>
Re: HBase 2 slower than HBase 1?
Posted by Andrew Purtell <ap...@apache.org>.
This is a good finding, nice work!
I added a comment on HBASE-24742 that mentions HBASE-24637 on the off
chance they are related, although I suspect more changes are implicated by
the 2.x regression.
On Tue, Jul 14, 2020 at 5:53 PM Bharath Vissapragada <bh...@apache.org>
wrote:
> FYI, we filed this today https://issues.apache.org/jira/browse/HBASE-24742
> .
> We ran into a similar regression when upgrading from 1.3 based branch to
> 1.6 based branch. After some profiling and code analysis we narrowed down
> the code paths.
>
> On Tue, Jul 14, 2020 at 11:38 AM Josh Elser <el...@apache.org> wrote:
>
> > Wow. Great stuff, Andrew!
> >
> > Thank you for compiling and posting it all here. I can only imagine how
> > time-consuming this was.
> >
> > On 6/26/20 1:57 PM, Andrew Purtell wrote:
> > > Hey Anoop, I opened https://issues.apache.org/jira/browse/HBASE-24637
> > and
> > > attached the patches and script used to make the comparison.
> > >
> > > On Fri, Jun 26, 2020 at 2:33 AM Anoop John <an...@gmail.com>
> > wrote:
> > >
> > >> Great investigation Andy. Do you know any Jiras which made changes in
> > SQM?
> > >> Would be great if you can attach your patch which tracks the scan
> > flow. If
> > >> we have a Jira for this issue, can you pls attach?
> > >>
> > >> Anoop
> > >>
> > >> On Fri, Jun 26, 2020 at 1:56 AM Andrew Purtell <
> > andrew.purtell@gmail.com>
> > >> wrote:
> > >>
> > >>> Related, I think I found a bug in branch-1 where we don’t heartbeat
> in
> > >> the
> > >>> filter all case until we switch store files, so scanning a very large
> > >> store
> > >>> file might time out with client defaults. Remarking on this here so I
> > >> don’t
> > >>> forget to follow up.
> > >>>
> > >>>> On Jun 25, 2020, at 12:27 PM, Andrew Purtell <ap...@apache.org>
> > >>> wrote:
> > >>>>
> > >>>>
> > >>>> I repeated this test with pe --filterAll and the results were
> > >> revealing,
> > >>> at least for this case. I also patched in thread local hash map for
> > >> atomic
> > >>> counters that I could update from code paths in SQM, StoreScanner,
> > >>> HFileReader*, and HFileBlock. Because a RPC is processed by a single
> > >>> handler thread I could update counters and accumulate micro-timings
> via
> > >>> System#nanoTime() per RPC and dump them out of CallRunner in some new
> > >> trace
> > >>> logging. I spent a couple of days making sure the instrumentation was
> > >>> placed equivalently in both 1.6 and 2.2 code bases and was producing
> > >>> consistent results. I can provide these patches upon request.
> > >>>>
> > >>>> Again, test tables with one family and 1, 5, 10, 20, 50, and 100
> > >>> distinct column-qualifiers per row. After loading the table I made a
> > >>> snapshot and cloned the snapshot for testing, for both 1.6 and 2.2,
> so
> > >> both
> > >>> versions were tested using the exact same data files on HDFS. I also
> > used
> > >>> the 1.6 version of PE for both, so the only change is on the server
> > (1.6
> > >> vs
> > >>> 2.2 masters and regionservers).
> > >>>>
> > >>>> It appears a refactor to ScanQueryMatcher and friends has disabled
> the
> > >>> ability of filters to provide SKIP hints, which prevents us from
> > >> bypassing
> > >>> version checking (so some extra cost in SQM), and appears to disable
> an
> > >>> optimization that avoids reseeking, leading to a serious and
> > proportional
> > >>> regression in reseek activity and time spent in that code path. So
> for
> > >>> queries that use filters, there can be a substantial regression.
> > >>>>
> > >>>> Other test cases that did not use filters did not show a regression.
> > >>>>
> > >>>> A test case where I used ROW_INDEX_V1 encoding showed an expected
> > >> modest
> > >>> proportional regression in seeking time, due to the fact it is
> > optimized
> > >>> for point queries and not optimized for the full table scan case.
> > >>>>
> > >>>> I will come back here when I understand this better.
> > >>>>
> > >>>> Here are the results for the pe --filterAll case:
> > >>>>
> > >>>>
> > >>>> 1.6.0 c1 2.2.5 c1
> > >>>> 1.6.0 c5 2.2.5 c5
> > >>>> 1.6.0 c10 2.2.5 c10
> > >>>> 1.6.0 c20 2.2.5 c20
> > >>>> 1.6.0 c50 2.2.5 c50
> > >>>> 1.6.0 c100 2.2.5 c100
> > >>>> Counts
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>> (better heartbeating)
> > >>>> (better heartbeating)
> > >>>> (better heartbeating)
> > >>>> (better heartbeating)
> > >>>> (better heartbeating)
> > >>>> rpcs 1 2 200% 2 6 300% 2 10
> > >>> 500% 3 17 567% 4 37 925% 8 72
> > >> 900%
> > >>>> block_reads 11507 11508 100% 57255 57257 100% 114471
> > >>> 114474 100% 230372 230377 100% 578292 578298 100%
> 1157955
> > >>> 1157963 100%
> > >>>> block_unpacks 11507 11508 100% 57255 57257 100% 114471
> > >>> 114474 100% 230372 230377 100% 578292 578298 100%
> 1157955
> > >>> 1157963 100%
> > >>>> seeker_next 10000000 10000000 100% 50000000
> > >>> 50000000 100% 100000000 100000000 100%
> > 200000000
> > >>> 200000000 100% 500000000 500000000 100%
> > >>> 1000000000 1000000000 100%
> > >>>> store_next 10000000 9988268 100% 50000000
> 49940082
> > >>> 100% 100000000 99879401 100% 200000000
> > >>> 199766539 100% 500000000 499414653 100%
> > >>> 1000000000 998836518 100%
> > >>>> store_reseek 1 11733 > ! 2 59924 > ! 8
> > >>> 120607 > ! 6 233467 > ! 10 585357 > ! 8
> > >>> 1163490 > !
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>> cells_matched 20000000 20000000 100% 60000000
> > >>> 60000000 100% 110000000 110000000 100%
> > 210000000
> > >>> 210000000 100% 510000000 510000000 100%
> > >>> 1010000000 1010000000 100%
> > >>>> column_hint_include 10000000 10000000 100%
> 50000000
> > >>> 50000000 100% 100000000 100000000 100%
> > >>> 200000000 200000000 100% 500000000 500000000
> > >>> 100% 1000000000 1000000000 100%
> > >>>> filter_hint_skip 10000000 10000000 100%
> 50000000
> > >>> 50000000 100% 100000000 100000000 100%
> > >>> 200000000 200000000 100% 500000000 500000000
> > >>> 100% 1000000000 1000000000 100%
> > >>>> sqm_hint_done 9999999 9999999 100% 9999998 9999998 100%
> 9999998
> > >>> 9999998 100% 9999997 9999997 100% 9999996 9999996 100%
> 9999992
> > >>> 9999992 100%
> > >>>> sqm_hint_seek_next_col 1 0 0% 2
> 40000002
> > >>> > ! 2 90000002 > ! 3 190000003
> > > !
> > >>> 4 490000004 > ! 8 990000008 > !
> > >>>> sqm_hint_seek_next_row 0 10000000 > ! 2
> > >>> 10000000 > ! 0 10000000 > ! 0
> > 10000000
> > >>> > ! 0 10000000 > ! 0 10000000
> > > !
> > >>>> sqm_hint_skip 10000000 0 0% 50000000 0
> > >>> 0% 100000000 0 0% 200000000 0 0%
> > >>> 500000000 0 0% 1000000000 0 0%
> > >>>> versions_hint_include_and_seek_next_col 0 0 0%
> > 0
> > >>> 40000000 > ! 0 90000000 > ! 0
> > >>> 190000000 > ! 0 490000000 > ! 0
> > >> 990000000
> > >>> > !
> > >>>> versions_hint_include_and_seek_next_row 0 0 0%
> > 0
> > >>> 10000000 > ! 0 10000000 > ! 0
> > >>> 10000000 > ! 0 10000000 > ! 0
> > 10000000
> > >>> > !
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>> Times
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>> block_read_ms 174.12 215.96 124% 683.78 883.02 129%
> 1724.66
> > >>> 1937.87 112% 3199.93 3470.92 108% 7582.96 7941.45 105%
> > 14701.52
> > >>> 16022.57 109%
> > >>>> block_unpack_ms 0.63 0.62 99% 2.35 2.35 100%
> > >>> 4.36 4.56 105% 9.10 8.30 91% 21.59 22.01 102%
> > >>> 40.97 40.93 100%
> > >>>> seeker_next_ms 1073.45 1053.51 98% 4452.52 4728.96 106%
> > >>> 9359.61 9706.06 104% 18879.28 18330.93 97%
> > 47664.95
> > >>> 46404.26 97% 96511.83 92121.30 95%
> > >>>> store_next_ms 2651.11 2423.27 91% 12048.64 11398.63
> > >>> 95% 24833.68 23586.20 95% 48493.26
> > 46574.38
> > >>> 96% 120786.00 115603.00 96% 240627.00
> > >>> 227945.00 95%
> > >>>> store_reseek_ms 2.71 62.17 2297% 10.93 233.67 2139%
> > >>> 10.88 401.88 3693% 13.98 783.18 5601% 22.26 1939.28
> 8714%
> > >>> 24.32 4065.25 16714%
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>> Rows=10000000
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>> ValueSize=20
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>> BlockEncoding=FAST_DIFF
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>> Compress=NONE
> > >>>> Filter=ALL
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>>
> > >>>> On Thu, Jun 11, 2020 at 5:08 PM Andrew Purtell <apurtell@apache.org
> >
> > >>> wrote:
> > >>>>> I used PE to generate 10M row tables with one family with either 1,
> > >> 10,
> > >>> 20, 50, or 100 values per row (unique column-qualifiers). An increase
> > in
> > >>> wall clock time was noticeable, for example:
> > >>>>>
> > >>>>> 1.6.0
> > >>>>>
> > >>>>> time ./bin/hbase pe --rows=5000000 --table=TestTable_f1_c20
> > >>> --columns=20 --nomapred scan 2
> > >>>>> real 1m20.179s
> > >>>>> user 0m45.470s
> > >>>>> sys 0m16.572s
> > >>>>>
> > >>>>> 2.2.5
> > >>>>>
> > >>>>> time ./bin/hbase pe --rows=5000000 --table=TestTable_f1_c20
> > >>> --columns=20 --nomapred scan 2
> > >>>>> real 1m31.016s
> > >>>>> user 0m48.658s
> > >>>>> sys 0m16.965s
> > >>>>>
> > >>>>> It didnt really make a difference if I used 1 thread or 4 or 10,
> the
> > >>> delta was about the same, proportionally. I picked two threads in the
> > end
> > >>> so I'd have enough time to launch async-profiler twice in another
> > shell,
> > >> to
> > >>> capture flamegraph and call tree output, respectively. async-profiler
> > >>> captured 10 seconds at steady state per test case. Upon first
> > inspection
> > >>> what jumps out is an increasing proportion of CPU time spent in GC in
> > >> 2.2.5
> > >>> vs 1.6.0. The difference increases as the number of column families
> > >>> increase. There is little apparent difference at 1 column family,
> but a
> > >> 2x
> > >>> or more difference at 20 columns, and a 10x or more difference at 100
> > >>> columns, eyeballing the charts, flipping back and forth between
> browser
> > >>> windows. This seems more than coincidental but obviously calls for
> > >> capture
> > >>> and analysis of GC trace, with JFR. Will do that next.
> > >>>>>
> > >>>>> JVM: openjdk version "1.8.0_232" OpenJDK Runtime Environment (Zulu
> > >>> 8.42.0.21-CA-macosx) (build 1.8.0_232-b18) OpenJDK 64-Bit Server VM
> > (Zulu
> > >>> 8.42.0.21-CA-macosx) (build 25.232-b18, mixed mode)
> > >>>>>
> > >>>>> Regionserver JVM flags: -Xms10g -Xmx10g -XX:+UseG1GC
> > >>> -XX:+AlwaysPreTouch -XX:+UseNUMA -XX:-UseBiasedLocking
> > >>> -XX:+ParallelRefProcEnabled
> > >>>>>
> > >>>>>
> > >>>>> On Thu, Jun 11, 2020 at 7:06 AM Jan Van Besien <ja...@ngdata.com>
> > >>> wrote:
> > >>>>>> This is promising, thanks a lot. Testing with hbase 2.2.5 shows an
> > >>>>>> improvement, but we're not there yet.
> > >>>>>>
> > >>>>>> As reported earlier, hbase 2.1.0 was about 60% slower than hbase
> > >> 1.2.0
> > >>>>>> in a test that simply scans all the regions in parallel without
> any
> > >>>>>> filter. A test with hbase 2.2.5 shows it to be about 40% slower
> than
> > >>>>>> 1.2.0. So that is better than 2.1.0, but still substantially
> slower
> > >>>>>> than what hbase 1.2.0 was.
> > >>>>>>
> > >>>>>> As before, I tested this both on a 3 node cluster as well as with
> a
> > >>>>>> unit test using HBaseTestingUtility. Both tests show very similar
> > >>>>>> relative differences.
> > >>>>>>
> > >>>>>> Jan
> > >>>>>>
> > >>>>>> On Thu, Jun 11, 2020 at 2:16 PM Anoop John <anoop.hbase@gmail.com
> >
> > >>> wrote:
> > >>>>>>>
> > >>>>>>> In another mail thread Zheng Hu brought up an important Jra fix
> > >>>>>>> https://issues.apache.org/jira/browse/HBASE-21657
> > >>>>>>> Can u pls check with this once?
> > >>>>>>>
> > >>>>>>> Anoop
> > >>>>>>>
> > >>>>>>>
> > >>>>>>> On Tue, Jun 9, 2020 at 8:08 PM Jan Van Besien <ja...@ngdata.com>
> > >>> wrote:
> > >>>>>>>
> > >>>>>>>> On Sun, Jun 7, 2020 at 7:49 AM Anoop John <
> anoop.hbase@gmail.com
> > >>>
> > >>> wrote:
> > >>>>>>>>> As per the above configs, it looks like Bucket Cache is not
> > >>> being used.
> > >>>>>>>>> Only on heap LRU cache in use.
> > >>>>>>>>
> > >>>>>>>> True (but it is large enough to hold everything, so I don't
> think
> > >>> it
> > >>>>>>>> matters).
> > >>>>>>>>
> > >>>>>>>>> @Jan - Is it possible for you to test with off heap Bucket
> > >> Cache?
> > >>>>>>>> Config
> > >>>>>>>>> bucket cache off heap mode with size ~7.5 GB
> > >>>>>>>>
> > >>>>>>>> I did a quick test but it seems not to make a measurable
> > >>> difference.
> > >>>>>>>> If anything, it is actually slightly slower even. I see 100% hit
> > >>> ratio
> > >>>>>>>> in the L1
> > >>>>>>>> LruBlockCache and effectively also 100% in the L2 BucketCache
> > >> (hit
> > >>>>>>>> ratio is not yet at 100% but hits increase with every test and
> > >>> misses
> > >>>>>>>> do not).
> > >>>>>>>>
> > >>>>>>>> Given that the LruBlockCache was already large enough to cache
> > >> all
> > >>> the
> > >>>>>>>> data anyway, I did not expect this to help either, to be honest.
> > >>>>>>>>
> > >>>>>>>>> Do you have any DataBlockEncoding enabled on the CF?
> > >>>>>>>>
> > >>>>>>>> Yes, FAST_DIFF. But this is of course true in both the tests
> with
> > >>>>>>>> hbase2 and hbase1.
> > >>>>>>>>
> > >>>>>>>> Jan
> > >>>>>>>>
> > >>>>>
> > >>>>>
> > >>>>> --
> > >>>>> Best regards,
> > >>>>> Andrew
> > >>>>>
> > >>>>> Words like orphans lost among the crosstalk, meaning torn from
> > truth's
> > >>> decrepit hands
> > >>>>> - A23, Crosstalk
> > >>>>
> > >>>>
> > >>>> --
> > >>>> Best regards,
> > >>>> Andrew
> > >>>>
> > >>>> Words like orphans lost among the crosstalk, meaning torn from
> truth's
> > >>> decrepit hands
> > >>>> - A23, Crosstalk
> > >>>
> > >>
> > >
> > >
> >
>
--
Best regards,
Andrew
Words like orphans lost among the crosstalk, meaning torn from truth's
decrepit hands
- A23, Crosstalk
Re: HBase 2 slower than HBase 1?
Posted by Bharath Vissapragada <bh...@apache.org>.
FYI, we filed this today https://issues.apache.org/jira/browse/HBASE-24742.
We ran into a similar regression when upgrading from 1.3 based branch to
1.6 based branch. After some profiling and code analysis we narrowed down
the code paths.
On Tue, Jul 14, 2020 at 11:38 AM Josh Elser <el...@apache.org> wrote:
> Wow. Great stuff, Andrew!
>
> Thank you for compiling and posting it all here. I can only imagine how
> time-consuming this was.
>
> On 6/26/20 1:57 PM, Andrew Purtell wrote:
> > Hey Anoop, I opened https://issues.apache.org/jira/browse/HBASE-24637
> and
> > attached the patches and script used to make the comparison.
> >
> > On Fri, Jun 26, 2020 at 2:33 AM Anoop John <an...@gmail.com>
> wrote:
> >
> >> Great investigation Andy. Do you know any Jiras which made changes in
> SQM?
> >> Would be great if you can attach your patch which tracks the scan
> flow. If
> >> we have a Jira for this issue, can you pls attach?
> >>
> >> Anoop
> >>
> >> On Fri, Jun 26, 2020 at 1:56 AM Andrew Purtell <
> andrew.purtell@gmail.com>
> >> wrote:
> >>
> >>> Related, I think I found a bug in branch-1 where we don’t heartbeat in
> >> the
> >>> filter all case until we switch store files, so scanning a very large
> >> store
> >>> file might time out with client defaults. Remarking on this here so I
> >> don’t
> >>> forget to follow up.
> >>>
> >>>> On Jun 25, 2020, at 12:27 PM, Andrew Purtell <ap...@apache.org>
> >>> wrote:
> >>>>
> >>>>
> >>>> I repeated this test with pe --filterAll and the results were
> >> revealing,
> >>> at least for this case. I also patched in thread local hash map for
> >> atomic
> >>> counters that I could update from code paths in SQM, StoreScanner,
> >>> HFileReader*, and HFileBlock. Because a RPC is processed by a single
> >>> handler thread I could update counters and accumulate micro-timings via
> >>> System#nanoTime() per RPC and dump them out of CallRunner in some new
> >> trace
> >>> logging. I spent a couple of days making sure the instrumentation was
> >>> placed equivalently in both 1.6 and 2.2 code bases and was producing
> >>> consistent results. I can provide these patches upon request.
> >>>>
> >>>> Again, test tables with one family and 1, 5, 10, 20, 50, and 100
> >>> distinct column-qualifiers per row. After loading the table I made a
> >>> snapshot and cloned the snapshot for testing, for both 1.6 and 2.2, so
> >> both
> >>> versions were tested using the exact same data files on HDFS. I also
> used
> >>> the 1.6 version of PE for both, so the only change is on the server
> (1.6
> >> vs
> >>> 2.2 masters and regionservers).
> >>>>
> >>>> It appears a refactor to ScanQueryMatcher and friends has disabled the
> >>> ability of filters to provide SKIP hints, which prevents us from
> >> bypassing
> >>> version checking (so some extra cost in SQM), and appears to disable an
> >>> optimization that avoids reseeking, leading to a serious and
> proportional
> >>> regression in reseek activity and time spent in that code path. So for
> >>> queries that use filters, there can be a substantial regression.
> >>>>
> >>>> Other test cases that did not use filters did not show a regression.
> >>>>
> >>>> A test case where I used ROW_INDEX_V1 encoding showed an expected
> >> modest
> >>> proportional regression in seeking time, due to the fact it is
> optimized
> >>> for point queries and not optimized for the full table scan case.
> >>>>
> >>>> I will come back here when I understand this better.
> >>>>
> >>>> Here are the results for the pe --filterAll case:
> >>>>
> >>>>
> >>>> 1.6.0 c1 2.2.5 c1
> >>>> 1.6.0 c5 2.2.5 c5
> >>>> 1.6.0 c10 2.2.5 c10
> >>>> 1.6.0 c20 2.2.5 c20
> >>>> 1.6.0 c50 2.2.5 c50
> >>>> 1.6.0 c100 2.2.5 c100
> >>>> Counts
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> (better heartbeating)
> >>>> (better heartbeating)
> >>>> (better heartbeating)
> >>>> (better heartbeating)
> >>>> (better heartbeating)
> >>>> rpcs 1 2 200% 2 6 300% 2 10
> >>> 500% 3 17 567% 4 37 925% 8 72
> >> 900%
> >>>> block_reads 11507 11508 100% 57255 57257 100% 114471
> >>> 114474 100% 230372 230377 100% 578292 578298 100% 1157955
> >>> 1157963 100%
> >>>> block_unpacks 11507 11508 100% 57255 57257 100% 114471
> >>> 114474 100% 230372 230377 100% 578292 578298 100% 1157955
> >>> 1157963 100%
> >>>> seeker_next 10000000 10000000 100% 50000000
> >>> 50000000 100% 100000000 100000000 100%
> 200000000
> >>> 200000000 100% 500000000 500000000 100%
> >>> 1000000000 1000000000 100%
> >>>> store_next 10000000 9988268 100% 50000000 49940082
> >>> 100% 100000000 99879401 100% 200000000
> >>> 199766539 100% 500000000 499414653 100%
> >>> 1000000000 998836518 100%
> >>>> store_reseek 1 11733 > ! 2 59924 > ! 8
> >>> 120607 > ! 6 233467 > ! 10 585357 > ! 8
> >>> 1163490 > !
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> cells_matched 20000000 20000000 100% 60000000
> >>> 60000000 100% 110000000 110000000 100%
> 210000000
> >>> 210000000 100% 510000000 510000000 100%
> >>> 1010000000 1010000000 100%
> >>>> column_hint_include 10000000 10000000 100% 50000000
> >>> 50000000 100% 100000000 100000000 100%
> >>> 200000000 200000000 100% 500000000 500000000
> >>> 100% 1000000000 1000000000 100%
> >>>> filter_hint_skip 10000000 10000000 100% 50000000
> >>> 50000000 100% 100000000 100000000 100%
> >>> 200000000 200000000 100% 500000000 500000000
> >>> 100% 1000000000 1000000000 100%
> >>>> sqm_hint_done 9999999 9999999 100% 9999998 9999998 100% 9999998
> >>> 9999998 100% 9999997 9999997 100% 9999996 9999996 100% 9999992
> >>> 9999992 100%
> >>>> sqm_hint_seek_next_col 1 0 0% 2 40000002
> >>> > ! 2 90000002 > ! 3 190000003
> > !
> >>> 4 490000004 > ! 8 990000008 > !
> >>>> sqm_hint_seek_next_row 0 10000000 > ! 2
> >>> 10000000 > ! 0 10000000 > ! 0
> 10000000
> >>> > ! 0 10000000 > ! 0 10000000
> > !
> >>>> sqm_hint_skip 10000000 0 0% 50000000 0
> >>> 0% 100000000 0 0% 200000000 0 0%
> >>> 500000000 0 0% 1000000000 0 0%
> >>>> versions_hint_include_and_seek_next_col 0 0 0%
> 0
> >>> 40000000 > ! 0 90000000 > ! 0
> >>> 190000000 > ! 0 490000000 > ! 0
> >> 990000000
> >>> > !
> >>>> versions_hint_include_and_seek_next_row 0 0 0%
> 0
> >>> 10000000 > ! 0 10000000 > ! 0
> >>> 10000000 > ! 0 10000000 > ! 0
> 10000000
> >>> > !
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> Times
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> block_read_ms 174.12 215.96 124% 683.78 883.02 129% 1724.66
> >>> 1937.87 112% 3199.93 3470.92 108% 7582.96 7941.45 105%
> 14701.52
> >>> 16022.57 109%
> >>>> block_unpack_ms 0.63 0.62 99% 2.35 2.35 100%
> >>> 4.36 4.56 105% 9.10 8.30 91% 21.59 22.01 102%
> >>> 40.97 40.93 100%
> >>>> seeker_next_ms 1073.45 1053.51 98% 4452.52 4728.96 106%
> >>> 9359.61 9706.06 104% 18879.28 18330.93 97%
> 47664.95
> >>> 46404.26 97% 96511.83 92121.30 95%
> >>>> store_next_ms 2651.11 2423.27 91% 12048.64 11398.63
> >>> 95% 24833.68 23586.20 95% 48493.26
> 46574.38
> >>> 96% 120786.00 115603.00 96% 240627.00
> >>> 227945.00 95%
> >>>> store_reseek_ms 2.71 62.17 2297% 10.93 233.67 2139%
> >>> 10.88 401.88 3693% 13.98 783.18 5601% 22.26 1939.28 8714%
> >>> 24.32 4065.25 16714%
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> Rows=10000000
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> ValueSize=20
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> BlockEncoding=FAST_DIFF
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> Compress=NONE
> >>>> Filter=ALL
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> On Thu, Jun 11, 2020 at 5:08 PM Andrew Purtell <ap...@apache.org>
> >>> wrote:
> >>>>> I used PE to generate 10M row tables with one family with either 1,
> >> 10,
> >>> 20, 50, or 100 values per row (unique column-qualifiers). An increase
> in
> >>> wall clock time was noticeable, for example:
> >>>>>
> >>>>> 1.6.0
> >>>>>
> >>>>> time ./bin/hbase pe --rows=5000000 --table=TestTable_f1_c20
> >>> --columns=20 --nomapred scan 2
> >>>>> real 1m20.179s
> >>>>> user 0m45.470s
> >>>>> sys 0m16.572s
> >>>>>
> >>>>> 2.2.5
> >>>>>
> >>>>> time ./bin/hbase pe --rows=5000000 --table=TestTable_f1_c20
> >>> --columns=20 --nomapred scan 2
> >>>>> real 1m31.016s
> >>>>> user 0m48.658s
> >>>>> sys 0m16.965s
> >>>>>
> >>>>> It didnt really make a difference if I used 1 thread or 4 or 10, the
> >>> delta was about the same, proportionally. I picked two threads in the
> end
> >>> so I'd have enough time to launch async-profiler twice in another
> shell,
> >> to
> >>> capture flamegraph and call tree output, respectively. async-profiler
> >>> captured 10 seconds at steady state per test case. Upon first
> inspection
> >>> what jumps out is an increasing proportion of CPU time spent in GC in
> >> 2.2.5
> >>> vs 1.6.0. The difference increases as the number of column families
> >>> increase. There is little apparent difference at 1 column family, but a
> >> 2x
> >>> or more difference at 20 columns, and a 10x or more difference at 100
> >>> columns, eyeballing the charts, flipping back and forth between browser
> >>> windows. This seems more than coincidental but obviously calls for
> >> capture
> >>> and analysis of GC trace, with JFR. Will do that next.
> >>>>>
> >>>>> JVM: openjdk version "1.8.0_232" OpenJDK Runtime Environment (Zulu
> >>> 8.42.0.21-CA-macosx) (build 1.8.0_232-b18) OpenJDK 64-Bit Server VM
> (Zulu
> >>> 8.42.0.21-CA-macosx) (build 25.232-b18, mixed mode)
> >>>>>
> >>>>> Regionserver JVM flags: -Xms10g -Xmx10g -XX:+UseG1GC
> >>> -XX:+AlwaysPreTouch -XX:+UseNUMA -XX:-UseBiasedLocking
> >>> -XX:+ParallelRefProcEnabled
> >>>>>
> >>>>>
> >>>>> On Thu, Jun 11, 2020 at 7:06 AM Jan Van Besien <ja...@ngdata.com>
> >>> wrote:
> >>>>>> This is promising, thanks a lot. Testing with hbase 2.2.5 shows an
> >>>>>> improvement, but we're not there yet.
> >>>>>>
> >>>>>> As reported earlier, hbase 2.1.0 was about 60% slower than hbase
> >> 1.2.0
> >>>>>> in a test that simply scans all the regions in parallel without any
> >>>>>> filter. A test with hbase 2.2.5 shows it to be about 40% slower than
> >>>>>> 1.2.0. So that is better than 2.1.0, but still substantially slower
> >>>>>> than what hbase 1.2.0 was.
> >>>>>>
> >>>>>> As before, I tested this both on a 3 node cluster as well as with a
> >>>>>> unit test using HBaseTestingUtility. Both tests show very similar
> >>>>>> relative differences.
> >>>>>>
> >>>>>> Jan
> >>>>>>
> >>>>>> On Thu, Jun 11, 2020 at 2:16 PM Anoop John <an...@gmail.com>
> >>> wrote:
> >>>>>>>
> >>>>>>> In another mail thread Zheng Hu brought up an important Jra fix
> >>>>>>> https://issues.apache.org/jira/browse/HBASE-21657
> >>>>>>> Can u pls check with this once?
> >>>>>>>
> >>>>>>> Anoop
> >>>>>>>
> >>>>>>>
> >>>>>>> On Tue, Jun 9, 2020 at 8:08 PM Jan Van Besien <ja...@ngdata.com>
> >>> wrote:
> >>>>>>>
> >>>>>>>> On Sun, Jun 7, 2020 at 7:49 AM Anoop John <anoop.hbase@gmail.com
> >>>
> >>> wrote:
> >>>>>>>>> As per the above configs, it looks like Bucket Cache is not
> >>> being used.
> >>>>>>>>> Only on heap LRU cache in use.
> >>>>>>>>
> >>>>>>>> True (but it is large enough to hold everything, so I don't think
> >>> it
> >>>>>>>> matters).
> >>>>>>>>
> >>>>>>>>> @Jan - Is it possible for you to test with off heap Bucket
> >> Cache?
> >>>>>>>> Config
> >>>>>>>>> bucket cache off heap mode with size ~7.5 GB
> >>>>>>>>
> >>>>>>>> I did a quick test but it seems not to make a measurable
> >>> difference.
> >>>>>>>> If anything, it is actually slightly slower even. I see 100% hit
> >>> ratio
> >>>>>>>> in the L1
> >>>>>>>> LruBlockCache and effectively also 100% in the L2 BucketCache
> >> (hit
> >>>>>>>> ratio is not yet at 100% but hits increase with every test and
> >>> misses
> >>>>>>>> do not).
> >>>>>>>>
> >>>>>>>> Given that the LruBlockCache was already large enough to cache
> >> all
> >>> the
> >>>>>>>> data anyway, I did not expect this to help either, to be honest.
> >>>>>>>>
> >>>>>>>>> Do you have any DataBlockEncoding enabled on the CF?
> >>>>>>>>
> >>>>>>>> Yes, FAST_DIFF. But this is of course true in both the tests with
> >>>>>>>> hbase2 and hbase1.
> >>>>>>>>
> >>>>>>>> Jan
> >>>>>>>>
> >>>>>
> >>>>>
> >>>>> --
> >>>>> Best regards,
> >>>>> Andrew
> >>>>>
> >>>>> Words like orphans lost among the crosstalk, meaning torn from
> truth's
> >>> decrepit hands
> >>>>> - A23, Crosstalk
> >>>>
> >>>>
> >>>> --
> >>>> Best regards,
> >>>> Andrew
> >>>>
> >>>> Words like orphans lost among the crosstalk, meaning torn from truth's
> >>> decrepit hands
> >>>> - A23, Crosstalk
> >>>
> >>
> >
> >
>
Re: HBase 2 slower than HBase 1?
Posted by Andrew Purtell <ap...@apache.org>.
I went out on vacation (and am still out) before tracking this down. If you
are waiting for me to make more progress with HBASE-24637, I can do that in
a couple of weeks, Anyone is welcome to step in sooner. ..
On Tue, Jul 14, 2020 at 11:38 AM Josh Elser <el...@apache.org> wrote:
> Wow. Great stuff, Andrew!
>
> Thank you for compiling and posting it all here. I can only imagine how
> time-consuming this was.
>
> On 6/26/20 1:57 PM, Andrew Purtell wrote:
> > Hey Anoop, I opened https://issues.apache.org/jira/browse/HBASE-24637
> and
> > attached the patches and script used to make the comparison.
> >
> > On Fri, Jun 26, 2020 at 2:33 AM Anoop John <an...@gmail.com>
> wrote:
> >
> >> Great investigation Andy. Do you know any Jiras which made changes in
> SQM?
> >> Would be great if you can attach your patch which tracks the scan
> flow. If
> >> we have a Jira for this issue, can you pls attach?
> >>
> >> Anoop
> >>
> >> On Fri, Jun 26, 2020 at 1:56 AM Andrew Purtell <
> andrew.purtell@gmail.com>
> >> wrote:
> >>
> >>> Related, I think I found a bug in branch-1 where we don’t heartbeat in
> >> the
> >>> filter all case until we switch store files, so scanning a very large
> >> store
> >>> file might time out with client defaults. Remarking on this here so I
> >> don’t
> >>> forget to follow up.
> >>>
> >>>> On Jun 25, 2020, at 12:27 PM, Andrew Purtell <ap...@apache.org>
> >>> wrote:
> >>>>
> >>>>
> >>>> I repeated this test with pe --filterAll and the results were
> >> revealing,
> >>> at least for this case. I also patched in thread local hash map for
> >> atomic
> >>> counters that I could update from code paths in SQM, StoreScanner,
> >>> HFileReader*, and HFileBlock. Because a RPC is processed by a single
> >>> handler thread I could update counters and accumulate micro-timings via
> >>> System#nanoTime() per RPC and dump them out of CallRunner in some new
> >> trace
> >>> logging. I spent a couple of days making sure the instrumentation was
> >>> placed equivalently in both 1.6 and 2.2 code bases and was producing
> >>> consistent results. I can provide these patches upon request.
> >>>>
> >>>> Again, test tables with one family and 1, 5, 10, 20, 50, and 100
> >>> distinct column-qualifiers per row. After loading the table I made a
> >>> snapshot and cloned the snapshot for testing, for both 1.6 and 2.2, so
> >> both
> >>> versions were tested using the exact same data files on HDFS. I also
> used
> >>> the 1.6 version of PE for both, so the only change is on the server
> (1.6
> >> vs
> >>> 2.2 masters and regionservers).
> >>>>
> >>>> It appears a refactor to ScanQueryMatcher and friends has disabled the
> >>> ability of filters to provide SKIP hints, which prevents us from
> >> bypassing
> >>> version checking (so some extra cost in SQM), and appears to disable an
> >>> optimization that avoids reseeking, leading to a serious and
> proportional
> >>> regression in reseek activity and time spent in that code path. So for
> >>> queries that use filters, there can be a substantial regression.
> >>>>
> >>>> Other test cases that did not use filters did not show a regression.
> >>>>
> >>>> A test case where I used ROW_INDEX_V1 encoding showed an expected
> >> modest
> >>> proportional regression in seeking time, due to the fact it is
> optimized
> >>> for point queries and not optimized for the full table scan case.
> >>>>
> >>>> I will come back here when I understand this better.
> >>>>
> >>>> Here are the results for the pe --filterAll case:
> >>>>
> >>>>
> >>>> 1.6.0 c1 2.2.5 c1
> >>>> 1.6.0 c5 2.2.5 c5
> >>>> 1.6.0 c10 2.2.5 c10
> >>>> 1.6.0 c20 2.2.5 c20
> >>>> 1.6.0 c50 2.2.5 c50
> >>>> 1.6.0 c100 2.2.5 c100
> >>>> Counts
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> (better heartbeating)
> >>>> (better heartbeating)
> >>>> (better heartbeating)
> >>>> (better heartbeating)
> >>>> (better heartbeating)
> >>>> rpcs 1 2 200% 2 6 300% 2 10
> >>> 500% 3 17 567% 4 37 925% 8 72
> >> 900%
> >>>> block_reads 11507 11508 100% 57255 57257 100% 114471
> >>> 114474 100% 230372 230377 100% 578292 578298 100% 1157955
> >>> 1157963 100%
> >>>> block_unpacks 11507 11508 100% 57255 57257 100% 114471
> >>> 114474 100% 230372 230377 100% 578292 578298 100% 1157955
> >>> 1157963 100%
> >>>> seeker_next 10000000 10000000 100% 50000000
> >>> 50000000 100% 100000000 100000000 100%
> 200000000
> >>> 200000000 100% 500000000 500000000 100%
> >>> 1000000000 1000000000 100%
> >>>> store_next 10000000 9988268 100% 50000000 49940082
> >>> 100% 100000000 99879401 100% 200000000
> >>> 199766539 100% 500000000 499414653 100%
> >>> 1000000000 998836518 100%
> >>>> store_reseek 1 11733 > ! 2 59924 > ! 8
> >>> 120607 > ! 6 233467 > ! 10 585357 > ! 8
> >>> 1163490 > !
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> cells_matched 20000000 20000000 100% 60000000
> >>> 60000000 100% 110000000 110000000 100%
> 210000000
> >>> 210000000 100% 510000000 510000000 100%
> >>> 1010000000 1010000000 100%
> >>>> column_hint_include 10000000 10000000 100% 50000000
> >>> 50000000 100% 100000000 100000000 100%
> >>> 200000000 200000000 100% 500000000 500000000
> >>> 100% 1000000000 1000000000 100%
> >>>> filter_hint_skip 10000000 10000000 100% 50000000
> >>> 50000000 100% 100000000 100000000 100%
> >>> 200000000 200000000 100% 500000000 500000000
> >>> 100% 1000000000 1000000000 100%
> >>>> sqm_hint_done 9999999 9999999 100% 9999998 9999998 100% 9999998
> >>> 9999998 100% 9999997 9999997 100% 9999996 9999996 100% 9999992
> >>> 9999992 100%
> >>>> sqm_hint_seek_next_col 1 0 0% 2 40000002
> >>> > ! 2 90000002 > ! 3 190000003
> > !
> >>> 4 490000004 > ! 8 990000008 > !
> >>>> sqm_hint_seek_next_row 0 10000000 > ! 2
> >>> 10000000 > ! 0 10000000 > ! 0
> 10000000
> >>> > ! 0 10000000 > ! 0 10000000
> > !
> >>>> sqm_hint_skip 10000000 0 0% 50000000 0
> >>> 0% 100000000 0 0% 200000000 0 0%
> >>> 500000000 0 0% 1000000000 0 0%
> >>>> versions_hint_include_and_seek_next_col 0 0 0%
> 0
> >>> 40000000 > ! 0 90000000 > ! 0
> >>> 190000000 > ! 0 490000000 > ! 0
> >> 990000000
> >>> > !
> >>>> versions_hint_include_and_seek_next_row 0 0 0%
> 0
> >>> 10000000 > ! 0 10000000 > ! 0
> >>> 10000000 > ! 0 10000000 > ! 0
> 10000000
> >>> > !
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> Times
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> block_read_ms 174.12 215.96 124% 683.78 883.02 129% 1724.66
> >>> 1937.87 112% 3199.93 3470.92 108% 7582.96 7941.45 105%
> 14701.52
> >>> 16022.57 109%
> >>>> block_unpack_ms 0.63 0.62 99% 2.35 2.35 100%
> >>> 4.36 4.56 105% 9.10 8.30 91% 21.59 22.01 102%
> >>> 40.97 40.93 100%
> >>>> seeker_next_ms 1073.45 1053.51 98% 4452.52 4728.96 106%
> >>> 9359.61 9706.06 104% 18879.28 18330.93 97%
> 47664.95
> >>> 46404.26 97% 96511.83 92121.30 95%
> >>>> store_next_ms 2651.11 2423.27 91% 12048.64 11398.63
> >>> 95% 24833.68 23586.20 95% 48493.26
> 46574.38
> >>> 96% 120786.00 115603.00 96% 240627.00
> >>> 227945.00 95%
> >>>> store_reseek_ms 2.71 62.17 2297% 10.93 233.67 2139%
> >>> 10.88 401.88 3693% 13.98 783.18 5601% 22.26 1939.28 8714%
> >>> 24.32 4065.25 16714%
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> Rows=10000000
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> ValueSize=20
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> BlockEncoding=FAST_DIFF
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> Compress=NONE
> >>>> Filter=ALL
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> On Thu, Jun 11, 2020 at 5:08 PM Andrew Purtell <ap...@apache.org>
> >>> wrote:
> >>>>> I used PE to generate 10M row tables with one family with either 1,
> >> 10,
> >>> 20, 50, or 100 values per row (unique column-qualifiers). An increase
> in
> >>> wall clock time was noticeable, for example:
> >>>>>
> >>>>> 1.6.0
> >>>>>
> >>>>> time ./bin/hbase pe --rows=5000000 --table=TestTable_f1_c20
> >>> --columns=20 --nomapred scan 2
> >>>>> real 1m20.179s
> >>>>> user 0m45.470s
> >>>>> sys 0m16.572s
> >>>>>
> >>>>> 2.2.5
> >>>>>
> >>>>> time ./bin/hbase pe --rows=5000000 --table=TestTable_f1_c20
> >>> --columns=20 --nomapred scan 2
> >>>>> real 1m31.016s
> >>>>> user 0m48.658s
> >>>>> sys 0m16.965s
> >>>>>
> >>>>> It didnt really make a difference if I used 1 thread or 4 or 10, the
> >>> delta was about the same, proportionally. I picked two threads in the
> end
> >>> so I'd have enough time to launch async-profiler twice in another
> shell,
> >> to
> >>> capture flamegraph and call tree output, respectively. async-profiler
> >>> captured 10 seconds at steady state per test case. Upon first
> inspection
> >>> what jumps out is an increasing proportion of CPU time spent in GC in
> >> 2.2.5
> >>> vs 1.6.0. The difference increases as the number of column families
> >>> increase. There is little apparent difference at 1 column family, but a
> >> 2x
> >>> or more difference at 20 columns, and a 10x or more difference at 100
> >>> columns, eyeballing the charts, flipping back and forth between browser
> >>> windows. This seems more than coincidental but obviously calls for
> >> capture
> >>> and analysis of GC trace, with JFR. Will do that next.
> >>>>>
> >>>>> JVM: openjdk version "1.8.0_232" OpenJDK Runtime Environment (Zulu
> >>> 8.42.0.21-CA-macosx) (build 1.8.0_232-b18) OpenJDK 64-Bit Server VM
> (Zulu
> >>> 8.42.0.21-CA-macosx) (build 25.232-b18, mixed mode)
> >>>>>
> >>>>> Regionserver JVM flags: -Xms10g -Xmx10g -XX:+UseG1GC
> >>> -XX:+AlwaysPreTouch -XX:+UseNUMA -XX:-UseBiasedLocking
> >>> -XX:+ParallelRefProcEnabled
> >>>>>
> >>>>>
> >>>>> On Thu, Jun 11, 2020 at 7:06 AM Jan Van Besien <ja...@ngdata.com>
> >>> wrote:
> >>>>>> This is promising, thanks a lot. Testing with hbase 2.2.5 shows an
> >>>>>> improvement, but we're not there yet.
> >>>>>>
> >>>>>> As reported earlier, hbase 2.1.0 was about 60% slower than hbase
> >> 1.2.0
> >>>>>> in a test that simply scans all the regions in parallel without any
> >>>>>> filter. A test with hbase 2.2.5 shows it to be about 40% slower than
> >>>>>> 1.2.0. So that is better than 2.1.0, but still substantially slower
> >>>>>> than what hbase 1.2.0 was.
> >>>>>>
> >>>>>> As before, I tested this both on a 3 node cluster as well as with a
> >>>>>> unit test using HBaseTestingUtility. Both tests show very similar
> >>>>>> relative differences.
> >>>>>>
> >>>>>> Jan
> >>>>>>
> >>>>>> On Thu, Jun 11, 2020 at 2:16 PM Anoop John <an...@gmail.com>
> >>> wrote:
> >>>>>>>
> >>>>>>> In another mail thread Zheng Hu brought up an important Jra fix
> >>>>>>> https://issues.apache.org/jira/browse/HBASE-21657
> >>>>>>> Can u pls check with this once?
> >>>>>>>
> >>>>>>> Anoop
> >>>>>>>
> >>>>>>>
> >>>>>>> On Tue, Jun 9, 2020 at 8:08 PM Jan Van Besien <ja...@ngdata.com>
> >>> wrote:
> >>>>>>>
> >>>>>>>> On Sun, Jun 7, 2020 at 7:49 AM Anoop John <anoop.hbase@gmail.com
> >>>
> >>> wrote:
> >>>>>>>>> As per the above configs, it looks like Bucket Cache is not
> >>> being used.
> >>>>>>>>> Only on heap LRU cache in use.
> >>>>>>>>
> >>>>>>>> True (but it is large enough to hold everything, so I don't think
> >>> it
> >>>>>>>> matters).
> >>>>>>>>
> >>>>>>>>> @Jan - Is it possible for you to test with off heap Bucket
> >> Cache?
> >>>>>>>> Config
> >>>>>>>>> bucket cache off heap mode with size ~7.5 GB
> >>>>>>>>
> >>>>>>>> I did a quick test but it seems not to make a measurable
> >>> difference.
> >>>>>>>> If anything, it is actually slightly slower even. I see 100% hit
> >>> ratio
> >>>>>>>> in the L1
> >>>>>>>> LruBlockCache and effectively also 100% in the L2 BucketCache
> >> (hit
> >>>>>>>> ratio is not yet at 100% but hits increase with every test and
> >>> misses
> >>>>>>>> do not).
> >>>>>>>>
> >>>>>>>> Given that the LruBlockCache was already large enough to cache
> >> all
> >>> the
> >>>>>>>> data anyway, I did not expect this to help either, to be honest.
> >>>>>>>>
> >>>>>>>>> Do you have any DataBlockEncoding enabled on the CF?
> >>>>>>>>
> >>>>>>>> Yes, FAST_DIFF. But this is of course true in both the tests with
> >>>>>>>> hbase2 and hbase1.
> >>>>>>>>
> >>>>>>>> Jan
> >>>>>>>>
> >>>>>
> >>>>>
> >>>>> --
> >>>>> Best regards,
> >>>>> Andrew
> >>>>>
> >>>>> Words like orphans lost among the crosstalk, meaning torn from
> truth's
> >>> decrepit hands
> >>>>> - A23, Crosstalk
> >>>>
> >>>>
> >>>> --
> >>>> Best regards,
> >>>> Andrew
> >>>>
> >>>> Words like orphans lost among the crosstalk, meaning torn from truth's
> >>> decrepit hands
> >>>> - A23, Crosstalk
> >>>
> >>
> >
> >
>
--
Best regards,
Andrew
Words like orphans lost among the crosstalk, meaning torn from truth's
decrepit hands
- A23, Crosstalk