[MDEV-9129] Server is restarting in the loop after crash - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.1.8
Fix Version/s: 10.1.10
Component/s: Encryption, Storage Engine - InnoDB, Storage Engine - XtraDB
Labels:
- replication
Environment:
linode virtual server Linode 48GB 16 Cores 1152 GB SSD
Centos 6.5

Sprint:
10.1.10

Description

Mariadb 10.1.8 server crashed and now it is restarting in the loop

Server is used just as backup server with no read traffic and it crashed during replication of commands from master running Mariadb 10.0.22

Part of the error log:

2015-11-13 05:39:37 7f4e03ffe700  InnoDB: Assertion failure in thread 139973051279104 in file row0merge.cc line 892

InnoDB: Failing assertion: b < &block[srv_sort_buf_size]

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.

151113  5:39:37 [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: 10.1.8-MariaDB-log

key_buffer_size=134217728

read_buffer_size=131072

max_used_connections=0

max_threads=5002

thread_count=0

It is possible that mysqld could use up to

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 11117553 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

2015-11-13 05:39:37 7f4e047ff700  InnoDB: Assertion failure in thread 139973059671808 in file row0merge.cc line 892

InnoDB: Failing assertion: b < &block[srv_sort_buf_size]

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.

151113 05:39:38 mysqld_safe Number of processes running now: 0

151113 05:39:38 mysqld_safe mysqld restarted

2015-11-13  5:39:38 139789607671840 [Note] /usr/sbin/mysqld (mysqld 10.1.8-MariaDB-log) starting as process 11180 ...

2015-11-13 05:39:38 7f234de89820 InnoDB: Warning: Setting innodb_use_sys_malloc to FALSE is DEPRECATED. This option may be removed in future releases, together with the InnoDB's internal memory allocator.

2015-11-13  5:39:38 139789607671840 [Note] InnoDB: Using mutexes to ref count buffer pool pages

2015-11-13  5:39:38 139789607671840 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

2015-11-13  5:39:38 139789607671840 [Note] InnoDB: Memory barrier is not used

2015-11-13  5:39:38 139789607671840 [Note] InnoDB: Compressed tables use zlib 1.2.3

2015-11-13  5:39:38 139789607671840 [Note] InnoDB: Using Linux native AIO

2015-11-13  5:39:38 139789607671840 [Note] InnoDB: Using CPU crc32 instructions

2015-11-13  5:39:38 139789607671840 [Note] InnoDB: Initializing buffer pool, size = 25.0G

2015-11-13  5:39:40 139789607671840 [Note] InnoDB: Completed initialization of buffer pool

2015-11-13  5:39:41 139789607671840 [Note] InnoDB: Highest supported file format is Barracuda.

2015-11-13  5:39:41 139789607671840 [Note] InnoDB: Log scan progressed past the checkpoint lsn 4932606017459

2015-11-13  5:39:41 139789607671840 [Note] InnoDB: Database was not shutdown normally!

2015-11-13  5:39:41 139789607671840 [Note] InnoDB: Starting crash recovery.

2015-11-13  5:39:41 139789607671840 [Note] InnoDB: Reading tablespace information from the .ibd files...

2015-11-13  5:39:57 139789607671840 [Note] InnoDB: Processed 100683 .ibd/.isl files

2015-11-13  5:40:13 139789607671840 [Note] InnoDB: Processed 198737 .ibd/.isl files

2015-11-13  5:40:29 139789607671840 [Note] InnoDB: Processed 297902 .ibd/.isl files

2015-11-13  5:40:45 139789607671840 [Note] InnoDB: Processed 391842 .ibd/.isl files

2015-11-13  5:41:01 139789607671840 [Note] InnoDB: Processed 487883 .ibd/.isl files

2015-11-13  5:41:17 139789607671840 [Note] InnoDB: Processed 579656 .ibd/.isl files

2015-11-13  5:41:33 139789607671840 [Note] InnoDB: Processed 670725 .ibd/.isl files

2015-11-13  5:41:42 139789607671840 [Note] InnoDB: Restoring possible half-written data pages

2015-11-13  5:41:42 139789607671840 [Note] InnoDB: from the doublewrite buffer...

InnoDB: Doing recovery: scanned up to log sequence number 4932606076098

2015-11-13  5:41:43 139789607671840 [Note] InnoDB: Starting an apply batch of log records to the database...

InnoDB: Progress in percent: 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

InnoDB: Apply batch completed

InnoDB: Last MySQL binlog file position 0 242205496, file name ./mysql-bin.001779

2015-11-13  5:42:07 139789607671840 [Note] InnoDB: 128 rollback segment(s) are active.

2015-11-13  5:42:07 139789607671840 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.26-74.0 started; log sequence number 4932606076098

2015-11-13  5:42:07 139756801316608 [Note] InnoDB: Dumping buffer pool(s) not yet started

2015-11-13  5:42:07 139789607671840 [Note] Plugin 'FEEDBACK' is disabled.

2015-11-13  5:42:07 139789607671840 [Note] Recovering after a crash using mysql-bin

2015-11-13  5:42:07 139789607671840 [Note] Starting crash recovery...

2015-11-13  5:42:07 139789607671840 [Note] Crash recovery finished.

2015-11-13  5:42:07 139789607671840 [Note] Server socket created on IP: '::'.

2015-11-13  5:42:07 139789607671840 [Note] Event Scheduler: Loaded 0 events

2015-11-13  5:42:07 139789607671840 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--log-basename=#' or '--relay-log=3_dbbackup_la_linode-uk-relay-bin' to avoid this problem.

2015-11-13  5:42:07 139789607671840 [Note] /usr/sbin/mysqld: ready for connections.

Version: '10.1.8-MariaDB-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server

2015-11-13  5:42:07 139789218531072 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.001790' at position 257187369, relay log './3_dbbackup_la_linode-uk-relay-bin.000928' position: 257187657

2015-11-13  5:42:07 139789606020864 [Note] Slave I/O thread: connected to master 'replicator@192.168.169.192:3306',replication started in log 'mysql-bin.001790' at position 862639170

2015-11-13  5:42:07 139789218830080 [Note] InnoDB: Online DDL : Start

2015-11-13  5:42:07 139789218830080 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files

2015-11-13 05:42:09 7f1b9f3fe700  InnoDB: Assertion failure in thread 139756612609792 in file row0merge.cc line 892

InnoDB: Failing assertion: b < &block[srv_sort_buf_size]

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.

151113  5:42:09 [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: 10.1.8-MariaDB-log

key_buffer_size=134217728

read_buffer_size=131072

max_used_connections=0

max_threads=5002

thread_count=0

It is possible that mysqld could use up to

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 11117553 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

2015-11-13 05:42:09 7f1b9fbff700  InnoDB: Assertion failure in thread 139756621002496 in file row0merge.cc line 892

InnoDB: Failing assertion: b < &block[srv_sort_buf_size]

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.

151113 05:42:10 mysqld_safe Number of processes running now: 0

151113 05:42:10 mysqld_safe mysqld restarted

2015-11-13  5:42:10 140555941337120 [Note] /usr/sbin/mysqld (mysqld 10.1.8-MariaDB-log) starting as process 11482 ...

2015-11-13 05:42:10 7fd5baf45820 InnoDB: Warning: Setting innodb_use_sys_malloc to FALSE is DEPRECATED. This option may be removed in future releases, together with the InnoDB's internal memory allocator.

2015-11-13  5:42:10 140555941337120 [Note] InnoDB: Using mutexes to ref count buffer pool pages

2015-11-13  5:42:10 140555941337120 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

2015-11-13  5:42:10 140555941337120 [Note] InnoDB: Memory barrier is not used

2015-11-13  5:42:10 140555941337120 [Note] InnoDB: Compressed tables use zlib 1.2.3

2015-11-13  5:42:10 140555941337120 [Note] InnoDB: Using Linux native AIO

2015-11-13  5:42:10 140555941337120 [Note] InnoDB: Using CPU crc32 instructions

2015-11-13  5:42:10 140555941337120 [Note] InnoDB: Initializing buffer pool, size = 25.0G

2015-11-13  5:42:13 140555941337120 [Note] InnoDB: Completed initialization of buffer pool

2015-11-13  5:42:13 140555941337120 [Note] InnoDB: Highest supported file format is Barracuda.

2015-11-13  5:42:13 140555941337120 [Note] InnoDB: Log scan progressed past the checkpoint lsn 4932606076108

2015-11-13  5:42:13 140555941337120 [Note] InnoDB: Database was not shutdown normally!

2015-11-13  5:42:13 140555941337120 [Note] InnoDB: Starting crash recovery.

2015-11-13  5:42:13 140555941337120 [Note] InnoDB: Reading tablespace information from the .ibd files...

2015-11-13  5:42:29 140555941337120 [Note] InnoDB: Processed 97537 .ibd/.isl files

2015-11-13  5:42:45 140555941337120 [Note] InnoDB: Processed 195624 .ibd/.isl files

2015-11-13  5:43:01 140555941337120 [Note] InnoDB: Processed 293425 .ibd/.isl files

2015-11-13  5:43:17 140555941337120 [Note] InnoDB: Processed 386672 .ibd/.isl files

2015-11-13  5:43:33 140555941337120 [Note] InnoDB: Processed 480040 .ibd/.isl files

2015-11-13  5:43:49 140555941337120 [Note] InnoDB: Processed 574244 .ibd/.isl files

2015-11-13  5:44:05 140555941337120 [Note] InnoDB: Processed 661463 .ibd/.isl files

2015-11-13  5:44:16 140555941337120 [Note] InnoDB: Restoring possible half-written data pages

2015-11-13  5:44:16 140555941337120 [Note] InnoDB: from the doublewrite buffer...

InnoDB: Doing recovery: scanned up to log sequence number 4932606134463

2015-11-13  5:44:17 140555941337120 [Note] InnoDB: Starting an apply batch of log records to the database...

InnoDB: Progress in percent: 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

InnoDB: Apply batch completed

InnoDB: Last MySQL binlog file position 0 242205496, file name ./mysql-bin.001779

2015-11-13  5:44:40 140555941337120 [Note] InnoDB: 128 rollback segment(s) are active.

2015-11-13  5:44:40 140555941337120 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.26-74.0 started; log sequence number 4932606134463

2015-11-13  5:44:40 140523113240320 [Note] InnoDB: Dumping buffer pool(s) not yet started

2015-11-13  5:44:40 140555941337120 [Note] Plugin 'FEEDBACK' is disabled.

2015-11-13  5:44:40 140555941337120 [Note] Recovering after a crash using mysql-bin

2015-11-13  5:44:40 140555941337120 [Note] Starting crash recovery...

2015-11-13  5:44:40 140555941337120 [Note] Crash recovery finished.

2015-11-13  5:44:40 140555941337120 [Note] Server socket created on IP: '::'.

2015-11-13  5:44:40 140555941337120 [Note] Event Scheduler: Loaded 0 events

2015-11-13  5:44:40 140555941337120 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--log-basename=#' or '--relay-log=3_dbbackup_la_linode-uk-relay-bin' to avoid this problem.

2015-11-13  5:44:40 140555941337120 [Note] /usr/sbin/mysqld: ready for connections.

Version: '10.1.8-MariaDB-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server

2015-11-13  5:44:40 140555552024320 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.001790' at position 257187369, relay log './3_dbbackup_la_linode-uk-relay-bin.000928' position: 257187657

2015-11-13  5:44:40 140555939686144 [Note] Slave I/O thread: connected to master 'replicator@192.168.169.192:3306',replication started in log 'mysql-bin.001790' at position 873411395

2015-11-13  5:44:40 140555846170368 [Note] InnoDB: Online DDL : Start

2015-11-13  5:44:40 140555846170368 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files

2015-11-13 05:44:42 7fce0a7fe700  InnoDB: Assertion failure in thread 140522916144896 in file row0merge.cc line 892

InnoDB: Failing assertion: b < &block[srv_sort_buf_size]

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.

.... and the same logs again and again

Attachments

Issue Links

relates to

MDEV-9148 Assertion `thd->stmt_arena != thd->progress.arena' failed in thd_progress_init

Closed

Activity

Transition	Time In Source Status	Execution Times

Elena Stepanova made transition - 2015-11-17 13:24

Open

Confirmed

4d 5h 21m

Jan Lindström (Inactive) made transition - 2015-12-15 19:13

Confirmed

In Progress

28d 5h 49m

Jan Lindström (Inactive) made transition - 2015-12-15 20:40

In Progress

Closed

1h 27m

People

Assignee:: Jan Lindström (Inactive)

Reporter:: Viktor Zeman

Votes:: 0 Vote for this issue

Watchers:: 5 Start watching this issue

Dates

Created:: 2015-11-13 08:03

Updated:: 2016-11-02 18:32

Resolved:: 2015-12-15 20:40

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.