field.cc:3822: virtual longlong Field_long::val_int(): Assertion `table->in_use == _current_thd()' failed

Bug #1113388 reported by Elena Stepanova on 2013-02-02
12
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
High
Laurynas Biveinis
5.1
Won't Fix
High
Unassigned
5.5
Fix Released
High
Laurynas Biveinis
5.6
Fix Released
High
Laurynas Biveinis

Bug Description

It looks very similar to bug #951588, except that it's marked as fixed a few versions ago.

mysqld: Percona-Server/sql/field.cc:3721: virtual longlong Field_long::val_int(): Assertion `table->in_use == _current_thd()' failed.

# 2013-02-02T15:30:50 #6 0x00007fa6b7384d4d in __GI___assert_fail (assertion=0xc20120 "table->in_use == _current_thd()", file=<optimized out>, line=3721, function=<optimized out>) at assert.c:81
# 2013-02-02T15:30:50 #7 0x0000000000732d1e in Field_long::val_int (this=0x37c12f0) at Percona-Server/sql/field.cc:3721
# 2013-02-02T15:30:50 #8 0x00000000008d62c6 in ha_innobase::write_row (this=0x37d9b70, record=0x37c1210 "\f\374S") at Percona-Server/storage/innobase/handler/ha_innodb.cc:6101
# 2013-02-02T15:30:50 #9 0x000000000075c150 in handler::ha_write_row (this=0x37d9b70, buf=0x37c1210 "\f\374S") at Percona-Server/sql/handler.cc:5424
# 2013-02-02T15:30:50 #10 0x00000000006795fe in copy_data_between_tables (from=0x379b090, to=0x3761000, create=..., ignore=false, order_num=0, order=0x0, copied=0x7fa6a8fded68, deleted=0x7fa6a8fded70, keys_onoff=LEAVE_AS_IS, error_if_not_empty=false) at Percona-Server/sql/sql_table.cc:7370
# 2013-02-02T15:30:50 #11 0x00000000006773dc in mysql_alter_table (thd=0x3746be0, new_db=0x37bdeb0 "test", new_name=0x37bd950 "E", create_info=0x7fa6a8fe02d0, table_list=0x37bd988, alter_info=0x7fa6a8fe03b0, order_num=0, order=0x0, ignore=false) at Percona-Server/sql/sql_table.cc:6674
# 2013-02-02T15:30:50 #12 0x0000000000897a98 in Alter_table_statement::execute (this=0x37bdf98, thd=0x3746be0) at Percona-Server/sql/sql_alter.cc:106
# 2013-02-02T15:30:50 #13 0x00000000005efe53 in mysql_execute_command (thd=0x3746be0) at Percona-Server/sql/sql_parse.cc:4615
# 2013-02-02T15:30:50 #14 0x00000000005f29a3 in mysql_parse (thd=0x3746be0, rawbuf=0x37bd880 "ALTER TABLE `E` ADD COLUMN o INTEGER", length=36, parser_state=0x7fa6a8fe2040) at Percona-Server/sql/sql_parse.cc:5844
# 2013-02-02T15:30:50 #15 0x00000000005e66a1 in dispatch_command (command=COM_QUERY, thd=0x3746be0, packet=0x3846471 "ALTER TABLE `E` ADD COLUMN o INTEGER", packet_length=36) at Percona-Server/sql/sql_parse.cc:1061
# 2013-02-02T15:30:50 #16 0x00000000005e597d in do_command (thd=0x3746be0) at Percona-Server/sql/sql_parse.cc:788
# 2013-02-02T15:30:50 #17 0x00000000006cd47e in do_handle_one_connection (thd_arg=0x3746be0) at Percona-Server/sql/sql_connect.cc:1497
# 2013-02-02T15:30:50 #18 0x00000000006cce64 in handle_one_connection (arg=0x3746be0) at Percona-Server/sql/sql_connect.cc:1404
# 2013-02-02T15:30:50 #19 0x00007fa6b80c8efc in start_thread (arg=0x7fa6a8fe3700) at pthread_create.c:304
# 2013-02-02T15:30:50 #20 0x00007fa6b743af4d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
# 2013-02-02T15:30:50 #21 0x0000000000000000 in ?? ()

