JOIN constructors takes a long time in 5.3

[Vladislav Vaintroub]

I run sysbench on MariaDB on Windows with Visual Studio sampling profiler , comparing 5.2 and 5.3 performance.
sysbench version is 0.5 and for the test I created select1.lua, which does nothing else but running prepared "SELECT 1".

Performance reports show a big difference inside JOIN constructor, and for this specific test JOIN::JOIN is the most expensive function with 24.23% exclusive samples.

Here is he list of functions that show up as more expensive in 5.3 compared to 5.2

Comparison Column Delta Baseline Value Comparison Value
JOIN::JOIN 23,15 1,08 24,23
RtlpAllocateHeap 3,24 0,00 3,24
RtlpInsertFreeBlock 1,93 0,00 1,93
RtlpFreeHeap 1,42 0,00 1,42

Looking at what has changed from 5.2 to 5.3, JOIN structure grew from around 5K to around 32K. Besides, it contains 2 large arrays of POSITION structures, and POSITION has a non-trivial constructor, since it includes semi-join strategy classes for which virtual function tables must be setup (confirmed by switching to disassembly and single-stepping through JOIN::JOIN)

[Vladislav Vaintroub (wlad-montyprogram)]

Profiling with another test (point_select) shows the same slowdown in JOIN::JOIN. Second expensive call as compared to
5.2 is JON::choose_subquery_plan.

Comparison Delta Baseline Value Comparison Value
JOIN::JOIN 7,83 0,42 8,25
JOIN::choose_subquery_plan 3,47 0,00 3,47
ut_delay 1,55 0,00 1,55
memcpy 1,35 0,00 1,35
RtlpAllocateHeap 1,28 0,00 1,28

For JOIN::choose_subquery_plan function, profiler points at the line at the very start of the function
  Join_plan_state save_qep; /* The original QEP of the subquery. */

I suspect that the bottleneck here could be again initialization of the POSITION structures in the best_positions array in
Join_plan_state

[Vladislav Vaintroub (wlad-montyprogram)]

Running sysbench 0.5 using

sysbench --test=select1_1.lua --num-threads=10 --max-requests=0 --max-time=300 run

Result with 5.2.11 (lp:maria/5.2)
read/write requests: 19127047 (63756.70 per sec.)

Result with 5.3.4 (lp:maria/5.3)
read/write requests: 16301437 (54338.01 per sec.)

lua script select1_1.lua attached

[Vladislav Vaintroub (wlad-montyprogram)]

Results from a slightly realistic test , using sysbench 0.4 and POINT_SELECT "unit test"

sysbench --num-threads=10 --test=oltp --oltp-table-size=1000000 --oltp-dist-type=uniform --oltp-table-name=sbtest --init-rng=on --max-requests=0 --max-time=180 --mysql-user=root --mysql-port=3306 --mysql-host=127.0.0.1 --mysql-db=test --myisam-max-rows=1000000 --mysql-table-engine=INNODB --oltp-point-selects=1 --oltp-simple-ranges=0 --oltp-sum-ranges=0 --oltp-order-ranges=0 --oltp-distinct-ranges=0 --oltp-skip-trx=on --oltp-read-only=on run

5.2.11
   transactions: 8351523 (46397.22 per sec.)
5.3.4
   transactions: 6961462 (38674.66 per sec.)

[Sergey Petrunia (sergefp)]

I am trying to repeat the problem on Linux. I run latest MariaDB 5.2 and 5.3, compiled with compile-pentium-max.

I'm using sysbench with this lua file:
== tests/db/_select_one.lua ==
pathtest = string.match(test, "(.*/)") or ""

dofile(pathtest .. "common.lua")

function thread_init(thread_id)
   set_vars()
end

function event(thread_id)
   rs = db_query("select 1")
end
== EOF ==

and I run sysbench with:
./sysbench --test=./tests/db/_select_one.lua --db-driver=mysql --mysql-user=root --mysql-socket=/tmp/mysql.sock --max-requests=100000 run

