Comment 7 for bug 1236696

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote : Re: InnoDB: Error: semaphore wait has lasted > 600 seconds. InnoDB: We intentionally crash the server, because it appears to be hung. 2013-10-07 16:29:16 7fc3ebfff700 InnoDB: Assertion failure in thread <nr> in file srv0srv.cc line 2124

The interesting thread is 37:

Thread 37 (LWP 15806):
+bt
#0 0x000000363720b43c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x0000000000ac4143 in os_cond_wait (fast_mutex=0x27e6c30, cond=0x27e6c70) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/os/os0sync.cc:214
#2 os_event_wait_low (event=0x27e6c30, reset_sig_count=264) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/os/os0sync.cc:610
#3 0x0000000000b63601 in sync_array_wait_event (arr=0x20e3460, index=0) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/sync/sync0arr.cc:433
#4 0x0000000000b653a6 in rw_lock_s_lock_spin (_lock=0x27e6a38, pass=0, priority_lock=true, high_priority=false, file_name=0xe1eb90 "/bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/btr/btr0sea.cc", line=954) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/sync/sync0rw.cc:537
#5 0x0000000000bc60ae in pfs_rw_lock_s_lock_func (line=954, file_name=0xe1eb90 "/bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/btr/btr0sea.cc", lock=0x27e6a38, pass=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/include/sync0rw.ic:1090
#6 btr_search_guess_on_hash (index=0x280c2b8, info=0x280c670, tuple=0x7fc2e40595d8, mode=4, latch_mode=2, cursor=0x7fc3f08230b0, has_search_latch=0, mtr=0x7fc3f08228c0) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/btr/btr0sea.cc:954
#7 0x0000000000bb7680 in btr_cur_search_to_nth_level (index=0x280c2b8, level=0, tuple=0x7fc2e40595d8, mode=4, latch_mode=2, cursor=0x7fc3f08230b0, has_search_latch=0, file=0xe04590 "/bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/row/row0ins.cc", line=2370, mtr=0x7fc3f08228c0) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/btr/btr0cur.cc:539
#8 0x0000000000b09b8e in row_ins_clust_index_entry_low (flags=0, mode=2, index=0x280c2b8, n_uniq=2, entry=0x7fc2e40595d8, n_ext=0, thr=0x7fc2e4050370) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/row/row0ins.cc:2370
#9 0x0000000000b0e825 in row_ins_clust_index_entry (index=0x280c2b8, entry=0x7fc2e40595d8, thr=0x7fc2e4050370, n_ext=0) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/row/row0ins.cc:2909
#10 0x0000000000b0ee07 in row_ins_index_entry (thr=0x7fc2e4050370, entry=0x7fc2e40595d8, index=0x280c2b8) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/row/row0ins.cc:3003
#11 row_ins_index_entry_step (thr=0x7fc2e4050370, node=0x7fc2e40d3d20) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/row/row0ins.cc:3080
#12 row_ins (thr=0x7fc2e4050370, node=0x7fc2e40d3d20) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/row/row0ins.cc:3220
#13 row_ins_step (thr=0x7fc2e4050370) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/row/row0ins.cc:3345
#14 0x0000000000aec6c8 in que_thr_step (thr=0x7fc2e4050370) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/que/que0que.cc:1095
#15 que_run_threads_low (thr=0x7fc2e4050370) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/que/que0que.cc:1177
#16 0x0000000000aece50 in que_run_threads (thr=0x7fc2e4050370) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/que/que0que.cc:1218
#17 0x0000000000b2678d in row_create_table_for_mysql (table=0x7fc2e40bcf78, trx=0x7fc2e40f5c78, commit=false) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/row/row0mysql.cc:2264
#18 0x0000000000a565b1 in create_table_def (flags2=1024, flags=1, remote_path=0x100 <Address 0x100 out of bounds>, temp_path=0x0, table_name=0x7fc3f0823aa0 "test/e", form=0x7fc3f0823d80, trx=0x7fc2e40f5c78) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/handler/ha_innodb.cc:9143
#19 ha_innobase::create (this=<optimized out>, name=0x400 <Address 0x400 out of bounds>, form=0x7fc3f0823d80, create_info=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/handler/ha_innodb.cc:10037
#20 0x00000000005c0bae in ha_create_table (thd=0x2a10d50, path=<optimized out>, db=0x7fc2e80053f8 "test", table_name=0x7fc2e8004e60 "e", create_info=0x7fc3f0827890, update_create_info=false, is_temp_table=false) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/sql/handler.cc:4882
#21 0x00000000007d8766 in rea_create_table (thd=0x2a10d50, path=0x7fc3f0825e40 "./test/e", db=0x7fc2e80053f8 "test", table_name=0x7fc2e8004e60 "e", create_info=0x7fc3f0827890, create_fields=..., keys=0, key_info=0x7fc2e413a698, file=0x7fc2e4138980, no_ha_table=false) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/sql/unireg.cc:526
#22 0x000000000077c159 in create_table_impl (thd=0x2a10d50, db=0x7fc2e80053f8 "test", table_name=0x7fc2e8004e60 "e", path=0x7fc3f0825e40 "./test/e", create_info=0x7fc3f0827890, alter_info=0x7fc3f0827290, internal_tmp_table=false, select_field_count=43, no_ha_table=false, is_trans=0x0, key_info=0x7fc3f0826050, key_count=0x7fc3f0826058) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/sql/sql_table.cc:4847
#23 0x000000000077cb57 in mysql_create_table_no_lock (thd=0x2a10d50, db=0x7fc2e80053f8 "test", table_name=0x7fc2e8004e60 "e", create_info=0x7fc3f0827890, alter_info=0x7fc3f0827290, select_field_count=43, is_trans=0x0) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/sql/sql_table.cc:4959
#24 0x0000000000702f45 in create_table_from_items (thd=0x2a10d50, create_info=0x7fc3f0827890, create_table=0x7fc2e8004e98, alter_info=0x7fc3f0827290, items=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/sql/sql_insert.cc:4050
#25 0x00000000007031d4 in select_create::prepare (this=0x7fc2e40e58a0, values=..., u=0x2a13208) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/sql/sql_insert.cc:4118
#26 0x000000000074314f in JOIN::prepare (this=0x7fc2e40e5a20, tables_init=<optimized out>, wild_num=44120432, conds_init=<optimized out>, og_num=0, order_init=<optimized out>, group_init=0x0, having_init=0x0, select_lex_arg=0x2a13850, unit_arg=0x2a13208) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/sql/sql_resolver.cc:335
#27 0x000000000074b9fa in mysql_prepare_select (free_join=<optimized out>, select_lex=0x2a13850, unit=0x2a13208, result=0x7fc2e40e58a0, select_options=2416184064, having=0x0, group=0x0, order=0x0, og_num=0, conds=0x0, fields=..., wild_num=1, tables=0x7fc2e80055d0, thd=0x2a10d50) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/sql/sql_select.cc:1055
#28 mysql_select (thd=0x2a10d50, tables=0x7fc2e80055d0, wild_num=1, fields=..., conds=0x0, order=<optimized out>, group=0x2a13950, having=0x0, select_options=2416184064, result=0x7fc2e40e58a0, unit=0x2a13208, select_lex=0x2a13850) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/sql/sql_select.cc:1178
#29 0x000000000074bdbb in handle_select (thd=0x2a10d50, result=0x7fc2e40e58a0, setup_tables_done_option=0) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/sql/sql_select.cc:111
#30 0x0000000000727dd5 in mysql_execute_command (thd=0x2a10d50) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/sql/sql_parse.cc:3330
#31 0x0000000000729328 in mysql_parse (thd=0x2a10d50, rawbuf=0x2a13140 "Pc9\001", length=<optimized out>, parser_state=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/sql/sql_parse.cc:6569
#32 0x000000000072a48c in dispatch_command (command=COM_QUERY, thd=0x2a10d50, packet=0x7fc3f0828910 "P\r\241\002", packet_length=57) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/sql/sql_parse.cc:1436
#33 0x000000000072b687 in do_command (thd=0x2a10d50) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/sql/sql_parse.cc:1051
#34 0x00000000007d8c07 in threadpool_process_request (thd=0x2a10d50) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/sql/threadpool_common.cc:316
#35 0x00000000007db918 in handle_event (connection=0x291e390) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/sql/threadpool_unix.cc:1468
#36 worker_main (param=0x1527e00 <all_groups+1024>) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/sql/threadpool_unix.cc:1521
#37 0x0000000000a2cdda in pfs_spawn_thread (arg=0x7fc2ec00c110) at /bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/perfschema/pfs.cc:1858
#38 0x0000003637207851 in start_thread () from /lib64/libpthread.so.0
#39 0x0000003636ee890d in clone () from /lib64/libc.so.6

