Solution: Although I haven't found a proper solution yet I'm at least sure that this is purely a disk I/O problem and has nothing to do with MySQL...
I have a MySQL server (5.1.54-1ubuntu4-log) running on an Core i7 950 8-core-machine (24 GB RAM, 2x1.5 TB SATA-disks in software RAID 1) that hosts a database with two MyISAM tables. The first table is called stats the second table is called users. The stats table is basically used for logging, part of which are unique user-id's. Once per day all new user-id's are inserted into the users table using an INSERT ... SELECT query like so:
INSERT LOW_PRIORITY IGNORE
INTO users(id)
SELECT s.user_id
FROM `stats` s
WHERE 1
AND s.created_at BETWEEN '2011-10-18 00:00:00' AND '2011-10-18 23:59:59'
GROUP BY s.user_id;
Whenever I issue a query like this, which takes about 30 seconds to execute, the server becomes completely unresponsive, i.e. I can't even issue ls (it takes forever), open ssh connections freeze, server density sends alerts, that it doesn't receive any data, and so on...
The first thing I notice is that MySQL uses some CPU and does heavy disk I/O:
PID RUID EUID THR SYSCPU USRCPU VGROW RGROW RDDSK WRDSK ST EXC S CPUNR CPU CMD 1/6
12497 mysql mysql 20 0.31s 3.70s 0K -260K 0K 301.4M -- - S 7 40% mysqld
These values drop to 0 after a few seconds, then atop doesn't show any %CPU but the 1-minute load average jumps up considerably (from ~0.0 to >2) and very high disk I/O is reported on one of the two harddisks that are in the RAID 1 (it randomly changes between sda and sdb):
MDD | md2 | busy 0% | read 0 | write 6 | KiB/r 0 | | KiB/w 4 | MBr/s 0.00 | MBw/s 0.00 | avq 0.00 | avio 0.00 ms |
DSK | sda | busy 107% | read 0 | write 3946 | KiB/r 0 | | KiB/w 18 | MBr/s 0.00 | MBw/s 7.27 | avq 143.87 | avio 2.53 ms |
DSK | sdb | busy 33% | read 0 | write 4670 | KiB/r 0 | | KiB/w 16 | MBr/s 0.00 | MBw/s 7.69 | avq 25.77 | avio 0.66 ms |
This is also the point where the server becomes unresponsive.
I have seen the same behavior with other very I/O intensive INSERT ... SELECT or INSERT ... ON DUPLICATE KEY UPDATE queries.
Is this due to a poorly configured MySQL server? Or maybe a badly configured software raid? Or could it even be a hardware issue? Can I provide more information? I'm thankful for any hints and suggestions.
Update 1 2011-10-20:
Some more information about the RAID/Swap setup:
$ cat /proc/mdstat
Personalities : [raid1] [raid0] [raid6] [raid5] [raid4] [raid10] [linear] [multipath]
md1 : active raid1 sdb2[1] sda2[0]
264960 blocks [2/2] [UU]
md2 : active raid1 sdb3[1] sda3[0]
1462766336 blocks [2/2] [UU]
md0 : active raid1 sdb1[1] sda1[0]
2102464 blocks [2/2] [UU]
Output of free shortly before system hangs:
$ free -t
total used free shared buffers cached
Mem: 24733872 21613360 3120512 0 310988 17130316
-/+ buffers/cache: 4172056 20561816
Swap: 2102460 0 2102460
Total: 26836332 21613360 5222972
And the swappiness:
$ sysctl vm.swappiness
vm.swappiness = 60
top output during the time where the system is in the unresponsive state:
$ top
top - 10:25:42 up 15 days, 21:15, 3 users, load average: 2.35, 0.96, 0.48
Tasks: 145 total, 1 running, 142 sleeping, 1 stopped, 1 zombie
Cpu(s): 0.0%us, 0.1%sy, 0.0%ni, 63.5%id, 36.4%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 24733872k total, 21670104k used, 3063768k free, 311056k buffers
Swap: 2102460k total, 0k used, 2102460k free, 17207236k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
246 root 20 0 0 0 0 D 0 0.0 0:53.70 md2_raid1
8337 me 20 0 19352 1464 1076 R 0 0.0 0:00.15 top
29999 root 39 19 183m 5724 1520 S 0 0.0 0:24.56 php5-fpm
1 root 20 0 23984 2116 1332 S 0 0.0 0:05.34 init
2 root 20 0 0 0 0 S 0 0.0 0:00.00 kthreadd
3 root 20 0 0 0 0 S 0 0.0 0:02.22 ksoftirqd/0
4 root 20 0 0 0 0 S 0 0.0 0:44.11 kworker/0:0
... more kernel tasks ...
Output of vmstat during one of the queries:
$ vmstat 3
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
0 0 0 2901468 311248 17395360 0 0 0 7 3 0 0 0 99 0
1 0 0 2892880 311256 17402756 0 0 0 0 179 238 7 0 93 0
1 0 0 2867220 311264 17414812 0 0 0 0 191 249 10 1 88 0
1 4 0 2818084 311264 17415600 0 0 0 105571 849 706 4 0 67 28
0 4 0 2821948 311264 17415600 0 0 0 0 941 72 0 0 64 36
0 4 0 2826288 311264 17415600 0 0 0 7 936 72 0 0 65 35
0 4 0 2829264 311264 17415600 0 0 0 0 703 59 0 0 64 36
0 6 0 2833728 311264 17415600 0 0 0 0 965 87 0 0 53 46
0 6 0 2838316 311264 17415600 0 0 0 0 1007 77 0 0 65 35
0 7 0 2841548 311264 17415600 0 0 0 0 1041 80 0 0 65 35
0 7 0 2844764 311264 17415600 0 0 0 0 1059 72 0 0 64 36
0 7 0 2848732 311264 17415600 0 0 0 0 964 62 0 0 55 45
0 8 0 2850972 311264 17415600 0 0 0 0 859 60 0 0 59 41
1 10 0 2853328 311264 17415600 0 0 0 0 996 66 0 0 52 48
0 10 0 2855560 311264 17415600 0 0 0 0 862 70 0 0 56 44
0 10 0 2857668 311264 17415600 0 0 0 0 959 71 0 0 37 63
0 10 0 2859900 311264 17415600 0 0 0 0 882 54 0 0 53 47
0 9 0 2862760 311264 17415600 0 0 0 0 982 65 0 0 54 46
Table locks:
mysql> SHOW STATUS LIKE 'Table%';
+-----------------------+-------+
| Variable_name | Value |
+-----------------------+-------+
| Table_locks_immediate | 64386 |
| Table_locks_waited | 62856 |
+-----------------------+-------+
Explain select:
mysql> EXPLAIN SELECT s.user_id FROM stats s WHERE 1 AND s.created_at BETWEEN '2011-10-17 00:00:00' AND '2011-10-18 23:59:59' GROUP BY s.user_id;
+----+-------------+-------+------+---------------+------+---------+------+---------+----------------------------------------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+-------+------+---------------+------+---------+------+---------+----------------------------------------------+
| 1 | SIMPLE | s | ALL | NULL | NULL | NULL | NULL | 5348073 | Using where; Using temporary; Using filesort |
+----+-------------+-------+------+---------------+------+---------+------+---------+----------------------------------------------+
Update 2 2011-10-20:
I have run the same tests on a different machine (Core2Duo 2.7 GHz, 4 GB Ram, 2 SATA-HD's in software RAID 1) with the same software versions and things look similar but different:
- After an initial high cpu% caused by mysql, total cpu% drops to 0
- Disk-writes jump up, as do load averages
- System becomes slow but yet not entirely unresponsive as with the other machine
So maybe I really have to rethink the MySQL query since it seems to cause too much disk I/O at a time.
Is there a way to limit the disk I/O that the mysql-server is allowed to perform?
Update 3 2011-10-20:
Issuing a simple sudo dd if=/dev/zero of=/hugefile bs=1M count=4096 also results in the system being stalled. atop reports for memory and disk:
MEM | tot 23.6G | free 371.0M | cache 18.6G | dirty 1.1G | buff 109.3M | | slab 1.1G | | | | |
SWP | tot 2.0G | free 2.0G | | | | | | | | vmcom 4.6G | vmlim 13.8G |
MDD | md2 | busy 0% | read 2 | write 0 | KiB/r 8 | | KiB/w 0 | MBr/s 0.00 | MBw/s 0.00 | avq 0.00 | avio 0.00 ms |
DSK | sda | busy 106% | read 2 | write 2045 | KiB/r 8 | | KiB/w 509 | MBr/s 0.00 | MBw/s 101.85 | avq 97.65 | avio 4.89 ms |
DSK | sdb | busy 106% | read 0 | write 2042 | KiB/r 0 | | KiB/w 510 | MBr/s 0.00 | MBw/s 101.75 | avq 146.56 | avio 4.90 ms |
created_atfield, as without an index MySQL needs to do a whole lot more work. – John Gardeniers Oct 19 '11 at 22:31topandfreeoutput would be helpful) Also do you have monitoring on pages in/out from the VM system? What is vm.swappiness set to? (sysctl) This feels like mysql is configured to consume too much memory and you are running into swap, which is why everything is slow. – polynomial Oct 20 '11 at 3:49