Re: B-Tree support function number 3 (strxfrm() optimization)

On 31 March 2014 11:32, Thom Brown <thom@linux.com> wrote:
> On 31 March 2014 06:51, Peter Geoghegan <pg@heroku.com> wrote:
>> On Wed, Mar 26, 2014 at 8:08 PM, Peter Geoghegan <pg@heroku.com> wrote:
>>> The API I envisage is a new support function 3 that operator class
>>> authors may optionally provide.
>>
>> I've built a prototype patch, attached, that extends SortSupport and
>> tuplesort to support "poor man's normalized keys". All the regression
>> tests pass, so while it's just a proof of concept, it is reasonably
>> well put together for one. The primary shortcoming of the prototype
>> (the main reason why I'm calling it a prototype rather than just a
>> patch) is that it isn't sufficiently generalized (i.e. it only works
>> for the cases currently covered by SortSupport - not B-Tree index
>> builds, or B-Tree scanKeys). There is no B-Tree support function
>> number 3 in the patch. I didn't spend too long on this.
>>
>> I'm pretty happy with the results for in-memory sorting of text (my
>> development system uses 'en_US.UTF8', so please assume that any costs
>> involved are for runs that use that collation). With the dellstore2
>> sample database [1] restored to my local development instance, the
>> following example demonstrates just how much the technique can help
>> performance.
>>
>> With master:
>>
>> pg@hamster:~/sort-tests$ cat sort.sql
>> select * from (select * from customers order by firstname offset 100000) d;
>> pg@hamster:~/sort-tests$ pgbench -f sort.sql -n -T 100
>> transaction type: Custom query
>> scaling factor: 1
>> query mode: simple
>> number of clients: 1
>> number of threads: 1
>> duration: 100 s
>> number of transactions actually processed: 819
>> latency average: 122.100 ms
>> tps = 8.186197 (including connections establishing)
>> tps = 8.186522 (excluding connections establishing)
>>
>> With patch applied (requires initdb for new text SortSupport pg_proc entry):
>>
>> pg@hamster:~/sort-tests$ cat sort.sql
>> select * from (select * from customers order by firstname offset 100000) d;
>> pg@hamster:~/sort-tests$ pgbench -f sort.sql -n -T 100
>> transaction type: Custom query
>> scaling factor: 1
>> query mode: simple
>> number of clients: 1
>> number of threads: 1
>> duration: 100 s
>> number of transactions actually processed: 2525
>> latency average: 39.604 ms
>> tps = 25.241723 (including connections establishing)
>> tps = 25.242447 (excluding connections establishing)
>
> As another data point, I ran the same benchmark, but I don't appear to
> yield the same positive result.  An initdb was done for each rebuild,
> my system uses en_GB.UTF-8 (if that's relevant) and I used your same
> sort.sql...
>
> With master:
>
> thom@swift ~/Development $ pgbench -f sort.sql -n -T 100 ds2
> transaction type: Custom query
> scaling factor: 1
> query mode: simple
> number of clients: 1
> number of threads: 1
> duration: 100 s
> number of transactions actually processed: 421479
> latency average: 0.237 ms
> tps = 4214.769601 (including connections establishing)
> tps = 4214.906079 (excluding connections establishing)
>
> With patch applied:
>
> thom@swift ~/Development $ pgbench -f sort.sql -n -T 100 ds2
> transaction type: Custom query
> scaling factor: 1
> query mode: simple
> number of clients: 1
> number of threads: 1
> duration: 100 s
> number of transactions actually processed: 412405
> latency average: 0.242 ms
> tps = 4124.047237 (including connections establishing)
> tps = 4124.177437 (excluding connections establishing)
>
>
> And with 4 runs (TPS):
>
> Master: 4214.906079 / 4564.532623 / 4152.784608 / 4152.578297 (avg: 4271)
> Patched: 4124.177437 / 3777.561869 / 3777.561869 / 2484.220475 (avg: 3481)
>
> I'm not sure what's causing the huge variation.  I ran 5 minute benchmarks too:
>
> Master:
>
> thom@swift ~/Development $ pgbench -f sort.sql -n -T 300 ds2
> transaction type: Custom query
> scaling factor: 1
> query mode: simple
> number of clients: 1
> number of threads: 1
> duration: 300 s
> number of transactions actually processed: 1092221
> latency average: 0.275 ms
> tps = 3640.733002 (including connections establishing)
> tps = 3640.784628 (excluding connections establishing)
>
>
> Patched:
>
> thom@swift ~/Development $ pgbench -f sort.sql -n -T 300 ds2
> transaction type: Custom query
> scaling factor: 1
> query mode: simple
> number of clients: 1
> number of threads: 1
> duration: 300 s
> number of transactions actually processed: 1068239
> latency average: 0.281 ms
> tps = 3560.794946 (including connections establishing)
> tps = 3560.835076 (excluding connections establishing)
>
>
>
> And per-second results for the first 30 seconds:
>
>
> Master:
>
> progress: 1.0 s, 2128.8 tps, lat 0.464 ms stddev 0.084
> progress: 2.0 s, 2138.9 tps, lat 0.464 ms stddev 0.015
> progress: 3.0 s, 2655.6 tps, lat 0.374 ms stddev 0.151
> progress: 4.0 s, 2214.0 tps, lat 0.448 ms stddev 0.080
> progress: 5.0 s, 2171.1 tps, lat 0.457 ms stddev 0.071
> progress: 6.0 s, 2131.6 tps, lat 0.466 ms stddev 0.035
> progress: 7.0 s, 3811.2 tps, lat 0.260 ms stddev 0.177
> progress: 8.0 s, 2139.6 tps, lat 0.464 ms stddev 0.017
> progress: 9.0 s, 7989.7 tps, lat 0.124 ms stddev 0.091
> progress: 10.0 s, 8509.7 tps, lat 0.117 ms stddev 0.062
> progress: 11.0 s, 3131.3 tps, lat 0.317 ms stddev 0.177
> progress: 12.0 s, 9362.1 tps, lat 0.106 ms stddev 0.006
> progress: 13.0 s, 5831.0 tps, lat 0.170 ms stddev 0.137
> progress: 14.0 s, 4949.3 tps, lat 0.201 ms stddev 0.156
> progress: 15.0 s, 2136.9 tps, lat 0.464 ms stddev 0.028
> progress: 16.0 s, 3918.3 tps, lat 0.253 ms stddev 0.177
> progress: 17.0 s, 4102.7 tps, lat 0.242 ms stddev 0.122
> progress: 18.0 s, 2997.6 tps, lat 0.331 ms stddev 0.151
> progress: 19.0 s, 2139.1 tps, lat 0.464 ms stddev 0.034
> progress: 20.0 s, 3189.5 tps, lat 0.311 ms stddev 0.173
> progress: 21.0 s, 2120.7 tps, lat 0.468 ms stddev 0.030
> progress: 22.0 s, 3197.7 tps, lat 0.311 ms stddev 0.182
> progress: 23.0 s, 2115.3 tps, lat 0.469 ms stddev 0.034
> progress: 24.0 s, 2129.0 tps, lat 0.466 ms stddev 0.031
> progress: 25.0 s, 2190.7 tps, lat 0.453 ms stddev 0.106
> progress: 26.0 s, 2118.6 tps, lat 0.468 ms stddev 0.031
> progress: 27.0 s, 2136.8 tps, lat 0.464 ms stddev 0.018
> progress: 28.0 s, 5160.7 tps, lat 0.193 ms stddev 0.156
> progress: 29.0 s, 2312.5 tps, lat 0.429 ms stddev 0.107
> progress: 30.0 s, 2145.9 tps, lat 0.463 ms stddev 0.038
> progress: 31.0 s, 2107.6 tps, lat 0.471 ms stddev 0.071
>
>
>
> Patched:
>
> progress: 1.0 s, 2136.2 tps, lat 0.463 ms stddev 0.084
> progress: 2.0 s, 2153.3 tps, lat 0.461 ms stddev 0.035
> progress: 3.0 s, 2336.0 tps, lat 0.425 ms stddev 0.112
> progress: 4.0 s, 2144.8 tps, lat 0.463 ms stddev 0.037
> progress: 5.0 s, 2171.7 tps, lat 0.457 ms stddev 0.041
> progress: 6.0 s, 2161.9 tps, lat 0.459 ms stddev 0.036
> progress: 7.0 s, 2143.1 tps, lat 0.463 ms stddev 0.019
> progress: 8.0 s, 2148.4 tps, lat 0.462 ms stddev 0.032
> progress: 9.0 s, 2142.1 tps, lat 0.463 ms stddev 0.028
> progress: 10.0 s, 2133.6 tps, lat 0.465 ms stddev 0.032
> progress: 11.0 s, 2138.3 tps, lat 0.464 ms stddev 0.020
> progress: 12.0 s, 2578.7 tps, lat 0.385 ms stddev 0.149
> progress: 13.0 s, 2455.6 tps, lat 0.404 ms stddev 0.119
> progress: 14.0 s, 2909.5 tps, lat 0.341 ms stddev 0.170
> progress: 15.0 s, 2133.7 tps, lat 0.465 ms stddev 0.025
> progress: 16.0 s, 2876.9 tps, lat 0.345 ms stddev 0.160
> progress: 17.0 s, 2167.1 tps, lat 0.458 ms stddev 0.038
> progress: 18.0 s, 3623.4 tps, lat 0.274 ms stddev 0.181
> progress: 19.0 s, 2476.3 tps, lat 0.401 ms stddev 0.137
> progress: 20.0 s, 2166.9 tps, lat 0.458 ms stddev 0.030
> progress: 21.0 s, 3150.0 tps, lat 0.315 ms stddev 0.176
> progress: 22.0 s, 2220.3 tps, lat 0.447 ms stddev 0.084
> progress: 23.0 s, 2131.3 tps, lat 0.466 ms stddev 0.030
> progress: 24.0 s, 2154.2 tps, lat 0.461 ms stddev 0.047
> progress: 25.0 s, 2122.5 tps, lat 0.468 ms stddev 0.040
> progress: 26.0 s, 2202.2 tps, lat 0.451 ms stddev 0.079
> progress: 27.0 s, 2150.6 tps, lat 0.461 ms stddev 0.039
> progress: 28.0 s, 2156.1 tps, lat 0.460 ms stddev 0.027
> progress: 29.0 s, 2152.1 tps, lat 0.461 ms stddev 0.028
> progress: 30.0 s, 2235.4 tps, lat 0.444 ms stddev 0.071

While this seems to indicate some kind or regression with the patch,
I've just realised that the data files weren't read in as the csv
files were in the wrong path, so that explains the very high tps.
*facepalm*  So here are the *right* benchmarks:

Master:

thom@swift ~/Development $ pgbench -f sort.sql -n -T 100 ds2
transaction type: Custom query
scaling factor: 1
query mode: simple
number of clients: 1
number of threads: 1
duration: 100 s
number of transactions actually processed: 2093
latency average: 47.778 ms
tps = 20.920833 (including connections establishing)
tps = 20.921719 (excluding connections establishing)

(a repeat shows 20.737619)


With patch:

thom@swift ~/Development $ pgbench -f sort.sql -n -T 100 ds2
transaction type: Custom query
scaling factor: 1
query mode: simple
number of clients: 1
number of threads: 1
duration: 100 s
number of transactions actually processed: 6148
latency average: 16.265 ms
tps = 61.477152 (including connections establishing)
tps = 61.479736 (excluding connections establishing)

(a repeat shows 62.252024)

So clearly a 3-fold improvement in this case.
-- 
Thom