[MDEV-9569] Crash during import with failed assertion purge_sys->rseg->last_page_no != FIL_NULL Created: 2016-02-16  Updated: 2022-11-10  Resolved: 2022-11-10

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s: 10.0.16
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Ettore Pasquini Assignee: Jan Lindström (Inactive)
Resolution: Incomplete Votes: 0
Labels: crash, innodb, mysqldump, xtradb
Environment:

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.



 Comments   
Comment by Elena Stepanova [ 2016-02-17 ]

ettore,

Could you please upload the dump to our ftp.askmonty.org/private ? Only MariaDB developers will have access to it.

Also, it would be a big help if you could

  • add the option core-file to [mysqld] section of your server config;
  • add the option core-file-size=unlimited to [mysqld_safe] section;
  • after the server crashes, store the core dump;
  • run gdb --batch --eval-command="thread apply all bt" /usr/local/libexec/mysqld <coredump location>;
  • attach the output.

Do you build the server from sources, or do you use a binary tarball, or some OpenBSD-specific binary package?
Is there any reason you are trying to upgrade to 10.0.16, which is after all 7 releases behind? Until we see the stack trace and/or reproduce the crash, I can't say for sure if it's been fixed in later versions, but still, using a newer release in general seems to be wiser.

Comment by Ettore Pasquini [ 2016-02-17 ]

I will upload what you ask soon.

To answer some of your questions:

Comment by Ettore Pasquini [ 2016-02-17 ]

elenst,
I changed my.cnf per your recommendation:

-..
 
[mysqld]
 
core-file
 
...
 
[mysqld_safe]
 
core-file-size=unlimited
 
...

but when the server crashes I am not able to see any core dump being saved, even after scanning the whole disk for files like "core*". Not sure why it's not writing the core. I've seen some documentation mentioning --core-file and --stack-trace options but at least the latter is not being accepted.

I uploaded the dump + schema SQL + the error log to the private website. The archive is called MDEV-9569.zip.

Comment by Elena Stepanova [ 2016-02-22 ]

jplindst,

Could you please take a look for any idea what it could be? Something PPC-related, perhaps?
I'm not getting the problem by just loading the dump to a fresh server, but mine is neither PPC nor OpenBSD 5.7.

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