MySQL Bugs: #24664: Rare problem in LCP, can lead to unability to restart

Bug #24664	Rare problem in LCP, can lead to unability to restart
Submitted:	28 Nov 2006 18:23	Modified:	28 Dec 2006 14:58
Reporter:	Anatoly Pidruchny (Candidate Quality Contributor)
Status:	Closed
Category:	Server: Cluster	Severity:	S3 (Non-critical)
Version:	5.1.12	OS:	Linux (Linux x86_64)
Assigned to:	Jonas Oreland	Target Version:

Description:
A data node fails to restart on a fairly loaded Cluster when it can not restore from a
REDO log. Looks like it happens when the REDO log is overwritten on the other node. But
then I expect a good error message, not an internal program error.

Below is the error log:

========== ndb_3_error.log ==========
Current byte-offset of file-pointer is: 568                       

Time: Tuesday 28 November 2006 - 09:12:17
Status: Temporary error, restart node
Message: Internal program error (failed ndbrequire) (Internal error, programming error or
missing error message, please report a bug)
Error: 2341
Error data: restore.cpp
Error object: RESTORE (Line: 1154) 0x0000000a
Program: ndbd
Pid: 21924
Trace: /sm/mysql/ndb_data/ndb_3_trace.log.6
Version: Version 5.1.12 (beta)
***EOM***
========== ndb_3_error.log ==========

How to repeat:
Put 2-data node Cluster under test load, bring down one of the data nodes, wait for two
local checkpoints to finish, then try to bring the data node back up.

Changed category to Cluster.

Cluster configuration file

Attachment: config.ini (application/octet-stream, text), 861 bytes.

trace log

Attachment: ndb_3_trace.log.6.gz (application/x-gzip, text), 31.28 KiB.

Data node output log

Attachment: ndb_3_out.log (application/octet-stream, text), 32.70 KiB.

Some info about the aborted ndbd process from GDB

Attachment: gdb.out.log (application/octet-stream, text), 10.43 KiB.

Hi,

Is it possible for you to when this happens
1) shutdown rest of cluster (might not be necessary, but to be "safe")
2) upload entire filesystem (including config.ini)
   (to ftp.mysql.com is probably a good idea)

/Jonas

Hi, Jonas,

I have uploaded the file bug-data-24664.tgz into ftp://ftp.mysql.com/pub/mysql/upload.
This is the entire filesystem from the data node 2 after the crash. Please let me know if
this file is OK. I am not sure if the full file has been uploaded. The config.ini file is
already attached to this bug report.

/Anatoly

Hi, Jonas,

did you have a chance to take a look at this one?
I suspect that not the full data file bug-data-24664.tgz has been uploaded, but I can not
check. The length of the file should be 211,244,711 bytes. Please let me know if the file
was uploaded fully or partially. If partially then I will try to upload it again.

Thanks,

/Anatoly

Hi

It looks like it's ok.
shell> ls -l bug-data-24664.tgz 
--w-rw----  1 ftpuploads myftp 211244711 Nov 29 15:27 bug-data-24664.tgz

shell> md5sum bug-data-24664.tgz
8bc7afb3701debb5a10586464a649c23  bug-data-24664.tgz
joreland@production:/supportftp/pub/mysql/upload> 

And I havent had time to look at it yet...

/Jonas

Hi again,

Now actually started on this...
And I really wanted fs for both ndbd's 
Is this possible?

/Jonas

Hi, Jonas,

I have just re-produced the problem. I can send you the filesystems of the both data nodes
2 and 3. But it would take several days to upload them. The previous time when I uploaded
the filesystem of node 2, it took about 18 hours. Can I remove some files from the
filesystems before ziping?

1. I assume that you do not need the BACKUP directory.
2. ndb_2_signal.log is 1474225452 bytes and ndb_3_signal.log is 845740759 bytes. Do you
need these files?
3. ndb_2_out.log is 264316175 bytes and ndb_3_out.log is 169104261 bytes. Do you need
these files as they are? Can I cut history from these files and send you only some number
of last lines?
4. On the filesystem of node 3 there is a core file core.17582, 103632896 bytes. Do you
need this file? I think if you need it, then you also need the ndbd executable file that I
am running, right?

/Anatoly

Hi,

18h puhh...

Anyway I only need the config.ini + the content of FileSystemPath

shell> ls -l ../../ndb_2_fs/
drwxr-x--- 4 jonas users 96 Dec  4 15:15 D1/
drwxr-x--- 3 jonas users 72 Dec  4 15:15 D10/
drwxr-x--- 3 jonas users 72 Dec  4 15:15 D11/
drwxr-x--- 4 jonas users 96 Dec  4 15:15 D2/
drwxr-x--- 3 jonas users 72 Dec  4 15:15 D8/
drwxr-x--- 3 jonas users 72 Dec  4 15:15 D9/
drwxr-x--- 3 jonas users 72 Dec  4 15:15 LCP/

I.e. the actual filesystem...
Is that possible to upload ?

/Jonas

Jonas,

