Details
-
Type:
Bug
-
Status: Open
-
Priority:
Major
-
Resolution: Unresolved
-
Affects Version/s: 5.5.37
-
Fix Version/s: None
-
Component/s: None
-
Labels:None
-
Environment:RHEL 7 on IBM Power7 hardware
A newly installed mariadb-server
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
Gliffy Diagrams
Attachments
Activity
- All
- Comments
- Work Log
- History
- Activity
- Transitions
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.
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?
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.
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).
Hi Elena,
I'm running the test now. I'll let you know what I've discovered.
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
I just found the log of the statement. Let me isolate the dump to that specific table and I'll let you know more.
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.
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.