It is waiting to S-latch the the btr latch part, but no other thread holds it, thus a missed wakeup event.

    (gdb) print/x (*(prio_rw_lock_t *)cell->wait_object).base_lock->lock_word
    $17 = 0x100000 - unlocked

    (gdb) print event
    $14 = (os_event_t) 0x27e6c30 - equal to lock->event below

    (gdb) print *(prio_rw_lock_t *)cell->wait_object
    $13 = {base_lock = {lock_word = 1048576, waiters = 1, recursive = 0, writer_thread = 140478917900032, event = 0x27e6c30, wait_ex_event = 0x27e6cc0, list = {prev = 0x27e82a0, next = 0x27d24c0},
    debug_list = {count = 0, start = 0x0, end = 0x0}, level = 160, pfs_psi = 0x0, count_os_wait = 264, lock_name = 0xe1f3cf "&btr_search_latch_arr[i]",
    last_s_file_name = 0xe1eb90 "/bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/btr/btr0sea.cc",
    last_x_file_name = 0xe1eb90 "/bzr/5.6_dbg/Percona-Server-5.6.13-rc60.6/storage/innobase/btr/btr0sea.cc", writer_is_wait_ex = 0, last_s_line = 954, last_x_line = 1653, magic_n = 22643},
  high_priority_s_waiters = 0, high_priority_s_event = 0x27e6d50, high_priority_x_waiters = 0, high_priority_x_event = 0x27e6de0, high_priority_wait_ex_waiter = 1}