Re: HBase 2 slower than HBase 1?

2020-12-01 Thread ramkrishna vasudevan
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 <
[email protected]> 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  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 <
>> [email protected]> 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 
>> > 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 <
>> > [email protected]>
>> > > 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 
>> 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 <
>> [email protected]>
>> > > > > 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 <
>> > > > > [email protected]>
>> > > > > >> 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 <
>> > [email protected]
>> > > >
>> > > > > >>> 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

Re: HBase 2 slower than HBase 1?

2020-11-05 Thread ramkrishna vasudevan
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  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 <
> [email protected]> 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 
> > 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 <
> > [email protected]>
> > > 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 
> 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 <
> [email protected]>
> > > > > 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 <
> > > > > [email protected]>
> > > > > >> 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 <
> > [email protected]
> > > >
> > > > > >>> 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

Re: HBase 2 slower than HBase 1?

2020-11-05 Thread Bruno Dumon
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 <
[email protected]> 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 
> 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 <
> [email protected]>
> > 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  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 
> > > > 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 <
> > > > [email protected]>
> > > > >> 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 <
> [email protected]
> > >
> > > > >>> 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 f

Re: HBase 2 slower than HBase 1?

2020-10-30 Thread ramkrishna vasudevan
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  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 
> 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  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 
> > > 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 <
> > > [email protected]>
> > > >> 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  >
> > > >>> 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 c1002.2.5 c100
> > >  Counts
> > > 
> > > 
> > > 
> > > 
> > > 
> > > 
> > > 
> > > 
> > > 
> > > 
> > > 
> > > 
> > > 
> > > 
> > > 
> > > 
> > > 
> > > 
> > > 
> > > 
> > > 
> > > 
> > >  

Re: HBase 2 slower than HBase 1?

2020-07-14 Thread Andrew Purtell
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 
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  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 
> > 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 <
> > [email protected]>
> > >> 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 
> > >>> 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 c1002.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  2

Re: HBase 2 slower than HBase 1?

2020-07-14 Thread Andrew Purtell
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  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 
> 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 <
> [email protected]>
> >> 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 
> >>> 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 c1002.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   10001000100%5000
> >>> 5000100%1   1   100%
> 2
> >>>   2   100%5   5   100%
> >>> 10  10  100%
>  store_next10009988268 100%500049940082
> >>>100%1   99879401100%2
> >>>   199766539   100%5   499414653   100%
> >>> 10  

Re: HBase 2 slower than HBase 1?

2020-07-14 Thread Bharath Vissapragada
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  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 
> 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 <
> [email protected]>
> >> 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 
> >>> 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 c1002.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   10001000100%5000
> >>> 5000100%1   1   100%
> 2
> >>>   2   100%5   5   100%
> >>> 10  10  100%
>  store_next10009988268 100%500049940082
> >>>100%1   99879401100%2
> >>>   199766539   100%5   499414653  

Re: HBase 2 slower than HBase 1?

2020-07-14 Thread Josh Elser

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

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 c1002.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   10001000100%5000

5000100%1   1   100%2
  2   100%5   5   100%
10  10  100%

store_next10009988268 100%500049940082

   100%1   99879401100%2
  199766539   100%5   499414653   100%
10  998836518   100%

store_reseek  1   11733   > ! 2   59924   > ! 8

  120607  > ! 6   233467  > ! 10  585357  > ! 8
  1163490 > !




















cells_matched 20002000100%6000

6000100%11000   11000   100%21000
  21000   100%51000   51000   100%
101000  101000  100%

column_hint_include   10001000100%5000

   5000100%1   1   100%
2   2   100%5   5
  100%10  10  100%

filter_hint_skip  10001000100%5000

   5000100%1   1   100%
2   2   100%5   5
  100%10  10  100%

sqm_hint_done 999 999 100%

Re: HBase 2 slower than HBase 1?

2020-06-26 Thread Andrew Purtell
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  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 
> 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 
> > 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 c1002.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   10001000100%5000
> > 5000100%1   1   100%2
> >  2   100%5   5   100%
> > 10  10  100%
> > > store_next10009988268 100%500049940082
> >   100%1   99879401100%2
> >  199766539   100%5   499414653   100%
> > 10  998836518   100%
> > > store_reseek  1   11733   > ! 2   59924   > ! 8
> >  120607  > ! 6   233467  > ! 10  585357  > ! 8
> >  1163490 > !
> > >
> > >
> > >
> > >
> > >
> > >
> > >
> > >
> > >
> > >
> > >
> > >
> > >
> > >
> > >
> > >
> > >
> > >
> > >
> > > cells_matched 20002000100%6000
> > 6000100%11000   11000   100%21000
> >  21000   100%51000   51000   100%
> > 101000  101000  100%
> > > column_hint_include   10001000100%5000
> >   5000100%1   1   100%

