[MDEV-3853] Deadlock or assertion ret < srv_page_size failure on concurrent ALTER TABLE and SELECT from I_S - Jira

XML

Word

Printable

Details

Type: Bug
Status: Open (View Workflow)
Priority: Major
Resolution: Unresolved
Affects Version/s: 10.0.1, 5.5.29, 5.3.10, 5.3.11, 5.2.13, 5.1.66
Fix Version/s: None
Component/s: None
Labels:
None

Description

It's a recent regression which seems to have appeared after merge from Percona-Server 5.1.66-rel14.1.
A bug for Percona Server hasn't been filed yet as on some reason it's less reliably reproducible there, although I've seen it once.

On MariaDB, reproducible starting from maria/5.1 revno 3163, maria/5.3 revno 3592.

+----+------+-----------------+------+---------+------+-------------------+-----------------------------------------------------------------+----------+

| Id | User | Host            | db   | Command | Time | State             | Info                                                            | Progress |

+----+------+-----------------+------+---------+------+-------------------+-----------------------------------------------------------------+----------+

|  2 | root | 127.0.0.1:59063 | test | Sleep   |  115 |                   | NULL                                                            |    0.000 |

|  7 | root | 127.0.0.1:59068 | test | Query   |  106 | copy to tmp table | ALTER TABLE `E` ADD COLUMN o INTEGER                            |   54.524 |

|  8 | root | 127.0.0.1:59069 | test | Query   |  105 | executing         | SELECT * FROM INFORMATION_SCHEMA . `INNODB_BUFFER_PAGE` LIMIT 1 |    0.000 |

|  9 | root | 127.0.0.1:59070 | test | Query   |  105 | executing         | SELECT * FROM INFORMATION_SCHEMA . `INNODB_BUFFER_PAGE` LIMIT 1 |    0.000 |

| 13 | root | 127.0.0.1:59074 | NULL | Query   |    0 | NULL              | show full processlist                                           |    0.000 |

+----+------+-----------------+------+---------+------+-------------------+-----------------------------------------------------------------+----------+

Stacks of the three threads executing statements:

Thread 4 (Thread 0x7f818aa0f710 (LWP 3794)):

#0  0x00007f81a940e39c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0

#1  0x0000000000bdb882 in safe_cond_wait (cond=0x7f81990945f0, mp=0x7f8199094540,

    file=0xdfaa60 "os/os0sync.c", line=210) at thr_mutex.c:498

#2  0x0000000000ae990b in os_cond_wait (cond=0x7f81990945f0, mutex=0x7f8199094540)

    at os/os0sync.c:210

#3  0x0000000000aea131 in os_event_wait_low (event=0x7f8199094540, reset_sig_count=26)

    at os/os0sync.c:636

#4  0x0000000000b2b9d6 in sync_array_wait_event (arr=0x7f8198008e90, index=0)

    at sync/sync0arr.c:451

#5  0x0000000000b2cd93 in rw_lock_x_lock_wait (lock=0x7f818ffedd70,

    file_name=0xe05040 "trx/trx0rec.c", line=1270) at sync/sync0rw.c:520

#6  0x0000000000b2ce72 in rw_lock_x_lock_low (lock=0x7f818ffedd70, pass=0,

    file_name=0xe05040 "trx/trx0rec.c", line=1270) at sync/sync0rw.c:563

#7  0x0000000000b2cf47 in rw_lock_x_lock_func (lock=0x7f818ffedd70, pass=0,

    file_name=0xe05040 "trx/trx0rec.c", line=1270) at sync/sync0rw.c:622

#8  0x0000000000b62caf in buf_page_get_gen (space=0, zip_size=0, offset=46, rw_latch=2, guess=0x0,

    mode=10, file=0xe05040 "trx/trx0rec.c", line=1270, mtr=0x7f818aa0b060) at buf/buf0buf.c:2230

#9  0x0000000000b3454a in trx_undo_report_row_operation (flags=0, op_type=1, thr=0x7f81992cc630,

    index=0x7f819930b518, clust_entry=0x7f8199308df8, update=0x0, cmpl_info=0, rec=0x0,

    roll_ptr=0x7f818aa0b5c0) at trx/trx0rec.c:1268

