Bug #89126 create table panic on innobase_parse_hint_from_comment
Submitted: 7 Jan 2018 13:42 Modified: 4 Feb 2019 13:04
Reporter: Yan Huang (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.7.16 OS:Any
Assigned to: CPU Architecture:Any

[7 Jan 2018 13:42] Yan Huang
Description:
MySQL panic on following backtrace: 

```
/data/app/mysql/bin/mysqld(my_print_stacktrace+0x35)[0xf1dff5]
/data/app/mysql/bin/mysqld(handle_fatal_signal+0x4a4)[0x79d3b4]
/lib64/libpthread.so.0(+0xf850)[0x7f8d7b81f850]
/data/app/mysql/bin/mysqld(_Z30dict_index_set_merge_thresholdP12dict_index_tm+0x2ad)[0x11d60bd]
/data/app/mysql/bin/mysqld(_Z32innobase_parse_hint_from_commentP3THDP12dict_table_tPK11TABLE_SHARE+0x6b2)[0xfe8f22]
/data/app/mysql/bin/mysqld(_ZN19create_table_info_t24create_table_update_dictEv+0x1e0)[0xfed290]
/data/app/mysql/bin/mysqld(_ZN11ha_innopart6createEPKcP5TABLEP24st_ha_create_information+0x6cb)[0x1005a0b]
/data/app/mysql/bin/mysqld(_Z15ha_create_tableP3THDPKcS2_S2_P24st_ha_create_informationbb+0x2a3)[0x7e6d63]
/data/app/mysql/bin/mysqld(_Z16rea_create_tableP3THDPKcS2_S2_P24st_ha_create_informationR4ListI12Create_fieldEjP6st_keyP7handlerb+0x11a)[0xdb45da]
/data/app/mysql/bin/mysqld[0xd58917]
/data/app/mysql/bin/mysqld(_Z26mysql_create_table_no_lockP3THDPKcS2_P24st_ha_create_informationP10Alter_infojPb+0xe7)[0xd591e7]
/data/app/mysql/bin/mysqld(_Z18mysql_create_tableP3THDP10TABLE_LISTP24st_ha_create_informationP10Alter_info+0x9f)[0xd5998f]
/data/app/mysql/bin/mysqld(_Z21mysql_execute_commandP3THDb+0x4ed2)[0xcf7622]
/data/app/mysql/bin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x3a5)[0xcf7a15]
/data/app/mysql/bin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0x116d)[0xcf8bed]
/data/app/mysql/bin/mysqld(_Z10do_commandP3THD+0x194)[0xcf96e4]
/data/app/mysql/bin/mysqld(handle_connection+0x29c)[0xdc5a0c]
/data/app/mysql/bin/mysqld(pfs_spawn_thread+0x174)[0xf7a804]
/lib64/libpthread.so.0(+0x7806)[0x7f8d7b817806]
/lib64/libc.so.6(clone+0x6d)[0x7f8d7a59064d]
```

Cause: table is closed before read by innobase_parse_hint_from_comment, and srv_master_thread recycle innobase_table first

How to repeat:
1. create table, block its thread before innobase_parse_hint_from_comment (ha_innodb.cc)
2. let srv_master_thread trigger srv_master_evict_from_table_cache (srv0srv.cc) by gdb, preconditions:
2.1 cur_time % SRV_MASTER_DICT_LRU_INTERVAL == 0
2.2 table cache length >= table_definition_cache
3. srv_master_thread will release table->heap in dict_make_room_in_cache
4. let create-table thread go
5. MySQL panic

Suggested fix:
Patch based on 5.7 master is attached
[7 Jan 2018 13:43] Yan Huang
patch based on MySQL 5.7 master

Attachment: mysql_panic_on_innobase_parse_hint_from_comment.diff (application/octet-stream, text), 531 bytes.

[11 Jan 2018 9:25] MySQL Verification Team
Hi,

I can reproduce this with a debugger but I'm not able to get the real-life example to reproduce this. I'll set the bug to verified and let the ibd team decide how to deal with it. As for your patch, I don't see that you signed OCA so we can't use it. If you would like to sign OCA please follow the procedure and then we can accept this as contribution.

all best
Bogdan

In order to submit contributions you must first sign the Oracle Contribution Agreement (OCA).
For additional information please check http://www.oracle.com/technetwork/community/oca-486395.html.
If you have any questions, please contact the MySQL community team (https://dev.mysql.com/community/).
[11 Jan 2018 9:31] MySQL Verification Team
I'm not sure I follow what this patch does? From what I See it just removes an empty line?!
[11 Jan 2018 13:38] Yan Huang
Hello Bogdan Kecman,
1. The patch puts `dict_table_close` line after `innobase_parse_hint_from_comment` line.
2. I will apply for OCA in days, sorry for inconvenience.
3. We found this bug in production, the following example may help:
3.1. The table cache is almost full
3.2. We created a partition-table with 12 partitions, and table cache is full
3.3. While creating table, `cur_time % SRV_MASTER_DICT_LRU_INTERVAL == 0` happens by chance (so we cannot reproduce the crash after reboot)
[19 Jan 2018 4:08] Yan Huang
Hello Bogdan Kecman,
My OCA was sent early in this week, and waiting for reply.
[23 Jan 2018 14:26] Yan Huang
Hello,
My OCA is signed already. Thanks.
[28 Feb 2018 6:17] Yan Huang
resent patch to Contributions tab

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: mysql_panic_on_innobase_parse_hint_from_comment.diff (application/octet-stream, text), 531 bytes.

[20 Mar 2018 16:05] MySQL Verification Team
Bug:

https://bugs.mysql.com/bug.php?id=90126 is a duplicate of this one.
[21 Aug 2018 0:24] Marcelo Altmann
Was able to reproduce it on 5.7.23:

00:03:39 UTC - mysqld got signal 11 ;
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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=602
max_threads=1024
thread_count=602
connection_count=602
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 415104 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7fb97c019a20
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 = 7fb9cc826e80 thread_stack 0x40000
/home/marcelo.altmann/bug-89126/mysql-5-7-23/bin/mysqld(my_print_stacktrace+0x2c)[0xebb61c]
/home/marcelo.altmann/bug-89126/mysql-5-7-23/bin/mysqld(handle_fatal_signal+0x451)[0x7aa021]
/lib64/libpthread.so.0(+0xf6d0)[0x7fba6182d6d0]
/home/marcelo.altmann/bug-89126/mysql-5-7-23/bin/mysqld(_Z32innobase_parse_hint_from_commentP3THDP12dict_table_tPK11TABLE_SHARE+0x1c0)[0xf618f0]
/home/marcelo.altmann/bug-89126/mysql-5-7-23/bin/mysqld(_ZN19create_table_info_t24create_table_update_dictEv+0x17d)[0xf7348d]
/home/marcelo.altmann/bug-89126/mysql-5-7-23/bin/mysqld(_ZN11ha_innobase6createEPKcP5TABLEP24st_ha_create_information+0x27d)[0xf74f0d]
/home/marcelo.altmann/bug-89126/mysql-5-7-23/bin/mysqld(_ZN11ha_innopart20create_new_partitionEP5TABLEP24st_ha_create_informationPKcjP17partition_element+0xb5)[0xf84365]
/home/marcelo.altmann/bug-89126/mysql-5-7-23/bin/mysqld(_ZN16Partition_helper17change_partitionsEP24st_ha_create_informationPKcPyS4_+0x469)[0xbf84c9]
/home/marcelo.altmann/bug-89126/mysql-5-7-23/bin/mysqld[0xc9b8af]
/home/marcelo.altmann/bug-89126/mysql-5-7-23/bin/mysqld(_Z26fast_alter_partition_tableP3THDP5TABLEP10Alter_infoP24st_ha_create_informationP10TABLE_LISTPcPKcP14partition_info+0x51d)[0xca5fbd]
/home/marcelo.altmann/bug-89126/mysql-5-7-23/bin/mysqld(_Z17mysql_alter_tableP3THDPKcS2_P24st_ha_create_informationP10TABLE_LISTP10Alter_info+0xd98)[0xcfd928]
/home/marcelo.altmann/bug-89126/mysql-5-7-23/bin/mysqld(_ZN19Sql_cmd_alter_table7executeEP3THD+0x52e)[0xdf645e]
/home/marcelo.altmann/bug-89126/mysql-5-7-23/bin/mysqld(_Z21mysql_execute_commandP3THDb+0x5b0)[0xc923f0]
/home/marcelo.altmann/bug-89126/mysql-5-7-23/bin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x3bd)[0xc985bd]
/home/marcelo.altmann/bug-89126/mysql-5-7-23/bin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0xa70)[0xc99100]
/home/marcelo.altmann/bug-89126/mysql-5-7-23/bin/mysqld(_Z10do_commandP3THD+0x177)[0xc9aa77]
/home/marcelo.altmann/bug-89126/mysql-5-7-23/bin/mysqld(handle_connection+0x270)[0xd56be0]
/home/marcelo.altmann/bug-89126/mysql-5-7-23/bin/mysqld(pfs_spawn_thread+0x1b1)[0xeebf81]
/lib64/libpthread.so.0(+0x7e25)[0x7fba61825e25]
/lib64/libc.so.6(clone+0x6d)[0x7fba604ebbad]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7fb97c01cfe0): ALTER TABLE bug_89126.t1 REORGANIZE PARTITION p1,pMAX INTO (PARTITION pMAX VALUES LESS THAN MAXVALUE)
Connection ID (thread ID): 4
Status: NOT_KILLED

