[MDEV-11063] Crash on creating large FULLTEXT index Created: 2016-10-14  Updated: 2023-05-12  Resolved: 2023-05-12

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.1.18
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Niels Assignee: Marko Mäkelä
Resolution: Incomplete Votes: 0
Labels: None
Environment:

Ubuntu 16.0.4


 Description    

161014 13:56:15 [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-1~xenial
 
key_buffer_size=402653184
 
read_buffer_size=2097152
 
max_used_connections=1
 
max_threads=153
 
thread_count=1
 
It is possible that mysqld could use up to
 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1021898 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0x6ffce008
 
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 = 0xb4f045fc thread_stack 0x48400
 
(my_addr_resolve failure: fork)
 
/usr/sbin/mysqld(my_print_stacktrace+0x28) [0xb69fbe28]
 
/usr/sbin/mysqld(handle_fatal_signal+0x2c7) [0xb652d777]
 
[0xb6eb8404]
 
[0xb6eb8428]
 
/lib/i386-linux-gnu/libc.so.6(gsignal+0x39) [0xb597ce89]
 
/lib/i386-linux-gnu/libc.so.6(abort+0x157) [0xb597e3e7]
 
/usr/sbin/mysqld(+0x57c5a7) [0xb66975a7]
 
/usr/sbin/mysqld(+0x5d16fd) [0xb66ec6fd]
 
/usr/sbin/mysqld(+0x6194ef) [0xb67344ef]
 
/usr/sbin/mysqld(+0x61ad8f) [0xb6735d8f]
 
/usr/sbin/mysqld(+0x6202df) [0xb673b2df]
 
/usr/sbin/mysqld(+0x58547d) [0xb66a047d]
 
/usr/sbin/mysqld(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool)+0x2ef7) [0xb6422a57]
 
/usr/sbin/mysqld(mysql_execute_command(THD*)+0x7ce7) [0xb6393037]
 
/usr/sbin/mysqld(mysql_parse(THD*, char*, unsigned int, Parser_state*)+0x320) [0xb6396160]
 
/usr/sbin/mysqld(dispatch_command(enum_server_command, THD*, char*, unsigned int)+0x2ce8) [0xb6399f58]
 
/usr/sbin/mysqld(do_command(THD*)+0x1b4) [0xb639a7d4]
 
/usr/sbin/mysqld(do_handle_one_connection(THD*)+0x1ec) [0xb6468c4c]
 
/usr/sbin/mysqld(handle_one_connection+0x40) [0xb6468e00]
 
/lib/i386-linux-gnu/libpthread.so.0(+0x62b5) [0xb5d682b5]
 
/lib/i386-linux-gnu/libc.so.6(clone+0x6e) [0xb5a3816e]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x67819018): is an invalid pointer
 
Connection ID (thread ID): 2
 
Status: NOT_KILLED
 
 
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=o$
 
 
 
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.
 
 
 
We think the query pointer is invalid, but we will try to print it anyway.
 
Query: CREATE FULLTEXT INDEX `fullemail` ON `contacts` (`email`)
 
 
 
161014 13:56:16 mysqld_safe Number of processes running now: 0
 
161014 13:56:16 mysqld_safe mysqld restarted
 
2016-10-14 13:56:16 3044911104 [Note] /usr/sbin/mysqld (mysqld 10.1.18-MariaDB-1~xenial) starting as process 8594 ...
 
2016-10-14 13:56:17 b57da800 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory alloc$
 
2016-10-14 13:56:17 3044911104 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
2016-10-14 13:56:17 3044911104 [Note] InnoDB: The InnoDB memory heap is disabled
 
2016-10-14 13:56:17 3044911104 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2016-10-14 13:56:17 3044911104 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
 
2016-10-14 13:56:17 3044911104 [Note] InnoDB: Compressed tables use zlib 1.2.8
 
2016-10-14 13:56:17 3044911104 [Note] InnoDB: Using Linux native AIO
 
2016-10-14 13:56:18 3044911104 [Note] InnoDB: Using generic crc32 instructions
 
2016-10-14 13:56:18 3044911104 [Note] InnoDB: Initializing buffer pool, size = 384.0M
 
2016-10-14 13:56:18 3044911104 [Note] InnoDB: Completed initialization of buffer pool
 
