|
I think that to find the source of the regression, flame graphs produced from perf record samples would be most useful.
Would it be possible for you to upload the flame graphs of the benchmark on MariaDB 10.2.37 and 10.2.38?
Another option might be to compare MariaDB 10.4.18 and 10.4.19 (assuming that the same regression is observable between these releases) and to enable the optimizer trace (MDEV-6111). I would expect the problem to be a worse query execution plan to be chosen, and not something in the InnoDB storage engine.
|
|
I added FlameGraph to the ticket.
But perf do not resolved the symbols despite I install dbgsym package (and reinstall mariadb package from http://archive.mariadb.org/mariadb-$MARIADB_VERSION/repo/ubuntu/ ).
Do you have an advice to fix that?
I don't have many time today but I try to have a look to the optimizer trace tomorrow.
|
|
cypx, thank you for trying it. One more thing that could be helpful would be the EXPLAIN output for the SELECT statement in each environment.
danblack, can you help with the debug symbols?
|
|
Trace and explain added!
|
|
https://github.com/cypx/mariadb-issue/pull/1
rough explaination.
|
|
cypx, thank you. I do not see a huge difference between the optimizer trace and the EXPLAIN SELECT output between 10.4.18 and 10.4.19. Did you reproduce the 20× performance difference between those 2 versions?
|
|
@danblack thank for the explanation, I think understand, I will retry tomorrow.
@marko Yes I reproduce, It took less than 5mn to get the 1.4.18 trace and more than one and half hour to get the 1.4.19 one.
At the end of the trace the attaching_conditions_to_tables have difference for some table (eao, eao2...), could it be significant?
Also, I realize I don't have say that the issue have been initially spotted on baremetal servers running Debian (so it's not related to docker and/or virtualization side effect)
|
|
cypx, the difference between the end of trace_10.4.18.json and trace_10.4.19.json seems to be that the 10.4.19 output uses the format database_name.table_name.column_name while the 10.4.18 output omits the database_name.
I am not an expert at reading this output, but the difference between the numbers of rows or the costs seems to be rather small. I hope that the flame graphs will shed some light on this. I can’t yet rule out InnoDB (my area of expertise) as the culprit of this regression.
|
|
I gave up trying to do perf report with symbols on docker because despite Daniel Black advice and some others documentation found on the web it's not working on my environment.
So I set up Ubuntu 20.04 VMs using http://archive.mariadb.org/mariadb-$MARIADB_VERSION/repo/ubuntu/ repository and I get flamegraph with symbols.
The issue has been reproduced, as the VMs is a bit slower it's take 8mn 03s with 10.4.18 and 3hours 48mn 28s with 10.4.18...
I added the new flamegraph to the the issue.
|
|
__nss_database_lookup stands out, though this appears to be a [false lookup|
https://stackoverflow.com/questions/66762523/why-does-nss-database-lookup-take-most-of-the-time-in-my-numerical-c-program]. Being under JOIN_CACHE::read_all_record_fields, a very small function of functions it called appear in the flamegraph already. So I don't know what is all the time in this sample.
Only a little innodb shows up in 10.4.18 (index read). I failed to find a significant sample in 10.4.19.
|
|
The function JOIN_CACHE::join_matching_records() stands out in the call graphs. I do not see any significant time being spent in InnoDB. In perf_full_10.4.18_8mn03.svg, JOIN_TAB_SCAN::next() or rr_next() is spending 0.45% of the recorded samples, mostly executing inside InnoDB. In perf_full_10.4.18_8mn03.svg the function JOIN_CACHE::join_matching_records() seems to invoke something else to read the data. According to the search function in Mozilla Firefox, function names containing ha_innobase account for 0.4% of the samples. I could not visually find any such stack trace in the output.
A search
git log -SJOIN_CACHE mariadb-10.4.18..mariadb-10.4.19 sql
|
identified this change that was supposed to fix MDEV-21104.
Would reverting that change fix the regression?
|
|
@marko Good catch! I confirm reverting 90780bb5a949d5e27b39df4adaa1d7b1ad98948e on 10.4.19 fix the regression.
On the same VM, it's take 7mn52s to run the query with a reverted 10.4.19 build.
I added the flamegraph to the issue.
|
|
Raising to blocker priority as the level of regression in the query time is of a very large magnitude and occurring in such a common application like Magento 2 should be given the highest priority possible, especially as the causing commit has been identified.
|
|
The patch 90780bb5a949d5e27b39df4adaa1d7b1ad98948e fixed an algorithmic bug in the implementation of BNL for outer joins. That bug led to wrong result set for a class of queries. The cause of the bug were missing actions needed for BNL to be valid for any dataset used by an affected query. It may happens that for other datasets that actions are not needed to get the right result set.
|
|
cypx, please could you confirm that the following piece of your query is as it was intended to be:
LEFT JOIN magentodb.eav_attribute_option AS eao3
|
ON ea.attribute_id = eao.attribute_id AND ce_varchar_1.value = eao.option_id
|
LEFT JOIN magentodb.eav_attribute_option_value eaov_1
|
ON eaov_1.option_id = eao.option_id
|
If it's so then there is no conditions imposed on eao3. Is it what should be?
I'm asking because I have to force the optimizer to produce a plan similar to yours for my simulation test case.
|
|
@igor I'm not a Magento developper but as far as I understand it's seems intended and the result match the expectation.
Note also that the query is generated by ORM so it could be suboptimal.
|
|
alice, can I trouble you for a minimised test case of https://github.com/cypx/mariadb-issue
|
|
I was afraid to oversimplify the test and to loose the problem, so please also check the initial test case.
With the test below - the query takes around 0.2s on 10.4.18 vs 3.2s on 10.4.19. Explain/Analyze for the query show the same.
Also with less rows the test will be shorter, but I've left as it is now, because it is easier to see the difference. Attached as mdev-32351.test
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | r_rows | filtered | r_filtered | Extra |
|
+------+-------------+--------------+--------+---------------------------------+------------------+---------+----------------------------------------------+------+---------+----------+------------+--------------------------------------------------------------+
|
| 1 | SIMPLE | t1 | index | NULL | attribute_set_id | 2 | NULL | 53 | 53.00 | 100.00 | 100.00 | Using index; Using temporary |
|
| 1 | SIMPLE | t2 | ALL | entity_type_id | NULL | NULL | NULL | 240 | 240.00 | 100.00 | 100.00 | Using where; Using join buffer (flat, BNL join) |
|
| 1 | SIMPLE | ce_varchar_0 | eq_ref | entity_id,attribute_id,store_id | entity_id | 8 | test.t1.entity_id,test.t2.attribute_id,const | 1 | 0.00 | 100.00 | 100.00 | Using where |
|
| 1 | SIMPLE | ce_varchar_1 | eq_ref | entity_id,attribute_id,store_id | entity_id | 8 | test.t1.entity_id,test.t2.attribute_id,const | 1 | 0.00 | 100.00 | 100.00 | Using where |
|
| 1 | SIMPLE | t3 | eq_ref | PRIMARY,attribute_id | PRIMARY | 4 | test.ce_varchar_0.value | 1 | 0.00 | 100.00 | 100.00 | Using where |
|
| 1 | SIMPLE | eao3 | index | NULL | attribute_id | 2 | NULL | 2447 | 2447.00 | 100.00 | 0.04 | Using where; Using index; Using join buffer (flat, BNL join) |
|
+------+-------------+--------------+--------+---------------------------------+------------------+---------+----------------------------------------------+------+---------+----------+------------+--------------------------------------------------------------+
|
6 rows in set (0.227 sec)
|
on debug build:
1af855819300ba4e4dd3d582c5c521ff99321152
SHOW PROFILES;
|
Query_ID Duration Query
|
1 1.67817776 SELECT DISTINCT 1 ...
|
90780bb5a949d5e27b39df4adaa1d7b1ad98948e
SHOW PROFILES;
|
Query_ID Duration Query
|
1 20.51277929 SELECT DISTINCT 1 ...
|
10.4 0c7af6a2a19343cb9d4fedbd7165b8
SHOW PROFILES;
|
Query_ID Duration Query
|
1 32.21734665 SELECT DISTINCT 1 ..
|
|
|
--source include/have_sequence.inc
|
|
CREATE TABLE t1 (b int NOT NULL, PRIMARY KEY (b));
|
INSERT INTO t1 select seq from seq_1_to_10000;
|
|
CREATE TABLE t3 ( c int NOT NULL, PRIMARY KEY (c)) ;
|
INSERT INTO t3 select seq from seq_1_to_3000;
|
|
CREATE TABLE t4 ( b int NOT NULL, d varchar(255), KEY (b)) ;
|
insert into t4 VALUES (1,1),(2,2),(3,3);
|
|
set session profiling = ON;
|
|
SELECT 1
|
FROM t1
|
LEFT JOIN t4 ON t1.b = t4.b
|
LEFT JOIN t3 ON t4.d = t3.c
|
LEFT JOIN t3 AS eao3 ON t3.c=1;
|
|
SHOW PROFILES;
|
|
set session profiling = OFF;
|
|
|
Folks, igor has done a first proof of concept fix. This hasn't been reviewed yet, but if you are able to test this on a non-production environment we welcome the feedback.
The container image: quay.io/mariadb-foundation/mariadb-devel:10.4-mdev-32351-pkgtest (arm64/amd64)
Various packages: https://ci.mariadb.org/39481/
Debian repos can use a repo line:
deb [trusted=yes] https://ci.mariadb.org/39481/amd64-ubuntu-2204-deb-autobake/debs ./
|
Adjust arch/distro/distro version as need.
RPM autobake directories have a repo file in them that can be used.
Feedback welcome.
|
|
With 10.4.32 build, the query takes 08mn 24s on the same VM used for previous testing (8mn 03s with 10.4.18 and 3hours 48mn 28s with 10.4.19).
So fhe fix look good to me.
I added 10.4.32 FlameGraph to the issue.
|
|
Thanks for testing cypx. Good to know the positive case worked. As we arrived at this bug however its making sure all the other queries also perform correctly and fast as well.
|
|
cypx, I should have also asked, the result was correct for the query?
|
|
Daniel Black, The result was correct and it was the same between 10.4.18 & 10.4.32 (diff & md5 match).
|
|
igor, it's a problem that there's no visible test coverage for "Don't unpack the buffer if we have MATCH_IMPOSSIBLE" functionality.
I've backported r_unpack_time_ms patch from 10.6: https://github.com/MariaDB/server/commit/a9cf22654e99b6b40d7eedd6e7443c1a2813da17
After that, one can do with a very small patch to add tests for this: https://github.com/MariaDB/server/commit/5745468d17e6f48d136935329a55cc97090024e1
Both patches are in bb-10.4-mdev32351-tests, on top of your fix. What do you think?
|
|
... The fix itself is ok, although it's difficult to understand.
|
explain_10237.txt
mdev-32351.test
