ftrace marker と uprobe-based event tracer オーバヘッド比較

はじめに

ユーザ空間のプログラムのトレース情報を取得する方法には、さまざまなものがありますが、ここでは "ftrace marker" と "uprobe-based event tracer" を取り上げ、トレースオーバヘッドを測定してみます。
"ftrace marker" とは ftrace trace_marker ファイルにトレース情報を書き込むことで、ftrace でトレース情報を取得する機能です。Kernel のトレース情報とユーザプログラムのトレース情報を照らしあわせたい時等に便利です。
使い方は簡単で、tracing ディレクトリの trace_marker ファイルに write するだけです。
例

# echo test > /sys/kernel/debug/tracing/ftrace_marker
# cat /sys/kernel/debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 1/1   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
           <...>-23108 [003] ...1 34500.124363: tracing_mark_write: test

"uprobe-based event tracer" とは kprobe-based event tracer のユーザ空間版で、kprobe のように動的にプローブを差し込むことができる機能です。以下でも若干解説しますが、詳しい使い方については、ドキュメントをご覧ください。

比較方法
"ftrace marker" と "uprobe-based event tracer" をそれぞれ使って、トレースポイントを 1000回踏むのにかかる時間を測定します。
測定プログラムは以下を用意しました。
下の3つの関数をそれぞれ 1000回ずつ呼び出し、かかった時間を測定する簡単なものです。
do_nothing()  : 関数呼び出しのオーバヘッドを考慮するための何もしない関数
marker_write() : ftrace marker に write する関数
uprobe_test() :  uprobe を差し込む対象の関数

probench.c

#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <fcntl.h>
#include <sys/time.h>

int marker_fd;

long time_usec(void) {
    struct timeval tv;

    gettimeofday(&tv, NULL);
    return tv.tv_sec * 1000000 + tv.tv_usec;
}

void probe_bench(void (*func)()) {
    long start_us, end_us, diff_us;
    int i, loop_max;

    loop_max = 1000;
    start_us = time_usec();
    for (i = 0; i < loop_max; i++) {
        func();
    }
    end_us = time_usec();
    diff_us = end_us - start_us;
    printf("Elapsed time(us): %ld\n", diff_us);
    printf("per trace point(us): %f\n", (double) diff_us / loop_max);
    printf("\n");
}

void do_nothing(void) {
}

void marker_write(void) {
    write(marker_fd, "test\n", 5);
}

void uprobe_test(void) {
}


int main(int argc, char *argv)
{
    char path[256];
    int trace_fd;

    strcpy(path, "/sys/kernel/debug/tracing/tracing_on");
    trace_fd = open(path, O_WRONLY);
    if (trace_fd >= 0)
        write(trace_fd, "1", 1);

    strcpy(path, "/sys/kernel/debug/tracing/trace_marker");
    marker_fd = open(path, O_WRONLY);

    printf("-- nothing --\n");
    probe_bench(do_nothing);

    printf("-- ftrace marker --\n");
    probe_bench(marker_write);

    printf("-- uprobe --\n");
    probe_bench(uprobe_test);

    close(marker_fd);
}

Makefile

probench: probench.c
 gcc -g -o $@ $< -O2

clean:
 rm probench

上記のプログラムを make したあと、uprobe を差し込む場所を指定します。
まず、ELF を読んでプログラムヘッダからテキストセグメント開始アドレスを探しましょう。

# readelf -e probench | less
...
プログラムヘッダ:
  タイプ        オフセット          仮想Addr           物理Addr
            ファイルサイズ        メモリサイズ         フラグ 整列
...
  LOAD           0x0000000000000000 0x0000000000400000 0x0000000000400000
                 0x0000000000000be4 0x0000000000000be4  R E    200000

テキストセグメント開始アドレスは0x400000とわかりました。
次に、uprobe_test 関数のアドレスは以下のコマンドで取得できます。

 # readelf -s probench | grep uprobe_test
    59: 0000000000400830     2 FUNC    GLOBAL DEFAULT   13 uprobe_test

アドレスは0x400830とわかりました。
uprobe_test にプローブを差し込みましょう。uprobe_test 関数のアドレス0x400830 から テキストセグメント開始アドレス 0x400000を引き算した 0x830 をuprobe_events に書き込みます。書き込み後はイベントをオンにしてやります。

# echo 'p:test /path/to/probench:0x830' > /sys/kerenel/debug/tracing/uprobe_events
# echo 1 > /sys/kerenel/debug/tracing/events/uprobes/test/enable

以上で準備がととのいました。ベンチマークプログラム : probench を実行しましょう。

# ./probench       
-- nothing --
Elapsed time(us): 8
per trace point(us): 0.008000

-- ftrace marker --
Elapsed time(us): 1742
per trace point(us): 1.742000

-- uprobe --
Elapsed time(us): 4255
per trace point(us): 4.255000

結果は、
ftrace marker : 1.7us/TracePoint
uprobe : 4.3us/TracePoint
でした。関数呼び出しのオーバヘッドは無視できるようです。
uprobe は ftrace marker と比べて、若干オーバヘッドが嵩むようです。

余談
uprobe-based event tracer ではなく、systemtap を使った場合でも測って見ました。
以下のようなスクリプトを実行したあとで probench を走らせます。

#!/usr/bin/stap

probe begin {
 printf("start\n")
}

probe process("/home/eiichi/git/probench/probench").function("uprobe_test") {
}

# ./probench
-- nothing --
Elapsed time(us): 8
per trace point(us): 0.008000

-- ftrace marker --
Elapsed time(us): 1766
per trace point(us): 1.766000

-- uprobe --
Elapsed time(us): 3994
per trace point(us): 3.994000

systemtap の場合は 4.0us/TracePoint でした。uprobe-based event tracer と変わらないようです。

まとめ
"ftrace marker" と "uprobe-based event tracer" のオーバヘッドを比較すると、前者より後者のほうが２倍以上大きいことがわかりました。トレースオーバヘッドを気にする かつ ユーザプログラムを改変できる場合は ftrace marker を使ったほうがいいでしょう。

参考情報：
kernel/Documentation/trace/ftrace.txt
kernel/Documentation/trace/kprobetracer.txt
kernel/Documentation/trace/uprobetracer.txt