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
