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
• Status: Duplicate
• 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

[1 Dec 2009 8:23] Oli Sennhauser

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.

[1 Dec 2009 8:32] Oli Sennhauser

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 }

[10 Aug 2010 18:17] MySQL Verification Team

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

[11 Aug 2010 5:40] MySQL Verification Team

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.

[11 Aug 2010 5:53] MySQL Verification Team

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.

[12 Aug 2010 6:27] MySQL Verification Team

repeated on 5.1.49 with innodb plugin 1.0.10

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

[20 Aug 2010 19:45] MySQL Verification Team

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.

[21 Aug 2010 5:23] MySQL Verification Team

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 :)

[24 Aug 2010 9:15] MySQL Verification Team

this hangup is still repeatable in this version:

sbester@box2:~/big/build/bzr/mysql-5.1-security> bzr revision-info
3483 [e-mail]-20100820122324-zhq53easgf6ke9wz

[24 Aug 2010 9:22] Calvin Sun

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

[28 Sep 2010 8:48] Bugs System

Pushed into mysql-5.1 5.1.52 (revid:[e-mail]-20100928083322-wangbv97uobu7g66) (version source revid:[e-mail]-20100928083322-wangbv97uobu7g66) (merge vers: 5.1.52) (pib:21)

[14 Oct 2010 8:35] Bugs System

Pushed into mysql-5.1-telco-7.0 5.1.51-ndb-7.0.20 (revid:[e-mail]-20101014082627-jrmy9xbfbtrebw3c) (version source revid:[e-mail]-20101014082627-jrmy9xbfbtrebw3c) (merge vers: 5.1.51-ndb-7.0.20) (pib:21)

[14 Oct 2010 8:50] Bugs System

Pushed into mysql-5.1-telco-6.3 5.1.51-ndb-6.3.39 (revid:[e-mail]-20101014083757-5qo48b86d69zjvzj) (version source revid:[e-mail]-20101014083757-5qo48b86d69zjvzj) (merge vers: 5.1.51-ndb-6.3.39) (pib:21)

[14 Oct 2010 9:05] Bugs System

Pushed into mysql-5.1-telco-6.2 5.1.51-ndb-6.2.19 (revid:[e-mail]-20101014084420-y54ecj85j5we27oa) (version source revid:[e-mail]-20101014084420-y54ecj85j5we27oa) (merge vers: 5.1.51-ndb-6.2.19) (pib:21)

[9 Nov 2010 19:47] Bugs System

Pushed into mysql-5.5 5.5.7-rc (revid:[e-mail]-20101109182959-otkxq8vo2dcd13la) (version source revid:[e-mail]-20100824081003-v4ecy0tga99cpxw2) (merge vers: 5.1.50) (pib:21)

[13 Nov 2010 16:14] Bugs System

Pushed into mysql-trunk 5.6.99-m5 (revid:[e-mail]-20101113155825-czmva9kg4n31anmu) (version source revid:[e-mail]-20100824081003-v4ecy0tga99cpxw2) (merge vers: 5.1.50) (pib:21)

[13 Nov 2010 16:37] Bugs System

Pushed into mysql-next-mr (revid:[e-mail]-20101113160336-atmtmfb3mzm4pz4i) (version source revid:[e-mail]-20100824081003-v4ecy0tga99cpxw2) (pib:21)

[27 Jul 2011 13:37] Chris Calender

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?

[27 Jul 2011 13:47] MySQL Verification Team

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