[#MDEV-13394] pthread_create() failure causes os_thread_create() crash in CREATE FULLTEXT INDEX

Comment by Andras [ 2017-08-12 ]

any news on this? the crash repeated 1-2 times, today I noticed there was an update via yum

Comment by Elena Stepanova [ 2017-08-12 ]

From the attached log:

2017-07-27 12:33:02 5bbfbb70 InnoDB: FTS Optimize Removing table bocp_919_swisoimpexs/#sql2-6ceb-37e08f

2017-07-27 12:33:09 6c0c6f70  InnoDB: Assertion failure in thread 1812754288 in file os0thread.cc line 195

InnoDB: Failing assertion: ret == 0

InnoDB: We intentionally generate a memory trap.

InnoDB: Submit a detailed bug report to http://bugs.mysql.com.

InnoDB: If you get repeated assertion failures or crashes, even

InnoDB: immediately after the mysqld startup, there may be

InnoDB: corruption in the InnoDB tablespace. Please refer to

InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html

InnoDB: about forcing recovery.

170727 12:33:09 [ERROR] mysqld got signal 6 ;

This could be because you hit a bug. It is also possible that this binary

or one of the libraries it was linked against is corrupt, improperly built,

or misconfigured. This error can also be caused by malfunctioning hardware.

To report this bug, see 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.25-MariaDB

key_buffer_size=268435456

read_buffer_size=2097152

max_used_connections=172

max_threads=202

thread_count=23

It is possible that mysqld could use up to

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1092177 K  bytes of memory

Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x625bc008

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 = 0x6c0c669c thread_stack 0x48400

/usr/sbin/mysqld(my_print_stacktrace+0x2d)[0x886530d]

/usr/sbin/mysqld(handle_fatal_signal+0x4e8)[0x83a68d8]

[0xb7718500]

/lib/libc.so.6(abort+0x17a)[0xb71b905a]

/usr/sbin/mysqld[0x859b90c]

/usr/sbin/mysqld[0x85bd103]

/usr/sbin/mysqld[0x85da155]

/usr/sbin/mysqld[0x854671e]

/usr/sbin/mysqld[0x8287394]

/usr/sbin/mysqld(_Z17mysql_alter_tableP3THDPcS1_P14HA_CREATE_INFOP10TABLE_LISTP10Alter_infojP8st_orderb+0x4064)[0x828b6f4]

/usr/sbin/mysqld(_ZN19Sql_cmd_alter_table7executeEP3THD+0x5d3)[0x82dc883]

/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x14ba)[0x81f7e9a]

/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x28a)[0x81ffdda]

/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x23d9)[0x8202f09]

/usr/sbin/mysqld(_Z10do_commandP3THD+0x16e)[0x820345e]

/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x2e0)[0x82d8af0]

/usr/sbin/mysqld(handle_one_connection+0x3c)[0x82d8bcc]

/lib/libpthread.so.0(+0x6bc9)[0xb76fbbc9]

/lib/libc.so.6(clone+0x5e)[0xb727004e]

Trying to get some variables.

Some pointers may be invalid and cause the dump to abort.

Query (0x37f9018): is an invalid pointer

Connection ID (thread ID): 3661967

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=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=off

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: ALTER TABLE product_variants_919 DROP INDEX `variant_title` , ADD FULLTEXT `variant_title` (`variant_title`) COMMENT ''

Comment by Elena Stepanova [ 2017-08-12 ]

Do you happen to know whether other occurrences also happened on ALTER TABLE product_variants_919 .. ?
Could you please paste the output of

SHOW CREATE TABLE product_variants_919;

SHOW INDEX IN product_variants_919;

and attach your cnf file(s)?
Were there other errors or warnings in the error log prior to the crash?

Comment by Alice Sherepa [ 2017-09-08 ]

Hi Andras,
it looks like the problem is that thread can not be created (lack of resources or smth), pthread_create returned error
https://github.com/MariaDB/server/blob/10.1/storage/xtradb/os/os0thread.cc#L195

