[MDEV-14204] innodb.log_data_file_size failed in buildbot, server failed to start Created: 2017-10-29  Updated: 2022-02-14  Resolved: 2022-02-14

Status: Closed
Project: MariaDB Server
Component/s: Tests
Affects Version/s: 10.2
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Unassigned
Resolution: Cannot Reproduce Votes: 0
Labels: None


 Description   

http://buildbot.askmonty.org/buildbot/builders/win32-debug/builds/5966/steps/test/logs/stdio
http://buildbot.askmonty.org/buildbot/builders/win32-debug/builds/5966/steps/test/logs/mysqld.1.err.4

innodb.log_data_file_size '4k,innodb'    w4 [ fail ]
 
        Test ended at 2017-10-25 23:14:18
 
 
 
CURRENT_TEST: innodb.log_data_file_size
 
 
 
 
 
Failed to start mysqld.1
 
mysqltest failed but provided no output
 
The result from queries just before the failure was:
 
< snip >
 
SET GLOBAL innodb_file_per_table=0;
 
CREATE TABLE t(a INT)ENGINE=InnoDB;
 
SET GLOBAL innodb_file_per_table=1;
 
CREATE TABLE ibd4(a INT UNIQUE)ENGINE=InnoDB;
 
CREATE TABLE ibd4f(a INT UNIQUE)ENGINE=InnoDB;
 
CREATE TABLE ibd5(a INT UNIQUE, b INT UNIQUE)ENGINE=InnoDB;
 
# Kill the server
 
DROP TABLE t,ibd4,ibd4f,ibd5;


CURRENT_TEST: innodb.log_data_file_size
 
2017-10-25 23:10:36 3584 [Note] D:/win32-debug/build/sql//Debug/mysqld.exe (mysqld 10.2.10-MariaDB-debug-log) starting as process 4744 ...
 
2017-10-25 23:10:36 3584 [Note] Plugin 'partition' is disabled.
 
2017-10-25 23:10:36 3584 [Note] InnoDB: innodb_page_size=4096
 
2017-10-25 23:10:36 3584 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
 
2017-10-25 23:10:36 3584 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
 
2017-10-25 23:10:36 3584 [Note] InnoDB: Uses event mutexes
 
2017-10-25 23:10:36 3584 [Note] InnoDB: Compressed tables use zlib 1.2.3
 
2017-10-25 23:10:36 3584 [Note] InnoDB: Number of pools: 1
 
2017-10-25 23:10:36 3584 [Note] InnoDB: Using generic crc32 instructions
 
2017-10-25 23:10:36 3584 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
 
2017-10-25 23:10:36 3584 [Note] InnoDB: Completed initialization of buffer pool
 
2017-10-25 23:10:36 3584 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-10-25 23:10:36 3584 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
2017-10-25 23:10:36 3584 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2017-10-25 23:10:36 3584 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2017-10-25 23:10:36 3584 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB.
 
2017-10-25 23:10:37 3584 [Note] InnoDB: Waiting for purge to start
 
2017-10-25 23:10:37 3584 [Note] InnoDB: 5.7.20 started; log sequence number 730979
 
2017-10-25 23:10:37 2604 [Note] InnoDB: Loading buffer pool(s) from D:\win32-debug\build\mysql-test\var\4\mysqld.1\data\ib_buffer_pool
 
2017-10-25 23:10:37 3584 [Note] Plugin 'SEQUENCE' is disabled.
 
2017-10-25 23:10:37 3584 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
 
2017-10-25 23:10:37 3584 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
 
2017-10-25 23:10:37 3584 [Note] Plugin 'INNODB_MUTEXES' is disabled.
 
2017-10-25 23:10:37 3584 [Note] Plugin 'INNODB_CMP' is disabled.
 
2017-10-25 23:10:37 3584 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
 
2017-10-25 23:10:37 3584 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
 
2017-10-25 23:10:37 3584 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
 
2017-10-25 23:10:37 3584 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
 
2017-10-25 23:10:37 3584 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
 
2017-10-25 23:10:37 3584 [Note] Plugin 'FEEDBACK' is disabled.
 
2017-10-25 23:10:37 3584 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
 
2017-10-25 23:10:37 3584 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
 
2017-10-25 23:10:37 3584 [Note] Plugin 'user_variables' is disabled.
 
2017-10-25 23:10:37 2604 [Note] InnoDB: Buffer pool(s) load completed at 171025 23:10:37
 
CURRENT_TEST: innodb.log_data_file_size
 
2017-10-25 23:14:28 516 [Note] D:/win32-debug/build/sql//Debug/mysqld.exe (mysqld 10.2.10-MariaDB-debug-log) starting as process 3556 ...
 
2017-10-25 23:14:28 516 [Note] Plugin 'partition' is disabled.
 
2017-10-25 23:14:28 516 [Note] InnoDB: innodb_page_size=4096
 
