apacheのログローテートには再起動を伴う

今日の一幕。

Aさん「今日の4:30頃のport80停止は何か作業を行った結果でしょうか」
Bさん「時間的にはログローテートのタイミングですね」
Aさん「そうなんですね。でもなぜ今日に限ってアラートが上がったのでしょうか」
Bさん「centosのログローテート(正確には日次cron)は4:30開始です。ログローテートの仕組みはファイル名を変えての『apache再起動』です。監視に引っかかるぐらいの時間がapache再起動にかかればこうなりますが……」
Aさん「起動しているので問題ないですかね……時間がかかった理由は気になりますが……」
Bさん「あるいはネットワーク遮断が起きればこういう出方をするかもしれないです」

centos標準のhttpdはlogrotateという仕組みを使ってログローテートを行います。これはcronで毎日起動しますが、これは4:30に起動され、httpdの場合は再起動を伴います(※若干のウソがあります)。
そのため、httpdの設定を変えて再起動しないなど手抜きすると翌日に動いていないなんてことになるので、意外と注意が必要な事項です。

Bさん「まったく別のサーバにも同じ内容のアラートがあったorz」
Bさん「監視側の誤検知のようです」

オーノー。そんなこともあります。

サーバの負荷を調べるコマンド集その2:ディスクI/O、ネットワークI/Oの確認

サーバの負荷を確認する、サーバの負荷を調べるコマンド集その1の続きです。

ディスクI/Oの確認:sar、dstat

ディスクI/Oがどうであるか、一番手っ取り早いのがsarです。

$ sar
 Linux 2.6.32-220.7.1.el6.x86_64 (feanor.localdomain)     2012年07月07日     _x86_64_    (2 CPU)

 00時00分01秒       CPU     %user     %nice   %system   %iowait    %steal     %idle
 00時10分01秒       all     12.29      0.00      4.91      0.14      0.00     82.66
 00時20分01秒       all      6.21      0.00      4.16      0.04      0.00     89.59

「%iowait」の数値が他と比べて大きければ、ディスクI/Oに引きずられている可能性が高いです。時系列に並ぶので、どの時刻から上がっているか、定期バッチ処理が契機の時などはわかりやすいです。

契機がなく定常的に負荷が高い場合、現在どのプロセスが高いかを確認します。「dstat -al –top-bio」です。

$ dstat -al --top-bio
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system-- ---load-avg--- ----most-expensive----
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw | 1m   5m  15m |  block i/o process   
 29   4  50  16   0   2| 914k 1994k|   0     0 | 210B   84B| 104  9732 |1.19 1.28 1.32|init [3]    173k 2032k
 13   4  49  33   0   3|1504k  164k|1068k 2282k|   0     0 |8212    13k|1.19 1.28 1.32|nfsd        324k    0
 13   3  76   5   0   2|1852k  100k|1669k 4248k|   0     0 |7286    11k|1.10 1.26 1.31|nfsd        304k    0
 29   8  44  14   1   5|1928k   84k|1444k 4733k|   0     0 |  13k   20k|1.10 1.26 1.31|nfsd        316k    0
 28   6  45  18   0   5| 272k  148k|1643k 3038k|   0     0 |  12k   19k|1.10 1.26 1.31|nfsd        104k    0

コマンドがない場合は、centosの場合はepel導入後「yum install dstat」で幸せになれます。
vmstatのように、1秒ごとに1行ずつ表示されていきます。最初の1・2行は表示がなんだかおかしいのですが、3行目あたりから見ると安定します。
見るべきは一番右の「block i/o process」で、これに出てくるプロセスがそのタイミングで一番I/O負荷をかけているプロセスです。これでいうとnfsdをなんとかしてやろう、ということになります。

ネットワークI/Oの確認:dstat

ネットワークI/Oの負荷が問題になる場合はzabbix等の監視ソフトが導入されている場合が多いのでコマンドで頑張るシーンはあまりないとは思いますが、dstatの「net/total」の欄がネットワークの通信量になります。これが回線契約の上限値にはりつきっぱなしになっているなどあれば、ネットワークの見直しが必要になります。

ネットワークを使っているプロセスが特定できずに困ったという経験がないためプロセスを特定するちょうど良いコマンドは知らないのですが、ネットワークだけを使うというのはルータでもない限りあまり考えられないので、topなどでCPUなりを使っているプロセスを特定するとだいたい特定できます。

さいごに

