Странно работает скрипт SystemTap. Есть специалисты по этому инструменту?

Question

[Александр Демченко]

Дано: небольшой скрипт, который следит за вызовами сисколов read и write из конкретного процесса и считает, сколько данных было записано и прочитано процессом в каждый файл.

global fds, counts

probe syscall.open.return {
        if ( ( pid() == target() ) & ( $return != -1 ) ) {
                printf("%s opened as %d\n", user_string($filename), $return)
                fds[$return] = user_string($filename)
        }
}

probe syscall.read.return, syscall.write.return {
        if ( (pid() == target()) & ($return > 0) ) {
                counts[fds[$fd]] += $return
        }
}

probe end {
        foreach (fname in counts+) {
                count = counts[fname]
                if ( count > 1024) {
                        count = count / 1024
                        bs = "Kb"
                } else {
                        bs = "B"
                }
                printf("%s: %d %s\n", fname, count, bs)
        }
}

Если запустить его так: stap test.stp -c 'cat test.stp' - то все вроде работает корректно. Вот вывод:

...
здесь вывод самого cat
...
/etc/ld.so.cache opened as 3
/lib64/libc.so.6 opened as 3
/usr/lib/locale/locale-archive opened as 3
test.stp opened as 3
test.stp: 541 B
: 541 B
/lib64/libc.so.6: 832 B

Но, если я пытаюсь перенаправить вывод cat в /dev/null - stap test.stp -c 'cat test.stp > /dev/null' - то получаю какую-то ерунду:

/etc/ld.so.cache opened as 3
/lib64/libtinfo.so.5 opened as 3
/lib64/libdl.so.2 opened as 3
/lib64/libc.so.6 opened as 3
/dev/tty opened as 3
/usr/lib/locale/locale-archive opened as 3
/proc/meminfo opened as 3
/usr/lib64/gconv/gconv-modules.cache opened as 3
/lib64/libtinfo.so.5: 832 B
/lib64/libdl.so.2: 832 B
/lib64/libc.so.6: 832 B
/proc/meminfo: 1024 B

Как-будто файл test.stp и не открывается вовсе. Сначало думал, что это ядро меня как-то обманывает: видит, что вывод сливается в пустоту и не делает ничего. Но если запускать то же самое под strace получается вывод одинаковый в обоих случаях:

strace -e open -o trace cat test.stp > /dev/null

open("/home/al/lib/tls/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/home/al/lib/tls/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/home/al/lib/x86_64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/home/al/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
open("test.stp", O_RDONLY)              = 3
+++ exited with 0 +++

Не могу понять, где я ступил.

Answer 1

[Вадим Мисбах-Соловьёв]

Для начала, в команде вызова cat под strace вы в нуль перенаправляете вывод stdout'а strace (которого, впринципе, и нету), а не cat.

Ну а так — скорее всего, оптимизации системтапа. Сейчас, дайте пару минут, покопаю.