#ifdef UNIV_HPUX10

	ret = pthread_create(&pthread, pthread_attr_default, func, arg);

#else

	ret = pthread_create(&pthread, &attr, func, arg);

#endif

ut_a(ret == 0);

are all crashes that you get the same? please attach full error log

Comment by Andras [ 2017-09-08 ]

hello

I checked the logs and indeed there seems to be a memory problem, although there is 6.5GiB RAM

2017-09-08  7:01:23 1069543280 [ERROR] InnoDB:  InnoDB: Unable to allocate memory of size 2899208.

2017-09-08 07:01:23 3fbfef70  InnoDB: Assertion failure in thread 1069543280 in file ha_innodb.cc line 21960

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.

170908 07:01:23 mysqld_safe Number of processes running now: 0

170908 07:01:23 mysqld_safe mysqld restarted

2017-09-08  7:01:23 3069872544 [Warning] You need to use --log-bin to make --binlog-format work.

2017-09-08  7:01:23 3069872544 [Warning] 'THREAD_CONCURRENCY' is deprecated and will be removed in a future release.

2017-09-08  7:01:23 3069872544 [Note] /usr/sbin/mysqld (mysqld 10.1.26-MariaDB) starting as process 29760 ...

2017-09-08  7:01:24 3069872544 [Note] InnoDB: Using mutexes to ref count buffer pool pages

2017-09-08  7:01:24 3069872544 [Note] InnoDB: The InnoDB memory heap is disabled

2017-09-08  7:01:24 3069872544 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

2017-09-08  7:01:24 3069872544 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier

2017-09-08  7:01:24 3069872544 [Note] InnoDB: Compressed tables use zlib 1.2.3

2017-09-08  7:01:24 3069872544 [Note] InnoDB: Using Linux native AIO

2017-09-08  7:01:24 3069872544 [Note] InnoDB: Using generic crc32 instructions

2017-09-08  7:01:24 3069872544 [Note] InnoDB: Initializing buffer pool, size = 384.0M

2017-09-08  7:01:24 3069872544 [Note] InnoDB: Completed initialization of buffer pool

2017-09-08  7:01:24 3069872544 [Note] InnoDB: Highest supported file format is Barracuda.

2017-09-08  7:01:24 3069872544 [Note] InnoDB: Starting crash recovery from checkpoint LSN=12410212293040

2017-09-08  7:01:40 3069872544 [Note] InnoDB: Processed 56408 .ibd/.isl files

2017-09-08  7:01:42 3069872544 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...

2017-09-08  7:01:42 3069872544 [Note] InnoDB: Read redo log up to LSN=12410212295168

2017-09-08  7:01:42 3069872544 [Note] InnoDB: Starting final batch to recover 12 pages from redo log

InnoDB: Last MySQL binlog file position 0 841564108, file name ./mysql-bin.011327

2017-09-08  7:01:57 3069872544 [Note] InnoDB: 128 rollback segment(s) are active.

2017-09-08  7:01:57 3069872544 [Note] InnoDB: Waiting for purge to start

2017-09-08  7:01:57 3069872544 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log sequence number 12410212295148

2017-09-08  7:01:58 1405090672 [Note] InnoDB: Dumping buffer pool(s) not yet started

2017-09-08  7:01:58 3069872544 [Note] Plugin 'FEEDBACK' is disabled.

2017-09-08  7:01:58 3069872544 [Note] Recovering after a crash using tc.log

2017-09-08  7:01:58 3069872544 [Note] Starting crash recovery...

2017-09-08  7:01:58 3069872544 [Note] Crash recovery finished.

2017-09-08  7:01:58 3069872544 [Note] Server socket created on IP: '::'.

2017-09-08  7:01:58 3069872544 [Note] /usr/sbin/mysqld: ready for connections.

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

currently there is 5GiB ram free, so not sure why the OOM
I will watch the server more, but if you check the above my.cnf, the settings were not aggressive,
I will monitor this

Comment by Andras [ 2017-09-08 ]

I installed sys-snap.pl to find out more if there is another crash

