TNF ユーティリティの使い方

TNF ユーティリティは、libtnfprobe ライブラリ、prex(1) コマンド、および tnfdump(1) コマンドで構成されています。

• libtnfprobe - プログラムにリンクされているライブラリで、トレース記録をバイナリの TNF トレースファイルに生成します。

• prex - プローブポイントと、プローブポイントによって収集された各種データを操作するユーティリティです。

• tnfdump - バイナリの TNF トレースファイルを ASCII ファイルに変換するユーティリティです。

コード内のデータを収集する箇所 (プローブポイント) に、コマンドを挿入することができます。prex を使用して実行可能オブジェクトを実行すると、プローブポイントの操作が可能になります。収集された情報は、Trace Normal Form (TNF) と呼ばれる形式のトレースファイルに書き込まれます。tnfdump は、そのバイナリの TNF トレースファイルを ASCII ファイルに変換します。

プローブポイントは、.init() セクション、.fini() セクション、マルチスレッド化されたコード、共有オブジェクト、dlopen(3X) によってオープンされた共有オブジェクトなど、C または C++ コードの任意の場所に挿入できます。

また、プローブ関数と呼ばれる関数をこれらのプローブポイントに接続できます。プローブ関数は、収集された情報に基づいてアクションを実行します (現在使用できるプローブ関数は、出力を stderr に書き込むデバッグ関数だけです) 。

通常の TNF セッションでは、以下の操作を行います。

1. プローブポイントをプログラムに挿入します。ソースコードには、プローブポイントがすでに組み込まれている場合もあります。

2. prex を使用して、プログラムを起動します。libtnfprobe は自動的に prex によって起動前にロード (プリロード) されます。プログラムを起動するときに、そのプログラムを libtnfprobe にリンクすることもできます。その場合は、実行中のプログラムに prex を接続できます。「実行中のプロセスへの prex の接続」を参照してください。

3. prex でプローブポイントを操作して、必要な情報をプログラムから収集します。

4. tnfdump を使用して、ターゲットプログラムから生成されたバイナリの TNF 情報トレースファイルを ASCII ファイルに変換します。「読み取り可能な形式へのバイナリファイルの変換」を参照してください。

5. ASCII ファイル中の情報を確認します。

プローブポイントの挿入

プローブポイントの挿入についての詳細は、「上級者向きのトピック」で説明しています。

「C プログラムのサンプル」では、プローブポイントの設計と配置について説明しています。「prex セッションのサンプル」と 「トレースファイルの読み取り」では、プローブポイントの操作方法と、それぞれのプローブポイントでどのような情報が収集されるかについて説明しています。

prex の起動

ユーザーは、prex を使用してプログラムをロードするか、もしくは実行中のプロセスに prex を接続することができます。以下の 2 つの節で、その手順を説明します。

prex によるプログラムの起動

prex を使用してプログラムを起動すると、ターゲットのプログラムに libtnfprove ライブラリがプリロードされます。したがって、プログラムを明示的に libtnfprobe にリンクする必要はありません。

prex は、プログラムを起動し、コードが実行される前にそのプログラムを停止します。.init() セクションが実行される前であってもプログラムの実行は停止されるため、プローブポイントを .init() セクションに配置して初期化コードをトレースすることができます。

プローブポイントが含まれていて、引数を受け取らない a.out という単純な実行可能プログラムの場合には、以下のコマンドを使用できます。

$ prex a.out

(prex は、環境変数 $PATH を使用して実行可能プログラムを検索します。)

オプションを指定するには、以下の書式で指定します。

prex [-o outfilename] [-s kbytes_size]
     [-l sharedobjs] cmd [cmdargs...]

-o、-s、-l オプションについては、「prex のコマンド行オプション」で説明しています。

実行中のプロセスへの prex の接続

a.out という名前のプログラムを実行中に、その a.out のプロセス ID (PID) が 2374 である (ps(1) コマンドを使用して確認できます) が示した場合には、以下のコマンドによって prex を a.out に接続できます。

$ prex -p 2374

実行中のプログラムに prex を接続する場合には、先に libtnfprobe をそのプログラムにリンクする必要があります。libtnfprobe にリンクしていないと、libtnfprobe がプログラムにリンクされていないというエラーメッセージが表示され、prex が終了します。

libtnfprobe とのリンク

libtnfprobe ライブラリにリンクすると、割り当てられたトレースファイルのサイズ (prex のコマンド行オプションで制御可能) に約 33 KB (25 KB は共有可能) を加えた分だけプログラムのサイズが、増加します。prex を使用して実行中のプログラムに接続しない場合は、libtnfprobe にリンクしないでください。