RQG grammar percona-is.yy (the grammar queries any tables in I_S, but it really boils down to concurrent ALTER TABLE and SELECT I_S. GLOBAL_TEMPORARY_TABLES or such):

query:
        SELECT * FROM { $last_database = 'INFORMATION_SCHEMA' } . _table LIMIT 1 ;

thread1:
        ALTER TABLE _table ADD COLUMN _letter INTEGER |
        ALTER TABLE _table DROP COLUMN _letter ;

# End of RQG grammar

RQG command line:

perl ./runall.pl --threads=2 --duration=600 --queries=100M --grammar=percona-is.yy --engine=InnoDB --gendata --basedir=<your basedir>

The test crashes for me within seconds after start.

revision-id: <email address hidden>
revno: 411
branch-nick: percona-server

Built as
cmake . -DCMAKE_BUILD_TYPE=Debug && make

Related branches

Elena -

Thanks for your bug report. What was the table definition for "E" before the crashing ALTER TABLE?

Indeed it's very similar to bug 951588. There is a difference though that 951588 testcase does not exercise auto_increment, and this crash is in the auto_increment code path. Extending the 951588 testcase to exercise auto_increment goes through this code path, but does not assert.

Elena Stepanova (elenst) wrote :

Initial structure of table E

CREATE TABLE E (
                        pk INTEGER AUTO_INCREMENT,
                        col_int_nokey INTEGER /*! NULL */,
                        col_int_key INTEGER /*! NULL */,

                        col_date_key DATE /*! NULL */,
                        col_date_nokey DATE /*! NULL */,

                        col_time_key TIME /*! NULL */,
                        col_time_nokey TIME /*! NULL */,

                        col_datetime_key DATETIME /*! NULL */,
                        col_datetime_nokey DATETIME /*! NULL */,

                        col_varchar_key VARCHAR(1) /*! NULL */,
                        col_varchar_nokey VARCHAR(1) /*! NULL */,

                        PRIMARY KEY (pk),
                        KEY (col_int_key),
                        KEY (col_date_key),
                        KEY (col_time_key),
                        KEY (col_datetime_key),
                        KEY (col_varchar_key, col_int_key)
                ) ENGINE=InnoDB

I don't have logs from the exact reported crash, but in a very similar one the crash happened on the very first ALTER TABLE E ADD COLUMN, so the table definition hadn't yet changed by then.

Same was the case with my intermediate (non-deterministic) MTR test. All it did was

- create table as described above;
- populate with 1000 rows;
- run ALTER TABLE .. ADD COLUMN;
- in parallel with alter, run I_S queries
        SELECT * FROM INFORMATION_SCHEMA . `INNODB_BUFFER_PAGE` LIMIT 1;
        SELECT * FROM INFORMATION_SCHEMA . `GLOBAL_TEMPORARY_TABLES` LIMIT 1;

I don't know if the first query is anyhow important or it's there just for the right timing, I suspect the latter.

Anyway, it happens easily with the provided grammar, I expect you shouldn't have a problem reproducing it.

Verified on PS 5.5.29 using the grammar provided.

PS 5.6.10 just crashed with this grammar:

