[MDEV-18717] Server crash when trying to alter add Primary Key to InnoDB table Created: 2019-02-24  Updated: 2019-03-11  Resolved: 2019-03-11

Status: Closed
Project: MariaDB Server
Component/s: OTHER
Affects Version/s: 10.3.13
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Stefan Vartolomeev Assignee: Unassigned
Resolution: Cannot Reproduce Votes: 0
Labels: None
Environment:

I have the latest mariadb docker container running on Windows 10 Home edition. MariaDB version: Server version: 10.3.13-MariaDB-1:10.3.13+maria~bionic-log


Attachments: File my.cnf    
Issue Links:
Relates
relates to MDEV-16124 fil_rename_tablespace() times out and... Closed

 Description   

Executing the following statement causes the DB to crash:

CREATE TABLE `atest` (
  `id` int NOT NULL,
  `name` varchar(20) NOT NULL
) ENGINE=InnoDB;
 
ALTER TABLE `atest` ADD PRIMARY KEY (`id`);

Here's the log I'm getting:

-- When the container is started
Database initialized
MySQL init process in progress...
2019-02-24 15:51:29 0 [Note] mysqld (mysqld 10.3.13-MariaDB-1:10.3.13+maria~bionic-log) starting as process 109 ...
2019-02-24 15:51:29 0 [Warning] Setting lower_case_table_names=2 because file system for /var/lib/mysql/ is case insensitive
2019-02-24 15:51:29 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-02-24 15:51:29 0 [Note] InnoDB: Uses event mutexes
2019-02-24 15:51:29 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-02-24 15:51:29 0 [Note] InnoDB: Number of pools: 1
2019-02-24 15:51:29 0 [Note] InnoDB: Using SSE2 crc32 instructions
2019-02-24 15:51:29 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
2019-02-24 15:51:29 0 [Note] InnoDB: Completed initialization of buffer pool
2019-02-24 15:51:29 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-02-24 15:51:30 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-02-24 15:51:30 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-02-24 15:51:30 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
MySQL init process in progress...
2019-02-24 15:51:30 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2019-02-24 15:51:30 0 [Note] InnoDB: Waiting for purge to start
2019-02-24 15:51:31 0 [Note] InnoDB: 10.3.13 started; log sequence number 1630824; transaction id 21
2019-02-24 15:51:31 0 [Note] Plugin 'FEEDBACK' is disabled.
2019-02-24 15:51:31 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2019-02-24 15:51:31 0 [Note] InnoDB: Buffer pool(s) load completed at 190224 15:51:31
2019-02-24 15:51:31 0 [Warning] 'user' entry 'root@865e711deccc' ignored in --skip-name-resolve mode.
2019-02-24 15:51:31 0 [Warning] 'user' entry '@865e711deccc' ignored in --skip-name-resolve mode.
2019-02-24 15:51:31 0 [Warning] 'proxies_priv' entry '@% root@865e711deccc' ignored in --skip-name-resolve mode.
2019-02-24 15:51:31 0 [Note] Reading of all Master_info entries succeded
2019-02-24 15:51:31 0 [Note] Added new Master_info '' to hash table
2019-02-24 15:51:31 0 [Note] mysqld: ready for connections.
Version: '10.3.13-MariaDB-1:10.3.13+maria~bionic-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.
2019-02-24 15:52:10 11 [Warning] 'proxies_priv' entry '@% root@865e711deccc' ignored in --skip-name-resolve mode.
 
2019-02-24 15:52:10 0 [Note] mysqld (initiated by: unknown): Normal shutdown
2019-02-24 15:52:10 0 [Note] InnoDB: FTS optimize thread exiting.
2019-02-24 15:52:10 0 [Note] Event Scheduler: Purging the queue. 0 events
2019-02-24 15:52:10 0 [Note] InnoDB: Starting shutdown...
2019-02-24 15:52:10 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
2019-02-24 15:52:11 0 [Note] InnoDB: Buffer pool(s) dump completed at 190224 15:52:11
2019-02-24 15:52:11 0 [Note] InnoDB: Shutdown completed; log sequence number 1630833; transaction id 24
2019-02-24 15:52:11 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2019-02-24 15:52:11 0 [Note] mysqld: Shutdown complete
 
 
MySQL init process done. Ready for start up.
 
