dtrace:examples

Differences

This shows you the differences between two versions of the page.

Link to this comparison view

Both sides previous revision Previous revision
Next revision		 Previous revision
dtrace:examples [2009/02/14 13:41] – Sample output for callout profiling. RobertWatsondtrace:examples [2020/12/25 15:22] (current) – Update probe name for priv-err RobertWatson
Line 6: Line 6:
  
 <code> <code>
-callout_execute:::callout_start+callout_execute:::callout-start
 { {
         self->cstart = timestamp;         self->cstart = timestamp;
 } }
  
-callout_execute:::callout_end+callout_execute:::callout-end
 { {
  
Line 55: Line 55:
  
 ===== Measure total time spent in each callout handler over 1-second intervals ===== ===== Measure total time spent in each callout handler over 1-second intervals =====
-This script is loosely based on a similar one from [[/OpenSolaris|OpenSolaris]]'s sdt Provider page, but due to slight differences in types and probe naming, we can't use theirs verbatim:+This script is loosely based on a similar one from %%OpenSolaris%%'s sdt Provider page, but due to slight differences in types and probe naming, we can't use theirs verbatim:
  
 <code> <code>
-callout_execute:::callout_start+#pragma D option quiet 
 + 
 +callout_execute:::callout-start
 { {
         self->cstart = timestamp;         self->cstart = timestamp;
 } }
  
-callout_execute:::callout_end+callout_execute:::callout-end
 { {
  
Line 75: Line 77:
         clear(@callouts);         clear(@callouts);
         printf("\n");         printf("\n");
 +}
 +
 +BEGIN
 +{
 +        printf("%40s | %s\n", "function", "nanoseconds per second");
 } }
 </code> </code>
  
 Submitted by [[/RobertWatson|RobertWatson]]. Submitted by [[/RobertWatson|RobertWatson]].
 +
 +Note: Probes were named callout_start and callout_end in older versions.
  
 This script works by measuring the time at the start of a callout, then again on termination and billing that time incrementally to the callout function that ran.  Once a second, we print the results and reset the counters. This script works by measuring the time at the start of a callout, then again on termination and billing that time incrementally to the callout function that ran.  Once a second, we print the results and reset the counters.
 +
 +<code>
 +cinnamon-freebsd# dtrace -s d.d
 +                                function | nanoseconds per second
 +                      kernel`ipport_tick      19215
 +                        kernel`nd6_timer      21521
 +                   kernel`lance_watchdog      31848
 +             kernel`kbdmux_kbd_intr_timo      34418
 +                       kernel`logtimeout     106167
 +                       kernel`pffasttimo     149003
 +                       kernel`scrn_timer     157988
 +                     kernel`tcp_isn_tick     161720
 +                       kernel`pfslowtimo     201723
 +                    kernel`dcons_timeout     309218
 +                              0xc42deeb0     443589
 +                           kernel`lim_cb     584293
 +                    kernel`atkbd_timeout     789599
 +                              0xc42d34f0     807851
 +                   kernel`sleepq_timeout    4198977
 +
 +^C
 +</code>
  
 ===== Measure total time spent in non-MPSAFE callouts over 10-second intervals ===== ===== Measure total time spent in non-MPSAFE callouts over 10-second intervals =====
Line 121: Line 152:
  
 As before, except that only callouts using Giant are measured.  Note the "`" before Giant in order to name a kernel global variable. As before, except that only callouts using Giant are measured.  Note the "`" before Giant in order to name a kernel global variable.
 +
 +<code>
 +cinnamon-freebsd# dtrace -s d.d
 +dtrace: dynamic variable size lowered to 16m
 +                                function | nanoseconds per second
 +                        kernel`nd6_timer      19388
 +             kernel`kbdmux_kbd_intr_timo     141079
 +                       kernel`scrn_timer     345507
 +                       kernel`logtimeout     418742
 +                    kernel`atkbd_timeout     574425
 +
 +^C
 +</code>
  
 ===== Collect stack traces leading to failed priv_check_cred() calls ===== ===== Collect stack traces leading to failed priv_check_cred() calls =====
-This script captures an array of counters, one for each stack trace leading to a non-zero return from priv_check_cred() using the fbt provider:+This script captures an array of counters, one for each stack trace leading to a failed kernel privilege check:
  
 <code> <code>
-fbt::priv_check_cred:return +priv:::priv-err
-/arg1 != 0/+
 { {
         @traces[stack()] = count();         @traces[stack()] = count();
Line 135: Line 178:
 Submitted by [[/RobertWatson|RobertWatson]] Submitted by [[/RobertWatson|RobertWatson]]
  
-Interestingly, fbt on my test box only appears to have an entry event for priv_check() and no return.+<code> 
 +dtrace: script 'priv.d' matched 1 probe 
 +dtrace: aggregation size lowered to 6m 
 +^C 
 + 
 +              kernel`priv_check_cred+0xc3 
 +              kernel`vaccess+0x104 
 +              kernel`ufs_access+0x1e6 
 +              kernel`VOP_ACCESS_APV+0xa5 
 +              kernel`nfsrv_access+0xfa 
 +              kernel`nfsrv3_access+0x2fc 
 +              kernel`nfssvc_program+0x397 
 +              kernel`svc_run_internal+0x942 
 +              kernel`svc_run+0x7f 
 +              kernel`nfssvc_nfsd+0xad 
 +              kernel`nfssvc+0x235 
 +              kernel`syscall+0x2d3 
 +              kernel`0xc0b43790 
 +               32 
 + 
 +              kernel`priv_check_cred+0xc3 
 +              kernel`vaccess+0x179 
 +              kernel`ufs_access+0x1e6 
 +              kernel`VOP_ACCESS_APV+0xa5 
 +              kernel`nfsrv_access+0xfa 
 +              kernel`nfsrv3_access+0x23f 
 +              kernel`nfssvc_program+0x397 
 +              kernel`svc_run_internal+0x942 
 +              kernel`svc_run+0x7f 
 +              kernel`nfssvc_nfsd+0xad 
 +              kernel`nfssvc+0x235 
 +              kernel`syscall+0x2d3 
 +              kernel`0xc0b43790 
 +               32 
 +... 
 +</code> 
 + 
 +===== Histogram of time spent waiting on NFSv3 RPCs by system call ===== 
 +This script measures all time spent waiting on RPC replies for each system call, and then generates a histogram of those times sorted by system call name. 
 + 
 +Exists in %%FreeBSD%% as ''%%/usr/src/share/dtrace/nfsclienttime%%''. 
 + 
 +<code> 
 +syscall:::entry 
 +{ 
 + 
 +        self->count = 0; 
 +} 
 + 
 +nfsclient:nfs3::start 
 +{ 
 + 
 +        self->timestamp = timestamp; 
 +} 
 + 
 +nfsclient:nfs3::done 
 +{ 
 + 
 +        self->count += (timestamp - self->timestamp); 
 +} 
 + 
 +syscall:::return 
 +/self->count != 0/  { 
 + 
 +        @syscalls[probefunc] = quantize(self->count); 
 +} 
 +</code> 
 + 
 +Submitted by [[/RobertWatson|RobertWatson]] 
 + 
 +<code> 
 +dtrace: script 'd.d' matched 1040 probes 
 +dtrace: aggregation size lowered to 6m 
 +^C 
 +  fstatfs                                            
 +           value  ------------- Distribution ------------- count     
 +          131072 |                                         0         
 +          262144 |@@@@@@@@@@@@@                            2         
 +          524288 |@@@@@@@@@@@@@                            2         
 +         1048576 |@@@@@@@@@@@@@                            2         
 +         2097152 |                                         0         
 + 
 +  open                                               
 +           value  ------------- Distribution ------------- count     
 +               4 |                                         0         
 +               8 |@                                        3         
 +              16 |                                         1         
 +              32 |@                                        2         
 +              64 |                                         1         
 +             128 |                                         0         
 +             256 |                                         0         
 +             512 |                                         0         
 +            1024 |                                         0         
 +            2048 |                                         1         
 +            4096 |                                         1         
 +            8192 |                                         0         
 +           16384 |                                         0         
 +           32768 |                                         0         
 +           65536 |                                         0         
 +          131072 |                                         0         
 +          262144 |@@@@@                                    11        
 +          524288 |@@@@@@@@@@@@@@@@                         35        
 +         1048576 |@@@@@@@@@@@@                             26        
 +         2097152 |@                                        3         
 +         4194304 |@                                        2         
 +         8388608 |                                         0         
 + 
 +  lstat                                              
 +           value  ------------- Distribution ------------- count     
 +              64 |                                         0         
 +             128 |                                         1         
 +             256 |                                         1         
 +             512 |                                         0         
 +            1024 |                                         1         
 +            2048 |                                         1         
 +            4096 |                                         0         
 +            8192 |                                         0         
 +           16384 |                                         1         
 +           32768 |                                         0         
 +           65536 |                                         0         
 +          131072 |                                         1         
 +          262144 |@@@@@                                    15        
 +          524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              86        
 +         1048576 |@@@@@                                    17        
 +         2097152 |                                         1         
 +         4194304 |                                         0         
 +         8388608 |                                         1         
 +        16777216 |                                         0         
 +</code> 
 + 
 +===== Trace of NFS RPCs and attribute/access cache interactions by system call ===== 
 + 
 +This script creates a trace of NFS RPCs, NFS attribute cache activity, and NFS access cache activity, along with the system call that instigated the activity.  Notice that NFS events may happen outside of the context of a system call, most likely due to the VM system paging from NFS, in which case the system call name is reported as "-". 
 + 
 +Exists in %%FreeBSD%% as ''%%/usr/src/share/dtrace/nfsattrstats%%''. 
 + 
 +<code> 
 +syscall:::entry 
 +{ 
 + 
 +        self->syscallname = probefunc; 
 +} 
 + 
 +syscall:::return 
 +{ 
 + 
 +        self->syscallname = ""; 
 +} 
 + 
 +nfsclient::: 
 +/self->syscallname != 0 && self->syscallname != ""/ 
 +{ 
 + 
 +        trace(probemod); 
 +        trace(arg0); 
 +        trace(execname); 
 +        trace(self->syscallname); 
 +} 
 + 
 +nfsclient::: 
 +/self->syscallname == 0 || self->syscallname == ""/ 
 +{ 
 + 
 +        trace(probemod); 
 +        trace(arg0); 
 +        trace(execname); 
 +        trace("-"); 
 +} 
 +</code> 
 + 
 +Submitted by [[/RobertWatson|RobertWatson]] 
 + 
 +<code> 
 +1    531                 get:hit   attrcache             3281906832  ls         lstat                             
 +1    527                 get:hit   accesscache           3281906832  ls         open                              
 +1    531                 get:hit   attrcache             3281906832  ls         open                              
 +1    527                 get:hit   accesscache           3281906832  ls         open                              
 +1    530              flush:done   attrcache             3281906832  ls         open                              
 +1    532                get:miss   attrcache             3281906832  ls         open                              
 +1    568           getattr:start   nfs3                  3281906832  ls         open                              
 +1    569            getattr:done   nfs3                  3281906832  ls         open                              
 +1    533               load:done   attrcache             3281906832  ls         open                              
 +1    527                 get:hit   accesscache           3281906832  ls         fchdir                            
 +1    531                 get:hit   attrcache             3281906832  ls         stat                              
 +1    527                 get:hit   accesscache           3281906832  ls         open                              
 +1    530              flush:done   attrcache             3281906832  ls         open                              
 +1    532                get:miss   attrcache             3281906832  ls         open                              
 +1    568           getattr:start   nfs3                  3281906832  ls         open                              
 +1    569            getattr:done   nfs3                  3281906832  ls         open                              
 +1    533               load:done   attrcache             3281906832  ls         open                              
 +1    531                 get:hit   attrcache             3281906832  ls         fstat                             
 +1    602            fsstat:start   nfs3                  3281906832  ls         fstatfs                           
 +1    603             fsstat:done   nfs3                  3281906832  ls         fstatfs                           
 +1    533               load:done   attrcache             3281906832  ls         fstatfs                           
 +1    531                 get:hit   attrcache             3281906832  ls         fstat                             
 +1    527                 get:hit   accesscache           3281906832  ls         fchdir                            
 +1    531                 get:hit   attrcache             3281906832  ls         getdirentries                     
 +1    527                 get:hit   accesscache           3281906832  ls         lstat                             
 +1    531                 get:hit   attrcache             3376191584  ls         lstat                             
 +1    531                 get:hit   attrcache             3376191584  ls         lstat                             
 +1    531                 get:hit   attrcache             3281906832  ls         getdirentries                     
 +1    527                 get:hit   accesscache           3281906832  ls         fchdir                            
 +1    527                 get:hit   accesscache           3281906832  ls         pathconf                          
 +1    531                 get:hit   attrcache             3376191584  ls         pathconf          
 +</code> 
 + 
 +===== Distribution of name cache entry string lengths ===== 
 + 
 +This example script captures a distribution of the length of strings added to the VFS name cache. 
 + 
 +<code> 
 +vfs:namecache:enter:done 
 +{ 
 + 
 +        @distribution = quantize(strlen((string)arg1)); 
 +} 
 +</code> 
 + 
 +Submitted by [[/RobertWatson|RobertWatson]] 
 + 
 +<code> 
 +value  ------------- Distribution ------------- count 
 +    0 |                                         0 
 +    1 |                                         2 
 +    2 |@@                                       296 
 +    4 |@@@@@@@@@@@                              1879 
 +    8 |@@@@@@@@@@@@@@@@                         2719 
 +   16 |@@@@@@@@@@@                              1974 
 +   32 |                                         69 
 +   64 |                                         2 
 +  128 |                                         0 
 +</code> 
 + 
 +A similar script to look at the distribution of lengths in hits could be generated using the probe vfs:namecache:lookup:hit.  Notice that vfs:namecache:lookup:miss includes additional pathname components, due to an implementation detail of the probe, and lends itself to this analysis less. 
 + 
 +---- 
 + 
 +{{tag>Dtrace HowTo}}
  
  • dtrace/examples.1234618880.txt.gz
  • Last modified: 2009/02/14 13:41
  • by RobertWatson