[MDEV-8851] innodb.innodb_information_schema fails sporadically in buildbot Created: 2015-09-26  Updated: 2022-01-14  Resolved: 2022-01-14

Status: Closed
Project: MariaDB Server
Component/s: Tests
Affects Version/s: 5.5, 10.0, 10.1, 10.2, 10.3, 10.4, 10.5
Fix Version/s: 10.2.42, 10.3.33, 10.4.23, 10.5.14, 10.6.6, 10.7.2, 10.8.1

Type: Bug Priority: Minor
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-7069 Fix buildbot failures in main server ... Stalled
relates to MDEV-14756 Remove trx_sys_t::rw_trx_list Closed

 Description   

Happens very rarely, only a few occurrences according to the cross-reference report, mainly on bld-dan-debug:
http://buildbot.askmonty.org/buildbot/builders/bld-dan-debug/builds/2452/steps/test/logs/stdio

innodb.innodb_information_schema 'innodb_plugin' w2 [ fail ]
 
        Test ended at 2015-09-26 15:07:00
 
 
 
CURRENT_TEST: innodb.innodb_information_schema
 
--- /opt/buildbot-slave/mariadb/dan_demeter1/build/mysql-test/suite/innodb/r/innodb_information_schema.result	2015-09-26 13:47:18.270782937 +0300
 
+++ /opt/buildbot-slave/mariadb/dan_demeter1/build/mysql-test/suite/innodb/r/innodb_information_schema.reject	2015-09-26 15:07:00.729228344 +0300
 
@@ -1,18 +1,18 @@
 
 lock_mode	lock_type	lock_table	lock_index	lock_rec	lock_data
 
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	2	'1', 'abc', '''abc', 'abc''', 'a''bc', 'a''bc''', '''abc'''''
 
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	2	'1', 'abc', '''abc', 'abc''', 'a''bc', 'a''bc''', '''abc'''''
 
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	3	'2', 'abc', '"abc', 'abc"', 'a"bc', 'a"bc"', '"abc""'
 
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	3	'2', 'abc', '"abc', 'abc"', 'a"bc', 'a"bc"', '"abc""'
 
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	4	'3', 'abc', '\\abc', 'abc\\', 'a\\bc', 'a\\bc\\', '\\abc\\\\'
 
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	4	'3', 'abc', '\\abc', 'abc\\', 'a\\bc', 'a\\bc\\', '\\abc\\\\'
 
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	5	'4', 'abc', '\0abc', 'abc\0', 'a\0bc', 'a\0bc\0', 'a\0bc\0\0'
 
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	5	'4', 'abc', '\0abc', 'abc\0', 'a\0bc', 'a\0bc\0', 'a\0bc\0\0'
 
+X	RECORD	`test`.```t'\"_str`	`PRIMARY`	3	NULL
 
+X	RECORD	`test`.```t'\"_str`	`PRIMARY`	3	NULL
 
+X	RECORD	`test`.```t'\"_str`	`PRIMARY`	1	NULL
 
+X	RECORD	`test`.```t'\"_str`	`PRIMARY`	1	NULL
 
+X	RECORD	`test`.```t'\"_str`	`PRIMARY`	2	NULL
 
+X	RECORD	`test`.```t'\"_str`	`PRIMARY`	2	NULL
 
+X	RECORD	`test`.```t'\"_str`	`PRIMARY`	5	NULL
 
+X	RECORD	`test`.```t'\"_str`	`PRIMARY`	4	NULL
 
+X	RECORD	`test`.```t'\"_str`	`PRIMARY`	4	NULL
 