I am going to upload the following two files:

-rw-r--r--  1 apidruch games 340336991 Dec  4 10:19 bug_24664_ndb_2_fs.tgz
-rw-r--r--  1 apidruch games 342450453 Dec  4 10:20 bug_24664_ndb_3_fs.tgz

They are the filesystems of data nodes 2 and 3. The config.ini file is already attached to
this bug report.

/Anatoly

Jonas,

can we use any other way to send the big files to you? Looks like the MySQL FTP service
limits upload speed to less then 3K per second per FTP session. I tried to upload the
files bug_24664_ndb_2_fs.tgz and bug_24664_ndb_3_fs.tgz. My FTP client estimated
completion time to more then 31 hours. So, I canceled the uploads, then split the files
into smaller 30M parts. I tried to upload the following files in parallel:
12/04/2006 11:45 AM 31,457,280 bug_24664_ndb_2_fs.tgz.001
12/04/2006 11:45 AM 31,457,280 bug_24664_ndb_2_fs.tgz.002
12/04/2006 11:45 AM 31,457,280 bug_24664_ndb_2_fs.tgz.003
12/04/2006 11:45 AM 31,457,280 bug_24664_ndb_2_fs.tgz.004
12/04/2006 11:45 AM 31,457,280 bug_24664_ndb_2_fs.tgz.005
12/04/2006 11:45 AM 31,457,280 bug_24664_ndb_2_fs.tgz.006
12/04/2006 11:45 AM 31,457,280 bug_24664_ndb_2_fs.tgz.007
12/04/2006 11:45 AM 31,457,280 bug_24664_ndb_2_fs.tgz.008
12/04/2006 11:45 AM 31,457,280 bug_24664_ndb_2_fs.tgz.009
12/04/2006 11:46 AM 31,457,280 bug_24664_ndb_2_fs.tgz.010
12/04/2006 11:46 AM 25,764,191 bug_24664_ndb_2_fs.tgz.011

Only the last part was uploaded successfully, all other files failed to upload after more
then 90% was uploaded, because something happened and all FTP upload sessions failed. I
think it is MySQL FTP server to blame. Now I can not re-start the upload of these files
again, because probably parts of these files already exist on the server and FTP server
does not allow to overwrite them.

I can send the files by email, I can upload them to some other FTP server (e.g.,
megaupload.com), I can send files using "Send File" command in a messenger, whatever works
for you. I can also try to upload them again. But then please clean the files that were
uploaded partially. These are the files bug_24664_ndb_2_fs.tgz.001 to
bug_24664_ndb_2_fs.tgz.010, and also bug_24664_ndb_3_fs.tgz.003 and
bug_24664_ndb_3_fs.tgz.005.

/Anatoly

Hi,

any "ftp"-site that works for you works for me.

I never used megaupload.com, but if you think it will work, then let's try it...

/Jonas

ps. I removed the files from our ftp-site. ds.

Jonas,

by using a better FTP client I was able to upload both files to MySQL FTP server. Please
delete any part files if still remaining. The MD5 checksums of the uploaded files are:

bug_24664_ndb_2_fs.tgz 5DF851324A5B67E9699BC3E7A15F6B58
bug_24664_ndb_3_fs.tgz B6AF999DB4C2F13E862FF95AA8261B79

/Anatoly

Hi,

Thx for files.

FYI: making progress...it looks like I made a thinking error 
     and only enabled the lcp-snapshot for DD tables, which
     is very incorrect...or actually either way...
     will look more, expect to have patch quite soon...

BTW: Thx again for brilliant bug reports, and lots of help

/Jonas

Now have "semi" reproducable testcase...
(using error inserts...)

Quite tricky to write test prg for this...

/Jonas

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/16456

ChangeSet@1.2343, 2006-12-05 15:10:56+01:00, jonas@perch.ndb.mysql.com +7 -0
  ndb - bug#24664
    1) run lcp snapshot for both MM and DD tables (so I dont have to change restore to use
WRITE)
    2) fix >= and > bug in lcp skip/keep handling
    3) very cool test prog for this :-)

Hi,

I now think I fixed it.

Could you test patch attached to bug report.
It's only the "dbtup/*"-part which is actual fix
rest is new debug code to be able to trigger bug...

Let me know how it goes

/Jonas

and again, thx for all help

Hi, Jonas.

I wanted to do a rolling upgrade of the two data nodes without bringing down the cluster.
So I shut down node 2, then upgraded the software, then tried to start node 2 with "ndbd
--initial --core". It crashed during startup on Phase 5. Here is the error log:

Current byte-offset of file-pointer is: 568                       

Time: Tuesday 5 December 2006 - 12:29:58
Status: Temporary error, restart node
Message: Internal program error (failed ndbrequire) (Internal error, programming error or
missing error message, please report a bug)
Error: 2341
Error data: dbtup/DbtupScan.cpp
Error object: DBTUP (Line: 1064) 0x0000000e
Program: ndbd
Pid: 8621
Trace: /sm/mysql/ndb_data/ndb_2_trace.log.1
Version: Version 5.1.12 (beta)
***EOM***

