MySQL Bugs: #59047: Crash due to long semaphore wait

Bug #59047	Crash due to long semaphore wait
Submitted:	19 Dec 2010 22:02	Modified:	12 Aug 2011 21:26
Reporter:	Boris Shargorodskiy	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S1 (Critical)
Version:	5.0.91-community-log	OS:	Linux (2.6.18-194.3.1.el5 x86_64)
Assigned to:		CPU Architecture:	Any

Description:
One of our production database servers crashed twice during the week with similar sympthoms, and there was one more crash before.

System:
OS: CentOS release 5.5 (Final)
Memory: 24GB
CPU: Six-Core AMD Opteron(tm) Processor 2431 800MHz
MySQL: 5.0.91-community-log

There are the following things I found which are the same for all the crashes:

1) There is thread specified in "SEMAPHORES" section of "INNODB MONITOR OUTPUT" (it is specified always first) which waits for the semaphore created in file btr0sea.c line 139 and the same thread has reserved it (some other threads wait for it as well):

  --Thread 1239300416 has waited at btr0sea.c line 1577 for 943.00 seconds the semaphore:
  X-lock on RW-latch at 0x2aaab77990b8 created in file btr0sea.c line 139
  a writer (thread id 1239300416) has reserved it in mode  wait exclusive
  number of readers 1, waiters flag 1
  Last time read locked in file btr0cur.c line 561
  Last time write locked in file btr0sea.c line 516

2) One of the threads specified in #1 (which waits for the semaphore) is "Main thread" specified in "ROW OPERATIONS" section of "INNODB MONITOR OUTPUT"; it "doing insert buffer merge" in all cases:

  --Thread 1169811776 has waited at btr0sea.c line 943 for 941.00 seconds the semaphore:
  S-lock on RW-latch at 0x2aaab77990b8 created in file btr0sea.c line 139
  a writer (thread id 1239300416) has reserved it in mode  wait exclusive
  number of readers 1, waiters flag 1
  Last time read locked in file btr0cur.c line 561
  Last time write locked in file btr0sea.c line 516

  ROW OPERATIONS
  --------------
  1 queries inside InnoDB, 0 queries in queue
  4 read views open inside InnoDB
  Main thread process no. 6622, id 1169811776, state: doing insert buffer merge
  Number of rows inserted 78912878, updated 41115376, deleted 31269295, read 19386566459
  0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

3) There is thread specified in "SEMAPHORES" section of "INNODB MONITOR OUTPUT" which waits for the semaphore created in file dict0dict.c line 709:

  --Thread 1274976576 has waited at dict0dict.c line 751 for 943.00 seconds the semaphore:
  Mutex at 0x2aaab77a98b8 created file dict0dict.c line 709, lock var 1
  waiters flag 1

4) There is either "create table" or "drop table" statement executed at the crash time on table which have at least one non-unique index (it takes two transactions):

  ---TRANSACTION 0 1535247247, ACTIVE 928 sec, process no 6622, OS thread id 1239300416 creating index
  4 lock struct(s), heap size 1216, undo log entries 10
  MySQL thread id 95070, query id 1210505367 72.5.65.85 cs59 creating table
  create table upload_list_results_102234_95070 (
      `upload_fk` bigint not null,
      `inserted_count` bigint not null,
      `deleted_count` bigint not null,
      primary key (`upload_fk`),
      index `inserted_count_index` (`inserted_count`),
      index `deleted_count_index` (`deleted_count`)
  ) engine=InnoDB default charset=latin1

  ---TRANSACTION 0 1535247017, not started, process no 6622, OS thread id 1239300416
  MySQL thread id 95070, query id 1210505367 72.5.65.85 cs59 creating table
  create table upload_list_results_102234_95070 (
      `upload_fk` bigint not null,
      `inserted_count` bigint not null,
      `deleted_count` bigint not null,
      primary key (`upload_fk`),
      index `inserted_count_index` (`inserted_count`),
      index `deleted_count_index` (`deleted_count`)
  ) engine=InnoDB default charset=latin1

How to repeat:
I did not found the way to repeat it yet.

Suggested fix:
-

Could you please provide the backtrace. Thanks in advance.

