Just for others to know, it was the memory problem. I re-set the memory
parameters for ndbmtd (two nodes) to minimum. Then I could run the backup
successfully.
Thanks
BA
On Wed, Oct 24, 2012 at 11:57 AM, Bheemsen Aitha <pgbn73@stripped>wrote:
> Hi,
>
> After following the steps at the following website, I tried to do an
> online backup of the cluster.
>
>
>
> http://dev.mysql.com/doc/refman/5.0/en/mysql-cluster-backup-using-management-client.html
>
> It is a plain vanilla command which is below. The cluster is almost an
> empty database, but backup is crashing at least one data node and was never
> successful.
>
> ndb_mgm -e "START BACKUP WAIT COMPLETED"
>
> Did anyone have this kind of error before? I tried searching on web but
> could not find a solution.
>
> Here is the error I received.
>
> Connected to Management Server at: localhost:1186
> Waiting for completed, this may take several minutes
> Backup failed
> * 3001: Could not start backup
> * Backup aborted due to node failure: Permanent error: Internal
> error
>
> ALERT -- Node 2: Backup 2 started from 49 has been aborted. Error: 1326
>
>
> Here is little background about our setup.
>
> OS: Redhat Linux 5.8
> Cluster: MySQL 5.5, NDB 7.2.7
> Cluster was installed and set up on two hosts using MCM, one host hosting
> mysqld, ndb_mgmd and the other hosting
> ndbmtd1 and ndbmtd2.
>
> I even tried by setting up the following parameters, but got the same
> error again.
>
>
> set BackupDataBufferSize:ndbmtd=256M attcluster;
> set BackupLogBufferSize:ndbmtd=256M attcluster;
> set BackupMemory:ndbmtd=512M attcluster;
> set BackupWriteSize:ndbmtd=32M attcluster;
> set BackupMaxWriteSize:ndbmtd=128M attcluster;
>
> Here are some links I found on web similar to my error.
>
>
> http://forums.mysql.com/read.php?25,230891,230959#msg-230959
> http://grokbase.com/t/mysql/cluster/0578z8cj71/backup-error
> http://bugs.mysql.com/bug.php?id=66104
>
>
> mcm> show status -r attcluster;
> +--------+----------+-----------------+---------+-----------+---------+
> | NodeId | Process | Host | Status | Nodegroup | Package |
> +--------+----------+-----------------+---------+-----------+---------+
> | 49 | ndb_mgmd | ut06sandboxdb01 | running | | 7.2.7 |
> | 50 | mysqld | ut06sandboxdb01 | running | | 7.2.7 |
> | 1 | ndbmtd | ut06sandboxdb02 | failed | 0 | 7.2.7 |
> | 2 | ndbmtd | ut06sandboxdb02 | running | 0 | 7.2.7 |
> +--------+----------+-----------------+---------+-----------+---------+
> 4 rows in set (0.07 sec)
>
> mcm>
>
> I see the core dump in DataDir of node 1.
>
> [root@ut06sandboxdb02 data]# ls -ltr
> /opt/app/mcm-1.1.6_64-linux-rhel5-x86/mcm_data/clusters/attcluster/1/data
> total 16949760
> -rw-rw-r-- 1 mysql mysql 0 Oct 19 12:23 ndb_1_out.err
> -rw-rw-r-- 1 mysql mysql 1 Oct 21 04:02 ndb_1_trace.log.next
> -rw-rw-r-- 1 mysql mysql 568 Oct 21 04:02 ndb_1_error.log
> -rw-rw-r-- 1 mysql mysql 12202 Oct 21 04:02 ndb_1_trace.log.1_t4
> -rw-rw-r-- 1 mysql mysql 923467 Oct 21 04:02 ndb_1_trace.log.1_t3
> -rw-rw-r-- 1 mysql mysql 923489 Oct 21 04:02 ndb_1_trace.log.1_t2
> -rw-rw-r-- 1 mysql mysql 934663 Oct 21 04:02 ndb_1_trace.log.1_t1
> -rw-rw-r-- 1 mysql mysql 948989 Oct 21 04:02 ndb_1_trace.log.1
> -rw------- 1 mysql mysql 4104044544 Oct 23 11:04 core.21529
> -rw------- 1 mysql mysql 5880332288 Oct 23 18:22 core.8108
> -rw------- 1 mysql mysql 4538155008 Oct 23 23:56 core.1124
> -rw------- 1 mysql mysql 2924789760 Oct 24 00:32 core.9176
> -rw-rw-r-- 1 mysql mysql 460826 Oct 24 00:33 ndb_1_out.log
>
> Here is more info from mcmd.log. I really appreciate any help on this.
>
>
> 2012-10-23 18:09:58.193: (message) [T0x19add970 RECFG]:
> [1,ndb_mgmd,0]: 2012-10-23 18:09:58 [MgmtSrvr] WARNING -- Node 2: Failed
> to memlock pages, error: 12 (Cannot allocate memory)
> [1,ndb_mgmd,0]: 2012-10-23 18:09:58 [MgmtSrvr] INFO -- Node 2: Waiting
> 30 sec for nodes 1 to connect, nodes [ all: 1 and 2 connected: 2 no-wait: ]
>
> 2012-10-23 18:09:58.193: (message) [T0x19add970 RECFG]:
> [1,ndb_mgmd,0]: 2012-10-23 18:09:58 [MgmtSrvr] INFO -- Node 2: Waiting
> 30 sec for nodes 1 to connect, nodes [ all: 1 and 2 connected: 2 no-wait: ]
>
> 2012-10-23 18:09:58.286: (message) [T0x19add970 RECFG]:
> [1,ndb_mgmd,0]: 2012-10-23 18:09:58 [MgmtSrvr] INFO -- Node 2:
> Communication to Node 1 opened
> [1,ndb_mgmd,0]: 2012-10-23 18:09:58 [MgmtSrvr] INFO -- Node 2: Node 1
> Connected
>
> 2012-10-23 18:09:58.347: (message) last message repeated 1 times
> 2012-10-23 18:09:58.347: (message) [T0x19add970 RECFG]:
> [1,ndb_mgmd,0]: 2012-10-23 18:09:58 [MgmtSrvr] INFO -- Node 1: Node 2
> Connected
> [1,ndb_mgmd,0]: 2012-10-23 18:09:58 [MgmtSrvr] INFO -- Node 1: Node 2:
> API mysql-5.5.25 ndb-7.2.7
> [1,ndb_mgmd,0]: 2012-10-23 18:09:58 [MgmtSrvr] INFO -- Node 2:
> CM_REGCONF president = 1, own Node = 2, our dynamic id = 0/13
> [1,ndb_mgmd,0]: 2012-10-23 18:09:58 [MgmtSrvr] INFO -- Node 2: Node 1:
> API mysql-5.5.25 ndb-7.2.7
> [1,ndb_mgmd,0]: 2012-10-23 18:09:58 [MgmtSrvr] INFO -- Node 2: Start
> phase 1 completed
>
> 2012-10-23 18:09:58.437: (message) last message repeated 1 times
> 2012-10-23 18:09:58.437: (message) [T0x19add970 RECFG]:
> [1,ndb_mgmd,0]: 2012-10-23 18:09:58 [MgmtSrvr] INFO -- Node 2: Start
> phase 2 completed (node restart)
>
> 2012-10-23 18:09:58.467: (message) last message repeated 1 times
> 2012-10-23 18:09:58.467: (message) [T0x19add970 RECFG]:
> [1,ndb_mgmd,0]: 2012-10-23 18:09:58 [MgmtSrvr] INFO -- Node 1: DICT:
> locked by node 2 for NodeRestart
> [1,ndb_mgmd,0]: 2012-10-23 18:09:58 [MgmtSrvr] INFO -- Node 2: Start
> phase 3 completed (node restart)
> [1,ndb_mgmd,0]: 2012-10-23 18:09:58 [MgmtSrvr] INFO -- Node 2: Start
> phase 4 completed (node restart)
>
> 2012-10-23 18:09:59.029: (message) last message repeated 1 times
> 2012-10-23 18:09:59.029: (message) [T0x19add970 RECFG]:
> [1,ndb_mgmd,0]: 2012-10-23 18:09:59 [MgmtSrvr] INFO -- Node 2: Receive
> arbitrator node 49 [ticket=1fac001848b1b289]
>
> 2012-10-23 18:09:59.711: (message) last message repeated 1 times
> 2012-10-23 18:09:59.711: (message) [T0x19add970 RECFG]:
> [1,ndb_mgmd,0]: 2012-10-23 18:09:59 [MgmtSrvr] INFO -- Node 2:
> Starting to restore schema
>
> 2012-10-23 18:10:00.185: (message) last message repeated 1 times
> 2012-10-23 18:10:00.185: (message) [T0x19add970 RECFG]:
> [1,ndb_mgmd,0]: 2012-10-23 18:10:00 [MgmtSrvr] INFO -- Node 2: Restore
> of schema complete
>
> 2012-10-23 18:10:00.216: (message) last message repeated 1 times
> 2012-10-23 18:10:00.216: (message) [T0x19add970 RECFG]:
> [1,ndb_mgmd,0]: 2012-10-23 18:10:00 [MgmtSrvr] INFO -- Node 1: Node
> restart completed copy of dictionary information
> [1,ndb_mgmd,0]: 2012-10-23 18:10:00 [MgmtSrvr] INFO -- Node 2: DICT:
> activate index 6 done (sys/def/5/ndb_index_stat_sample_x1)
>
> 2012-10-23 18:10:00.227: (message) last message repeated 1 times
> 2012-10-23 18:10:00.227: (message) [T0x19add970 RECFG]:
> [1,ndb_mgmd,0]: 2012-10-23 18:10:00 [MgmtSrvr] INFO -- Node 2: GCP
> Monitor: unlimited lags allowed
> [1,ndb_mgmd,0]: 2012-10-23 18:10:00 [MgmtSrvr] INFO -- Node 2: Node
> restart starting to copy the fragments to Node 2
> [1,ndb_mgmd,0]: 2012-10-23 18:10:00 [MgmtSrvr] INFO -- Node 2: Node: 2
> StartLog: [GCI Keep: 124385 LastCompleted: 124437 NewestRestorable: 124454]
>
> 2012-10-23 18:10:02.187: (message) last message repeated 1 times
> 2012-10-23 18:10:02.187: (message) [T0x19add970 RECFG]:
> [1,ndb_mgmd,0]: 2012-10-23 18:10:02 [MgmtSrvr] INFO -- Node 2: LQH:
> Starting to rebuild ordered indexes
> [1,ndb_mgmd,0]: 2012-10-23 18:10:02 [MgmtSrvr] INFO -- Node 2: LQH:
> index 6 rebuild done
> [1,ndb_mgmd,0]: 2012-10-23 18:10:02 [MgmtSrvr] INFO -- Node 2: LQH:
> Rebuild ordered indexes complete
>
> 2012-10-23 18:10:02.296: (message) last message repeated 3 times
> 2012-10-23 18:10:02.296: (message) [T0x19add970 RECFG]:
> [1,ndb_mgmd,0]: 2012-10-23 18:10:02 [MgmtSrvr] INFO -- Node 2: Node
> restart completed copying the fragments to Node 2
>
> 2012-10-23 18:10:03.431: (message) last message repeated 1 times
> 2012-10-23 18:10:03.431: (message) [T0x19add970 RECFG]:
> [1,ndb_mgmd,0]: 2012-10-23 18:10:03 [MgmtSrvr] INFO -- Node 1: Local
> checkpoint 87 started. Keep GCI = 124428 oldest restorable GCI = 124426
>
>
>
>
> Thanks
>
