3.4.1 Example: Using simpleTimeProbe.d to Show the Elapsed Time Between Two Probes

The following example shows how you would create a simple script that measures the time elapsed between the first probe and the second probe (query-userentry to query-maxcheckval).

/* simpleTimeProbe.d */

/* Show how much time elapses between two probes */

primeget*:::query-userentry
{
  self->t = timestamp; /* Initialize a thread-local variable with the time */
}

primeget*:::query-maxcheckval
/self->t != 0/
{
  timeNow = timestamp;
  /* Divide by 1000 for microseconds */
  printf("%s (pid=%d) spent %d microseconds between userentry & maxcheckval\n",
         execname, pid, ((timeNow - self->t)/1000));

  self->t = 0; /* Reset the variable */
}

Start the execution of the target application:

# ./prime
Enter a positive target integer to test for prime status:

Then, run the DTrace script from another window:

# dtrace -q -s simpleTimeProbe.d

As the application is running, the output of the script is also running in parallel:

# ./prime 
Enter a positive target integer to test for prime status: 7921
Square root of 7921 is 89.000000
89 highest value to check as divisor
7921 is not prime because there is a factor 89
# ./prime 
Enter a positive target integer to test for prime status: 995099
Square root of 995099 is 997.546509
997 highest value to check as divisor
995099 is not prime because there is a factor 7
# ./prime 
Enter a positive target integer to test for prime status: 7921
Square root of 7921 is 89.000000
89 highest value to check as divisor
7921 is not prime because there is a factor 89

On the command line where the script is being run, you should see output similar to the following:

# dtrace -q -s simpleTimeProbe.d
prime (pid=2328) spent 45 microseconds between userentry & maxcheckval
prime (pid=2330) spent 41 microseconds between userentry & maxcheckval
prime (pid=2331) spent 89 microseconds between userentry & maxcheckval
^C