[MDEV-5405] RQG induced crash in mi_assign_to_key_cache in safe mutex unlock - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 5.3.12, 5.5.34, 10.0.6
Fix Version/s: 5.5.35, 10.0.8
Component/s: None
Labels:
None
Environment:
centos 6.2 running a debug build of mariadb-5.5.34

Description

When running this RQG test:

./runall.pl --grammar=conf/partitioning/partitions-99-hash.yy --duration=300 --queries=100000000 --threads=64 --basedir=/home/prohaska/mariadb-5.5.34-install/ --vardir=/home/prohaska/vardir.part99.3 --mask-level=0 --mask=0 --seed=1 --mysqld=--general_log --sqltrace

The code hits an assert in safe_mutex_unlock. With this code in mi_keycache.c that i added:

  lock = &share->key_cache->op_lock;

  pthread_mutex_lock(&share->key_cache->op_lock);

  if (flush_key_blocks(share->key_cache, share->kfile, &share->dirty_part_map,

                       FLUSH_RELEASE))

    error= my_errno;

    mi_print_error(info->s, HA_ERR_CRASHED);

    mi_mark_crashed(info);              /* Mark that table must be checked */

=>assert(lock == &share->key_cache->op_lock);

  pthread_mutex_unlock(&share->key_cache->op_lock);

Hits the assert since some other thread probably changed the share->key_cache pointer:

#8  0x0000000000c3988a in mi_assign_to_key_cache (info=0x7fb600b1ba60, key_map=1, key_cache=0x7fb60c83ebe0) at /home/prohaska/mariadb-5.5.34/storage/myisam/mi_keycache.c:89

#9  0x0000000000c147ff in ha_myisam::assign_to_keycache (this=0x7fb6005d3e78, thd=0x7fb5f194c060, check_opt=0x7fb5efb22ce0) at /home/prohaska/mariadb-5.5.34/storage/myisam/ha_myisam.cc:1237

#10 0x0000000000c752a5 in ha_partition::handle_opt_part (this=0x7fb5f66ffa78, thd=0x7fb5f194c060, check_opt=0x7fb5efb22ce0, part_id=5, flag=5) at /home/prohaska/mariadb-5.5.34/sql/ha_partition.cc:1084

#11 0x0000000000c75978 in ha_partition::handle_opt_partitions (this=0x7fb5f66ffa78, thd=0x7fb5f194c060, check_opt=0x7fb5efb22ce0, flag=5) at /home/prohaska/mariadb-5.5.34/sql/ha_partition.cc:1239

#12 0x0000000000c75083 in ha_partition::assign_to_keycache (this=0x7fb5f66ffa78, thd=0x7fb5f194c060, check_opt=0x7fb5efb22ce0) at /home/prohaska/mariadb-5.5.34/sql/ha_partition.cc:1011

#13 0x00000000007159c0 in mysql_admin_table(THD *, TABLE_LIST *, HA_CHECK_OPT *, const char *, thr_lock_type, bool, bool, uint, int (*)(THD *, TABLE_LIST *, HA_CHECK_OPT *), struct {...}, int (*)(THD *, \

TABLE_LIST *)) (thd=0x7fb5f194c060, tables=0x7fb5f11da168, check_opt=0x7fb5efb22ce0, operator_name=0xd7efcd "assign_to_keycache", lock_type=TL_READ_NO_INSERT, open_for_modify=false, repair_table_use_frm=\

false, extra_open_options=0, prepare_func=0x0, operator_func=&virtual table offset 504, view_operator_func=0x0) at /home/prohaska/mariadb-5.5.34/sql/sql_admin.cc:649

#14 0x0000000000716c27 in mysql_assign_to_keycache (thd=0x7fb5f194c060, tables=0x7fb5f11da168, key_cache_name=0x7fb5f194fe48) at /home/prohaska/mariadb-5.5.34/sql/sql_admin.cc:992

#15 0x000000000060a1dc in mysql_execute_command (thd=0x7fb5f194c060) at /home/prohaska/mariadb-5.5.34/sql/sql_parse.cc:2349

