Solaris 動的トレースガイド

第 26 章 sched プロバイダ

sched プロバイダは、CPU スケジューリング関連のプローブを使用できるようにします。CPU は、すべてのスレッドが使用しなければならない唯一のリソースです。したがって、sched プロバイダは、体系的な動作を理解するためにたいへん役立ちます。たとえば、sched プロバイダを使って、スレッドによるさまざまな処理 (スレッドのスリープ、実行、優先順位の変更、別のスレッドの呼び起こしなど) が行われた時期および理由を調べることができます。

プローブ

表 26–1 では、sched プローブについて説明します。

表 26–1 sched プローブ

プローブ 

説明 

change-pri

スレッドの優先順位が変更される直前に起動するプローブ。args[0] は、スレッドの lwpsinfo_t をポイントしています。スレッドの現在の優先順位は、この構造体の pr_pri フィールドに格納されます。args[1] は、このスレッドが含まれているプロセスの psinfo_t をポイントしています。args[2] には、スレッドの新しい優先順位が格納されます。

dequeue

実行可能スレッドが実行キューから外される直前に起動するプローブ。args[0] は、キューから外されるスレッドの lwpsinfo_t をポイントしています。args[1] は、このスレッドが含まれているプロセスの psinfo_t をポイントしています。args[2] は、このスレッドがキューから外される CPU の cpuinfo_t をポイントしています。スレッドが外される実行キューが特定の CPU に関連付けられていない場合、この構造体の cpu_id メンバーの値は -1 になります。

enqueue

実行可能スレッドが実行キューに入れられる直前に起動するプローブ。args[0] は、キューに入れられるスレッドの lwpsinfo_t をポイントしています。args[1] は、このスレッドが含まれているプロセスの psinfo_t をポイントしています。args[2] は、このスレッドがキューに入れられる CPU の cpuinfo_t をポイントしています。スレッドが入れられる実行キューが特定の CPU に関連付けられていない場合、この構造体の cpu_id メンバーの値は -1 になります。args[3] には、スレッドを実行キューの先頭に入れるかどうかを示すブール値が入ります。この値は、スレッドを実行キューの先頭に入れる場合はゼロ以外の値、実行キューの末尾に入れる場合はゼロになります。

off-cpu

現在の CPU がスレッドの実行を終了する直前に起動するプローブ。curcpu 変数は、現在の CPU を表します。curlwpsinfo 変数は、実行を終了しようとしているスレッドを表します。curpsinfo 変数は、現在のスレッドが含まれているプロセスの説明です。args[0] は、現在の CPU が次に実行するスレッドの lwpsinfo_t 構造体をポイントしています。args[1] は、次のスレッドが含まれているプロセスの psinfo_t をポイントしています。

on-cpu

CPU がスレッドの実行を開始した直後に起動するプローブ。curcpu 変数は、現在の CPU を表します。curlwpsinfo 変数は、実行を開始するスレッドを表します。curpsinfo 変数は、現在のスレッドが含まれているプロセスの説明です。

preempt

現在のスレッドが横取りされる直前に起動するプローブ。このプローブが起動すると、現在のスレッドにより、実行するスレッドが選択されます。続いて、現在のスレッドに対して off-cpu プローブが起動します。ある CPU 上のスレッドを横取りするスレッドが、別の CPU 上で実行されている場合もあります。この場合も preempt プローブは起動しますが、ディスパッチャは、実行の優先順位の高いスレッドを見つけることができません。このため、off-cpu プローブではなく remain-cpu プローブが起動します。

remain-cpu

スケジューリングに関する決定がなされたにもかかわらず、現在のスレッドの実行の続行がディスパッチャによって選択されたときに、起動するプローブ。curcpu 変数は、現在の CPU を表します。curlwpsinfo 変数は、実行を開始するスレッドを表します。curpsinfo 変数は、現在のスレッドが含まれているプロセスの説明です。

schedctl-nopreempt

横取り制御要求により、スレッドが横取りされたあと、実行キューの先頭に入れ直されたときに起動するプローブ。横取り制御の詳細については、schedctl_init(3C) を参照してください。preempt の場合と同じく、schedctl-nopreempt に続いて off-cpuremain-cpu が起動します。schedctl-nopreempt は、現在のスレッドを実行キューの先頭に入れ直す指示です。このため、off-cpu よりも remain-cpu のほうが、schedctl-nopreempt に続いて起動する確率が高いと言えます。args[0] は、横取りされるスレッドの lwpsinfo_t をポイントしています。args[1] は、このスレッドが含まれているプロセスの psinfo_t をポイントしています。

schedctl-preempt

スレッドが横取り制御を使用しているにもかかわらず横取りされ、実行キューの末尾に入れ直されたときに、起動するプローブ。横取り制御の詳細については、schedctl_init(3C) を参照してください。preempt の場合と同じく、schedctl-preempt に続いて off-cpuremain-cpu が起動します。preempt の場合と同じく、(そして schedctl-nopreempt の場合とは違って)、schedctl-preempt は、現在のスレッドを実行キューの末尾に入れ直す指示です。その結果、remain-cpu よりも off-cpu のほうが、schedctl-preempt に続いて起動する確率が高いといえます。args[0] は、横取りされるスレッドの lwpsinfo_t をポイントしています。args[1] は、このスレッドが含まれているプロセスの psinfo_t をポイントしています。

schedctl-yield

横取り制御を有効にし、タイムスライスを人工的に延長したスレッドが、CPU をほかのスレッドに譲るコードを実行したときに、起動するプローブ。 

sleep

現在のスレッドが同期オブジェクトでスリープする直前に起動するプローブ。同期オブジェクトの型は、curlwpsinfo がポイントしている lwpsinfo_tpr_stype メンバーに格納されます。同期オブジェクトのアドレスは、curlwpsinfo がポイントしている lwpsinfo_tpr_wchan メンバーに格納されます。このアドレスの意味は、非公開の実装詳細情報ですが、アドレス値は、同期オブジェクトに固有のトークンとして機能します。

surrender

CPU が、別の CPU から、スケジューリングに関する決定を下すように指示を受けたときに起動するプローブ。こうした指示は、一般に、より優先順位の高いスレッドが実行可能状態になったときに発行されます。 

tick

クロック刻みベースのアカウンティングの一環として起動するプローブ。クロック刻みベースのアカウンティングでは、固定間隔の割り込みが発生したとき、どのスレッドとどのプロセスが実行されていたかを調べることによって、CPU のアカウンティングが行われます。args[0] は、CPU 時間の割り当てを受けるスレッドの lwpsinfo_t をポイントしています。args[1] は、このスレッドが含まれているプロセスの psinfo_t をポイントしています。

wakeup