ただし、再起動が容易ではなく、長時間連続して実行するプログラムの場合で、将来そのプログラムに関する情報を収集する可能性がある場合には、libtnfprobe をプログラムにリンクしてください。ウィンドウサーバーなどが、その例です。このような停止や再起動を頻繁に行わない種類のプログラムの場合には、プログラムの実行を開始する前に libtnfprobe にリンクする必要があります。

以下のいずれかの方法で libtnfprobe に、リンクすることができます。

これからプログラムのコンパイルを行う場合には、cc 行に -ltnfprobe を追加します (-lthread を使用している場合には、必ず -lthread の前に -ltnfprobe を入力してください)。

$ cc -ltnfprobe -lthread -o cookie cookie.c

プログラムがコンパイル済みの場合、または libtnfprobe に明示的に依存するプログラムを作成しない場合には、以下のコマンドを使用します。

$ LD_PRELOAD=libtnfprobe.so.1 executable_object_name

LD_PRELOAD については、『リンカーとライブラリ』を参照してください。

prex の停止と再開

prex を使用してプログラムをロードするか、または実行中のプログラムに prex を接続したら、Control-c キーを押してプログラムを停止し、制御を prex に渡します。

prex が実行されて、プログラムが停止すると、prex のプロンプトが表示されます。

prex>

このプロンプトに prex コマンドを入力して、プローブポイントを制御します。たとえば、プローブポイントの一覧表示や、トレースの開始、プログラムのデバッグを行うことができます。

プログラムの実行を再開するには、continue コマンドを入力します。

prex> continue

プログラムを停止して prex に戻るには、Control-c キーを押します。

$ ^c
prex>

prex の標準のコマンド行オプションを表 1-1 に示します。

prex のコマンド行オプション

prex の実行

prex をプログラムに接続後、prex コマンドを使用して、収集するデータのパラメータを変更できます。prex list コマンドを使用して、プログラム内のプローブをすべて表示できます。プログラムの実行中にプローブポイントが実行されると、その実行ごとに情報がトレースファイルに記録されます。収集された情報は、tnfdump() を使用して表示します。tnfdump() については、「tnfdump ファイルの読み取り」を参照してください。

ユーザーは、プログラムに対する prex の接続と切り離しを繰り返し行なって、複数のセッションを作成できます。たとえば、最初のセッションでは、prex を使用してターゲットプログラムを起動し、プローブを設定してから prex コマンドの quit resume を実行することができます。

この操作は、prex の起動、収集する情報の定義、prex の終了を行い、最後にプログラムの実行を再開することによって情報の収集を開始します。これらの処理を行うコマンドを表 1-2 に示します。

2 回目のセッションでは、prex を同じプログラムに接続して、プローブを再設定してから、再度 prex コマンドの continue を実行することができます。この操作は繰り返し何度でも行うことができます。

すべてのトレース結果は、最初のセッションで名前を指定したトレースファイルに書き込まれます。このトレースファイル名を変更することはできません。

prex コマンドの構成要素

プローブポイントをソースコードに挿入するときに、さまざまな属性や (必要に応じて) 値を各プローブポイントに割り当てることができます。たとえば、任意の名前を "name" 属性の値に割り当てることができます。

定義済みの属性とその値の意味を表 1-3 に示します。prex コマンドを使用して、プローブポイントの属性または値に一致する複数のプローブポイントをグループとして選択できます。また、選択したプローブポイントのトレースやデバッグを行うこともできます。

prex コマンドとそのアクションは、表 1-5 を参照してください。

例 1-1 では、TNF_PROBE マクロによって work_start という名前のプローブポイントが定義されています。このプローブポイントには、state と message という 2 つの引数があります。work_start という名前のプローブが検出されるたびに、変数 state と message のタイムスタンプと値がトレースファイルに記録されます。

例 1-1 prex の属性と値

 #include <tnf/probe.h>
 
 int
 work(int state, char *message)
 {
    TNF_PROBE_2(work_start, "work_module work"
               "sunw%debug in function work",
               tnf_long, int_input, state,
               tnf_string, string_input, message);
   ...
   ...
 }

TNF_PROBE マクロとこのコード例についての詳細は、「TNF_PROBE マクロの使い方」を参照してください。

属性