2016-10-14 13:56:18 3044911104 [Note] InnoDB: Highest supported file format is Barracuda.
 
2016-10-14 13:56:18 3044911104 [Note] InnoDB: The log sequence numbers 385048524300 and 385048524300 in ibdata files do not match the log sequence number 385408285912 in the ib_logfiles!
 
2016-10-14 13:56:18 3044911104 [Note] InnoDB: Database was not shutdown normally!
 
2016-10-14 13:56:18 3044911104 [Note] InnoDB: Starting crash recovery.
 
2016-10-14 13:56:18 3044911104 [Note] InnoDB: Reading tablespace information from the .ibd files...
 
2016-10-14 13:56:21 3044911104 [Note] InnoDB: Restoring possible half-written data pages
 
2016-10-14 13:56:21 3044911104 [Note] InnoDB: from the doublewrite buffer...
 
InnoDB: Last MySQL binlog file position 0 1215194, file name /var/log/mysql/mariadb-bin.000024
 
2016-10-14 13:56:22 3044911104 [Note] InnoDB: 128 rollback segment(s) are active.
 
2016-10-14 13:56:22 3044911104 [Note] InnoDB: Waiting for purge to start
 
2016-10-14 13:56:22 3044911104 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.32-78.1 started; log sequence number 385408285912
 
2016-10-14 13:56:22 1799355200 [Note] InnoDB: Dumping buffer pool(s) not yet started
 
2016-10-14 13:56:22 3044911104 [Note] Plugin 'FEEDBACK' is disabled.
 
2016-10-14 13:56:22 3044911104 [Note] Recovering after a crash using tc.log
 
2016-10-14 13:56:22 3044911104 [Note] Starting crash recovery...
 
2016-10-14 13:56:22 3044911104 [Note] Crash recovery finished.
 
2016-10-14 13:56:22 3044911104 [Note] Server socket created on IP: '::'.
 
2016-10-14 13:56:23 3044911104 [Note] /usr/sbin/mysqld: ready for connections.
 
Version: '10.1.18-MariaDB-1~xenial'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution

Size of table is about 150M entries.

 Comments   
Comment by Elena Stepanova [ 2016-10-14 ]

niels1189,

Could you please paste or attach

  • a part of the error log preceding the 'signal 6' line;
  • the output of 

    SHOW CREATE TABLE fullemail;
    		 
    SHOW INDEX IN fullemail;
    		 
    SHOW TABLE STATUS LIKE 'fullemail';

  • your cnf file(s).

If it's a development server with test data which you can share with us, even better – please upload it to ftp.askmonty.org/private.

Comment by Niels [ 2016-10-14 ] 

2016-10-14 13:34:28 1581243200 [Note] InnoDB: Online DDL : merge-sorting has estimated 2 runs
 
2016-10-14 13:34:28 3035647808 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2016-10-14 13:34:28 3035647808 [Note] InnoDB: Online DDL : Start merge-sorting index `GEN_CLUST_INDEX` (1 / 3), estimated cost : 5.0000
 
2016-10-14 13:34:28 3035647808 [Note] InnoDB: Online DDL : merge-sorting has estimated 42 runs
 
2016-10-14 13:34:30 3035647808 [Note] InnoDB: Online DDL : End of  merge-sorting index `GEN_CLUST_INDEX` (1 / 3)
 
2016-10-14 13:34:30 3035647808 [Note] InnoDB: Online DDL : Start building index `GEN_CLUST_INDEX` (1 / 3), estimated cost : 7.5000
 
2016-10-14 13:34:32 3035647808 [Note] InnoDB: Online DDL : End of building index `GEN_CLUST_INDEX` (1 / 3)
 
2016-10-14 13:34:32 3035647808 [Note] InnoDB: Online DDL : Completed
 
2016-10-14 13:34:35 3035647808 [Note] InnoDB: Online DDL : Completed
 
2016-10-14 13:34:35 3035647808 [Note] InnoDB: Online DDL : Start merge-sorting index `FTS_DOC_ID_INDEX` (3 / 3), estimated cost : 5.0000
 
2016-10-14 13:34:35 3035647808 [Note] InnoDB: Online DDL : merge-sorting has estimated 7 runs
 
