[MDEV-6436] Error Importing MySQLdump File Created: 2014-07-10  Updated: 2019-03-31  Resolved: 2019-03-31

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

Type: Bug Priority: Major
Reporter: Nat Prakongpan Assignee: Sergey Vojtovich
Resolution: Duplicate Votes: 0
Labels: None
Environment:

RHEL 7 on IBM Power7 hardware
A newly installed mariadb-server

Issue Links:
Duplicate
duplicates MDEV-6615 Incorrect barrier logic in mutex_exit... Closed

 Description   

I was able to access mysql initial. Then the import lasted ~10 seconds before the error message below.
[root@localhost ~]# mysql < DB_Backup1.sqldump
ERROR 2013 (HY000) at line 125: Lost connection to MySQL server during query

mariadb.log shows:

[root@localhost ~]# cat /var/log/mariadb/mariadb.log
 
140710 06:43:55 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
 
140710  6:43:55 InnoDB: The InnoDB memory heap is disabled
 
140710  6:43:55 InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
140710  6:43:55 InnoDB: Compressed tables use zlib 1.2.7
 
140710  6:43:55 InnoDB: Using Linux native AIO
 
140710  6:43:55 InnoDB: Initializing buffer pool, size = 128.0M
 
140710  6:43:55 InnoDB: Completed initialization of buffer pool
 
InnoDB: The first specified data file ./ibdata1 did not exist:
 
InnoDB: a new database to be created!
 
140710  6:43:55  InnoDB: Setting file ./ibdata1 size to 10 MB
 
InnoDB: Database physically writes the file full: wait...
 
140710  6:43:55  InnoDB: Log file ./ib_logfile0 did not exist: new to be created
 
InnoDB: Setting log file ./ib_logfile0 size to 5 MB
 
InnoDB: Database physically writes the file full: wait...
 
140710  6:43:55  InnoDB: Log file ./ib_logfile1 did not exist: new to be created
 
InnoDB: Setting log file ./ib_logfile1 size to 5 MB
 
InnoDB: Database physically writes the file full: wait...
 
InnoDB: Doublewrite buffer not found: creating new
 
InnoDB: Doublewrite buffer created
 
InnoDB: 127 rollback segment(s) active.
 
InnoDB: Creating foreign key constraint system tables
 
InnoDB: Foreign key constraint system tables created
 
140710  6:43:55  InnoDB: Waiting for the background threads to start
 