現在のスレッドが同期オブジェクトでスリープしているスレッドを呼び起こす直前に起動するプローブ。args[0] は、スリープ中のスレッドの lwpsinfo_t をポイントしています。args[1] は、スリープ中のスレッドが含まれているプロセスの psinfo_t をポイントしています。同期オブジェクトの型は、スリープ中のスレッドの lwpsinfo_tpr_stype メンバーに格納されます。同期オブジェクトのアドレスは、スリープ中のスレッドの lwpsinfo_tpr_wchan メンバーに格納されます。このアドレスの意味は、非公開の実装詳細情報ですが、アドレス値は、同期オブジェクトに固有のトークンとして機能します。

引数

表 26–2 に、sched プローブの引数の型を一覧します。引数については、表 26–1 を参照してください。

表 26–2 sched プローブ引数

プローブ 

args[0]

args[1]

args[2]

args[3]

change-pri

lwpsinfo_t *

psinfo_t *

pri_t

— 

dequeue

lwpsinfo_t *

psinfo_t *

cpuinfo_t *

— 

enqueue

lwpsinfo_t *

psinfo_t *

cpuinfo_t *

int

off-cpu

lwpsinfo_t *

psinfo_t *

— 

— 

on-cpu

— 

— 

— 

— 

preempt

— 

— 

— 

— 

remain-cpu

— 

— 

— 

— 

schedctl-nopreempt

lwpsinfo_t *

psinfo_t *

— 

— 

schedctl-preempt

lwpsinfo_t *

psinfo_t *

— 

— 

schedctl-yield

lwpsinfo_t *

psinfo_t *

— 

— 

sleep

— 

— 

— 

— 

surrender

lwpsinfo_t *

psinfo_t *

— 

— 

tick

lwpsinfo_t *

psinfo_t *

— 

— 

wakeup

lwpsinfo_t *

psinfo_t *

— 

— 

表 26–2 からわかるように、多くの sched プローブは、引数として lwpsinfo_t のポインタ (スレッド) と psinfo_t のポインタ (スレッドが含まれているプロセス) をとります。これらの構造体の詳細については、それぞれ lwpsinfo_tpsinfo_tを参照してください。

cpuinfo_t

cpuinfo_t 構造体は、CPU を定義します。表 26–2 からわかるように、enqueue プローブと dequeue プローブは、どちらも引数として cpuinfo_t のポインタをとります。また、現在の CPU の cpuinfo_t は、curcpu 変数でポイントされています。以下に、cpuinfo_t 構造体の定義を示します。

typedef struct cpuinfo {
	processorid_t cpu_id;           /* CPU identifier */
	psetid_t cpu_pset;              /* processor set identifier */
	chipid_t cpu_chip;              /* chip identifier */
	lgrp_id_t cpu_lgrp;             /* locality group identifer */
	processor_info_t cpu_info;      /* CPU information */
} cpuinfo_t;

cpu_id メンバーは、psrinfo(1M)p_online(2) から返されるプロセッサ識別子です。

cpu_pset メンバーは、CPU を含む (CPU がある場合) プロセッサセットです。プロセッサセットの詳細については、psrset(1M) のマニュアルページを参照してください。

cpu_chip メンバーは、物理チップの識別子です。物理チップには、複数の CPU が搭載されていることがあります。詳細については、psrinfo(1M) のマニュアルページを参照してください。

cpu_lgrp メンバーは、CPU の遅延グループの識別子です。遅延グループの詳細については、liblgrp(3LIB) のマニュアルページを参照してください。

cpu_info メンバーは、processor_info(2) から返される CPU の processor_info_t 構造体です。

on-cpuoff-cpu

「どの CPU が、どのくらいの時間、スレッドを実行しているか」という問いは頻繁に発生します。この問題へのシステム全体レベルの答えは、次の例のように on-cpu プローブと off-cpu プローブを使用することにより、簡単に導き出すことができます。

sched:::on-cpu
{
	self->ts = timestamp;
}

sched:::off-cpu
/self->ts/
{
	@[cpu] = quantize(timestamp - self->ts);
	self->ts = 0;
}

このスクリプトを実行すると、次のような出力が得られます。


# dtrace -s ./where.d
dtrace: script './where.d' matched 5 probes
^C

        0
           value  ------------- Distribution ------------- count    
            2048 |                                         0        
            4096 |@@                                       37       
            8192 |@@@@@@@@@@@@@                            212      
           16384 |@                                        30       
           32768 |                                         10       
           65536 |@                                        17       
          131072 |                                         12       
          262144 |                                         9        
          524288 |                                         6        
         1048576 |                                         5        
         2097152 |                                         1        
         4194304 |                                         3        
         8388608 |@@@@                                     75       
        16777216 |@@@@@@@@@@@@                             201      
        33554432 |                                         6        
        67108864 |                                         0        

        1
           value  ------------- Distribution ------------- count    
            2048 |                                         0        
            4096 |@                                        6        
            8192 |@@@@                                     23       
           16384 |@@@                                      18       
           32768 |@@@@                                     22       
           65536 |@@@@                                     22       
          131072 |@                                        7        
          262144 |                                         5        
          524288 |                                         2        
         1048576 |                                         3        
         2097152 |@                                        9        
         4194304 |                                         4        
         8388608 |@@@                                      18       
        16777216 |@@@                                      19       
        33554432 |@@@                                      16       
        67108864 |@@@@                                     21       
       134217728 |@@                                       14       
       268435456 |                                         0

出力結果によると、CPU 1 上のスレッドは、100 マイクロ秒未満で一気に実行されるか、あるいは約 10 ミリ秒間実行されます。ヒストグラムから、2 つのデータクラスタ間に顕著な差異があることがわかります。また、特定のプロセスを実行している CPU を知りたい場合もあります。この場合も、on-cpu プローブと off-cpu プローブを使用します。以下のスクリプトを実行すると、指定されたアプリケーションを 10 秒間以上実行する CPU が表示されます。

#pragma D option quiet

dtrace:::BEGIN
{
	start = timestamp;
}

sched:::on-cpu
/execname == $$1/
{
	self->ts = timestamp;
}

sched:::off-cpu
/self->ts/
{
	@[cpu] = sum(timestamp - self->ts);
	self->ts = 0;
}

profile:::tick-1sec
/++x == 10/
{
	exit(0);
}
        
dtrace:::END
{
	printf("CPU distribution of imapd over %d seconds:\n\n",
	    (timestamp - start) / 1000000000);
	printf("CPU microseconds\n--- ------------\n");
	normalize(@, 1000);
	printa("%3d %@d\n", @);
}

IMAP デーモンを指定して、このスクリプトを大規模メールサーバー上で実行してみましょう。次のような出力が得られます。


# dtrace -s ./whererun.d imapd
CPU distribution of imapd over 10 seconds:

CPU microseconds
--- ------------
 15 10102
 12 16377
 21 25317
 19 25504
 17 35653
 13 41539
 14 46669
 20 57753
 22 70088
 16 115860
 23 127775
 18 160517

Solaris は、スレッドを実行する CPU を選択する際、スレッドがスリープしていた時間を考慮します。 スリープ時間が短いスレッドは、移行しにくい傾向にあります。off-cpu プローブと on-cpu プローブを使って、この動作を監視できます。