2016-10-14 13:34:35 3035647808 [Note] InnoDB: Online DDL : End of  merge-sorting index `FTS_DOC_ID_INDEX` (3 / 3)
 
2016-10-14 13:34:35 3035647808 [Note] InnoDB: Online DDL : Start building index `FTS_DOC_ID_INDEX` (3 / 3), estimated cost : 7.5000
 
2016-10-14 13:34:36 3035647808 [Note] InnoDB: Online DDL : End of building index `FTS_DOC_ID_INDEX` (3 / 3)
 
2016-10-14 13:34:36 3035647808 [Note] InnoDB: Online DDL : Completed
 
2016-10-14 13:34:36 3035647808 [Note] InnoDB: Online DDL : Start
 
2016-10-14 13:34:36 3035647808 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2016-10-14 13:56:15 3035647808 [ERROR] InnoDB:  InnoDB: Unable to allocate memory of size 8056.
 
 
 
2016-10-14 13:56:15 b4f04f40  InnoDB: Assertion failure in thread 3035647808 in file ha_innodb.cc line 21956
 
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.

I think this is what you wanted.

SHOW CREATE TABLE fullemail;
 
SHOW INDEX IN fullemail;
 
SHOW TABLE STATUS LIKE 'fullemail';

I think you meant 'contacts' instead of 'fullemail'

| contacts | CREATE TABLE `contacts` (
 
  `email` varchar(128) DEFAULT NULL,
 
  `firstname` varchar(64) DEFAULT NULL,
 
  `lastname` varchar(64) DEFAULT NULL,
 
  `phone` varchar(64) DEFAULT NULL,
 
) ENGINE=InnoDB DEFAULT CHARSET=utf8 |


+--------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
 
| Table        | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment |
 
+--------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
 
| contacts|          0 | PRIMARY  |            1 | firstname      | A         |          71 |     NULL | NULL   |      | BTREE      |         |               |
 
| contacts|          0 | PRIMARY  |            2 | phone        | A         |          71 |     NULL | NULL   |      | BTREE      |         |               |
 
+--------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
 
2 rows in set (0.00 sec)


+-------+--------+---------+------------+-----------+----------------+-------------+-----------------+--------------+-----------+----------------+---------------------+-------------+------------+-----------------+----------+----------------+---------+
 
| Name  | Engine | Version | Row_format | Rows      | Avg_row_length | Data_length | Max_data_length | Index_length | Data_free | Auto_increment | Create_time         | Update_time | Check_time | Collation       | Checksum | Create_options | Comment |
 
+-------+--------+---------+------------+-----------+----------------+-------------+-----------------+--------------+-----------+----------------+---------------------+-------------+------------+-----------------+----------+----------------+---------+
 
| contacts | InnoDB |      10 | Compact    | 116048215 |            131 | 15209594880 |               0 |            0 |   7340032 |           NULL | 2016-10-13 15:28:54 | NULL        | NULL       | utf8_general_ci |     NULL |                |         |
 
+-------+--------+---------+------------+-----------+----------------+-------------+-----------------+--------------+-----------+----------------+---------------------+-------------+------------+-----------------+----------+----------------+---------+

Cnf file:

# MariaDB database server configuration file.
 
#
 
# You can copy this file to one of:
 
# - "/etc/mysql/my.cnf" to set global options,
 
# - "~/.my.cnf" to set user-specific options.
 
#
 
# One can use all long options that the program supports.
 
# Run program with --help to get a list of available options and with
 
# --print-defaults to see which it would actually understand and use.
 
#
 
# For explanations see
 
# http://dev.mysql.com/doc/mysql/en/server-system-variables.html
 
 
 
# This will be passed to all mysql clients
 
# It has been reported that passwords should be enclosed with ticks/quotes
 
# escpecially if they contain "#" chars...
 
# Remember to edit /etc/mysql/debian.cnf when changing the socket location.
 
[client]
 
port            = 3306
 
socket          = /var/run/mysqld/mysqld.sock
 
 
 
# Here is entries for some specific programs
 
# The following values assume you have at least 32M ram
 
 
 
# This was formally known as [safe_mysqld]. Both versions are currently parsed.
 
[mysqld_safe]
 
socket          = /var/run/mysqld/mysqld.sock
 
nice            = 0
 
 
 
