Donnerstag März 31, 2005

DTrace for Beginners

When I started playing with DTrace I found this blog entry. DTrace sounded like a really cool tool. However, I have to admit that I was not able to follow the instructions in the blog entry. Either I'm too dumb, the DTrace syntax has changed since November 2004 or the blog entry contains typos. Whatever the reason for my failure was, I decided to try getting to the same results via reading the official DTrace documentation.

Since I'm not a DTrace expert (I'm a beginner myself) and since I haven't coded for a long time, my approach might not be optimal. Thus, don't take my examples as an official blue print for using DTrace. Nevertheless, I believe my experiences might be useful for someone.

Since I already figured out how DTrace works in general by reading the DTrace guide, I wanted to dig deeper into the topic by writing a few lines of C code myself. Thus, based on the article/blog entry mentioned above I wrote a very simple program that uses the sprintf function:


#include <stdio.h>

int main()
{

char *name = "John Smith";
char *street = "3400 Stevenson Blvd.";
char *city = "94538 Fremont, CA";
long phone = 510123456;
char address[80];
char buffer[80];

printf("Press ENTER to continue!\n\n");
gets(buffer);
sprintf(address, "%-20s | %-25s | %-25s | Phone: %-10ld", name, street, city, phone);
printf("Address:\n%s\n", address);

}

I copiled the code and started the binary. BTW, I included the gets function, so that I can grep for the process ID and call DTrace before the application continues and terminates. Here is the output of my little application:


# /usr/sfw/bin/gcc sprintf_test.c
# ./a.out
Press ENTER to continue!


Address:
John Smith | 3400 Stevenson Blvd. | 94538 Fremont, CA | Phone: 510123456
#

In parallel to calling my little sprintf application again and again in one terminal window, I played with DTrace in another terminal window. Here are the outputs of my tests:


# ps -ef | grep a.out root 763 705 0 12:09:30 pts/5 0:00 ./a.out
    root 765 706 0 12:09:39 pts/4 0:00 grep a.out
# dtrace -n pid763:::entry'{ @functioncalls[probefunc] = count(); }' dtrace: description 'pid763:::entry' matched 2895 probes
^C

  pthread_rwlock_unlock     1
  _fflush_u     1
  rwlock_lock     1
  rw_write_held     1
  rw_rdlock_impl     1
  pthread_rwlock_rdlock     1
  _fflush_u_iops     1
  fflush     1
  _cleanup     1
  libc_fini     1
  call_array     1
  call_fini     1
  visit     1
  dep_visit     1
  calloc     1
  atexit_fini     1
  _getfp     1
  _exithandle     1
  exit     1
  _write     1
  _xflsbuf     1
  memchr     1
  _flockget     1
  printf     1
  sprintf     1
  memccpy     1
  bind_one     2
  unused     2
  _ndoprnt     2
  malloc     2
  align     2
  split     2
  free     2
  defrag     2
  rwl_entry     2
  getxfdat     2
  _realbufend     2
  mutex_lock_impl     2
  mutex_lock     2
  sigon     2
  getbucketnum     3
  lfree     3
  ferror_unlocked     3
  mutex_unlock     3
  lmutex_unlock     3
  lmutex_lock     3
  strlen     4
  memset     4
  is_dep_init     7
  elf_hash     7
  elf_rtbndr     7
  elf_bndr     7
  lookup_sym     7
  load_completion     7
  is_dep_ready     8
  tsort     9
  enter     9
  _lwp_mutex_unlock     9
  rt_bind_guard     9
  rt_mutex_unlock     9
  fmap_setup     9
  _ti_bind_guard     9
  leave     9
  rt_mutex_lock     9
  _lwp_mutex_lock     9
  rd_event     9
  memcpy     10
  strcmp     12
  callable     14
  elf_find_sym     14
  rt_bind_clear     18
  _ti_bind_clear     18
# ps -ef | grep a.out root 767 705 0 12:10:16 pts/5 0:00 ./a.out
    root 769 706 0 12:11:00 pts/4 0:00 grep a.out
# dtrace -n pid767::printf:entry'{ @outputstring[copyinstr(arg0), copyinstr(arg1)] = count(); }'
dtrace: description 'pid767::printf:entry' matched 2 probes
^C

  Address:
%s
                                        John Smith | 3400 Stevenson Blvd. | 94538 Fremont, CA | Phone: 510123456 1
# ps -ef | grep a.out root 771 705 0 12:11:28 pts/5 0:00 ./a.out
    root 773 706 0 12:11:32 pts/4 0:00 grep a.out
# dtrace -n pid771::sprintf:entry'{ @formatstrings[copyinstr(arg1)] = count(); }' dtrace: description 'pid771::sprintf:entry' matched 2 probes
^C

  %-20s | %-25s | %-25s | Phone: %-10ld 1
#

To be honest, although I don't know if you can do the same thing on other operating system platforms, I'm pretty impressed by what you can do with DTrace. Currently I'm not writing code for my day-to-day job, but if I had to, I'm pretty sure I'd like to use a tool like DTrace. I slowly can understand why so many people seem to be excited about Solaris 10 and the DTrace feature.