Comment by Andras [ 2017-09-09 ]

The crash orrured 3 times tonight

Here is the log from the last

2017-09-09 06:19:23 16bfbb70 InnoDB: FTS Optimize Removing table bocp_934_idealcolmin/#sql2-32bb-eb7

2017-09-09 06:19:24 16bfbb70 InnoDB: FTS Optimize Removing table bocp_934_idealcolmin/#sql2-32bb-eb7

2017-09-09 06:19:28 16bfbb70 InnoDB: FTS Optimize Removing table bocp_934_idealcolmin/#sql2-32bb-eb7

2017-09-09 06:19:29 16bfbb70 InnoDB: FTS Optimize Removing table bocp_934_idealcolmin/#sql2-32bb-eb7

2017-09-09 06:19:30 b6ca1f70  InnoDB: Assertion failure in thread 3066699632 in file ut0mem.cc line 105

InnoDB: Failing assertion: ret || !assert_on_error

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.

170909  6:19:30 [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.26-MariaDB

key_buffer_size=268435456

read_buffer_size=2097152

max_used_connections=21

max_threads=202

thread_count=3

It is possible that mysqld could use up to

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1092183 K  bytes of memory

Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x243ba008

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 = 0xb6ca169c thread_stack 0x48400

2017-09-09  6:20:00 3066396528 [ERROR] mysqld: Out of memory (Needed 2095120 bytes)

2017-09-09  6:26:19 3067305840 [ERROR] mysqld: Out of memory (Needed 2095136 bytes)

2017-09-09  6:53:48 2362429296 [ERROR] mysqld: Out of memory (Needed 1006632 bytes)

2017-09-09  7:33:03 2362429296 [ERROR] mysqld: Out of memory (Needed 2095128 bytes)

2017-09-09  7:37:13 3066396528 [ERROR] mysqld: Out of memory (Needed 2095128 bytes)

2017-09-09  7:37:42 2362429296 [ERROR] mysqld: Out of memory (Needed 2095128 bytes)

2017-09-09  7:42:30 2793979760 [ERROR] mysqld: Out of memory (Needed 2095136 bytes)

2017-09-09  7:43:45 3068821360 [ERROR] mysqld: Out of memory (Needed 2095136 bytes)

2017-09-09  7:52:02 2793979760 [ERROR] mysqld: Out of memory (Needed 2095128 bytes)

2017-09-09 07:54:08 16bfbb70 InnoDB: FTS Optimize Removing table bocp_830_sczetcorpor/#sql-32bb_3efa

2017-09-09  7:54:12 2793979760 [ERROR] mysqld: Out of memory (Needed 2095136 bytes)

2017-09-09  7:54:14 3068821360 [ERROR] mysqld: Out of memory (Needed 2095136 bytes)

2017-09-09  7:54:16 3068821360 [ERROR] mysqld: Out of memory (Needed 2095120 bytes)

2017-09-09  7:54:22 3068821360 [ERROR] mysqld: Out of memory (Needed 2095136 bytes)

2017-09-09  7:54:24 3068821360 [ERROR] mysqld: Out of memory (Needed 2096448 bytes)

2017-09-09  7:54:37 3068821360 [ERROR] mysqld: Out of memory (Needed 99224 bytes)

2017-09-09  7:54:37 3068821360 [ERROR] mysqld: Out of memory (Needed 99224 bytes)

2017-09-09  7:54:40 3068821360 [ERROR] mysqld: Out of memory (Needed 2095136 bytes)

2017-09-09  7:54:44 3068821360 [ERROR] mysqld: Out of memory (Needed 2095120 bytes)

2017-09-09  7:54:45 2793979760 [ERROR] mysqld: Out of memory (Needed 2095136 bytes)

2017-09-09  7:54:48 2793979760 [ERROR] mysqld: Out of memory (Needed 2095136 bytes)

2017-09-09  7:54:51 2793979760 [ERROR] mysqld: Out of memory (Needed 99160 bytes)

2017-09-09  7:54:51 2793979760 [ERROR] mysqld: Out of memory (Needed 99160 bytes)

2017-09-09  7:55:01 3068821360 [ERROR] mysqld: Out of memory (Needed 99136 bytes)

2017-09-09  7:55:01 3068821360 [ERROR] mysqld: Out of memory (Needed 99136 bytes)

2017-09-09  7:55:13 3068821360 [ERROR] mysqld: Out of memory (Needed 99160 bytes)

2017-09-09  7:55:13 3068821360 [ERROR] mysqld: Out of memory (Needed 99160 bytes)

2017-09-09  7:55:22 3068821360 [ERROR] mysqld: Out of memory (Needed 99224 bytes)

2017-09-09  7:55:22 3068821360 [ERROR] mysqld: Out of memory (Needed 99224 bytes)

2017-09-09  7:55:27 3068821360 [ERROR] mysqld: Out of memory (Needed 99344 bytes)

2017-09-09  7:55:27 3068821360 [ERROR] mysqld: Out of memory (Needed 99344 bytes)

2017-09-09  7:55:31 3068821360 [ERROR] InnoDB:  InnoDB: Unable to allocate memory of size 214840.

2017-09-09 07:55:31 b6ea7f70  InnoDB: Assertion failure in thread 3068821360 in file ha_innodb.cc line 21960

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.

170909 07:55:31 mysqld_safe Number of processes running now: 0

170909 07:55:31 mysqld_safe mysqld restarted

2017-09-09  7:55:32 3070327200 [Warning] You need to use --log-bin to make --binlog-format work.

2017-09-09  7:55:32 3070327200 [Warning] 'THREAD_CONCURRENCY' is deprecated and will be removed in a future release.

2017-09-09  7:55:32 3070327200 [Note] /usr/sbin/mysqld (mysqld 10.1.26-MariaDB) starting as process 17497 ...

2017-09-09  7:55:32 3070327200 [Note] InnoDB: Using mutexes to ref count buffer pool pages

2017-09-09  7:55:32 3070327200 [Note] InnoDB: The InnoDB memory heap is disabled

2017-09-09  7:55:32 3070327200 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

2017-09-09  7:55:32 3070327200 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier

2017-09-09  7:55:32 3070327200 [Note] InnoDB: Compressed tables use zlib 1.2.3

2017-09-09  7:55:32 3070327200 [Note] InnoDB: Using Linux native AIO

2017-09-09  7:55:32 3070327200 [Note] InnoDB: Using generic crc32 instructions

2017-09-09  7:55:32 3070327200 [Note] InnoDB: Initializing buffer pool, size = 1.4G

2017-09-09  7:55:32 3070327200 [Note] InnoDB: Completed initialization of buffer pool

2017-09-09  7:55:32 3070327200 [Note] InnoDB: Highest supported file format is Barracuda.

2017-09-09  7:55:32 3070327200 [Note] InnoDB: Starting crash recovery from checkpoint LSN=12446905032867

2017-09-09  7:55:48 3070327200 [Note] InnoDB: Processed 38060 .ibd/.isl files

2017-09-09  7:55:58 3070327200 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...

2017-09-09  7:55:58 3070327200 [Note] InnoDB: Read redo log up to LSN=12446905163776

2017-09-09  7:55:58 3070327200 [Note] InnoDB: Starting final batch to recover 23 pages from redo log

InnoDB: Last MySQL binlog file position 0 841564108, file name ./mysql-bin.011327

2017-09-09  7:56:08 3070327200 [Note] InnoDB: 128 rollback segment(s) are active.

2017-09-09  7:56:08 3070327200 [Note] InnoDB: Waiting for purge to start

2017-09-09  7:56:08 3070327200 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log sequence number 12446905199633

2017-09-09  7:56:08 318765936 [Note] InnoDB: Dumping buffer pool(s) not yet started

2017-09-09  7:56:08 3070327200 [Note] Plugin 'FEEDBACK' is disabled.

2017-09-09  7:56:08 3070327200 [Note] Recovering after a crash using tc.log

2017-09-09  7:56:08 3070327200 [Note] Starting crash recovery...

2017-09-09  7:56:08 3070327200 [Note] Crash recovery finished.

2017-09-09  7:56:08 3070327200 [Note] Server socket created on IP: '::'.

2017-09-09  7:56:08 3070327200 [Note] /usr/sbin/mysqld: ready for connections.

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

I checked syssnap and there is not memory limit reach, there was 1.5GiB memory free at the time:

20170909 6 20 Load Average: 0.95 1.31 1.41 1/68 15659

Memory Usage:

MemTotal:        6656000 kB

MemFree:         1572440 kB

Cached:          2787168 kB

Buffers:               0 kB

Active:          2483124 kB

Inactive:        2385360 kB

Active(anon):    1383444 kB

Inactive(anon):   697872 kB

Active(file):    1099680 kB

Inactive(file):  1687488 kB

Unevictable:           0 kB

Mlocked:               0 kB

SwapTotal:       6656000 kB

SwapFree:        6519796 kB

Dirty:                56 kB

Writeback:             0 kB

AnonPages:       2081316 kB

Shmem:            132092 kB

Slab:              82900 kB

SReclaimable:      61404 kB

SUnreclaim:        21496 kB

Virtual Memory Stats:

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
0 0 136204 1572376 0 2787168 14 14 173 421 0 1 10 1 88 0 0
0 0 136204 1572400 0 2787168 0 0 4 6468 0 750 1 0 99 1 0
0 0 136204 1572404 0 2787192 0 0 0 6468 0 730 0 0 99 1 0
0 0 136204 1572400 0 2787192 0 0 0 6404 0 724 0 0 99 0 0
0 0 136204 1572124 0 2787464 0 0 0 6404 0 572 0 0 99 0 0
0 0 136204 1572116 0 2787464 0 0 0 6404 0 712 0 1 99 1 0
0 0 136204 1571824 0 2787752 0 0 0 6436 0 708 1 1 98 0 0
0 0 136204 1571816 0 2787752 0 0 0 6436 0 729 0 0 99 0 0
0 0 136204 1571808 0 2787752 0 0 0 6424 0 705 1 0 99 0 0
0 0 136204 1571804 0 2787752 0 0 0 6436 0 749 0 0 99 0 0

However I found out that there was one the following commands running at the time:

nice -n 19 mysqlcheck -Ar

nice -n 19 mysqlcheck -Ao

you have the my.cnf attached at the beginning
there are no agressinve memory limits set, why would we hit OOM?

Comment by Elena Stepanova [ 2017-10-01 ]

freedomizer,

if it happens regularly, could you maybe enable general log for a while, so we could see what else is happening on the instance around the time of the crash?
At the beginning, I asked for SHOW INDEX, I don't think it ever made it here. Alternatively, could you say how big the table product_variants_919 is?
Config and logs seem to be out of sync. The config says that innodb_buffer_pool_size is 384M, however the last log says that it's 1.4G. Is it the log from the same machine or a different one?
In your monitoring, do you have memory consumption per process? Can you increase the frequency of measurement? The suspicion is that the server might temporarily request a lot of memory in a short time (e.g. in relation to full-text indexes).
which exactly CentOS are you using, and which MariaDB packages (RPMs, or bintars, and if bintars, then what kind, or do you build from sources)?

Comment by Elena Stepanova [ 2017-11-05 ]

freedomizer, if you still encounter the issue, could you please provide the requested information?

[MDEV-13394] pthread_create() failure causes os_thread_create() crash in CREATE FULLTEXT INDEX Created: 2017-07-27 Updated: 2019-01-10 Resolved: 2017-12-11
Status:	Closed
Project:	MariaDB Server
Component/s:	Storage Engine - InnoDB
Affects Version/s:	10.1.25
Fix Version/s:	N/A

[MDEV-13394] pthread_create() failure causes os_thread_create() crash in CREATE FULLTEXT INDEX Created: 2017-07-27 Updated: 2019-01-10 Resolved: 2017-12-11