system.time(Sys.sleep(2)) # 2秒間スリープ user system elapsed
0.000 0.000 2.003 Rで小さなデータを扱っている間は処理にかかる時間はほとんど気になりませんが、データが大きくなったりたくさんの処理を一度に実行したりすると待たされる場合が出てきます。そうなると気になるのが「具体的にどのくらい時間がかかるのか」という点です。
実行時間を計測する関数
処理にかかる時間を計りたいとき、プログラミングの経験がある人ならば、
- 処理開始の現在時刻を変数
sに保存 - 処理実行
- 処理終了の現在時刻を変数
eに保存 e - sで実行時間を取得
という方法がすぐに思い浮かぶと思いますが、Rにはこの一連の流れを行ってくれるsystem.time()関数があります。実行時間を計りたいRコードをsystem.time()関数に渡すと、それにかかった時間を次のように返してくれます。
この中の「elapsed」が処理全体でかかった秒数です。「user」と「system」はCPUを使用した時間を表しています。
しかし、実際にはこの関数だけでは不便なところがあります。
system.time()関数の不便なところ
まず、system.time() は引数に1つの式（expression）しか指定できないため、複数の処理をまとめて計測したい場合は、コード全体を { } で囲むか、わざわざ関数化して渡す必要があります。
また、出力結果が「秒単位」なのも困ることがあります。数秒で終わる処理なら問題ありませんが、処理時間が数時間に及ぶような場合に秒数で出されても直感的に何時間か分かりにくいです。わざわざ電卓で割って計算するのも手間がかかります。
さらに、CPU の「user」時間と「system」時間が出力されますが、通常は単純に「全体でどれだけ時間が経過したか（elapsed time）」だけが分かれば十分なことがほとんどです。
source() をラップして計測を自動化する
私は普段、一連の処理を R スクリプト（.R ファイル）にまとめ、それを source() 関数で実行することをよく行います。そこで、「source() 自体をラップして、実行時間を自動的に計測して表示する関数に置き換えてしまえばいいのではないか」と考えました。
実装したコードは次のとおりです。
source <- function(path) {
# 実行開始時の経過時間を記録
startTime <- proc.time()[3]
# 終了時に実行時間を計算して表示する
on.exit(message("elapsed ", format(as.POSIXct(proc.time()[3] - startTime, tz="UTC"), format="%Hh:%Mm:%Ss")))
# エラー発生時にデバッグモード（recover）に入る設定
options(error = utils::recover)
# 本来のsource関数を実行
base::source(path)
}時間をフォーマット変換する
この実装で工夫したのは、秒単位の数値を Hh:Mm:Ss という読みやすい形式に変換する方法です。
単純に計算して文字列を結合しても良いのですが、ここでは as.POSIXct を利用しました。proc.time()[3] - startTime で得られる「経過秒数」を POSIXct 型に変換し、format() 関数を適用することで、時刻形式への変換をRに任せています。
tz="UTC"を指定しているのは、システムのタイムゾーンによるオフセットが経過時間に加算されていまうのを防ぐためです。
ついでにデバッグ環境も有効にする
あわせて options(error = utils::recover) も組み込んでいます。
長時間かかるスクリプトを実行している中でエラーが出て止まってしまうと、エラーメッセージだけからではどこで何が起きたのかを知ることが難しい場合が多いです。utils::recover()を使うとエラー発生時にその時点での変数状態を確認できるデバッグモードに入ることができます。普段はデバッグモードはオフにしていますが、source()実行時に自動的に有効にすることで切り替え忘れがなくなります。
まとめ
このようにsource()関数を拡張したことで、スクリプトを実行するたびに実行時間が明確に得られるようになり、見通しを立てやすくなりました。特に何度も同じようなスクリプトを実行する状況ではとても役に立つと思います。