...
stack_bottom = 7f4a54967e38 thread_stack 0x40000
/home/openxs/dbs/p5.6/bin/mysqld(my_print_stacktrace+0x35)[0x930aa5]
/home/openxs/dbs/p5.6/bin/mysqld(handle_fatal_signal+0x42b)[0x66036b]
/lib64/libpthread.so.0[0x3ffac0eeb0]
/home/openxs/dbs/p5.6/bin/mysqld[0x9e146a]
/home/openxs/dbs/p5.6/bin/mysqld[0x72548b]
/home/openxs/dbs/p5.6/bin/mysqld[0x7257f5]
/home/openxs/dbs/p5.6/bin/mysqld(_Z24get_schema_tables_resultP4JOIN23enum_schema_table_state+0x2eb)[0x72e26b]
/home/openxs/dbs/p5.6/bin/mysqld(_ZN4JOIN14prepare_resultEPP4ListI4ItemE+0xad)[0x70cedd]
/home/openxs/dbs/p5.6/bin/mysqld(_ZN4JOIN4execEv+0x11c)[0x6c081c]
/home/openxs/dbs/p5.6/bin/mysqld(_Z12mysql_selectP3THDP10TABLE_LISTjR4ListI4ItemEPS4_P10SQL_I_ListI8st_orderESB_S7_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x310)[0x714bc0]
/home/openxs/dbs/p5.6/bin/mysqld(_Z13handle_selectP3THDP13select_resultm+0x203)[0x715573]
/home/openxs/dbs/p5.6/bin/mysqld[0x6e27ad]
/home/openxs/dbs/p5.6/bin/mysqld(_Z21mysql_execute_commandP3THD+0x1c03)[0x6eaeb3]
/home/openxs/dbs/p5.6/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x428)[0x6f19c8]
/home/openxs/dbs/p5.6/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x147e)[0x6f2eee]
/home/openxs/dbs/p5.6/bin/mysqld(_Z10do_commandP3THD+0x176)[0x6f3746]
/home/openxs/dbs/p5.6/bin/mysqld(_Z24do_handle_one_connectionP3THD+0x195)[0x6b81e5]
/home/openxs/dbs/p5.6/bin/mysqld(handle_one_connection+0x42)[0x6b8242]
/home/openxs/dbs/p5.6/bin/mysqld(pfs_spawn_thread+0x136)[0x9c2696]
/lib64/libpthread.so.0[0x3ffac06ccb]
/lib64/libc.so.6(clone+0x6d)[0x3ffa8e0c2d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f4a14004d70): SELECT * FROM INFORMATION_SCHEMA . `GLOBAL_TEMPORARY_TABLES` LIMIT 1
Connection ID (thread ID): 8
Status: NOT_KILLED
...

Valerii -

Could you please post a GDB-resolved stacktrace for the 5.6 crash?

I was not able to get crash or assertion on PS 5.1.x so far though.

Roel Van de Paar (roel11) wrote :

Reproduced during 5.6. QA testing.

Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :
summary: - Assertion `table->in_use == _current_thd()' fails on concurrent ALTER
+ field.cc:3822: virtual longlong Field_long::val_int(): Assertion
+ `table->in_use == _current_thd()' failed | Failure on concurrent ALTER
TABLE and SELECT from I_S
Roel Van de Paar (roel11) wrote :

New issue?

Download full text (6.0 KiB)