It crashed on the ndbrequire that was added by your patch for this bug. I think I am
missing some other patch. The thing is, the following change was rejected by the "patch
-p1" command:

***************
*** 1052,1075 ****
    tablePtr.i = req->tableId;
    ptrCheckGuard(tablePtr, cnoOfTablerec, tablerec);
  
-   if(tablePtr.p->m_no_of_disk_attributes)
-   {
-     jam();
-     FragrecordPtr fragPtr;
-     Uint32 fragId = req->fragmentId;
-     fragPtr.i = RNIL;
-     getFragmentrec(fragPtr, fragId, tablePtr.p);
-     ndbrequire(fragPtr.i != RNIL);
-     Fragrecord& frag = *fragPtr.p;
-     
-     ndbrequire(frag.m_lcp_scan_op == RNIL && c_lcp_scan_op != RNIL);
-     frag.m_lcp_scan_op = c_lcp_scan_op;
-     ScanOpPtr scanPtr;
-     c_scanOpPool.getPtr(scanPtr, frag.m_lcp_scan_op);
-     ndbrequire(scanPtr.p->m_fragPtrI == RNIL);
-     scanPtr.p->m_fragPtrI = fragPtr.i;
-     
-     scanFirst(signal, scanPtr);
-     scanPtr.p->m_state = ScanOp::First;
-   }
  }
--- 1051,1071 ----
    tablePtr.i = req->tableId;
    ptrCheckGuard(tablePtr, cnoOfTablerec, tablerec);
  
+   jam();
+   FragrecordPtr fragPtr;
+   Uint32 fragId = req->fragmentId;
+   fragPtr.i = RNIL;
+   getFragmentrec(fragPtr, fragId, tablePtr.p);
+   ndbrequire(fragPtr.i != RNIL);
+   Fragrecord& frag = *fragPtr.p;
+   
+   ndbrequire(frag.m_lcp_scan_op == RNIL && c_lcp_scan_op != RNIL);
+   frag.m_lcp_scan_op = c_lcp_scan_op;
+   ScanOpPtr scanPtr;
+   c_scanOpPool.getPtr(scanPtr, frag.m_lcp_scan_op);
+   ndbrequire(scanPtr.p->m_fragPtrI == RNIL);
+   scanPtr.p->m_fragPtrI = fragPtr.i;
+   
+   scanFirst(signal, scanPtr);
+   scanPtr.p->m_state = ScanOp::First;
  }

So, I applied these changes manually. The reason this change was rejected is because in
the original file version that I had this last ndbrequire was commented out, like this:

    //ndbrequire(scanPtr.p->m_fragPtrI == fragPtr.i); ?

The file storage/ndb/src/kernel/blocks/dbtup/DbtupScan.cpp that I had is the file that
goes in MySQL version 5.1.12, you can see what I mean if you look at that version of the
file.

What do you want me to do now? Should I apply some more patch(es)?

/Anatoly

Hi,

Apply pathc to bug http://bugs.mysql.com/bug.php?id=24331 before
applying this patch...

/Jonas

Jonas,

I applied that patch for bug 24331 as well. I stopped node 2, upgraded the NDB software,
then tried to start the node just with "ndbd --core". It crashed during startup phase 4.
Here is the error log:
Current byte-offset of file-pointer is: 568                       

Time: Tuesday 5 December 2006 - 13:34:04
Status: Temporary error, restart node
Message: Internal program error (failed ndbrequire) (Internal error, programming error or
missing error message, please report a bug)
Error: 2341
Error data: restore.cpp
Error object: RESTORE (Line: 1154) 0x0000000a
Program: ndbd
Pid: 8744
Trace: /sm/mysql/ndb_data/ndb_2_trace.log.1
Version: Version 5.1.12 (beta)
***EOM***

The other data node 3 is still running without these patches applied and I do not want to
shut down the whole cluster. I can give you more information about this crash if you want.
Now I am going to try to start the node 2 with "--initial --core".

/Anatoly.

Hi,

The patch fixes writing of LCP...
So it's expected that you need to start node "--initial"

Sorry for not mentioning this...

/Jonas

Jonas,

I think I can confirm now that your patch fixes the problem! After the rolling restart of
my data nodes with --initial, I tested several times the shutdown and restart of the data
nodes without --initial, and there were no crashes. Thank you very much for the great job
that you are doing!

/Anatoly

pushed into 5.1-new-ndb

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/16777

ChangeSet@1.2352, 2006-12-11 16:18:34+01:00, jonas@perch.ndb.mysql.com +1 -0
  ndb - bug#24664
    Fix in bug fix, make sure LCP_SKIP is only used for inserts...

Fixed bug

Thank you for your bug report. This issue has been committed to our source repository of
that product and will be incorporated into the next release.

If necessary, you can access the source repository and build the latest available version,
including the bug fix. More information about accessing the source trees is available at

    http://dev.mysql.com/doc/en/installing-source.html

Documented fix in 5.1.15 changelog.