DTrace User Guide

Speculative Tracing

This section discusses the DTrace facility for speculative tracing. Speculative tracing is the ability to tentatively trace data and decide whether to commit the data to a tracing buffer or discard it. The primary mechanism to filter out uninteresting events is the predicate mechanism. Predicates are useful when you know at the time that a probe fires whether or not the probe event is of interest. Predicates are not well suited to dealing with situations where you do not know if a given probe event is of interest or not until after the probe fires.

If a system call is occasionally failing with a common error code, you might want to examine the code path that leads to the error condition. You can use the speculative tracing facility to tentatively trace data at one or more probe locations, then decide to commit the data to the principal buffer at another probe location. The resulting trace data contains only the output of interest and requires no postprocessing.

Speculation Interfaces

The following table describes the DTrace speculation functions.

Table 4–1 DTrace Speculation Functions

Function Name 

Arguments 

Description 

speculation

None 

Returns an identifier for a new speculative buffer 

speculate

ID 

Denotes that the remainder of the clause should be traced to the speculative buffer specified by ID 

commit

ID 

Commits the speculative buffer that is associated with ID 

discard

ID 

Discards the speculative buffer associated with ID 

Creating a Speculation

The speculation() function allocates a speculative buffer and returns a speculation identifier. Use the speculation identifier in subsequent calls to the speculate() function. A speculation identifier of zero is always invalid, but can be passed to speculate(), commit() or discard(). If a call to speculation() fails, the dtrace command generates a message that is similar to the following example.


dtrace: 2 failed speculations (no speculative buffer space available)

Using a Speculation

To use a speculation, use a clause to pass an identifier that has been returned from speculation() to the speculate() function before any data-recording actions. All data-recording actions in a clause that contains a speculate() are speculatively traced. The D compiler generates a compile-time error if a call to speculate() follows data recording actions in a D probe clause. Clauses can contain either speculative tracing requests or non-speculative tracing requests, but not both.

Aggregating actions, destructive actions, and the exit action may never be speculative. Any attempt to take one of these actions in a clause that contains a speculate() results in a compile-time error. A speculate() function may not follow a previous speculate() function. Only one speculation is permitted per clause. A clause that contains only a speculate() function will speculatively trace the default action, which is defined to trace only the enabled probe ID.

The typical use of the speculation() function is to assign the result of the speculation() function to a thread-local variable. That thread-local variable acts as a subsequent predicate to other probes, as well as an argument to speculate().


Example 4–5 Typical Use of The speculation() Function

syscall::open:entry
{
	self->spec = speculation();
}

syscall:::
/self->spec/
{
	speculate(self->spec);
	printf("this is speculative");
}

Committing a Speculation

Commit speculations by using the commit() function. When you commit a speculative buffer the buffer's data is copied into the principal buffer. If the data in the speculative buffer exceeds the available space in the principal buffer, no data is copied and the drop count for the buffer increments. If the buffer has been speculatively traced on more than one CPU, the speculative data on the committing CPU is copied immediately, while speculative data on other CPUs is copied after the commit().

A speculative buffer that is being committed is not available to subsequent speculation() calls until each per-CPU speculative buffer is completely copied into its corresponding per-CPU principal buffer. Subsequent attempts to write the results of a speculate() function call to the committing buffer discard the data without generating an error. Subsequent calls to commit() or discard() also fail without generating an error. A clause that contains a commit() function cannot contain a data recording action, but a clause can contain multiple commit() calls to commit disjoint buffers.

Discarding a Speculation

Discard speculations by using the discard() function. If the speculation has only been active on the CPU that is calling the discard() function, the buffer is immediately available for subsequent calls to the speculation() function. If the speculation has been active on more than one CPU, the discarded buffer will be available for subsequent calls to the speculation() function after the call to discard(). If no speculative buffers are available at the time that the speculation() function is called adtrace message that is similar to the following example is generated:


dtrace: 905 failed speculations (available buffer(s) still busy)

Speculation Example

One potential use for speculations is to highlight a particular code path. The following example shows the entire code path under the open(2) system call when the open() fails.


Example 4–6 specopen.d: Code Flow for Failed open()

#!/usr/sbin/dtrace -Fs

syscall::open:entry,
syscall::open64:entry
{
	/*
	 * The call to speculation() creates a new speculation.  If this fails,
	 * dtrace(1M) will generate an error message indicating the reason for
	 * the failed speculation(), but subsequent speculative tracing will be
	 * silently discarded.
	 */
	self->spec = speculation();
	speculate(self->spec);

	/*
	 * Because this printf() follows the speculate(), it is being 
	 * speculatively traced; it will only appear in the data buffer if the
	 * speculation is subsequently commited.
	 */
	printf("%s", stringof(copyinstr(arg0)));
}

fbt:::
/self->spec/
{
	/*
	 * A speculate() with no other actions speculates the default action:
	 * tracing the EPID.
	 */
	speculate(self->spec);
}

syscall::open:return,
syscall::open64:return
/self->spec/
{
	/*
	 * To balance the output with the -F option, we want to be sure that
	 * every entry has a matching return.  Because we speculated the
	 * open entry above, we want to also speculate the open return.
	 * This is also a convenient time to trace the errno value.
	 */
	speculate(self->spec);
	trace(errno);
}

