.bashrc に処理時間を報告させる

ある時ふと「.bashrc と .bash_profile を区別する必要ははたしてあるのか」ということを思って、それからというもの、スタートアップの処理は全て .bashrc に書いている。見通しが良いしリロードも簡単に出来るのですこぶる良かったのだが、とうとう重たくなってきてしまった。その時点でのマシンの状態にもよるが、端末を立ち上げるたびに数秒待たされている。ボトルネックを探してなんとかしようと思うが、とりあえず .bashrc の最後で全体の処理にかかった時間を報告させることにした。

ちなみに私の環境の .bashrc では、常に末尾でメッセージを echo させるようにしている。

$ . ~/.bashrc 
... /home/minagoro/.bashrc is loaded

これは元々 .bashrc と .bash_profile の実行されるタイミングの違いを覚えるために、ずっと前に始めたものだ。どこかのブログに書いてあったのだけど、実用性のある出力ではないので、多くの人はすぐに止めると思う。だけど、実際シェルなので1行くらい出力が出ても邪魔にならないし、きちんと動作しているのがわかるので、私はずっとそのままにしている。

という訳で、すでに出力しているこのメッセージに、全体の処理にかかった時間を含めることにした。イメージとしてはこんな感じで、必要な精度はミリ秒とした。

... /home/minagoro/.bashrc is loaded (XXX msec)

まず、.bashrc の冒頭でその時点での時間を取得する。シェルが立ち上がってからの秒数を記録する SECONDS 環境変数というものがあるが、これでは精度が足りない。今回は date コマンドを使用して、ナノ秒までをとることとした。

# Start measuring the processing time for this script
start_time="`date +%s.%N`"

ちなみに、date コマンドの BSD 実装は %N に対応しておらず、秒までの精度しかとれない。 macOS で GNU 実装のコマンドを利用するには、GNU coreutils パッケージをインストールするのが常套手段である。 BSD 実装との区別のためにコマンド名の頭には全て g がつけられていて、 date コマンドの場合は gdate コマンドとして存在する。

$ date +%s.%N
1506684842.N
// BSD 実装では %N に対応していないので、ナノ秒ではなく N として表示される。

$ brew install coreutils
$ gdate %s.%N
1506684908.032411000
// GNU 実装では %N がナノ秒に変換される。

続いて、.bashrc の最後で処理時間を計測する。この時点での時間を取得して、冒頭で取得した時間の差から全体の処理時間を求める。少数の計算が必要になるが、ここでは古き良き bc コマンドを利用した。

# Finish measuring the processing time for this script
finish_time=`date +%S.%N`
elapsed_time=`echo "(${finish_time} - ${start_time}) * 1000" | bc`

echo "... ${HOME}/.bashrc is loaded (${elapsed_time%.*} msec)"

最後に、.bashrc を動かしてみる。

$ . ~/.bashrc 
... /home/minagoro/.bashrc is loaded (3103msec)

無事、処理時間が報告されるようになった。私の環境では、シェルが立ち上がるまでに3秒近くかかるようだ。👎