My results from two runs are:
== 5.2 ==
...
    response time:
         min: 0.08ms
         avg: 0.09ms
         max: 1.27ms
         approx. 95 percentile: 0.09ms
...
    response time:
         min: 0.04ms
         avg: 0.09ms
         max: 1.22ms
         approx. 95 percentile: 0.09ms

== 5.3 ==
...
    response time:
         min: 0.04ms
         avg: 0.09ms
         max: 1.32ms
         approx. 95 percentile: 0.10ms
...
    response time:
         min: 0.04ms
         avg: 0.09ms
         max: 1.54ms
         approx. 95 percentile: 0.10ms

[Sergey Petrunia (sergefp)]

As you see, 95% percentile went up from 0.09 to 0.10 ms. As far as I understood Wlad, he was observing a much greater slowdown.

[Sergey Petrunia (sergefp)]

Okay I have re-run the test mentioned in comment #4. My results are:
== 5.3 ==

OLTP test statistics:
    queries performed:
        read: 1553035
        write: 0
        other: 0
        total: 1553035
    transactions: 0 (0.00 per sec.)
    deadlocks: 0 (0.00 per sec.)
    read/write requests: 1553035 (8627.93 per sec.)
    other operations: 0 (0.00 per sec.)

General statistics:
    total time: 180.0008s
    total number of events: 1553035
    total time taken by event execution: 1797.9183s
    response time:
         min: 0.10ms
         avg: 1.16ms
         max: 71.55ms
         approx. 95 percentile: 2.63ms

Threads fairness:
    events (avg/stddev): 155303.5000/542.04
    execution time (avg/stddev): 179.7918/0.00

== 5.2 ==
OLTP test statistics:
    queries performed:
        read: 1467139
        write: 0
        other: 0
        total: 1467139
    transactions: 0 (0.00 per sec.)
    deadlocks: 0 (0.00 per sec.)
    read/write requests: 1467139 (8150.74 per sec.)
    other operations: 0 (0.00 per sec.)

General statistics:
    total time: 180.0007s
    total number of events: 1467139
    total time taken by event execution: 1797.8794s
    response time:
         min: 0.09ms
         avg: 1.23ms
         max: 17.57ms
         approx. 95 percentile: 2.70ms

Threads fairness:
    events (avg/stddev): 146713.9000/1128.34
    execution time (avg/stddev): 179.7879/0.00

== Comparison ==
5.3 is a bit faster on AVG response time (1.16 vs 1.23), and on 95 %ile
(2.63 vs 2.70 ms).
5.3 managed to run a bit more queries: 1,553,035 vs 1,467,139. But this is only a 5%
difference.

[Vladislav Vaintroub (wlad-montyprogram)]

One difference to your tests seems to be that I did not ran my tests with a single user.
I cannot predict the outcome with more users , but I do not exclude any possibility that effect of a CPU cache miss would be more visible with multiuser load.
That 5.3 would behave any better on this simplistic load, is rather unintuitive, to my knowlegde there were no performance-relevant patches affecting this load in between 5.2 and 5.3

[Sergey Petrunia (sergefp)]

On the question of wild instability of results on Linux: I've tried doing 10 runs on Fedora 16, x8_64:

MariaDB 5.2:
sysbench 0.5: multi-threaded system evaluation benchmark

Running the test with following options:
Number of threads: 10
Random number generator seed is 0 and will be ignored

Threads started!