#MyISAM specifications
 
 
 
[mysqld]
 
port            = 3306
 
socket          = /tmp/mysql.sock
 
skip-external-locking
 
key_buffer_size = 384M
 
max_allowed_packet = 1M
 
table_open_cache = 512
 
sort_buffer_size = 2M
 
read_buffer_size = 2M
 
read_rnd_buffer_size = 8M
 
myisam_sort_buffer_size = 64M
 
thread_cache_size = 8
 
query_cache_size = 32M
 
 
 
#InnoDB specifications
 
 
 
innodb_buffer_pool_size = 384M
 
innodb_additional_mem_pool_size = 20M
 
innodb_log_file_size = 100M
 
innodb_log_buffer_size = 8M
 
innodb_flush_log_at_trx_commit = 1
 
innodb_lock_wait_timeout = 3600
 
 
 
#
 
# * Galera-related settings
 
#
 
[galera]
 
# Mandatory settings
 
#wsrep_on=ON
 
#wsrep_provider=
 
#wsrep_cluster_address=
 
#binlog_format=row
 
#default_storage_engine=InnoDB
 
#innodb_autoinc_lock_mode=2
 
#
 
# Allow server to accept connections on all interfaces.
 
#
 
#bind-address=0.0.0.0
 
#
 
# Optional setting
 
#wsrep_slave_threads=1
 
#innodb_flush_log_at_trx_commit=0
 
 
 
[mysqldump]
 
quick
 
quote-names
 
max_allowed_packet      = 16M
 
 
 
[mysql]
 
#no-auto-rehash # faster start of mysql but no tab completion
 
 
 
[isamchk]
 
key_buffer              = 16M
 
 
 
#
 
# * IMPORTANT: Additional settings that can override those from this file!
 
#   The files must end with '.cnf', otherwise they'll be ignored.
 
#
 
!includedir /etc/mysql/conf.d/


# MariaDB-specific config file.
 
# Read by /etc/mysql/my.cnf
 
 
 
[client]
 
# Default is Latin1, if you need UTF-8 set this (also in server section)
 
#default-character-set = utf8
 
 
 
[mysqld]
 
#
 
# * Character sets
 
#
 
# Default is Latin1, if you need UTF-8 set all this (also in client section)
 
#
 
#character-set-server  = utf8
 
#collation-server      = utf8_general_ci
 
#character_set_server   = utf8
 
#collation_server       = utf8_general_ci


[mysqld_safe]
 
#skip_log_error
 
syslog
 
general_log_file        = /var/log/mysql/mysql.log
 
general_log             = 1
 
log_error=/var/log/mysql/mysql_error.log

Comment by Elena Stepanova [ 2016-10-16 ]

I think you meant 'contacts' instead of 'fullemail'

Yes, sorry, contacts of course.

Thanks for the data.

InnoDB: Unable to allocate memory of size 8056

Is it possible that you actually ran out of memory?
How much memory do you have on the machine, how much is normally free, and how big is contacts.ibd file? (the file itself, on the disk; I know that you mentioned already that the table has 150M rows)

Comment by Niels [ 2016-10-16 ]

There is currently 4GB RAM available on the server right now.
Passively (no scripts or commands running) it's currently consuming 700MB of RAM.

There is an apache server running on the server as well.
Current contacts.ibd is 16,012MB (16GB) large

How much RAM would I need to process 25GB size database since this will with no doubt increase in the future.

Comment by Niels [ 2016-10-18 ]

Still waiting for a response. The memory didn't seem to run out when I ran it. It reached 2.1GB of RAM usage before it crashed (using dstat)

Comment by Elena Stepanova [ 2016-10-18 ]

Sorry, we have a bit of backlog at the moment. We'll look into it shortly.

Comment by Elena Stepanova [ 2016-10-19 ]

Something does not add up in this data. niels1189, are you sure all of this is about the same table?
First, SHOW CREATE does not have any indexes (although there are signs they used to be there), while SHOW INDEX shows the primary key.
Secondly, you said that the table had 150M rows, table status also shows over 100M rows, but SHOW INDEX only shows 71?

Comment by Niels [ 2016-10-19 ]

