ざ・わーるど@はてな

気が向いた時に更新する雑記です

CPU負荷が高いPHPスクリプトを特定しましたぼく

loadaverageがクソ高いというのは前々から書いているんだけど、一体どのスクリプトが原因なのか特定できなくて困っていましたぼく。
そのスクリプトCPU使用率を30%も持っていくカススクリプトです。
特定しようにも、Linuxビギナーなので、どうしたらいいのかさっぱわかりません。


以前、id:fedlicさんに「何かトラブルがあったらまずログをみればいんじゃね」って言われたことを思い出して、Apacheのログをみることに。
ログに処理の時間とか出てないかなーと思ったけど標準では出ていなかったですね。


なので、どうして人に聞く前にYahoo!やgooで調べないんだ?失礼じゃないか、と言われるコミュニティで育ってきたので、とりあえずでGoogleしました。
httpd.conf周りの詳しい解説をしているサイト発見


http://72.14.207.104/search?q=cache:Z1yWo9UH1REJ:arika.org/doc/uu.200108.apache_log+LogFormat+httpd.conf&hl=ja&ct=clnk&cd=4

%T
リクエストの処理にかかった時間。

それらしい変数が用意されていることを発見。これを追加すればよさそうだけど、変に書き換えるのもこわいのでよくみると、LogFormatにはいくつかのパターンが用意されていたので%Tが含まれているものをさがす。
full,debugに%Tが含まれていた。

CustomLog /var/log/apache/access.log combined


という項目があって、いまはcombinedが指定されているみたい。
fullはかなりログが長くなるみたいなので、2項目くらい増える程度で済むdebugにしてApacheをリスタート。
いつもconfigのテストコマンドを忘れるのでメモ。

apachectl configtest


うまく再起動されたのでログを眺めてみる。

tail -f /var/log/apache/access.log


しばらくみていたら、処理に時間がかかっているスクリプト発見。

xxx.xxx.xxx.xxx - - [25/Feb/2006:23:06:21 +0900] "GET /xxx.php HTTP/1.0" 200 25294 "-" "Mozilla/5.0 (compatible; Yahoo! Slurp; http://help.yahoo.com/help/us/ysearch/slurp)" "-" 10231 22


どのスクリプトがアレなのかわかるとアレなのでとりあえず伏せておきました。
一番最後の22っていう数字が%Tの変数が割り当てられているところだった。
ほとんど0〜3くらいなのにこのスクリプトだけ以上に数値が高い。
何回か確認したけど、このスクリプトの処理だけどう考えても時間がかかっています。
これが負荷がかかっているスクリプトっていうことで間違いないですかねえ。


これははずせないスクリプトなので、負荷が下がるように書き直さないとだめそうだ。


何か妙な達成感があるなあ。Linuxおもしろい。