Bug #45097 Hang during recovery, redo logs for doublewrite buffer pages
Submitted: 26 May 2009 13:46 Modified: 19 Jun 2010 17:51
Reporter: Vasil Dimov Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.1 OS:Any
Assigned to: Satya B CPU Architecture:Any

[26 May 2009 13:46] Vasil Dimov 
Description:
A hang may occur in InnoDB recovery if the server crashed immediately after startup. The output looks like this:

090515 16:38:40 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 45753
090515 16:38:40 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 96
090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 97
[...]
090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 126
090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 127
0 090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 64
090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 65
[...]
090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 94
090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 95
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 160
090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 161
090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 162
[...]
090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 190
090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 191
79 80 81 82 83 84 090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 128
090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 129
090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 130
[...]
090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 158
090515 16:38:40 InnoDB: Warning: trying to read doublewrite buffer page 159
85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 ^C  <-- it hangs here

How to repeat:
Kill the server immediately after startup. Here is Embedded InnoDB code that reproduces the problem 100% of the time:

int
main(int argc, char** argv)
{
        ib_init();

        ib_startup("barracuda");

        return(0);
}
[27 May 2009 15:52] Vasil Dimov 
This could be the same as Bug#43948 recv_apply_hashed_log_recs() may hang up when meets DB_TABLESPACE_DELETED pages

The patch posted by Yasufumi does not fix the problem, described in the present bug. The present bug causes exactly the same wait on the condition (recv_sys->n_addrs == 0). Maybe the fix for the present bug will also resolve Bug#43948 in which case they will be duplicates.
[28 May 2009 1:16] Yasufumi Kinoshita 
Vasil,

I think this is not same as Bug#43948.
The problem is why the transaction log contains the modification to the pages in doublewrite buffer.
I think such log should not be recorded to transaction log....
[28 May 2009 13:04] Heikki Tuuri 
Yasufumi's bug is due to .ibd files having been deleted.

Vasil's bug was due to redo logging to the doublewrite buffer.
[11 Jun 2009 12:52] Bugs System 
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/76114

2936 Satya B	2009-06-11
      Applying InnoDB snashot 5.1-ss5282, PRE-Fix for BUG#45097
      
      BUG#45097 - Hang during recovery, redo logs for doublewrite buffer pages 
      
      Detailed revision comments:
      
      r5126 | vasil | 2009-05-26 16:57:12 +0300 (Tue, 26 May 2009) | 9 lines
      branches/5.1:
      
      Preparation for the fix of
      Bug#45097 Hang during recovery, redo logs for doublewrite buffer pages 
      
      Non-functional change: move FSP_* macros from fsp0fsp.h to a new file
      fsp0types.h. This is needed in order to be able to use FSP_EXTENT_SIZE 
      in mtr0log.ic.
      
      r5127 | vasil | 2009-05-26 17:05:43 +0300 (Tue, 26 May 2009) | 9 lines
      branches/5.1:
      
      Preparation for the fix of
      Bug#45097 Hang during recovery, redo logs for doublewrite buffer pages
      
      Do not include unnecessary headers mtr0log.h and fut0lst.h in trx0sys.h
      and include fsp0fsp.h just before it is needed. This is needed in order
      to be able to use TRX_SYS_SPACE in mtr0log.ic.
      added:
        storage/innobase/include/fsp0types.h
      modified:
        storage/innobase/include/fsp0fsp.h
        storage/innobase/include/trx0sys.h
[11 Jun 2009 13:05] Bugs System 
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/76116

2937 Satya B	2009-06-11
      Applying InnoDB snashot 5.1-ss5282, Fix for BUG#45097
      
      BUG#45097 - Hang during recovery, redo logs for doublewrite buffer pages 
      
      Detailed revision comments:
      
      r5128 | vasil | 2009-05-26 17:26:37 +0300 (Tue, 26 May 2009) | 7 lines
      branches/5.1:
      
      Fix Bug#45097 Hang during recovery, redo logs for doublewrite buffer pages
      
      Do not write redo log for the pages in the doublewrite buffer. Also, do not
      make a dummy change to the page because this is not needed.
      
      r5150 | vasil | 2009-05-27 18:56:03 +0300 (Wed, 27 May 2009) | 4 lines
      branches/5.1:
      
      Whitespace fixup.
      modified:
        storage/innobase/include/mtr0log.ic
        storage/innobase/include/trx0sys.h
        storage/innobase/trx/trx0sys.c
