MySQL Bugs: #49251: deadlock/crash with concurrent truncate table and index statistics calculation

Bug #49251	deadlock/crash with concurrent truncate table and index statistics calculation
Submitted:	1 Dec 2009 8:23	Modified:	26 Aug 2010 1:21
Reporter:	Oli Sennhauser	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S1 (Critical)
Version:	5.0.91,5.1.50, 5.5, 5.6.1	OS:	Any
Assigned to:	Assigned Account	CPU Architecture:	Any
Tags:	crash, innodb, semaphore waits

Description:
A customer experiences a server crash after a semaphore wait followed by a corruption. The table which was corrupted was active during the problem:

...
InnoDB: Error: semaphore wait has lasted > 600 seconds
InnoDB: We intentionally crash the server, because it appears to be hung.
091124 22:16:15InnoDB: Assertion failure in thread 1147169120 in file srv0srv.c line 2095
...
OS WAIT ARRAY INFO: reservation count 2275483678, signal count 1995552505
--Thread 1158457696 has waited at fsp0fsp.c line 2185 for 945.00 seconds the semaphore:
X-lock on RW-latch at 0x2a9ac6e940 created in file fil0fil.c line 1048
a writer (thread id 1164048736) has reserved it in mode  exclusive
number of readers 0, waiters flag 1
Last time read locked in file not yet reserved line 0
Last time write locked in file fsp0fsp.c line 2732
...
Version: '5.0.54a-enterprise-gpl-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Enterprise Server (GPL)
InnoDB: Error: trying to load index PRIMARY for table czen/LUCENE_SEEKER_JOB
InnoDB: but the index tree has been freed!
091124 23:08:52 - mysqld got signal 11;

How to repeat:
Was not able to repeat yet.

Suggested fix:
Do not crash or at least do not corrupt data during crash.

2162 /**************************************************************************
   2163 Calculates the number of pages reserved by a segment, and how many pages are
   2164 currently used. */
   2165
   2167 fseg_n_reserved_pages(
   2173 {
   2178         space = buf_frame_get_space_id(header);
   2185         mtr_x_lock(fil_space_get_latch(space), mtr);
   2187         inode = fseg_inode_get(header, mtr);
   2189         ret = fseg_n_reserved_pages_low(inode, used, mtr);
   2191         return(ret);
   2192 }

   2700 fsp_reserve_free_extents(
   2710 {
   2722         ut_ad(mtr);
   2728         *n_reserved = n_ext;
   2730         latch = fil_space_get_latch(space);
   2732         mtr_x_lock(latch, mtr);
   2734         space_header = fsp_get_space_header(space, mtr);

   1361 Allocates a single free page from a space. The page is marked as used. */
   1364 fsp_alloc_free_page(
   1371 {
   1382         ut_ad(mtr);
   1384         header = fsp_get_space_header(space, mtr);
                ...
   1479         /* Initialize the allocated page to the buffer pool, so that it can
   1480         be obtained immediately with buf_page_get without need for a disk
   1481         read. */
   1483         buf_page_create(space, page_no, mtr);
   1485         page = buf_page_get(space, page_no, RW_X_LATCH, mtr);
   1490         /* Prior contents of the page should be ignored */
   1491         fsp_init_file_page(page, mtr);
   1493         return(page_no);
   1494 }

seen this during concurrent truncate table and show keys from an innodb table..

repeated a hangup in 5.0.80, and saved stack traces, etc. there was FK keys created after starting the test.

Attachment: bug49251_5.0.80_hang_stack_traces.txt (text/plain), 25.00 KiB.

After the crash due to deadlock, and restart of mysqld, any attempt to access the partially truncated table will crash the server with stack trace:
show create table t1:

  mysqld-debug.exe!row_create_prebuilt()[row0mysql.c:647]
  mysqld-debug.exe!ha_innobase::open()[ha_innodb.cc:2253]
  mysqld-debug.exe!handler::ha_open()[handler.cc:1416]
  mysqld-debug.exe!openfrm()[table.cc:939]
  mysqld-debug.exe!open_unireg_entry()[sql_base.cc:2472]
  mysqld-debug.exe!open_table()[sql_base.cc:1923]
  mysqld-debug.exe!open_tables()[sql_base.cc:2762]
  mysqld-debug.exe!open_normal_and_derived_tables()[sql_base.cc:3103]
  mysqld-debug.exe!mysqld_show_create()[sql_show.cc:403]
  mysqld-debug.exe!mysql_execute_command()[sql_parse.cc:3563]
  mysqld-debug.exe!mysql_parse()[sql_parse.cc:6351]
  mysqld-debug.exe!dispatch_command()[sql_parse.cc:1941]
  mysqld-debug.exe!do_command()[sql_parse.cc:1629]
  mysqld-debug.exe!handle_one_connection()[sql_parse.cc:1235]
  mysqld-debug.exe!pthread_start()[my_winthread.c:86]
  mysqld-debug.exe!_callthreadstart()[thread.c:295]
  mysqld-debug.exe!_threadstart()[thread.c:277]
  kernel32.dll!BaseThreadStart()
 variables.

The only solution is to do DROP TABLE and then recreate it. No value of innodb_force_recovery will allow you to open the table. 

You will need to know the structure of it from backups, or a slave, etc.

repeated on 5.1.49 with innodb plugin 1.0.10

Attachment: bug49251_5.1.49.stack_traces.txt (text/plain), 29.86 KiB.

compile and run against a mysqld started with --innodb-lock-wait-timeout=1. give it some minutes or hours to hang or crash

Attachment: bug49251.c (text/plain), 10.38 KiB.

the above testcase might provoke various problems.
5.0.91 1): saw the hangup oli reported.
5.0.91 2): got assertion on truncate [file lock0lock.c line 4006 Failing assertion: !lock_get_wait(lock)]

5.1.50 1): saw the hangup oli reported

5.5.5 1) : dies so quickly my error log grew too big :)

this hangup is still repeatable in this version:

sbester@box2:~/big/build/bzr/mysql-5.1-security> bzr revision-info
3483 georgi.kodinov@oracle.com-20100820122324-zhq53easgf6ke9wz

Change back to Verified based on Shane's latest comment.

What bug is this a "duplicate" of?  There is no mention of the other bug, and so there is no way to know if that has been fixed or not, and if so, what versions?

See http://bugs.mysql.com/bug.php?id=54678.