緊急対応の場合はアプリケーションの特性であるなどを知っておかないと迅速な対応はできないので上記コマンドだけでは難しいものがありますが、普段からずっと重いなどの場合はこれらのコマンドでおおよそ原因プロセスを特定できています。プロセスを特定できれば「どこから手を付ければいいかわからない」ということにならず、「これこれを改善すれば効果が期待できる」と言い切りやすい状態になると思います。

サーバの負荷を調べるコマンド集その1:CPUの確認

1つのサーバに複数のサービス(WebとDBとか)が乗っていると、負荷が高いときにどれが原因なのか、原因のように見せかけて別の何かに引っ張られているだけなのか、よくわからなくなる場合があります。そんなときに手がかりになるコマンドをご紹介します。

「負荷が高い」とは

サーバにとって「負荷が高い」とは、サーバ資源の枯渇をさします。具体的には

  • CPUを使い切っている
  • ディスクI/Oを使い切っている
  • ネットワークI/Oを使い切っている
  • (メモリを使い切っている)

がwebサービスでの主要因です。他にもありますが、これで9割がた抑えられます。

メモリをカッコ書きにしたのは、メモリを使い切るとスワップが激しく稼働しだしてディスクI/Oを使い切ってしまうというのが負荷の原因なので、分類としては最終的にディスクI/Oに入ってしまうからです。しかし負荷のよくある原因の1つなので真っ先に監視対象になります。

CPUの確認:uptime、w、top、sar

uptimeはロードアベレージの確認に使います。

$ uptime
 15:45:16 up 632 days, 17:09,  1 user,  load average: 1.32, 0.68, 0.56

注目すべきは「1.23」の部分で、この部分がCPUスレッド数より大きいようであれば、処理をさばき切れていません。小さければ処理待ちは発生していないので、アプリケーションチューニングをがんばります。

CPUスレッド数がわからない場合は「cat /proc/cpuinfo」でprocessorの数を確認しましょう。

$ cat /proc/cpuinfo | grep processor | wc
      2       6      28

この場合は2個です。

wもロードアベレージの確認ですが、1文字で入力できるのでuptimeより6倍楽です。

$ w
 15:49:34 up  1:10,  2 users,  load average: 0.08, 0.06, 0.01
USER     TTY      FROM              LOGIN@   IDLE   JCPU   PCPU WHAT
takekosh tty1     :0               02:26    4:24m  9.75s  0.02s pam: gdm-password
takekosh pts/0    :0.0             02:26   13:16m  0.11s  0.11s bash

topはどのプロセスがCPUを使っているかを確認するのに使います。

top - 15:51:37 up  1:12,  4 users,  load average: 0.06, 0.05, 0.00
 Tasks: 183 total,   2 running, 181 sleeping,   0 stopped,   0 zombie
 Cpu(s):  0.3%us,  0.3%sy,  0.0%ni, 98.5%id,  0.6%wa,  0.0%hi,  0.2%si,  0.0%st
 Mem:   2054880k total,   640624k used,  1414256k free,    20484k buffers
 Swap:  4128760k total,        0k used,  4128760k free,   299380k cached

 PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 3312 takekosh  20   0 15020 1252  920 R  0.7  0.1   0:00.04 top
 2116 root      20   0  130m  29m 7436 S  0.3  1.5   0:10.13 Xorg
 2477 root      20   0 40328  612  364 S  0.3  0.0   0:02.11 udisks-daemon
 2899 takekosh  20   0  310m  15m  10m S  0.3  0.8   0:05.88 gnome-terminal

「%CPU」の部分が大きいプロセスがCPUを使っています。重くなっている処理ですが、このプロセスが原因ではない場合もあります。

sarは10分ごとのサーバ状況を表示します。

$ sar
 Linux 2.6.32-220.7.1.el6.x86_64 (feanor.localdomain)     2012年07月07日     _x86_64_    (2 CPU)

 00時00分01秒       CPU     %user     %nice   %system   %iowait    %steal     %idle
 00時10分01秒       all     12.29      0.00      4.91      0.14      0.00     82.66
 00時20分01秒       all      6.21      0.00      4.16      0.04      0.00     89.59

コマンドがない場合は「yum install sysstat」で幸せになれます。

このうち「%user」が高ければ「CPUを使い切っている」になります。その時はさっきのtopで見たプロセスを調整することになります。「%iowait」が高い場合はCPUは「他に引きずられて高くなっている」になります。その場合はディスクI/Oを疑ってみます。

時系列での表示なので、負荷の上がった時間帯に走り始める処理(たとえばバックアップとか)を知っていると、それを疑うと近道です。近道ですが、あくまでも推測になので、ときどき遠回りになります。

長くなったので一旦切ります。次はディスクI/Oの確認です。

続き:サーバの負荷を調べるコマンド集その2