Could you please specify what should be attached as a backtrace?
(I had submitted couple files when I created the bug report. They are confidential, so I submitted them privately with respective comments. my.cnf was attached to the bug report and the error log was put to FTP  ftp://ftp.mysql.com/pub/mysql/upload/bug-data-59047.zip)

Thank you for the report.

Unfrotunately error log does not contain backtrace. Do you use release binaries? Could you please use debug binary (mysqld-debug in same directory where mysqld is located), turn core files to 'On' and send us core file together with mysqld which created it next time when crash occur?

Thank you for the explanation.

We use RPM packages loaded from MySQL site (in this case MySQL-server-community-5.0.91-1.rhel5.x86_64.rpm). Unfortunately the problem happened on one of our production servers, so we cannot put there the debug package.
Thank you.

Today there was one more crash on other production server. The crash looks the same, except that just part of "INNODB MONITOR OUTPUT" was written into the error log, and this time there was "alter table" statement (please see the item 4 above).

I think this problem may be related to http://bugs.mysql.com/bug.php?id=59733

Were you using innodb_file_per_table=0 (the default setting)? If yes, then this could be a duplicate of Bug #59733.

There is no innodb_file_per_table=1 in the provided my.cnf, so this could indeed be a duplicate of Bug #59733. Without a core dump (or a backtrace of all threads), it is impossible to tell.

Marco,

Can you suggest a scenario to reproduce Bug #59733? We will try to figure out whether our application is able to behave that way, try so simulate it and see if we can get similar results. 

Thank you,
Anton

Errorlog from 5.0.91

Attachment: m1.txt (text/plain), 1.91 KiB.

We have a similar problem on a heavy loaded master - 6 slaves setup (1400-2000 updates/second, 12000-15000 selects/second), that started to occur after upgrade from 5.0.45 to 5.0.91. We had several similar stops on the master see mine file m1.txt

We upgraded from 5.0.91 to 5.1.55 to see if this problem was fixed. But only a few days after upgrade, we found this on the master see file m2.txt

On a readslave see file m3.txt

The database is large (about 1TB innodb tablespace size), and it is not an easy task to convert to innod_file_per_table (to convert all tables).
We will try to convert one of the slaves to a complete file per table setup.

Errorlog from 5.1.55 master

Attachment: m2.txt (text/plain), 2.72 KiB.

Errorlog from 5.1.55 slave

Attachment: m3.txt (text/plain), 3.40 KiB.

Today there was one more crash on one more of our production servers. The crash looks the same.
This time there was "core-file" option set in my.cnf. The core file was uploaded to FTP: "bug-data-core-file-59047.tar". The error log was uploaded to FTP as well: "bug-data-error-log-59047.tar".

Thank you.

We have analyzed the core file and found the threads participated in the deadlock:

---TRANSACTION 1 333718766, ACTIVE 243 sec, process no 31018, OS thread id 1175783744 inserting, thread declared inside InnoDB 500
mysql tables in use 2, locked 2
ROLLING BACK 21 lock struct(s), heap size 3024, undo log entries 3
MySQL thread id 189556, query id 3627043776 72.5.65.85 cs59 Sending data
insert into partition_104793_crm_data (
    `crm_fk`, `type`, `data`
)
select
    434028 as `crm_fk`, d.`type`, d.`data`
from
    upload_tmp_data_104793_189556 as d
where
    d.`upload_fk` = 1

Thread 337 (Thread 3891): 
Thread id 1175783744 (Holding dict0dict.c mutex and waiting S-latch since X-latch requested)
#0  0x00000039b740ab99 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000007e4585 in os_event_wait_low ()
#2  0x00000000007d892a in sync_array_wait_event ()
#3  0x00000000007d9f65 in rw_lock_x_lock_func ()
#4  0x000000000075ebe4 in btr_search_update_hash_on_delete ()
#5  0x00000000007521d7 in btr_cur_optimistic_delete ()
#6  0x0000000000739480 in ?? ()
#7  0x000000000073963e in row_undo_ins ()
#8  0x000000000073353f in row_undo_step ()
#9  0x000000000070f45d in que_run_threads ()
#10 0x0000000000770809 in trx_general_rollback_for_mysql ()
#11 0x0000000000720516 in row_mysql_handle_errors ()
#12 0x0000000000721a80 in row_insert_for_mysql ()
#13 0x000000000067e460 in ha_innobase::write_row(char*) ()
#14 0x0000000000620f01 in write_record(THD*, st_table*, st_copy_info*) ()
#15 0x0000000000621533 in select_insert::send_data(List<Item>&) ()
#16 0x0000000000601279 in ?? ()
#17 0x0000000000610f8c in ?? ()
#18 0x0000000000611098 in sub_select(JOIN*, st_join_table*, bool) ()
#19 0x0000000000611330 in ?? ()
#20 0x000000000061c1ec in JOIN::exec() ()
#21 0x000000000061dfbd in mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) ()
#22 0x000000000061e8b7 in handle_select(THD*, st_lex*, select_result*, unsigned long) ()
#23 0x00000000005cce3f in mysql_execute_command(THD*) ()
#24 0x0000000000628835 in Prepared_statement::execute(String*, bool) ()
#25 0x0000000000628ed1 in mysql_sql_stmt_execute(THD*) ()
#26 0x00000000005c930f in mysql_execute_command(THD*) ()
#27 0x00000000006dbe9c in sp_instr_stmt::exec_core(THD*, unsigned int*) ()
#28 0x00000000006dc042 in sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*) ()
#29 0x00000000006e1ace in sp_instr_stmt::execute(THD*, unsigned int*) ()
#30 0x00000000006dfd29 in sp_head::execute(THD*) ()
#31 0x00000000006e03db in sp_head::execute_procedure(THD*, List<Item>*) ()
#32 0x00000000005cd4f4 in mysql_execute_command(THD*) ()
#33 0x00000000005ce2e1 in mysql_parse(THD*, char const*, unsigned int, char const**) ()
#34 0x00000000005cf3a2 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
#35 0x00000000005d0584 in handle_one_connection ()
#36 0x00000039b74064a7 in start_thread () from /lib64/libpthread.so.0
#37 0x00000032934d3c2d in clone () from /lib64/libc.so.6

---TRANSACTION 1 333718779, ACTIVE 243 sec, process no 31018, OS thread id 1182439744, thread declared inside InnoDB 469
mysql tables in use 34, locked 0
, holds adaptive hash latch
MySQL thread id 189526, query id 3627043742 72.5.65.81 cs59 Sending data
SELECT l.id, (SELECT d.number FROM partition_101991_crm_numbers AS d WHERE d.crm_fk=l.crm_fk AND d.type=1), (SELECT d.number FROM partition_101991_crm_numbers AS d WHERE d.crm_fk=l.crm_fk AND d.type=2), (SELECT d.number FROM partition_101991_crm_numbers AS d WHERE d.crm_
fk=l.crm_fk AND d.type=3), (SELECT d.data FROM partition_101991_crm_data AS d WHERE d.crm_fk=l.crm_fk AND d.type=1), (SELECT d.data FROM partition_101991_crm_data AS d WHERE d.crm_fk=l.crm_fk AND d.type=2), (SELECT d.data FROM partition_101991_crm_data AS d WHERE d.crm_f
k=l.crm_fk AND d.type=3), (SELECT d.data FROM partition_10
Trx read view will not see trx with id >= 1 333718780, sees < 1 333718098

Thread 309 (Thread 3859):
Thread id 1182439744 (Waiting for Query_cache mutex and holding S-latch)
#0  0x00000039b740d174 in __lll_lock_wait () from /lib64/libpthread.so.0
#1  0x00000039b7408b00 in _L_lock_1233 () from /lib64/libpthread.so.0
#2  0x00000039b7408a83 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x00000000006b600e in query_cache_insert(st_net*, char const*, unsigned long) ()
#4  0x00000000005a9dbd in net_real_write ()
#5  0x00000000005aa153 in ?? ()
#6  0x00000000005aa5c3 in my_net_write ()
#7  0x00000000005ab2ae in Protocol::write() ()
#8  0x00000000005a5fff in select_send::send_data(List<Item>&) ()
#9  0x0000000000601279 in ?? ()
#10 0x0000000000610f8c in ?? ()
#11 0x0000000000611098 in sub_select(JOIN*, st_join_table*, bool) ()
#12 0x0000000000611330 in ?? ()
#13 0x000000000061c1ec in JOIN::exec() ()
#14 0x000000000061dfbd in mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) ()
#15 0x000000000061e8b7 in handle_select(THD*, st_lex*, select_result*, unsigned long) ()
#16 0x00000000005c9dd4 in mysql_execute_command(THD*) ()
#17 0x00000000005ce2e1 in mysql_parse(THD*, char const*, unsigned int, char const**) ()
#18 0x00000000005cf3a2 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
#19 0x00000000005d0584 in handle_one_connection ()
#20 0x00000039b74064a7 in start_thread () from /lib64/libpthread.so.0
#21 0x00000032934d3c2d in clone () from /lib64/libc.so.6

---TRANSACTION 1 333718789, ACTIVE 243 sec, process no 31018, OS thread id 1248999744
mysql tables in use 15, locked 0
MySQL thread id 189417, query id 3627043779 72.5.65.94 cs59
Select m.id as m_id, m.modified As m_mod, (Select d.data From partition_103263_crm_data As d Where m.id = d.crm_fk And d.type = 1) As first_name, (Select d.data From partition_103263_crm_data As d Where m.id = d.crm_fk And d.type = 2) As last_name, (Select d.data From partition_103263_crm_data As d Where m.id = d.crm_fk And d.type = 3) As company, (Select d.data From partition_103263_crm_data As d Where m.id = d.crm_fk And d.type = 4) As street, (Select d.data From partition_103263_crm_data As d Where m.id = d.crm_fk And d.type = 5) As city, (Select d.data From partition_103263_crm_data As d W
Trx read view will not see trx with id >= 1 333718790, sees < 1 333718098

Thread 175 (Thread 15706):
Thread id 1248999744 (Holding Query_cache mutex and waiting for dict0dict mutex)
#0  0x00000039b740ab99 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000007e4585 in os_event_wait_low ()
#2  0x00000000007d892a in sync_array_wait_event ()
#3  0x00000000007daab7 in mutex_spin_wait ()
#4  0x0000000000705893 in dict_table_get ()
#5  0x000000000072ba19 in row_search_check_if_query_cache_permitted ()
#6  0x000000000067eeee in innobase_query_caching_of_table_permitted(THD*, char*, unsigned int, unsigned long long*) ()
#7  0x0000000000680074 in ha_innobase::register_query_cache_table(THD*, char*, unsigned int, char (**)(THD*, char*, unsigned int, unsigned long long*), unsigned long long*) ()
#8  0x00000000006b3adc in Query_cache::ask_handler_allowance(THD*, TABLE_LIST*) ()
#9  0x00000000006b630a in Query_cache::store_query(THD*, TABLE_LIST*) ()
#10 0x00000000005c9dc4 in mysql_execute_command(THD*) ()
#11 0x00000000005ce2e1 in mysql_parse(THD*, char const*, unsigned int, char const**) ()
#12 0x00000000005cf3a2 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
#13 0x00000000005d0584 in handle_one_connection ()
#14 0x00000039b74064a7 in start_thread () from /lib64/libpthread.so.0
#15 0x00000032934d3c2d in clone () from /lib64/libc.so.6

Currently we are verifying assumption that we have experienced two different kinds of crashes before.

Two things to try that may prevent this and help to isolate a possible cause:

1. Turn off the adaptive hash index using --skip-innodb-hash-index or when the server is running using set global innodb_hash_index = 0;

2. Turn off the query cache by setting query_cache_type = 0 and query_cache_size = 0 in my.cnf. You can turn it off partially dynamically using SET GLOBAL query_cache_size = 0 but this doesn't fully eliminate all taking and releasing of the query cache mutex; from 5.5 setting the type to 0 in my.cnf fully eliminates this, it can't be done dynamically.

If you try these and they solve the problem or not please let us know.

Please do what James suggested and inform us about results.

We had turned off the adaptive hash index and the problem disappeared.

Thank you!

Thank you for the feedback.

Closing as "Not a bug"

Despite the fact that in this particular case the problem is solved, the bug takes a place definitely.
Turning off the adaptive hash index is just a workaround which hides the bug.
If this workaround is not found/applied by the customer, the system may crash.
Moreove such workaround is applicable only for the cases if system load specifics let to turn it off.

Thanks for letting us know that the workaround was effective. Please confirm that that was with 5.0. We've seen a few reports for 5.0 that feature btr0sea.c and dict0dict.c and which go away when the adaptive hash index is turned off. It's unlikely that we will ever fix that in 5.0 because it's no longer getting anything but the most critical updates, generally only security bug fixes.

For 5.5 it would be a good idea to use the latest because there have been some fixes related to the change buffer (formerly adaptive hash index). As the current production version it's also one where we'd be very interested in reports of this so we can locate and fix the problem if it's not already known. For reports we'd need the last innodb monitor output, complete from the error log file, and the full crash section that follows, probably showing the watchdog thread killing the server deliberately. We've also recently made the watchdog thread better at avoiding false positives and that may reduce the chance of a false alarm.

> Please confirm that that was with 5.0.
That was with 5.0.

We use 5.0.91 currently, but are going to migrate to 5.5 in the nearest future.