You are here
Why does MySQL Cluster takes so long for --initial?
This week we had a very interesting problem at a customer: They complained, that their MySQL Cluster takes about 1 hour for a --initial
start-up. After some tuning on the hardware and the config.ini
they brought it down to around 40 minutes. But this is still unacceptable long...
This sounds a little strange to me. But let us have a look at their config.ini
first. It looked more or less like the following (which is already tuned!):
# # config.ini # [NDB_MGMD DEFAULT] DataDir = /localdisk/cluster [NDBD DEFAULT] DataDir = /localdisk/cluster NoOfReplicas = 2 LockPagesInMainMemory = 1 DataMemory = 12000M IndexMemory = 2000M FragmentLogFileSize = 256M NoOfFragmentLogFiles = 42 DiskCheckpointSpeedInRestart = 100M ODirect = 1 BackupMaxWriteSize = 1M BackupDataBufferSize = 16M BackupLogBufferSize = 4M BackupMemory = 20M [NDB_MGMD] id = 1 hostname = 192.168.0.1 [NDBD] id = 10 hostname = 192.168.0.10 [NDBD] id = 11 hostname = 192.168.0.11 [MYSQLD] [MYSQLD] [MYSQLD] [MYSQLD] [MYSQLD]
So the config.ini
looks fine. But why does it take so long? Let us have a look who is the evil guy:
# grep phase ndb_1_cluster.log | grep "Node 10" 2008-10-24 12:24:16 [MgmSrvr] INFO -- Node 10: Start phase 1 completed 2008-10-24 12:24:16 [MgmSrvr] INFO -- Node 10: Start phase 2 completed (initial start) 2008-10-24 12:24:16 [MgmSrvr] INFO -- Node 10: Start phase 3 completed (initial start) 2008-10-24 13:03:03 [MgmSrvr] INFO -- Node 10: Start phase 4 completed (initial start) 2008-10-24 13:03:08 [MgmSrvr] INFO -- Node 10: Start phase 5 completed (initial start) 2008-10-24 13:03:08 [MgmSrvr] INFO -- Node 10: Start phase 6 completed (initial start) 2008-10-24 13:03:08 [MgmSrvr] INFO -- Node 10: Start phase 7 completed (initial start) 2008-10-24 13:03:08 [MgmSrvr] INFO -- Node 10: Start phase 8 completed (initial start) 2008-10-24 13:03:08 [MgmSrvr] INFO -- Node 10: Start phase 9 completed (initial start) 2008-10-24 13:03:08 [MgmSrvr] INFO -- Node 10: Start phase 100 completed (initial start) 2008-10-24 13:03:08 [MgmSrvr] INFO -- Node 10: Start phase 101 completed (initial start)
Start phase 4 is the one! But what is start phase 4? According to the MySQL Cluster documentation start phase 4 means:
Phase 4. For an initial start or initial node restart, the redo log files are created. The number of these files is equal to NoOfFragmentLogFiles
.
Creating the redo log files is the problem! I have never created a MySQL Cluster with 42 Gbyte of redo log file (42 x 4 x 256Mbyte) myself so I have no practical experience with it how long it should take.
What I did first was a rough calculation of the value I would expect:
43'008 Mbyte : 50 Mbyte/s = 860 s = 15 minutes
After 15 minutes I would expect the cluster to be up and running (plus some seconds for the other phases). What I expect seems not to be the same as what happens... :-(
I turned on iostat
(by the way: IMHO iostat
(sysstat
packages) belongs on every server which does some kind of I/O!):
# iostat -x 1 avg-cpu: %user %nice %system %iowait %steal %idle 0.00 0.00 0.12 18.35 0.00 81.52 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util sda 0.00 193.00 0.00 55.00 0.00 2016.00 0.00 1008.00 36.65 2.13 38.55 18.18 100.00 avg-cpu: %user %nice %system %iowait %steal %idle 0.00 0.00 0.25 18.88 0.00 80.88 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util sda 0.00 192.00 0.00 48.00 0.00 2088.00 0.00 1044.00 43.50 1.72 35.50 20.83 100.00 avg-cpu: %user %nice %system %iowait %steal %idle 0.00 0.00 0.00 19.12 0.00 80.88 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util sda 0.00 200.00 0.00 47.00 0.00 2088.00 0.00 1044.00 44.43 1.69 35.91 21.28 100.00
OK. As we can see, the I/O device is fully utilized. Good to know. Looks like we have an I/O problem! We do only around 50 w/s which is really bad (normal disks can do around 150 - 250 w/s) and we write with a throughput of 1 MByte/s (is about 20 kbyte/write) instead of 50 Mbyte/s.
What came to my mind is, that earlier this year I have written an article about Sparse files. I found then, that MySQL Cluster writes the redo log files as sparse files to disk. Could this have an impact? But we have never had any complains about this from other customers...
So what I did next: I tried on a completely different hardware from an other vendor and it took only 13 minutes! The problem seems to be NOT MySQL Cluster (alone) related! On our machines we have also an NFS mount. So let us try there: Even worse: 10 minutes! Then we did a synthetical test on the hardware:
# dd if=/dev/zero of=redo_log.42g count=0 obs=1 seek=42G # dd if=/dev/zero of=redo_log.42g bs=32K count=1376256 of=direct
This was running in 12 minutes! I was confused. Maybe my simulation has to be more complex:
#!/bin/bash let i=1 # 1376256 while [[ $i -le ]] ; do dd if=/dev/zero of=big_file.42g obs=512 count=1 seek=32K let i=$i+1 done
No results which come close to the thing I have seen from MySQL Cluster...
Let us summarize:
Our servers with Mysql Cluster: 37 minutes Test servers with Mysql Cluster: 13 minutes Our servers with dd: 12 minutes Our servers with NFS: 10 minutes
This does not make sense to me. I need the PERFECT simulation!
For knowing more, how the redo log files were created I run a trace on the ndbd
process during the creation:
# strace -o ndbd.trace -ff -s 128 -p <ndbd_pid> <ndbd_pid>
As a result I got this:
open("/localdisk/cluster/ndb_11_fs/D10/DBLQH/S3.FragLog", O_RDWR|O_CREAT|O_TRUNC|O_DIRECT, 0666) = 17 lseek(17, 268402688, SEEK_SET) = 268402688 # 256M - 32k write(17, "..."..., 32768) = 32768 fsync(17) = 0 lseek(17, 0, SEEK_SET) = 0 write(17, "..."..., 32768) = 32768 fsync(17) = 0 lseek(17, 1048576, SEEK_SET) = 1048576 write(17, ""..., 32768) = 32768 fsync(17) = 0 lseek(17, 2097152, SEEK_SET) = 2097152 write(17, ""..., 32768)= 32768 fsync(17) = 0 ... lseek(17, 267386880, SEEK_SET) = 267386880 write(17, ""..., 32768) = 32768 fsync(17) = 0 close(17) = 0
OK. I see, my simulation up to now was not yet good enough... I need a Perl script to simulate this more exactly. The script you can find here: cluster_initial_test.pl.
Before I run the script I was pretty nervous: Would it work? But after a few minutes it was already clear: It has the wanted effect. After around 1/3 of the redo log files were created I estimated the end time to 59 minutes and when it ended it took around 50 minutes. Perfect!
After I came back from a short jig I was thinking about why it took longer than 40 minutes... What I can see from the system statistics is, that the I/O system is more relaxed with my script than with the original MySQL Cluster --initial
restart.
# iostat -x 1 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util sda 0.00 161.39 0.00 49.50 0.00 1798.02 0.00 899.01 36.32 1.05 20.40 14.32 70.89 sda 0.00 176.00 0.00 51.00 0.00 1920.00 0.00 960.00 37.65 1.07 21.18 14.04 71.60 sda 0.00 170.71 0.00 46.46 0.00 1882.83 0.00 941.41 40.52 0.99 21.22 15.74 73.13
So it is about 25-33% less utilized. MySQL Cluster creates the redo log files with 4 threads in parallel. For me this is a sufficient exact explanation for the moment why it takes longer.
We are able to decouple now the hardware problem from the software product. I cannot really help the hardware guys to solve their problem, but at least we were able to give them a simulation of the problem. So they can run the tests without us.
On the other hand MySQL Cluster is doing exactly what I always tell my customers not to do: "COMMIT
after every INSERT
". This is the worst thing what you can do with an I/O system. MySQL Cluster does a sync to disk after every 32k block (1 block per Mbyte).
So I was talking to Jonas, one of our MySQL Cluster developers, and told him the whole story. He was just asking me: Is 14:00 early enough for the patch?
Before 14:00 I had already the patch in my mailbox. We applied it and tested it and...
5 minutes 12 seconds!
So I think now everybody should be happy?
Addendum:
- The perl script could be improved by:
sysopen(HANDLE, $path, O_RDWR|O_CREAT|O_EXCL|O_DIRECT) or die "sysopen $path: $!";
- Maybe the problem could be also simulated much easier with dd like this:
# dd if=/dev/zero of=redo_log.42g bs=1M count=43008 of=direct conv=fsync
- You can find the patch here: Bug #40734
- Shinguz's blog
- Log in or register to post comments
Comments
Why does MySQL Cluster takes so long for --initial?
Why does MySQL Cluster takes so long for --initial?
Why does MySQL Cluster takes so long for --initial?
Why does MySQL Cluster takes so long for --initial?