Bagaimana saya bisa tahu jika buffer pipa penuh?

Saya menyalurkan output dari satu program ke beberapa Perl yang saya tulis. Ini adalah proses yang berjalan lama, kadang-kadang berhari-hari, jadi saya ingin mencari tahu di mana kemacetan saya dan mencoba untuk membukanya. Saya ingin tahu apakah data sedang disalurkan ke skrip saya lebih cepat daripada skrip saya bisa memprosesnya. Jika demikian, saya akan mencoba untuk menyempurnakan skrip saya, tetapi tidak jika saya tidak perlu. Saya melihat pembicaraan tentang flag yang diset ketika buffer penuh yang mencegah menulis lagi padanya, tetapi bagaimana saya memeriksa untuk melihat apakah atau seberapa sering flag itu disetel? Ada ide?

Saya akan melacak skrip Perl Anda dengan alat pelacak panggilan sistem: strace(Linux), dtruss(OS X), ktrace(FreeBSD), truss(Solaris), dll. Tujuannya adalah untuk melihat berapa lama waktu yang dihabiskan skrip Perl Anda untuk membaca dari stdin dan berapa banyak waktu yang dihabiskan oleh program lain untuk menulis pada stdout-nya.

Di sini saya menguji ini dengan penulis sebagai hambatan:

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>

Angka pertama di sini adalah waktu sejak dimulainya syscall sebelumnya, dan angka terakhir adalah waktu yang dihabiskan di syscall. Jadi kita dapat memposting proses dengan Perl sedikit untuk menggabungkannya ... [*]

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
...

Anda bisa menjadi lebih hebat dan membuat skrip SystemTap atau DTrace yang melacak kedua sisi sekaligus, hanya melacak deskriptor file yang benar, dan mencetak pembaruan status yang bagus setiap detik atau lebih dengan berapa persen waktu masing-masing menunggu yang lain.

[*] - Peringatan: agregasi kasar saya kurang tepat jika baca / tulis dipanggil pada deskriptor file lainnya; itu akan meremehkan waktu kerja dalam kasus itu.

Versi dtrace sebenarnya cukup rapi.

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

Dan versi 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
...

Anda bisa memasukkan pv -TCperintah di saluran pipa Anda:

cmd1 | pv -TC | cmd2

pvmenggunakan buffernya sendiri dan -Tmembuatnya melaporkan seberapa penuhnya rata-rata pada periode 1 detik (secara default).

Jika selalu 100%, maka itu berarti cmd1lebih cepat dalam menghasilkan output daripada cmd2memakannya. Jika tidak, maka sebaliknya. Waspadalah bahwa pipa itu sendiri dapat menampung 64kB.

Lihat juga -Buntuk menentukan pvukuran buffer. Anda dapat menggunakan beberapa pvs seperti pada:

$ 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]