* How to reproduce:

my.cnf
[mysqld]
max_connections=1024
table_open_cache=500
table-definition-cache=400
open_files_limit=65535
innodb_open_files=4096
innodb_buffer_pool_size=2G

1) Create sysbench test data:
./use -e "CREATE DATABASE sbtest"
sysbench --db-driver=mysql \
--db-ps-mode=disable --mysql-host=127.0.0.1 --mysql-port=5726 \
--mysql-user=root --mysql-password=msandbox --table_size=100 \
--tables=1500 /usr/share/sysbench/oltp_insert.lua --threads=30 prepare

2) Create a dummy table
CREATE DATABASE bug_89126;
USE bug_89126;
CREATE TABLE `t1` (
  `ID` int(11) NOT NULL AUTO_INCREMENT,
  PRIMARY KEY (`ID`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
/*!50100 PARTITION BY RANGE (ID)
(PARTITION p0 VALUES LESS THAN (1) ENGINE = InnoDB,
 PARTITION pMAX VALUES LESS THAN MAXVALUE ENGINE = InnoDB) */;

3) Session 1: loop through an ALTER TABLE:

for i in {1..9999};
do
./use -e "ALTER TABLE bug_89126.t1 REORGANIZE PARTITION pMAX INTO (PARTITION p1 VALUES LESS THAN (2), PARTITION pMAX VALUES LESS THAN MAXVALUE)"
./use -e "ALTER TABLE bug_89126.t1 REORGANIZE PARTITION p1,pMAX INTO (PARTITION pMAX VALUES LESS THAN MAXVALUE)"
done

4) Session 2: On a concurrent session, make sure you exhaust open table_definition_cache

