2021-03-07

気付けば約一年ぶりになってしまった。

プロセスのCPU使用率をログする

psコマンドを使ってプロセスのCPU使用時間をログする

あるゲームのサーバプログラムをLinuxに常駐するにあたり、CPU使用率の高さが気になったため使用率をログして観察することにした。

使用するのはpsコマンド。

ps -o pid,%mem,etime,time,cmd -p 1677987 --no-headers

引数の説明

出典: ps(1)

これを実行すれば実行時点でのプロセスの情報が見られる。あとはこのコマンドを定期的に実行し続け、ファイルに記録すればログできる。

while sleep 5; do ps -o pid,%mem,etime,time,cmd -p 1677987 --no-headers; done | ts '%FT%.T%z' | tee cpu.log

コマンドの説明

とはいえ、これで得られる情報はCPUの延べ使用時間であり、CPUの使用率ではない。psの-o引数に%cpuというオプションを与えることはできるが、これはプロセスが起動してから現在までの全使用率の平均なので、htopコマンド等で確認できる現在の使用率は分からない。

各時点でのCPU使用率を求めるには、cpu.logの2レコード間のtime列の差をetime列の差で割ればよい。例えば、timeの差が10秒、etimeの差が5秒であれば、その時のCPU使用率は10 / 5 = 2 = 200%となる。

psコマンドの出力からCPU使用率の推移を求める

それを計算してくれるプログラムを作成するにあたり、上述のpsコマンドの内容を少し修正する。

ps -o pid,%mem,etimes,times,cmd -p 1677987 --no-headers

etimesとtimesはそれぞれetimeとtimeと同様だが、秒数を出力する。

これを先述のwhileループなどと合わせるとこんな感じの出力が出る。

$ while sleep 5; do ps -o pid,%mem,etimes,times,cmd -p 1677987 --no-headers; done | ts '%FT%.T%z' | tee cpu.log
2021-03-08T02:09:42.446245+0900 1677987  6.1  195834    53271 ./bedrock_server
2021-03-08T02:09:47.461144+0900 1677987  6.1  195839    53272 ./bedrock_server
2021-03-08T02:09:52.475901+0900 1677987  6.1  195844    53272 ./bedrock_server
2021-03-08T02:09:57.491627+0900 1677987  6.1  195849    53272 ./bedrock_server
2021-03-08T02:10:02.506595+0900 1677987  6.1  195854    53273 ./bedrock_server
2021-03-08T02:10:07.521677+0900 1677987  6.1  195859    53273 ./bedrock_server
2021-03-08T02:10:12.562648+0900 1677987  6.1  195864    53274 ./bedrock_server
... (Ctrl-Cで止めるまで出続ける)

これの右から3番目と2番目がそれぞれetimesとtimesなので、これらをプログラムで解析すればよい。例えばPythonならばこんな感じのプログラムになる。

# cpu.py

with open("out.log") as f:
    # ひとつ前の行を持っておくための変数
    prevLine = None
    for thisLine in f:
        # 最初の行はprevLineに入れてループしなおす
        if prevLine is None:
            prevLine = thisLine
            continue
        # ひとつ前の行と現在の行からそれぞれetimesとtimesの行を取り出す
        # また、タイムスタンプは現在の行のものを流用する
        _, _, _, prevEtimes, prevTimes, *_ = prevLine.split()
        ts, _, _, thisEtimes, thisTimes, *_ = thisLine.split()
        # タイムスタンプとCPU使用率を出力する
        print(ts, (int(thisTimes) - int(prevTimes)) / (int(thisEtimes) - int(prevEtimes)) * 100, sep='\t')
        # 常にprevLineがthisLineのひとつ前の行になるようにする
        prevLine = thisLine

psコマンドの出力は秒単位でありあまり精度が高くない。筆者の環境では上記プログラムをそのまま実行したら0.0と20.0が不規則に繰り返された。もっと多くの行の平均を取る、100秒毎のデータ間で使用率を計算するなどの工夫をするといいだろう。筆者はHaskellerなのでHaskellで作ってみたら、いい感じのデータが取れた。

なおpsコマンドが情報源としている/procファイルシステムを自分で読みに行く手もある(proc(5))。ログが有用だと思ったらそちらに切り替えるといいだろう。/proc/$PID/statを解析することになる。Clock tick数(sysconf(_SC_CLK_TCK))をC言語以外でどう取るかがちょっと面倒くさいが十分可能である(Pythonならばos.sysconf_names['SC_CLK_TCK']でできるらしい)。やはり筆者はHaskellで作ってみたら、(当たり前だが)同じようなデータが取れた。Clock tick数の数値によってはpsよりも精度の高い値が得られる(筆者の環境では1秒あたり100なので、0.01秒の精度になった)。

グラフの作成は筆者のようなエクセル嫌いであればOnline Graph Maker · Plotly Chart Studioがお手軽でオススメ。

お問い合わせはこちらまで: @matil019 リプにブログのリンクを含めていただけるとスムーズに会話できます。
記事一覧