あなたの知らない time(1) の世界

The moment

自分が書いたプログラムのメモリ使用量を測定したいことがある。プログラムがOOM Killerによってお亡くなりになった場合や、ページフォルトをなくして高速化したい場合などだ。定常的に起動するサーバーのプログラムなら、sarや meminfo など(今なら Datadog とかだろうか)を使ってじーっと見つめるわけだ。もっとモダンにやるなら perf や DTrace を使ってもよいかもしれない。しかしこれらのツールは基本的にプロセスIDを渡してサンプリングして外から覗く方法だ。

わたしのユースケースはデーモンプロセスではなく、 main から入って必要な計算をして、それが終わったら main を抜けるバッチジョブ(単にコンソールから実行して終わるまで待つ、いわゆる "Hello world!" 的なやつ)だ。これだと、プログラムが起動して終わるまでそこそこの時間で終わってしまって、外部プロセスを一緒に起動するものだとタイミングを合わせにくい。それに、外部からのサンプリングでは最大使用量は分からないから、キャパシティ設計やOOM Kill防止には使えない。サンプリングのタイミングのメモリ使用量しか測定できず、サンプリングの周期を短くすれば性能を阻害してしまうし、長くしてしまえば最大使用量に近い値をとる可能性が下がる。もっと文句をいうと、VisualVM使えねえんだよ!!

うーん何かよい方法はないものか…とインターネットを放浪しているとやはりそこはStackOverflowだ。残念ながらそのページは失念してしまったが(昨日のHistoryを見返す気にはなれない)、「Javaでメモリ使用量測りたいんだけど、どうしたらいいの?」というよくある質問に「Macなら " time -lp java ... " でカンタンだよー」というJavaMacも実は全然関係ない質問だった。もっとドンピシャなやつは見つかったのだけど、用語の組み合わせからして検索しにくいものであることはご理解いただきたい(追記:別マシンのブラウザに残っていた)。

でまあ、いそいろ調べて BSD time(1)とかGNU time(1)をみているうちに Linux でも "/usr/bin/time -v " でMax RSSを調べられることがわかった。ちなみに最初は BSD time(1) のコード見てどうやってんのかなーとか調べていたが、始めから GNU time(1) のマニュアルを丁寧に読めば全部わかる話だった。どちらも getrusage(2) というPosix APIを叩いて子プロセスの情報をカーネルからとってくるようになっている。BSDは調べていないが、Linuxでは /proc/[pid]/stat から情報をとってきているようだ。なので、 malloc/free の合計とかにはなっていなくて、OSからみえるページ単位とかのはずなんだがその割にはRSSが4Kにアラインされていないのでよくわからない。そもそもRSSって何なんだ。

手元にある、4GBほどメモリを使うテストプログラムを動かしてみると、こんな感じになる。

$ /usr/bin/time -v ./a.out                                           
/sys/kernel/mm/transparent_hugepage/enabled: [always] madvise never
memory allocator performance test
2097152 of memory pointers with 2048 bytes; 4.295 GB total
time: 181.617 sec
        Command being timed: "./a.out"
        User time (seconds): 181.99
        System time (seconds): 1.11
        Percent of CPU this job got: 99%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 3:03.41
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 4838748
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 0
        Minor (reclaiming a frame) page faults: 1205812
        Voluntary context switches: 1
        Involuntary context switches: 2704
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

ページフォルト数、ファイルIO、ネットワークIO、コンテキストスイッチ数、ページサイズからon-cpu timeまでわりと重要なものがサクッと出るので、DTraceとかperfとか重いやつをいきなり始める前にこれでマイクロベンチをとってみるのがよいだろう。ちなみに "-f FORMAT" で任意の形式で出せるし、出力をファイルに出すことも可能だ。つまりこういう風に無駄に結果をJSONに保存することもできる。

$ /usr/bin/time -f "{\"maxrss\":%M}" -o out.json lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 16.04.1 LTS
Release:        16.04
Codename:       xenial
$ cat out.json
{"maxrss":11864}                                 

ちなみに、ソースコードBSD time の方がさっぱりしてて読みやすいけど、Formattingの機能はない。GNU timeはやけにゴチャゴチャしてるなーと思ったんだけど、Formattingのためだったというのは後で気づいた。

もうちょっと真面目にやるなら、Linuxには最近 eBPF という優れたトレーシングフレームワークが入って、そのフロントエンド的なツールとして IOVisorというスグレモノがあって、こんな感じで全てのメモリアロケーションをトレースできる。これをちょっと書き換えたらMax RSSなんてお手のものだし、JVMの中身がわかっていればヒープとページの関係もよくわかる。

ちなみに、Mac OSについているBSD timeはなかなかふざけていて、manpageを見てもRSS関連は単位が明記されていない。プログラムの出力をみても分からない。参考にと書かれいている getusage(2) のmanを見ようとしたら入っていない(ちゃんとXCodeも入れてるつもりだ)。で、ヘッダにコメントであるかな?と、manpageにかかれている /usr/include/sys/resource.h を見てみようとすると

$ less /usr/include/sys/resource.h
/usr/include/sys/resource.h: No such file or directory

である。Akisute先生じゃないが、🍎📠である。自作のプログラムで検証するに、どうやらバイト単位のようだが…

$ /usr/bin/time -lp ./a.out
/sys/kernel/mm/transparent_hugepage/enabled: Bad file descriptor
Cannot open THP setting file. Maybe not Linux?
memory allocator performance test
4194304 of memory pointers with 2048 bytes; 8.590 GB total
time: 417.990 sec
real       425.90
user       153.47
sys        204.87
11523166208  maximum resident set size
         0  average shared memory size
         0  average unshared data size
         0  average unshared stack size
  44780389  page reclaims
         0  page faults
         0  swaps
         0  block input operations
         0  block output operations
         0  messages sent
         0  messages received
         0  signals received
     10802  voluntary context switches
   2338890  involuntary context switches

知っていたのにここまで読んでくれた方には感謝の念しかない。そう私が知らなかっただけ。