#16 0x00000000006132be in mysql_parse (thd=0x7fb5f194c060, rawbuf=0x7fb5f11da078 "CACHE INDEX i IN c4", length=19, parser_state=0x7fb5efb23650) at /home/prohaska/mariadb-5.5.34/sql/sql_parse.cc:5798

(gdb) p lock

$1 = (void *) 0x7fb622c1e6b0

(gdb) p &share->key_cache->op_lock

$2 = (safe_mutex_t *) 0x7fb5ff8308b0

Attachments

Activity

Ascending order - Click to sort in descending order

Rich Prohaska created issue - 2013-12-06 22:08

Sergei Golubchik made changes - 2013-12-10 18:05

Field	Original Value	New Value
Description	When running this RQG test: ./runall.pl --grammar=conf/partitioning/partitions-99-hash.yy --duration=300 --queries=100000000 --threads=64 --basedir=/home/prohaska/mariadb-5.5.34-install/ --vardir=/home/prohaska/vardir.part99.3 --mask-level=0 --mask=0 --seed=1 --mysqld=--general_log --sqltrace The code hits an assert in safe_mutex_unlock. With this code in mi_keycache.c that i added: lock = &share->key_cache->op_lock; pthread_mutex_lock(&share->key_cache->op_lock); if (flush_key_blocks(share->key_cache, share->kfile, &share->dirty_part_map, FLUSH_RELEASE)) { error= my_errno; mi_print_error(info->s, HA_ERR_CRASHED); mi_mark_crashed(info); /* Mark that table must be checked / } =>assert(lock == &share->key_cache->op_lock); pthread_mutex_unlock(&share->key_cache->op_lock); Hits the assert since some other thread probably changed the share->key_cache pointer: #8 0x0000000000c3988a in mi_assign_to_key_cache (info=0x7fb600b1ba60, key_map=1, key_cache=0x7fb60c83ebe0) at /home/prohaska/mariadb-5.5.34/storage/myisam/mi_keycache.c:89 #9 0x0000000000c147ff in ha_myisam::assign_to_keycache (this=0x7fb6005d3e78, thd=0x7fb5f194c060, check_opt=0x7fb5efb22ce0) at /home/prohaska/mariadb-5.5.34/storage/myisam/ha_myisam.cc:1237 #10 0x0000000000c752a5 in ha_partition::handle_opt_part (this=0x7fb5f66ffa78, thd=0x7fb5f194c060, check_opt=0x7fb5efb22ce0, part_id=5, flag=5) at /home/prohaska/mariadb-5.5.34/sql/ha_partition.cc:1084 #11 0x0000000000c75978 in ha_partition::handle_opt_partitions (this=0x7fb5f66ffa78, thd=0x7fb5f194c060, check_opt=0x7fb5efb22ce0, flag=5) at /home/prohaska/mariadb-5.5.34/sql/ha_partition.cc:1239 #12 0x0000000000c75083 in ha_partition::assign_to_keycache (this=0x7fb5f66ffa78, thd=0x7fb5f194c060, check_opt=0x7fb5efb22ce0) at /home/prohaska/mariadb-5.5.34/sql/ha_partition.cc:1011 #13 0x00000000007159c0 in mysql_admin_table(THD , TABLE_LIST , HA_CHECK_OPT , const char , thr_lock_type, bool, bool, uint, int ()(THD , TABLE_LIST , HA_CHECK_OPT ), struct {...}, int ()(THD , \ TABLE_LIST )) (thd=0x7fb5f194c060, tables=0x7fb5f11da168, check_opt=0x7fb5efb22ce0, operator_name=0xd7efcd "assign_to_keycache", lock_type=TL_READ_NO_INSERT, open_for_modify=false, repair_table_use_frm=\ false, extra_open_options=0, prepare_func=0x0, operator_func=&virtual table offset 504, view_operator_func=0x0) at /home/prohaska/mariadb-5.5.34/sql/sql_admin.cc:649 #14 0x0000000000716c27 in mysql_assign_to_keycache (thd=0x7fb5f194c060, tables=0x7fb5f11da168, key_cache_name=0x7fb5f194fe48) at /home/prohaska/mariadb-5.5.34/sql/sql_admin.cc:992 #15 0x000000000060a1dc in mysql_execute_command (thd=0x7fb5f194c060) at /home/prohaska/mariadb-5.5.34/sql/sql_parse.cc:2349 #16 0x00000000006132be in mysql_parse (thd=0x7fb5f194c060, rawbuf=0x7fb5f11da078 "CACHE INDEX i IN c4", length=19, parser_state=0x7fb5efb23650) at /home/prohaska/mariadb-5.5.34/sql/sql_parse.cc:5798 (gdb) p lock $1 = (void ) 0x7fb622c1e6b0 (gdb) p &share->key_cache->op_lock $2 = (safe_mutex_t ) 0x7fb5ff8308b0	When running this RQG test: {code} ./runall.pl --grammar=conf/partitioning/partitions-99-hash.yy --duration=300 --queries=100000000 --threads=64 --basedir=/home/prohaska/mariadb-5.5.34-install/ --vardir=/home/prohaska/vardir.part99.3 --mask-level=0 --mask=0 --seed=1 --mysqld=--general_log --sqltrace {code} The code hits an assert in {{safe_mutex_unlock}}. With this code in {{mi_keycache.c}} that i added: {code} lock = &share->key_cache->op_lock; pthread_mutex_lock(&share->key_cache->op_lock); if (flush_key_blocks(share->key_cache, share->kfile, &share->dirty_part_map, FLUSH_RELEASE)) { error= my_errno; mi_print_error(info->s, HA_ERR_CRASHED); mi_mark_crashed(info); /* Mark that table must be checked / } =>assert(lock == &share->key_cache->op_lock); pthread_mutex_unlock(&share->key_cache->op_lock); {code} Hits the assert since some other thread probably changed the share->key_cache pointer: {noformat} #8 0x0000000000c3988a in mi_assign_to_key_cache (info=0x7fb600b1ba60, key_map=1, key_cache=0x7fb60c83ebe0) at /home/prohaska/mariadb-5.5.34/storage/myisam/mi_keycache.c:89 #9 0x0000000000c147ff in ha_myisam::assign_to_keycache (this=0x7fb6005d3e78, thd=0x7fb5f194c060, check_opt=0x7fb5efb22ce0) at /home/prohaska/mariadb-5.5.34/storage/myisam/ha_myisam.cc:1237 #10 0x0000000000c752a5 in ha_partition::handle_opt_part (this=0x7fb5f66ffa78, thd=0x7fb5f194c060, check_opt=0x7fb5efb22ce0, part_id=5, flag=5) at /home/prohaska/mariadb-5.5.34/sql/ha_partition.cc:1084 #11 0x0000000000c75978 in ha_partition::handle_opt_partitions (this=0x7fb5f66ffa78, thd=0x7fb5f194c060, check_opt=0x7fb5efb22ce0, flag=5) at /home/prohaska/mariadb-5.5.34/sql/ha_partition.cc:1239 #12 0x0000000000c75083 in ha_partition::assign_to_keycache (this=0x7fb5f66ffa78, thd=0x7fb5f194c060, check_opt=0x7fb5efb22ce0) at /home/prohaska/mariadb-5.5.34/sql/ha_partition.cc:1011 #13 0x00000000007159c0 in mysql_admin_table(THD , TABLE_LIST , HA_CHECK_OPT , const char , thr_lock_type, bool, bool, uint, int ()(THD , TABLE_LIST , HA_CHECK_OPT ), struct {...}, int ()(THD , \ TABLE_LIST )) (thd=0x7fb5f194c060, tables=0x7fb5f11da168, check_opt=0x7fb5efb22ce0, operator_name=0xd7efcd "assign_to_keycache", lock_type=TL_READ_NO_INSERT, open_for_modify=false, repair_table_use_frm=\ false, extra_open_options=0, prepare_func=0x0, operator_func=&virtual table offset 504, view_operator_func=0x0) at /home/prohaska/mariadb-5.5.34/sql/sql_admin.cc:649 #14 0x0000000000716c27 in mysql_assign_to_keycache (thd=0x7fb5f194c060, tables=0x7fb5f11da168, key_cache_name=0x7fb5f194fe48) at /home/prohaska/mariadb-5.5.34/sql/sql_admin.cc:992 #15 0x000000000060a1dc in mysql_execute_command (thd=0x7fb5f194c060) at /home/prohaska/mariadb-5.5.34/sql/sql_parse.cc:2349 #16 0x00000000006132be in mysql_parse (thd=0x7fb5f194c060, rawbuf=0x7fb5f11da078 "CACHE INDEX i IN c4", length=19, parser_state=0x7fb5efb23650) at /home/prohaska/mariadb-5.5.34/sql/sql_parse.cc:5798 (gdb) p lock $1 = (void ) 0x7fb622c1e6b0 (gdb) p &share->key_cache->op_lock $2 = (safe_mutex_t ) 0x7fb5ff8308b0 {noformat}

Sergei Golubchik made changes - 2013-12-10 18:06

Assignee

Elena Stepanova [ elenst ]

Elena Stepanova made changes - 2013-12-21 01:16

Fix Version/s		10.0.8 [ 14200 ]
Fix Version/s		5.5.35 [ 14000 ]
Fix Version/s		5.3.13 [ 12602 ]
Affects Version/s		10.0.7 [ 14100 ]
Affects Version/s		5.3.13 [ 12602 ]
Assignee	Elena Stepanova [ elenst ]	Alexander Barkov [ bar ]

Elena Stepanova made changes - 2013-12-21 01:18

Comment

[ The problem appeared in 5.3 tree with the following revision:

------------------------------------------------------------
revno: 3674
revision-id: bar@mariadb.org-20130812124759-8cy7ot1s3ysgned2
parent: sanja@montyprogram.com-20130801084611-udozq8c9kxgy94bq
committer: Alexander Barkov <bar@mariadb.org>
branch nick: 5.3.b4652
timestamp: Mon 2013-08-12 16:47:59 +0400
message:
~~MDEV-4652~~ Wrong result for CONCAT(GREATEST(TIME('00:00:01'),TIME('00:00:00'))

###########################

# Test case:

CREATE TABLE t1 (t TIME);
INSERT INTO t1 VALUES ('03:22:30'),('18:30:05');
SELECT CONVERT_TZ( GREATEST( t, CURRENT_DATE() ), 'Europe/Moscow', 'Japan' ) FROM t1;

]

Elena Stepanova made changes - 2013-12-21 01:18

Assignee

Alexander Barkov [ bar ]

Elena Stepanova [ elenst ]

Elena Stepanova made changes - 2013-12-21 01:18

Fix Version/s	5.3.13 [ 12602 ]
Fix Version/s	5.5.35 [ 14000 ]
Fix Version/s	10.0.8 [ 14200 ]

Elena Stepanova made changes - 2013-12-21 01:19

Affects Version/s	5.3.13 [ 12602 ]
Affects Version/s	10.0.7 [ 14100 ]

Elena Stepanova added a comment - 2013-12-25 20:29 - edited

I presume the initial problem (on unmodified binaries) was this:

safe_mutex: Trying to unlock mutex keycache->op_lock that wasn't locked at mi_keycache.c, line 86

Last used at mf_keycache.c, line: 6048

131225 21:21:25 [ERROR] mysqld got signal 6 ;

Simplified grammar:

thread1_init:

   CREATE TABLE IF NOT EXISTS `t1` ( `f` INT, KEY(`f`) ) ENGINE=MyISAM;

query:

        CACHE INDEX t1 IN cache_name |

        SET GLOBAL cache_name.key_buffer_size = _smallint_unsigned ;

cache_name:

        c1 | c2 ;

# End of grammar

Command line:

perl ./runall.pl --grammar=mdev5405.yy --duration=300 --queries=100M --threads=4 --skip-gendata --vardir=<your vardir> --basedir=<your basedir>

or with already running server

perl ./gentest.pl  --grammar=mdev5405.yy --duration=300 --queries=100M --threads=4 --dsn=dbi:mysql:user=root:port=3306:database=test:host=127.0.0.1

Reproducible on 5.3 and 5.5. On 10.0, it tends to hang instead.

I've set it up on perro as usual, for 5.3 and 5.5

cd mdev5405

. ./run53

#5  0x00007f5572bf7b8b in __GI_abort () at abort.c:91

#6  0x0000000000b97cad in safe_mutex_unlock (mp=0x7f550c0d7388, file=0xd88d38 "mi_keycache.c", line=86) at thr_mutex.c:425

#7  0x000000000093825e in mi_assign_to_key_cache (info=0x7f550400b7c8, key_map=1, key_cache=0x7f550c0d7338) at mi_keycache.c:86

#8  0x000000000090f859 in ha_myisam::assign_to_keycache (this=0x7f550400aca0, thd=0x4d8c0b8, check_opt=0x7f55587eac30) at ha_myisam.cc:1356

#9  0x0000000000839cda in mysql_admin_table(THD *, TABLE_LIST *, HA_CHECK_OPT *, const char *, thr_lock_type, bool, bool, uint, int (*)(THD *, TABLE_LIST *, HA_CHECK_OPT *), struct {...}, int (*)(THD *, TABLE_LIST *)) (thd=0x4d8c0b8, tables=0x7f550c02c640, check_opt=0x7f55587eac30, operator_name=0xd5d8d8 "assign_to_keycache", lock_type=TL_READ_NO_INSERT, open_for_modify=false, no_warnings_for_error=false, extra_open_options=0, prepare_func=0, operator_func=&virtual table offset 480, view_operator_func=0) at sql_table.cc:4972

#10 0x000000000083b289 in mysql_assign_to_keycache (thd=0x4d8c0b8, tables=0x7f550c02c640, key_cache_name=0x4d8ef38) at sql_table.cc:5305

#11 0x000000000068aa58 in mysql_execute_command (thd=0x4d8c0b8) at sql_parse.cc:2459

#12 0x000000000069600c in mysql_parse (thd=0x4d8c0b8, rawbuf=0x7f550c02c550 "CACHE INDEX t1 IN c2", length=20, found_semicolon=0x7f55587eb7e0) at sql_parse.cc:6173

#13 0x0000000000687a67 in dispatch_command (command=COM_QUERY, thd=0x4d8c0b8, packet=0x4d942a9 "", packet_length=20) at sql_parse.cc:1243

#14 0x0000000000686cd8 in do_command (thd=0x4d8c0b8) at sql_parse.cc:923

#15 0x0000000000683b72 in handle_one_connection (arg=0x4d8c0b8) at sql_connect.cc:1231

#16 0x00007f5573788e9a in start_thread (arg=0x7f55587ec700) at pthread_create.c:308

#17 0x00007f5572cb1cbd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112

Elena Stepanova added a comment - 2013-12-25 20:29 - edited I presume the initial problem (on unmodified binaries) was this: safe_mutex: Trying to unlock mutex keycache->op_lock that wasn't locked at mi_keycache.c, line 86 Last used at mf_keycache.c, line: 6048 131225 21:21:25 [ERROR] mysqld got signal 6 ; Simplified grammar: thread1_init: CREATE TABLE IF NOT EXISTS `t1` ( `f` INT, KEY(`f`) ) ENGINE=MyISAM; query: CACHE INDEX t1 IN cache_name | SET GLOBAL cache_name.key_buffer_size = _smallint_unsigned ; cache_name: c1 | c2 ; # End of grammar Command line: perl ./runall.pl --grammar=mdev5405.yy --duration=300 --queries=100M --threads=4 --skip-gendata --vardir=<your vardir> --basedir=<your basedir> or with already running server perl ./gentest.pl --grammar=mdev5405.yy --duration=300 --queries=100M --threads=4 --dsn=dbi:mysql:user=root:port=3306:database=test:host=127.0.0.1 Reproducible on 5.3 and 5.5. On 10.0, it tends to hang instead. I've set it up on perro as usual, for 5.3 and 5.5 cd mdev5405 . ./run53 #5 0x00007f5572bf7b8b in __GI_abort () at abort.c:91 #6 0x0000000000b97cad in safe_mutex_unlock (mp=0x7f550c0d7388, file=0xd88d38 "mi_keycache.c", line=86) at thr_mutex.c:425 #7 0x000000000093825e in mi_assign_to_key_cache (info=0x7f550400b7c8, key_map=1, key_cache=0x7f550c0d7338) at mi_keycache.c:86 #8 0x000000000090f859 in ha_myisam::assign_to_keycache (this=0x7f550400aca0, thd=0x4d8c0b8, check_opt=0x7f55587eac30) at ha_myisam.cc:1356 #9 0x0000000000839cda in mysql_admin_table(THD *, TABLE_LIST *, HA_CHECK_OPT *, const char *, thr_lock_type, bool, bool, uint, int (*)(THD *, TABLE_LIST *, HA_CHECK_OPT *), struct {...}, int (*)(THD *, TABLE_LIST *)) (thd=0x4d8c0b8, tables=0x7f550c02c640, check_opt=0x7f55587eac30, operator_name=0xd5d8d8 "assign_to_keycache", lock_type=TL_READ_NO_INSERT, open_for_modify=false, no_warnings_for_error=false, extra_open_options=0, prepare_func=0, operator_func=&virtual table offset 480, view_operator_func=0) at sql_table.cc:4972 #10 0x000000000083b289 in mysql_assign_to_keycache (thd=0x4d8c0b8, tables=0x7f550c02c640, key_cache_name=0x4d8ef38) at sql_table.cc:5305 #11 0x000000000068aa58 in mysql_execute_command (thd=0x4d8c0b8) at sql_parse.cc:2459 #12 0x000000000069600c in mysql_parse (thd=0x4d8c0b8, rawbuf=0x7f550c02c550 "CACHE INDEX t1 IN c2", length=20, found_semicolon=0x7f55587eb7e0) at sql_parse.cc:6173 #13 0x0000000000687a67 in dispatch_command (command=COM_QUERY, thd=0x4d8c0b8, packet=0x4d942a9 "", packet_length=20) at sql_parse.cc:1243 #14 0x0000000000686cd8 in do_command (thd=0x4d8c0b8) at sql_parse.cc:923 #15 0x0000000000683b72 in handle_one_connection (arg=0x4d8c0b8) at sql_connect.cc:1231 #16 0x00007f5573788e9a in start_thread (arg=0x7f55587ec700) at pthread_create.c:308 #17 0x00007f5572cb1cbd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112

Elena Stepanova made changes - 2013-12-25 20:29

Affects Version/s		5.3.12 [ 12000 ]
Affects Version/s		10.0.6 [ 13202 ]
Assignee	Elena Stepanova [ elenst ]	Sergei Golubchik [ serg ]

Elena Stepanova made changes - 2013-12-25 20:51

Fix Version/s		10.0.7 [ 14100 ]
Fix Version/s		5.5.35 [ 14000 ]
Fix Version/s		5.3.13 [ 12602 ]

Sergei Golubchik made changes - 2013-12-28 17:50

Fix Version/s		10.0.8 [ 14200 ]
Fix Version/s	10.0.7 [ 14100 ]

Sergei Golubchik made changes - 2014-01-24 20:51

Status

Open [ 1 ]

In Progress [ 3 ]

Sergei Golubchik made changes - 2014-01-28 01:18

Fix Version/s	5.3.13 [ 12602 ]
Resolution		Fixed [ 1 ]
Status	In Progress [ 3 ]	Closed [ 6 ]

Daniel Bartholomew added a comment - 2014-01-29 19:20

http://bazaar.launchpad.net/~maria-captains/maria/5.5/revision/4047

Daniel Bartholomew added a comment - 2014-01-29 19:20 http://bazaar.launchpad.net/~maria-captains/maria/5.5/revision/4047

Sergei Golubchik made changes - 2014-06-13 15:06

Workflow

defaullt [ 30638 ]

MariaDB v2 [ 42831 ]

Rasmus Johansson (Inactive) made changes - 2015-05-18 17:50

Workflow

MariaDB v2 [ 42831 ]

MariaDB v3 [ 61849 ]

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

Workflow

MariaDB v3 [ 61849 ]

MariaDB v4 [ 147312 ]

People

Assignee:: Sergei Golubchik

Reporter:: Rich Prohaska

Votes:: 0 Vote for this issue

Watchers:: 5 Start watching this issue

Dates

Created:: 2013-12-06 22:08

Updated:: 2014-01-29 19:20

Resolved:: 2014-01-28 01:18

Git Integration

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

MariaDB Server

Details

Description

Attachments

Activity

People

Dates

Git Integration