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.hb...@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.purt...@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 <apurt...@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 <apurt...@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.hb...@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.hb...@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
