サポート #26

レスポンスが重い

山本 義治 が約11年前に追加. 約11年前に更新.

ステータス:進行中開始日:2013/12/19
優先度:通常期日:
担当者:-進捗 %:

0%

カテゴリ:システム全般作業時間の記録:-
対象バージョン:-

説明

#状況
システム全体的に管理画面のレスポンスが重い。
特に全体集計、広告詳細レポート、クライアント管理画面レポート

#対策
・slowクエリーログを取って、処理に時間がかかっているクエリーを突き止める
・explainを実行してindex最適化
・クエリキャッシュの見直し（キャッシュサイズ調整、特定クエリのみキャッシュとか）
・スレープの活用

子チケット

サポート #30: DBテーブルindex最適化新規

履歴

#1 山本 義治 が約11年前に更新

スレーブ

db1$ mysql> show processlist;
--------------------+---------------------+------+---------+----------+----------------------------------+------------------------------------------------------------------------------------------------------+ | Id | User | Host | db | Command | Time | State | Info |
--------------------+---------------------+------+---------+----------+----------------------------------+------------------------------------------------------------------------------------------------------+ | 2 | system user | | NULL | Connect | 61626371 | Waiting for master to send event | NULL | | 3 | system user | | aff | Connect | 50 | Locked | update action_log_merge set point_back_response = 4 where aff_id = '9wb70WPA86044370' | | 2186871 | root | localhost | aff | Query | 0 | NULL | show processlist | | 2187026 | mysql | 192.168.2.101:43914 | aff | Query | 62 | Sending data | select action_log_id from action_log_201312 where (status = '1' or status = '4')and admit_date >= '2 |
--------------------+---------------------+------+---------+----------+----------------------------------+------------------------------------------------------------------------------------------------------+
4 rows in set (0.00 sec)

スレーブのテーブルの読み込している途中で
同じテーブルに対してマスターの同期がロックされる
mergeテーブル特有の症状？

#2 山本 義治 が約11年前に更新

