私は私が書いたいくつかのPerlにプログラムの出力をパイプで接続しています。これは長いプロセスであり、時には数日かかるので、ボトルネックがある場所を見つけて解決しようとします。私のスクリプトが処理できるよりも速くデータが私のスクリプトにパイプされているのだろうか。このような場合はスクリプトを調整しようとしますが、必要でなければ調整しません。バッファがいっぱいになったときに追加の書き込みを防ぐためにフラグを設定する方法について説明しますが、フラグが設定されているかどうか、どのくらいの頻度で確認するにはどうすればよいですか?どんなアイデアがありますか?
答え1
strace
私はPerlスクリプト(Linux)、dtruss
(OS X)、ktrace
(FreeBSD)、truss
(Solaris)などを追跡するためにシステムコール追跡ツールを使用します。目標は、Perlスクリプトが標準入力からの読み込みを待つのに費やす時間と、他のプログラムが標準出力への書き込みを待つのに費やす時間をチェックすることです。
ここでは作家をボトルネックとしてテストしています。
terminal 1$ gzip -c < /dev/urandom | cat > /dev/null
terminal 2$ ps auxw | egrep 'gzip|cat'
slamb 25311 96.0 0.0 2852 516 pts/0 R+ 23:35 3:40 gzip -c
slamb 25312 0.8 0.0 2624 336 pts/0 S+ 23:35 0:01 cat
terminal 2$ strace -p 25312 -s 0 -rT -e trace=read
Process 25312 attached - interrupt to quit
0.000000 read(0, ""..., 4096) = 4096 <0.005207>
0.005531 read(0, ""..., 4096) = 4096 <0.000051>
ここで、最初の数字は最後のシステムコールが開始されてからの時間であり、最後の数字はシステムコールにかかった時間です。したがって、Perlを使用して後処理を実行してそれを集約できます... [*]
terminal 2$ strace -p 25312 -s 0 -rT -e trace=read 2>&1 | perl -nle 'm{^\s*([\d.]+) read\(0, .*<([\d.]+)>} or next; $total_work += $1 - $last_wait; $total_wait += $2; $last_wait = $2; print "working for $total_work sec, waiting for $total_wait sec"; $last_wait = $2;'
working for 0 sec, waiting for 0.005592 sec
...
working for 0.305356 sec, waiting for 2.28624900000002 sec
...
terminal 2$ strace -p 25311 -s 0 -rT -e trace=write 2>&1 | perl -nle 'm{^\s*([\d.]+) write\(1, .*<([\d.]+)>} or next; $total_work += $1 - $last_wait; $total_wait += $2; $last_wait = $2; print "working for $total_work sec, waiting for $total_wait sec"; $last_wait = $2;'
...
working for 5.15862000000001 sec, waiting for 0.0555740000000007 sec
...
もう少し派手にして、両方、正しいファイルディスクリプタだけを追跡し、それぞれが他の側を待っている時間の割合で、毎秒素晴らしいステータスアップデートを印刷するSystemTapまたはDTraceスクリプトを作成できます。
[*] - 警告:他のファイル記述子から読み書きを呼び出すと、おおよその集計がより正確になりません。この場合、作業時間が過小評価されます。
dtraceのバージョンは実際には非常に簡潔です。
terminal 1$ gzip -c < /dev/urandom | cat > /dev/null
terminal 2$ ps aux | egrep 'gzip| cat'
slamb 54189 95.8 0.0 591796 584 s006 R+ 12:49AM 22:49.55 gzip -c
slamb 54190 0.4 0.0 599828 392 s006 S+ 12:49AM 0:06.08 cat
terminal 2$ cat > pipe.d <<'EOF'
#!/usr/sbin/dtrace -qs
BEGIN
{
start = timestamp;
writer_blocked = 0;
reader_blocked = 0;
}
tick-1s, END
{
this->elapsed = timestamp - start;
printf("since startup, writer blocked %3d%% of time, reader %3d%% of time\n",
100 * writer_blocked / this->elapsed,
100 * reader_blocked / this->elapsed);
}
syscall::write:entry
/pid == $1 && arg0 == 1/
{
self->entry = timestamp;
}
syscall::write:return
/pid == $1 && self->entry != 0/
{
writer_blocked += timestamp - self->entry;
self->entry = 0;
}
syscall::read:entry
/pid == $2 && arg0 == 0/
{
self->entry = timestamp;
}
syscall::read:return
/pid == $2 && self->entry != 0/
{
reader_blocked += timestamp - self->entry;
self->entry = 0;
}
EOF
terminal 2$ chmod u+x pipe.d
terminal 2$ sudo ./pipe.d 54189 54190
since startup, writer blocked 0% of time, reader 98% of time
since startup, writer blocked 0% of time, reader 99% of time
since startup, writer blocked 0% of time, reader 99% of time
since startup, writer blocked 0% of time, reader 99% of time
since startup, writer blocked 0% of time, reader 99% of time
^C
since startup, writer blocked 0% of time, reader 99% of time
SystemTapバージョン:
terminal 1$ gzip -c /dev/urandom | cat > /dev/null
terminal 2$ ps auxw | egrep 'gzip| cat'
slamb 3405 109 0.0 4356 584 pts/1 R+ 02:57 0:04 gzip -c /dev/urandom
slamb 3406 0.2 0.0 10848 588 pts/1 S+ 02:57 0:00 cat
terminal 2$ cat > probes.stp <<'EOF'
#!/usr/bin/env stap
global start
global writer_pid
global writes
global reader_pid
global reads
probe begin {
start = gettimeofday_us()
writer_pid = strtol(argv[1], 10)
reader_pid = strtol(argv[2], 10)
}
probe timer.s(1), end {
elapsed = gettimeofday_us() - start
printf("since startup, writer blocked %3d%% of time, reader %3d%% of time\n",
100 * @sum(writes) / elapsed,
100 * @sum(reads) / elapsed)
}
probe syscall.write.return {
if (pid() == writer_pid && $fd == 1)
writes <<< gettimeofday_us() - @entry(gettimeofday_us())
}
probe syscall.read.return {
if (pid() == reader_pid && $fd == 0)
reads <<< gettimeofday_us() - @entry(gettimeofday_us())
}
EOF
terminal 2$ chmod a+x probes.stp
terminal 2$ sudo ./pipe.stp 3405 3406
since startup, writer blocked 0% of time, reader 99% of time
...
答え2
pv -TC
パイプラインにコマンドを挿入できます。
cmd1 | pv -TC | cmd2
pv
独自のバッファを使用して、-T
1秒間の平均フィルを報告するようにします(デフォルト)。
常に100%は、出力がcmd1
消費されるよりも出力が速く生成されることを意味します。cmd2
そうでなければその逆です。パイプ自体は64kBを保存することができます。
-B
指定されたpv
バッファサイズも参照してください。次のように複数のsを使用できますpv
。
$ cmd1 | pv -cCTrbN 'cmd1 -> cmd2' | cmd2 | pv -cCTrbN 'cmd2 -> cmd3' | cmd3
cmd1 -> cmd2: 1.92GiB { 53%} [ 387MiB/s]
cmd2 -> cmd3: 1.92GiB { 0%} [ 387MiB/s]