sched:::off-cpu
/curlwpsinfo->pr_state == SSLEEP/
{
	self->cpu = cpu;
	self->ts = timestamp;
}

sched:::on-cpu
/self->ts/
{
	@[self->cpu == cpu ?
	    "sleep time, no CPU migration" : "sleep time, CPU migration"] =
	    lquantize((timestamp - self->ts) / 1000000, 0, 500, 25);
	self->ts = 0;
	self->cpu = 0;
}

このスクリプトを約 30 秒間実行すると、次の例のような出力が得られます。


# dtrace -s ./howlong.d
dtrace: script './howlong.d' matched 5 probes
^C
 sleep time, CPU migration                         
           value  -------------- Distribution ------------ count    
             < 0 |                                         0        
               0 |@@@@@@@                                  6838     
              25 |@@@@@                                    4714     
              50 |@@@                                      3108     
              75 |@                                        1304     
             100 |@                                        1557     
             125 |@                                        1425     
             150 |                                         894      
             175 |@                                        1526     
             200 |@@                                       2010     
             225 |@@                                       1933     
             250 |@@                                       1982     
             275 |@@                                       2051     
             300 |@@                                       2021     
             325 |@                                        1708     
             350 |@                                        1113     
             375 |                                         502      
             400 |                                         220      
             425 |                                         106      
             450 |                                         54       
             475 |                                         40       
          >= 500 |@                                        1716     

  sleep time, no CPU migration                      
           value  -------------- Distribution ------------ count    
             < 0 |                                         0        
               0 |@@@@@@@@@@@@                             58413    
              25 |@@@                                      14793    
              50 |@@                                       10050    
              75 |                                         3858     
             100 |@                                        6242     
             125 |@                                        6555     
             150 |                                         3980     
             175 |@                                        5987     
             200 |@                                        9024     
             225 |@                                        9070     
             250 |@@                                       10745    
             275 |@@                                       11898    
             300 |@@                                       11704    
             325 |@@                                       10846    
             350 |@                                        6962     
             375 |                                         3292     
             400 |                                         1713     
             425 |                                         585      
             450 |                                         201      
             475 |                                         96       
          >= 500 |                                         3946

この出力例では、移行が行われた回数よりも、移行が行われなかった回数のほうが多くなっています。また、スリープ時間が長くなるほど、移行が行われやすくなっています。スリープ時間が 100 ミリ秒以下のときは、分布状態に顕著な差異が見られます。しかし、スリープ時間がもっと長くなれば、この差異はほとんど見られなくなります。この結果から、決められたしきい値を超えると、スケジューリングに関する決定の際にスリープ時間が考慮されなくなるものと推測できます。

最後に、off-cpu プローブと on-cpu プローブを pr_stype フィールドと組み合わせて使用することにより、スレッドがスリープする理由および期間を特定する例を示します。

sched:::off-cpu
/curlwpsinfo->pr_state == SSLEEP/
{
	/*
	 * We're sleeping.  Track our sobj type.
	 */
	self->sobj = curlwpsinfo->pr_stype;
	self->bedtime = timestamp;
}

sched:::off-cpu
/curlwpsinfo->pr_state == SRUN/
{
	self->bedtime = timestamp;
}

sched:::on-cpu
/self->bedtime && !self->sobj/
{
	@["preempted"] = quantize(timestamp - self->bedtime);
	self->bedtime = 0;
}

sched:::on-cpu
/self->sobj/
{
	@[self->sobj == SOBJ_MUTEX ? "kernel-level lock" :
	    self->sobj == SOBJ_RWLOCK ? "rwlock" :
	    self->sobj == SOBJ_CV ? "condition variable" :
	    self->sobj == SOBJ_SEMA ? "semaphore" :
	    self->sobj == SOBJ_USER ? "user-level lock" :
	    self->sobj == SOBJ_USER_PI ? "user-level prio-inheriting lock" :
	    self->sobj == SOBJ_SHUTTLE ? "shuttle" : "unknown"] =
	    quantize(timestamp - self->bedtime);

	self->sobj = 0;
	self->bedtime = 0;
}

このスクリプトを数秒間実行すると、次のような出力が得られます。


# dtrace -s ./whatfor.d
dtrace: script './whatfor.d' matched 12 probes
^C
 kernel-level lock
           value  -------------- Distribution ------------ count    
           16384 |                                         0        
           32768 |@@@@@@@@                                 3        
           65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@            11       
          131072 |@@                                       1        
          262144 |                                         0        

  preempted
           value  -------------- Distribution ------------ count    
           16384 |                                         0        
           32768 |                                         4        
           65536 |@@@@@@@@                                 408      
          131072 |@@@@@@@@@@@@@@@@@@@@@@                   1031     
          262144 |@@@                                      156      
          524288 |@@                                       116      
         1048576 |@                                        51       
         2097152 |                                         42       
         4194304 |                                         16       
         8388608 |                                         15       
        16777216 |                                         4        
        33554432 |                                         8        
        67108864 |                                         0        

  semaphore
           value  -------------- Distribution ------------ count    
           32768 |                                         0        
           65536 |@@                                       61       
          131072 |@@@@@@@@@@@@@@@@@@@@@@@@                 553      
          262144 |@@                                       63       
          524288 |@                                        36       
         1048576 |                                         7        
         2097152 |                                         22       
         4194304 |@                                        44       
         8388608 |@@@                                      84       
        16777216 |@                                        36       
        33554432 |                                         3        
        67108864 |                                         6        
       134217728 |                                         0        
       268435456 |                                         0        
       536870912 |                                         0        
      1073741824 |                                         0        
      2147483648 |                                         0        
      4294967296 |                                         0        
      8589934592 |                                         0        
     17179869184 |                                         1        
     34359738368 |                                         0        

  shuttle                                           
           value  -------------- Distribution ------------ count    
           32768 |                                         0        
           65536 |@@@@@                                    2        
          131072 |@@@@@@@@@@@@@@@@                         6        
          262144 |@@@@@                                    2        
          524288 |                                         0        
         1048576 |                                         0        
         2097152 |                                         0        
         4194304 |@@@@@                                    2        
         8388608 |                                         0        
        16777216 |                                         0        
        33554432 |                                         0        
        67108864 |                                         0        
       134217728 |                                         0        
       268435456 |                                         0        
       536870912 |                                         0        
      1073741824 |                                         0        
      2147483648 |                                         0        
      4294967296 |@@@@@                                    2        
      8589934592 |                                         0        
     17179869184 |@@                                       1        
     34359738368 |                                         0        

  condition variable                                
           value  -------------- Distribution ------------ count    
           32768 |                                         0        
           65536 |                                         122      
          131072 |@@@@@                                    1579     
          262144 |@                                        340      
          524288 |                                         268      
         1048576 |@@@                                      1028     
         2097152 |@@@                                      1007     
         4194304 |@@@                                      1176     
         8388608 |@@@@                                     1257     
        16777216 |@@@@@@@@@@@@@@                           4385     
        33554432 |                                         295      
        67108864 |                                         157      
       134217728 |                                         96       
       268435456 |                                         48       
       536870912 |                                         144      
      1073741824 |                                         10       
      2147483648 |                                         22       
      4294967296 |                                         18       
      8589934592 |                                         5        
     17179869184 |                                         6        
     34359738368 |                                         4        
     68719476736 |                                         0