db2$ mysql> show processlist;
---------------+---------------------+------+-------------+----------+----------------------------------------------------------------+------------------------------------------------------------------------------------------------------+ | Id | User | Host | db | Command | Time | State | Info |
---------------+---------------------+------+-------------+----------+----------------------------------------------------------------+------------------------------------------------------------------------------------------------------+ | 769443 | repl | 192.168.2.102:41267 | NULL | Binlog Dump | 61625217 | Has sent all binlog to slave; waiting for binlog to be updated | NULL | | 84496683 | root | localhost | aff | Query | 0 | NULL | show processlist | | 84502638 | mysql | 192.168.2.101:55286 | aff | Query | 13 | Sending data | SELECT TB1.m_owner_id, TB1.m_id, TB1.asp_id, TB1.listing_id, TB1.t_id FROM (SELECT m_owner_id, m_id, | | 84502686 | mysql | 192.168.2.103:55270 | aff | Query | 7 | Locked | update click_log_201312 set status = '5' where aff_id = 'eb8SOOC486047748' | | 84502688 | mysql | 192.168.2.101:55308 | aff | Query | 6 | Locked | insert into click_log_201312 (
c_owner_id,
c_id,
asp_id,
aff_id,
t_id,
career, | | 84502689 | mysql | 192.168.2.101:55309 | aff | Query | 6 | Locked | insert into click_log_201312 (
c_owner_id,
c_id,
asp_id,
aff_id,
t_id,
career, | | 84502690 | mysql | 192.168.2.101:55310 | aff | Query | 6 | Locked | insert into click_log_201312 (
c_owner_id,
c_id,
listing_id,
aff_id,
t_id,
c | | 84502705 | mysql | 192.168.2.103:55279 | aff | Query | 1 | Locked | insert into click_log_201312 (
c_owner_id,
c_id,
asp_id,
aff_id,
t_id,
career, |
---------------+---------------------+------+-------------+----------+----------------------------------------------------------------+------------------------------------------------------------------------------------------------------+
8 rows in set (0.00 sec)

click_log系テーブルがロックされている

MyISAMのテーブルロック（shared read lock）がかかっている
↓
実行待ちクエリーがキャッシュに保持される

※MyISAMのコンカレントインサート機能
https://blogs.oracle.com/takemura/entry/myisam%E3%82%B9%E3%83%88%E3%83%AC%E3%83%BC%E3%82%B8%E3%82%A8%E3%83%B3%E3%82%B8%E3%83%B3%E3%81%AE%E3%82%B3%E3%83%B3%E3%82%AB%E3%83%AC%E3%83%B3%E3%83%88%E3%82%A4%E3%83%B3%E3%82%B5%E3%83%BC%E3%83%88%E6%A9%9F%E8%83%BD%E3%81%AB%E3%81%A4%E3%81%84%E3%81%A6

#3 山本 義治 が約11年前に更新

レポート系のクエリーをスレーブに変更

/www/aff/admin/www/stat/stat_total.php
/www/aff/admin/www/stat/stat_total_day.php
/www/aff/admin/www/stat/click_log_detail.php
/www/aff/admin/www/stat/action_log_detail.php
/www/aff/admin/www/stat/content/report.php
/www/aff/admin/www/stat/content/report_day.php
/www/aff/user/www/merchant/report/top.php

#4 山本 義治 が約11年前に更新

db2

mysql> show processlist;
---------------+---------------------+------+-------------+----------+----------------------------------------------------------------+------------------------------------------------------------------------------------------------------+ | Id | User | Host | db | Command | Time | State | Info |
---------------+---------------------+------+-------------+----------+----------------------------------------------------------------+------------------------------------------------------------------------------------------------------+ | 769443 | repl | 192.168.2.102:41267 | NULL | Binlog Dump | 61737210 | Has sent all binlog to slave; waiting for binlog to be updated | NULL | | 84834662 | mysql | 192.168.2.101:60907 | aff | Query | 5 | Sorting result | select * from click_log_201103 where status != 5 and subscriber = 'a3OWgwKRxm6HosAY' order by click_ | | 84834663 | mysql | 192.168.2.103:58629 | aff | Query | 5 | Sorting result | select * from click_log_201103 where status != 5 and subscriber = 'a3OWgwKRxm6HosAY' order by click_ | | 84834985 | mysql | 192.168.2.103:58798 | aff | Query | 96 | Copying to tmp table | select 201305 as action_month, DATE_FORMAT(resign_date,'%Y%m') as resign_month, count(action_log_id) | | 84835105 | mysql | 192.168.2.101:32920 | aff | Query | 82 | Locked | update action_log_merge set
point = '0',
point_back_response = '2',
point_back_ | | 84835142 | mysql | 192.168.2.101:32942 | aff | Query | 165 | Sending data | SELECT '201305' AS conv_date, CASE WHEN AVG, DATE_FORMAT | | 84835376 | mysql | 192.168.2.101:54035 | aff | Query | 100 | Locked | SELECT tb.YEARMONTH
,tb.click_count
,tb.click_unique_count
,tb.action_count
,CASE WHEN tb.click_ | | 84835379 | mysql | 192.168.2.101:54037 | aff | Query | 97 | Sending data | SELECT '201305' AS conv_date, CASE WHEN AVG, DATE_FORMAT | | 84835392 | mysql | 192.168.2.101:54049 | aff | Query | 99 | Sending data | SELECT '201305' AS conv_date, CASE WHEN AVG, DATE_FORMAT | | 84835408 | mysql | 192.168.2.101:54058 | aff | Query | 90 | Sending data | SELECT '201305' AS conv_date, CASE WHEN AVG, DATE_FORMAT | | 84835411 | mysql | 192.168.2.101:54061 | aff | Query | 96 | Sending data | SELECT '201305' AS conv_date, CASE WHEN AVG, DATE_FORMAT | | 84835413 | mysql | 192.168.2.101:54063 | aff | Query | 96 | Sending data | SELECT '201305' AS conv_date, CASE WHEN AVG, DATE_FORMAT | | 84835415 | mysql | 192.168.2.101:54065 | aff | Query | 1 | Locked | select 201305 as action_month, DATE_FORMAT(resign_date,'%Y%m') as resign_month, count(action_log_id) | | 84835418 | mysql | 192.168.2.101:54068 | aff | Query | 96 | Sending data | SELECT '201305' AS conv_date, CASE WHEN AVG, DATE_FORMAT | | 84835419 | mysql | 192.168.2.101:54069 | aff | Query | 96 | Sending data | SELECT '201305' AS conv_date, CASE WHEN AVG, DATE_FORMAT | | 84835431 | mysql | 192.168.2.101:54080 | aff | Query | 92 | Sending data | SELECT '201305' AS conv_date, CASE WHEN AVG, DATE_FORMAT | | 84835436 | mysql | 192.168.2.101:54082 | aff | Query | 93 | Sending data | SELECT '201305' AS conv_date, CASE WHEN AVG, DATE_FORMAT | | 84835487 | mysql | 192.168.2.101:54108 | aff | Query | 82 | Locked | select * from action_log_merge where aff_id = 'KVHccrq481141513' | | 84835605 | mysql | 192.168.2.101:54172 | aff | Query | 53 | Locked | select * from action_log_merge where point_back_response = 2 | | 84835618 | mysql | 192.168.2.101:54179 | aff | Query | 51 | Locked | select * from action_log_merge where aff_id = 'VT95y86086159673' | | 84835633 | mysql | 192.168.2.103:59099 | aff | Query | 47 | Locked | select * from action_log_merge where aff_id = 'B3q3WI1T86159586' | | 84835645 | mysql | 192.168.2.101:54195 | aff | Query | 44 | Locked | select * from action_log_merge where aff_id = 'zs3zfHO286155305' | | 84835660 | mysql | 192.168.2.101:54207 | aff | Query | 39 | Locked | SELECT '201305' AS conv_date, CASE WHEN AVG, DATE_FORMAT | | 84835694 | mysql | 192.168.2.101:54225 | aff | Query | 32 | Locked | select * from action_log_merge where aff_id = '4E9aS5Pc86159436' | | 84835710 | mysql | 192.168.2.101:54234 | aff | Query | 28 | Locked | SELECT tb.YEARMONTH
,tb.click_count
,tb.click_unique_count
,tb.action_count
,CASE WHEN tb.click_ | | 84835753 | mysql | 192.168.2.101:54262 | aff | Query | 20 | Locked | SELECT '201305' AS conv_date, CASE WHEN AVG, DATE_FORMAT | | 84835814 | root | localhost | aff | Query | 0 | NULL | show processlist | | 84835841 | mysql | 192.168.2.101:54306 | aff | Sleep | 1 | | NULL | | 84835845 | mysql | 192.168.2.101:54309 | aff | Sleep | 0 | | NULL | | 84835849 | mysql | 192.168.2.103:59195 | aff | Sleep | 0 | | NULL |
---------------+---------------------+------+-------------+----------+----------------------------------------------------------------+------------------------------------------------------------------------------------------------------+
30 rows in set (0.13 sec)

#5 山本 義治 が約11年前に更新

〜i-generationレスポンス改善策 2013/12/13〜

問題点）

管理画面のレポートの表示レスポンスが遅くなっている。
DBサーバのクエリーログを確認したところ、
レポート系のクエリのレスポンスに時間がかかる場合がある
（アクセスが集中すると発生）
アプリケーション側のクエリ最適化またはサーバのスケールアップが必要。

サーバステータスを見るとCPU負荷はWeb,DBともに安定しているが、
DBマスターサーバのメモリが8GMAXを消費している状態が続いているため
パフォーマンスに影響が出ている可能性がある
(2013/3頃からMAXに達している)

施策１）メモリキャッシュ解放

DBマスターサーバのメモリキャッシュを手動解放する

※実施時間：数分
※一時的なキャッシュの解放のため継続的な効果がどれぐらいあるかは未定

12/17 午前8時〜　山本、矢野

施策２）MySQL再起動

DBマスターサーバ、スレーブサーバともにMySQLを再起動する

マスター
1) 参照系クエリをスレーブサーバへ向き先変更
2) クリック、登録、退会通知等の更新系クエリをファイルに書き出す
3) マスターサーバのMySQLを再起動
4) 2でログに保存したクエリを手動で反映

スレーブ
1) スレーブの向き先をマスターに切り替える
2) スレーブサーバのMySQLを再起動
3) レポート系のクエリをスレーブに向ける（元の状態に戻す）