Thread 45 (LWP 26461):
+bt
#0 0x0000003fde20b43c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x0000000000a50fe3 in os_cond_wait (fast_mutex=0x3836360, cond=0x38363a0) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/os/os0sync.cc:214
#2 os_event_wait_low (event=0x3836360, reset_sig_count=165) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/os/os0sync.cc:610
#3 0x0000000000aee651 in sync_array_wait_event (arr=0x32204a0, index=4) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/sync/sync0arr.cc:424
#4 0x0000000000af2e3c in mutex_spin_wait (mutex=0x3836268, file_name=0xda5e28 "/bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/handler/ha_innodb.cc", line=4705) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/sync/sync0sync.cc:583
#5 0x00000000009e75bb in mutex_enter_func (line=4705, file_name=0xda5e28 "/bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/handler/ha_innodb.cc", mutex=0x3836268) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/include/sync0sync.ic:220
#6 pfs_mutex_enter_func (line=4705, file_name=0xda5e28 "/bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/handler/ha_innodb.cc", mutex=0x3836268) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/include/sync0sync.ic:251
#7 innobase_build_index_translation (share=0x7f8f68073f20, ib_table=0x7f8f680651d8, table=0x7f8f680776d0) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/handler/ha_innodb.cc:4705
#8 ha_innobase::open (this=0x7f8f7c087d70, name=0x7f9000ec5b90 "./test/#sql-63a4_20#P#p0", mode=<optimized out>, test_if_locked=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/handler/ha_innodb.cc:5183
#9 0x00000000005b547a in handler::ha_open (this=0x7f8f7c087d70, table_arg=0x7f8f680776d0, name=0x7f9000ec5b90 "./test/#sql-63a4_20#P#p0", mode=7, test_if_locked=2) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/handler.cc:2473
#10 0x00000000005b7671 in handler::clone (this=0x7f8f6807d390, name=0x7f9000ec5b90 "./test/#sql-63a4_20#P#p0", mem_root=0x3a2f1b8) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/handler.cc:2389
#11 0x00000000009d8d8e in ha_innobase::clone (this=0x7f8f6807d390, name=0x7f9000ec5b90 "./test/#sql-63a4_20#P#p0", mem_root=0x3a2f1b8) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/handler/ha_innodb.cc:5352
#12 0x0000000000c4b3b7 in ha_partition::open (this=0x7f8f680589d8, name=0x7f8f680782d0 "./test/#sql-63a4_20", mode=1745284816, test_if_locked=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/ha_partition.cc:3243
#13 0x00000000005b547a in handler::ha_open (this=0x7f8f680589d8, table_arg=0x7f8f680776d0, name=0x7f8f680782d0 "./test/#sql-63a4_20", mode=7, test_if_locked=1026) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/handler.cc:2473
#14 0x0000000000c469e8 in ha_partition::clone (this=0x7f8f6807cd20, name=0x7f8f680782d0 "./test/#sql-63a4_20", mem_root=0x3a2f1b8) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/ha_partition.cc:3412
#15 0x00000000007485ad in store_temporary_table_record (thd=0x3a2bbb0, table=0x7f8f7c07d0c0, tmp_table=0x7f8f680776d0, db=<optimized ...

Read more...

Download full text (4.0 KiB)

Thread 1 (LWP 26471):
+bt
#0 0x0000003fde20c69c in pthread_kill () from /lib64/libpthread.so.0
#1 0x000000000068302e in handle_fatal_signal (sig=6) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/signal_handler.cc:251
#2 <signal handler called>
#3 0x0000003fdde328a5 in raise () from /lib64/libc.so.6
#4 0x0000003fdde34085 in abort () from /lib64/libc.so.6
#5 0x0000003fdde2ba1e in __assert_fail_base () from /lib64/libc.so.6
#6 0x0000003fdde2bae0 in __assert_fail () from /lib64/libc.so.6
#7 0x0000000000812f91 in Field_long::val_int (this=0x7f8f6807f140) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/field.cc:3822
#8 0x00000000009ea3fc in ha_innobase::write_row (this=0x7f8f6807d390, record=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/handler/ha_innodb.cc:6957
#9 0x00000000005b7b9f in handler::ha_write_row (this=0x7f8f6807d390, buf=0x7f8f6806eee8 "") at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/handler.cc:7414
#10 0x0000000000c4a3e9 in ha_partition::write_row (this=0x7f8f6807cd20, buf=0x7f8f6806eee8 "") at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/ha_partition.cc:3927
#11 0x00000000005b7b9f in handler::ha_write_row (this=0x7f8f6807cd20, buf=0x7f8f6806eee8 "") at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/handler.cc:7414
#12 0x000000000076883b in copy_data_between_tables (from=0x7f8f680412b0, to=0x7f8f680776d0, create=..., ignore=false, order_num=0, order=0x7f8ffc35ce30, copied=0x7f8ffc35ea28, deleted=0x7f8ffc35ea20, keys_onoff=Alter_info::LEAVE_AS_IS, alter_ctx=0x7f8ffc35d040) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_table.cc:8974
#13 0x0000000000775732 in mysql_alter_table (thd=<optimized out>, new_db=0x7f8ffc35e810 "\340\260L\001", new_name=0x7f8f680776d0 "\250\177\ah\217\177", create_info=<optimized out>, table_list=0x7f8f68004e90, alter_info=0x7f8ffc35eb90, order_num=0, order=0x0, ignore=false) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_table.cc:8502
#14 0x0000000000776642 in mysql_recreate_table (thd=0x3a2bbb0, table_list=0x7f8f68004e90) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_table.cc:9093
#15 0x000000000087f1a1 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=0x3a2bbb0, tables=0x7f8ffc35f170, check_opt=0x3a2ed08, operator_name=0xd5ea14 "optimize", lock_type=TL_WRITE, open_for_modify=false, repair_table_use_frm=false, extra_open_options=0, prepare_func=0x0, operator_func=(int (handler::*)(handler * const, THD *, HA_CHECK_OPT *)) 0x5bde30 <handler::ha_optimize(THD*, st_ha_check_opt*)>, view_operator_func=0x0) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_admin.cc:783
#16 0x000000000087f82a in Sql_cmd_optimize_table::execute (this=<optimized out>, thd=0x3a2bbb0) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_admin.cc:1097
#17 0x00000000007152e6 in mysql_execute_command (thd=0x3a2bbb0) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_parse.cc:5132
#18 0x000000000071b8b8 in mysql_parse (thd=0x3a2bbb0, rawbuf=0x3a2df68 "p\234\065\001", length=<optimized out>, parser_state=<optimized out>) a...

