Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Incomplete
-
10.0.16
-
OpenBSD 5.7
500 Mhz PPC iBook, non-SSD drive (3.3G free)
Description
I have a small MySQL 5.1.70 InnoDB database: 4 tables; ~3K, ~23K, ~500K, ~600K rows. This runs on OpenBSD 5.4 with no issues. I'm testing an upgrade to OpenBSD 5.7 / MariaDB 10.0.16 on a staging server (500 Mhz PPC iBook). I've recreated the db schema to match the prod one and ran `mysql_upgrade --force` just to be safe. I dumped the prod data (just text/numbers, no blobs/binaries) with:
$ mysqldump -u root -p --single-transaction --no-create-info --skip-add-drop-table --skip-extended-insert mydb > data_dump.sql
|
The dump file size is 116M.
The problem is that MariaDB keeps aborting randomly while importing the first table from the dump, which is just ~23K rows. Importing a different table first yields equal results.
staging $ mysql -u root -p -D mydb < data_dump.sql
|
Enter password:
|
ERROR 2013 (HY000) at line 8039: Lost connection to MySQL server during query
|
The line where it crashes is a normal INSERT no different from thousands before that one, such as:
INSERT INTO `atable` VALUES (477, 'a@example.com', 'abc', 'abc', 'abcde', 1200, 0, 0, 0, '2ba53bc6de4e8e66c9bd19da2414725c53033e8bd76e942a7a282de54cb3d834', 0,'LPLHUCORFZGRSROEMHRZG', NULL, 1329510762, NULL, 'N');
In fact repeating the import again (after truncating tables and ensuring server starts ok) will NOT crash at the same line. I've seen it crash anywhere between 1000 to 9000 rows, never at the same row. So I ruled out the bad data hypothesis.
During the import there's no high memory pressure (`top` reported 200+Mb free RAM) and there's plenty of disk space (3.3 GB). I've also ruled out possible hardware issues because using MySQL never gave me a problem on the same data set.
The error log shows the following (from server startup to crash):
160211 12:07:05 mysqld_safe Starting mysqld daemon with databases from /var/mysql
|
160211 12:07:06 [Note] InnoDB: Using mutexes to ref count buffer pool pages
|
160211 12:07:06 [Note] InnoDB: The InnoDB memory heap is disabled
|
160211 12:07:06 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
160211 12:07:06 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
|
160211 12:07:06 [Note] InnoDB: Compressed tables use zlib 1.2.3
|
160211 12:07:06 [Note] InnoDB: Not using CPU crc32 instructions
|
160211 12:07:06 [Note] InnoDB: Initializing buffer pool, size = 128.0M
|
160211 12:07:06 [Note] InnoDB: Completed initialization of buffer pool
|
160211 12:07:06 [Note] InnoDB: Setting log file /var/mysql/ib_logfile101 size to 32 MB
|
160211 12:07:09 [Note] InnoDB: Setting log file /var/mysql/ib_logfile1 size to 32 MB
|
160211 12:07:11 [Note] InnoDB: Renaming log file /var/mysql/ib_logfile101 to /var/mysql/ib_logfile0
|
160211 12:07:11 [Warning] InnoDB: New log files created, LSN=27985430
|
160211 12:07:11 [Note] InnoDB: Highest supported file format is Barracuda.
|
160211 12:07:11 [Note] InnoDB: 128 rollback segment(s) are active.
|
160211 12:07:12 [Note] InnoDB: Waiting for purge to start
|
160211 12:07:12 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.22-71.0 started; log sequence number 27985932
|
160211 12:07:12 [Note] Server socket created on IP: '127.0.0.1'.
|
160211 12:07:12 [Note] Event Scheduler: Loaded 0 events
|
160211 12:07:12 [Note] /usr/local/libexec/mysqld: ready for connections.
|
Version: '10.0.16-MariaDB-log' socket: '/var/run/mysql/mysql.sock' port: 3306 OpenBSD port: mariadb-server-10.0.16v0
|
2016-02-11 12:09:34 c10b6700 InnoDB: Assertion failure in thread 3238749952 in file trx0purge.cc line 695
|
InnoDB: Failing assertion: purge_sys->rseg->last_page_no != FIL_NULL
|
InnoDB: We intentionally generate a memory trap.
|
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
|
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: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
|
InnoDB: about forcing recovery.
|
Abort trap
|
160211 12:09:34 mysqld_safe mysqld restarted
|
160211 12:09:34 [Note] InnoDB: Using mutexes to ref count buffer pool pages
|
160211 12:09:34 [Note] InnoDB: The InnoDB memory heap is disabled
|
160211 12:09:34 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
160211 12:09:34 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
|
160211 12:09:34 [Note] InnoDB: Compressed tables use zlib 1.2.3
|
160211 12:09:34 [Note] InnoDB: Not using CPU crc32 instructions
|
160211 12:09:34 [Note] InnoDB: Initializing buffer pool, size = 128.0M
|
160211 12:09:35 [Note] InnoDB: Completed initialization of buffer pool
|
160211 12:09:35 [Note] InnoDB: Highest supported file format is Barracuda.
|
160211 12:09:35 [Note] InnoDB: Log scan progressed past the checkpoint lsn 31818497
|
160211 12:09:35 [Note] InnoDB: Database was not shutdown normally!
|
160211 12:09:35 [Note] InnoDB: Starting crash recovery.
|
160211 12:09:35 [Note] InnoDB: Reading tablespace information from the .ibd files...
|
160211 12:09:35 [Note] InnoDB: Restoring possible half-written data pages
|
160211 12:09:35 [Note] InnoDB: from the doublewrite buffer...
|
InnoDB: Doing recovery: scanned up to log sequence number 32140062
|
160211 12:09:36 [Note] InnoDB: Starting an apply batch of log records to the database...
|
InnoDB: Progress in percent: 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
|
InnoDB: Apply batch completed
|
InnoDB: Last MySQL binlog file position 0 2314577, file name ./binlog.000079
|
160211 12:09:36 [Note] InnoDB: 128 rollback segment(s) are active.
|
160211 12:09:36 [Note] InnoDB: Waiting for purge to start
|
160211 12:09:36 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.22-71.0 started; log sequence number 32140062
|
160211 12:09:37 [Note] Recovering after a crash using binlog
|
160211 12:09:37 [Note] Starting crash recovery...
|
160211 12:09:37 [Note] Crash recovery finished.
|
160211 12:09:37 [Note] Server socket created on IP: '127.0.0.1'.
|
160211 12:09:37 [Note] Event Scheduler: Loaded 0 events
|
160211 12:09:37 [Note] /usr/local/libexec/mysqld: ready for connections.
|
Version: '10.0.16-MariaDB-log' socket: '/var/run/mysql/mysql.sock' port: 3306 OpenBSD port: mariadb-server-10.0.16v0
|
Here's my my.cnf file:
[client]
|
port = 3306
|
socket = /var/run/mysql/mysql.sock
|
|
|
[mysqld]
|
port = 3306
|
socket = /var/run/mysql/mysql.sock
|
datadir = /var/mysql
|
max_allowed_packet = 128M
|
table_open_cache = 64
|
sort_buffer_size = 128K
|
read_buffer_size = 512K
|
net_buffer_length = 64K
|
server-id = 1
|
general-log = 1
|
general_log_file = query.log
|
log-error = error.log
|
slow-query-log = 1
|
long_query_time = 2
|
slow_query_log_file = slow_queries.log
|
bind-address = 127.0.0.1
|
log-bin = binlog
|
binlog_format = mixed
|
max_binlog_size = 512M
|
key_buffer_size = 2M
|
read_rnd_buffer_size = 1M
|
innodb_data_home_dir = /var/mysql/
|
innodb_log_group_home_dir = /var/mysql/
|
innodb_data_file_path = ibdata1:10M:autoextend
|
innodb_buffer_pool_size = 128M
|
innodb_log_file_size = 32M
|
innodb_log_buffer_size = 16M
|
innodb_lock_wait_timeout = 50
|
innodb_max_dirty_pages_pct = 1
|
|
|
[mysqldump]
|
quick
|
max_allowed_packet = 16M
|
|
|
[mysql]
|
no-auto-rehash
|
|
|
[mysqlhotcopy]
|
interactive-timeout
|
Increasing `innodb_buffer_pool_size/innodb_log_file_size` to `256M/64M` seemed to post-pone the crash a little but didn't help significantly. Reducing/Increasing max_allowed_packet (also using extended-inserts) didn't help either. I also tried to completely uninstall/reinstall MariaDB and use the default my.cnf, to no avail.