※事前準備：1日
※実施時間：数時間
　アクセスの少ない時間帯を考えると朝方から午前中が望ましい

施策３）物理メモリ増設

さくら側の作業のため、平日日中作業となる可能性が高い。
サーバの再起動が必要なため、マスター、スレーブ1台づつ実施。
スレーブサーバをマスターへ切り替える作業が必要。

※事前準備：2〜3日
※実施時間：数時間

施策４）アプリケーション側のクエリー最適化

#7 山本 義治 が約11年前に更新

1) DBバックアップ

[db2]
mysqldump -u root -p --default-character-set=binary --skip-lock-tables aff > /home/admin/aff.dump.20131217

2) メモリキャッシュ解放

解放前
[root@db2 admin]# cat /proc/meminfo
MemTotal: 8176928 kB
MemFree: 44380 kB
Buffers: 17208 kB
Cached: 7242196 kB
SwapCached: 0 kB
Active: 2070696 kB
Inactive: 5920964 kB
HighTotal: 0 kB
HighFree: 0 kB
LowTotal: 8176928 kB
LowFree: 44380 kB
SwapTotal: 2048276 kB
SwapFree: 2048176 kB
Dirty: 366880 kB
Writeback: 0 kB
AnonPages: 732212 kB
Mapped: 20652 kB
Slab: 104676 kB
PageTables: 16996 kB
NFS_Unstable: 0 kB
Bounce: 0 kB
CommitLimit: 6136740 kB
Committed_AS: 1423968 kB
VmallocTotal: 34359738367 kB
VmallocUsed: 19232 kB
VmallocChunk: 34359718795 kB
HugePages_Total: 0
HugePages_Free: 0
HugePages_Rsvd: 0
Hugepagesize: 2048 kB

