2013.05.27
OpenStack構築後にCPU負荷が異様に高まったのでその対応
OpenStackは以下を参考にインストール。
http://docs.openstack.org/grizzly/basic-install/apt/content/
インストールバージョンはgrizzly。
OSはUbuntu12.04。
コントローラノード1台、ネットワークノード1台、コンピュータノード2台の構成。
で、インストール後管理画面を開くと異様に遅いOpenStackが。
とりあえずvmstatで状況を確認。
hoge@fuga:~$ vmstat 1 procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu---- r b swpd free buff cache si so bi bo in cs us sy id wa 1 1 34888 73116 35168 881976 0 0 2151 139 83 6 6 1 51 41 0 1 34888 68032 35200 887116 0 0 5068 76 638 1142 4 1 48 47 1 0 34888 75720 35144 879248 0 0 6944 48 580 1052 3 1 49 48 0 1 34888 72124 35144 882692 0 0 4816 0 316 653 1 1 50 49 2 0 34888 67412 35184 887384 0 0 4736 828 576 1058 3 1 48 48 0 1 34888 74232 35168 880540 0 0 5580 64 1149 2193 7 1 45 46 0 1 34888 70512 35192 884328 0 0 3712 80 885 1625 5 1 45 49 0 1 34888 65428 35200 889336 0 0 5008 24 473 899 2 1 45 53 0 1 34888 73240 35120 881360 0 0 5872 28 458 847 2 1 51 47 0 1 34888 68776 35160 885860 0 0 4480 104 672 1174 4 1 40 56 0 1 34888 64808 35176 889948 0 0 4016 52 547 1064 3 1 49 48 0 1 34888 72124 35148 882600 0 0 5120 0 300 638 1 0 50 49 0 1 34888 66420 35148 888280 0 0 5664 0 310 627 1 1 50 49 0 1 34888 75100 35100 879676 0 0 3760 52 1135 2110 9 1 42 49 0 1 34888 71504 35180 883196 0 0 3620 1052 1161 2023 6 2 43 50
CPUのwaitが高過ぎますね。
hoge@fuga:~$ top
top - 14:37:50 up 2 days, 21:56, 1 user, load average: 1.67, 1.54, 1.46
Tasks: 138 total, 2 running, 136 sleeping, 0 stopped, 0 zombie
Cpu(s): 3.8%us, 1.0%sy, 0.0%ni, 47.8%id, 47.3%wa, 0.0%hi, 0.2%si, 0.0%st
Mem: 2050020k total, 1977740k used, 72280k free, 23848k buffers
Swap: 2097148k total, 34888k used, 2062260k free, 894848k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
1436 mysql 20 0 1310m 191m 3928 S 2 9.6 100:21.52 mysqld
1996 rabbitmq 20 0 1139m 106m 1844 S 2 5.3 97:33.42 beam.smp
1341 quantum 20 0 186m 39m 3748 S 1 2.0 100:18.12 python
1345 cinder 20 0 91428 19m 3324 S 1 1.0 22:43.32 cinder-volume
1362 nova 20 0 213m 49m 3712 S 0 2.5 1:44.69 nova-consoleaut
1397 cinder 20 0 197m 35m 3672 S 0 1.8 2:20.62 cinder-schedule
1 root 20 0 24584 2156 1132 S 0 0.1 4:37.98 init
load averageも高い。動いてるのは強いて言えばmysqldぽい。
beam.smpは見かけない子なのでググってみるとRabbitMQの関係の子らしい。特に原因には関係ないぽい。
ひたすらwaitなのでIOも確認してみる。
hoge@fuga:~$ sudo iotop
Total DISK READ: 4.95 M/s | Total DISK WRITE: 144.30 K/s
TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
22748 be/4 mysql 4.78 M/s 0.00 B/s 0.00 % 96.90 % mysqld
2227 be/4 rabbitmq 0.00 B/s 7.80 K/s 0.00 % 17.65 % beam.smp -W w -K true -A30 -P 1048576 --~ir "/var/lib/rabbitmq/mnesia/rabbit@fuga"
27136 be/4 www-data 0.00 B/s 0.00 B/s 0.00 % 0.00 % apache2 -k start
1 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % init
2 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % [kthreadd]
3 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.00 % [ksoftirqd/0]
mysqldが犯人で確定。
mysqlが何してるのか確認してみる。
mysql> show processlist; +------+----------+-----------+----------+---------+------+--------------+------------------------------------------------------------------------------------------------------+ | Id | User | Host | db | Command | Time | State | Info | +------+----------+-----------+----------+---------+------+--------------+------------------------------------------------------------------------------------------------------+ | 1923 | quantum | localhost | quantum | Sleep | 1 | | NULL | | 1924 | nova | localhost | nova | Sleep | 1 | | NULL | | 1925 | nova | localhost | nova | Sleep | 1 | | NULL | | 1926 | nova | localhost | nova | Sleep | 6 | | NULL | | 1927 | cinder | localhost | cinder | Sleep | 3 | | NULL | | 1928 | cinder | localhost | cinder | Sleep | 7 | | NULL | | 1929 | nova | localhost | nova | Sleep | 11 | | NULL | | 1931 | nova | localhost | nova | Sleep | 7 | | NULL | | 1932 | nova | localhost | nova | Sleep | 7 | | NULL | | 1933 | quantum | localhost | quantum | Sleep | 1 | | NULL | | 1935 | quantum | localhost | quantum | Sleep | 1 | | NULL | | 1936 | quantum | localhost | quantum | Sleep | 0 | | NULL | | 1938 | nova | localhost | nova | Sleep | 16 | | NULL | | 1939 | nova | localhost | nova | Sleep | 6 | | NULL | | 1946 | quantum | localhost | quantum | Sleep | 2 | | NULL | | 1949 | nova | localhost | nova | Sleep | 1 | | NULL | | 1950 | keystone | localhost | keystone | Query | 238 | Sending data | SELECT token.id AS token_id, token.expires AS token_expires, token.extra AS token_extra, token.valid | | 1951 | root | localhost | NULL | Query | 0 | NULL | show processlist | +------+----------+-----------+----------+---------+------+--------------+------------------------------------------------------------------------------------------------------+
keystoneがデータを送り続けてるらしい。
keystoneのログを見てみる。
root@fuga:/var/log/keystone# tail -f keystone.log
2013-05-27 14:50:00 INFO [sqlalchemy.engine.base.Engine] SELECT role.id AS role_id, role.name AS role_name, role.extra AS role_extra_
FROM role_
WHERE role.id = %s_
LIMIT %s
2013-05-27 14:50:00 INFO [sqlalchemy.engine.base.Engine] ('bc1d3f04415a4feb89fee7ad327a9f6b', 1)
2013-05-27 14:50:00 DEBUG [keystone.policy.backends.rules] enforce admin_required: {'tenant_id': u'b1493d6491b54dcabb33792632df4945', 'user_id': u'6b06407ab6be40c7a90185774d082921', u'roles': [u'_member_', u'admin']}
2013-05-27 14:50:00 INFO [sqlalchemy.engine.base.Engine] SELECT token.id AS token_id, token.expires AS token_expires, token.extra AS token_extra, token.valid AS token_valid, token.user_id AS token_user_id, token.trust_id AS token_trust_id_
FROM token_
WHERE token.expires > %s AND token.valid = %s
2013-05-27 14:50:00 INFO [sqlalchemy.engine.base.Engine] (datetime.datetime(2013, 5, 27, 5, 50, 0, 186563), 0)
確かにkeystoneが投げてるクエリっぽい。
mysqlに入って実行してみる。
mysql> SELECT token.id AS token_id, token.expires AS token_expires, token.extra AS token_extra, token.valid AS token_valid, token.user_id AS token_user_id, token.trust_id AS token_trust_id FROM token WHERE token.expires > '2013-05-27 06:11:45' and token.valid = 0; Empty set (4 min 44.50 sec)
5分近くかかってる。こいつがつまってそう。
レコード数を確認してみる。
mysql> select table_name,table_rows,data_length/1024/1024 as 'data/MB',index_length/1024/1024 as 'index/MB' from information_schema.TABLES where table_schema='keystone'; +------------------------+------------+---------------+------------+ | table_name | table_rows | data/MB | index/MB | +------------------------+------------+---------------+------------+ | credential | 0 | 0.01562500 | 0.03125000 | | domain | 1 | 0.01562500 | 0.01562500 | | ec2_credential | 0 | 0.01562500 | 0.00000000 | | endpoint | 18 | 0.01562500 | 0.01562500 | | group | 0 | 0.01562500 | 0.01562500 | | group_domain_metadata | 0 | 0.01562500 | 0.01562500 | | group_project_metadata | 0 | 0.01562500 | 0.01562500 | | migrate_version | 1 | 0.01562500 | 0.00000000 | | policy | 0 | 0.01562500 | 0.00000000 | | project | 3 | 0.01562500 | 0.01562500 | | role | 3 | 0.01562500 | 0.01562500 | | service | 6 | 0.01562500 | 0.00000000 | | token | 152946 | 1098.00000000 | 0.00000000 | | trust | 0 | 0.01562500 | 0.00000000 | | trust_role | 0 | 0.01562500 | 0.00000000 | | user | 6 | 0.01562500 | 0.01562500 | | user_domain_metadata | 0 | 0.01562500 | 0.01562500 | | user_group_membership | 0 | 0.01562500 | 0.01562500 | | user_project_metadata | 6 | 0.01562500 | 0.01562500 | +------------------------+------------+---------------+------------+ 19 rows in set (0.07 sec)
多いな。
インデックスを確認してみる。
mysql> show index from token; +-------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+ | Table | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment | +-------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+ | token | 0 | PRIMARY | 1 | id | A | 145268 | NULL | NULL | | BTREE | | | +-------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+ 1 row in set (0.17 sec)
idにしかふられてない。
こいつじゃないかなー。こいつっぽい気がするなー。
10万行超えるレコードを毎回フルスキャンは遅いんじゃないかなー。
expiresとvalidにも張っておいたほうがいいんじゃないかなー。
index作ってみる。
mysql> alter table token add index expires(expires); Query OK, 0 rows affected (6 min 6.79 sec) Records: 0 Duplicates: 0 Warnings: 0 mysql> alter table token add index valid(valid); Query OK, 0 rows affected (2 min 59.38 sec) Records: 0 Duplicates: 0 Warnings: 0
効果を確認。
mysql> explain SELECT token.id AS token_id, token.expires AS token_expires, token.extra AS token_extra, token.valid AS token_valid, token.user_id AS token_user_id, token.trust_id AS token_trust_id FROM token WHERE token.expires > '2013-05-27 06:11:45' and token.valid = 0; +----+-------------+-------+------+---------------+-------+---------+-------+------+-------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +----+-------------+-------+------+---------------+-------+---------+-------+------+-------------+ | 1 | SIMPLE | token | ref | expires,valid | valid | 1 | const | 4 | Using where | +----+-------------+-------+------+---------------+-------+---------+-------+------+-------------+ 1 row in set (0.02 sec) mysql> SELECT token.id AS token_id, token.expires AS token_expires, token.extra AS token_extra, token.valid AS token_valid, token.user_id AS token_user_id, token.trust_id AS token_trust_id FROM token WHERE token.expires > '2013-05-27 06:11:45' and token.valid = 0; Empty set (0.00 sec)
効いてる効いてる。
hoge@fuga:~$ top top - 17:48:25 up 3 days, 1:07, 2 users, load average: 0.16, 0.35, 0.61 Tasks: 144 total, 2 running, 142 sleeping, 0 stopped, 0 zombie Cpu(s): 4.6%us, 1.0%sy, 0.0%ni, 93.9%id, 0.5%wa, 0.0%hi, 0.0%si, 0.0%st Mem: 2050020k total, 1932860k used, 117160k free, 19116k buffers Swap: 2097148k total, 52204k used, 2044944k free, 862236k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1341 quantum 20 0 186m 39m 3732 S 4 2.0 104:51.66 python 1996 rabbitmq 20 0 1132m 105m 1860 S 3 5.3 101:57.68 beam.smp 1384 nova 20 0 226m 61m 3740 S 1 3.1 17:19.29 nova-conductor 1345 cinder 20 0 91428 17m 3324 S 0 0.9 23:46.03 cinder-volume 1436 mysql 20 0 1310m 185m 4196 S 0 9.3 105:59.44 mysqld 2309 root 20 0 91016 4328 2116 S 0 0.2 0:05.59 apache2
load average下がった。
hoge@fuga:~$ sudo iotop
Total DISK READ: 0.00 B/s | Total DISK WRITE: 2.76 M/s
TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
1739 be/4 mysql 0.00 B/s 769.22 K/s 0.00 % 0.82 % mysqld
387 be/3 root 0.00 B/s 26.92 K/s 0.00 % 0.31 % [jbd2/dm-12-8]
2079 be/4 mysql 0.00 B/s 3.85 K/s 0.00 % 0.03 % mysqld
22747 be/4 mysql 0.00 B/s 3.85 K/s 0.00 % 0.03 % mysqld
1511 be/4 mysql 0.00 B/s 3.85 K/s 0.00 % 0.02 % mysqld
1 be/4 root 0.00 B/s 7.69 K/s 0.00 % 0.00 % init
mysqlのIOも下がった。
hoge@fuga:~$ vmstat 1 procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu---- r b swpd free buff cache si so bi bo in cs us sy id wa 0 0 52328 130860 24160 847128 0 0 2140 139 15 38 6 1 51 41 0 0 52328 130852 24160 847132 0 0 0 0 155 297 0 0 100 0 0 0 52328 130852 24176 847116 0 0 0 52 368 664 2 1 97 0 0 0 52328 130852 24192 847124 0 0 0 404 959 1834 8 1 91 1 0 0 52328 130852 24240 847112 0 0 0 1628 598 1147 4 0 96 0 0 0 52328 130844 24272 847156 0 0 0 64 386 744 2 1 97 0 0 0 52328 130844 24288 847156 0 0 0 48 484 876 3 0 97 0 0 0 52328 130844 24312 847160 0 0 0 76 524 991 3 1 96 0 0 0 52328 130844 24328 847172 0 0 4 44 360 666 2 1 97 1 0 0 52328 130844 24328 847192 0 0 0 0 151 289 0 0 100 0
waitも下がった。
これで管理画面も正常に動作するようになったよ！