+X	RECORD	`test`.```t'\"_str`	`PRIMARY`	5	NULL
 
 X	RECORD	`test`.`t_min`	`PRIMARY`	2	-128, 0, -32768, 0, -8388608, 0, -2147483648, 0, -9223372036854775808, 0
 
 X	RECORD	`test`.`t_min`	`PRIMARY`	2	-128, 0, -32768, 0, -8388608, 0, -2147483648, 0, -9223372036854775808, 0
 
 X	RECORD	`test`.`t_max`	`PRIMARY`	2	127, 255, 32767, 65535, 8388607, 16777215, 2147483647, 4294967295, 9223372036854775807, 18446744073709551615
 
 X	RECORD	`test`.`t_max`	`PRIMARY`	2	127, 255, 32767, 65535, 8388607, 16777215, 2147483647, 4294967295, 9223372036854775807, 18446744073709551615
 
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	1	supremum pseudo-record
 
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	1	supremum pseudo-record
 
 lock_table	COUNT(*)
 
 `test`.`t_max`	2
 
 `test`.`t_min`	2

Re-running the same sequence of tests on a local machine did not reproduce the problem.



 Comments   
Comment by Marko Mäkelä [ 2018-02-26 ]

The test is nondeterministic. If the page containing the locked record is not in the buffer pool, NULL will be reported instead of the key of the record.

In MariaDB 10.3.5 this failure might occur more easily, because a performance fix of MDEV-14756 removed the code that would attempt to load the page into the buffer pool some time before trying to dump the contents. Here is a recent failure:

CURRENT_TEST: innodb.innodb_information_schema
 
--- /usr/share/mysql/mysql-test/suite/innodb/r/innodb_information_schema.result	2018-02-25 22:27:15.000000000 -0500
 
+++ /dev/shm/var/4/log/innodb_information_schema.reject	2018-02-25 23:57:20.610548619 -0500
 
@@ -1,10 +1,10 @@
 
 lock_mode	lock_type	lock_table	lock_index	lock_rec	lock_data
 
-X	RECORD	`test`.```t'\"_str`	PRIMARY	2	'1', 'abc', '''abc', 'abc''', 'a''bc', 'a''bc''', '''abc'''''
 
+X	RECORD	`test`.```t'\"_str`	PRIMARY	2	NULL
 
+X	RECORD	`test`.```t'\"_str`	PRIMARY	4	NULL
 
+X	RECORD	`test`.```t'\"_str`	PRIMARY	4	NULL
 
 X	RECORD	`test`.```t'\"_str`	PRIMARY	2	'1', 'abc', '''abc', 'abc''', 'a''bc', 'a''bc''', '''abc'''''
 
 X	RECORD	`test`.```t'\"_str`	PRIMARY	3	'2', 'abc', '"abc', 'abc"', 'a"bc', 'a"bc"', '"abc""'
 
 X	RECORD	`test`.```t'\"_str`	PRIMARY	3	'2', 'abc', '"abc', 'abc"', 'a"bc', 'a"bc"', '"abc""'
 
-X	RECORD	`test`.```t'\"_str`	PRIMARY	4	'3', 'abc', '\\abc', 'abc\\', 'a\\bc', 'a\\bc\\', '\\abc\\\\'
 
-X	RECORD	`test`.```t'\"_str`	PRIMARY	4	'3', 'abc', '\\abc', 'abc\\', 'a\\bc', 'a\\bc\\', '\\abc\\\\'
 
 X	RECORD	`test`.```t'\"_str`	PRIMARY	5	'4', 'abc', '\0abc', 'abc\0', 'a\0bc', 'a\0bc\0', 'a\0bc\0\0'
 
 X	RECORD	`test`.```t'\"_str`	PRIMARY	5	'4', 'abc', '\0abc', 'abc\0', 'a\0bc', 'a\0bc\0', 'a\0bc\0\0'
 
 X	RECORD	`test`.`t_min`	PRIMARY	2	-128, 0, -32768, 0, -8388608, 0, -2147483648, 0, -9223372036854775808, 0
 
 
 
mysqltest: Result length mismatch

Because this is the only test that covers the conversion of the record values, I think that we must include the column in the output.

A simple fix might be to re-bootstrap the server before the test, so that no background operations (change buffer merge, purge) can cause the pages to be evicted. The test is only inserting a few records; it does not use much buffer pool by itself.
Another possibility would be to restart the server with innodb_force_recovery=4 between the INSERT and SELECT. This could corrupt any secondary indexes, but the test itself is not creating any tables with secondary indexes.

Comment by Marko Mäkelä [ 2020-08-26 ]