#10 0x0000000000b51bed in btr_cur_ins_lock_and_undo (flags=0, cursor=0x7f818aa0bbf0,

    entry=0x7f8199308df8, thr=0x7f81992cc630, mtr=0x7f818aa0b740, inherit=0x7f818aa0b640)

    at btr/btr0cur.c:1083

#11 0x0000000000b52092 in btr_cur_optimistic_insert (flags=0, cursor=0x7f818aa0bbf0,

    entry=0x7f8199308df8, rec=0x7f818aa0bbe8, big_rec=0x7f818aa0bbe0, n_ext=0, thr=0x7f81992cc630,

    mtr=0x7f818aa0b740) at btr/btr0cur.c:1284

#12 0x0000000000b06c08 in row_ins_index_entry_low (mode=2, index=0x7f819930b518,

    entry=0x7f8199308df8, n_ext=0, thr=0x7f81992cc630) at row/row0ins.c:2184

#13 0x0000000000b07053 in row_ins_index_entry (index=0x7f819930b518, entry=0x7f8199308df8,

    n_ext=0, foreign=1, thr=0x7f81992cc630) at row/row0ins.c:2296

#14 0x0000000000b07295 in row_ins_index_entry_step (node=0x7f8199451070, thr=0x7f81992cc630)

    at row/row0ins.c:2381

#15 0x0000000000b074e0 in row_ins (node=0x7f8199451070, thr=0x7f81992cc630) at row/row0ins.c:2513

#16 0x0000000000b076f3 in row_ins_step (thr=0x7f81992cc630) at row/row0ins.c:2623

#17 0x0000000000b0d460 in row_insert_for_mysql (mysql_rec=0x7f8199307230 "\f\374\210\003",

    prebuilt=0x7f819947c958) at row/row0mysql.c:1168

#18 0x0000000000aafe21 in ha_innobase::write_row (this=0x7f819944ff40,

    record=0x7f8199307230 "\f\374\210\003") at handler/ha_innodb.cc:5649

#19 0x0000000000862b85 in handler::ha_write_row (this=0x7f819944ff40,

    buf=0x7f8199307230 "\f\374\210\003") at handler.cc:4978

#20 0x0000000000890d3f in copy_data_between_tables (thd=0x7f8199297e38, from=0x7f818400c768,

    to=0x7f81992a9428, create=..., ignore=false, order_num=0, order=0x0, copied=0x7f818aa0db30,

    deleted=0x7f818aa0db28, keys_onoff=LEAVE_AS_IS, error_if_not_empty=false) at sql_table.cc:8118

#21 0x000000000088f000 in mysql_alter_table (thd=0x7f8199297e38, new_db=0x1c19148 "test",

    new_name=0x1c18d18 "E", create_info=0x7f818aa0e100, table_list=0x1c18d50,

    alter_info=0x7f818aa0e200, order_num=0, order=0x0, ignore=false, require_online=false)

    at sql_table.cc:7540

#22 0x00000000006e4002 in mysql_execute_command (thd=0x7f8199297e38) at sql_parse.cc:2974

#23 0x00000000006edc50 in mysql_parse (thd=0x7f8199297e38,

    rawbuf=0x1c18c50 "ALTER TABLE `E` ADD COLUMN o INTEGER", length=36,

    found_semicolon=0x7f818aa0ec98) at sql_parse.cc:6158

#24 0x00000000006dfa90 in dispatch_command (command=COM_QUERY, thd=0x7f8199297e38,

    packet=0x7f81992dbe59 "ALTER TABLE `E` ADD COLUMN o INTEGER", packet_length=36)

    at sql_parse.cc:1228

#25 0x00000000006dedc4 in do_command (thd=0x7f8199297e38) at sql_parse.cc:923

#26 0x00000000006dbc12 in handle_one_connection (arg=0x7f8199297e38) at sql_connect.cc:1218

#27 0x00007f81a9409a4f in start_thread () from /lib64/libpthread.so.0

#28 0x00007f81a87f382d in clone () from /lib64/libc.so.6

#29 0x0000000000000000 in ?? ()

Thread 3 (Thread 0x7f818a9c7710 (LWP 3796)):

#0  0x00007f81a940e39c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0

#1  0x0000000000bdb882 in safe_cond_wait (cond=0x7f8199086bf0, mp=0x7f8199086b40,

    file=0xdfaa60 "os/os0sync.c", line=210) at thr_mutex.c:498

#2  0x0000000000ae990b in os_cond_wait (cond=0x7f8199086bf0, mutex=0x7f8199086b40)

    at os/os0sync.c:210

#3  0x0000000000aea131 in os_event_wait_low (event=0x7f8199086b40, reset_sig_count=1)

    at os/os0sync.c:636

#4  0x0000000000b2b9d6 in sync_array_wait_event (arr=0x7f8198008e90, index=2)

    at sync/sync0arr.c:451

#5  0x0000000000b2d6a8 in mutex_spin_wait (mutex=0x7f818ffe65f8,

    file_name=0xe09b88 "./include/buf0buf.ic", line=347) at sync/sync0sync.c:621

#6  0x0000000000b2d22b in mutex_enter_func (mutex=0x7f818ffe65f8,

    file_name=0xe09b88 "./include/buf0buf.ic", line=347) at ./include/sync0sync.ic:221

#7  0x0000000000b5ee12 in buf_page_get_mutex_enter (bpage=0x7f818ffe6540)

    at ./include/buf0buf.ic:347

#8  0x0000000000ac72fc in i_s_innodb_fill_buffer_pool (thd=0x7f81992dfe98, tables=0x1ba1918)

    at handler/i_s.cc:5796

#9  0x0000000000ac74d7 in i_s_innodb_buffer_page_fill_table (thd=0x7f81992dfe98, tables=0x1ba1918)

    at handler/i_s.cc:5852

#10 0x00000000008b27ed in get_schema_tables_result (join=0x1e514e0,

    executed_place=PROCESSED_BY_JOIN_EXEC) at sql_show.cc:7089

#11 0x0000000000763e67 in JOIN::exec (this=0x1e514e0) at sql_select.cc:2225

#12 0x00000000007668fd in mysql_select (thd=0x7f81992dfe98, rref_pointer_array=0x7f81992e2b88,

    tables=0x1ba1918, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0,

    having=0x0, proc_param=0x0, select_options=2684635648, result=0x1ba3410, unit=0x7f81992e2428,

    select_lex=0x7f81992e2930) at sql_select.cc:2983

#13 0x000000000075d449 in handle_select (thd=0x7f81992dfe98, lex=0x7f81992e2388, result=0x1ba3410,

    setup_tables_done_option=0) at sql_select.cc:286

#14 0x00000000006eb275 in execute_sqlcom_select (thd=0x7f81992dfe98, all_tables=0x1ba1918)

    at sql_parse.cc:5157

#15 0x00000000006e2332 in mysql_execute_command (thd=0x7f81992dfe98) at sql_parse.cc:2290

#16 0x00000000006edc50 in mysql_parse (thd=0x7f81992dfe98,

    rawbuf=0x1ba1670 "SELECT * FROM INFORMATION_SCHEMA . `INNODB_BUFFER_PAGE` LIMIT 1", length=63,

    found_semicolon=0x7f818a9c6c98) at sql_parse.cc:6158

#17 0x00000000006dfa90 in dispatch_command (command=COM_QUERY, thd=0x7f81992dfe98,

    packet=0x7f81992e35c9 "SELECT * FROM INFORMATION_SCHEMA . `INNODB_BUFFER_PAGE` LIMIT 1",

    packet_length=63) at sql_parse.cc:1228

#18 0x00000000006dedc4 in do_command (thd=0x7f81992dfe98) at sql_parse.cc:923

#19 0x00000000006dbc12 in handle_one_connection (arg=0x7f81992dfe98) at sql_connect.cc:1218

#20 0x00007f81a9409a4f in start_thread () from /lib64/libpthread.so.0

#21 0x00007f81a87f382d in clone () from /lib64/libc.so.6

#22 0x0000000000000000 in ?? ()

Thread 2 (Thread 0x7f818a97f710 (LWP 3798)):

#0  0x00007f81a940e39c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0

#1  0x0000000000bdb882 in safe_cond_wait (cond=0x7f8198ab38e0, mp=0x7f8198ab3830,

    file=0xdfaa60 "os/os0sync.c", line=210) at thr_mutex.c:498

#2  0x0000000000ae990b in os_cond_wait (cond=0x7f8198ab38e0, mutex=0x7f8198ab3830)

    at os/os0sync.c:210

#3  0x0000000000aea131 in os_event_wait_low (event=0x7f8198ab3830, reset_sig_count=16)

    at os/os0sync.c:636

#4  0x0000000000b2b9d6 in sync_array_wait_event (arr=0x7f8198008e90, index=3)

    at sync/sync0arr.c:451

#5  0x0000000000b2d6a8 in mutex_spin_wait (mutex=0x1a8b5e0, file_name=0xdf407f "handler/i_s.cc",

    line=5792) at sync/sync0sync.c:621

#6  0x0000000000b2d22b in mutex_enter_func (mutex=0x1a8b5e0, file_name=0xdf407f "handler/i_s.cc",

    line=5792) at ./include/sync0sync.ic:221

#7  0x0000000000ac72e6 in i_s_innodb_fill_buffer_pool (thd=0x7f81992f12f8, tables=0x1ea22e8)

    at handler/i_s.cc:5792

#8  0x0000000000ac74d7 in i_s_innodb_buffer_page_fill_table (thd=0x7f81992f12f8, tables=0x1ea22e8)

    at handler/i_s.cc:5852

#9  0x00000000008b27ed in get_schema_tables_result (join=0x7f818403d9b0,

    executed_place=PROCESSED_BY_JOIN_EXEC) at sql_show.cc:7089

#10 0x0000000000763e67 in JOIN::exec (this=0x7f818403d9b0) at sql_select.cc:2225

#11 0x00000000007668fd in mysql_select (thd=0x7f81992f12f8, rref_pointer_array=0x7f81992f3fe8,

    tables=0x1ea22e8, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0,

    having=0x0, proc_param=0x0, select_options=2684635648, result=0x1ea3de0, unit=0x7f81992f3888,

    select_lex=0x7f81992f3d90) at sql_select.cc:2983

#12 0x000000000075d449 in handle_select (thd=0x7f81992f12f8, lex=0x7f81992f37e8, result=0x1ea3de0,

    setup_tables_done_option=0) at sql_select.cc:286

#13 0x00000000006eb275 in execute_sqlcom_select (thd=0x7f81992f12f8, all_tables=0x1ea22e8)

    at sql_parse.cc:5157

#14 0x00000000006e2332 in mysql_execute_command (thd=0x7f81992f12f8) at sql_parse.cc:2290

#15 0x00000000006edc50 in mysql_parse (thd=0x7f81992f12f8,

    rawbuf=0x1ea2040 "SELECT * FROM INFORMATION_SCHEMA . `INNODB_BUFFER_PAGE` LIMIT 1", length=63,

    found_semicolon=0x7f818a97ec98) at sql_parse.cc:6158

#16 0x00000000006dfa90 in dispatch_command (command=COM_QUERY, thd=0x7f81992f12f8,

    packet=0x7f81992f4a29 "SELECT * FROM INFORMATION_SCHEMA . `INNODB_BUFFER_PAGE` LIMIT 1",

    packet_length=63) at sql_parse.cc:1228

#17 0x00000000006dedc4 in do_command (thd=0x7f81992f12f8) at sql_parse.cc:923

#18 0x00000000006dbc12 in handle_one_connection (arg=0x7f81992f12f8) at sql_connect.cc:1218

#19 0x00007f81a9409a4f in start_thread () from /lib64/libpthread.so.0

#20 0x00007f81a87f382d in clone () from /lib64/libc.so.6

#21 0x0000000000000000 in ?? ()

RQG grammar (mdev-3853.yy):

query:

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

thread1:

        ALTER TABLE _table ADD COLUMN _letter INTEGER |

        ALTER TABLE _table DROP COLUMN _letter ;

RQG command line, assuming you already have server up and running on port 3306:

 perl ./gentest.pl --threads=3 --duration=600 --queries=100M --grammar=mdev-3853.yy --engine=InnoDB --dsn=dbi:mysql:host=127.0.0.1:port=3306:user=root:database=test --gendata

The deadlock is reproducible on maria/5.1 revno 3180, maria/5.2 revno 3204, maria/5.3 revno 3619.
I didn't see the deadlock on 5.5 and 10.0, but I'm getting the assertion failure instead (not every time, but often enough):

130128  2:39:35  InnoDB: Assertion failure in thread 140451356055296 in file page0page.ic line 934

InnoDB: Failing assertion: ret < srv_page_size

#5  0x00007fbd5fc5fb0b in __GI_abort () at abort.c:92

#6  0x0000000000b6f3fa in page_get_data_size (page=0x7fbd4d6ac000 "") at 10.0-base/storage/xtradb/include/page0page.ic:934

#7  0x0000000000a688ea in i_s_innodb_buffer_pool_pages_index_fill (thd=0x43bb0b8, tables=0x7fbd3c1662d0, cond=0x0) at 10.0-base/storage/xtradb/handler/i_s.cc:6564

#8  0x000000000069ec20 in do_fill_table (thd=0x43bb0b8, table_list=0x7fbd3c1662d0, join_table=0x7fbd3c284260) at 10.0-base/sql/sql_show.cc:7914

#9  0x000000000069f032 in get_schema_tables_result (join=0x7fbd3c1f2330, executed_place=PROCESSED_BY_JOIN_EXEC) at 10.0-base/sql/sql_show.cc:8021

#10 0x0000000000648560 in JOIN::exec_inner (this=0x7fbd3c1f2330) at 10.0-base/sql/sql_select.cc:2414

#11 0x0000000000647bbd in JOIN::exec (this=0x7fbd3c1f2330) at 10.0-base/sql/sql_select.cc:2258

#12 0x000000000064b1e5 in mysql_select (thd=0x43bb0b8, rref_pointer_array=0x43be040, tables=0x7fbd3c1662d0, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2684619520, result=0x7fbd3c0a7890, unit=0x43bd698, select_lex=0x43bdd90) at 10.0-base/sql/sql_select.cc:3194

#13 0x0000000000641a76 in handle_select (thd=0x43bb0b8, lex=0x43bd5e0, result=0x7fbd3c0a7890, setup_tables_done_option=0) at 10.0-base/sql/sql_select.cc:368

#14 0x00000000006192b1 in execute_sqlcom_select (thd=0x43bb0b8, all_tables=0x7fbd3c1662d0) at 10.0-base/sql/sql_parse.cc:4765

#15 0x0000000000611941 in mysql_execute_command (thd=0x43bb0b8) at 10.0-base/sql/sql_parse.cc:2245

#16 0x000000000061bb1b in mysql_parse (thd=0x43bb0b8, rawbuf=0x7fbd3c1c0680 "SELECT * FROM INFORMATION_SCHEMA . `INNODB_BUFFER_POOL_PAGES_INDEX` LIMIT 1", length=75, parser_state=0x7fbd612f8540) at 10.0-base/sql/sql_parse.cc:5881

#17 0x000000000060ec8b in dispatch_command (command=COM_QUERY, thd=0x43bb0b8, packet=0x43c04d9 "SELECT * FROM INFORMATION_SCHEMA . `INNODB_BUFFER_POOL_PAGES_INDEX` LIMIT 1", packet_length=75) at 10.0-base/sql/sql_parse.cc:1070

#18 0x000000000060df42 in do_command (thd=0x43bb0b8) at 10.0-base/sql/sql_parse.cc:809

#19 0x0000000000722735 in do_handle_one_connection (thd_arg=0x43bb0b8) at 10.0-base/sql/sql_connect.cc:1253

#20 0x0000000000722120 in handle_one_connection (arg=0x43bb0b8) at 10.0-base/sql/sql_connect.cc:1168

#21 0x00007fbd60998efc in start_thread (arg=0x7fbd612f9700) at pthread_create.c:304

The stack trace is from

revision-id: sergii@pisem.net-20130124165225-gczln6zrzi4lz4bx

revno: 3485

branch-nick: 10.0-base

In all cases the server was built with BUILD/compile-pentium-valgrind-max-no-ndb.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

threads_5.5_90cb72127
223 kB
2018-07-10 16:40

Issue Links

relates to

MDEV-344 InnoDB: Assertion failure ret < srv_page_size in page0page.ic line 904

Closed

Activity

People

Assignee:: Unassigned

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 4 Start watching this issue

Dates

Created:: 2012-11-12 06:02

Updated:: 2023-12-14 10:05

Git Integration

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