解放後
[root@db2 admin]# cat /proc/meminfo
MemTotal: 8176928 kB
MemFree: 7361792 kB
Buffers: 476 kB
Cached: 21572 kB
SwapCached: 0 kB
Active: 752188 kB
Inactive: 1420 kB
HighTotal: 0 kB
HighFree: 0 kB
LowTotal: 8176928 kB
LowFree: 7361792 kB
SwapTotal: 2048276 kB
SwapFree: 2048176 kB
Dirty: 216 kB
Writeback: 0 kB
AnonPages: 731532 kB
Mapped: 19628 kB
Slab: 25280 kB
PageTables: 16900 kB
NFS_Unstable: 0 kB
Bounce: 0 kB
CommitLimit: 6136740 kB
Committed_AS: 1421284 kB
VmallocTotal: 34359738367 kB
VmallocUsed: 19232 kB
VmallocChunk: 34359718795 kB
HugePages_Total: 0
HugePages_Free: 0
HugePages_Rsvd: 0
Hugepagesize: 2048 kB

3) 通常のバックアップスクリプト実行

[root@db2 bkup]# ./bkup.linux.sh
mysqldump: Couldn't execute 'SHOW TRIGGERS LIKE 'click\_log\_201203'': Can't create/write to file '/tmp/#sql_5b84_0.MYD' (Errcode: 24) (1)
gzip: /usr/local/mysql/aff/bkup/aff.dump.20131217.gz already exists; do you wish to overwrite (y or n)? y

→ダンプが途中で止まる

top - 09:20:16 up 756 days, 18:50, 4 users, load average: 1.75, 1.84, 1.75
Tasks: 116 total, 1 running, 115 sleeping, 0 stopped, 0 zombie
Cpu(s): 21.3%us, 1.0%sy, 0.0%ni, 37.8%id, 39.4%wa, 0.2%hi, 0.3%si, 0.0%st
Mem: 8176928k total, 8133264k used, 43664k free, 21340k buffers
Swap: 2048276k total, 100k used, 2048176k free, 7176996k cached