sysbench --db-driver=mysql \
--db-ps-mode=disable --mysql-host=127.0.0.1 --mysql-port=5726 \
--mysql-user=root --mysql-password=msandbox --table_size=100 \
--tables=1500 /usr/share/sysbench/oltp_insert.lua --threads=600 --report-interval=1 --time=0 run

* Note: This may take few hours to occur. 
* * In order to increase the peace in which this issue happens. Modify storage/innobase/handler/ha_innodb.cc :

diff --git a/storage/innobase/handler/ha_innodb.cc b/storage/innobase/handler/ha_innodb.cc
index f1cba47..b02c305 100644
--- a/storage/innobase/handler/ha_innodb.cc
+++ b/storage/innobase/handler/ha_innodb.cc
@@ -12127,6 +12127,9 @@ create_table_info_t::create_table_update_dict()

        dict_table_close(innobase_table, FALSE, FALSE);

+       /* facilitate the occurrence of https://bugs.mysql.com/bug.php?id=89126 */
+       os_thread_sleep(5000000);
+
        innobase_parse_hint_from_comment(m_thd, innobase_table, m_form->s);

        DBUG_RETURN(0);

After applying the patch provided by Yan Huang fixes the crash.
[4 Feb 2019 13:03] Daniel Price
Posted by developer:
 
    Problem:
    Accessing freed table object inside innodb_parse_hint_from_comment()
    
    Analysis:
    In create table thread, we are using dict_table_t memory object after closing
    the table, and during close, we set the reference count of the table object
    to zero which makes it available for a background thread to clear the
    dict_table_t from the cache. If the background thread frees the memory for the
    dict_table_t before creating thread calls innodb_parse_hint_from_comment(),
    it causes the issue.
    
    Fix:
    Close table object after calling innodb_parse_hint_from_comment().
[4 Feb 2019 13:04] Daniel Price
Posted by developer:
 
Fixed as of the upcoming 5.7.26, 8.0.16 release, and here's the changelog entry:

A function called by a CREATE TABLE thread attempted to access a table
object after it was freed by a background thread. 

Thanks to Yan Huang for the patch.