水底

ScalaとかC#とかk8sとか

プログラムを変更せずに標準出力ごとにタイムスタンプを付ける方法とPythonでのサンプル

develop shell

プログラムの実行時間を計測したいけどプログラム自体には手を加えたくないor加えられないということがあると思います。プログラム全体の実行時間の計測時間であれば time コマンドで簡単に行なえますが、より内部的に計測する場合の一つの手段として、標準出力のタイミングをチェックするという方法があります。 そんなときに便利なコマンドのメモです。

例えばこんな感じに。

[2019-05-18 17:11:14] 0
[2019-05-18 17:11:15] 1
[2019-05-18 17:11:16] 2
[2019-05-18 17:11:17] 3
[2019-05-18 17:11:18] 4

いくつか方法があります。

コマンド

(1) シェル芸で頑張る

実行例
{command} | xargs -L 1 bash -c 'printf "[%s] %s\n" "$(date +%Y-%m-%d\ %H:%M:%S)" "$*"' bash
[2019-05-18 17:11:14] 0
[2019-05-18 17:11:15] 1
[2019-05-18 17:11:16] 2
メリット
  • 依存が少ないためポータビリティが高い
  • 改変する自由度が高い
デメリット
  • コマンドが長く、手打ちには面倒
参考

(2) ts コマンド

インストール
sudo apt install moreutils # debian/ubuntu
brew install moreutils # mac
実行例
{command} | ts '[%Y-%m-%d %H:%M:%S]'
[2019-05-18 17:11:14] 0
[2019-05-18 17:11:15] 1
[2019-05-18 17:11:16] 2

他にも色々な表示方法があります。

{command} | ts -s # プログラム開始からの経過時間
00:00:00 1
00:00:01 2
00:00:02 3

{command} | ts -i # 直前の出力からの経過時間
00:00:00 1
00:00:01 2
00:00:01 3
メリット
  • コマンドがシンプル
  • 専用コマンドなので高機能
デメリット
  • コマンドのインストールが必要

(3) gnomon コマンド

インストール
npm install -g gnomon
実行例
{command} | gnomon

すごくいい感じなので公式のgifを。 f:id:amaya382:20190518173151g:plain

メリット
  • 専用コマンドなので高機能
    • ｶｯｺｲｲ
デメリット
  • コマンドのインストールが必要
    • npmも必要

Pythonの実例とバッファリングのお話

現在時刻を表示だけの簡単なスクリプトです。ただし、その間隔がだんだん長くなります。

# main.py
import time
import datetime

for i in range(4):
    time.sleep(i)
    print("{0:%Y-%m-%d %H:%M:%S}".format(datetime.datetime.now()))

このスクリプトの各 print のタイミングを計測したいと思います。ここでは ts -s でプログラム開始からの経過時間を計測します。

python3 main.py | ts -s
00:00:06 2019-05-18 17:49:24
00:00:06 2019-05-18 17:49:25
00:00:06 2019-05-18 17:49:27
00:00:06 2019-05-18 17:49:30

実行してみるとプログラム終了時にまとめて出力されてしまい、うまく計測できませんでした。 Pythonスクリプト内でコマンドが実行された時刻は現在時刻の変化として出力されていますが、プログラム開始からの経過時間は全て6秒になってしまっています。

これはPythonからの出力がバッファリングされてまとめて出力されることによるものです。 -u オプションを付けることでバッファリングを無効にすることができます。

python3 -u main.py | ts -s
00:00:00 2019-05-18 17:49:34
00:00:01 2019-05-18 17:49:35
00:00:03 2019-05-18 17:49:37
00:00:06 2019-05-18 17:49:40

他にも、print 関数側で強制フラッシュオプション print("foo", flush=True) を付ける、環境変数 PYTHONUNBUFFERED=1 を設定するといった方法もあります。

Pythonに限らずデフォルトでバッファリングが有効なコマンド類も多いですが、大抵オプションが用意されています。例えば grep の --line-buffered とかもその一つで、行単位でflushしてくれるようになります。その他、 stdbuf コマンドを利用して無理やりバッファの挙動を変更するという方法もあります。この辺りは tail -f を grep 等でフィルタしながらリアルタイムでログを見るときとかにもお世話になるやつです。

当然ですが、バッファリングを無くすと大量の出力でパフォーマンスが落ちるのでご注意を。