2019-02-24 15:52:11 0 [Note] mysqld (mysqld 10.3.13-MariaDB-1:10.3.13+maria~bionic-log) starting as process 1 ...
2019-02-24 15:52:11 0 [Warning] Setting lower_case_table_names=2 because file system for /var/lib/mysql/ is case insensitive
2019-02-24 15:52:11 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-02-24 15:52:11 0 [Note] InnoDB: Uses event mutexes
2019-02-24 15:52:11 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-02-24 15:52:11 0 [Note] InnoDB: Number of pools: 1
2019-02-24 15:52:11 0 [Note] InnoDB: Using SSE2 crc32 instructions
2019-02-24 15:52:11 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
2019-02-24 15:52:11 0 [Note] InnoDB: Completed initialization of buffer pool
2019-02-24 15:52:11 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-02-24 15:52:11 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-02-24 15:52:11 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-02-24 15:52:11 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-02-24 15:52:12 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2019-02-24 15:52:12 0 [Note] InnoDB: Waiting for purge to start
2019-02-24 15:52:12 0 [Note] InnoDB: 10.3.13 started; log sequence number 1630833; transaction id 21
2019-02-24 15:52:12 0 [Note] Plugin 'FEEDBACK' is disabled.
2019-02-24 15:52:12 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2019-02-24 15:52:12 0 [Note] InnoDB: Buffer pool(s) load completed at 190224 15:52:12
2019-02-24 15:52:12 0 [Note] Server socket created on IP: '::'.
2019-02-24 15:52:13 0 [Warning] 'proxies_priv' entry '@% root@865e711deccc' ignored in --skip-name-resolve mode.
2019-02-24 15:52:13 0 [Note] Reading of all Master_info entries succeded
2019-02-24 15:52:13 0 [Note] Added new Master_info '' to hash table
2019-02-24 15:52:13 0 [Note] mysqld: ready for connections.
Version: '10.3.13-MariaDB-1:10.3.13+maria~bionic-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
2019-02-24 15:52:56 9 [ERROR] InnoDB: Operating system error number 26 in a file operation.
2019-02-24 15:52:56 9 [ERROR] InnoDB: Error number 26 means 'Text file busy'
2019-02-24 15:52:56 9 [Note] InnoDB: Some operating system error numbers are described at https://mariadb.com/kb/en/library/operating-system-error-codes/
2019-02-24 15:52:56 9 [ERROR] InnoDB: Cannot rename file './appziodb/atest.ibd' to './appziodb/#sql-ib21.ibd'
2019-02-24 15:52:56 0x7fa05cc58700  InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.3.13/storage/innobase/handler/handler0alter.cc line 8817
InnoDB: Failing assertion: error == DB_SUCCESS
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
InnoDB: about forcing recovery.
190224 15:52:56 [ERROR] mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
 
Server version: 10.3.13-MariaDB-1:10.3.13+maria~bionic-log
key_buffer_size=134217728
read_buffer_size=2097152
max_used_connections=1
max_threads=102
thread_count=8
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 760012 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x7fa02400a498
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x7fa05cc57dd8 thread_stack 0x49000
mysqld(my_print_stacktrace+0x2e)[0x5560d5ade47e]
mysqld(handle_fatal_signal+0x5a5)[0x5560d557e295]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12890)[0x7fa07888a890]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xc7)[0x7fa077d9ee97]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x141)[0x7fa077da0801]
mysqld(+0x497cfc)[0x5560d52cecfc]
mysqld(+0x8e6df7)[0x5560d571ddf7]
mysqld(+0x48eac7)[0x5560d52c5ac7]
mysqld(_Z17mysql_alter_tableP3THDPK25st_mysql_const_lex_stringS3_P14HA_CREATE_INFOP10TABLE_LISTP10Alter_infojP8st_orderb+0x2ee0)[0x5560d5430ce0]
mysqld(_ZN19Sql_cmd_alter_table7executeEP3THD+0x3cf)[0x5560d5480b4f]
mysqld(_Z21mysql_execute_commandP3THD+0x1226)[0x5560d53a31e6]
mysqld(_Z11mysql_parseP3THDPcjP12Parser_statebb+0x20a)[0x5560d53aaa4a]
mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0x1cc7)[0x5560d53ad447]
mysqld(_Z10do_commandP3THD+0x178)[0x5560d53ae1e8]
mysqld(_Z24do_handle_one_connectionP7CONNECT+0x212)[0x5560d547dd92]
mysqld(handle_one_connection+0x3d)[0x5560d547df6d]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db)[0x7fa07887f6db]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7fa077e8188f]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7fa02401b160): ALTER TABLE `atest` ADD PRIMARY KEY (`id`)
Connection ID (thread ID): 9
Status: NOT_KILLED
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on


-- HERE The container restarts and then I'm getting this log output and the container restarts again