属性は、コード内のプローブポイントを識別するための特性です。定義済みの属性を表 1-3 に示します。ユーザーは、TNF_PROBE を使用して別の属性を追加定義することができます。「TNF_PROBE マクロの使い方」を参照してください。

プローブの照合構文

プローブの属性と値に基づいてプローブを選択します。 selector_list に選択条件を指定します。それぞれの属性または値は、以下のいずれかで表現できます。

• 識別子−英字、数字、_ ¥ . % (下線、バックスラッシュ、ピリオド、パーセント記号) を使用した文字列。識別子の最初の文字を数字にすることはできません。

• 引用符付き文字列−単一引用符で囲んだ文字列。この文字列は文字どおりに解釈される直定数とみなされます。照合する文字列が予約語の場合に便利な表現です。予約語の一覧については、表 1-4 を参照してください。

• 正規表現−スラッシュ (/) で囲んだ文字列。ed(1) の規則に従って照合用に拡張されています。正規表現においてパス名などを表すためにスラッシュを使用する場合は、/¥/tmp¥/filename のように、バックスラッシュでそのスラッシュをエスケープしてください。

selector_list は、1 つ以上の selector= という形式の選択条件で構成されています。最初の selector= が指定されていない場合は、keys= がデフォルトになります。たとえば、enable コマンドは以下の書式で指定します。

enable selector_list

たとえば、以下のように指定します。

enable name=/first/ file='sampleZ.c'

このコマンドは、値 first が含まれている name 属性 (正規表現による一致) をもつプローブポイント、または値が sampleZ.c である file 属性を持つプローブポイントをすべて有効にします。なお、トレースは、論理積ではなく論理和であることに注意してください。

選択条件 selector_list の簡略名として、$set_name のように変数を設定することができます。以下の例では、myprobes がその set_name に当たります。

create $myprobes name=/first/ file='sampleZ.c'
enable $myprobes

これは、前述の例と同じ処理を行います。set_name は、識別子の命名規則に従っています。デフォルト設定の $all は、プログラムのプローブをすべて選択します。

予約語

予約語を表 1-4 に示します。これらの予約語を使用して属性または値を選択する場合は、その予約語を単一引用符で囲んでください。

たとえば、以下のコマンドは、trace 属性の値が ON のプローブをすべて有効にします。trace と on はどちらも予約語なので、単一引用符で囲む必要があります。

enable 'trace'='on'

list name file probes $all

トレース、プローブポイント、デバッグ関数の設定状態

プローブポイントをトレースするには、プローブポイントのトレースをオンにして、プローブポイントを有効にする必要があります。プローブポイントでデバッグするには、プローブポイントをデバッグ関数に接続して、そのプローブポイントを有効にする必要があります。

トレース、プローブポイント、デバッグ関数の設定状態の組み合わせと、その結果を表 1-6 に示します。

スクリプトによる prex の制御

prex へのコマンドは、prex コマンド行から、または prex コマンドが含まれているファイルから入力します。

prex を起動すると、prex は .prexrc という名前のファイルをまず $HOME/ ディレクトリ内で探し、その次に、prex を起動したディレクトリ内で探します。コマンドは、検索されたすべてのファイルから読み取られます。したがって、ホームディレクトリの .prexrc ファイルで設定されたデフォルト値が、現在のディレクトリの .prexrc ファイルによって上書きされる可能性もあります。

検索された .prexrc ファイルを読み取った後は、prex コマンド行から入力されたコマンドが実行されます。.prexrc ファイルを使用して作業のすべてを設定する場合は、.prexrc ファイル中の最後の文を quit resume にします。quit resume は、prex を終了してプログラムを再実行します。

また、prex の実行中には、source filename コマンドを使用して、prex が読み取るコマンドが記述されているファイル filename を指定できます。このファイルは、どのような名前でも構いません。

スクリプト内のコマンドは、prex コマンド行から入力するコマンドと同様に、すべて ASCII 形式にしてください。スクリプトには以下の規則が適用されます。

• 各コマンドの最後には、改行文字を入力します。

• 次の行までコマンドが続く場合は、1 行目の終わりにバックスラッシュ (¥) を入力します。

• トークンは、空白 (1 つ以上の空白文字またはタブ) で区切ります。