140710  6:43:56 Percona XtraDB (http://www.percona.com) 5.5.37-MariaDB-34.0 started; log sequence number 0
 
140710  6:43:56 [Note] Plugin 'FEEDBACK' is disabled.
 
140710  6:43:56 [Note] Server socket created on IP: '0.0.0.0'.
 
140710  6:43:56 [Note] Event Scheduler: Loaded 0 events
 
140710  6:43:56 [Note] /usr/libexec/mysqld: ready for connections.
 
Version: '5.5.37-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
 
140710  7:40:22  InnoDB: Assertion failure in thread 70366338281648 in file fil0fil.c line 5286
 
InnoDB: Failing assertion: node->n_pending > 0
 
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.5/en/forcing-innodb-recovery.html
 
InnoDB: about forcing recovery.
 
140710  7:40:22 [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 http://kb.askmonty.org/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: 5.5.37-MariaDB
 
key_buffer_size=134217728
 
read_buffer_size=131072
 
max_used_connections=1
 
max_threads=153
 
thread_count=1
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 466717 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0x0
 
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 0x48000
 
/usr/libexec/mysqld(my_print_stacktrace-0x4c07a8)[0x222df618]
 
/usr/libexec/mysqld(handle_fatal_signal-0x985960)[0x21dee640]
 
[0x3fff92ae0478]
 
/lib64/libc.so.6(abort-0x182b94)[0x3fff921efe74]
 
/usr/libexec/mysqld(+0x9c4310)[0x221d4310]
 
/usr/libexec/mysqld(+0x9d2314)[0x221e2314]
 
/usr/libexec/mysqld(+0x91edc8)[0x2212edc8]
 
/lib64/libpthread.so.0(+0xc460)[0x3fff92a8c460]
 
/lib64/libc.so.6(clone-0xb9ee8)[0x3fff922be150]
 
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.
 
140710 07:40:22 mysqld_safe Number of processes running now: 0
 
140710 07:40:22 mysqld_safe mysqld restarted
 
140710  7:40:22 InnoDB: The InnoDB memory heap is disabled
 
140710  7:40:22 InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
140710  7:40:22 InnoDB: Compressed tables use zlib 1.2.7
 
140710  7:40:22 InnoDB: Using Linux native AIO
 
140710  7:40:22 InnoDB: Initializing buffer pool, size = 128.0M
 
140710  7:40:22 InnoDB: Completed initialization of buffer pool
 
140710  7:40:22 InnoDB: highest supported file format is Barracuda.
 
InnoDB: Log scan progressed past the checkpoint lsn 21478975
 
140710  7:40:22  InnoDB: Database was not shut down normally!
 
InnoDB: Starting crash recovery.
 
InnoDB: Reading tablespace information from the .ibd files...
 
InnoDB: Restoring possible half-written data pages from the doublewrite
 
InnoDB: buffer...
 
InnoDB: Doing recovery: scanned up to log sequence number 26721792
 
InnoDB: Doing recovery: scanned up to log sequence number 28142371
 
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
 
InnoDB: in total 2049 row operations to undo
 
InnoDB: Trx id counter is 500
 
140710  7:40:23  InnoDB: Starting an apply batch of log records to the database...
 
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 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 140710  7:40:23  InnoDB: Assertion failure in thread 70366413123760 in file data0type.ic line 488
 
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.5/en/forcing-innodb-recovery.html
 
InnoDB: about forcing recovery.
 
140710  7:40:23 [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 http://kb.askmonty.org/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: 5.5.37-MariaDB
 
key_buffer_size=134217728
 
read_buffer_size=131072
 
max_used_connections=0
 
max_threads=153
 
thread_count=0
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 466717 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0x0
 
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 0x48000
 
/usr/libexec/mysqld(my_print_stacktrace-0x4c07a8)[0x2260f618]
 
/usr/libexec/mysqld(handle_fatal_signal-0x985960)[0x2211e640]
 
[0x3fff95170478]
 
/lib64/libc.so.6(abort-0x182b94)[0x3fff9487fe74]
 
/usr/libexec/mysqld(+0x9ae328)[0x224ee328]
 
/usr/libexec/mysqld(+0xa2c504)[0x2256c504]
 
/usr/libexec/mysqld(+0xa1a70c)[0x2255a70c]
 
/usr/libexec/mysqld(+0xa1cd1c)[0x2255cd1c]
 
/usr/libexec/mysqld(+0x9827bc)[0x224c27bc]
 
/usr/libexec/mysqld(+0x9d2478)[0x22512478]
 
/usr/libexec/mysqld(+0x91edc8)[0x2245edc8]
 
/lib64/libpthread.so.0(+0xc460)[0x3fff9511c460]
 
/lib64/libc.so.6(clone-0xb9ee8)[0x3fff9494e150]
 
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.
 
140710 07:40:23 mysqld_safe mysqld from pid file /var/run/mariadb/mariadb.pid ended



 Comments   
Comment by Elena Stepanova [ 2014-07-14 ]

Hi,

Would you be able to provide the dump that you were trying to load?

Was the problem reproducible (in case you tried), e.g. if you removed and re-created the datadir, and tried to load the dump again, did you get the crash again?

Thanks.

Comment by Nat Prakongpan [ 2014-07-14 ]

Hi Elena,

Sorry I couldn't provide the dump as it contains sensitive personal information. I was able to recreate the issue a few times before I logged the crash here. I'm sure I can reproduce it again. After the crash, we had to remove MariaDB server, delete the datadir, and reinstall MariaDB bofore we could get the server to start again.

Comment by Elena Stepanova [ 2014-07-15 ]

Hi Nat,

I was able to recreate the issue a few times before I logged the crash here. I'm sure I can reproduce it again. After the crash, we had to remove MariaDB server, delete the datadir, and reinstall MariaDB bofore we could get the server to start again.

In the provided log, you have two types of failures. The initial one apparently happened on loading the dump. The other one happened upon restart after the initial crash. The latter one seems to be caused by the data corruption, and it is likely to be repeatable, that is, if you try to restart server again in the same way, it will fail again; and again.

My question was about the initial failure. If your server is up and running, and you try to load the dump, does it always crash?

Comment by Nat Prakongpan [ 2014-07-15 ]

Hi Elana,

Yes, it always crashes when I try to load the dump. The dump was from --all-databases on RHEL 6.5/x86_64 Server version 5.5.37-MariaDB. I'm thinking about trying to do just one database and see what happens.

Comment by Elena Stepanova [ 2014-07-15 ]

Hi Nat,

If it's reproducible, you can do the following:

  • enable general_log (add general_log=1 to the cnf file, or run SET GLOBAL general_log=1 at runtime; optionally set general_log_file to the path of your choice, so you could more easily find it);
  • try to load the dump again;

After it crashes, the last statement written into the general log should be the one that causes the crash. Then you can easily narrow it down to one database, and if it's still reproducible with one database, maybe even to a single table.

But doing so, please keep checking that your crash is still Failing assertion: node->n_pending > 0, because after the initial crash you might be getting side-effects of data corruption, which would also make server abort, but are of a different nature.

Maybe it turns out that the particular schema/table where the crash occurs does not contain confidential data, and you'll be able to upload it (please note that things that are not for wide public but aren't strictly confidential can be uploaded to ftp.askmonty.org/private, this way only MariaDB developers will have access to them).

Comment by Nat Prakongpan [ 2014-07-15 ]

Hi Elena,

I'm running the test now. I'll let you know what I've discovered.

Comment by Nat Prakongpan [ 2014-07-15 ]

Hi Elena,

It doesn't seem to show me the failed statement. This run I increased the InnoDB initial buffer pool size to 60G, and it seemed to take longer before it crashes. Here's the excerp from the log:

140715 9:10:10 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.5.37-MariaDB-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 MariaDB Server

140715 9:21:48 InnoDB: Assertion failure in thread 70299105882288 in file fil0fil.c line 5286
InnoDB: Failing assertion: node->n_pending > 0
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.5/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
140715 9:21:48 [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 http://kb.askmonty.org/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: 5.5.37-MariaDB-log
key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=1
max_threads=153
thread_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 466717 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0x0
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 0x48000
/usr/libexec/mysqld(my_print_stacktrace-0x4c07a8)[0x21a3f618]
/usr/libexec/mysqld(handle_fatal_signal-0x985960)[0x2154e640]
[0x3fffb5860478]
/lib64/libc.so.6(abort-0x182b94)[0x3fffb4f6fe74]
/usr/libexec/mysqld(+0x9c4310)[0x21934310]
/usr/libexec/mysqld(+0x9d2314)[0x21942314]
/usr/libexec/mysqld(+0x91edc8)[0x2188edc8]
/lib64/libpthread.so.0(+0xc460)[0x3fffb580c460]
/lib64/libc.so.6(clone-0xb9ee8)[0x3fffb503e150]
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.
140715 09:21:48 mysqld_safe Number of processes running now: 0
140715 09:21:48 mysqld_safe mysqld restarted

Comment by Nat Prakongpan [ 2014-07-15 ]

I just found the log of the statement. Let me isolate the dump to that specific table and I'll let you know more.

Comment by Nat Prakongpan [ 2014-07-15 ]

I've uploaded mdev-6436.tgz to ftp.askmonty.org/private. I use the create.dump (edit out CONSTRAINT line) to create the table. The appevent.dump is the actual lock/insert/unlock. The error happens when I was trying to import the appevent.dump.

Comment by Elena Stepanova [ 2019-03-31 ]

svoj,

Would you say that it was the same problem as MDEV-6615 fixed in 5.5.40?

I suspect the relation because this upstream bug https://bugs.mysql.com/bug.php?id=77795 presents an assertion failure which looks identical; it's closed as a duplicate of https://bugs.mysql.com/bug.php?id=76135 which, in turn, is a spin-off of MDEV-6615.

Comment by Sergey Vojtovich [ 2019-03-31 ]

Yes, it very likely duplicates MDEV-6615. Feel free to reopen if it is still reproducible with latest 5.5+ release.

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