[8 Jul 2009 13:30] Bugs System 
Pushed into 5.1.37 (revid:joro@sun.com-20090708131116-kyz8iotbum8w9yic) (version source revid:satya.bn@sun.com-20090629130311-dy1x480i0rx49cen) (merge vers: 5.1.37) (pib:11)
[9 Jul 2009 7:36] Bugs System 
Pushed into 5.1.37 (revid:joro@sun.com-20090708131116-kyz8iotbum8w9yic) (version source revid:satya.bn@sun.com-20090629130311-dy1x480i0rx49cen) (merge vers: 5.1.37) (pib:11)
[10 Jul 2009 11:21] Bugs System 
Pushed into 5.4.4-alpha (revid:anozdrin@bk-internal.mysql.com-20090710111017-bnh2cau84ug1hvei) (version source revid:satya.bn@sun.com-20090629130606-3o5j3wii9kta3z05) (merge vers: 5.4.4-alpha) (pib:11)
[17 Jul 2009 3:08] Paul DuBois 
Noted in 5.1.37, 5.4.4 changelogs.

InnoDB recovery could hang due to redo logging of doublewrite buffer
pages.
[12 Aug 2009 22:24] Paul DuBois 
Noted in 5.4.2 changelog because next 5.4 version will be 5.4.2 and not 5.4.4.
[14 Aug 2009 23:10] Paul DuBois 
Ignore previous comment about 5.4.2.
[26 Aug 2009 13:45] Bugs System 
Pushed into 5.1.37-ndb-7.0.8 (revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (version source revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (merge vers: 5.1.37-ndb-7.0.8) (pib:11)
[26 Aug 2009 13:46] Bugs System 
Pushed into 5.1.37-ndb-6.3.27 (revid:jonas@mysql.com-20090826105955-bkj027t47gfbamnc) (version source revid:jonas@mysql.com-20090826105955-bkj027t47gfbamnc) (merge vers: 5.1.37-ndb-6.3.27) (pib:11)
[26 Aug 2009 13:48] Bugs System 
Pushed into 5.1.37-ndb-6.2.19 (revid:jonas@mysql.com-20090825194404-37rtosk049t9koc4) (version source revid:jonas@mysql.com-20090825194404-37rtosk049t9koc4) (merge vers: 5.1.37-ndb-6.2.19) (pib:11)
[27 Aug 2009 16:32] Bugs System 
Pushed into 5.1.35-ndb-7.1.0 (revid:magnus.blaudd@sun.com-20090827163030-6o3kk6r2oua159hr) (version source revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (merge vers: 5.1.37-ndb-7.0.8) (pib:11)
[7 Oct 2009 18:40] Paul DuBois 
The 5.4 fix has been pushed to 5.4.2.
[5 May 2010 15:23] Bugs System 
Pushed into 5.1.47 (revid:joro@sun.com-20100505145753-ivlt4hclbrjy8eye) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[6 May 2010 17:50] Paul DuBois 
Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.
[28 May 2010 5:58] Bugs System 
Pushed into mysql-next-mr (revid:alik@sun.com-20100524190136-egaq7e8zgkwb9aqi) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (pib:16)
[28 May 2010 6:26] Bugs System 
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100524190941-nuudpx60if25wsvx) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[28 May 2010 6:54] Bugs System 
Pushed into 5.5.5-m3 (revid:alik@sun.com-20100524185725-c8k5q7v60i5nix3t) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[29 May 2010 22:40] Paul DuBois 
Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.
[15 Jun 2010 8:10] Bugs System 
Pushed into 5.5.5-m3 (revid:alik@sun.com-20100615080459-smuswd9ooeywcxuc) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (merge vers: 5.1.47) (pib:16)
[15 Jun 2010 8:26] Bugs System 
Pushed into mysql-next-mr (revid:alik@sun.com-20100615080558-cw01bzdqr1bdmmec) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (pib:16)
[17 Jun 2010 12:00] Bugs System 
Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 12:41] Bugs System 
Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 13:27] Bugs System 
Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)