syscall::open:return,
syscall::open64:return
/self->spec && errno != 0/
{
	/*
	 * If errno is non-zero, we want to commit the speculation.
	 */
	commit(self->spec);
	self->spec = 0;
}

syscall::open:return,
syscall::open64:return
/self->spec && errno == 0/
{
	/*
	 * If errno is not set, we discard the speculation.
	 */
	discard(self->spec);
	self->spec = 0;
}

When you run the previous script, the script generates output that is similar to the following example.


# ./specopen.d
dtrace: script './specopen.d' matched 24282 probes
CPU FUNCTION                                 
  1  => open                                  /var/ld/ld.config
  1    -> open                                
  1      -> copen                             
  1        -> falloc                          
  1          -> ufalloc                       
  1            -> fd_find                     
  1              -> mutex_owned               
  1              <- mutex_owned               
  1            <- fd_find                     
  1            -> fd_reserve                  
  1              -> mutex_owned               
  1              <- mutex_owned               
  1              -> mutex_owned               
  1              <- mutex_owned               
  1            <- fd_reserve                  
  1          <- ufalloc                       
  1          -> kmem_cache_alloc              
  1            -> kmem_cache_alloc_debug      
  1              -> verify_and_copy_pattern   
  1              <- verify_and_copy_pattern   
  1              -> file_cache_constructor    
  1                -> mutex_init              
  1                <- mutex_init              
  1              <- file_cache_constructor    
  1              -> tsc_gethrtime             
  1              <- tsc_gethrtime             
  1              -> getpcstack                
  1              <- getpcstack                
  1              -> kmem_log_enter            
  1              <- kmem_log_enter            
  1            <- kmem_cache_alloc_debug      
  1          <- kmem_cache_alloc              
  1          -> crhold                        
  1          <- crhold                        
  1        <- falloc                          
  1        -> vn_openat                       
  1          -> lookupnameat                  
  1            -> copyinstr                   
  1            <- copyinstr                   
  1            -> lookuppnat                  
  1              -> lookuppnvp                
  1                -> pn_fixslash             
  1                <- pn_fixslash             
  1                -> pn_getcomponent         
  1                <- pn_getcomponent         
  1                -> ufs_lookup              
  1                  -> dnlc_lookup           
  1                    -> bcmp                
  1                    <- bcmp                
  1                  <- dnlc_lookup           
  1                  -> ufs_iaccess           
  1                    -> crgetuid            
  1                    <- crgetuid            
  1                    -> groupmember         
  1                      -> supgroupmember    
  1                      <- supgroupmember
  1                    <- groupmember         
  1                  <- ufs_iaccess           
  1                <- ufs_lookup              
  1                -> vn_rele                 
  1                <- vn_rele                 
  1                -> pn_getcomponent         
  1                <- pn_getcomponent         
  1                -> ufs_lookup              
  1                  -> dnlc_lookup           
  1                    -> bcmp                
  1                    <- bcmp                
  1                  <- dnlc_lookup           
  1                  -> ufs_iaccess           
  1                    -> crgetuid            
  1                    <- crgetuid            
  1                  <- ufs_iaccess           
  1                <- ufs_lookup              
  1                -> vn_rele                 
  1                <- vn_rele                 
  1                -> pn_getcomponent         
  1                <- pn_getcomponent         
  1                -> ufs_lookup              
  1                  -> dnlc_lookup           
  1                    -> bcmp                
  1                    <- bcmp                
  1                  <- dnlc_lookup           
  1                  -> ufs_iaccess           
  1                    -> crgetuid            
  1                    <- crgetuid            
  1                  <- ufs_iaccess           
  1                  -> vn_rele               
  1                  <- vn_rele               
  1                <- ufs_lookup              
  1                -> vn_rele                 
  1                <- vn_rele                 
  1              <- lookuppnvp                
  1            <- lookuppnat                  
  1          <- lookupnameat                  
  1        <- vn_openat                       
  1        -> setf                            
  1          -> fd_reserve                    
  1            -> mutex_owned                 
  1            <- mutex_owned                 
  1            -> mutex_owned                 
  1            <- mutex_owned                 
  1          <- fd_reserve                    
  1          -> cv_broadcast                  
  1          <- cv_broadcast                  
  1        <- setf                            
  1        -> unfalloc                        
  1          -> mutex_owned                   
  1          <- mutex_owned                   
  1          -> crfree                        
  1          <- crfree                        
  1          -> kmem_cache_free               
  1            -> kmem_cache_free_debug       
  1              -> kmem_log_enter            
  1              <- kmem_log_enter            
  1              -> tsc_gethrtime             
  1              <- tsc_gethrtime             
  1              -> getpcstack                
  1              <- getpcstack                
  1              -> kmem_log_enter            
  1              <- kmem_log_enter
  1              -> file_cache_destructor     
  1                -> mutex_destroy           
  1                <- mutex_destroy           
  1              <- file_cache_destructor     
  1              -> copy_pattern              
  1              <- copy_pattern              
  1            <- kmem_cache_free_debug       
  1          <- kmem_cache_free               
  1        <- unfalloc                        
  1        -> set_errno                       
  1        <- set_errno                       
  1      <- copen                             
  1    <- open                                
  1  <= open                                          2