OLTP test statistics:
    queries performed:
            read: 1454781
            read: 1445217
            read: 1486174
            read: 1541128
            read: 1510506
            read: 1484820
            read: 1520778
            read: 1472821
            read: 1377681
            read: 1498271
    response time:
         avg: 1.24ms
         avg: 1.24ms
         avg: 1.21ms
         avg: 1.17ms
         avg: 1.19ms
         avg: 1.21ms
         avg: 1.18ms
         avg: 1.22ms
         avg: 1.31ms
         avg: 1.20ms

         approx. 95 percentile: 2.72ms
         approx. 95 percentile: 2.71ms
         approx. 95 percentile: 2.68ms
         approx. 95 percentile: 2.60ms
         approx. 95 percentile: 2.65ms
         approx. 95 percentile: 2.68ms
         approx. 95 percentile: 2.64ms
         approx. 95 percentile: 2.68ms
         approx. 95 percentile: 2.79ms
         approx. 95 percentile: 2.66ms
------------------------------
MariaDB 5.3.5:
    queries performed:
        read: 1503817
        read: 1531896
        read: 1637580
        read: 1570776
        read: 1517940
        read: 1600717
        read: 1585504
        read: 1477577
        read: 1543501
        read: 1504005
    response time:
         avg: 1.20ms
         avg: 1.17ms
         avg: 1.10ms
         avg: 1.14ms
         avg: 1.18ms
         avg: 1.12ms
         avg: 1.13ms
         avg: 1.22ms
         avg: 1.16ms
         avg: 1.20ms

         approx. 95 percentile: 2.67ms
         approx. 95 percentile: ...

[Vladislav Vaintroub (wlad-montyprogram)]

I rerun the same test on the facebook-maria2
comparing 5.3 vs 5.3 (both bzr, both compiled with BUILD/compile-amd64-max)
I can confirm my observation that 5.3 is slower in this test that 5.2

Moreover, when I ran the test with 10 users (which does not saturate all CPUs on the box), I note CPU usage difference - it is about 540% for mysqld/5.3 and about 500% for mysqld/5.2

5.2 appears to have 8% better throughput in this machine with this test

5.2
    read/write requests: 23498807 (130548.85 per sec.)
    read/write requests: 23231222 (129062.21 per sec.)
    read/write requests: 23270830 (129282.23 per sec.)
    read/write requests: 23326939 (129593.98 per sec.)
    read/write requests: 23282261 (129345.76 per sec.)
    read/write requests: 23251680 (129175.87 per sec.)
    read/write requests: 23455982 (130310.90 per sec.)
    read/write requests: 23513217 (130628.89 per sec.)
    read/write requests: 23116047 (128422.35 per sec.)
    read/write requests: 23672964 (131516.35 per sec.)
5.3
    read/write requests: 22013700 (122298.22 per sec.)
    read/write requests: 21608442 (120046.80 per sec.)
    read/write requests: 21812529 (121180.61 per sec.)
    read/write requests: 21333168 (118517.53 per sec.)
    read/write requests: 21418365 (118990.84 per sec.)
    read/write requests: 21578643 (119881.20 per sec.)
    read/write requests: 21673488 (120408.14 per sec.)
    read/write requests: 21336076 (118533.65 per sec.)
    read/write requests: 21353352 (118629.67 per sec.)
    read/write requests: 21247205 (118039.92 per sec.)

[Vladislav Vaintroub (wlad-montyprogram)]

Rerun the same test on facebook-maria2 with increased number of users (100), to saturate the CPUs.

Observations: mysqld/5.2 CPU usage stays approx. 580%, mysqld/5.3 usage stays approx. 615%, the rest of CPUs is used by sysbench (idle percentage is 0 in both cases)

5.2
    read/write requests: 32853086 (182516.31 per sec.)
    read/write requests: 32807783 (182264.87 per sec.)
    read/write requests: 31899948 (177221.22 per sec.)

5.3
    read/write requests: 30569874 (169832.10 per sec.)
    read/write requests: 30239683 (167997.72 per sec.)
    read/write requests: 30255084 (168083.12 per sec.)

[Vladislav Vaintroub (wlad-montyprogram)]

Same test with 100 users on pitbull,
shows 16% slowdown on 5.3 as compared to 5.2