enqueuedequeue

CPU がアイドル状態になると、ディスパッチャは、別の (アイドル状態でない) CPU のキューにある処理を探します。以下は、dequeue プローブを使って、アプリケーションがどの CPU によって、どのくらいの頻度で転送されるかを確認する例です。

#pragma D option quiet

sched:::dequeue
/args[2]->cpu_id != --1 && cpu != args[2]->cpu_id &&
    (curlwpsinfo->pr_flag & PR_IDLE)/
{
	@[stringof(args[1]->pr_fname), args[2]->cpu_id] =
	    lquantize(cpu, 0, 100);
}

END
{
	printa("%s stolen from CPU %d by:\n%@d\n", @);
}

このスクリプトを 4 CPU システム上で実行した場合、出力の末尾部分は次のようになります。


# dtrace -s ./whosteal.d
^C
...
 nscd stolen from CPU 1 by:

           value  -------------- Distribution ------------ count    
               1 |                                         0        
               2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 28       
               3 |                                         0        

snmpd stolen from CPU 1 by:

           value  -------------- Distribution ------------ count    
             < 0 |                                         0        
               0 |@                                        1        
               1 |                                         0        
               2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@     31       
               3 |@@                                       2        
               4 |                                         0        

sched stolen from CPU 1 by:

           value  -------------- Distribution ------------ count    
             < 0 |                                         0        
               0 |@@                                       3        
               1 |                                         0        
               2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@         36       
               3 |@@@@                                     5        
               4 |                                         0

どの CPU がどの処理を行なったかではなく、プロセスやスレッドが実行待ち状態になっている CPU について知りたい場合もあります。この場合も、enqueue プローブと dequeue プローブを組み合わせて使用します。

sched:::enqueue
{
	self->ts = timestamp;
}

sched:::dequeue
/self->ts/
{
	@[args[2]->cpu_id] = quantize(timestamp - self->ts);
	self->ts = 0;
}

このスクリプトを数秒間実行すると、次のような出力が得られます。


# dtrace -s ./qtime.d
dtrace: script './qtime.d' matched 5 probes
^C
       -1
           value  -------------- Distribution ------------ count    
            4096 |                                         0        
            8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2        
           16384 |                                         0        

        0
           value  -------------- Distribution ------------ count    
            1024 |                                         0        
            2048 |@@@@@@@@@@@@@@@                          262      
            4096 |@@@@@@@@@@@@@                            227      
            8192 |@@@@@                                    87       
           16384 |@@@                                      54       
           32768 |                                         7        
           65536 |                                         9        
          131072 |                                         1        
          262144 |                                         5        
          524288 |                                         4        
         1048576 |                                         2        
         2097152 |                                         0        
         4194304 |                                         0        
         8388608 |                                         0        
        16777216 |                                         1        
        33554432 |                                         2        
        67108864 |                                         2        
       134217728 |                                         0        
       268435456 |                                         0        
       536870912 |                                         0        
      1073741824 |                                         1        
      2147483648 |                                         1        
      4294967296 |                                         0        

        1
           value  -------------- Distribution ------------ count    
            1024 |                                         0        
            2048 |@@@@                                     49       
            4096 |@@@@@@@@@@@@@@@@@@@@                     241      
            8192 |@@@@@@@                                  91       
           16384 |@@@@                                     55       
           32768 |                                         7        
           65536 |                                         3        
          131072 |                                         2        
          262144 |                                         1        
          524288 |                                         0        
         1048576 |                                         0        
         2097152 |                                         0        
         4194304 |                                         0        
         8388608 |                                         0        
        16777216 |                                         0        
        33554432 |                                         3        
        67108864 |                                         1        
       134217728 |                                         4        
       268435456 |                                         2        
       536870912 |                                         0        
      1073741824 |                                         3        
      2147483648 |                                         2        
      4294967296 |                                         0

末尾にゼロ以外の値が出力されている点に注目してください。これらのデータポイントから、どちらの CPU にも、スレッドの実行前に数秒間キューに入れられたインスタンスが、複数あることがわかります。

待ち時間ではなく、実行キューの長さの推移を調べたい場合もあります。このためには、enqueue プローブと dequeue プローブを使って、キューの長さを追跡する連想配列を設定します。

sched:::enqueue
{
	this->len = qlen[args[2]->cpu_id]++;
	@[args[2]->cpu_id] = lquantize(this->len, 0, 100);
}

sched:::dequeue
/qlen[args[2]->cpu_id]/
{
	qlen[args[2]->cpu_id]—;
}

ほとんどの場合アイドル状態である単一プロセッサが搭載されたラップトップシステム上で、このスクリプトを約 30 秒間実行すると、次のような出力が得られます。


# dtrace -s ./qlen.d
dtrace: script './qlen.d' matched 5 probes
^C
        0
           value  -------------- Distribution ------------ count    
             < 0 |                                         0        
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@                110626   
               1 |@@@@@@@@@                                41142    
               2 |@@                                       12655    
               3 |@                                        5074     
               4 |                                         1722     
               5 |                                         701      
               6 |                                         302      
               7 |                                         63       
               8 |                                         23       
               9 |                                         12       
              10 |                                         24       
              11 |                                         58       
              12 |                                         14       
              13 |                                         3        
              14 |                                         0

アイドル状態のシステムに典型的な出力結果が得られます。 実行可能スレッドが入れられる時点の実行キューは、ほとんどの場合非常に短いものです (3 スレッド以下)。しかし、このシステムがたいていの場合アイドル状態にあることを考慮すると、表の下部に例外データポイントが出力されるのは、少し予想外かもしれません。たとえば、この実行キューに、実行可能スレッド 13 個分に相当する長さがなぜ必要なのでしょうか。この問題について調べるには、実行キューの長さが長いときに実行キューの内容を表示するような D スクリプトを作成します。この問題を複雑にしているのは、D の有効化です。D の有効化は、データ構造に対して繰り返し実行できないため、当然、実行キュー全体に対しても繰り返し実行できません。たとえ D の有効化にこれが可能であっても、カーネルの内部データ構造への依存関係は避けるべきです。

この種のスクリプトを実行するときは、enqueue プローブと dequeue プローブの両方を有効にし、投機アクションと連想配列の両方を使用します。スレッドがキューに入れられると、スクリプトによって、キューの長さが増分され、スレッドによりキー付けされた連想配列内のタイムスタンプが記録されます。この場合、スレッドは別のスレッドによってキューに入れられた可能性があるので、スレッド固有変数は使用できません。次に、キューの長さが上限を超えていないかどうかのチェックが行われます。上限を超えていた場合、新しい投機アクションが開始され、タイムスタンプと新しい上限値が記録されます。その後、スレッドがキューから外されると、キューに入れられた時点のタイムスタンプと最長のタイムスタンプとの比較が行われます。 スレッドが、最長のタイムスタンプよりにキューに入れられている場合、このスレッドは、最長のタイムスタンプが記録されとき、キュー内にあったことになります。この場合は、このスレッドの情報が投機的にトレースされます。最長のタイムスタンプの時点でキュー内にあったスレッドすべてがカーネルによってキューから外されると、スクリプトにより、投機データのコミットが行われます。以下に、このスクリプトを示します。

