ここ1ヶ月ほどmuninがPostgreSQLから情報をとれなくなるほど負荷があがることが1日に1,2回程度発生していました。
以下の赤い四角で囲った部分です。
グラフがぽっかり抜けています。
スロークエリがあると想定してログを取得するも、問題となるようなクエリはありませんでした。
実行に時間がかかっているクエリはたくさんあったのですが、いずれのクエリも平常時はms単位で応答を返すものでした。
が、この事象が発生するときは、応答に5秒かかる…というような状態でした。
sarを実行すると以下のような出力が得られました。
06時40分01秒 CPU %user %nice %system %iowait %steal %idle
06時41分01秒 all 7.36 2.01 3.00 0.58 0.00 87.05
06時42分01秒 all 4.46 0.00 1.79 0.32 0.00 93.43
06時43分01秒 all 4.87 0.00 1.55 0.43 0.00 93.15
06時44分01秒 all 6.98 0.00 2.56 0.26 0.00 90.19
06時45分01秒 all 13.59 0.00 5.06 0.24 0.00 81.11
06時46分01秒 all 45.36 1.99 17.29 0.30 0.00 35.06
06時47分01秒 all 74.13 0.00 25.38 0.00 0.00 0.49
06時48分01秒 all 74.97 0.00 24.87 0.00 0.00 0.16
06時49分02秒 all 76.15 0.00 23.46 0.00 0.00 0.39
06時50分01秒 all 44.06 0.00 14.09 0.08 0.00 41.77
06時51分01秒 all 14.55 1.98 5.38 0.90 0.00 77.19
06時52分01秒 all 9.73 0.00 2.82 0.31 0.00 87.14
※sarはCentOSの場合、デフォルトでは10分に1回記録するようになっていますが、10分だと問題が発生したときにログを見るのがつらいので1分に変更すべきだと思います。ちなみに、この問題が発生したとき、DBサーバーは10分間隔だったで…1分に変更しました。
userとsystemでCPU時間を100%使いつくしている状態です。
負荷が高いのはPostgreSQLを動かしているサーバーで、Apacheを動かしているサーバーの負荷は問題ありませんでした。
以上から、PostgreSQLでなにか起こっているに違いないと思って、いろいろ切り分けたのですが、PostgreSQLのログを見ても何もわかりませんでした。
何か多くのアクセスがきているのが原因かもしれないと思い、Apacheのログを見たのですが、何かが起こっている06時46分と何も起こってない時間のアクセス数はあまりかわらず、多くのアクセスがきているわけではなさそうでした。
アクセス数はかわらないのですが、どこからアクセスがきているのか?を集計したところ、bingbotが多くをしめていました。
bingbotにしぼって06時45分のログを見たのが以下です。
soukan.phpはあるゲームに似た評価をされているゲームを表示するスクリプトです。
このスクリプトは作りが悪くて…SQLを1万回程度実行するスクリプトです。
SQL自体は0.006秒程度で応答を返すのですが、それを1万回実行するので…応答がかえるまでに60秒程度かかります。
実行に60秒程度かかるスクリプトをだいたい5秒おきに実行されてしまったので負荷が高くなったようでした。
自分は、DBのネックで負荷があがる場合は、iowaitが高くなると思い込んでいたのですが、1つのスクリプトで応答時間は短いけどSQLを大量に発行して処理が追いつかなくなる場合は、userやsystemが高くなる…ということを知りました。
本格対処はsoukan.phpを書き換えることなのですが、暫定対処として、bingbotをブロックすることにしました。
以下の赤い四角で囲った部分です。
グラフがぽっかり抜けています。
スロークエリがあると想定してログを取得するも、問題となるようなクエリはありませんでした。
実行に時間がかかっているクエリはたくさんあったのですが、いずれのクエリも平常時はms単位で応答を返すものでした。
が、この事象が発生するときは、応答に5秒かかる…というような状態でした。
sarを実行すると以下のような出力が得られました。
06時40分01秒 CPU %user %nice %system %iowait %steal %idle
06時41分01秒 all 7.36 2.01 3.00 0.58 0.00 87.05
06時42分01秒 all 4.46 0.00 1.79 0.32 0.00 93.43
06時43分01秒 all 4.87 0.00 1.55 0.43 0.00 93.15
06時44分01秒 all 6.98 0.00 2.56 0.26 0.00 90.19
06時45分01秒 all 13.59 0.00 5.06 0.24 0.00 81.11
06時46分01秒 all 45.36 1.99 17.29 0.30 0.00 35.06
06時47分01秒 all 74.13 0.00 25.38 0.00 0.00 0.49
06時48分01秒 all 74.97 0.00 24.87 0.00 0.00 0.16
06時49分02秒 all 76.15 0.00 23.46 0.00 0.00 0.39
06時50分01秒 all 44.06 0.00 14.09 0.08 0.00 41.77
06時51分01秒 all 14.55 1.98 5.38 0.90 0.00 77.19
06時52分01秒 all 9.73 0.00 2.82 0.31 0.00 87.14
※sarはCentOSの場合、デフォルトでは10分に1回記録するようになっていますが、10分だと問題が発生したときにログを見るのがつらいので1分に変更すべきだと思います。ちなみに、この問題が発生したとき、DBサーバーは10分間隔だったで…1分に変更しました。
userとsystemでCPU時間を100%使いつくしている状態です。
負荷が高いのはPostgreSQLを動かしているサーバーで、Apacheを動かしているサーバーの負荷は問題ありませんでした。
以上から、PostgreSQLでなにか起こっているに違いないと思って、いろいろ切り分けたのですが、PostgreSQLのログを見ても何もわかりませんでした。
何か多くのアクセスがきているのが原因かもしれないと思い、Apacheのログを見たのですが、何かが起こっている06時46分と何も起こってない時間のアクセス数はあまりかわらず、多くのアクセスがきているわけではなさそうでした。
アクセス数はかわらないのですが、どこからアクセスがきているのか?を集計したところ、bingbotが多くをしめていました。
bingbotにしぼって06時45分のログを見たのが以下です。
207.46.13.34 [30/Apr/2020:06:45:27+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=6151 HTTP/1.1 200 49991 40.77.167.157 [30/Apr/2020:06:45:30+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=19208 HTTP/1.1 200 51751 40.77.167.157 [30/Apr/2020:06:45:22+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=2830 HTTP/1.1 200 50266 207.46.13.34 [30/Apr/2020:06:45:22+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=9955 HTTP/1.1 200 51289 40.77.167.157 [30/Apr/2020:06:45:24+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=2041 HTTP/1.1 200 50478 40.77.167.186 [30/Apr/2020:06:45:39+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=21480 HTTP/1.1 504 247 40.77.167.186 [30/Apr/2020:06:45:39+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=20671 HTTP/1.1 504 247 40.77.167.186 [30/Apr/2020:06:45:39+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=20632 HTTP/1.1 504 247 207.46.13.34 [30/Apr/2020:06:45:43+0900] GET /~ap2/ero/toukei_kaiseki/soukan.php?game=16545 HTTP/1.1 504 247soukan.phpにそこそこな頻度でアクセスした結果、504を返しています。
soukan.phpはあるゲームに似た評価をされているゲームを表示するスクリプトです。
このスクリプトは作りが悪くて…SQLを1万回程度実行するスクリプトです。
SQL自体は0.006秒程度で応答を返すのですが、それを1万回実行するので…応答がかえるまでに60秒程度かかります。
実行に60秒程度かかるスクリプトをだいたい5秒おきに実行されてしまったので負荷が高くなったようでした。
自分は、DBのネックで負荷があがる場合は、iowaitが高くなると思い込んでいたのですが、1つのスクリプトで応答時間は短いけどSQLを大量に発行して処理が追いつかなくなる場合は、userやsystemが高くなる…ということを知りました。
本格対処はsoukan.phpを書き換えることなのですが、暫定対処として、bingbotをブロックすることにしました。
