Bug #48431 Loop in linked list when printing crash dump
Submitted: 30 Oct 2009 9:31 Modified: 28 Dec 2009 17:39
Reporter: Jørgen Austvik Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Cluster: Cluster (NDB) storage engine Severity:S3 (Non-critical)
Version:mysql-5.1-telco-6.3 OS:Linux (RHEL 5.2)
Assigned to: Jonas Oreland CPU Architecture:Any

[30 Oct 2009 9:31] Jørgen Austvik 
Description:
ndbd.1/log.out: 1.6TB (until quota was used up) of this:
>> 009-10-29 09:01:49 [ndbd] INFO     -- Undo head - undofile02.dat page:
>> 3577 lsn: 4410537
>> 2009-10-29 09:01:49 [ndbd] INFO     --    - next - undofile01.dat(1246057)
>> 2009-10-29 09:02:00 [ndbd] INFO     -- Logfile group: 2
>> 2009-10-29 09:02:00 [ndbd] INFO     --   head: undofile02.dat page: 3577
>> 2009-10-29 09:02:00 [ndbd] INFO     --   tail: undofile02.dat page: 1283
>> 2009-10-29 09:02:00 [ndbd] INFO     -- Flushing page cache after undo
>> completion
>> 2009-10-29 09:02:02 [ndbd] INFO     -- Flushing complete
>> RedoPageCache: avoided 0 (0/0) page-reads
>> RedoOpenFileCache: Avoided 0 file-open/close closed: 0
>> changing file from 16818188 to 16818176
>> miss matched writes
>> dirty pages
>>   0 :
>>   1 : [ Page: ptr.i: 110 [ m_file_no: 0 m_page_no: 1017] list_index: 1
>> free_space: 126 uncommitted_used_space: 0 ] [ Page: ptr.i: 110 [
>> m_file_no: 0 m_page_no: 1017] list_i
>> ndex: 1 free_space: 126 uncommitted_used_space: 0 ] [ Page: ptr.i: 110 [
>> m_file_no: 0 m_page_no: 1017] list_index: 1 free_space: 126
>> uncommitted_used_space: 0 ] [ Page: ptr
>> .i: 110 [ m_file_no: 0 m_page_no: 1017] list_index: 1 free_space: 126
>> uncommitted_used_space: 0 ] [ Page: ptr.i: 110 [ m_file_no: 0 m_page_no:
>> 1017] list_index: 1 free_spac
>> e: 126 uncommitted_used_space: 0 ] [ Page: ptr.i: 110 [ m_file_no: 0
>> m_page_no: 1017] list_index: 1 free_space: 126 uncommitted_used_space: 0
>> ] [ Page: ptr.i: 110 [ m_file_
>> no: 0 m_page_no: 1017] list_index: 1 free_space: 126
>> uncommitted_used_space: 0 ] [ Page: ptr.i: 110 [ m_file_no: 0 m_page_no:
>> 1017] list_index: 1 free_space: 126 uncommitte
>> d_used_space: 0 ] [ Page: ptr.i: 110 [ m_file_no: 0 m_page_no: 1017]
>> list_index: 1 free_space: 126 uncommitted_used_space: 0 ] [ Page: ptr.i:
>> 110 [ m_file_no: 0 m_page_no:
>> 1017] list_index: 1 free_space: 126 uncommitted_used_space: 0 ] [ Page:
>> ptr.i: 110 [ m_file_no: 0 m_page_no: 1017] list_index: 1 free_space: 126
>> uncommitted_used_space: 0 ]
>>  [ Page: ptr.i: 110 [ m_file_no: 0 m_page_no: 1017] list_index: 1
>> free_space: 126 uncommitted_used_space: 0 ] [ Page: ptr.i: 110 [
>> m_file_no: 0 m_page_no: 1017] list_index:
>>  1 free_space: 126 uncommitted_used_space: 0 ] [ Page: ptr.i: 110 [
>> m_file_no: 0 m_page_no: 1017] list_index: 1 free_space: 126
>> uncommitted_used_space: 0 ] [ Page: ptr.i: 1
>> 10 [ m_file_no: 0 m_page_no: 1017] list_index: 1 free_space: 126
>> uncommitted_used_space: 0 ] [ Page: ptr.i: 110 [ m_file_no: 0 m_page_no:
>> 1017] list_index: 1 free_space: 12
>> 6 uncommitted_used_space: 0 ] [ Page: ptr.i: 110 [ m_file_no: 0
>> m_page_no: 1017] list_index: 1 free_space: 126 uncommitted_used_space: 0
>> ] [ Page: ptr.i: 110 [ m_file_no: 0
>>  m_page_no: 1017] list_index: 1 free_space: 126 uncommitted_used_space: 0 ]
>>
>> (and a lot more of this)
>>
>>  1 free_space: 126 uncommitted_used_space: 0 ] [ Page: ptr.i: 110 [
>> m_file_no: 0 m_page_no: 1017] list_index: 1 free_space: 126 uncom
>> mitted_used_space: 0 ] [ Page: ptr.i: 110 [ m_file_no: 0 m_page_no:
>> 1017] list_index: 1 free_space: 126 uncommitted_used_space: 0 ] [ Page:
>> ptr.i: 110 [ m_file_no: 0 m_page
>> _no: 1017] list_index: 1 free_space: 126 uncommitted_used_space: 0 ] [
>> Page: ptr.i: 110 [ m_file_no: 0 m_page_no: 1017] list_index: 1
>> free_space: 126 uncommitted_used_space
>> : 0 ] [ Page: ptr.i: 110 [ m_file_no: 0 m_page_no: 1017] list_index: 1
>> free_space: 126 uncommitted_used_space: 0 ] [ Page: ptr.i: 110 [
>> m_file_no: 0 m_page_no: 1017] list_i
>> ndex: 1 free_space: 126 uncommitted_used_space: 0 ] [ Page: ptr.i: 110 [
>> m_file_no: 0 m_page_no: 1017]

2009-10-29 07:09:21 [ndbd] INFO     -- NDB Cluster -- DB node 2
2009-10-29 07:09:21 [ndbd] INFO     -- mysql-5.1.39 ndb-6.3.28-GA --
2009-10-29 07:09:21 [ndbd] INFO     -- Configuration fetched at tyr01 port 14000

The log is filled with a lot of these (every 10-15 sec):
2009-10-29 07:25:57 [ndbd] INFO     -- Restarting system
2009-10-29 07:25:58 [ndbd] INFO     -- Node 2: Node shutdown completed, restarting, no start.
2009-10-29 07:25:58 [ndbd] INFO     -- Ndb has terminated (pid 32699) restarting
2009-10-29 07:25:58 [ndbd] INFO     -- Angel pid: 30403 ndb pid: 32731
2009-10-29 07:25:58 [ndbd] INFO     -- NDB Cluster -- DB node 2
2009-10-29 07:25:58 [ndbd] INFO     -- mysql-5.1.39 ndb-6.3.28-GA --
2009-10-29 07:25:58 [ndbd] INFO     -- Configuration fetched at tyr01 port 14000
NDBFS/AsyncFile: Allocating 310392 for In/Deflate buffer
NDBFS/AsyncFile: Allocating 310392 for In/Deflate buffer
NDBFS/AsyncFile: Allocating 310392 for In/Deflate buffer
NDBFS/AsyncFile: Allocating 310392 for In/Deflate buffer
NDBFS/AsyncFile: Allocating 310392 for In/Deflate buffer
NDBFS/AsyncFile: Allocating 310392 for In/Deflate buffer
NDBFS/AsyncFile: Allocating 310392 for In/Deflate buffer
NDBFS/AsyncFile: Allocating 310392 for In/Deflate buffer
NDBFS/AsyncFile: Allocating 310392 for In/Deflate buffer
...

Last log before loop:

NDBFS/AsyncFile: Allocating 310392 for In/Deflate buffer
2009-10-29 09:01:28 [ndbd] INFO     -- Ndbd_mem_manager::init(1) min: 300Mb initial: 556Mb
Adding 556Mb to ZONE_LO (1,17791)
WOPool::init(61, 9)
RWPool::init(22, 13)
...
WARNING: timerHandlingLab now: 6199716488 sent: 6199716378 diff: 110
RWPool::init(c2, 18)
RWPool::init(e2, 18)
WOPool::init(41, 12)
RWPool::init(82, 12)
...
RWPool::init(a2, 52)
WOPool::init(21, 12)
2009-10-29 09:01:31 [ndbd] INFO     -- findNeighbours from: 1975 old (left: 65535 right: 65535) new (3 3)
Dbdict: create name=sys/def/SYSTAB_0,id=0,obj_ptr_i=6
Dbdict: create name=sys/def/NDB$EVENTS_0,id=1,obj_ptr_i=7
Dbdict: create name=TEST_DB/def/TAB0_6196743,id=8,obj_ptr_i=8
Dbdict: create name=TEST_DB/def/TAB1_6196743,id=9,obj_ptr_i=9
Dbdict: create name=TEST_DB/def/TAB2_6196743,id=10,obj_ptr_i=10
...
RESTORE table: 33 0 rows applied
RESTORE table: 33 0 rows applied
RESTORE table: 33 0 rows applied
RESTORE table: 38 130365 rows applied
RESTORE table: 38 130635 rows applied
Applying undo to LCP: 183
2009-10-29 09:01:49 [ndbd] INFO     -- Undo head - undofile02.dat page: 3577 lsn: 4410537
2009-10-29 09:01:49 [ndbd] INFO     --    - next - undofile01.dat(1246057)
2009-10-29 09:02:00 [ndbd] INFO     -- Logfile group: 2 
2009-10-29 09:02:00 [ndbd] INFO     --   head: undofile02.dat page: 3577
2009-10-29 09:02:00 [ndbd] INFO     --   tail: undofile02.dat page: 1283
2009-10-29 09:02:00 [ndbd] INFO     -- Flushing page cache after undo completion
2009-10-29 09:02:02 [ndbd] INFO     -- Flushing complete
RedoPageCache: avoided 0 (0/0) page-reads
RedoOpenFileCache: Avoided 0 file-open/close closed: 0
changing file from 16818188 to 16818176
miss matched writes
dirty pages

How to repeat:
Only seen once in a test that is run frequently
[21 Dec 2009 12:39] 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/95218

3065 Jonas Oreland	2009-12-21
      ndb - bug#48431 - limit #pages written to out-file, when crashing in DbtupDiskAlloc
[21 Dec 2009 12:40] 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/95219

3065 Jonas Oreland	2009-12-21
      ndb - bug#48431 - limit #pages written to out-file, when crashing in DbtupDiskAlloc
[21 Dec 2009 13:22] Jonas Oreland 
pushed to 6.2.19, 6.3.31, 7.0.11
docs: When crashing due to bug in DD, the currently active page-list
  is printed to stdout (ndb_X_out.log). It was discovered that one of 
  those lists could contain a loop, making the printout never end,
  generating endless with data (1.6Tb !!)

  Patch changes so that a maximum of 512 entries will be printed from each list.
[28 Dec 2009 17:39] Jon Stephens 
Documented bugfix in the NDB 6.2.19, 6.3.1, and 7.0.10 changelogs, as follows:

        When a crash occurs due to a problem in Disk Data code, the
        currently active page list is printed to stdout (that is, in
        ndb_node-id_out.log). One of these lists could contain an
        endless loop; this caused a printout that was effectively
        never-ending. Now in such cases, a maximum of 512 entries is
        printed from each list.

Closed.