5.2
   read/write requests: 85804752 (476692.37 per sec.)
    read/write requests: 86828823 (482381.63 per sec.)
    read/write requests: 85943353 (477462.30 per sec.)
    read/write requests: 87286946 (484926.68 per sec.)
    read/write requests: 85267699 (473708.53 per sec.)
    read/write requests: 85890731 (477169.94 per sec.)
    read/write requests: 88038362 (489101.28 per sec.)
    read/write requests: 87684761 (487136.79 per sec.)
    read/write requests: 85887807 (477153.68 per sec.)
    read/write requests: 87857021 (488093.79 per sec.)

5.3
    read/write requests: 74338487 (412990.99 per sec.)
    read/write requests: 75104673 (417247.55 per sec.)
    read/write requests: 75161348 (417562.43 per sec.)
    read/write requests: 73985184 (411028.07 per sec.)
    read/write requests: 75481194 (419339.30 per sec.)
    read/write requests: 74973092 (416516.54 per sec.)
    read/write requests: 73483094 (408238.68 per sec.)
    read/write requests: 73488830 (408270.67 per sec.)
    read/write requests: 74586217 (414366.99 per sec.)
    read/write requests: 74786541 (415480.09 per sec.)

[Vladislav Vaintroub (wlad-montyprogram)]

FWIW, here is the parameters I used (on pitbull). Should not make any difference for that test, but perhaps I missed something and it does mean something

[mysqld]
sql-mode="NO_ENGINE_SUBSTITUTION"
back_log=1000
port=3306
max_connections=10001
max_connect_errors=5000
max_prepared_stmt_count=500000
table_cache=8092
transaction_isolation=REPEATABLE-READ
loose-skip-external-locking
innodb_status_file=0
innodb-file-per-table=1
innodb_data_file_path=ibdata1:200M:autoextend
innodb_buffer_pool_size=300M
innodb_additional_mem_pool_size=20M
innodb_log_file_size=650M
innodb_log_files_in_group=2
innodb_log_buffer_size=100M
innodb_support_xa=0
innodb_doublewrite=0
innodb_thread_concurrency=0
skip-grant-tables
innodb_flush_log_at_trx_commit=0
innodb_flush_method=ALL_O_DIRECT
innodb_spin_wait_delay=3

[Vladislav Vaintroub (wlad-montyprogram)]

Attached in a simple patch that de-virtualizes semijoin strategy picker classes.

It fixes the problem (tested on Windows)

- SELECT 1 test (10 users)

5.3, without fix
    read/write requests: 11739503 (39131.57 per sec.)
    read/write requests: 11787997 (39293.23 per sec.)
    read/write requests: 11776222 (39253.97 per sec.)

5.3, with fix
    read/write requests: 12887151 (42957.08 per sec.)
    read/write requests: 12876115 (42920.29 per sec.)
    read/write requests: 12925002 (43083.25 per sec.)

5.2
    read/write requests: 13186290 (43954.19 per sec.)
    read/write requests: 13099010 (43663.26 per sec.)
    read/write requests: 13115124 (43716.98 per sec.)

Summary on SELECT 1:
- The fix speeds up 5.3 on this test by 9.7%
- 5.3 is stil a bit slower than 5.2 (approx 1%)

Another test : OLTP_RO (64 users, sysbench 0.4)

5.3:
    read/write requests: 4869802 (27051.41 per sec.)
    read/write requests: 4795000 (26635.60 per sec.)
    read/write requests: 4948034 (27485.88 per sec.)

5.3-fix
   read/write requests: 5354006 (29741.23 per sec.)
   read/write requests: 5327574 (29593.89 per sec.)
   read/write requests: 5477906 (30429.07 per sec.)

Summary on OLTP-RO:
Fix makes 5.3 ~ 10.6% faster

[Michael Widenius (monty)]

Now we allocate just as much memory that is needed. This shows a notable speedup compared even to MariaDB 5.2!