[root@db2 bkup]# cat /proc/meminfo
MemTotal: 8176928 kB
MemFree: 852300 kB
Buffers: 16936 kB
Cached: 6374632 kB
SwapCached: 0 kB
Active: 1018320 kB
Inactive: 6113468 kB
HighTotal: 0 kB
HighFree: 0 kB
LowTotal: 8176928 kB
LowFree: 852300 kB
SwapTotal: 2048276 kB
SwapFree: 2048176 kB
Dirty: 382976 kB
Writeback: 0 kB
AnonPages: 740172 kB
Mapped: 19628 kB
Slab: 156552 kB
PageTables: 16896 kB
NFS_Unstable: 0 kB
Bounce: 0 kB
CommitLimit: 6136740 kB
Committed_AS: 1422920 kB
VmallocTotal: 34359738367 kB
VmallocUsed: 19232 kB
VmallocChunk: 34359718795 kB
HugePages_Total: 0
HugePages_Free: 0
HugePages_Rsvd: 0
Hugepagesize: 2048 kB

top - 09:23:41 up 756 days, 18:53, 4 users, load average: 0.54, 1.54, 1.67
Tasks: 114 total, 2 running, 112 sleeping, 0 stopped, 0 zombie
Cpu(s): 2.0%us, 2.0%sy, 0.0%ni, 49.8%id, 46.3%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 8176928k total, 862772k used, 7314156k free, 452k buffers
Swap: 2048276k total, 100k used, 2048176k free, 61032k cached

[root@db2 bkup]# cat /proc/meminfo
MemTotal: 8176928 kB
MemFree: 7353844 kB
Buffers: 264 kB
Cached: 20636 kB
SwapCached: 0 kB
Active: 760240 kB
Inactive: 832 kB
HighTotal: 0 kB
HighFree: 0 kB
LowTotal: 8176928 kB
LowFree: 7353844 kB
SwapTotal: 2048276 kB
SwapFree: 2048176 kB
Dirty: 156 kB
Writeback: 0 kB
AnonPages: 740172 kB
Mapped: 19628 kB
Slab: 25060 kB
PageTables: 16896 kB
NFS_Unstable: 0 kB
Bounce: 0 kB
CommitLimit: 6136740 kB
Committed_AS: 1420048 kB
VmallocTotal: 34359738367 kB
VmallocUsed: 19232 kB
VmallocChunk: 34359718795 kB
HugePages_Total: 0
HugePages_Free: 0
HugePages_Rsvd: 0
Hugepagesize: 2048 kB

[admin@db1 ~]$ date
Tue Dec 17 12:43:39 JST 2013

通常のバックアップスクリプト
rw-r--r- 1 root root 2.1G Dec 17 09:07 aff.dump.20131217.gz

DB1サーバでgzipしたもの
rw-rw-r- 1 admin admin 3.0G Dec 17 12:16 aff.dump.20131217.gz

→サイズが1G程度差分がある
→dumpが途中でとまってメモリ解放される
なんらかのエラーが発生している？ログには残っていない

/var/log/mysqld.log
131217 5:11:54 [ERROR] /usr/libexec/mysqld: Can't open file: './aff/asp_list.frm' (errno: 24)

4) バックアップスクリプトにオプション付ける

[root@db2 bkup]# cat bkup.linux.sh
#!/bin/sh
HOME=/usr/local/mysql/aff
DATABASE=aff
#USER=mysql
#PASSWORD=Gnke8d9C
USER=root
PASSWORD=mysql

rm -f $HOME/bkup/aff.dump.`date --date '90 days ago' "+%Y%m%d"`
rm -f $HOME/bkup/aff.dump.`date --date '90 days ago' "+%Y%m%d"`.gz
/usr/local/mysql/bin/mysqldump -u $USER -p$PASSWORD --default-character-set=binary --skip-lock-tables $DATABASE > $HOME/bkup/aff.dump.`date "+%Y%m%d"`
/bin/gzip $HOME/bkup/aff.dump.`date "+%Y%m%d"`

他の形式にエクスポート: Atom PDF