It turns out that 10.5 is affected too, and because 10.5 includes MDEV-19514, my earlier idea of using innodb_force_recovery=4 might not have worked.
http://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-amd64-debug/builds/4542

10.5 a18639f1a913b446f32d7fbe531aa0d5782cf720

 
innodb.innodb_information_schema 'innodb' w2 [ fail ]
 
        Test ended at 2020-07-23 22:57:30
 
 
 
CURRENT_TEST: innodb.innodb_information_schema
 
--- /usr/share/mysql-test/suite/innodb/r/innodb_information_schema.result	2020-07-23 18:55:27.000000000 +0000
 
+++ /dev/shm/var/2/log/innodb_information_schema.reject	2020-07-23 22:57:30.318387939 +0000
 
@@ -1,12 +1,12 @@
 
 lock_mode	lock_type	lock_table	lock_index	lock_rec	lock_data
 
-X	RECORD	`test`.```t'\"_str`	PRIMARY	2	'1', 'abc', '''abc', 'abc''', 'a''bc', 'a''bc''', '''abc'''''
 
-X	RECORD	`test`.```t'\"_str`	PRIMARY	2	'1', 'abc', '''abc', 'abc''', 'a''bc', 'a''bc''', '''abc'''''
 
-X	RECORD	`test`.```t'\"_str`	PRIMARY	3	'2', 'abc', '"abc', 'abc"', 'a"bc', 'a"bc"', '"abc""'
 
-X	RECORD	`test`.```t'\"_str`	PRIMARY	3	'2', 'abc', '"abc', 'abc"', 'a"bc', 'a"bc"', '"abc""'
 
-X	RECORD	`test`.```t'\"_str`	PRIMARY	4	'3', 'abc', '\\abc', 'abc\\', 'a\\bc', 'a\\bc\\', '\\abc\\\\'
 
-X	RECORD	`test`.```t'\"_str`	PRIMARY	4	'3', 'abc', '\\abc', 'abc\\', 'a\\bc', 'a\\bc\\', '\\abc\\\\'
 
-X	RECORD	`test`.```t'\"_str`	PRIMARY	5	'4', 'abc', '\0abc', 'abc\0', 'a\0bc', 'a\0bc\0', 'a\0bc\0\0'
 
-X	RECORD	`test`.```t'\"_str`	PRIMARY	5	'4', 'abc', '\0abc', 'abc\0', 'a\0bc', 'a\0bc\0', 'a\0bc\0\0'
 
+X	RECORD	`test`.```t'\"_str`	PRIMARY	5	NULL
 
+X	RECORD	`test`.```t'\"_str`	PRIMARY	3	NULL
 
+X	RECORD	`test`.```t'\"_str`	PRIMARY	5	NULL
 
+X	RECORD	`test`.```t'\"_str`	PRIMARY	2	NULL
 
+X	RECORD	`test`.```t'\"_str`	PRIMARY	4	NULL
 
+X	RECORD	`test`.```t'\"_str`	PRIMARY	2	NULL
 
+X	RECORD	`test`.```t'\"_str`	PRIMARY	3	NULL
 
+X	RECORD	`test`.```t'\"_str`	PRIMARY	4	NULL
 
 X	RECORD	`test`.`t_min`	PRIMARY	2	-128, 0, -32768, 0, -8388608, 0, -2147483648, 0, -9223372036854775808, 0
 
 X	RECORD	`test`.`t_min`	PRIMARY	2	-128, 0, -32768, 0, -8388608, 0, -2147483648, 0, -9223372036854775808, 0
 
 X	RECORD	`test`.`t_max`	PRIMARY	2	127, 255, 32767, 65535, 8388607, 16777215, 2147483647, 4294967295, 9223372036854775807, 18446744073709551615
 
 
 
mysqltest: Result length mismatch

Comment by Marko Mäkelä [ 2022-01-14 ]

I thought that the easiest fix was to filter out the lock_data column from the output. It is not perfect, because our regression test will now be unable to catch real regressions in that functionality.

Generated at Thu Feb 08 07:30:16 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.