2019-02-24 15:57:19 0 [Note] mysqld (mysqld 10.3.13-MariaDB-1:10.3.13+maria~bionic-log) starting as process 1 ...
2019-02-24 15:57:20 0 [Warning] Setting lower_case_table_names=2 because file system for /var/lib/mysql/ is case insensitive
2019-02-24 15:57:20 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-02-24 15:57:20 0 [Note] InnoDB: Uses event mutexes
2019-02-24 15:57:20 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-02-24 15:57:20 0 [Note] InnoDB: Number of pools: 1
2019-02-24 15:57:20 0 [Note] InnoDB: Using SSE2 crc32 instructions
2019-02-24 15:57:20 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
2019-02-24 15:57:20 0 [Note] InnoDB: Completed initialization of buffer pool
2019-02-24 15:57:20 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-02-24 15:57:20 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1635517
2019-02-24 15:57:20 0 [Note] InnoDB: Ignoring data file './appziodb/atest.ibd' with space ID 6. Another data file called ./appziodb/#sql-1_9.ibd exists with the same space ID.
2019-02-24 15:57:20 0 [Note] InnoDB: Ignoring data file './appziodb/atest.ibd' with space ID 5. Another data file called ./appziodb/#sql-ib21.ibd exists with the same space ID.
2019-02-24 15:57:20 0 [Note] InnoDB: Ignoring data file './appziodb/atest.ibd' with space ID 6. Another data file called ./appziodb/#sql-1_9.ibd exists with the same space ID.
2019-02-24 15:57:20 0 [ERROR] InnoDB: Operating system error number 26 in a file operation.
2019-02-24 15:57:20 0 [ERROR] InnoDB: Error number 26 means 'Text file busy'
2019-02-24 15:57:20 0 [Note] InnoDB: Some operating system error numbers are described at https://mariadb.com/kb/en/library/operating-system-error-codes/
2019-02-24 15:57:20 0 [ERROR] InnoDB: Cannot rename file './appziodb/#sql-1_9.ibd' to './appziodb/atest.ibd'
2019-02-24 15:57:20 0x7fb1da2ca7c0  InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.3.13/storage/innobase/fil/fil0fil.cc line 2245
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
InnoDB: about forcing recovery.
190224 15:57:20 [ERROR] mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
 
Server version: 10.3.13-MariaDB-1:10.3.13+maria~bionic-log
key_buffer_size=134217728
read_buffer_size=2097152
max_used_connections=0
max_threads=102
thread_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 760012 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x0 thread_stack 0x49000
mysqld(my_print_stacktrace+0x2e)[0x561566e4d47e]
mysqld(handle_fatal_signal+0x5a5)[0x5615668ed295]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12890)[0x7fb1d864c890]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xc7)[0x7fb1d7b60e97]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x141)[0x7fb1d7b62801]
mysqld(+0x497cfc)[0x56156663dcfc]
mysqld(+0xac3f1e)[0x561566c69f1e]
mysqld(+0x92370b)[0x561566ac970b]
mysqld(+0x92654f)[0x561566acc54f]
mysqld(+0x926a07)[0x561566acca07]
mysqld(+0x92704b)[0x561566acd04b]
mysqld(+0x927443)[0x561566acd443]
mysqld(+0x927a01)[0x561566acda01]
mysqld(+0x9d3cd1)[0x561566b79cd1]
mysqld(+0x8c6741)[0x561566a6c741]
mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x62)[0x5615668ef8f2]
mysqld(+0x57ffa9)[0x561566725fa9]
mysqld(_Z11plugin_initPiPPci+0x85a)[0x56156672710a]
mysqld(+0x4b6df1)[0x56156665cdf1]
mysqld(_Z11mysqld_mainiPPc+0x53a)[0x56156666302a]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe7)[0x7fb1d7b43b97]
mysqld(_start+0x2a)[0x561566655f1a]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Fatal signal 11 while backtracing

Attached is also the my.cnf. Because of issues with O_DIRECT and VirtualBox I had to use this configuration in order to run on windows:
innodb_use_native_aio=0
innodb_flush_method=O_DSYNC
log_bin=ON



 Comments   
Comment by Vladislav Vaintroub [ 2019-02-28 ]

I tried to reproduce the same, but could not ,with the docker toolbox, as there is no native docker on Windows home edition.
I started the container with

$ docker run --name mariadbtest -e MYSQL_ROOT_PASSWORD=mypass -d mariadb/server:10.3 --innodb-use-native-aio=0 --log-bi
n=ON --innodb-flush-method=O_DSYNC

Also with default settings, i.e without innodb-use-native-aio=0, it the commands worked fine. Im not sure if it has to do anything with the fact, that I also have a Virtual Box installation on that same machine.

Comment by Elena Stepanova [ 2019-03-11 ]

stefolog,
Maybe you should see if this thread helps if you haven't yet, it seems to be discussing similar problems, which appear to be outside MariaDB server.

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