3.4.2 Example: Using timeTweenprobes.d to Show the Elapsed Time Between Each Probe

You can broaden the script to monitor all of the following probes in the application:

  • query-userentry

  • query-maxcheckval

  • query-factorreturnA

  • query-factorreturnB

  • query-final

/* timeTweenProbes.d */

/* show how much time elapses between each probe */

BEGIN
{
  iterationCount = 0;
}


primeget*:::query-userentry
{
  printf("%s (pid=%d) running\n", execname, pid);
  self->t = timestamp; /* Initialize a thread-local variable with time */
}

primeget*:::query-maxcheckval
/self->t != 0/
{
  timeNow = timestamp;
  printf(" maxcheckval spent %d microseconds since userentry\n",
         ((timeNow - self->t)/1000));  /* Divide by 1000 for microseconds */
  self->t = timeNow; /* set the time to recent sample */
}

primeget*:::query-factorreturnA
/self->t != 0/
{
  timeNow = timestamp;
  printf(" factorreturnA spent %d microseconds since maxcheckval\n",
         ((timeNow - self->t)/1000));  /* Divide by 1000 for microseconds */
  self->t = timeNow; /* set the time to recent sample */
}

primeget*:::query-factorreturnB
/self->t != 0/
{
  timeNow = timestamp;
  printf(" factorreturnB spent %d microseconds since factorreturnA\n",
         ((timeNow - self->t)/1000));  /* Divide by 1000 for microseconds */
  self->t = timeNow; /* set the time to recent sample */
}

primeget*:::query-final
/self->t != 0/
{
  printf(" prime spent %d microseconds from factorreturnB until ending\n",
         ((timestamp - self->t)/1000));
  self->t = 0; /* Reset the variable */
  iterationCount++;
}

END
{
  trace(iterationCount);
}

Again, start the execution of the target application first, then run the script from another window:

# ./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
# ./prime 
Enter a positive target integer to test for prime status: 95099
Square root of 95099 is 308.381256
308 highest value to check as divisor
95099 is not prime because there is a factor 61
# ./prime 
Enter a positive target integer to test for prime status: 95099
Square root of 95099 is 308.381256
308 highest value to check as divisor
95099 is not prime because there is a factor 61
# ./prime 
Enter a positive target integer to test for prime status: 5099         
Square root of 5099 is 71.407280
71 highest value to check as divisor
5099 is a prime number

The corresponding output from the script is similar to the following:

# dtrace -q -s ./timeTweenProbes.d
prime (pid=2437) running
 maxcheckval spent 96 microseconds since userentry
 factorreturnA spent 9 microseconds since maxcheckval
 factorreturnB spent 6 microseconds since factorreturnA
 prime spent 9 microseconds from factorreturnB until ending
prime (pid=2439) running
 maxcheckval spent 45 microseconds since userentry
 factorreturnA spent 10 microseconds since maxcheckval
 factorreturnB spent 7 microseconds since factorreturnA
 prime spent 9 microseconds from factorreturnB until ending
prime (pid=2440) running
 maxcheckval spent 43 microseconds since userentry
 factorreturnA spent 11 microseconds since maxcheckval
 factorreturnB spent 8 microseconds since factorreturnA
 prime spent 10 microseconds from factorreturnB until ending
prime (pid=2441) running
 maxcheckval spent 53 microseconds since userentry
 factorreturnA spent 10 microseconds since maxcheckval
 factorreturnB spent 7 microseconds since factorreturnA
 prime spent 10 microseconds from factorreturnB until ending
prime (pid=2442) running
 maxcheckval spent 40 microseconds since userentry
 factorreturnA spent 9 microseconds since maxcheckval
 factorreturnB spent 48 microseconds since factorreturnA
 prime spent 10 microseconds from factorreturnB until ending

^C
5

As is observed in the previous example, there is now a set of DTrace features that can be used with the probes that were created.