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/03/22 23:03] – Updated privilege check example to use priv provider. 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>
 #pragma D option quiet #pragma D option quiet
  
-callout_execute:::callout_start+callout_execute:::callout-start
 { {
         self->cstart = timestamp;         self->cstart = timestamp;
 } }
  
-callout_execute:::callout_end+callout_execute:::callout-end
 { {
  
Line 86: Line 86:
  
 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.
Line 168: Line 170:
  
 <code> <code>
-priv:::priv_err+priv:::priv-err
 { {
         @traces[stack()] = count();         @traces[stack()] = count();
Line 215: Line 217:
 ===== Histogram of time spent waiting on NFSv3 RPCs by system call ===== ===== 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. 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> <code>
Line 303: Line 307:
         16777216 |                                         0                 16777216 |                                         0        
 </code> </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.1237763022.txt.gz
  • Last modified: 2009/03/22 23:03
  • by RobertWatson