☰

パイプライン時間を測定する方法は？

tag-icon • tag-icon bash shell pipe time
パイプライン時間を測定する方法は？

私は2つの別々のコマンドで構成されたコマンドが欲しいですtime。 1 つは出力を別のコマンドにパイプします。たとえば、次の2つのスクリプトを考えてみましょう。

$ cat foo.sh
#!/bin/sh
sleep 4

$ cat bar.sh
#!/bin/sh
sleep 2

今のtime時間をどのように報告できますかfoo.sh | bar.sh？ （はい、ここではパイプが意味をなさないことがわかりますが、これは単なる例です。）パイプなしでサブシェルで順番に実行すると、期待どおりに機能します。

$ time ( foo.sh; bar.sh )

real    0m6.020s
user    0m0.010s
sys     0m0.003s

ただし、パイピング時に機能させることはできません。

$ time ( foo.sh | bar.sh )

real    0m4.009s
user    0m0.007s
sys     0m0.003s

$ time ( { foo.sh | bar.sh; } )

real    0m4.008s
user    0m0.007s
sys     0m0.000s

$ time sh -c "foo.sh | bar.sh "

real    0m4.006s
user    0m0.000s
sys     0m0.000s

同様の質問を読んだ(複数のコマンドで時間を実行し、時間出力をファイルに書き込む方法は？）スタンドアロンtime実行ファイルを試しました。

$ /usr/bin/time -p sh -c "foo.sh | bar.sh"
real 4.01
user 0.00
sys 0.00

パイプラインのみを実行する3番目のスクリプトを生成しても機能しません。

$ cat baz.sh
#!/bin/sh
foo.sh | bar.sh

それから時間：

$ time baz.sh

real    0m4.009s
user    0m0.003s
sys     0m0.000s

time興味深いことに、最初のコマンドが完了した直後に終了しないようです。次のように変更した場合bar.sh：

#!/bin/sh
sleep 2
seq 1 5

繰り返しますが、以前に出力が印刷されるとtime予想していましたが、そうではありません。timeseq

$ time ( { foo.sh | bar.sh; } )
1
2
3
4
5

real    0m4.005s
user    0m0.003s
sys     0m0.000s

レポート1を印刷する前に完了するのを待っているにもかかわらず、time実行にかかる時間は計算されないようです。bar.sh

すべてのテストは、Archシステムでbash 4.4.12（1）リリースを使用して実行されました。私はプロジェクトでbashだけを使うことができ、これはそれの一部なので、zsh他の強力なシェルがこの問題を解決できるとしても、それは私にとって実行可能な解決策ではありません。

それでは、一連のパイプラインコマンドを実行するのにかかる時間をどのように取得できますか？そして、私たちがこれを行うとき、なぜ動作しませんか？time最初のコマンドが完了するとすぐに終了するようです。なぜ？

私は次の方法で個人的な時間を持つことができることを知っています。

( time foo.sh ) 2>foo.time | ( time bar.sh ) 2> bar.time

しかし、すべてのタスクを単一のタスクで時間を測定することが可能であるかどうかはまだ知りたいです。

1 これはバッファの問題ではないようです。とを使ってスクリプトを実行してみましたが、unbuffered出力する前にstdbuf -i0 -o0 -e0数字がtime印刷され続けます。

答え1

それはい布材。

パイプラインの複数の部分が同時に実行されます。パイプ内でプロセスを同期/シリアル化する唯一のことはIOです。つまり、あるプロセスがパイプの次のプロセスに書き込み、次のプロセスが最初のプロセスによって書き込まれた内容を読み取ります。これ以外にも公演をしています。独立してお互い。

パイプ内のプロセス間で読み取りまたは書き込みが発生しないため、パイプの実行にかかる時間がsleep最も長い呼び出し時間です。

また、書いたかもしれません

time ( foo.sh & bar.sh &; wait )

ここにリリースチャットで少し変更されたいくつかのサンプルスクリプト:

#!/bin/sh
# This is "foo.sh"
echo 1; sleep 1
echo 2; sleep 1
echo 3; sleep 1
echo 4

そして

#!/bin/sh
# This is "bar.sh"
sleep 2
while read line; do
  echo "LL $line"
done
sleep 1

質問は「time ( sh foo.sh | sh bar.sh )3+3 = 6秒ではなく4秒が返されるのはなぜですか？」です。

各コマンドが実行されたおおよその時間を含む何が起こっているかを確認するには、次のようにします（出力には私の説明が含まれます）。

$ time ( env PS4='$SECONDS foo: ' sh -x foo.sh | PS4='$SECONDS bar: ' sh -x bar.sh )
0 bar: sleep 2
0 foo: echo 1     ; The output is buffered
0 foo: sleep 1
1 foo: echo 2     ; The output is buffered
1 foo: sleep 1
2 bar: read line  ; "bar" wakes up and reads the two first echoes
2 bar: echo LL 1
LL 1
2 bar: read line
2 bar: echo LL 2
LL 2
2 bar: read line  ; "bar" waits for more
2 foo: echo 3     ; "foo" wakes up from its second sleep
2 bar: echo LL 3
LL 3
2 bar: read line
2 foo: sleep 1
3 foo: echo 4     ; "foo" does the last echo and exits
3 bar: echo LL 4
LL 4
3 bar: read line  ; "bar" fails to read more
3 bar: sleep 1    ; ... and goes to sleep for one second

real    0m4.14s
user    0m0.00s
sys     0m0.10s

したがって、inへの最初の2つの呼び出しの出力バッファリングは、全体としてechoパイプラインに6秒ではなく4秒かかりますfoo.sh。

答え2

これは良い例ですか？

$ time perl -e 'alarm(3); 1 while 1;' | perl -e 'alarm(4); 1 while 1;'
Alarm clock

real    0m4.004s
user    0m6.992s
sys     0m0.004s

スクリプトbusyloopはそれぞれ3秒、4秒間持続し、並列実行のため、実際の時間は合計4秒、CPU時間は7秒かかりました。 （少なくともおおよそ）

またはこれ：

$ time ( sleep 2; echo) | ( read x; sleep 3 )

real    0m5.004s
user    0m0.000s
sys     0m0.000s

並列に実行されないため、合計時間は5秒です。すべての睡眠に費やされるため、CPU時間は使用されません。

答え3

可能であればsysdigトラッカーを挿入できます。いつでもコードを変更して必要な書き込みを追加できるとします。/dev/null

echo '>::blah::' >/dev/null
foo.sh | bar.sh
echo '<::blah::' >/dev/null

（ただし、これは「単一操作」の要件を満たしていません。）その後、以下を介して項目を記録します。

$ sudo sysdig -w blalog "span.tags contains blah"

その後、期間をエクスポートするにはsysdigドラッグが必要になることがあります。

description = "Exports sysdig span tag durations";
short_description = "Export span tag durations.";
category = "Tracers";

args = {}

function on_init()
    ftags = chisel.request_field("span.tags")
    flatency = chisel.request_field("span.duration")
    chisel.set_filter("evt.type=tracer and evt.dir=<")
    return true
end

function on_event()
    local tags = evt.field(ftags)
    local latency = evt.field(flatency)
    if latency then
        print(tostring(tags) .. "\t" .. tonumber(latency) / 1e9)
    end
    return true
end

ディレクトリに保存されると、sysdig/chiselsファイルは spantagduration.lua次のように使用できます。

$ sysdig -r blalog -c spantagduration
...

csysdigまたはJSON出力を使用できます。

答え4

とても面白いですね。古いスレッドというのはわかりましたが、私も同じ状況になっていました。エイリアシングが簡単な解決策であることがわかりました。少なくともこれはbashとfishで動作します。すべての殻についてはよくわかりません。

変える:time ( foo.sh | bar.sh )

努力する：

alias foobar="foo.sh | bar.sh" time foobar

関連情報