[MDEV-11233] CREATE FULLTEXT INDEX with a token longer than 127 bytes crashes server - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 10.1.17, 10.1.18
Fix Version/s: 10.0.30, 10.1.20, 10.2.3
Component/s: Data Definition - Alter Table, Storage Engine - InnoDB
Labels:
- index
- innodb
Environment:
Centos 6.5, Mariadb 10.1.18 and Mariadb 10.1.17 (and also on all older)
Linode virtual server 48GB RAM

Sprint:
10.1.20

Description

Adding fulltext index on bigger table crash server

2016-11-04 07:41:26 7f7149bfe700  InnoDB: Assertion failure in thread 140124545345280 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.

161104  7:41:26 [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.17-MariaDB

key_buffer_size=134217728

read_buffer_size=131072

max_used_connections=54

max_threads=902

thread_count=8

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

2016-11-04 07:41:27 7f714a3ff700  InnoDB: Assertion failure in thread 140124553737984 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.

161104 07:41:29 mysqld_safe Number of processes running now: 0

161104 07:41:29 mysqld_safe mysqld restarted

2016-11-04  7:41:29 140601780914208 [Note] /usr/sbin/mysqld (mysqld 10.1.17-MariaDB) starting as process 25262 ...

2016-11-04  7:41:29 140601780914208 [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-04  7:41:29 140601780914208 [Warning] option 'innodb-ft-cache-size': unsigned value 83886080 adjusted to 80000000

2016-11-04  7:41:29 140601780914208 [Note] InnoDB: Using mutexes to ref count buffer pool pages

2016-11-04  7:41:29 140601780914208 [Note] InnoDB: The InnoDB memory heap is disabled

2016-11-04  7:41:29 140601780914208 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

2016-11-04  7:41:29 140601780914208 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier

2016-11-04  7:41:29 140601780914208 [Note] InnoDB: Compressed tables use zlib 1.2.3

2016-11-04  7:41:29 140601780914208 [Note] InnoDB: Using Linux native AIO

2016-11-04  7:41:29 140601780914208 [Note] InnoDB: Using SSE crc32 instructions

2016-11-04  7:41:29 140601780914208 [Note] InnoDB: Initializing buffer pool, size = 14.0G

2016-11-04  7:41:30 140601780914208 [Note] InnoDB: Completed initialization of buffer pool

2016-11-04  7:41:30 140601780914208 [Note] InnoDB: Highest supported file format is Barracuda.

2016-11-04  7:41:30 140601780914208 [Note] InnoDB: Log scan progressed past the checkpoint lsn 5089194166241

2016-11-04  7:41:30 140601780914208 [Note] InnoDB: Database was not shutdown normally!

2016-11-04  7:41:30 140601780914208 [Note] InnoDB: Starting crash recovery.

2016-11-04  7:41:30 140601780914208 [Note] InnoDB: Reading tablespace information from the .ibd files...

2016-11-04  7:41:46 140601780914208 [Note] InnoDB: Processed 81433 .ibd/.isl files

2016-11-04  7:42:02 140601780914208 [Note] InnoDB: Processed 165583 .ibd/.isl files

2016-11-04  7:42:18 140601780914208 [Note] InnoDB: Processed 248732 .ibd/.isl files

2016-11-04  7:42:34 140601780914208 [Note] InnoDB: Processed 331595 .ibd/.isl files

2016-11-04  7:42:50 140601780914208 [Note] InnoDB: Processed 410190 .ibd/.isl files

2016-11-04  7:43:06 140601780914208 [Note] InnoDB: Processed 490369 .ibd/.isl files

2016-11-04  7:43:22 140601780914208 [Note] InnoDB: Processed 571032 .ibd/.isl files

2016-11-04  7:43:38 140601780914208 [Note] InnoDB: Processed 653103 .ibd/.isl files

2016-11-04  7:43:54 140601780914208 [Note] InnoDB: Processed 733414 .ibd/.isl files

2016-11-04  7:44:10 140601780914208 [Note] InnoDB: Processed 811624 .ibd/.isl files

2016-11-04  7:44:26 140601780914208 [Note] InnoDB: Processed 891341 .ibd/.isl files

2016-11-04  7:44:42 140601780914208 [Note] InnoDB: Processed 969320 .ibd/.isl files

2016-11-04  7:44:58 140601780914208 [Note] InnoDB: Processed 1047838 .ibd/.isl files

2016-11-04  7:45:14 140601780914208 [Note] InnoDB: Processed 1123078 .ibd/.isl files

2016-11-04  7:45:25 140601780914208 [Note] InnoDB: Restoring possible half-written data pages

2016-11-04  7:45:25 140601780914208 [Note] InnoDB: from the doublewrite buffer...

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

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

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

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

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

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

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

.... etc

Problem was started by SQL:
ALTER TABLE `qu_la_contacts` ADD FULLTEXT `qu_la_contacts_ftidx` (`firstname` ,`lastname` ,`emails` ,`system_name`)

on table, which has about 200k rows

CREATE TABLE IF NOT EXISTS `qu_la_contacts` (

  `contactid` CHAR(8) NOT NULL,

  `parent_contactid` CHAR(8) NULL,

  `company` CHAR(1) NOT NULL DEFAULT 'N',

  `job_position` VARCHAR(255) NULL,

  `emails` TEXT NULL,

  `firstname` VARCHAR(100) NULL,

  `lastname` VARCHAR(100) NULL,

  `system_name` VARCHAR(100) NULL,

  `description` VARCHAR(255) NULL,

  `rtype` CHAR(1) NOT NULL,

  `status` CHAR(1) NOT NULL DEFAULT 'A' COMMENT 'A=Active, X=Deleted',

  `datecreated` DATETIME NULL,

  `avatar_url` TEXT NULL,

  `city` VARCHAR(255) NULL,

  `countrycode` VARCHAR(2) NULL,

  `note` TEXT NULL,

  `time_offset` INT NULL,

  `language` VARCHAR(10) NULL,

  `gender` CHAR(1) NOT NULL DEFAULT 'M',

  `levelid` CHAR(8) NULL,

  `ldap_id` VARCHAR(255) NULL,

  `groups` VARCHAR(255) NULL,

  `ip` VARCHAR(39) NULL,

  `useragent` TEXT NULL,

  `screen` VARCHAR(12) NULL,

  `latitude` FLOAT NULL,

  `longitude` FLOAT NULL,

  `last_action_type` CHAR(1) NULL,

  `last_action_date` DATETIME NULL,

  `last_action_meta` VARCHAR(80) NULL,

  PRIMARY KEY (`contactid`),

  INDEX `fk_qu_la_contacts_qu_la_levels1_idx` (`levelid` ASC),

  INDEX `fk_parent_contactid` (`parent_contactid` ASC),

  INDEX `qu_la_contacts_datecreated` (`datecreated` ASC),

  INDEX `qu_la_contacts_firstname` (`firstname` ASC),

  INDEX `qu_la_contacts_lastname` (`lastname` ASC),

  INDEX `qu_la_contacts_system_name` (`system_name` ASC),

  INDEX `qu_la_contacts_company` (`company`)

ENGINE = InnoDB;

Server settings:

[mysqld]

server-id=14

datadir=/opt/mysql/

socket=/var/lib/mysql/mysql.sock

tmpdir=/tmp/

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

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

#transaction-isolation=READ-COMMITTED

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

Exactly the same problem happen on another table when adding fulltext index (table size about 150MB) (reported in additional comments here: https://jira.mariadb.org/browse/MDEV-9129):

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

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;

Attachments

Issue Links

is duplicated by

MDEV-11918 CREATE FULLTEXT INDEX with a token longer than 127 bytes crashes server (10.0 version)

Closed

relates to

MDEV-11241 Certain combining marks cause MariaDB to crash when doing Full-Text searches

Closed

Activity

Ascending order - Click to sort in descending order

Viktor Zeman created issue - 2016-11-04 08:16

Viktor Zeman made changes - 2016-11-04 08:19

Field	Original Value	New Value
Description	Adding fulltext index on bigger table crash server {code:java} 2016-11-04 07:41:26 7f7149bfe700 InnoDB: Assertion failure in thread 140124545345280 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. 161104 7:41:26 [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.17-MariaDB key_buffer_size=134217728 read_buffer_size=131072 max_used_connections=54 max_threads=902 thread_count=8 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 2016-11-04 07:41:27 7f714a3ff700 InnoDB: Assertion failure in thread 140124553737984 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. 161104 07:41:29 mysqld_safe Number of processes running now: 0 161104 07:41:29 mysqld_safe mysqld restarted 2016-11-04 7:41:29 140601780914208 [Note] /usr/sbin/mysqld (mysqld 10.1.17-MariaDB) starting as process 25262 ... 2016-11-04 7:41:29 140601780914208 [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-04 7:41:29 140601780914208 [Warning] option 'innodb-ft-cache-size': unsigned value 83886080 adjusted to 80000000 2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Using mutexes to ref count buffer pool pages 2016-11-04 7:41:29 140601780914208 [Note] InnoDB: The InnoDB memory heap is disabled 2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2016-11-04 7:41:29 140601780914208 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier 2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Compressed tables use zlib 1.2.3 2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Using Linux native AIO 2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Using SSE crc32 instructions 2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Initializing buffer pool, size = 14.0G 2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Completed initialization of buffer pool 2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Highest supported file format is Barracuda. 2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Log scan progressed past the checkpoint lsn 5089194166241 2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Database was not shutdown normally! 2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Starting crash recovery. 2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Reading tablespace information from the .ibd files... 2016-11-04 7:41:46 140601780914208 [Note] InnoDB: Processed 81433 .ibd/.isl files 2016-11-04 7:42:02 140601780914208 [Note] InnoDB: Processed 165583 .ibd/.isl files 2016-11-04 7:42:18 140601780914208 [Note] InnoDB: Processed 248732 .ibd/.isl files 2016-11-04 7:42:34 140601780914208 [Note] InnoDB: Processed 331595 .ibd/.isl files 2016-11-04 7:42:50 140601780914208 [Note] InnoDB: Processed 410190 .ibd/.isl files 2016-11-04 7:43:06 140601780914208 [Note] InnoDB: Processed 490369 .ibd/.isl files 2016-11-04 7:43:22 140601780914208 [Note] InnoDB: Processed 571032 .ibd/.isl files 2016-11-04 7:43:38 140601780914208 [Note] InnoDB: Processed 653103 .ibd/.isl files 2016-11-04 7:43:54 140601780914208 [Note] InnoDB: Processed 733414 .ibd/.isl files 2016-11-04 7:44:10 140601780914208 [Note] InnoDB: Processed 811624 .ibd/.isl files 2016-11-04 7:44:26 140601780914208 [Note] InnoDB: Processed 891341 .ibd/.isl files 2016-11-04 7:44:42 140601780914208 [Note] InnoDB: Processed 969320 .ibd/.isl files 2016-11-04 7:44:58 140601780914208 [Note] InnoDB: Processed 1047838 .ibd/.isl files 2016-11-04 7:45:14 140601780914208 [Note] InnoDB: Processed 1123078 .ibd/.isl files 2016-11-04 7:45:25 140601780914208 [Note] InnoDB: Restoring possible half-written data pages 2016-11-04 7:45:25 140601780914208 [Note] InnoDB: from the doublewrite buffer... InnoDB: Doing recovery: scanned up to log sequence number 5089199408640 InnoDB: Doing recovery: scanned up to log sequence number 5089204651520 InnoDB: Doing recovery: scanned up to log sequence number 5089209894400 InnoDB: Doing recovery: scanned up to log sequence number 5089215137280 InnoDB: Doing recovery: scanned up to log sequence number 5089220380160 InnoDB: Doing recovery: scanned up to log sequence number 5089225623040 InnoDB: Doing recovery: scanned up to log sequence number 5089230865920 .... etc {code} Problem was started by SQL: ALTER TABLE `qu_la_contacts` ADD FULLTEXT `qu_la_contacts_ftidx` (`firstname` ,`lastname` ,`emails` ,`system_name`) on table {code:java} CREATE TABLE IF NOT EXISTS `qu_la_contacts` ( `contactid` CHAR(8) NOT NULL, `parent_contactid` CHAR(8) NULL, `company` CHAR(1) NOT NULL DEFAULT 'N', `job_position` VARCHAR(255) NULL, `emails` TEXT NULL, `firstname` VARCHAR(100) NULL, `lastname` VARCHAR(100) NULL, `system_name` VARCHAR(100) NULL, `description` VARCHAR(255) NULL, `rtype` CHAR(1) NOT NULL, `status` CHAR(1) NOT NULL DEFAULT 'A' COMMENT 'A=Active, X=Deleted', `datecreated` DATETIME NULL, `avatar_url` TEXT NULL, `city` VARCHAR(255) NULL, `countrycode` VARCHAR(2) NULL, `note` TEXT NULL, `time_offset` INT NULL, `language` VARCHAR(10) NULL, `gender` CHAR(1) NOT NULL DEFAULT 'M', `levelid` CHAR(8) NULL, `ldap_id` VARCHAR(255) NULL, `groups` VARCHAR(255) NULL, `ip` VARCHAR(39) NULL, `useragent` TEXT NULL, `screen` VARCHAR(12) NULL, `latitude` FLOAT NULL, `longitude` FLOAT NULL, `last_action_type` CHAR(1) NULL, `last_action_date` DATETIME NULL, `last_action_meta` VARCHAR(80) NULL, PRIMARY KEY (`contactid`), INDEX `fk_qu_la_contacts_qu_la_levels1_idx` (`levelid` ASC), INDEX `fk_parent_contactid` (`parent_contactid` ASC), INDEX `qu_la_contacts_datecreated` (`datecreated` ASC), INDEX `qu_la_contacts_firstname` (`firstname` ASC), INDEX `qu_la_contacts_lastname` (`lastname` ASC), INDEX `qu_la_contacts_system_name` (`system_name` ASC), INDEX `qu_la_contacts_company` (`company`) ) ENGINE = InnoDB; {code} Server settings: {code:java} [mysqld] server-id=14 datadir=/opt/mysql/ socket=/var/lib/mysql/mysql.sock tmpdir=/tmp/ 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 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 #transaction-isolation=READ-COMMITTED 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 {code}	Adding fulltext index on bigger table crash server {code:java} 2016-11-04 07:41:26 7f7149bfe700 InnoDB: Assertion failure in thread 140124545345280 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. 161104 7:41:26 [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.17-MariaDB key_buffer_size=134217728 read_buffer_size=131072 max_used_connections=54 max_threads=902 thread_count=8 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 2016-11-04 07:41:27 7f714a3ff700 InnoDB: Assertion failure in thread 140124553737984 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. 161104 07:41:29 mysqld_safe Number of processes running now: 0 161104 07:41:29 mysqld_safe mysqld restarted 2016-11-04 7:41:29 140601780914208 [Note] /usr/sbin/mysqld (mysqld 10.1.17-MariaDB) starting as process 25262 ... 2016-11-04 7:41:29 140601780914208 [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-04 7:41:29 140601780914208 [Warning] option 'innodb-ft-cache-size': unsigned value 83886080 adjusted to 80000000 2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Using mutexes to ref count buffer pool pages 2016-11-04 7:41:29 140601780914208 [Note] InnoDB: The InnoDB memory heap is disabled 2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2016-11-04 7:41:29 140601780914208 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier 2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Compressed tables use zlib 1.2.3 2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Using Linux native AIO 2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Using SSE crc32 instructions 2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Initializing buffer pool, size = 14.0G 2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Completed initialization of buffer pool 2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Highest supported file format is Barracuda. 2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Log scan progressed past the checkpoint lsn 5089194166241 2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Database was not shutdown normally! 2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Starting crash recovery. 2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Reading tablespace information from the .ibd files... 2016-11-04 7:41:46 140601780914208 [Note] InnoDB: Processed 81433 .ibd/.isl files 2016-11-04 7:42:02 140601780914208 [Note] InnoDB: Processed 165583 .ibd/.isl files 2016-11-04 7:42:18 140601780914208 [Note] InnoDB: Processed 248732 .ibd/.isl files 2016-11-04 7:42:34 140601780914208 [Note] InnoDB: Processed 331595 .ibd/.isl files 2016-11-04 7:42:50 140601780914208 [Note] InnoDB: Processed 410190 .ibd/.isl files 2016-11-04 7:43:06 140601780914208 [Note] InnoDB: Processed 490369 .ibd/.isl files 2016-11-04 7:43:22 140601780914208 [Note] InnoDB: Processed 571032 .ibd/.isl files 2016-11-04 7:43:38 140601780914208 [Note] InnoDB: Processed 653103 .ibd/.isl files 2016-11-04 7:43:54 140601780914208 [Note] InnoDB: Processed 733414 .ibd/.isl files 2016-11-04 7:44:10 140601780914208 [Note] InnoDB: Processed 811624 .ibd/.isl files 2016-11-04 7:44:26 140601780914208 [Note] InnoDB: Processed 891341 .ibd/.isl files 2016-11-04 7:44:42 140601780914208 [Note] InnoDB: Processed 969320 .ibd/.isl files 2016-11-04 7:44:58 140601780914208 [Note] InnoDB: Processed 1047838 .ibd/.isl files 2016-11-04 7:45:14 140601780914208 [Note] InnoDB: Processed 1123078 .ibd/.isl files 2016-11-04 7:45:25 140601780914208 [Note] InnoDB: Restoring possible half-written data pages 2016-11-04 7:45:25 140601780914208 [Note] InnoDB: from the doublewrite buffer... InnoDB: Doing recovery: scanned up to log sequence number 5089199408640 InnoDB: Doing recovery: scanned up to log sequence number 5089204651520 InnoDB: Doing recovery: scanned up to log sequence number 5089209894400 InnoDB: Doing recovery: scanned up to log sequence number 5089215137280 InnoDB: Doing recovery: scanned up to log sequence number 5089220380160 InnoDB: Doing recovery: scanned up to log sequence number 5089225623040 InnoDB: Doing recovery: scanned up to log sequence number 5089230865920 .... etc {code} Problem was started by SQL: ALTER TABLE `qu_la_contacts` ADD FULLTEXT `qu_la_contacts_ftidx` (`firstname` ,`lastname` ,`emails` ,`system_name`) on table, which has about 200k rows {code:java} CREATE TABLE IF NOT EXISTS `qu_la_contacts` ( `contactid` CHAR(8) NOT NULL, `parent_contactid` CHAR(8) NULL, `company` CHAR(1) NOT NULL DEFAULT 'N', `job_position` VARCHAR(255) NULL, `emails` TEXT NULL, `firstname` VARCHAR(100) NULL, `lastname` VARCHAR(100) NULL, `system_name` VARCHAR(100) NULL, `description` VARCHAR(255) NULL, `rtype` CHAR(1) NOT NULL, `status` CHAR(1) NOT NULL DEFAULT 'A' COMMENT 'A=Active, X=Deleted', `datecreated` DATETIME NULL, `avatar_url` TEXT NULL, `city` VARCHAR(255) NULL, `countrycode` VARCHAR(2) NULL, `note` TEXT NULL, `time_offset` INT NULL, `language` VARCHAR(10) NULL, `gender` CHAR(1) NOT NULL DEFAULT 'M', `levelid` CHAR(8) NULL, `ldap_id` VARCHAR(255) NULL, `groups` VARCHAR(255) NULL, `ip` VARCHAR(39) NULL, `useragent` TEXT NULL, `screen` VARCHAR(12) NULL, `latitude` FLOAT NULL, `longitude` FLOAT NULL, `last_action_type` CHAR(1) NULL, `last_action_date` DATETIME NULL, `last_action_meta` VARCHAR(80) NULL, PRIMARY KEY (`contactid`), INDEX `fk_qu_la_contacts_qu_la_levels1_idx` (`levelid` ASC), INDEX `fk_parent_contactid` (`parent_contactid` ASC), INDEX `qu_la_contacts_datecreated` (`datecreated` ASC), INDEX `qu_la_contacts_firstname` (`firstname` ASC), INDEX `qu_la_contacts_lastname` (`lastname` ASC), INDEX `qu_la_contacts_system_name` (`system_name` ASC), INDEX `qu_la_contacts_company` (`company`) ) ENGINE = InnoDB; {code} Server settings: {code:java} [mysqld] server-id=14 datadir=/opt/mysql/ socket=/var/lib/mysql/mysql.sock tmpdir=/tmp/ 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 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 #transaction-isolation=READ-COMMITTED 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 {code} Exactly the same problem happen on another table when adding fulltext index (table size about 150MB): {code:java} ALTER TABLE qu_g_mails ADD FULLTEXT ft_qu_g_mails1 (subject, body_text, body_html); {code} {code:java} 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; {code}

Viktor Zeman made changes - 2016-11-04 08:20

Description

Adding fulltext index on bigger table crash server

{code:java}
2016-11-04 07:41:26 7f7149bfe700 InnoDB: Assertion failure in thread 140124545345280 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.
161104 7:41:26 [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.17-MariaDB
key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=54
max_threads=902
thread_count=8
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
2016-11-04 07:41:27 7f714a3ff700 InnoDB: Assertion failure in thread 140124553737984 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.
161104 07:41:29 mysqld_safe Number of processes running now: 0
161104 07:41:29 mysqld_safe mysqld restarted
2016-11-04 7:41:29 140601780914208 [Note] /usr/sbin/mysqld (mysqld 10.1.17-MariaDB) starting as process 25262 ...
2016-11-04 7:41:29 140601780914208 [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-04 7:41:29 140601780914208 [Warning] option 'innodb-ft-cache-size': unsigned value 83886080 adjusted to 80000000
2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2016-11-04 7:41:29 140601780914208 [Note] InnoDB: The InnoDB memory heap is disabled
2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-11-04 7:41:29 140601780914208 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Compressed tables use zlib 1.2.3
2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Using Linux native AIO
2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Using SSE crc32 instructions
2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Initializing buffer pool, size = 14.0G
2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Completed initialization of buffer pool
2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Highest supported file format is Barracuda.
2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Log scan progressed past the checkpoint lsn 5089194166241
2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Database was not shutdown normally!
2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Starting crash recovery.
2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Reading tablespace information from the .ibd files...
2016-11-04 7:41:46 140601780914208 [Note] InnoDB: Processed 81433 .ibd/.isl files
2016-11-04 7:42:02 140601780914208 [Note] InnoDB: Processed 165583 .ibd/.isl files
2016-11-04 7:42:18 140601780914208 [Note] InnoDB: Processed 248732 .ibd/.isl files
2016-11-04 7:42:34 140601780914208 [Note] InnoDB: Processed 331595 .ibd/.isl files
2016-11-04 7:42:50 140601780914208 [Note] InnoDB: Processed 410190 .ibd/.isl files
2016-11-04 7:43:06 140601780914208 [Note] InnoDB: Processed 490369 .ibd/.isl files
2016-11-04 7:43:22 140601780914208 [Note] InnoDB: Processed 571032 .ibd/.isl files
2016-11-04 7:43:38 140601780914208 [Note] InnoDB: Processed 653103 .ibd/.isl files
2016-11-04 7:43:54 140601780914208 [Note] InnoDB: Processed 733414 .ibd/.isl files
2016-11-04 7:44:10 140601780914208 [Note] InnoDB: Processed 811624 .ibd/.isl files
2016-11-04 7:44:26 140601780914208 [Note] InnoDB: Processed 891341 .ibd/.isl files
2016-11-04 7:44:42 140601780914208 [Note] InnoDB: Processed 969320 .ibd/.isl files
2016-11-04 7:44:58 140601780914208 [Note] InnoDB: Processed 1047838 .ibd/.isl files
2016-11-04 7:45:14 140601780914208 [Note] InnoDB: Processed 1123078 .ibd/.isl files
2016-11-04 7:45:25 140601780914208 [Note] InnoDB: Restoring possible half-written data pages
2016-11-04 7:45:25 140601780914208 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 5089199408640
InnoDB: Doing recovery: scanned up to log sequence number 5089204651520
InnoDB: Doing recovery: scanned up to log sequence number 5089209894400
InnoDB: Doing recovery: scanned up to log sequence number 5089215137280
InnoDB: Doing recovery: scanned up to log sequence number 5089220380160
InnoDB: Doing recovery: scanned up to log sequence number 5089225623040
InnoDB: Doing recovery: scanned up to log sequence number 5089230865920
.... etc
{code}

Problem was started by SQL:
ALTER TABLE `qu_la_contacts` ADD FULLTEXT `qu_la_contacts_ftidx` (`firstname` ,`lastname` ,`emails` ,`system_name`)

on table, which has about 200k rows

{code:java}
CREATE TABLE IF NOT EXISTS `qu_la_contacts` (
  `contactid` CHAR(8) NOT NULL,
  `parent_contactid` CHAR(8) NULL,
  `company` CHAR(1) NOT NULL DEFAULT 'N',
  `job_position` VARCHAR(255) NULL,
  `emails` TEXT NULL,
  `firstname` VARCHAR(100) NULL,
  `lastname` VARCHAR(100) NULL,
  `system_name` VARCHAR(100) NULL,
  `description` VARCHAR(255) NULL,
  `rtype` CHAR(1) NOT NULL,
  `status` CHAR(1) NOT NULL DEFAULT 'A' COMMENT 'A=Active, X=Deleted',
  `datecreated` DATETIME NULL,
  `avatar_url` TEXT NULL,
  `city` VARCHAR(255) NULL,
  `countrycode` VARCHAR(2) NULL,
  `note` TEXT NULL,
  `time_offset` INT NULL,
  `language` VARCHAR(10) NULL,
  `gender` CHAR(1) NOT NULL DEFAULT 'M',
  `levelid` CHAR(8) NULL,
  `ldap_id` VARCHAR(255) NULL,
  `groups` VARCHAR(255) NULL,
  `ip` VARCHAR(39) NULL,
  `useragent` TEXT NULL,
  `screen` VARCHAR(12) NULL,
  `latitude` FLOAT NULL,
  `longitude` FLOAT NULL,
  `last_action_type` CHAR(1) NULL,
  `last_action_date` DATETIME NULL,
  `last_action_meta` VARCHAR(80) NULL,
  PRIMARY KEY (`contactid`),
  INDEX `fk_qu_la_contacts_qu_la_levels1_idx` (`levelid` ASC),
  INDEX `fk_parent_contactid` (`parent_contactid` ASC),
  INDEX `qu_la_contacts_datecreated` (`datecreated` ASC),
  INDEX `qu_la_contacts_firstname` (`firstname` ASC),
  INDEX `qu_la_contacts_lastname` (`lastname` ASC),
  INDEX `qu_la_contacts_system_name` (`system_name` ASC),
  INDEX `qu_la_contacts_company` (`company`)
  )
ENGINE = InnoDB;
{code}

Server settings:

{code:java}
[mysqld]
server-id=14
datadir=/opt/mysql/
socket=/var/lib/mysql/mysql.sock
tmpdir=/tmp/

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
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
#transaction-isolation=READ-COMMITTED
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

{code}

Exactly the same problem happen on another table when adding fulltext index (table size about 150MB):

{code:java}
ALTER TABLE qu_g_mails ADD FULLTEXT ft_qu_g_mails1 (subject, body_text, body_html);
{code}

{code:java}
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;
{code}

Adding fulltext index on bigger table crash server

{code:java}
2016-11-04 07:41:26 7f7149bfe700 InnoDB: Assertion failure in thread 140124545345280 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.
161104 7:41:26 [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.17-MariaDB
key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=54
max_threads=902
thread_count=8
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
2016-11-04 07:41:27 7f714a3ff700 InnoDB: Assertion failure in thread 140124553737984 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.
161104 07:41:29 mysqld_safe Number of processes running now: 0
161104 07:41:29 mysqld_safe mysqld restarted
2016-11-04 7:41:29 140601780914208 [Note] /usr/sbin/mysqld (mysqld 10.1.17-MariaDB) starting as process 25262 ...
2016-11-04 7:41:29 140601780914208 [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-04 7:41:29 140601780914208 [Warning] option 'innodb-ft-cache-size': unsigned value 83886080 adjusted to 80000000
2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2016-11-04 7:41:29 140601780914208 [Note] InnoDB: The InnoDB memory heap is disabled
2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-11-04 7:41:29 140601780914208 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Compressed tables use zlib 1.2.3
2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Using Linux native AIO
2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Using SSE crc32 instructions
2016-11-04 7:41:29 140601780914208 [Note] InnoDB: Initializing buffer pool, size = 14.0G
2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Completed initialization of buffer pool
2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Highest supported file format is Barracuda.
2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Log scan progressed past the checkpoint lsn 5089194166241
2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Database was not shutdown normally!
2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Starting crash recovery.
2016-11-04 7:41:30 140601780914208 [Note] InnoDB: Reading tablespace information from the .ibd files...
2016-11-04 7:41:46 140601780914208 [Note] InnoDB: Processed 81433 .ibd/.isl files
2016-11-04 7:42:02 140601780914208 [Note] InnoDB: Processed 165583 .ibd/.isl files
2016-11-04 7:42:18 140601780914208 [Note] InnoDB: Processed 248732 .ibd/.isl files
2016-11-04 7:42:34 140601780914208 [Note] InnoDB: Processed 331595 .ibd/.isl files
2016-11-04 7:42:50 140601780914208 [Note] InnoDB: Processed 410190 .ibd/.isl files
2016-11-04 7:43:06 140601780914208 [Note] InnoDB: Processed 490369 .ibd/.isl files
2016-11-04 7:43:22 140601780914208 [Note] InnoDB: Processed 571032 .ibd/.isl files
2016-11-04 7:43:38 140601780914208 [Note] InnoDB: Processed 653103 .ibd/.isl files
2016-11-04 7:43:54 140601780914208 [Note] InnoDB: Processed 733414 .ibd/.isl files
2016-11-04 7:44:10 140601780914208 [Note] InnoDB: Processed 811624 .ibd/.isl files
2016-11-04 7:44:26 140601780914208 [Note] InnoDB: Processed 891341 .ibd/.isl files
2016-11-04 7:44:42 140601780914208 [Note] InnoDB: Processed 969320 .ibd/.isl files
2016-11-04 7:44:58 140601780914208 [Note] InnoDB: Processed 1047838 .ibd/.isl files
2016-11-04 7:45:14 140601780914208 [Note] InnoDB: Processed 1123078 .ibd/.isl files
2016-11-04 7:45:25 140601780914208 [Note] InnoDB: Restoring possible half-written data pages
2016-11-04 7:45:25 140601780914208 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 5089199408640
InnoDB: Doing recovery: scanned up to log sequence number 5089204651520
InnoDB: Doing recovery: scanned up to log sequence number 5089209894400
InnoDB: Doing recovery: scanned up to log sequence number 5089215137280
InnoDB: Doing recovery: scanned up to log sequence number 5089220380160
InnoDB: Doing recovery: scanned up to log sequence number 5089225623040
InnoDB: Doing recovery: scanned up to log sequence number 5089230865920
.... etc
{code}

Problem was started by SQL:
ALTER TABLE `qu_la_contacts` ADD FULLTEXT `qu_la_contacts_ftidx` (`firstname` ,`lastname` ,`emails` ,`system_name`)

on table, which has about 200k rows

{code:java}
CREATE TABLE IF NOT EXISTS `qu_la_contacts` (
  `contactid` CHAR(8) NOT NULL,
  `parent_contactid` CHAR(8) NULL,
  `company` CHAR(1) NOT NULL DEFAULT 'N',
  `job_position` VARCHAR(255) NULL,
  `emails` TEXT NULL,
  `firstname` VARCHAR(100) NULL,
  `lastname` VARCHAR(100) NULL,
  `system_name` VARCHAR(100) NULL,
  `description` VARCHAR(255) NULL,
  `rtype` CHAR(1) NOT NULL,
  `status` CHAR(1) NOT NULL DEFAULT 'A' COMMENT 'A=Active, X=Deleted',
  `datecreated` DATETIME NULL,
  `avatar_url` TEXT NULL,
  `city` VARCHAR(255) NULL,
  `countrycode` VARCHAR(2) NULL,
  `note` TEXT NULL,
  `time_offset` INT NULL,
  `language` VARCHAR(10) NULL,
  `gender` CHAR(1) NOT NULL DEFAULT 'M',
  `levelid` CHAR(8) NULL,
  `ldap_id` VARCHAR(255) NULL,
  `groups` VARCHAR(255) NULL,
  `ip` VARCHAR(39) NULL,
  `useragent` TEXT NULL,
  `screen` VARCHAR(12) NULL,
  `latitude` FLOAT NULL,
  `longitude` FLOAT NULL,
  `last_action_type` CHAR(1) NULL,
  `last_action_date` DATETIME NULL,
  `last_action_meta` VARCHAR(80) NULL,
  PRIMARY KEY (`contactid`),
  INDEX `fk_qu_la_contacts_qu_la_levels1_idx` (`levelid` ASC),
  INDEX `fk_parent_contactid` (`parent_contactid` ASC),
  INDEX `qu_la_contacts_datecreated` (`datecreated` ASC),
  INDEX `qu_la_contacts_firstname` (`firstname` ASC),
  INDEX `qu_la_contacts_lastname` (`lastname` ASC),
  INDEX `qu_la_contacts_system_name` (`system_name` ASC),
  INDEX `qu_la_contacts_company` (`company`)
  )
ENGINE = InnoDB;
{code}

Server settings:

{code:java}
[mysqld]
server-id=14
datadir=/opt/mysql/
socket=/var/lib/mysql/mysql.sock
tmpdir=/tmp/

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
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
#transaction-isolation=READ-COMMITTED
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

{code}

Exactly the same problem happen on another table when adding fulltext index (table size about 150MB) (reported in additional comments here: https://jira.mariadb.org/browse/MDEV-9129):

{code:java}
ALTER TABLE qu_g_mails ADD FULLTEXT ft_qu_g_mails1 (subject, body_text, body_html);
{code}

{code:java}
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;
{code}

Viktor Zeman added a comment - 2016-11-04 14:14

After next investigation we think, that size of DB table doesn't play a role here.
It looks like the problem could be related to characters used in data.
If special characters are used, there is higher chance, that server crash.

e.g. we have about 800 databases on server with same structure, but only one DB crashed the server when changing qu_la_contacts table
(in db are special vietnamese characters)

On other hand adding fulltext index on qu_g_mails crash server nearly on every db we have on server. This table holds email sources, which contains special characters nearly in every db.

Our workaround was:
1. rename original table to table_backup
2. create empty table with correct structure (including fulltext index)
3. copy data from table_backup to empty table
In this way server doesn't crash.

Viktor Zeman added a comment - 2016-11-04 14:14 After next investigation we think, that size of DB table doesn't play a role here. It looks like the problem could be related to characters used in data. If special characters are used, there is higher chance, that server crash. e.g. we have about 800 databases on server with same structure, but only one DB crashed the server when changing qu_la_contacts table (in db are special vietnamese characters) On other hand adding fulltext index on qu_g_mails crash server nearly on every db we have on server. This table holds email sources, which contains special characters nearly in every db. Our workaround was: 1. rename original table to table_backup 2. create empty table with correct structure (including fulltext index) 3. copy data from table_backup to empty table In this way server doesn't crash.

Elena Stepanova added a comment - 2016-11-12 14:57

unitminer,

Is the problem reproducible if you reuse the tablespace instead of copying the data?

shutdown the server normally;
store the <crashing_table>.ibd file;
start the server;
create new empty table <new_table> with the same structure;
run ALTER TABLE <new_table> DISCARD TABLESPACE;
copy the stored ibd file to <new_table>.ibd in the corresponding database folder;
run ALTER TABLE <new_table> IMPORT TABLESPACE.

Does the server crash after that when you are using the new table?
If it does, would you be able to provide the example of such ibd file along with the exact structure of the <new_table> as SHOW CREATE TABLE shows?

Thanks.

Elena Stepanova added a comment - 2016-11-12 14:57 unitminer , Is the problem reproducible if you reuse the tablespace instead of copying the data? shutdown the server normally; store the <crashing_table>.ibd file; start the server; create new empty table <new_table> with the same structure; run ALTER TABLE <new_table> DISCARD TABLESPACE ; copy the stored ibd file to <new_table>.ibd in the corresponding database folder; run ALTER TABLE <new_table> IMPORT TABLESPACE . Does the server crash after that when you are using the new table? If it does, would you be able to provide the example of such ibd file along with the exact structure of the <new_table> as SHOW CREATE TABLE shows? Thanks.

Elena Stepanova made changes - 2016-11-12 14:58

Labels

index innodb

index innodb need_feedback

Viktor Zeman added a comment - 2016-11-18 13:21

Elena, I don't understand your request with DISCARD TABLESPACE.
I'm not able to run such commands on live environment.

Viktor Zeman added a comment - 2016-11-18 13:21 Elena, I don't understand your request with DISCARD TABLESPACE. I'm not able to run such commands on live environment.

Elena Stepanova made changes - 2016-11-18 15:26

Labels

index innodb need_feedback

index innodb

Marko Mäkelä made changes - 2016-12-02 12:00

Assignee

Marko Mäkelä [ marko ]

Marko Mäkelä added a comment - 2016-12-02 12:07

Someone on irc repeated the same problem. I suggested the following:

Use mysqldump or equivalent to copy the data.
Load the data to a new server.
The same CREATE FULLTEXT INDEX statement should still crash. (I am pretty sure about this; the input to the sort should be ordered by the clustered index (PRIMARY KEY).)
ALTER TABLE…DROP COLUMN to drop any irrelevant columns. We should only need the PRIMARY KEY columns and the column(s) that the fulltext index is being created on, and a possible FTS_DOC_ID column (if one has been created by the user).
The CREATE FULLTEXT INDEX should still crash.
DELETE half of the rows, and hope that the CREATE FULLTEXT INDEX still crashes. If not, restore the rows, delete rows by some other condition.
Repeat the last step until the data set is small enough.
Then (if needed) replace any confidential data while making sure that the CREATE FULLTEXT INDEX still crashes.
Send the mysqldump of the reduced table, and the CREATE FULLTEXT INDEX statement.
I am looking forward to get some data obtained by this method.

Marko Mäkelä added a comment - 2016-12-02 12:07 Someone on irc repeated the same problem. I suggested the following: Use mysqldump or equivalent to copy the data. Load the data to a new server. The same CREATE FULLTEXT INDEX statement should still crash. (I am pretty sure about this; the input to the sort should be ordered by the clustered index (PRIMARY KEY).) ALTER TABLE…DROP COLUMN to drop any irrelevant columns. We should only need the PRIMARY KEY columns and the column(s) that the fulltext index is being created on, and a possible FTS_DOC_ID column (if one has been created by the user). The CREATE FULLTEXT INDEX should still crash. DELETE half of the rows, and hope that the CREATE FULLTEXT INDEX still crashes. If not, restore the rows, delete rows by some other condition. Repeat the last step until the data set is small enough. Then (if needed) replace any confidential data while making sure that the CREATE FULLTEXT INDEX still crashes. Send the mysqldump of the reduced table, and the CREATE FULLTEXT INDEX statement. I am looking forward to get some data obtained by this method.

Waqar Khan added a comment - 2016-12-02 13:21 - edited

After some testing with Marko, we have an update for this and how to replicate:

CREATE TABLE t(t text CHARACTER SET utf8mb4 COLLATE utf8mb4_unicode_ci) ENGINE=InnoDB;

INSERT INTO t VALUES (0xD0B4E0B894E0B987E0B987E0B987E0B987E0B987E0B989E0B989E0B989E0B989E0B989E0B987E0B987E0B987E0B987E0B989E0B989E0B989E0B989E0B989E0B987E0B987E0B987E0B987E0B987E0B989E0B989E0B989E0B989E0B989E0B987E0B987E0B987E0B987E0B987E0B989E0B989E0B989E0B989E0B989E0B987E0B987E0B987E0B987E0B987E0B989E0B989E0B989E0B989E0B989);

CREATE FULLTEXT INDEX ft ON t(t);

DROP TABLE t;

Upon CREATE FULLTEXT INDEX ft ON t(t); the server with crash with the following snippet from the log file:

Dec 2 13:12:34 centos-mdb1 mysqld: 2016-12-02 13:12:34 7f4c2ebff700 InnoDB: Assertion failure in thread 139965178574592 in
file row0merge.cc line 897
Dec 2 13:12:34 centos-mdb1 mysqld: InnoDB: Failing assertion: b == &block[0] + buf->total_size + ROW_MERGE_RESERVE_SIZE

Waqar Khan added a comment - 2016-12-02 13:21 - edited After some testing with Marko, we have an update for this and how to replicate: CREATE TABLE t(t text CHARACTER SET utf8mb4 COLLATE utf8mb4_unicode_ci) ENGINE=InnoDB; INSERT INTO t VALUES (0xD0B4E0B894E0B987E0B987E0B987E0B987E0B987E0B989E0B989E0B989E0B989E0B989E0B987E0B987E0B987E0B987E0B989E0B989E0B989E0B989E0B989E0B987E0B987E0B987E0B987E0B987E0B989E0B989E0B989E0B989E0B989E0B987E0B987E0B987E0B987E0B987E0B989E0B989E0B989E0B989E0B989E0B987E0B987E0B987E0B987E0B987E0B989E0B989E0B989E0B989E0B989); CREATE FULLTEXT INDEX ft ON t(t); DROP TABLE t; Upon CREATE FULLTEXT INDEX ft ON t(t); the server with crash with the following snippet from the log file: Dec 2 13:12:34 centos-mdb1 mysqld: 2016-12-02 13:12:34 7f4c2ebff700 InnoDB: Assertion failure in thread 139965178574592 in file row0merge.cc line 897 Dec 2 13:12:34 centos-mdb1 mysqld: InnoDB: Failing assertion: b == &block [0] + buf->total_size + ROW_MERGE_RESERVE_SIZE

Rasmus Johansson (Inactive) made changes - 2016-12-02 13:31

Fix Version/s

10.1 [ 16100 ]

Rasmus Johansson (Inactive) made changes - 2016-12-02 13:32

Sprint

10.1.20 [ 119 ]

Rasmus Johansson (Inactive) made changes - 2016-12-02 13:32

Rank

Ranked lower

Marko Mäkelä added a comment - 2016-12-02 13:33

Also ~~MDEV-11241~~ is something about 4-byte UTF-8 and fulltext search, but outside InnoDB.

Marko Mäkelä added a comment - 2016-12-02 13:33 Also MDEV-11241 is something about 4-byte UTF-8 and fulltext search, but outside InnoDB.

Marko Mäkelä made changes - 2016-12-02 13:33

Link

This issue relates to ~~MDEV-11241~~ [ ~~MDEV-11241~~ ]

Marko Mäkelä added a comment - 2016-12-05 11:18

This bug is related to the following bug that was fixed in MySQL 5.6.29, 5.7.11 and 8.0.0:
Bug#79475 Insert a token of 84 4-bytes chars into fts index causes server crash
This particular bug fix was not merged to MariaDB. But, a follow-up bug fix was merged, causing this very bug:

commit 052a8b8e324122d99d58f328cc90f3249fc76a3a

Author: Shaohua Wang <shaohua.wang@oracle.com>

Date:   Thu Apr 7 11:37:32 2016 +0800

    BUG#22963169 MYSQL CRASHES ON CREATE FULLTEXT INDEX

If I revert the change of the latter fix to row_merge_fts_doc_tokenize(), the test case will not crash. Note: I was able to crash by using 3-byte UTF-8:

CREATE TABLE t(t text CHARACTER SET utf8) ENGINE=InnoDB;

INSERT INTO t set t=repeat(concat(repeat(0xE0B987, 4), repeat(0xE0B989, 5)), 5);

CREATE FULLTEXT INDEX ft ON t(t);

DROP TABLE t;

It seems that the correct fix is to keep the 84-character token length limit even when using utf8mb4. This would increase the storage size in bytes to 336. The MariaDB bug fix has the option to keep using 84*3 = 254 bytes as the maximum word size for those indexes that use encodings with less than 4 bytes per character. This would save 1 byte for fulltext index entries that where the length of an indexed word is between 128 and 254 bytes (43 to 84 three-byte characters, or 64 to 127 two-byte characters).

Marko Mäkelä added a comment - 2016-12-05 11:18 This bug is related to the following bug that was fixed in MySQL 5.6.29, 5.7.11 and 8.0.0: Bug#79475 Insert a token of 84 4-bytes chars into fts index causes server crash This particular bug fix was not merged to MariaDB. But, a follow-up bug fix was merged, causing this very bug: commit 052a8b8e324122d99d58f328cc90f3249fc76a3a Author: Shaohua Wang <shaohua.wang@oracle.com> Date: Thu Apr 7 11:37:32 2016 +0800 BUG#22963169 MYSQL CRASHES ON CREATE FULLTEXT INDEX If I revert the change of the latter fix to row_merge_fts_doc_tokenize(), the test case will not crash. Note: I was able to crash by using 3-byte UTF-8: CREATE TABLE t(t text CHARACTER SET utf8) ENGINE=InnoDB; INSERT INTO t set t=repeat(concat(repeat(0xE0B987, 4), repeat(0xE0B989, 5)), 5); CREATE FULLTEXT INDEX ft ON t(t); DROP TABLE t; It seems that the correct fix is to keep the 84-character token length limit even when using utf8mb4. This would increase the storage size in bytes to 336. The MariaDB bug fix has the option to keep using 84*3 = 254 bytes as the maximum word size for those indexes that use encodings with less than 4 bytes per character. This would save 1 byte for fulltext index entries that where the length of an indexed word is between 128 and 254 bytes (43 to 84 three-byte characters, or 64 to 127 two-byte characters).

Marko Mäkelä made changes - 2016-12-05 12:01

Summary

ADDING FULLTEXT INDEX crash server

CREATE FULLTEXT INDEX with a token longer than 127 bytes crashes server

Marko Mäkelä made changes - 2016-12-05 13:37

Status

Open [ 1 ]

In Progress [ 3 ]

Marko Mäkelä made changes - 2016-12-05 13:37

Assignee	Marko Mäkelä [ marko ]	Jan Lindström [ jplindst ]
Status	In Progress [ 3 ]	In Review [ 10002 ]

Jan Lindström (Inactive) added a comment - 2016-12-05 14:16

ok to push.

Jan Lindström (Inactive) added a comment - 2016-12-05 14:16 ok to push.

Jan Lindström (Inactive) made changes - 2016-12-05 14:16

Assignee	Jan Lindström [ jplindst ]	Marko Mäkelä [ marko ]
Status	In Review [ 10002 ]	Stalled [ 10000 ]

Marko Mäkelä made changes - 2016-12-05 14:33

issue.field.resolutiondate

2016-12-05 14:33:23.0

2016-12-05 14:33:23.097

Marko Mäkelä made changes - 2016-12-05 14:33

Component/s		Storage Engine - InnoDB [ 10129 ]
Fix Version/s		10.1.20 [ 22112 ]
Fix Version/s		10.2.3 [ 22115 ]
Fix Version/s	10.1 [ 16100 ]
Resolution		Fixed [ 1 ]
Status	Stalled [ 10000 ]	Closed [ 6 ]

Elena Stepanova added a comment - 2016-12-10 17:16

Adding to make it searchable in JIRA
Not long before the fix, we had a buildbot failure on innodb_fts.innodb_fts_misc with somewhat similar appearance:
http://buildbot.askmonty.org/buildbot/builders/kvm-deb-yakkety-x86/builds/175/steps/test_5/logs/stdio

Elena Stepanova added a comment - 2016-12-10 17:16 Adding to make it searchable in JIRA Not long before the fix, we had a buildbot failure on innodb_fts.innodb_fts_misc with somewhat similar appearance: http://buildbot.askmonty.org/buildbot/builders/kvm-deb-yakkety-x86/builds/175/steps/test_5/logs/stdio

Marko Mäkelä added a comment - 2016-12-12 06:38

elenst, that failure looks different, possibly a failure to create a thread:

CURRENT_TEST: innodb_fts.innodb_fts_misc

mysqltest: At line 59: query 'CREATE FULLTEXT INDEX idx on t1 (a,b)' failed: 2013: Lost connection to MySQL server during query

…

2016-11-22  7:08:49 3067240256 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files

161122  7:08:49 [ERROR] mysqld got signal 11 ;

…

Server version: 10.1.20-MariaDB-1~yakkety

…

/usr/sbin/mysqld(my_print_stacktrace+0x28)[0x809282e8]

/usr/sbin/mysqld(handle_fatal_signal+0x367)[0x80453647]

[0xb76fad10]

/lib/i386-linux-gnu/libpthread.so.0(pthread_create+0x435)[0xb7361a25]

/usr/lib/mysql/plugin/ha_innodb.so(+0x158531)[0xb12b2531]

/usr/lib/mysql/plugin/ha_innodb.so(+0x183eea)[0xb12ddeea]

/usr/lib/mysql/plugin/ha_innodb.so(+0x19bcd4)[0xb12f5cd4]

/usr/lib/mysql/plugin/ha_innodb.so(+0x108be0)[0xb1262be0]

/usr/sbin/mysqld(_Z17mysql_alter_tableP3THDPcS1_P14HA_CREATE_INFOP10TABLE_LISTP10Alter_infojP8st_orderb+0x2b46)[0x80348786]

There was no resolved stack trace with line numbers. The only place where ALTER TABLE is creating threads is for preprocessing data for fulltext indexes, the threads fts_parallel_tokenization (created by row_fts_start_psort()) and fts_parallel_merge (created by row_fts_start_parallel_merge()).
Neither of these places is checking whether the thread creation succeeded. It seems that the crash must have occurred while row_fts_start_parallel_merge() was being invoked by row_merge_build_indexes().
The problem appears to be that something inside pthread_create() fails. In InnoDB, pthread_create() is called by os_thread_create_func(), which invokes pthread_attr_init() on one argument without checking the return value of that function. However, according to the Linux man-pages version 4.8, pthread_attr_init() should always succeed on Linux.

The manual page for pthread_create() does not give hints why the pthread_create() might have crashed. Given that the platform is 32-bit (i386), one possibility could be exhaustion of the address space when trying to allocate stack for the thread. Maybe this could be repated by running the same tests on a single instance:

innodb.innodb_prefix_index_restart_server 'innodb_plugin' w1 [ pass ]   8513

innodb.innodb_stats 'innodb_plugin'      w1 [ pass ]    102

innodb.innodb_stats_create_on_corrupted 'innodb_plugin' w1 [ pass ]   2769

innodb.innodb_stats_create_table 'innodb_plugin' w1 [ pass ]     16

innodb.innodb_stats_drop_locked 'innodb_plugin' w1 [ pass ]   2206

innodb.innodb_stats_fetch 'innodb_plugin' w1 [ pass ]     34

innodb.innodb_stats_fetch_corrupted 'innodb_plugin' w1 [ pass ]   2792

innodb.innodb_stats_fetch_nonexistent 'innodb_plugin' w1 [ pass ]     23

innodb.innodb_stats_rename_table 'innodb_plugin' w1 [ pass ]      5

innodb.innodb_stats_rename_table_if_exists 'innodb_plugin' w1 [ pass ]    422

innodb.innodb_trx_weight 'innodb_plugin' w1 [ pass ]    135

innodb.mdev-117 'innodb_plugin'          w1 [ pass ]     17

innodb.row_lock 'innodb_plugin'          w1 [ pass ]    118

innodb.strict_mode 'innodb_plugin'       w1 [ pass ]     34

innodb.system_tables 'innodb_plugin'     w1 [ pass ]   2744

innodb.tmpdir 'innodb_plugin'            w1 [ pass ]    147

innodb.xa_recovery 'innodb_plugin'       w1 [ pass ]   5283

innodb_fts.fulltext 'innodb_plugin'      w1 [ pass ]   1162

innodb_fts.fulltext2 'innodb_plugin'     w1 [ pass ]   1120

innodb_fts.fulltext3 'innodb_plugin'     w1 [ pass ]     41

innodb_fts.fulltext_cache 'innodb_plugin' w1 [ pass ]     40

innodb_fts.fulltext_distinct 'innodb_plugin' w1 [ pass ]     57

innodb_fts.fulltext_left_join 'innodb_plugin' w1 [ pass ]    168

innodb_fts.fulltext_misc 'innodb_plugin' w1 [ pass ]    255

innodb_fts.fulltext_multi 'innodb_plugin' w1 [ pass ]     68

innodb_fts.fulltext_order_by 'innodb_plugin' w1 [ pass ]    182

innodb_fts.fulltext_update 'innodb_plugin' w1 [ pass ]     37

innodb_fts.fulltext_var 'innodb_plugin'  w1 [ pass ]     20

innodb_fts.innodb-fts-basic 'innodb_plugin' w1 [ pass ]     36

main.information_schema 'xtradb'         w4 [ pass ]   3770

main.progress_976225 'xtradb'            w4 [ pass ]     53

main.rowid_order_innodb 'xtradb'         w4 [ pass ]     46

innodb_fts.innodb-fts-ddl 'innodb_plugin' w1 [ pass ]   1020

innodb_fts.innodb-fts-fic 'innodb_plugin' w1 [ pass ]    545

innodb_fts.innodb_fts_large_records 'innodb_plugin' w1 [ pass ]   1056

innodb_fts.innodb_fts_misc 'innodb_plugin' w1 [ fail ]

Marko Mäkelä added a comment - 2016-12-12 06:38 elenst , that failure looks different, possibly a failure to create a thread: CURRENT_TEST: innodb_fts.innodb_fts_misc mysqltest: At line 59: query 'CREATE FULLTEXT INDEX idx on t1 (a,b)' failed: 2013: Lost connection to MySQL server during query … 2016-11-22 7:08:49 3067240256 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files 161122 7:08:49 [ERROR] mysqld got signal 11 ; … Server version: 10.1.20-MariaDB-1~yakkety … /usr/sbin/mysqld(my_print_stacktrace+0x28)[0x809282e8] /usr/sbin/mysqld(handle_fatal_signal+0x367)[0x80453647] [0xb76fad10] /lib/i386-linux-gnu/libpthread.so.0(pthread_create+0x435)[0xb7361a25] /usr/lib/mysql/plugin/ha_innodb.so(+0x158531)[0xb12b2531] /usr/lib/mysql/plugin/ha_innodb.so(+0x183eea)[0xb12ddeea] /usr/lib/mysql/plugin/ha_innodb.so(+0x19bcd4)[0xb12f5cd4] /usr/lib/mysql/plugin/ha_innodb.so(+0x108be0)[0xb1262be0] /usr/sbin/mysqld(_Z17mysql_alter_tableP3THDPcS1_P14HA_CREATE_INFOP10TABLE_LISTP10Alter_infojP8st_orderb+0x2b46)[0x80348786] There was no resolved stack trace with line numbers. The only place where ALTER TABLE is creating threads is for preprocessing data for fulltext indexes, the threads fts_parallel_tokenization (created by row_fts_start_psort()) and fts_parallel_merge (created by row_fts_start_parallel_merge()). Neither of these places is checking whether the thread creation succeeded. It seems that the crash must have occurred while row_fts_start_parallel_merge() was being invoked by row_merge_build_indexes(). The problem appears to be that something inside pthread_create() fails. In InnoDB, pthread_create() is called by os_thread_create_func(), which invokes pthread_attr_init() on one argument without checking the return value of that function. However, according to the Linux man-pages version 4.8, pthread_attr_init() should always succeed on Linux. The manual page for pthread_create() does not give hints why the pthread_create() might have crashed. Given that the platform is 32-bit (i386), one possibility could be exhaustion of the address space when trying to allocate stack for the thread. Maybe this could be repated by running the same tests on a single instance: innodb.innodb_prefix_index_restart_server 'innodb_plugin' w1 [ pass ] 8513 innodb.innodb_stats 'innodb_plugin' w1 [ pass ] 102 innodb.innodb_stats_create_on_corrupted 'innodb_plugin' w1 [ pass ] 2769 innodb.innodb_stats_create_table 'innodb_plugin' w1 [ pass ] 16 innodb.innodb_stats_drop_locked 'innodb_plugin' w1 [ pass ] 2206 innodb.innodb_stats_fetch 'innodb_plugin' w1 [ pass ] 34 innodb.innodb_stats_fetch_corrupted 'innodb_plugin' w1 [ pass ] 2792 innodb.innodb_stats_fetch_nonexistent 'innodb_plugin' w1 [ pass ] 23 innodb.innodb_stats_rename_table 'innodb_plugin' w1 [ pass ] 5 innodb.innodb_stats_rename_table_if_exists 'innodb_plugin' w1 [ pass ] 422 innodb.innodb_trx_weight 'innodb_plugin' w1 [ pass ] 135 innodb.mdev-117 'innodb_plugin' w1 [ pass ] 17 innodb.row_lock 'innodb_plugin' w1 [ pass ] 118 innodb.strict_mode 'innodb_plugin' w1 [ pass ] 34 innodb.system_tables 'innodb_plugin' w1 [ pass ] 2744 innodb.tmpdir 'innodb_plugin' w1 [ pass ] 147 innodb.xa_recovery 'innodb_plugin' w1 [ pass ] 5283 innodb_fts.fulltext 'innodb_plugin' w1 [ pass ] 1162 innodb_fts.fulltext2 'innodb_plugin' w1 [ pass ] 1120 innodb_fts.fulltext3 'innodb_plugin' w1 [ pass ] 41 innodb_fts.fulltext_cache 'innodb_plugin' w1 [ pass ] 40 innodb_fts.fulltext_distinct 'innodb_plugin' w1 [ pass ] 57 innodb_fts.fulltext_left_join 'innodb_plugin' w1 [ pass ] 168 innodb_fts.fulltext_misc 'innodb_plugin' w1 [ pass ] 255 innodb_fts.fulltext_multi 'innodb_plugin' w1 [ pass ] 68 innodb_fts.fulltext_order_by 'innodb_plugin' w1 [ pass ] 182 innodb_fts.fulltext_update 'innodb_plugin' w1 [ pass ] 37 innodb_fts.fulltext_var 'innodb_plugin' w1 [ pass ] 20 innodb_fts.innodb-fts-basic 'innodb_plugin' w1 [ pass ] 36 main.information_schema 'xtradb' w4 [ pass ] 3770 main.progress_976225 'xtradb' w4 [ pass ] 53 main.rowid_order_innodb 'xtradb' w4 [ pass ] 46 innodb_fts.innodb-fts-ddl 'innodb_plugin' w1 [ pass ] 1020 innodb_fts.innodb-fts-fic 'innodb_plugin' w1 [ pass ] 545 innodb_fts.innodb_fts_large_records 'innodb_plugin' w1 [ pass ] 1056 innodb_fts.innodb_fts_misc 'innodb_plugin' w1 [ fail ]

Manuel Arostegui added a comment - 2017-01-26 17:04

Quick note: this seems to affect also 10.0.28 and 10.0.29 but not 10.0.23.

Manuel Arostegui added a comment - 2017-01-26 17:04 Quick note: this seems to affect also 10.0.28 and 10.0.29 but not 10.0.23.

Marko Mäkelä added a comment - 2017-01-27 08:06

Reopening for backporting the fix to 10.0.

Marko Mäkelä added a comment - 2017-01-27 08:06 Reopening for backporting the fix to 10.0.

Marko Mäkelä made changes - 2017-01-27 08:06

Resolution	Fixed [ 1 ]
Status	Closed [ 6 ]	Stalled [ 10000 ]

Marko Mäkelä made changes - 2017-01-27 08:20

Fix Version/s		10.0.30 [ 22313 ]
Resolution		Fixed [ 1 ]
Status	Stalled [ 10000 ]	Closed [ 6 ]

Marko Mäkelä made changes - 2017-01-27 08:26

Link

This issue is duplicated by ~~MDEV-11918~~ [ ~~MDEV-11918~~ ]

Manuel Arostegui added a comment - 2017-01-27 08:29

Hey Marko - thanks.
Check this: https://jira.mariadb.org/browse/MDEV-11918 as there is a PR already requested there.

Manuel Arostegui added a comment - 2017-01-27 08:29 Hey Marko - thanks. Check this: https://jira.mariadb.org/browse/MDEV-11918 as there is a PR already requested there.

Sergei Golubchik made changes - 2021-12-06 21:43

Workflow

MariaDB v3 [ 78206 ]

MariaDB v4 [ 151186 ]

People

Assignee:: Marko Mäkelä

Reporter:: Viktor Zeman

Votes:: 0 Vote for this issue

Watchers:: 8 Start watching this issue

Dates

Created:: 2016-11-04 08:16

Updated:: 2017-01-27 08:29

Resolved:: 2017-01-27 08:20

Git Integration

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

MariaDB Server

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration