[MDEV-2496] LP:941889 - JOIN constructors takes a long time in 5.3 Created: 2012-02-27  Updated: 2015-02-02  Resolved: 2012-10-04

Status: Closed
Project: MariaDB Server
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major
Reporter: Vladislav Vaintroub Assignee: Michael Widenius
Resolution: Fixed Votes: 0
Labels: Launchpad

Attachments: XML File LPexportBug941889.xml     File LPexportBug941889_941889.diff     Zip Archive LPexportBug941889_join-slowdown.zip     File LPexportBug941889_join_constructor_patch.diff     File LPexportBug941889_select1_1.lua     File LPexportBug941889_select1_test.sh    

 Description   

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)

 Comments   
Comment by Vladislav Vaintroub [ 2012-02-27 ]

Re: JOIN constructors takes a long time in 5.3
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

Comment by Vladislav Vaintroub [ 2012-02-27 ]

Re: JOIN constructors takes a long time in 5.3

Comment by Vladislav Vaintroub [ 2012-02-27 ]

select1_1.lua
LPexportBug941889_select1_1.lua

Comment by Vladislav Vaintroub [ 2012-02-27 ]

Re: JOIN constructors takes a long time in 5.3
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

Comment by Vladislav Vaintroub [ 2012-02-27 ]

Re: JOIN constructors takes a long time in 5.3
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.)

Comment by Sergei Petrunia [ 2012-02-29 ]

Re: JOIN constructors takes a long time in 5.3
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

Comment by Sergei Petrunia [ 2012-02-29 ]

Re: JOIN constructors takes a long time in 5.3
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.

Comment by Sergei Petrunia [ 2012-02-29 ]

Re: JOIN constructors takes a long time in 5.3
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.

Comment by Vladislav Vaintroub [ 2012-03-01 ]

Re: JOIN constructors takes a long time in 5.3
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

Comment by Sergei Petrunia [ 2012-03-01 ]

Re: JOIN constructors takes a long time in 5.3
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: 2.63ms
approx. 95 percentile: 2.49ms
approx. 95 percentile: 2.57ms
approx. 95 percentile: 2.65ms
approx. 95 percentile: 2.54ms
approx. 95 percentile: 2.56ms
approx. 95 percentile: 2.70ms
approx. 95 percentile: 2.63ms
approx. 95 percentile: 2.67ms

.. as one can see, there is not much variety.

Comment by Vladislav Vaintroub [ 2012-03-03 ]

Re: JOIN constructors takes a long time in 5.3
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.)

Comment by Vladislav Vaintroub [ 2012-03-03 ]

Re: JOIN constructors takes a long time in 5.3

Comment by Vladislav Vaintroub [ 2012-03-03 ]

raw results, select1.lua
LPexportBug941889_join-slowdown.zip

Comment by Vladislav Vaintroub [ 2012-03-03 ]

Re: JOIN constructors takes a long time in 5.3

Comment by Vladislav Vaintroub [ 2012-03-03 ]

Re: JOIN constructors takes a long time in 5.3

Comment by Vladislav Vaintroub [ 2012-03-03 ]

shell script to invoke sysbench that I used
LPexportBug941889_select1_test.sh

Comment by Vladislav Vaintroub [ 2012-03-03 ]

Re: JOIN constructors takes a long time in 5.3
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.)

Comment by Vladislav Vaintroub [ 2012-03-03 ]

Re: JOIN constructors takes a long time in 5.3
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.)

Comment by Vladislav Vaintroub [ 2012-03-03 ]

Re: JOIN constructors takes a long time in 5.3
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

Comment by Vladislav Vaintroub [ 2012-03-18 ]

Re: JOIN constructors takes a long time in 5.3
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

Comment by Vladislav Vaintroub [ 2012-03-18 ]

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

De-virtualize strategy pickers
LPexportBug941889_join_constructor_patch.diff

Comment by Vladislav Vaintroub [ 2012-03-21 ]

Re: JOIN constructors takes a long time in 5.3

Comment by Vladislav Vaintroub [ 2012-03-21 ]

Fix to previously posted patch, makes compile with gcc's -fno-implicit-templates
LPexportBug941889_941889.diff

Comment by Michael Widenius [ 2012-03-23 ]

Re: JOIN constructors takes a long time in 5.3
Now we allocate just as much memory that is needed. This shows a notable speedup compared even to MariaDB 5.2!

Comment by Rasmus Johansson (Inactive) [ 2012-03-23 ]

Launchpad bug id: 941889

Generated at Thu Feb 08 06:42:15 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.