Read more...

summary: field.cc:3822: virtual longlong Field_long::val_int(): Assertion
- `table->in_use == _current_thd()' failed | Failure on concurrent ALTER
- TABLE and SELECT from I_S
+ `table->in_use == _current_thd()' failed
tags: added: i-s-temp-tables
tags: added: xtradb
tags: added: qa
Roel Van de Paar (roel11) wrote :

Further to comment #12 (I assume that was an important thread in this story), I now have a crash with a backtrace that looks very similar to the non-crashing stack posted in #12). Logged this as bug 1205200 - but it may be closely related, or even a duplicate.

MTR testcase for 5.6. Does not fail at exact same place, but the assert is the same, I believe it's the same root cause (THD::in_use reset in I_S query)

=== modified file 'Percona-Server/sql/sql_show.cc'
--- Percona-Server/sql/sql_show.cc 2013-06-27 15:15:35 +0000
+++ Percona-Server/sql/sql_show.cc 2013-07-30 15:01:06 +0000
@@ -4039,6 +4045,7 @@

       THD *t= tmp->in_use;
       tmp->in_use= thd;
+ DEBUG_SYNC(thd, "after_global_temp_table_in_use_reset");

       if (store_temporary_table_record(thd_item, tables->table, tmp,
                                        thd->lex->select_lex.db)) {

# Test for bug 1113388 (field.cc:3822: virtual longlong Field_long::val_int(): Assertion `table->in_use == _current_thd()' failed)

--source include/have_innodb.inc
--source include/have_debug_sync.inc

--disable_warnings
DROP TABLE IF EXISTS t1;
--enable_warnings

CREATE TABLE t1(a INT PRIMARY KEY) ENGINE=InnoDB;
INSERT INTO t1 VALUES (1);

SET DEBUG_SYNC= 'after_copy_data_between_tables_one_row SIGNAL optimize_ready WAIT_FOR i_s_stopped';
send OPTIMIZE TABLE t1;

connect (conn2,localhost,root,,);
connection conn2;

SET DEBUG_SYNC= 'now WAIT_FOR optimize_ready';
SET DEBUG_SYNC= 'after_global_temp_table_in_use_reset SIGNAL i_s_stopped WAIT_FOR optimize_completed';
send SELECT COUNT(*) FROM INFORMATION_SCHEMA.GLOBAL_TEMPORARY_TABLES;

connection default;
reap;
SET DEBUG_SYNC= 'now SIGNAL optimize_completed';

connection conn2;
reap;

disconnect conn2;
connection default;

DROP TABLE t1;

The temporary table->in_use patching with the THD of the I_S query is causing this. It's been present since day one and it has been made redundant by cloning the temp table handler instead of calling info on it directly.

5.1 does not include such temp tables in the temp table list, making them invisible to GLOBAL_TEMPORARY_TABLES queries. Fixing the code anyway in case the is some other code path that triggers it.

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-629

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers