| Bug #57248 | abort in btr_pcur_store_position | ||
|---|---|---|---|
| Submitted: | 5 Oct 2010 13:39 | Modified: | 11 Oct 2010 12:55 |
| Reporter: | Matthias Leich | Email Updates: | |
| Status: | Duplicate | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S2 (Serious) |
| Version: | mysql-5.5-runtime | OS: | Any |
| Assigned to: | Assigned Account | CPU Architecture: | Any |
| Tags: | Abort, RQG | ||
[6 Oct 2010 7:45]
Jon Olav Hauglid
This bug really hurts RQG testing.
[6 Oct 2010 14:02]
Jon Olav Hauglid
Also repeatable with mysql-5.5-bugteam.
[7 Oct 2010 10:31]
Matthias Leich
RQG sql grammar
Attachment: 57248.yy (application/octet-stream, text), 887 bytes.
[7 Oct 2010 11:14]
Matthias Leich
My command line is:
perl runall.pl \
--gendata=conf/runtime/WL5004_data.zz \
--duration=900 \
--queries=10000 \
--reporter=Deadlock,Backtrace,Shutdown \
--threads=32 \
--basedir=<path to MySQL tree> \
--mysqld=--lock-wait-timeout=1 \
--mysqld=--innodb-lock-wait-timeout=1 \
--mysqld=--log-output=file \
--grammar=./57248.yy \
--vardir=<use of tmpfs like /dev/shm/var_1 is recommended> \
--seed=877 | tee prt
The abort occurs on my notebook after some minutes.
This is more time than I need with the original grammar
but the shrinked grammar generates far way less different
SQL statements and scenarios.
It would be nice if my shrinked grammar would be smaller
but this is all I have after days of automatic and one
day manual simplification.
There are a lot stress factors
- LOCK TABLE ... READ
- two tables get frequent created within the same schema
but we have also a frequent drop of this schema
- use of transactions
- both tables are "connected" via a trigger
This is a mad administrator/production scenario but
unfortunately it harms RQG testing a lot.
Experiments with command line like above but the
original WL5004_* grammar
(Information about observations is only 90% correct,
don't remember everything.)
--------------------------------------------------------
- command line like above
High likelihood (> 50% to hit this bug)
- command line like above but server start up option
default-storage-engine=MyISAM
This and also a lot other issues which were observed
before the massive InnoDB related changes do not
show up.
- command line like above but use of triggers disabled in grammar
Likelihood to hit the current bug decreases significant
but sometimes the abort shows up.
=> Assumption: The DML statements within the trigger
and most probably their extreme frequent execution
seem to be the essential.
[10 Oct 2010 11:24]
Victor Kirkebo
Please take a look at bug#57345. I think it's the same problem. There's a couple of simple test cases attached to that bug report.
[11 Oct 2010 10:43]
Matthias Leich
Some note:
I made today 11. October
bzr pull mysql-5.5-runtime
bzr merge --weave bzr+ssh://mleich@bk-internal.mysql.com/bzrroot/server/mysql-5.5-innodb
No conflicts
make -j6
and executed my replay testcase.
Result
Thread 1 (process 12027):
#0 0x00007fd9f47f6ce6 in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000a51f2f in my_write_core (sig=11) at /work2/repo/mysql-5.5-runtime/mysys/stacktrace.c:328
#2 0x0000000000549af4 in handle_segfault (sig=11) at /work2/repo/mysql-5.5-runtime/sql/mysqld.cc:2511
#3 <signal handler called>
#4 0x00000000008c6543 in trx_print (f=0x7fd9f3b2d860, trx=0x4, max_query_len=0) at /work2/repo/mysql-5.5-runtime/storage/innobase/trx/trx0trx.c:1650
#5 0x00000000008e0952 in btr_pcur_restore_position_func (latch_mode=1, cursor=0x7fd9e000ac98, file=0xc1e860 "/work2/repo/mysql-5.5-runtime/storage/innobase/row/row0sel.c", line=3057, mtr=0x41c568d0)
at /work2/repo/mysql-5.5-runtime/storage/innobase/btr/btr0pcur.c:233
#6 0x00000000008a3718 in sel_restore_position_for_mysql (same_user_rec=0x41c56da0, latch_mode=1, pcur=0x7fd9e000ac98, moves_up=1, mtr=0x41c568d0) at /work2/repo/mysql-5.5-runtime/storage/innobase/row/row0sel.c:3057
#7 0x00000000008a61b8 in row_search_for_mysql (buf=0x7fd9e000a3e0 "ÿ", mode=1, prebuilt=0x7fd9e000aa28, match_mode=0, direction=0) at /work2/repo/mysql-5.5-runtime/storage/innobase/row/row0sel.c:4566
#8 0x00000000008853f1 in ha_innobase::index_read (this=0x7fd9e000a1e0, buf=0x7fd9e000a3e0 "ÿ", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /work2/repo/mysql-5.5-runtime/storage/innobase/handler/ha_innodb.cc:5640
#9 0x000000000087beda in ha_innobase::index_first (this=0x7fd9e000a1e0, buf=0x7fd9e000a3e0 "ÿ") at /work2/repo/mysql-5.5-runtime/storage/innobase/handler/ha_innodb.cc:5942
#10 0x0000000000885084 in ha_innobase::rnd_next (this=0x7fd9e000a1e0, buf=0x7fd9e000a3e0 "ÿ") at /work2/repo/mysql-5.5-runtime/storage/innobase/handler/ha_innodb.cc:6039
#11 0x000000000082aaf8 in rr_sequential (info=0x41c575f0) at /work2/repo/mysql-5.5-runtime/sql/records.cc:446
#12 0x000000000084dcd1 in mysql_delete (thd=0x1d86030, table_list=0x7fd9e009c930, conds=0x7fd9e0013408, order_list=0x7fd9e009bf98, limit=1, options=0) at /work2/repo/mysql-5.5-runtime/sql/sql_delete.cc:297
#13 0x00000000005e0886 in mysql_execute_command (thd=0x1d86030) at /work2/repo/mysql-5.5-runtime/sql/sql_parse.cc:2916
#14 0x0000000000832a33 in sp_instr_stmt::exec_core (this=0x7fd9e0013600, thd=0x1d86030, nextp=0x41c58b48) at /work2/repo/mysql-5.5-runtime/sql/sp_head.cc:3138
#15 0x0000000000832c56 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7fd9e0013640, thd=0x1d86030, nextp=0x41c58b48, open_tables=false, instr=0x7fd9e0013600) at /work2/repo/mysql-5.5-runtime/sql/sp_head.cc:2939
#16 0x0000000000836c20 in sp_instr_stmt::execute (this=0x7fd9e0013600, thd=0x1d86030, nextp=0x41c58b48) at /work2/repo/mysql-5.5-runtime/sql/sp_head.cc:3075
#17 0x000000000083730b in sp_head::execute (this=0x7fd9e009aeb0, thd=0x1d86030) at /work2/repo/mysql-5.5-runtime/sql/sp_head.cc:1409
#18 0x0000000000839095 in sp_head::execute_trigger (this=0x7fd9e009aeb0, thd=0x1d86030, db_name=0x7fd9e0024ad8, table_name=0x7fd9e0024ae8, grant_info=0x7fd9e0006040) at /work2/repo/mysql-5.5-runtime/sql/sp_head.cc:1706
#19 0x0000000000664827 in Table_triggers_list::process_triggers (this=0x7fd9e0005f90, thd=0x1d86030, event=TRG_EVENT_INSERT, time_type=TRG_ACTION_BEFORE, old_row_is_record1=true) at /work2/repo/mysql-5.5-runtime/sql/sql_trigger.cc:2046
#20 0x000000000058c2b8 in fill_record_n_invoke_before_triggers (thd=0x1d86030, ptr=0x7fd9e0005170, values=@0x1d88418, ignore_errors=true, triggers=0x7fd9e0005f90, event=TRG_EVENT_INSERT) at /work2/repo/mysql-5.5-runtime/sql/sql_base.cc:8521
#21 0x00000000005c4e01 in select_insert::store_values (this=0x1df3218, values=@0x1d88418) at /work2/repo/mysql-5.5-runtime/sql/sql_insert.cc:3483
#22 0x00000000005c82f0 in select_insert::send_data (this=0x1df3218, values=@0x1d88418) at /work2/repo/mysql-5.5-runtime/sql/sql_insert.cc:3419
#23 0x000000000062fa69 in JOIN::exec (this=0x7fd9e00558f0) at /work2/repo/mysql-5.5-runtime/sql/sql_select.cc:1854
#24 0x000000000062c92f in mysql_select (thd=0x1d86030, rref_pointer_array=0x1d884e0, tables=0x0, wild_num=0, fields=@0x1d88418, conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=3491498496, result=0x1df3218,
unit=0x1d87cf0, select_lex=0x1d88310) at /work2/repo/mysql-5.5-runtime/sql/sql_select.cc:2558
#25 0x0000000000631c6f in handle_select (thd=0x1d86030, lex=0x1d87c40, result=0x1df3218, setup_tables_done_option=1073741824) at /work2/repo/mysql-5.5-runtime/sql/sql_select.cc:296
#26 0x00000000005e067e in mysql_execute_command (thd=0x1d86030) at /work2/repo/mysql-5.5-runtime/sql/sql_parse.cc:2871
#27 0x00000000005e53c5 in mysql_parse (thd=0x1d86030, rawbuf=0x1df22e0 "INSERT INTO testdb_S.t1_base1_N SELECT 1 , 1 , 1", length=48, parser_state=0x41c5a9c0) at /work2/repo/mysql-5.5-runtime/sql/sql_parse.cc:5489
#28 0x00000000005e5bd5 in dispatch_command (command=COM_QUERY, thd=0x1d86030, packet=0x1dee2c1 "INSERT INTO testdb_S.t1_base1_N SELECT 1 , 1 , 1", packet_length=48) at /work2/repo/mysql-5.5-runtime/sql/sql_parse.cc:1029
#29 0x00000000005e6fc3 in do_command (thd=0x1d86030) at /work2/repo/mysql-5.5-runtime/sql/sql_parse.cc:769
#30 0x00000000006ae24f in do_handle_one_connection (thd_arg=0x1d86030) at /work2/repo/mysql-5.5-runtime/sql/sql_connect.cc:745
#31 0x00000000006ae341 in handle_one_connection (arg=0x1d86030) at /work2/repo/mysql-5.5-runtime/sql/sql_connect.cc:684
#32 0x00007fd9f47f2040 in start_thread () from /lib64/libpthread.so.0
#33 0x00007fd9f38ad08d in clone () from /lib64/libc.so.6
#34 0x0000000000000000 in ?? ()
[11 Oct 2010 10:47]
Jon Olav Hauglid
I'm running RQG tests on mysql-5.5-innodb (revno 3176).
I haven't seen the crash originally reported here yet, but I did get
a similar crash:
#5 0x00007fdbdf9326b0 in abort () at abort.c:92
#6 0x0000000000911cfe in btr_pcur_restore_position_func (latch_mode=1, cursor=0x7fdbc80a1738,
file=0xc9ea00 "/export/home/x/mysql-5.5-innodb/storage/innobase/row/row0sel.c", line=3063,
mtr=0x7fdbcee79f70) at /export/home/x/mysql-5.5-innodb/storage/innobase/btr/btr0pcur.c:236
#7 0x00000000008cb682 in sel_restore_position_for_mysql (same_user_rec=0x7fdbcee79ed8,
latch_mode=1, pcur=0x7fdbc80a1738, moves_up=1, mtr=0x7fdbcee79f70)
at /export/home/x/mysql-5.5-innodb/storage/innobase/row/row0sel.c:3063
#8 0x00000000008ce4b9 in row_search_for_mysql (buf=0x7fdbc80d5510 "\377", mode=1,
prebuilt=0x7fdbc8040b48, match_mode=0, direction=0)
at /export/home/x/mysql-5.5-innodb/storage/innobase/row/row0sel.c:4572
#9 0x00000000008a1187 in ha_innobase::index_read (this=0x7fdbc80d5310, buf=0x7fdbc80d5510 "\377",
key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY)
at /export/home/x/mysql-5.5-innodb/storage/innobase/handler/ha_innodb.cc:5640
#10 0x00000000008a1b52 in ha_innobase::index_first (this=0x7fdbc80d5310, buf=0x7fdbc80d5510 "\377")
at /export/home/x/mysql-5.5-innodb/storage/innobase/handler/ha_innodb.cc:5942
#11 0x00000000008a1d43 in ha_innobase::rnd_next (this=0x7fdbc80d5310, buf=0x7fdbc80d5510 "\377")
at /export/home/x/mysql-5.5-innodb/storage/innobase/handler/ha_innodb.cc:6039
#12 0x000000000083cae5 in rr_sequential (info=0x7fdbcee7a640)
at /export/home/x/mysql-5.5-innodb/sql/records.cc:446
#13 0x0000000000862539 in mysql_delete (thd=0x7fdbc8135ad0, table_list=0x23d5398, conds=0x23d5f48,
order_list=0x7fdbc8137e90, limit=18446744073709551615, options=0)
at /export/home/x/mysql-5.5-innodb/sql/sql_delete.cc:297
#14 0x00000000005c5cd3 in mysql_execute_command (thd=0x7fdbc8135ad0)
at /export/home/x/mysql-5.5-innodb/sql/sql_parse.cc:2986
#15 0x00000000005ccdc0 in mysql_parse (thd=0x7fdbc8135ad0,
rawbuf=0x23d5230 "DELETE FROM testdb_S . t1_merge1_S WHERE `pk` + SLEEP( 0.5 * 0.77 * 1 ) = 7---Type <return> to continue, or q <return> to quit---
", length=78, parser_state=0x7fdbcee7c110) at /export/home/x/mysql-5.5-innodb/sql/sql_parse.cc:5554
[11 Oct 2010 11:18]
Jon Olav Hauglid
I'm also seen the segfault Matthias posted [11 Oct 12:43] directly in 5.5-innodb.
[11 Oct 2010 12:55]
Jimmy Yang
Confirm it is dup of #57345. <joh> jyang: 55 mins now without problems, so I'd say the test was successful.
Description: The abort happens in storage/innobase/btr/btr0pcur.c:101 btr_pcur_store_position( /*====================*/ btr_pcur_t* cursor, /*!< in: persistent cursor */ mtr_t* mtr) /*!< in: mtr */ { page_cur_t* page_cursor; buf_block_t* block; rec_t* rec; dict_index_t* index; page_t* page; ulint offs; ut_a(cursor->pos_state == BTR_PCUR_IS_POSITIONED); <----- ut_ad(cursor->latch_mode != BTR_NO_LATCHES); The abort was found when testing with RQG - 32 threads - derivate of the WL5004_* grammar heavy concurrent DML and DDL Result on mysql-5.5-runtime revno: 3152 2010-10-04 --------------------------- Thread 1 (process 16106): #0 0x00007fdf0906ace6 in pthread_kill () from /lib64/libpthread.so.0 #1 0x0000000000a48efb in my_write_core (sig=6) at /work2/repo/mysql-5.5-runtime/mysys/stacktrace.c:328 #2 0x00000000005483d1 in handle_segfault (sig=6) at /work2/repo/mysql-5.5-runtime/sql/mysqld.cc:2507 #3 <signal handler called> #4 0x00007fdf080805c5 in raise () from /lib64/libc.so.6 #5 0x00007fdf08081bb3 in abort () from /lib64/libc.so.6 #6 0x00000000008d7523 in btr_pcur_store_position (cursor=0x2099998, mtr=0x479fc620) at /work2/repo/mysql-5.5-runtime/storage/innobase/btr/btr0pcur.c:101 #7 0x000000000089d1f5 in row_search_for_mysql (buf=0x1e0eb50 "ÿ", mode=1, prebuilt=0x1f43ae8, match_mode=0, direction=0) at /work2/repo/mysql-5.5-runtime/storage/innobase/row/row0sel.c:4552 #8 0x000000000087c4b1 in ha_innobase::index_read (this=0x1e0e950, buf=0x1e0eb50 "ÿ", key_ptr=0x1e82b58 "", key_len=4, find_flag=HA_READ_AFTER_KEY) at /work2/repo/mysql-5.5-runtime/storage/innobase/handler/ha_innodb.cc:5640 #9 0x000000000073147c in handler::index_read_map (this=0x1e0e950, buf=0x1e0eb50 "ÿ", key=0x1e82b58 "", keypart_map=1, find_flag=HA_READ_AFTER_KEY) at /work2/repo/mysql-5.5-runtime/sql/handler.h:1487 #10 0x000000000072ab67 in handler::read_range_first (this=0x1e0e950, start_key=0x1e55870, end_key=0x0, eq_range_arg=false, sorted=false) at /work2/repo/mysql-5.5-runtime/sql/handler.cc:4243 #11 0x000000000072ad76 in handler::read_multi_range_first (this=0x1e0e950, found_range_p=0x479fce10, ranges=0x1e55870, range_count=1, sorted=false, buffer=0x0) at /work2/repo/mysql-5.5-runtime/sql/handler.cc:4117 #12 0x0000000000804a2e in QUICK_RANGE_SELECT::get_next (this=0x1e0f230) at /work2/repo/mysql-5.5-runtime/sql/opt_range.cc:8692 #13 0x00000000008222b5 in rr_quick (info=0x479fd450) at /work2/repo/mysql-5.5-runtime/sql/records.cc:335 #14 0x000000000084532d in mysql_delete (thd=0x7fdef814c0e0, table_list=0x2022e90, conds=0x2457ee8, order_list=0x20224f8, limit=1, options=4194304) at /work2/repo/mysql-5.5-runtime/sql/sql_delete.cc:297 .... How to repeat: I will come up with a replay test case as soon as possible.