[MDEV-9129] Server is restarting in the loop after crash Created: 2015-11-13  Updated: 2016-11-02  Resolved: 2015-12-15

Status: Closed
Project: MariaDB Server
Component/s: Encryption, Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s: 10.1.8
Fix Version/s: 10.1.10

Type: Bug Priority: Major
Reporter: Viktor Zeman Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: replication
Environment:

linode virtual server Linode 48GB 16 Cores 1152 GB SSD
Centos 6.5

Issue Links:
Relates
relates to MDEV-9148 Assertion `thd->stmt_arena != thd->pr... Closed
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

 Comments   
Comment by Viktor Zeman [ 2015-11-13 ]

after closer investigation I have found, that the crash was caused by the replication of SQL:
Query: 'ALTER TABLE qu_la_contacts ADD FULLTEXT ft_qu_la_contacts_groups (groups)'
table has more than 1GB and more than few millions rows.

Comment by Viktor Zeman [ 2015-11-13 ]

When I started server in readonly mode, replication doesn't start and the server is running fine.
Also mysqlcheck confirmed, that all data are correct without corruption.

So the problem is isolated to ALTER TABLE, which adds fulltext index on huge table

Comment by Viktor Zeman [ 2015-11-13 ]

We have found solution to fix the problem:

innodb_sort_buffer_size was increased from default value 1MB to 4G

It should print at least the message, that the ALTER TABLE failed because of low buffer size or it should handle the creating of index on smaller buffers in less efficient way

Comment by Alex [ 2015-11-13 ]

I had same problem while having default innodb settings activated. It happened when I played with gtd_slave_pos table converting from myisam to innodb (and back), so it suddenly crashed and then mariadb (10) began endless restarts. I simply disabled innodb. Afterwards I couldn't simulate the problem again.

Comment by Elena Stepanova [ 2015-11-13 ]

unitminer,

Could you please paste the output of SHOW CREATE TABLE and SHOW INDEX IN ... for the table, and also attach your cnf files?

Trying to reproduce it on an arbitrary table of a similar size didn't succeed.

Comment by Viktor Zeman [ 2015-11-14 ]

Table looks like this after ALTER TABLE was executed

CREATE TABLE `qu_la_contacts` (
 
  `contactid` char(8) NOT NULL,
 
  `parent_contactid` char(8) DEFAULT NULL,
 
  `company` char(1) NOT NULL DEFAULT 'N',
 
  `job_position` varchar(255) DEFAULT NULL,
 
  `emails` text,
 
  `firstname` varchar(100) DEFAULT NULL,
 
  `lastname` varchar(100) DEFAULT NULL,
 
  `system_name` varchar(100) DEFAULT NULL,
 
  `description` varchar(255) DEFAULT NULL,
 
  `rtype` char(1) NOT NULL,
 
  `status` char(1) NOT NULL DEFAULT 'A' COMMENT 'A=Active, X=Deleted',
 
  `datecreated` datetime DEFAULT NULL,
 
  `avatar_url` text,
 
  `city` varchar(255) DEFAULT NULL,
 
  `countrycode` varchar(2) DEFAULT NULL,
 
  `note` text,
 
  `time_offset` int(11) DEFAULT NULL,
 
  `language` varchar(10) DEFAULT NULL,
 
  `gender` char(1) NOT NULL DEFAULT 'M',
 
  `levelid` char(8) DEFAULT NULL,
 
  `ldap_id` varchar(255) DEFAULT NULL,
 
  `groups` varchar(255) DEFAULT NULL,
 
  `ip` varchar(39) DEFAULT NULL,
 
  `useragent` text,
 
  `screen` varchar(12) DEFAULT NULL,
 
  `latitude` float DEFAULT NULL,
 
  `longitude` float DEFAULT NULL,
 
  `last_action_type` char(1) DEFAULT NULL,
 
  `last_action_date` datetime DEFAULT NULL,
 
  `last_action_meta` varchar(80) DEFAULT NULL,
 
  PRIMARY KEY (`contactid`),
 
  KEY `fk_qu_la_contacts_qu_la_levels1_idx` (`levelid`),
 
  KEY `fk_parent_contactid` (`parent_contactid`),
 
  KEY `qu_la_contacts_datecreated` (`datecreated`),
 
  FULLTEXT KEY `ft_qu_la_contacts_groups` (`groups`)
 
) ENGINE=InnoDB DEFAULT CHARSET=utf8 ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=8 

MariaDB [u72359_aa97]> show index in qu_la_contacts;
 
+----------------+------------+-------------------------------------+--------------+------------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
 
| Table          | Non_unique | Key_name                            | Seq_in_index | Column_name      | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment |
 
+----------------+------------+-------------------------------------+--------------+------------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
 
| qu_la_contacts |          0 | PRIMARY                             |            1 | contactid        | A         |      665638 |     NULL | NULL   |      | BTREE      |         |               |
 
| qu_la_contacts |          1 | fk_qu_la_contacts_qu_la_levels1_idx |            1 | levelid          | A         |          20 |     NULL | NULL   | YES  | BTREE      |         |               |
 
| qu_la_contacts |          1 | fk_parent_contactid                 |            1 | parent_contactid | A         |           2 |     NULL | NULL   | YES  | BTREE      |         |               |
 
| qu_la_contacts |          1 | qu_la_contacts_datecreated          |            1 | datecreated      | A         |      665638 |     NULL | NULL   | YES  | BTREE      |         |               |
 
| qu_la_contacts |          1 | ft_qu_la_contacts_groups            |            1 | groups           | NULL      |      665638 |     NULL | NULL   | YES  | FULLTEXT   |         |               |
 
+----------------+------------+-------------------------------------+--------------+------------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
 
5 rows in set (0.00 sec)
 

[mysqld]
 
server-id=103
 
datadir=/opt/mysql/
 
socket=/var/lib/mysql/mysql.sock
 
tmpdir=/tmp/
 
 
 
innodb_sort_buffer_size=4G
 
log_bin=mysql-bin
 
expire_logs_days=6
 
 
 
wait_timeout=60
 
long_query_time=1
 
slow_query_log=1
 
slow_query_log_file=/opt/log/slow.log
 
 
 
userstat = 1
 
user=root
 
symbolic-links=0
 
binlog_format=STATEMENT
 
default_storage_engine=InnoDB
 
slave_skip_errors=1062,1396,1690
 
innodb_autoinc_lock_mode=2
 
innodb_buffer_pool_size=25G
 
innodb_buffer_pool_instances=20
 
innodb_log_file_size=4G
 
innodb_log_buffer_size=196M
 
innodb_flush_log_at_trx_commit=0
 
innodb_thread_concurrency=24
 
innodb_file_per_table
 
innodb_write_io_threads=24
 
innodb_read_io_threads=24
 
innodb_sched_priority_cleaner=39
 
innodb_adaptive_flushing=1
 
innodb_purge_threads=5
 
innodb_adaptive_hash_index_partitions=64
 
innodb_flush_neighbors=0
 
innodb_flush_method=O_DIRECT
 
innodb_io_capacity=5000
 
innodb_io_capacity_max=8000
 
innodb_lru_scan_depth=1024
 
innodb_use_sys_malloc=0
 
innodb_file_format=Barracuda
 
innodb_file_format_max=Barracuda
 
slave_parallel_threads=10
 
log_slave_updates=on
 
performance_schema=off
 
 
 
skip-name-resolve
 
 
 
max_allowed_packet = 512M
 
 
 
query_cache_type=1
 
query_cache_size = 0
 
query_cache_limit = 1M
 
query_cache_min_res_unit=1K
 
max_connections = 5000
 
 
 
table_open_cache=64K
 
innodb_open_files=64K
 
open_files_limit=1020000
 
collation-server = utf8_general_ci
 
character-set-server = utf8
 
 
 
[mysqld_safe]
 
log-error=/opt/log/error.log
 
pid-file=/var/run/mysqld/mysqld.pid
 
malloc-lib=/usr/lib64/libjemalloc.so.1

Comment by Viktor Zeman [ 2015-11-14 ]

maybe the key to the problem is, that it was replicated from other server

Comment by Elena Stepanova [ 2015-11-18 ]

Thank you, I could reproduce it now.

2015-11-18 01:27:56 7f7c18ffe700  InnoDB: Assertion failure in thread 140170972096256 in file row0merge.cc line 892
 
InnoDB: Failing assertion: b < &block[srv_sort_buf_size]
 
InnoDB: We intentionally generate a memory trap.

Stack trace from 10.1 commit 836275bb203a47104eb7f28aa409924b91abc801

 
#4  0x00007f7d4b4593e0 in *__GI_abort () at abort.c:92
 
#5  0x00007f7d4e230098 in row_merge_buf_write (buf=0x7f7d1fca3028, of=<optimized out>, block=0x7f7d1e406000 "") at 10.1/storage/xtradb/row/row0merge.cc:892
 
#6  0x00007f7d4e21fb13 in fts_parallel_tokenization (arg=0x7f7d1fc1ef68) at 10.1/storage/xtradb/row/row0ftsort.cc:775
 
#7  0x00007f7d4d673b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
 
#8  0x00007f7d4b4ff95d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112

10.0 also fails, but differently, see MDEV-9148 (10.1 fails both on debug and release builds, while 10.0 only fails on release).
To reproduce, download and unpack ftp://ftp.askmonty.org/public/MDEV-9129_data.gz

create table t1 (groups varchar(255) DEFAULT NULL) ENGINE=InnoDB;
 
load data local infile 't1.data' into table t1;
 
ALTER TABLE t1 ADD FULLTEXT ft_qu_la_contacts_groups (groups);

Default server settings are enough.

Comment by Christian Loos [ 2015-12-09 ]

I'm also hit by this bug creating a fulltext index for a 2G InnoDB table.

I'm curious that increasing the innodb_sort_buffer_size from default value 1MB to 4G worked for @unitminer because:

  • 64M is the max value for innodb_sort_buffer_size and any value above will be reset to 64M
  • srv_sort_buf_size is actually the sort_buffer_size

I tried increasing the sort_buffer_size to 4G , but creating the fulltext index still crashes the server.

Comment by Jan Lindström (Inactive) [ 2015-12-15 ]

commit 1ac6640210bb337ecdfa9f8b818cc3c6156dbdcc
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Tue Dec 15 20:37:33 2015 +0200

MDEV-9129: Server is restarting in the loop after crash

Analysis: We have reserved ROW_MERGE_RESERVE_SIZE ( = 4) for
encryption key_version. When calculating is there more
space on sort buffer, this value needs to be substracted
from current available space.

Comment by Viktor Zeman [ 2016-11-02 ]

Bug was not fixed. We have updated to Mariadb 10.1.18 to make sure we are running latest stable version and bug is still crashing server

(Maybe it was fixed for any other row format, but for row_format=COMPRESSED the problem is still there and server crash)

Comment by Jan Lindström (Inactive) [ 2016-11-02 ]

Is it exactly the same assertion, can you provide the error log?

Comment by Viktor Zeman [ 2016-11-02 ]

Looks very similar:

2016-11-02 12:17:45 7f09b5ffe700  InnoDB: Assertion failure in thread 139679684880128 in file row0merge.cc line 890
 
InnoDB: Failing assertion: b == &block[0] + buf->total_size + ROW_MERGE_RESERVE_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.
 
161102 12:17:45 [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 https://mariadb.com/kb/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.18-MariaDB
 
key_buffer_size=134217728
 
read_buffer_size=131072
 
max_used_connections=7
 
max_threads=902
 
thread_count=4
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2112329 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 0x48400
 
/usr/sbin/mysqld(my_print_stacktrace+0x2b)[0x55b2f23d60ab]
 
/usr/sbin/mysqld(handle_fatal_signal+0x475)[0x55b2f1f329f5]
 
/lib64/libpthread.so.0(+0xf7e0)[0x7f0ef41c57e0]
 
/lib64/libc.so.6(gsignal+0x35)[0x7f0ef281f5e5]
 
/lib64/libc.so.6(abort+0x175)[0x7f0ef2820dc5]
 
/usr/sbin/mysqld(+0x7d217b)[0x55b2f213717b]
 
/usr/sbin/mysqld(+0x7bc990)[0x55b2f2121990]
 
/lib64/libpthread.so.0(+0x7aa1)[0x7f0ef41bdaa1]
 
/lib64/libc.so.6(clone+0x6d)[0x7f0ef28d5aad]
 
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.
 
161102 12:17:46 mysqld_safe Number of processes running now: 0
 
161102 12:17:46 mysqld_safe mysqld restarted
 
2016-11-02 12:17:47 140154303006752 [Note] /usr/sbin/mysqld (mysqld 10.1.18-MariaDB) starting as process 11425 ...
 
2016-11-02 12:17:47 140154303006752 [Warning] Although a path was specified for the --log-slow-queries option, log tables are used. To enable logging to files use the --log-output=file option.
 
2016-11-02 12:17:47 140154303006752 [Warning] option 'innodb-sort-buffer-size': unsigned value 4294967296 adjusted to 67108864
 
2016-11-02 12:17:47 140154303006752 [Warning] option 'innodb-ft-cache-size': unsigned value 83886080 adjusted to 80000000
 
2016-11-02 12:17:47 140154303006752 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
2016-11-02 12:17:47 140154303006752 [Note] InnoDB: The InnoDB memory heap is disabled
 
2016-11-02 12:17:47 140154303006752 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2016-11-02 12:17:47 140154303006752 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
 
2016-11-02 12:17:47 140154303006752 [Note] InnoDB: Compressed tables use zlib 1.2.3
 
2016-11-02 12:17:47 140154303006752 [Note] InnoDB: Using Linux native AIO
 
2016-11-02 12:17:47 140154303006752 [Note] InnoDB: Using SSE crc32 instructions
 
2016-11-02 12:17:47 140154303006752 [Note] InnoDB: Initializing buffer pool, size = 14.0G
 
2016-11-02 12:17:47 140154303006752 [Note] InnoDB: Completed initialization of buffer pool
 
2016-11-02 12:17:48 140154303006752 [Note] InnoDB: Highest supported file format is Barracuda.
 
2016-11-02 12:17:48 140154303006752 [Note] InnoDB: Log scan progressed past the checkpoint lsn 15937771677812
 
2016-11-02 12:17:48 140154303006752 [Note] InnoDB: Database was not shutdown normally!
 
2016-11-02 12:17:48 140154303006752 [Note] InnoDB: Starting crash recovery.
 
2016-11-02 12:17:48 140154303006752 [Note] InnoDB: Reading tablespace information from the .ibd files...
 
2016-11-02 12:18:04 140154303006752 [Note] InnoDB: Processed 92422 .ibd/.isl files
 
2016-11-02 12:18:15 140154303006752 [Note] InnoDB: Restoring possible half-written data pages 
2016-11-02 12:18:15 140154303006752 [Note] InnoDB: from the doublewrite buffer...
 
InnoDB: Doing recovery: scanned up to log sequence number 15937776920576
 
InnoDB: Doing recovery: scanned up to log sequence number 15937782163456
 
InnoDB: Doing recovery: scanned up to log sequence number 15937787406336
 
InnoDB: Doing recovery: scanned up to log sequence number 15937792649216

Comment by Viktor Zeman [ 2016-11-02 ]

Only difference between original crash report and current crash could be, that in the meantime we are using compressed table row format.

Comment by Jan Lindström (Inactive) [ 2016-11-02 ]

This is not a same assertion is different as it tries to assert that whole buffer was added to sort buffer. I could not repeat the assertion using original table and data above. Can you share the structure of the table and loaded data for current problem ?

Comment by Viktor Zeman [ 2016-11-02 ]

Table structure:

CREATE TABLE `qu_g_mails` (
 
  `mailid` int(10) unsigned NOT NULL AUTO_INCREMENT,
 
  `hdr_message_id` varchar(255) DEFAULT NULL,
 
  `unique_message_id` varchar(255) NOT NULL,
 
  `subject` text,
 
  `headers` text,
 
  `body_text` longtext,
 
  `body_html` longtext,
 
  `created` datetime NOT NULL,
 
  `delivered` datetime DEFAULT NULL,
 
  `from_mail` text,
 
  `to_recipients` text,
 
  `cc_recipients` text,
 
  `bcc_recipients` text,
 
  `accountuserid` char(8) DEFAULT NULL,
 
  `reply_to` text,
 
  PRIMARY KEY (`mailid`),
 
  KEY `IDX_qu_g_mails_1` (`accountuserid`)
 
) ENGINE=InnoDB  DEFAULT CHARSET=utf8 ROW_FORMAT=COMPRESSED;

Mysql crash when adding index on 3 columns: subject, body_text, body_html

ALTER TABLE qu_g_mails ADD FULLTEXT ft_qu_g_mails1 (subject, body_text, body_html);

Database table is filled with about 150MB of emails, I'm not able to provide these data

Here are server settings:

[mysqld]
 
server-id=3
 
datadir=/opt/mysql/
 
socket=/var/lib/mysql/mysql.sock
 
tmpdir=/tmp/
 
 
 
log_bin=mysql-bin
 
expire_logs_days=4
 
 
 
wait_timeout=60
 
 
 
long_query_time=1
 
slow_query_log=1
 
slow_query_log_file=/opt/log/slow.log
 
log_output=TABLE
 
 
 
userstat = 1
 
 
 
user=root
 
symbolic-links=0
 
binlog_format=STATEMENT
 
 
 
default_storage_engine=InnoDB
 
 
 
slave_skip_errors=1062,1396,1690
 
 
 
innodb_autoinc_lock_mode=2
 
 
 
innodb_buffer_pool_size=14G
 
innodb_buffer_pool_instances=10
 
innodb_log_file_size=1G
 
innodb_log_buffer_size=196M
 
innodb_flush_log_at_trx_commit=1
 
innodb_thread_concurrency=24
 
innodb_file_per_table
 
innodb_write_io_threads=24
 
innodb_read_io_threads=24
 
innodb_sched_priority_cleaner=39
 
innodb_adaptive_flushing=1
 
innodb_purge_threads=5
 
innodb_adaptive_hash_index_partitions=64
 
innodb_flush_neighbors=0
 
innodb_flush_method=O_DIRECT
 
innodb_io_capacity=5000
 
innodb_io_capacity_max=8000
 
innodb_lru_scan_depth=1024
 
innodb_sort_buffer_size=32M
 
innodb_ft_cache_size=80M
 
innodb_ft_total_cache_size=1G
 
 
 
 
 
 
 
slave_parallel_threads=10
 
log_slave_updates=on
 
 
 
performance_schema=off
 
 
 
skip-name-resolve
 
 
 
max_allowed_packet = 512M
 
 
 
query_cache_type=1
 
query_cache_size = 0
 
query_cache_limit = 1M
 
query_cache_min_res_unit=1K
 
max_connections = 900
 
 
 
table_open_cache=64K
 
innodb_open_files=64K
 
open_files_limit=1020000
 
collation-server = utf8_general_ci
 
character-set-server = utf8
 
 
 
log-error=/opt/log/error.log
 
 
 
[mysqld_safe]
 
log-error=/opt/log/error.log
 
pid-file=/var/run/mysqld/mysqld.pid
 
malloc-lib=/usr/lib64/libjemalloc.so.1

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