• コメントの先頭には、ハッシュ記号 (#) を入力します。

  コマンド行から入力する prex コマンドとスクリプトのコマンドとでコマンド言語は同じですが、スクリプトでは出力が stdout に送られるため、出力を返すコマンド (たとえば、list probes...) をスクリプトで使用してもあまり意味がありません。

C プログラムのサンプル

このプログラム cookie.c は　give me a COOKIE! というメッセージを表示します。それに対する応答は、大文字で入力する必要があります。小文字の場合は誤りとみなされます。また、数値の素因数を計算することもできます。これら 2 つの処理過程を通して、トレース機能がどのように動作しているかを見てみましょう。

このプログラムをコンパイルして cookie() という実行可能プログラムを作成するには、以下のコマンドを実行します。

$ cc -o cookie cookie.c 

このプログラムでは、5 つのプローブポイントが定義 (大文字で表記) されています。各プローブポイントの名前は、start (17 行目)、inloop (33 行目)、factor_start (60 行目)、found_a_factor (65 行目)、factor_end (72 行目)となっています。これらのプローブポイントについての詳細は、「prex セッションのサンプル」で説明しています。

例 1-2 cookie.c のコード

#include <sys/types.h>
#include <stdio.h>
#include <string.h>
#include <tnf/probe.h>

#define MAX_RESPONSE_SIZE 256

static void find_factor(int n);

int
main(int argc, char **argv)
{
    boolean_t shouldexit = B_FALSE;
    int       sum = 0, max_loop = 5;
    int       i;

    TNF_PROBE_0(start, "cookie main", 
         "sunw%debug starting main");

    while (!shouldexit) {
       char response[MAX_RESPONSE_SIZE];
       int factor_input;

       (void) printf("give me a COOKIE! ");
       (void) scanf("%s", response);

       if (!strcmp(response, "COOKIE")) {
            (void) printf("thanks!¥n");
            shouldexit = B_TRUE;
       }

       else if (!strcmp(response, "loop")) {
            for (i = 0; i < max_loop; i++) {
               TNF_PROBE_2(inloop, "cookie main
                           loop","sunw%debug in the loop",
                           tnf_long, loop_count,  i,
                           tnf_long, total_iterations,  sum);
               sum++;
            }
            max_loop += 2 ;
       }

      else if (!strcmp(response, "factor")) {
            (void) printf("number you want factored? ");
            (void) scanf("%d", &factor_input);
            find_factor(factor_input);
      }

      else {
            (void) printf("not a %s, ", response);
      }
    }
    return 0;

}   /* end main */
static void
find_factor(int n)
{
    int i;

    (void) printf("¥tfactors of %d = ", n);
    TNF_PROBE_1(factor_start, "factor", "",
                tnf_long, input_number, n);

    for (i=2; i <= n; i++) {
        while (n % i == 0) {
           TNF_PROBE_2(found_a_factor, "cookie find_factor",
                       "", tnf_long, searching_for, n,
                       tnf_long, factor, i);
           (void) printf("%d ", i);
           n /= i;
        }
    }
    TNF_PROBE_0(factor_end, "factor", "");
    (void) printf("¥n");
}

prex セッションのサンプル

この prex セッションのサンプルは、prex のさまざまな機能を紹介できるように作られています。cookie を実行するときに収集されるデータは、「tnfdump ファイルの読み取り」に示しています。

% prex cookie     /* prex によって、実行可能プログラム cookie がロードされます。*/
Target process stopped
Type "continue" to resume the target, "help" for help ...
prex> list sets
$all      'keys'=/.*/    /* エイリアス $all が 1 つ定義されています 
                                  --- (すべてのプローブです)。*/
prex> list fcns
&debug    tnf_probe_debug      /* デバッグ関数は、使用可能な唯一の関数です。*/
prex> list probes $all
name=inloop enable=off trace=on file=cookie.c line=35 funcs=<no value>
name=factor_end enable=off trace=on file=cookie.c line=72 funcs=<no value>
name=factor_start enable=off trace=on file=cookie.c line=61 funcs=<no value>
name=found_a_factor enable=off trace=on file=cookie.c line=67 funcs=<no value>
name=start enable=off trace=on file=cookie.c line=17 funcs=<no value>
prex>/* 行番号は、5 つのプローブのそれぞれの最終行を示しています。*/
prex> create $factor /factor/   /* "keys" 属性に文字列 "factor" が含まれている
                          プローブと一致する新しいセットを作成します。*/
prex>      
prex> list sets
$all      'keys'=/.*/
$factor   'keys'=/factor/        
/* "factor" という名前の新しいセットが作成されて、そのセットが表示されています。*/
prex>                              
  /* セットの一覧 */
prex> list probes $factor            
/* この行によって、どのプローブがそのセットと一致しているかがわかります。*/
name=factor_end enable=off trace=on file=cookie.c line=72 funcs=<no value>
name=factor_start enable=off trace=on file=cookie.c line=61 funcs=<no value>
name=found_a_factor enable=off trace=on file=cookie.c line=67 funcs=<no value>
prex> list probes $all    /* 有効なプローブがあるかどうか検査します。*/
name=inloop enable=off trace=on file=cookie.c line=35 funcs=<no value>
name=factor_end enable=off trace=on file=cookie.c line=72 funcs=<no value>
name=factor_start enable=off trace=on file=cookie.c line=61 funcs=<no value>
name=found_a_factor enable=off trace=on file=cookie.c line=67 funcs=<no value>
name=start enable=off trace=on file=cookie.c line=17 funcs=<no value>
prex>              /* 有効なプローブはありませんが、
                                   どのプローブもトレースはオンになっています。*/

prex> enable $all             /* すべてのプローブを有効にします。*/
prex> list probes $all        /* 有効なプローブがあるかどうか、再度検査します。*/  
name=inloop enable=on trace=on file=cookie.c line=35 funcs=<no value>
name=factor_end enable=on trace=on file=cookie.c line=72 funcs=<no value>
name=factor_start enable=on trace=on file=cookie.c line=61 funcs=<no value>
name=found_a_factor enable=on trace=on file=cookie.c line=67 funcs=<no value>
name=start enable=on trace=on file=cookie.c line=17 funcs=<no value
prex> list values name              /* プローブの名前を調べます。*/
name =                              
    factor_end                   
    factor_start
    found_a_factor
    inloop
    start
prex> list values /.*/          /* 定義済みの属性とその値をすべて表示します。*/
enable =              /* 固有の属性だけを表示します。*/
    on 
file =
    cookie.c
funcs =
   
keys =
    cookie
    factor
    find_factor
    loop
    main
line =
    17
    35
    61
    67
    72
name =
    factor_end
    factor_start
    found_a_factor
    inloop
    start
object =
    cookie
slots =
    factor
    input_number
    loop_count
    searching_for
    total_iterations
sunw%debug =           /* ユーザー定義のマクロ sunw%debug も表示されています。*/
    in     /* このマクロは、cookie.c の 17 行目で定義されています。*/
    loop
    main
    starting
    the
trace =
    on
prex> list values object
object =
    cookie
prex> connect &debug name=inloop
prex> list /.*/ probes $all         /* すべてのプローブの情報をすべて表示します。*/
enable=on trace=on object=cookie funcs=<no value> name=inloop slots=loop_count
total_iterations keys=cookie main loop file=cookie.c line=35 sunw%debug=in the loop 
enable=on trace=on object=cookie funcs=<no value> name=factor_end slots=<no value>
keys=factor file=cookie.c line=72
enable=on trace=on object=cookie funcs=<no value> name=factor_start slots=input_number
keys=factor file=cookie.c line=61 
enable=on trace=on object=cookie funcs=<no value> name=found_a_factor slots=searching_for
factor keys=cookie find_factor file=cookie.c line=67 
enable=on trace=on object=cookie funcs=<no value> name=start slots=<no value> 
keys=cookie
main file=cookie.c line=17 sunw%debug=starting main 
prex> continue
give me a COOKIE! loop       
 /* ループカウントの例 */
probe inloop; sunw%debug "in the loop"; loop_count=0; total_iterations=0;
probe inloop; sunw%debug "in the loop"; loop_count=1; total_iterations=1;
probe inloop; sunw%debug "in the loop"; loop_count=2; total_iterations=2;
probe inloop; sunw%debug "in the loop"; loop_count=3; total_iterations=3;
probe inloop; sunw%debug "in the loop"; loop_count=4; total_iterations=4;
give me a COOKIE! factor 
number you want factored? 25
 factors of 25 = 5 5
give me a COOKIE! factor
number you want factored? 43645729
 factors of 43645729 = 43645729
give me a COOKIE! ^C Target process stopped
Type "continue" to resume the target, "help" for help...
prex> continue
give me a COOKIE! biscuit
not a biscuit, give me a COOKIE!  cookie
not a cookie, give me a COOKIE! COOKIE
thanks!
prex: target process finished

トレースファイルの読み取り

prex で作成したバイナリのトレースファイルには、ユーザーが選択した prex コマンドによって判定された情報が含まれています (「prex の実行」を参照)。

デフォルトでは、トレースファイルは /$TMPDIR/trace-pid に作成されます。この pid は、ターゲットのプログラムのプロセス ID です。$TMPDIR が設定されていない場合は、/tmp/trace-pid にファイルが作成されます。トレースファイルの場所は、prex コマンドに -o オプションを付けて変更できます (詳細については、「prex のコマンド行オプション」を参照してください)。

トレースファイルが一杯になると、新しいイベントによって古いイベントが上書きされます。トレースファイルのデフォルトサイズは、4 MB です。このサイズは、prex の -s オプションで変更することができます。

プログラムのトレース結果がファイルに書き込まれた後で、そのプログラムが存在する間にはそのトレースファイルを削除したり、トレースファイルの名前を変更することはできません。トレースファイルをターゲットプログラムから切り離し、別の名前に変更したトレースファイルを再接続しても、新しい名前は無視されます。

読み取り可能な形式へのバイナリファイルの変換

バイナリのトレースファイルを ASCII ファイルに変換するには、tnfdump コマンドとバイナリのトレースファイルの名前を使用します。デフォルトで tnfdump の出力は stdout に送られるため、その出力をファイルにリダイレクトする必要があります。

$ tnfdump filename > newfile

tnfdump に -r オプションを付けると、詳細な (生の) TNF 出力が得られます。この詳細な TNF 出力を解釈するには、この章の説明範囲を超えた TNF の知識が必要となります。

tnfdump ファイルの読み取り

「prex セッションのサンプル」で説明した prex cookie コマンドの出力を以下に示します。tnfdump ファイルの出力は非常に幅が広いので、出力を表示する場合は幅の広いウィンドウを開いてください。

probe  tnf_name: "start" tnf_string: "keys cookie main;file cookie.c;line 17;sunw%debug
starting main"
probe  tnf_name: "factor_start" tnf_string: "keys factor;file cookie.c;line 61;"
probe  tnf_name: "found_a_factor" tnf_string: "keys cookie find_factor;file cookie.c;line
67;"
probe  tnf_name: "factor_end" tnf_string: "keys factor;file cookie.c;line 72;"
---------------- ---------------- ----- ----- ---------- --- -------------------------
------------------------
    Elapsed (ms)  Delta (ms)     PID  LWPID  TID  CPU Probe Name        Data / Description . . .
---------------- ---------------- ----- ----- ---------- --- -------------------------
------------------------
  0.000000 0.000000 5354 1 0 - start 
 4551.625000 4551.625000 5354 1 0 - factor_start input_number: 25
 4571.278000 19.653000 5354 1 0 - found_a_factor searching_for: 25 factor: 5
 4571.543000 0.265000 5354 1 0 - found_a_factor searching_for: 5 factor: 5
 4571.732000 0.189000 5354 1 0 - factor_end 
  23151.434000 18579.702000 5354 1 0 - factor_start input_number: 101247
  23151.509000 0.075000 5354 1 0 - found_a_factor searching_for: 101247 factor: 3
  23228.090000 76.581000 5354 1 0 - found_a_factor searching_for: 33749 factor: 33749
  23228.250000 0.160000 5354 1 0 - factor_end 
  89041.868000 65813.618000 5354 1 0 - factor_start input_number: -1690908149
  89041.920000 0.052000 5354 1 0 - factor_end 
 108271.852000 19229.932000 5354 1 0 - factor_start input_number: 43645729
 208857.756000  100585.904000 5354 1 0 - found_a_factor searching_for: 43645729 factor:
43645729
 208857.960000 0.204000 5354 1 0 - factor_end 
 334511.548000  125653.588000 5354 1 0 - factor_start input_number: 12
 334511.618000 0.070000 5354 1 0 - found_a_factor searching_for: 12 factor: 2
 334511.689000 0.071000 5354 1 0 - found_a_factor searching_for: 6 factor: 2
 334511.750000 0.061000 5354 1 0 - found_a_factor searching_for: 3 factor: 3
 334511.808000 0.058000 5354 1 0 - factor_end 

tnfdump の表示を見て、factor_end の時間から factor_start の時間を引くと、因数を見つけるまでに要した時間がわかります。43645729 の因数分解には、208857.960000 - 108271.852000 (つまり、100586.11) ミリ秒間かかっています。12 の因数分解には、334511.808000 - 334511.548000 (つまり、0.260000) ミリ秒間かかっています。

どのハードウェアプラットフォームでも、結果はナノ秒の精度で報告されます。ただし、結果の正確度は、使用しているハードウェアプラットフォームによって異なります。