I manually adjusted the show index copying it from another table since we removed the indexes from the original table hoping that would fix it some way.
We've not added them back so there are currently no indexes on the contacts table.
SHOW CREATE doesn't show indexes because the indexes were added after the creation of the table and the insertion of the data.

Comment by Elena Stepanova [ 2016-10-19 ]

There is no need to paste info from a different table, if a crash does not happen on it too, it just confuses the matters.

It's a bit obscure what happened when, lets try to clear it up.

You had the crash upon CREATE FULLTEXT INDEX `fullemail` ON `contacts` (`email`), that much we know.
You also said that the table had 150M rows at the time, lets go with that.
Which indexes did the table have then?
Is the crash repeatable? Did it happen more than once before you removed indexes?
Did it happen again after you removed indexes?

Comment by Niels [ 2016-10-19 ]

the same crash kept happening when the table had indexes, the crash repeated even after removing the indexes

Comment by Niels [ 2016-10-21 ]

I really want to know if the RAM is the issue or something else as soon as possible so I can continue on working.

Comment by Elena Stepanova [ 2016-10-21 ]

Just last night I ran a test with 100 mln rows table (ibd file 9.5G), without indexes, and the highest memory consumption grew while running the same CREATE FULLTEXT INDEX was 3.8G. So, I suppose with 150 mln rows it could have been bigger than 4G, but then it should have just swapped, right? Is there any sign of that?

Comment by Niels [ 2016-10-21 ]

I have no idea how I'd check that.
I think a lack of RAM could be the issue then.

Comment by Elena Stepanova [ 2016-10-21 ]

Either way, I"m not entirely convinced that it should be allowed to use this much memory. I'll pass it over to the InnoDB expert jplindst to say for sure.

Comment by Niels [ 2016-10-21 ]

Alright, then I'll be waiting on his view on this issue.

Comment by Jan Lindström (Inactive) [ 2016-10-24 ]

Hi, this really looks like out-of-memory situation. Based on this information it is hard to say if InnoDB could do something more intelligent than just asserting, I would need full stack dump for that. If alter table is progressed too far we can't roll-back it anymore easily i.e. it will then do it on crash recovery.

Comment by Elena Stepanova [ 2016-10-24 ]

jplindst, my main doubt was (and still is) not even about what happens when OOM occurs, but about why OOM occurs here to begin with. Is it normal that so much is happening in memory, rather than in temporary files on disk?

Comment by Jan Lindström (Inactive) [ 2016-10-24 ]

elenst Sorry, I do not know this fulltext code so well that I could really be sure it would not use as much memory as needed, and in this case we do not know how much memory is used on other stuff.

Comment by Niels [ 2016-11-10 ]

Alright, the RAM seems to have been the issue.
I'm coming back here because I found a few issue with FULLTEXT indexes.

PHP Fatal error: Uncaught PDOException: SQLSTATE[HY000]: General error: 128 Table handler out of memory in /home/root/datasearch.php:298 Stack trace:
It seems that the "tabler handler" has run out of memory. But I can't find how to increase this in the settings from MySQL/MariaDB or if this is even something you can adjust.
The query is a simple MATCH AGAINST but is expected to return a few million results. We want this for statistics analysis so it's wanted to get that many results back.
Let me know if you can look into it or if I need to create a new ticket for it.

Comment by Marko Mäkelä [ 2016-12-01 ]

My understanding is that the InnoDB fulltext search would allocate RAM for the query results and return it to the optimizer. Maybe it would allocate memory to return the whole result set at once?

That said, the original issue is a crash in CREATE FULLTEXT INDEX. Fulltext indexes inside InnoDB are implemented as a set of hidden InnoDB tables. There could be a bug in the memory management of the InnoDB internal SQL parser or in the code that creates fulltext indexes.

Can we repeat this with a smaller dataset, configuring a very small innodb_buffer_pool_size and restricting the memory usage of mysqld with ulimit? I would appreciate a self-contained test case. Preferrably it should be so small that Valgrind can handle it within reasonable time.

It is also possible that there is no memory leak or no excessive amount of actual heap memory usage, but the problem is that the memory heap gets fragmented. In that case, using another memory allocator library (such as jemalloc or tcmalloc) might help.

Comment by Marko Mäkelä [ 2023-04-11 ]

niels1189, this bug was just reassigned to me, after all these years. Do you still happen to be able to reproduce it?

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