[MDEV-30629] Add optimizer trace to main/order_by_innodb.test to diagnose debian build issue Created: 2023-02-09  Updated: 2023-03-19

Status: Open
Project: MariaDB Server
Component/s: Optimizer
Affects Version/s: 10.11
Fix Version/s: 10.11

Type: Bug Priority: Minor
Reporter: Rex Johnston Assignee: Rex Johnston
Resolution: Unresolved Votes: 0
Labels: None
Environment:

IBM s390, debian


 Description   

mysql test failing, add trace to aid diagnostics

CURRENT_TEST: main.order_by_innodb
 
--- /<<PKGBUILDDIR>>/mysql-test/main/order_by_innodb.result	2022-11-14 18:10:21.000000000 +0000
 
+++ /<<PKGBUILDDIR>>/mysql-test/main/order_by_innodb.reject	2023-02-06 01:30:20.732947938 +0000
 
@@ -250,7 +250,7 @@
 
 id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
 
 1	PRIMARY	t1	index	NULL	PRIMARY	4	NULL	#	Using index
 
 1	PRIMARY	t2	eq_ref	PRIMARY,id2	PRIMARY	4	func	#	Using where
 
-2	DEPENDENT SUBQUERY	dd	range	id2,for_latest_sort	for_latest_sort	6	NULL	#	Using where
 
+2	DEPENDENT SUBQUERY	dd	ref	id2,for_latest_sort	id2	4	test.t1.id	#	Using where; Using filesort
 
 drop table t1,t2,t3;



 Comments   
Comment by Otto Kekäläinen [ 2023-02-10 ]

This was tested in https://salsa.debian.org/mariadb-team/mariadb-server/-/merge_requests/35

Comment by Otto Kekäläinen [ 2023-02-10 ]

Now I saw the same test fail on ppc64el autopkgtest in Debian with different error: https://ci.debian.net/data/autopkgtest/testing/ppc64el/m/mariadb/31204767/log.gz

main.order_by_innodb 'innodb'            w5 [ fail ]
 
        Test ended at 2023-02-10 12:41:13
 
 
 
CURRENT_TEST: main.order_by_innodb
 
mysqltest: At line 191: query 'CREATE TABLE t3 (
 
id int NOT NULL PRIMARY KEY,
 
id2 int NOT NULL,
 
d1 datetime,
 
d2 timestamp NOT NULL,
 
KEY id2 (id2)
 
) engine=innodb' failed: <Unknown> (2013): Lost connection to server during query
 
 
 
The result from queries just before the failure was:
 
< snip >
 
t2.id = (select dd.id
 
from t2 dd
 
where
 
dd.id2 = t1.id and
 
d1 > '2019-02-06 00:00:00'
 
                 order by
 
dd.d1 desc, dd.d2 desc, dd.id desc limit 1
 
);
 
id	id
 
1	NULL
 
2	1
 
3	3
 
# Now, same as above but use a DESC index
 
CREATE TABLE t3 (
 
id int NOT NULL PRIMARY KEY,
 
id2 int NOT NULL,
 
d1 datetime,
 
d2 timestamp NOT NULL,
 
KEY id2 (id2)
 
) engine=innodb;
 
 
 
More results from queries before failure can be found in /tmp/tmp.8Mt1GzsIvB/var/5/log/order_by_innodb.log
 
 
 
 
 
Server [mysqld.1 - pid: 6871, winpid: 6871, exit: 256] failed during test run
 
Server log from this test:
 
----------SERVER LOG START-----------
 
2023-02-10 12:41:11 56 [ERROR] InnoDB: Database page corruption on disk or a failed read of file './ibdata1' page [page id: space=0, page number=386]. You may have to recover from a backup.
 
2023-02-10 12:41:11 56 [Note] InnoDB: Page dump (16384 bytes):
 
2023-02-10 12:41:11 56 [Note] InnoDB: 0000000000000182ffffffffffffffff00000000001b16f30002000000000000
 
2023-02-10 12:41:11 56 [Note] InnoDB: 000000000000000006000b78ffffffff0000ffffffff00000002054600000000
 
2023-02-10 12:41:11 56 [Note] InnoDB: 000001442d320000000100000182002c00000182002c00000000000000bb0000
 
2023-02-10 12:41:11 56 [Note] InnoDB: 0000000000bc000101100000000000000000000003b800000000018203daffff
 
2023-02-10 12:41:11 56 [Note] InnoDB: ffff000000000000000000000000000000000000000000000000000000000000
 
2023-02-10 12:41:11 56 [Note] InnoDB: 0000000000000000000000000000000000000000000000000000000000000000
 
2023-02-10 12:41:11 56 [Note] InnoDB: 0000000000000000000000000000000000000000000000000000000000000000
 
2023-02-10 12:41:11 56 [Note] InnoDB: 0000000000000000000000000000000000000000000000000000000000000000
 
2023-02-10 12:41:11 56 [Note] InnoDB: 0000000000000000000000000000000001390e000e0000000000b7e0dd000001
 
2023-02-10 12:41:11 56 [Note] InnoDB: 8001100474657374027432000c000474657374010274320110016d0d010e2000
 
...

Comment by Otto Kekäläinen [ 2023-02-12 ]

Fixed the above in https://salsa.debian.org/mariadb-team/mariadb-server/-/commit/91680f5590c41685e2b4d977527b76f7ed7f92b6 and pushed to Launchpad (https://launchpad.net/~mysql-ubuntu/+archive/ubuntu/mariadb-10.11/+builds?build_text=&build_state=all) again to hopefully catch the sporadic error in main.order_by_innodb.

Comment by Rex Johnston [ 2023-02-12 ]

It doesn't seem to be restricted to (debian; s390) architecture. From one of the above links (ubuntu; arm64)

CURRENT_TEST: main.order_by_innodb
 
--- /<<PKGBUILDDIR>>/mysql-test/main/order_by_innodb.result	2023-02-12 03:07:47.000000000 +0000
 
+++ /<<PKGBUILDDIR>>/mysql-test/main/order_by_innodb.reject	2023-02-12 03:32:47.694681917 +0000
 
@@ -591,6 +591,7 @@
 
                               {
 
                                 "access_type": "ref",
 
                                 "index": "id2",
 
+                                "rowid_filter_skipped": "cost_factor <= 0",
 
                                 "rows": 1,
 
                                 "cost": 2.00009765,
 
                                 "chosen": true
 
 
 
mysqltest: Result length mismatch

This correlates with some recent rowid filter changes in the optimizer.
Unsure yet about the file corruption.

Comment by Otto Kekäläinen [ 2023-02-19 ]

Added patch on Debian packaging permanently now via https://salsa.debian.org/mariadb-team/mariadb-server/-/commit/d5409b97de6acff701953c5641c9a06ffb884fc1 to debug failure in case we are lucky to see it again (typically on s390x or ppc64el).

Comment by Otto Kekäläinen [ 2023-03-19 ]

Related, I saw failure in https://buildd.debian.org/status/fetch.php?pkg=mariadb&arch=s390x&ver=1%3A10.11.2-2%7Eexp1&stamp=1678722906&raw=0 of related test:

main.order_by_optimizer_innodb 'innodb'  w2 [ fail ]
 
        Test ended at 2023-03-13 15:50:29
 
CURRENT_TEST: main.order_by_optimizer_innodb
 
--- /<<PKGBUILDDIR>>/mysql-test/main/order_by_optimizer_innodb.result 2023-02-01 17:28:03.000000000 +0000
 
+++ /<<PKGBUILDDIR>>/mysql-test/main/order_by_optimizer_innodb.reject 2023-03-13 15:50:19.568856370 +0000
 
@@ -41,7 +41,7 @@
 
 # The following should use range(ux_pk1_fd5), two key parts (key_len=5+8=13)
 
 EXPLAIN SELECT * FROM t2 USE INDEX(ux_pk1_fd5) WHERE pk1=9 AND fd5 < 500 ORDER BY fd5 DESC LIMIT 10;
 
 id select_type table type possible_keys key key_len ref rows Extra
 
-1 SIMPLE t2 range ux_pk1_fd5 ux_pk1_fd5 13 NULL 138 Using where
 
+1 SIMPLE t2 ref ux_pk1_fd5 ux_pk1_fd5 4 const 138 Using where
 
 # This also must use range, not ref. key_len must be 13
 
 EXPLAIN SELECT * FROM t2                       WHERE pk1=9 AND fd5 < 500 ORDER BY fd5 DESC LIMIT 10;
 
 id select_type table type possible_keys key key_len ref rows Extra

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