Home arrow Guides arrow Quick Guide to DTrace on FreeBSD
Quick Guide to DTrace on FreeBSD PDF
Tuesday, 15 May 2012
DTrace is a very useful tool to identify bottlenecks on your servers. But it can also be use to optimize your userland apps or services and to monitor your services. So it is both usefull for developers and for system administrators.

1. Configuring DTrace (adding support for DTrace in FreeBSD)

In order to add support for DTrace (as of FreeBSD 9.0 Release) we muste recompile the kernel adding the following options:

  options         KDTRACE_HOOKS
  options         DDB_CTF
  options         KDTRACE_FRAME
    # only for amd64 architecture
  makeoptions DEBUG="-g"                # only for amd64
  makeoptions WITH_CTF=1

Then edit /etc/make.conf and add the following lines:

  STRIP=
  CFLAGS+=-fno-omit-frame-pointer


(if you do not add the previous two lines in /etc/make.conf on your amd64 bits machine at least you might experience kernel panics.)

Then we will compile our kernel (let's say our kernel config file is SERVER):

  cd /usr/src
  make  -j4 WITH_CTF=1 buildkernel KERNCONF=SERVER
  make installkernel KERNCONF=SERVER


We will also need to add ksh93 shell, which is needed by DTrace because it has some script utilities written in Korn shell (but you do not need to change your current shell, just only to install ksh93 on your system):

  cd /usr/ports/shells/ksh93
  make install clean; rehash

Now we must add kernel module to /boot/loader.conf (because when we've recompiled kernel we only added kernel hooks for dtrace):

Add the following line to /boot/loader.conf:

  dtraceall_load="YES"

Also run from command line:

  kldload dtraceall

Now we will install DtraceToolkit from FreeBSD Ports:

  cd /usr/ports/sysutils/DTraceToolkit
  make install clean



2. Profiling FreeBSD with DTrace

Then we wil try two scripts from DTraceToolkit that works with yet incomplete version of DTrace on FreeBSD:

  /usr/local/bin/hotkernel
  /usr/local/bin/procsystime

  /usr/local/bin/hotkernel -m         # will display count for kernel modules only

An output of hotkernel script will look like (after you press CTRL+C to exit sampling):
hotkernel
# hotkernel
Sampling... Hit Ctrl-C to end.
^C
FUNCTION                                                COUNT   PCNT
kernel`copyout                                              1   0.0%
i915.ko`i915_driver_irq_handler                             1   0.0%
kernel`trap                                                 1   0.0%
kernel`copyin                                               1   0.0%
kernel`pmap_clear_modify                                    1   0.0%
kernel`_mtx_lock_flags                                      1   0.0%
kernel`sopoll_generic                                       1   0.0%
kernel`0xffffffff80                                         1   0.0%
kernel`_mtx_lock_sleep                                      2   0.0%
kernel`free                                                 2   0.0%
kernel`dev_relthread                                        2   0.0%
kernel`bcopy                                                2   0.0%
i915.ko`0xffffffff8                                         3   0.0%
kernel`spinlock_exit                                        7   0.1%
kernel`sched_idletd                                       424   5.4%
kernel`cpu_idle_mwait                                     905  11.5%
kernel`acpi_cpu_c1                                       6522  82.8%


An output of hotkernel -m will look like:


hotkernel -m
# hotkernel -m
Sampling... Hit Ctrl-C to end.
^C
MODULE                                                  COUNT   PCNT
geom_eli.ko                                                 1   0.0%
dtrace.ko                                                   1   0.0%
pf.ko                                                       1   0.0%
drm.ko                                                      2   0.0%
zfs.ko                                                      2   0.0%
i915.ko                                                    17   0.1%
crypto.ko                                                 174   0.9%
kernel                                                  18661  99.0%


An output of procsystime script will look like this:

procsystime
# procsystime
Tracing... Hit Ctrl-C to end...
dtrace: 238 dynamic variable drops with non-empty dirty list
^C
dtrace: 5669 dynamic variable drops with non-empty dirty list

Elapsed Times for all processes,

         SYSCALL          TIME (ns)
          kqueue               3168
       sigreturn               5346
       sigaction               6323
       getfsstat               7821
       ftruncate               8778
            mmap               9978
           wait4              10377
         connect              13155
           fstat              14892
            stat              15866
          socket              19430
           lseek              20447
          getpid              23192
          sendto              27960
           fcntl              39899
           close              62139
       setitimer              72591
            open             150226
        __sysctl             157164
     sigprocmask             418110
          writev             479019
           write             603059
    gettimeofday             923483
            read            4955931
   clock_gettime            5105779
           ioctl            6607093
          select         4331555478
        _umtx_op         6690992675
            poll        11690538141


List open files by FreeBSD processes, right when the files are opened:

  dtrace -n 'syscall::open*:entry { printf("%s %s",execname,copyinstr(arg0)); }'

3. Analyzing PHP Code With DTrace

As of PHP 5.4.x which is in Ports already you can enable support for DTrace. Just check DTRACE when running:

  cd /usr/ports/lang/php5
  make config


Then recompile PHP:

  make clean
  make; make deinstall; make reinstall


If you do not have PHP 5.4.x, just run csup on ports first.

Now we have PHP with DTrace support. We will make use of some scripts from DTraceToolkit to analyze our PHP scripts.

Now look at PHP code example from DTraceToolkit:

  cat /usr/local/share/DTraceToolkit/Code/Php/func_abc.php

Copy it to your web server visible directory:

  cp /usr/local/share/DTraceToolkit/Code/Php/func_abc.php /usr/local/www/data/

Then before running from your browser launch a profiling script from DTraceToolkit:

  /usr/local/share/DTraceToolkit/Php/php_cputime.d

Then, load func_abc.php in your browser by accessing:

  http://localhost/func_abc.php          # or http://YOUR_IP/func_abc.php

Now after the page was loaded and you've seen: Function A Function B Function C in your browser, press CTRL + C in your terminal where you've run php_cputime.d script and you will see the number of times every function was called and time spent in every function:

/usr/local/share/DTraceToolkit/Php/php_cputime.d # tracing func_abc.php
# /usr/local/share/DTraceToolkit/Php/php_cputime.d
Tracing... Hit Ctrl-C to end.
^C

Count,
   FILE                 TYPE       NAME                                COUNT
   test.php             func       func_a                                  1
   test.php             func       func_b                                  1
   test.php             func       func_c                                  1
   -                    total      -                                       3

Exclusive function on-CPU times (us),
   FILE                 TYPE       NAME                                TOTAL
   test.php             func       func_c                                 27
   test.php             func       func_b                                 40
   test.php             func       func_a                                164
   -                    total      -                                     232

Inclusive function on-CPU times (us),
   FILE                 TYPE       NAME                                TOTAL
   test.php             func       func_c                                 27
   test.php             func       func_b                                 67
   test.php             func       func_a                                232


If we want to see only functions right when they are called we can run the following inliner:

  dtrace -n function-entry'{ printf("calling %s() from %s -> line: %d\n", copyinstr(arg0), copyinstr(arg1), arg2) }' -q

4. Analyzing C Code With DTrace

We will write a simple C program that make use of two functions, one that computes sum of two integers and one that computes substraction of two numbers. Then we will analyze the program with DTrace.

So our C code is:

example1.c
#include <stdio.h>

int sum(int a, int b);
int dif(int m, int n);

int main(void) {
    int a = 100, b = 200, c, d, e, i, j = 2;

    c = sum(a,b);
   
   
    for(i=1; i<4;i++ ) {
        d = sum(i,a);
        e = dif(d,j);
    }

    printf("a = %d\nb = %d\nc = %d\nd = %d\ne = %d\n\n", a, b, c, d, e);
}

int sum(int a, int b) {
    return a + b;
}

int dif(int m, int n) {
    return m - n;
}


We will compile the app with:

  gcc example1.c -o example1

Running example1.c we will get the following output:

  # ./example1
a = 100
b = 200
c = 300
d = 103
e = 101


What we can do with DTrace userland? Well let's see few usefull inliners (running a dtrace simple script from command line):

  dtrace -n 'pid$target:example1:sum:return { trace(arg1); }' -c ./example1

CPU     ID                    FUNCTION:NAME
  1  43778                       sum:return               300
  1  43778                       sum:return               101
  1  43778                       sum:return               102
  1  43778                       sum:return               103

So using this inliner we can see the return value of every sum() call.

Let's see return values for dif() function call:

  dtrace -n 'pid$target:example1:dif:return { trace(arg1); }' -c ./example1

CPU     ID                    FUNCTION:NAME
  1  43779                       dif:return                99
  1  43779                       dif:return               100
  1  43779                       dif:return               101


We can even see the memory allocated for every function call. To see that for our dif() function run:

  dtrace -n 'pid$target:example1:dif:return { ustack() }' -c ./example1

we will get:

memory allocated for diff function
CPU     ID                    FUNCTION:NAME
  2  43780                       dif:return
              example1`dif+0x14
              example1`_start+0x8e
              ld-elf.so.1`0x80063a000

  2  43780                       dif:return
              example1`dif+0x14
              example1`_start+0x8e
              ld-elf.so.1`0x80063a000

  2  43780                       dif:return
              example1`dif+0x14
              example1`_start+0x8e
              ld-elf.so.1`0x80063a000

If we want to see the return offset and also the return value for our dif() function we will run:

  dtrace -n 'pid$target:example1:dif:return { printf("arg0 = %d, arg1 = %d", arg0, arg1); }' -c ./example1

If we want to see how many times our sum() function is called we run:

  dtrace -n 'pid$target:example1:sum:return { @[probefunc] = count(); }' -c ./example1

We can also see the order in which function sum() and dif() are called:

  dtrace -n 'pid$target:example1:sum:return, pid$target:example1:dif:return' -c ./example1

If we want to see which functions are called most, sorted by calls we'll run:

  dtrace -n 'pid$target:example1:sum:return, pid$target:example1:dif:return { @[probefunc] = count (); }' -c ./example1

We can also see at the same time calls and returns using -F parameter of DTrace which place an arrow in front of function with sense depending on call entry or return of function:

  dtrace -Fn 'pid$target:example1:sum:entry, pid$target:example1:sum:return, pid$target:example1:dif:entry, pid$target:example1:dif:return' -c ./example1

In this case the output would be:

CPU FUNCTION                                
  2  -> sum                                  
  2  <- sum                                  
  2  -> sum                                  
  2  <- sum                                  
  2  -> dif                                  
  2  <- dif                                  
  2  -> sum                                  
  2  <- sum                                  
  2  -> dif                                  
  2  <- dif                                  
  2  -> sum                                  
  2  <- sum                                  
  2  -> dif                                  
  2  <- dif

If we want to list providers for a function we will run:

  dtrace -ln 'pid$target::dif:' -c ./example1

which in this case will list return and entry providers.

If we want to see available providers from libc library (and use them to analyze our file) we run:

  dtrace -ln 'pid$target:libc*::' -c ./example1


If we want to see which functions are called and their order we can use the following D script:

ctrace.d
pid$target:example1:main:entry {
}

pid$target:example1:sum:entry {
}

pid$target:example1:dif:entry {
}


To use the script run:

  dtrace -s ctrace.d -c ./example1

We will get:

CPU     ID                    FUNCTION:NAME
  3  43848                       main:entry
  3  43849                        sum:entry
  3  43849                        sum:entry
  3  43850                        dif:entry
  3  43849                        sum:entry
  3  43850                        dif:entry
  3  43849                        sum:entry
  3  43850                        dif:entry

You notice the order in which functions are called.

Or we can use a nice indentation:

  dtrace -Fs ctrace.d -c ./example1

We will get:

CPU FUNCTION                                
  0  -> main                                 
  0    -> sum                                
  0      -> sum                              
  0        -> dif                            
  0          -> sum                          
  0            -> dif                        
  0              -> sum                      
  0                -> dif

This looks ok but we want to also see return functions. So we will add return to our ctrace.d script:

ctrace2.d
pid$target:example1:main:entry {
}

pid$target:example1:sum:entry {
}

pid$target:example1:dif:entry {
}

pid$target:example1:main:return {
}

pid$target:example1:sum:return {
}

pid$target:example1:dif:return {
}


Now by running:

  dtrace -Fs ctrace2.d -c ./example1

we will get the returns too (notice the direction indicated by arrow which is  different when calling a function from when the function returns):

CPU FUNCTION                                
  2  -> main                                 
  2    -> sum                                
  2    <- sum                                
  2    -> sum                                
  2    <- sum                                
  2    -> dif                                
  2    <- dif                                
  2    -> sum                                
  2    <- sum                                
  2    -> dif                                
  2    <- dif                                
  2    -> sum                                
  2    <- sum                                
  2    -> dif                                
  2    <- dif                                
  2  <- main


5. Analyzing C++ Code With DTrace

DTracing C++ is a little bit tricky. For start we will use a simple D script to trace syscalls made by our C++ example.

So let's create a simple script called cpptrace.d:

cpptrace.d
syscall:::entry
/pid == $target/
{
     @[probefunc] = count()
}


To trace our C++ program we will run:

  dtrace -s cpptrace.d -c ./mainapp

where mainapp is our binary compiled from our C++ code. So we will get:

dtrace result of syscalls made by our app
break                                                             1
  exit                                                              1
  fstat                                                             1
  ioctl                                                             1
  issetugid                                                         1
  madvise                                                           1
  munmap                                                            1
  readlink                                                          1
  mmap                                                              2
  sigprocmask                                                      10
  write

You will notice that using this script we only see syscalls made from to the system and not our objects.


Last Updated ( Wednesday, 08 August 2012 )
 
< Prev   Next >

Other BSD Systems

OpenBSD

Misc

Solaris

Polls

Best BSD firewall?