#pragma D option quiet
#pragma D option nspec=4
#pragma D option specsize=100k

int maxlen;
int spec[int];

sched:::enqueue
{
	this->len = ++qlen[this->cpu = args[2]->cpu_id];
	in[args[0]->pr_addr] = timestamp;
}

sched:::enqueue
/this->len > maxlen && spec[this->cpu]/
{
	/*
	 * There is already a speculation for this CPU.  We just set a new
	 * record, so we'll discard the old one.
	 */
	discard(spec[this->cpu]);
}

sched:::enqueue
/this->len > maxlen/
{
	/*
	 * We have a winner.  Set the new maximum length and set the timestamp
	 * of the longest length.
	 */
	maxlen = this->len;
	longtime[this->cpu] = timestamp;	

	/*
	 * Now start a new speculation, and speculatively trace the length.
	 */
	this->spec = spec[this->cpu] = speculation();
	speculate(this->spec);
	printf("Run queue of length %d:\n", this->len);
}

sched:::dequeue
/(this->in = in[args[0]->pr_addr]) &&
    this->in <= longtime[this->cpu = args[2]->cpu_id]/
{
	speculate(spec[this->cpu]);
	printf("  %d/%d (%s)\n", 
	    args[1]->pr_pid, args[0]->pr_lwpid,
	    stringof(args[1]->pr_fname));
}

sched:::dequeue
/qlen[args[2]->cpu_id]/
{
	in[args[0]->pr_addr] = 0;
	this->len = --qlen[args[2]->cpu_id];
}

sched:::dequeue
/this->len == 0 && spec[this->cpu]/
{
	/*
	 * We just processed the last thread that was enqueued at the time
	 * of longest length; commit the speculation, which by now contains
	 * each thread that was enqueued when the queue was longest.
	 */
	commit(spec[this->cpu]);
	spec[this->cpu] = 0;
}

このスクリプトを、先ほどと同じ単一のプロセッサが搭載されたラップトップで実行すると、次のような出力が得られます。


# dtrace -s ./whoqueue.d
Run queue of length 3:
 0/0 (sched)
  0/0 (sched)
  101170/1 (dtrace)
Run queue of length 4:
  0/0 (sched)
  100356/1 (Xsun)
  100420/1 (xterm)
  101170/1 (dtrace)
Run queue of length 5:
  0/0 (sched)
  0/0 (sched)
  100356/1 (Xsun)
  100420/1 (xterm)
  101170/1 (dtrace)
Run queue of length 7:
  0/0 (sched)
  100221/18 (nscd)
  100221/17 (nscd)
  100221/16 (nscd)
  100221/13 (nscd)
  100221/14 (nscd)
  100221/15 (nscd)
Run queue of length 16:
  100821/1 (xterm)
  100768/1 (xterm)
  100365/1 (fvwm2)
  101118/1 (xterm)
  100577/1 (xterm)
  101170/1 (dtrace)
  101020/1 (xterm)
  101089/1 (xterm)
  100795/1 (xterm)
  100741/1 (xterm)
  100710/1 (xterm)
  101048/1 (xterm)
  100697/1 (MozillaFirebird-)
  100420/1 (xterm)
  100394/1 (xterm)
  100368/1 (xterm)
^C

出力から、実行キューが長いのは、実行可能な xterm プロセスがたくさんあるせいだということがわかります。この測定と同時に、仮想デスクトップに変更が加えられています。したがって、上のような結果が得られた背景には、何らかの X イベント処理がかかわっていると推測できます。

sleepwakeup

enqueuedequeueの最後の例では、実行可能な xterm プロセスのせいで実行キュー長のバーストが起こったことがわかりました。ここで、この測定結果は仮想デスクトップの変更に起因するものだという仮説を立てることができます。この仮説を検証するには、wakeup プローブを使って、xterm プロセスが何によって呼び起こされているか、またその時期を特定します。次の例を参照してください。

#pragma D option quiet

dtrace:::BEGIN
{
	start = timestamp;
}

sched:::wakeup
/stringof(args[1]->pr_fname) == "xterm"/
{
	@[execname] = lquantize((timestamp - start) / 1000000000, 0, 10);
}

profile:::tick-1sec
/++x == 10/
{
	exit(0);
}

仮説の検証のため、このスクリプトを実行し、5 秒ほど待ったあと、1 度だけ仮想デスクトップを切り替えます。実行可能な xterm プロセスのバーストが、仮想デスクトップを切り替えたせいで発生しているのであれば、次の出力例のように、5 秒経過したところで呼び起こしアクティビティのバーストが確認されるはずです。


# dtrace -s ./xterm.d

  Xsun

           value  -------------- Distribution ------------ count    
               4 |                                         0        
               5 |@                                        1        
               6 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@   32       
               7 |                                         0

この出力から、xterm プロセスが仮想デスクトップの切り替えを行なった前後の時間帯に集中していることと、これらの xterm プロセスが X サーバーによって呼び起こされたことがわかります。X サーバーと xterm プロセスのやりとりについて調べたい場合は、X サーバーが wakeup プローブを起動したときのユーザースタックトレースを集積します。

X ウィンドウシステムのようなクライアントサーバーシステムのパフォーマンスについて理解するには、サーバーのサービス提供先であるクライアントについて理解する必要があります。この種の問題に対する答えは、従来のパフォーマンス解析ツールでは得にくいものです。しかし、「サーバーにメッセージを送信したクライアントは、サーバー側の処理が完了するまでスリープする」というモデルがある場合は、wakeup プローブを使って、サーバーがどのクライアントの要求を処理しているのかを特定できます。次の例を参照してください。

self int last;

sched:::wakeup
/self->last && args[0]->pr_stype == SOBJ_CV/
{
	@[stringof(args[1]->pr_fname)] = sum(vtimestamp - self->last);
	self->last = 0;
}

sched:::wakeup
/execname == "Xsun" && self->last == 0/
{
	self->last = vtimestamp;
}

このスクリプトを実行すると、次のような出力が得られます。


dtrace -s ./xwork.d
dtrace: script './xwork.d' matched 14 probes
^C
  xterm                                                       9522510
  soffice.bin                                                 9912594
  fvwm2                                                     100423123
  MozillaFirebird                                           312227077
  acroread                                                  345901577

この出力から、Xsun は、多くの作業を acroreadMozillaFirebirdfvwm2 のために行なっていることがわかります。ただし、fvwm2 の負荷はほかの 2 つほど大きくありません。条件変数同期オブジェクト (SOBJ_CV) からの呼び起こしだけが調べられている点に注目してください。表 25–4 で説明したように、条件変数は同期オブジェクトの一種であり、通常、共有データ領域へのアクセス以外の理由で同期化を行うときに使用されるものです。X サーバーの場合、クライアントは条件変数でスリープして、パイプ内のデータを待機します。

wakeup プローブとともに、追加で sleep プローブを使用すると、どのアプリケーションがどのアプリケーションでブロックされているのか、どのくらいの間ブロックされているのかを調べることができます。次の例を参照してください。

#pragma D option quiet

sched:::sleep
/!(curlwpsinfo->pr_flag & PR_ISSYS) && curlwpsinfo->pr_stype == SOBJ_CV/
{
	bedtime[curlwpsinfo->pr_addr] = timestamp;
}

sched:::wakeup
/bedtime[args[0]->pr_addr]/
{
	@[stringof(args[1]->pr_fname), execname] =
	    quantize(timestamp - bedtime[args[0]->pr_addr]);
	bedtime[args[0]->pr_addr] = 0;
}

END
{
	printa("%s sleeping on %s:\n%@d\n", @);
}

このスクリプトをデスクトップシステム上で数秒間実行した場合、出力の末尾部分は次のようになります。


# dtrace -s ./whofor.d
^C
...
 xterm sleeping on Xsun:

           value  -------------- Distribution ------------ count    
          131072 |                                         0        
          262144 |                                         12       
          524288 |                                         2        
         1048576 |                                         0        
         2097152 |                                         5        
         4194304 |@@@                                      45       
         8388608 |                                         1        
        16777216 |                                         9        
        33554432 |@@@@@                                    83       
        67108864 |@@@@@@@@@@@                              164      
       134217728 |@@@@@@@@@@                               147      
       268435456 |@@@@                                     56       
       536870912 |@                                        17       
      1073741824 |                                         9        
      2147483648 |                                         1        
      4294967296 |                                         3        
      8589934592 |                                         1        
     17179869184 |                                         0        

fvwm2 sleeping on Xsun:

           value  -------------- Distribution ------------ count    
           32768 |                                         0        
           65536 |@@@@@@@@@@@@@@@@@@@@@@                   67       
          131072 |@@@@@                                    16       
          262144 |@@                                       6        
          524288 |@                                        3        
         1048576 |@@@@@                                    15       
         2097152 |                                         0        
         4194304 |                                         0        
         8388608 |                                         1        
        16777216 |                                         0        
        33554432 |                                         0        
        67108864 |                                         1        
       134217728 |                                         0        
       268435456 |                                         0        
       536870912 |                                         1        
      1073741824 |                                         1        
      2147483648 |                                         2        
      4294967296 |                                         2        
      8589934592 |                                         2        
     17179869184 |                                         0        
     34359738368 |                                         2        
     68719476736 |                                         0        

syslogd sleeping on syslogd:

           value  -------------- Distribution ------------ count    
     17179869184 |                                         0        
     34359738368 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3        
     68719476736 |                                         0        

MozillaFirebird sleeping on MozillaFirebird:

           value  -------------- Distribution ------------ count    
           65536 |                                         0        
          131072 |                                         3        
          262144 |@@                                       14       
          524288 |                                         0        
         1048576 |@@@                                      18       
         2097152 |                                         0        
         4194304 |                                         0        
         8388608 |                                         1        
        16777216 |                                         0        
        33554432 |                                         1        
        67108864 |                                         3        
       134217728 |@                                        7        
       268435456 |@@@@@@@@@@                               53       
       536870912 |@@@@@@@@@@@@@@                           78       
      1073741824 |@@@@                                     25       
      2147483648 |                                         0        
      4294967296 |                                         0        
      8589934592 |@                                        7        
     17179869184 |                                         0

MozillaFirebird がブロックする様子と、ブロックする理由について調べたいこともあります。この問いの答えを導き出すには、上のスクリプトを以下の例のように変更します。

#pragma D option quiet

sched:::sleep
/execname == "MozillaFirebird" && curlwpsinfo->pr_stype == SOBJ_CV/
{
	bedtime[curlwpsinfo->pr_addr] = timestamp;
}

sched:::wakeup
/execname == "MozillaFirebird" && bedtime[args[0]->pr_addr]/
{
	@[args[1]->pr_pid, args[0]->pr_lwpid, pid, curlwpsinfo->pr_lwpid] = 
	    quantize(timestamp - bedtime[args[0]->pr_addr]);
	bedtime[args[0]->pr_addr] = 0;
}

sched:::wakeup
/bedtime[args[0]->pr_addr]/
{
	bedtime[args[0]->pr_addr] = 0;
}

END
{
	printa("%d/%d sleeping on %d/%d:\n%@d\n", @);
}

このスクリプトを数秒間実行すると、次のような出力が得られます。


# dtrace -s ./firebird.d
^C

 100459/1 sleeping on 100459/13:

           value  -------------- Distribution ------------ count    
          262144 |                                         0        
          524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
         1048576 |                                         0        

100459/13 sleeping on 100459/1:

           value  -------------- Distribution ------------ count    
        16777216 |                                         0        
        33554432 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
        67108864 |                                         0        

100459/1 sleeping on 100459/2:

           value  -------------- Distribution ------------ count    
           16384 |                                         0        
           32768 |@@@@                                     5        
           65536 |@                                        2        
          131072 |@@@@@                                    6        
          262144 |                                         1        
          524288 |@                                        2        
         1048576 |                                         0        
         2097152 |@@                                       3        
         4194304 |@@@@                                     5        
         8388608 |@@@@@@@@                                 9        
        16777216 |@@@@@                                    6        
        33554432 |@@                                       3        
        67108864 |                                         0        

100459/1 sleeping on 100459/5:

           value  -------------- Distribution ------------ count    
           16384 |                                         0        
           32768 |@@@@@                                    12       
           65536 |@@                                       5        
          131072 |@@@@@@                                   15       
          262144 |                                         1        
          524288 |                                         1        
         1048576 |                                         2        
         2097152 |@                                        4        
         4194304 |@@@@@                                    13       
         8388608 |@@@                                      8        
        16777216 |@@@@@                                    13       
        33554432 |@@                                       6        
        67108864 |@@                                       5        
       134217728 |@                                        4        
       268435456 |                                         0        
       536870912 |                                         1        
      1073741824 |                                         0        

100459/2 sleeping on 100459/1:

           value  -------------- Distribution ------------ count    
           16384 |                                         0        
           32768 |@@@@@@@@@@@@@@                           11       
           65536 |                                         0        
          131072 |@@                                       2        
          262144 |                                         0        
          524288 |                                         0        
         1048576 |@@@@                                     3        
         2097152 |@                                        1        
         4194304 |@@                                       2        
         8388608 |@@                                       2        
        16777216 |@                                        1        
        33554432 |@@@@@@                                   5        
        67108864 |                                         0        
       134217728 |                                         0        
       268435456 |                                         0        
       536870912 |@                                        1        
      1073741824 |@                                        1        
      2147483648 |@                                        1        
      4294967296 |                                         0        

100459/5 sleeping on 100459/1:

           value  -------------- Distribution ------------ count    
           16384 |                                         0        
           32768 |                                         1        
           65536 |                                         2        
          131072 |                                         4        
          262144 |                                         7        
          524288 |                                         1        
         1048576 |                                         5        
         2097152 |                                         10       
         4194304 |@@@@@@                                   77       
         8388608 |@@@@@@@@@@@@@@@@@@@@@@@                  270      
        16777216 |@@@                                      43       
        33554432 |@                                        20       
        67108864 |@                                        14       
       134217728 |                                         5        
       268435456 |                                         2        
       536870912 |                                         1        
      1073741824 |                                         0        

sleep プローブと wakeup プローブを使って、ネームサービスキャッシュデーモンなどの door サーバーのパフォーマンスを調べることもできます。次の例を参照してください。

sched:::sleep
/curlwpsinfo->pr_stype == SOBJ_SHUTTLE/
{
	bedtime[curlwpsinfo->pr_addr] = timestamp;
}

sched:::wakeup
/execname == "nscd" && bedtime[args[0]->pr_addr]/
{
	@[stringof(curpsinfo->pr_fname), stringof(args[1]->pr_fname)] =
	    quantize(timestamp - bedtime[args[0]->pr_addr]);
	bedtime[args[0]->pr_addr] = 0;
}

sched:::wakeup
/bedtime[args[0]->pr_addr]/
{
	bedtime[args[0]->pr_addr] = 0;
}

このスクリプトを大規模メールサーバー上で実行した場合、出力の末尾部分は次のようになります。


imapd
           value  -------------- Distribution ------------ count    
           16384 |                                         0        
           32768 |                                         2        
           65536 |@@@@@@@@@@@@@@@@@                        57       
          131072 |@@@@@@@@@@@                              37       
          262144 |                                         3        
          524288 |@@@                                      11       
         1048576 |@@@                                      10       
         2097152 |@@                                       9        
         4194304 |                                         1        
         8388608 |                                         0        

  mountd                                            
           value  -------------- Distribution ------------ count    
           65536 |                                         0        
          131072 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@            49       
          262144 |@@@                                      6        
          524288 |                                         1        
         1048576 |                                         0        
         2097152 |                                         0        
         4194304 |@@@@                                     7        
         8388608 |@                                        3        
        16777216 |                                         0        

  sendmail
           value  -------------- Distribution ------------ count    
           16384 |                                         0        
           32768 |@                                        18       
           65536 |@@@@@@@@@@@@@@@@@                        205      
          131072 |@@@@@@@@@@@@@                            154      
          262144 |@                                        23       
          524288 |                                         5        
         1048576 |@@@@                                     50       
         2097152 |                                         7        
         4194304 |                                         5        
         8388608 |                                         2        
        16777216 |                                         0        

  automountd                                        
           value  -------------- Distribution ------------ count    
           32768 |                                         0        
           65536 |@@@@@@@@@@                               22       
          131072 |@@@@@@@@@@@@@@@@@@@@@@@                  51       
          262144 |@@                                       6        
          524288 |                                         1        
         1048576 |                                         0        
         2097152 |                                         2        
         4194304 |                                         2        
         8388608 |                                         1        
        16777216 |                                         1        
        33554432 |                                         1        
        67108864 |                                         0        
       134217728 |                                         0        
       268435456 |                                         1        
       536870912 |                                         0

automountd の異常なデータポイントや、1 ミリ秒超で持続している sendmail のデータポイントについて調べることもできます。上記のスクリプトに述語を追加して、例外的な (異常な) 結果の原因を絞り込むこともできます。

preemptremain-cpu

Solaris は横取り式のシステムなので、優先順位の高いスレッドが優先順位の低いスレッドを「横取り」します。横取りが行われると、優先順位の低いほうのスレッドでかなりの遅延が発生します。このため、どのスレッドがどのスレッドによって横取りされているのか知りたい場合があります。以下は、preempt プローブと remain-cpu プローブを使って、この情報を表示する例です。

#pragma D option quiet

sched:::preempt
{
	self->preempt = 1;
}

sched:::remain-cpu
/self->preempt/
{
	self->preempt = 0;
}

sched:::off-cpu
/self->preempt/
{
	/*
	 * If we were told to preempt ourselves, see who we ended up giving
	 * the CPU to.
	 */
	@[stringof(args[1]->pr_fname), args[0]->pr_pri, execname,
	    curlwpsinfo->pr_pri] = count();
	self->preempt = 0;
}

END
{
	printf("%30s %3s %30s %3s %5s\n", "PREEMPTOR", "PRI",
	    "PREEMPTED", "PRI", "#");
	printa("%30s %3d %30s %3d %5@d\n", @);
}

このスクリプトをデスクトップシステム上で数秒間実行すると、次のような出力が得られます。


# dtrace -s ./whopreempt.d
^C
                     PREEMPTOR PRI                      PREEMPTED PRI     #
                         sched  60                           Xsun  53     1
                         xterm  59                           Xsun  53     1
               MozillaFirebird  57                           Xsun  53     1
                        mpstat 100                          fvwm2  59     1
                         sched  99                MozillaFirebird  57     1
                         sched  60                         dtrace  30     1
                        mpstat 100                           Xsun  59     2
                         sched  60                           Xsun  54     2
                         sched  99                          sched  60     2
                         fvwm2  59                           Xsun  44     2
                         sched  99                           Xsun  44     2
                         sched  60                          xterm  59     2
                         sched  99                           Xsun  53     2
                         sched  99                           Xsun  54     3
                         sched  60                          fvwm2  59     3
                         sched  60                           Xsun  59     3
                         sched  99                           Xsun  59     4
                         fvwm2  59                           Xsun  54     8
                         fvwm2  59                           Xsun  53     9
                          Xsun  59                MozillaFirebird  57    10
                         sched  60                MozillaFirebird  57    14
               MozillaFirebird  57                           Xsun  44    16
               MozillaFirebird  57                           Xsun  54    18

change-pri

「横取り」は、優先順位に基づいて行われます。この点を考慮して、優先順位が次第に変化していく様子を監視できます。以下は、change-pri プローブを使って、この情報を表示する例です。

sched:::change-pri
{
	@[stringof(args[0]->pr_clname)] =
	    lquantize(args[2] - args[0]->pr_pri, -50, 50, 5);
}

このスクリプトは、優先順位がどの程度上がったか (または下がったか) を確認し、スケジューリングクラス別に結果を集積します。このスクリプトを実行すると、次のような出力が得られます。


# dtrace -s ./pri.d
dtrace: script './pri.d' matched 10 probes
^C
 IA                                                
           value  -------------- Distribution ------------ count    
           < -50 |                                         20       
             -50 |@                                        38       
             -45 |                                         4        
             -40 |                                         13       
             -35 |                                         12       
             -30 |                                         18       
             -25 |                                         18       
             -20 |                                         23       
             -15 |                                         6        
             -10 |@@@@@@@@                                 201      
              -5 |@@@@@@                                   160      
               0 |@@@@@                                    138      
               5 |@                                        47       
              10 |@@                                       66       
              15 |@                                        36       
              20 |@                                        26       
              25 |@                                        28       
              30 |                                         18       
              35 |                                         22       
              40 |                                         8        
              45 |                                         11       
           >= 50 |@                                        34       

  TS                                                
           value  -------------- Distribution ------------ count    
             -15 |                                         0        
             -10 |@                                        1        
              -5 |@@@@@@@@@@@@                             7        
               0 |@@@@@@@@@@@@@@@@@@@@                     12       
               5 |                                         0        
              10 |@@@@@                                    3        
              15 |                                         0

対話型 (IA) スケジューリングクラスで優先順位の操作が出力されました。優先順位の「操作」ではなく、特定のプロセスとスレッドの優先順位の「値」が変化していく様子を確認することもできます。以下は、change-pri プローブを使って、この情報を表示する例です。

#pragma D option quiet

BEGIN
{
	start = timestamp;
}

sched:::change-pri
/args[1]->pr_pid == $1 && args[0]->pr_lwpid == $2/
{
	printf("%d %d\n", timestamp - start, args[2]);
}

tick-1sec
/++n == 5/
{
	exit(0);
}

優先順位が変化していく様子を確認するには、ウィンドウに次のコマンドを入力します。


$ echo $$
139208
$ while true ; do let i=0 ; done

先ほどとは別のウィンドウでスクリプトを実行し、結果をファイルにリダイレクトします。


# dtrace -s ./pritime.d 139208 1 > /tmp/pritime.out
#

上の例で生成された /tmp/pritime.out ファイルをプロッティングソフトウェアの入力ファイルとして使用すると、優先順位が変化していく様子を視覚的に確認できます。gnuplot は、Solaris Freeware Companion CD に収められている無料版プロッティングパッケージです。gnuplot のデフォルトのインストールディレクトリは、/opt/sfw/bin です。

tick

Solaris では、CPU アカウンティングがクロック刻みで行われます。このような CPU アカウンティングでは、決まった時間間隔でシステムクロック割り込みが発生し、そのとき実行中のスレッドとプロセスが CPU を使用しているものと見なされます。以下は、tick プローブを使ってこのアカウンティングの様子を調べる例です。


# dtrace -n sched:::tick'{@[stringof(args[1]->pr_fname)] = count()}'
^C
  arch                                                              1
  sh                                                                1
  sed                                                               1
  echo                                                              1
  ls                                                                1
  FvwmAuto                                                          1
  pwd                                                               1
  awk                                                               2
  basename                                                          2
  expr                                                              2
  resize                                                            2
  tput                                                              2
  uname                                                             2
  fsflush                                                           2
  dirname                                                           4
  vim                                                               9
  fvwm2                                                            10
  ksh                                                              19
  xterm                                                            21
  Xsun                                                             93
  MozillaFirebird                                                 260

システムクロック周波数は、オペレーティングシステムによって異なりますが、通常は 25 - 1024 ヘルツです。Solaris のシステムクロック周波数は調整できます。デフォルトでは 100 ヘルツです。

tick プローブは、システムクロックが実行可能なスレッドを検出したときにだけ起動します。tick プローブを使ってシステムクロック周波数を監視するには、常時実行可能なスレッドが必要です。まず、次の例のようなループしたシェルを作成します。


$ while true ; do let i=0 ; done

先ほどとは別のウィンドウで、次のスクリプトを実行します。

uint64_t last[int];

sched:::tick
/last[cpu]/
{
	@[cpu] = min(timestamp - last[cpu]);
}

sched:::tick
{
	last[cpu] = timestamp;
}

# dtrace -s ./ticktime.d
dtrace: script './ticktime.d' matched 2 probes
^C

  0          9883789

最小の間隔は 9.8 ミリ秒です。つまり、デフォルトのクロック周波数は 10 ミリ秒 (100 ヘルツ) になります。上の例で検出された最小値が 10 ミリ秒未満なのは、ジッターが発生しているせいです。

クロック刻みのアカウンティングには、欠点もあります。それは、アカウンティングを行うシステムクロックによって、時間に関するスケジューリングアクティビティがディスパッチされる場合があるということです。その結果、クロック刻みと同間隔で (つまり 10 ミリ秒に 1 回) スレッドが何らかの作業を行う場合に、正しいアカウンティングができません。時間に関するスケジューリングアクティビティのディスパッチの前後どちらでアカウンティングが行われるかによって、結果が実際よりも上下します。Solaris では、時間に関するディスパッチの前にアカウンティングが行われます。その結果、一定間隔で実行されるスレッドについてのアカウンティングが実際より低く報告されます。このようなスレッドは、実行期間をクロック刻みより短くすることによってクロック刻みの背後に「隠す」ことができます。以下は、システムにこのようなスレッドがどのくらいあるかを表示する例です。

sched:::tick,
sched:::enqueue
{
	@[probename] = lquantize((timestamp / 1000000) % 10, 0, 10);
}

このスクリプトを実行し、出力結果を確認すると、10 ミリ秒間にミリ秒のオフセットが 2 つ存在することがわかります。1 つは tick プローブのオフセット、もう 1 つは enqueue のオフセットです。


# dtrace -s ./tick.d
dtrace: script './tick.d' matched 4 probes
^C
  tick                                              
           value  -------------- Distribution ------------ count    
               6 |                                         0        
               7 |@                                        3        
               8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@   79       
               9 |                                         0        

  enqueue                                           
           value  -------------- Distribution ------------ count    
             < 0 |                                         0        
               0 |@@                                       267      
               1 |@@                                       300      
               2 |@@                                       259      
               3 |@@                                       291      
               4 |@@@                                      360      
               5 |@@                                       305      
               6 |@@                                       295      
               7 |@@@@                                     522      
               8 |@@@@@@@@@@@@                             1315     
               9 |@@@                                      337

ヒストグラム tick からは、クロック刻みが 8 ミリ秒のオフセットで起動していることがわかります。スケジューリングがクロック刻みと無関係に行われていれば、enqueue の出力結果は 10 ミリ秒間の中で均一に分布するはずです。しかし、実際には 8 ミリ秒のオフセットで値が大きく変化しています。したがって、このシステムには、時間ベースでスケジューリングされるスレッドも多少存在していることになります。

安定性

以下の表に、sched プロバイダの安定性を DTrace の安定性機構に従って示します。安定性機構の詳細については、第 39 章安定性を参照してください。

要素 

名前の安定性 

データの安定性 

依存クラス 

プロバイダ 

発展中 

発展中 

ISA

モジュール 

非公開 

非公開 

不明 

機能 

非公開 

非公開 

不明 

名前 

発展中 

発展中 

ISA

引数 

発展中 

発展中 

ISA