2017-10-25 23:14:28 516 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
 
2017-10-25 23:14:28 516 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
 
2017-10-25 23:14:28 516 [Note] InnoDB: Uses event mutexes
 
2017-10-25 23:14:28 516 [Note] InnoDB: Compressed tables use zlib 1.2.3
 
2017-10-25 23:14:28 516 [Note] InnoDB: Number of pools: 1
 
2017-10-25 23:14:28 516 [Note] InnoDB: Using generic crc32 instructions
 
2017-10-25 23:14:28 516 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
 
2017-10-25 23:14:28 516 [Note] InnoDB: Completed initialization of buffer pool
 
2017-10-25 23:14:29 516 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-10-25 23:14:29 516 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
2017-10-25 23:14:29 516 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2017-10-25 23:14:29 516 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2017-10-25 23:14:29 516 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB.
 
2017-10-25 23:14:29 516 [Note] InnoDB: Waiting for purge to start
 
2017-10-25 23:14:29 516 [Note] InnoDB: 5.7.20 started; log sequence number 730979
 
2017-10-25 23:14:30 796 [Note] InnoDB: Loading buffer pool(s) from D:\win32-debug\build\mysql-test\var\4\mysqld.1\data\ib_buffer_pool
 
2017-10-25 23:14:30 516 [Note] Plugin 'SEQUENCE' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_MUTEXES' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_CMP' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'FEEDBACK' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'user_variables' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
 
2017-10-25 23:14:30 516 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
 
2017-10-25 23:14:30 516 [Warning] D:/win32-debug/build/sql//Debug/mysqld.exe: unknown option '--loose-pam-debug'
 
2017-10-25 23:14:30 516 [Note] Server socket created on IP: '::'.
 
2017-10-25 23:14:30 796 [Note] InnoDB: Buffer pool(s) load completed at 171025 23:14:30
 
2017-10-25 23:14:30 516 [Note] Reading of all Master_info entries succeded
 
2017-10-25 23:14:30 516 [Note] Added new Master_info '' to hash table
 
2017-10-25 23:14:30 516 [Note] D:/win32-debug/build/sql//Debug/mysqld.exe: ready for connections.
 
Version: '10.2.10-MariaDB-debug-log'  socket: ''  port: 16140  Source distribution



 Comments   
Comment by Marko Mäkelä [ 2022-02-14 ]

As far as I can tell, the last failure of this test for a main branch was on 2021-09-17, due to a problem with the environment (ENOSPC on s390x). Before that, the last failure was on 2021-02-26:

10.3 25ecf8ed4b4cbca69a9fa09c27bbd4e5c83fafe3

 
innodb.log_data_file_size '16k,innodb'   w14 [ fail ]
 
        Test ended at 2021-02-26 12:50:44
 
 
 
CURRENT_TEST: innodb.log_data_file_size
 
mysqltest: At line 79: query '$drop_tables' failed: 2013: Lost connection to MySQL server during query
 
…
 
mysqld: /buildbot/amd64-ubuntu-1804-debug/build/storage/innobase/fil/fil0fil.cc:784: void fil_flush_low(fil_space_t*, bool): Assertion `!space->is_stopping()' failed.

Whatever the reason of the original failure was, it should have been fixed by now, because we have not had any genuine failures for almost a year now.

It looks like for 10.2, the very last known failure was this reported one, on Windows, on 2017-10-25:

10.2 e99c7c8334f842a6515a3116fe2cafd5

 
innodb.log_data_file_size '4k,innodb'    w4 [ fail ]
 
        Test ended at 2017-10-25 23:14:18
 
 
 
CURRENT_TEST: innodb.log_data_file_size
 
 
 
 
 
Failed to start mysqld.1
 
mysqltest failed but provided no output
 
The result from queries just before the failure was:
 
< snip >
 
SET GLOBAL innodb_file_per_table=0;
 
CREATE TABLE t(a INT)ENGINE=InnoDB;
 
SET GLOBAL innodb_file_per_table=1;
 
CREATE TABLE ibd4(a INT UNIQUE)ENGINE=InnoDB;
 
CREATE TABLE ibd4f(a INT UNIQUE)ENGINE=InnoDB;
 
CREATE TABLE ibd5(a INT UNIQUE, b INT UNIQUE)ENGINE=InnoDB;
 
# Kill the server
 
DROP TABLE t,ibd4,ibd4f,ibd5;
 
 
 
 
 
 
 
 - saving 'D:/win32-debug/build/mysql-test/var/4/log/innodb.log_data_file_size-4k,innodb/' to 'D:/win32-debug/build/mysql-test/var/log/innodb.log_data_file_size-4k,innodb/'
 
 
 
Retrying test innodb.log_data_file_size, attempt(2/3)...

Generated at Thu Feb 08 08:11:44 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.