Re: HBase 2 slower than HBase 1?

2020-06-26 Thread Anoop John
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 
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 
> 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 c1002.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   10001000100%5000
> 5000100%1   1   100%2
>  2   100%5   5   100%
> 10  10  100%
> > store_next10009988268 100%500049940082
>   100%1   99879401100%2
>  199766539   100%5   499414653   100%
> 10  998836518   100%
> > store_reseek  1   11733   > ! 2   59924   > ! 8
>  120607  > ! 6   233467  > ! 10  585357  > ! 8
>  1163490 > !
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> > cells_matched 20002000100%6000
> 6000100%11000   11000   100%21000
>  21000   100%51000   51000   100%
> 101000  101000  100%
> > column_hint_include   10001000100%5000
>   5000100%1   1   100%
> 2   2   100%5   5
>  100%10  10  100%
> > filter_hint_skip  10001000100%5000
>   5000100%1   1   100%
> 2   2   100%5   5
>  100%10  10  100%
> > sqm_hint_done 999 999 100%998 998 100%998
> 998 100%

Re: HBase 2 slower than HBase 1?

2020-06-25 Thread Andrew Purtell
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  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 c1002.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   10001000100%5000
> 5000100%1   1   100%2 
>   2   100%5   5   100%10  
> 10  100%
> store_next10009988268 100%500049940082
> 100%1   99879401100%2   199766539 
>   100%5   499414653   100%10  998836518   
> 100%
> store_reseek  1   11733   > ! 2   59924   > ! 8   120607  
> > ! 6   233467  > ! 10  585357  > ! 8   1163490 > !
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> cells_matched 20002000100%6000
> 6000100%11000   11000   100%21000 
>   21000   100%51000   51000   100%101000  
> 101000  100%
> column_hint_include   10001000100%5000
> 5000100%1   1   100%2 
>   2   100%5   5   100%10  
> 10  100%
> filter_hint_skip  10001000100%5000
> 5000100%1   1   100%2 
>   2   100%5   5   100%10  
> 10  100%
> sqm_hint_done 999 999 100%998 998 100%998 998 
> 100%997 997 100%996 996 100%992 992 100%
> sqm_hint_seek_next_col1   0   0%  2   4002
> > ! 2   9002> ! 3   19000

Re: HBase 2 slower than HBase 1?

2020-06-25 Thread Andrew Purtell
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 1000 1000 100% 5000 5000 100% 1
1 100% 2 2 100% 5 5 100% 10
10 100%
store_next 1000 9988268 100% 5000 49940082 100% 1 99879401
100% 2 199766539 100% 5 499414653 100% 10 998836518
100%
store_reseek 1 11733 > ! 2 59924 > ! 8 120607 > ! 6 233467 > ! 10 585357 > !
8 1163490 > !



















cells_matched 2000 2000 100% 6000 6000 100% 11000
11000 100% 21000 21000 100% 51000 51000 100% 101000
101000 100%
column_hint_include 1000 1000 100% 5000 5000 100% 1
1 100% 2 2 100% 5 5 100% 10
10 100%
filter_hint_skip 1000 1000 100% 5000 5000 100% 1
1 100% 2 2 100% 5 5 100% 10
10 100%
sqm_hint_done 999 999 100% 998 998 100% 998 998 100%
997 997 100% 996 996 100% 992 992 100%
sqm_hint_seek_next_col 1 0 0% 2 4002 > ! 2 9002 > ! 3 19003 > !
4 49004 > ! 8 99008 > !
sqm_hint_seek_next_row 0 1000 > ! 2 1000 > ! 0 1000 > ! 0
1000 > ! 0 1000 > ! 0 1000 > !
sqm_hint_skip 1000 0 0% 5000 0 0% 1 0 0% 2 0 0%
5 0 0% 10 0 0%
versions_hint_include_and_seek_next_col 0 0 0% 0 4000 > ! 0 9000 > !
0 19000 > ! 0 49000 > ! 0 99000 > !
versions_hint_include_and_seek_next_row 0 0 0% 0 1000 > ! 0 1000 > !
0 1000 > ! 0 1000 > ! 0 1000 > !



















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=1000

















ValueSize=20

















BlockEncoding=FAST_DIFF

















Compress=NONE
Filter=ALL