I originally posted this at http://blogs.sun.com/brendan/entry/colortrace.
I was recently asked to give a very short but important DTrace demonstration to a wide audience, where I would only have time to run and discuss one script. It is a tough choice, there are so many to pick from, including the 100+ scripts and oneliners in my DTraceToolkit. Also, a short text-based demo may not convey the incredible power of DTrace – if you aren't paying attention it may look like just another tool. DTrace is far more than that.
What a great excuse to use some color escape sequences (yes, I've wanted to do this since I started writing the DTraceToolkit). With a colorized output it won't look like just another tool, and I can draw appropriate attention to a key DTrace feature.
I wrote colortrace.d (or colourtrace.d, for readers from the Commonwealth), which prints a flow indented trace of function entrys and returns for the entire softwark stack. Different layers of the softwark stack have been colorized:
- blue - application functions
- green - library functions
- violet - system calls
- red - kernel functions
I added a column to print delta times in nanoseconds, to illustrate that we can measure whatever times we want. When Adam previously performed a similar demonstration, he added a color for a Java function layer.
Here I run colortrace.d on a bash shell, and while it is running I pressed the letter "t" in bash:
# ./colortrace.d -p 101695 DELTA(ns) TYPE FUNCTION 120805042 syscall <- read 34461 libc.so.1 <- _read 13474 libc.so.1 <- read 8387 bash <- rl_getc 12899 bash <- rl_read_key 10044 bash -> _rl_dispatch 11760 bash -> _rl_dispatch_subseq 7189 bash -> rl_insert 7020 bash -> _rl_insert_char 6777 bash -> _rl_any_typein 8922 bash <- _rl_any_typein 7489 bash -> rl_insert_text 9230 libc.so.1 -> strlen 12040 libc.so.1 <- strlen 7362 libc.so.1 -> strncpy 6956 libc.so.1 <- strncpy 6996 bash <- rl_insert_text 7095 bash <- _rl_insert_char 6069 bash <- rl_insert 8117 bash <- _rl_dispatch_subseq 6484 bash <- _rl_dispatch 6992 bash -> rl_redisplay 5764 libc.so.1 -> strlen 6577 libc.so.1 <- strlen 5356 libc.so.1 -> strncpy 6249 libc.so.1 <- strncpy 6992 libc.so.1 -> memset 7572 libc.so.1 <- memset 7749 libc.so.1 -> strlen 6118 libc.so.1 <- strlen 6627 bash -> _rl_move_cursor_relative 6573 bash <- _rl_move_cursor_relative 7533 bash -> _rl_output_some_chars 7458 libc.so.1 -> fwrite 6335 libc.so.1 -> _fwrite_unlocked 7085 libc.so.1 -> _realbufend 6167 libc.so.1 -> getxfdat 6250 libc.so.1 <- getxfdat 6490 libc.so.1 <- _realbufend 6306 libc.so.1 <- _fwrite_unlocked 6115 libc.so.1 <- fwrite 6488 bash <- _rl_output_some_chars 7628 libc.so.1 -> fflush 6317 libc.so.1 -> _fflush_u 6407 libc.so.1 -> _xflsbuf 5046 libc.so.1 -> _realbufend 52132 libc.so.1 -> getxfdat 5178 libc.so.1 <- getxfdat 5480 libc.so.1 <- _realbufend 7046 libc.so.1 -> _write 29263 syscall -> write 12044 kernel -> write32 9820 kernel -> write 5170 kernel -> getf 5514 kernel -> set_active_fd 5643 kernel <- set_active_fd 10803 kernel <- getf 7063 kernel -> nbl_need_check 5365 kernel <- nbl_need_check 6075 kernel -> fop_rwlock 5619 kernel -> fs_rwlock 4939 kernel <- fs_rwlock 5117 kernel <- fop_rwlock 5819 kernel -> fop_write 5389 kernel -> spec_write 6382 kernel -> smark 5471 kernel -> gethrestime_sec 5174 kernel -> gethrestime 5159 kernel -> pc_gethrestime 4724 kernel -> gethrtime 4923 kernel -> tsc_gethrtime 4831 kernel <- tsc_gethrtime 4875 kernel <- gethrtime 5240 kernel <- pc_gethrestime 5215 kernel <- gethrestime 5368 kernel <- gethrestime_sec 5710 kernel <- smark 5656 kernel -> strwrite 5529 kernel -> strwrite_common 5543 kernel -> straccess 4976 kernel -> mutex_owned 4761 kernel <- mutex_owned 5611 kernel <- straccess 6066 kernel -> strput 4713 kernel -> mutex_owned 4705 kernel <- mutex_owned 5836 kernel -> canputnext 6037 kernel <- canputnext 6160 kernel -> strmakedata 5542 kernel -> allocb_cred 5513 kernel -> allocb 4982 kernel -> kmem_cache_alloc 5522 kernel -> kmem_cache_alloc_debug 5185 kernel -> verify_and_copy_pattern 5054 kernel <- verify_and_copy_pattern 6464 kernel -> dblk_constructor 4853 kernel -> kmem_cache_alloc 4696 kernel -> kmem_cache_alloc_debug 5188 kernel -> verify_and_copy_pattern 4707 kernel <- verify_and_copy_pattern 5153 kernel -> gethrtime 4843 kernel -> tsc_gethrtime 4587 kernel <- tsc_gethrtime 4836 kernel <- gethrtime 5133 kernel -> getpcstack 4742 kernel <- getpcstack 4849 kernel -> kmem_log_enter 5100 kernel <- kmem_log_enter 5047 kernel <- kmem_cache_alloc_debug 5262 kernel <- kmem_cache_alloc 5773 kernel <- dblk_constructor 4970 kernel -> gethrtime 4610 kernel -> tsc_gethrtime 4504 kernel <- tsc_gethrtime 4975 kernel <- gethrtime 4906 kernel -> getpcstack 4534 kernel <- getpcstack 4991 kernel -> kmem_log_enter 4760 kernel <- kmem_log_enter 4740 kernel <- kmem_cache_alloc_debug 5060 kernel <- kmem_cache_alloc 5642 kernel <- allocb 5394 kernel -> crhold 5467 kernel <- crhold 5435 kernel <- allocb_cred 5531 kernel -> uiomove 5663 kernel -> xcopyin_nta 4871 kernel <- kcopy 5012 kernel <- uiomove 5939 kernel <- strmakedata 5853 kernel -> stream_willservice 5280 kernel <- stream_willservice 6012 kernel -> putnext 4937 kernel -> mutex_owned 4680 kernel <- mutex_owned 5381 kernel -> mutex_owned 4694 kernel <- mutex_owned 6160 kernel -> ttcompatwput 5016 kernel -> putnext 4776 kernel -> mutex_owned 4523 kernel <- mutex_owned 4981 kernel -> mutex_owned 4661 kernel <- mutex_owned 5683 kernel -> ldtermwput 5704 kernel -> bcanputnext 5815 kernel -> claimstr 5410 kernel <- claimstr 5598 kernel -> bcanput 6099 kernel <- bcanput 5602 kernel -> releasestr 5013 kernel -> cv_broadcast 5708 kernel -> getpcstack 4690 kernel <- getpcstack 5167 kernel -> apic_intr_enter 5135 kernel -> psm_get_cpu_id 4733 kernel <- psm_get_cpu_id 5540 kernel -> psm_get_cpu_id 4531 kernel <- psm_get_cpu_id 5295 kernel -> psm_get_cpu_id 4503 kernel <- psm_get_cpu_id 4917 kernel <- apic_intr_enter 5296 kernel -> hilevel_intr_prolog 10448 kernel -> apic_intr_exit 5041 kernel -> psm_get_cpu_id 4481 kernel <- psm_get_cpu_id 5119 kernel <- apic_intr_exit 5333 kernel <- hilevel_intr_epilog 5143 kernel <- cv_broadcast 5124 kernel <- releasestr 5350 kernel <- bcanputnext 5851 kernel -> ldtermwmsg 6826 kernel -> msgdsize 5427 kernel <- msgdsize 5652 kernel -> ldterm_output_msg 4981 kernel -> allocb 4817 kernel -> kmem_cache_alloc 5224 kernel -> kmem_cache_alloc_debug 5270 kernel -> verify_and_copy_pattern 5033 kernel <- verify_and_copy_pattern 5303 kernel -> dblk_constructor 4692 kernel -> kmem_cache_alloc 4928 kernel -> kmem_cache_alloc_debug 5243 kernel -> getpcstack 4569 kernel <- getpcstack 5069 kernel -> apic_intr_enter 4830 kernel <- apic_intr_enter 4972 kernel -> hilevel_intr_prolog 40463 kernel -> apic_intr_exit 5107 kernel -> psm_get_cpu_id 4549 kernel <- psm_get_cpu_id 4995 kernel <- apic_intr_exit 5123 kernel <- hilevel_intr_epilog 5633 kernel -> verify_and_copy_pattern 4867 kernel <- verify_and_copy_pattern 5360 kernel -> gethrtime 4633 kernel -> tsc_gethrtime 4566 kernel <- tsc_gethrtime 4999 kernel <- gethrtime 4856 kernel -> getpcstack 4739 kernel <- getpcstack 5058 kernel -> kmem_log_enter 4818 kernel <- kmem_log_enter 4786 kernel <- kmem_cache_alloc_debug 5189 kernel <- kmem_cache_alloc 5063 kernel <- dblk_constructor 4939 kernel -> gethrtime 4694 kernel -> tsc_gethrtime 4706 kernel <- tsc_gethrtime 4749 kernel <- gethrtime 4852 kernel -> getpcstack 4780 kernel <- getpcstack 4838 kernel -> kmem_log_enter 4669 kernel <- kmem_log_enter 5068 kernel <- kmem_cache_alloc_debug 4970 kernel <- kmem_cache_alloc 4925 kernel <- allocb 6118 kernel -> movtuc 6115 kernel <- movtuc 5246 kernel -> freeb 5098 kernel -> dblk_lastfree 5180 kernel -> crfree 5155 kernel <- crfree 5292 kernel -> kmem_cache_free 4946 kernel -> kmem_cache_free_debug 4814 kernel -> kmem_log_enter 4880 kernel <- kmem_log_enter 4998 kernel -> gethrtime 4598 kernel -> tsc_gethrtime 4653 kernel <- tsc_gethrtime 4949 kernel <- gethrtime 4841 kernel -> getpcstack 4515 kernel <- getpcstack 5073 kernel -> kmem_log_enter 4595 kernel <- kmem_log_enter 5352 kernel -> dblk_destructor 5061 kernel -> kmem_cache_free 4670 kernel -> kmem_cache_free_debug 4721 kernel -> kmem_log_enter 4863 kernel <- kmem_log_enter 4914 kernel -> gethrtime 4555 kernel -> tsc_gethrtime 4853 kernel <- tsc_gethrtime 4761 kernel <- gethrtime 4825 kernel -> getpcstack 4714 kernel <- getpcstack 4888 kernel -> kmem_log_enter 4580 kernel <- kmem_log_enter 5219 kernel -> copy_pattern 4980 kernel <- copy_pattern 4978 kernel <- kmem_cache_free_debug 5806 kernel <- kmem_cache_free 4964 kernel <- dblk_destructor 4893 kernel -> copy_pattern 4530 kernel <- copy_pattern 5010 kernel <- kmem_cache_free_debug 4931 kernel <- kmem_cache_free 5002 kernel <- dblk_lastfree 5293 kernel <- freeb 5397 kernel <- ldterm_output_msg 5285 kernel -> msgdsize 4840 kernel <- msgdsize 6236 kernel -> drv_setparm 5415 kernel <- drv_setparm 5231 kernel -> putnext 4820 kernel -> mutex_owned 4617 kernel <- mutex_owned 5286 kernel -> mutex_owned 4526 kernel <- mutex_owned 5851 kernel -> ptemwput 5325 kernel -> bcanputnext 4759 kernel -> claimstr 4458 kernel <- claimstr 5060 kernel -> bcanput 5074 kernel <- bcanput 4841 kernel -> releasestr 4663 kernel -> cv_broadcast 4771 kernel <- cv_broadcast 4773 kernel <- releasestr 4758 kernel <- bcanputnext 5838 kernel -> ptemwmsg 5242 kernel -> putnext 4584 kernel -> mutex_owned 4811 kernel <- mutex_owned 5169 kernel -> mutex_owned 4473 kernel <- mutex_owned 6277 kernel -> ptswput 5691 kernel -> putq 6413 kernel -> qenable_locked 5001 kernel -> mutex_owned 4522 kernel <- mutex_owned 5765 kernel <- qenable_locked 5307 kernel -> mutex_owned 4553 kernel <- mutex_owned 5277 kernel <- putq 5303 kernel -> cv_broadcast 4546 kernel <- cv_broadcast 5789 kernel <- ptswput 4863 kernel -> mutex_owned 4681 kernel <- mutex_owned 4865 kernel -> mutex_owned 4482 kernel <- mutex_owned 5909 kernel <- putnext 5438 kernel <- ptemwmsg 5338 kernel <- ptemwput 5258 kernel -> mutex_owned 4592 kernel <- mutex_owned 4857 kernel -> mutex_owned 4719 kernel <- mutex_owned 4820 kernel <- putnext 4941 kernel <- ldtermwmsg 5600 kernel <- ldtermwput 4921 kernel -> mutex_owned 4483 kernel <- mutex_owned 5049 kernel -> mutex_owned 4495 kernel <- mutex_owned 4763 kernel <- putnext 5565 kernel <- ttcompatwput 4934 kernel -> mutex_owned 4543 kernel <- mutex_owned 4859 kernel -> mutex_owned 4682 kernel <- mutex_owned 4805 kernel <- putnext 5706 kernel -> stream_runservice 5130 kernel -> mutex_owned 4505 kernel <- mutex_owned 6436 kernel -> queue_service 5501 kernel -> runservice 5329 kernel -> entersq 5686 kernel <- entersq 6490 kernel -> ptswsrv 4974 kernel -> getq 4688 kernel -> getq_noenab 4922 kernel <- getq_noenab 5330 kernel <- getq 4888 kernel -> bcanputnext 5246 kernel -> getpcstack 4641 kernel <- getpcstack 5019 kernel -> apic_intr_enter 5023 kernel <- apic_intr_enter 4991 kernel -> hilevel_intr_prolog 40252 kernel -> apic_intr_exit 4984 kernel -> psm_get_cpu_id 4831 kernel <- psm_get_cpu_id 5005 kernel <- apic_intr_exit 4903 kernel <- hilevel_intr_epilog 5265 kernel -> claimstr 5086 kernel <- claimstr 5119 kernel -> bcanput 5071 kernel <- bcanput 4889 kernel -> releasestr 4679 kernel -> cv_broadcast 4965 kernel <- cv_broadcast 4878 kernel <- releasestr 4769 kernel <- bcanputnext 5142 kernel -> putnext 4871 kernel -> mutex_owned 4567 kernel <- mutex_owned 5209 kernel -> mutex_owned 4526 kernel <- mutex_owned 6066 kernel -> strrput 6220 kernel -> qclaimed 5323 kernel <- qclaimed 5297 kernel -> mutex_owned 4483 kernel <- mutex_owned 5265 kernel -> putq 4667 kernel -> qenable_locked 4592 kernel -> mutex_owned 4739 kernel <- mutex_owned 4880 kernel <- qenable_locked 4880 kernel -> mutex_owned 4659 kernel <- mutex_owned 4864 kernel <- putq 4883 kernel -> mutex_owned 4690 kernel <- mutex_owned 5938 kernel -> pollwakeup 6412 kernel -> pollnotify 4819 kernel -> mutex_owned 4517 kernel <- mutex_owned 5862 kernel -> cv_signal 5412 kernel -> disp_lock_enter 5260 kernel -> lock_set_spl 4898 kernel <- splx 5298 kernel <- lock_set_spl 5513 kernel <- disp_lock_enter 6097 kernel -> sleepq_wakeone_chan 5878 kernel -> sleepq_unlink 5882 kernel <- sleepq_unlink 6150 kernel -> ts_wakeup 6835 kernel -> setbackdq 4878 kernel -> gethrtime_unscaled 4767 kernel -> tsc_gethrtimeunscaled 4768 kernel <- tsc_gethrtimeunscaled 5305 kernel <- gethrtime_unscaled 5345 kernel -> cpu_update_pct 4993 kernel -> scalehrtime 5250 kernel -> tsc_scalehrtime 4980 kernel <- tsc_scalehrtime 5317 kernel <- scalehrtime 5715 kernel -> cpu_decay 5451 kernel -> exp_x 4760 kernel <- exp_x 5225 kernel <- cpu_decay 5253 kernel <- cpu_update_pct 6435 kernel -> cpu_choose 5793 kernel -> disp_lowpri_cpu 6383 kernel <- disp_lowpri_cpu 5624 kernel <- cpu_choose 6285 kernel -> disp_lock_enter_high 5746 kernel <- disp_lock_enter_high 6425 kernel -> cpu_resched 6065 kernel -> poke_cpu 5701 kernel -> apic_send_ipi 5626 kernel -> get_apic_cmd1 5355 kernel <- get_apic_cmd1 5742 kernel <- apic_send_ipi 5167 kernel <- poke_cpu 5254 kernel <- cpu_resched 6656 kernel -> cpu_wakeup 5605 kernel <- cpu_wakeup 5194 kernel <- setbackdq 5575 kernel <- ts_wakeup 5068 kernel -> disp_lock_exit_high 4899 kernel <- disp_lock_exit_high 5750 kernel <- sleepq_wakeone_chan 5206 kernel -> disp_lock_exit 4893 kernel <- splx 5125 kernel <- disp_lock_exit 5716 kernel <- cv_signal 5366 kernel <- pollnotify 5885 kernel <- pollwakeup 5684 kernel <- strrput 5051 kernel -> mutex_owned 4614 kernel <- mutex_owned 5096 kernel -> mutex_owned 4530 kernel <- mutex_owned 4840 kernel <- putnext 5045 kernel -> getq 4681 kernel -> getq_noenab 4647 kernel <- getq_noenab 5013 kernel <- getq 5021 kernel -> cv_broadcast 4747 kernel <- cv_broadcast 5865 kernel <- ptswsrv 6120 kernel -> leavesq 5334 kernel <- leavesq 5146 kernel -> cv_broadcast 4552 kernel <- cv_broadcast 6149 kernel <- runservice 5560 kernel <- queue_service 5922 kernel <- stream_runservice 5748 kernel <- strput 6336 kernel <- strwrite_common 5398 kernel <- strwrite 5481 kernel <- spec_write 5895 kernel <- fop_write 6266 kernel -> fop_rwunlock 5432 kernel -> fs_rwunlock 5318 kernel <- fs_rwunlock 5455 kernel <- fop_rwunlock 5430 kernel -> releasef 5303 kernel -> clear_active_fd 5447 kernel <- clear_active_fd 5098 kernel -> cv_broadcast 4594 kernel <- cv_broadcast 5455 kernel <- releasef 5460 kernel <- write 6000 kernel <- write32 6729 syscall <- write 28571 libc.so.1 <- _write 10001 libc.so.1 <- _xflsbuf 6926 libc.so.1 <- _fflush_u 6176 libc.so.1 <- fflush 7718 bash <- rl_redisplay 54421 bash <- readline_internal_char 8667 bash -> readline_internal_char 11003 libc.so.1 -> sigsetjmp 11960 libc.so.1 -> __csigsetjmp 6691 libc.so.1 <- __csigsetjmp 6367 libc.so.1 <- sigsetjmp 6954 bash -> _rl_init_argument 7834 bash <- _rl_init_argument 7598 bash -> rl_read_key 7065 bash -> _rl_next_macro_key 6371 bash <- _rl_next_macro_key 6299 bash -> rl_getc 6818 libc.so.1 -> fileno 6908 libc.so.1 <- fileno 6850 libc.so.1 -> read 7184 libc.so.1 -> _read 28550 syscall -> read 9637 kernel -> read32 6043 kernel -> read 5360 kernel -> getf 5147 kernel -> set_active_fd 4994 kernel <- set_active_fd 6298 kernel <- getf 5840 kernel -> nbl_need_check 4779 kernel <- nbl_need_check 5503 kernel -> fop_rwlock 5009 kernel -> fs_rwlock 4558 kernel <- fs_rwlock 4867 kernel <- fop_rwlock 5894 kernel -> fop_read 5403 kernel -> spec_read 5469 kernel -> smark 5361 kernel -> gethrestime_sec 4852 kernel -> gethrestime 5152 kernel -> pc_gethrestime 4890 kernel -> gethrtime 4720 kernel -> tsc_gethrtime 4807 kernel <- tsc_gethrtime 5195 kernel <- gethrtime 5355 kernel <- pc_gethrestime 5085 kernel <- gethrestime 4978 kernel <- gethrestime_sec 5017 kernel <- smark 5537 kernel -> strread 5804 kernel -> straccess 4817 kernel -> mutex_owned 4734 kernel <- mutex_owned 5419 kernel <- straccess 5344 kernel -> mutex_owned 4534 kernel <- mutex_owned 5591 kernel -> strget 4831 kernel -> mutex_owned 4535 kernel <- mutex_owned 4874 kernel -> mutex_owned 4675 kernel <- mutex_owned 5018 kernel -> getq_noenab 4821 kernel <- getq_noenab 5847 kernel <- strget 4908 kernel -> mutex_owned 4584 kernel <- mutex_owned 5557 kernel -> qbackenable 4978 kernel <- qbackenable 6433 kernel -> strwaitq 4917 kernel -> mutex_owned 4469 kernel <- mutex_owned 6029 kernel -> allocb_wait 5397 kernel -> allocb 4903 kernel -> kmem_cache_alloc 5236 kernel -> kmem_cache_alloc_debug 5242 kernel -> verify_and_copy_pattern 5294 kernel <- verify_and_copy_pattern 5744 kernel -> dblk_constructor ... 200 lines truncated ... ^C
There is a lot of output as flow passes from the user program to the kernel and back again, all of which is traceable.
If you were familiar with previous state of the art tracing and debugging tools, then DTrace has just raised the bar. Previously, truss (or strace) by default prints some of the lines you see above in violet; apptrace and truss -u the lines in green; truss -ua.out the lines in blue; software debuggers the lines in blue and green; and TNF could print a small nuber of the red lines. DTrace sees all.
DTrace can also print user level instructions, which I could have printed above in orange. If I had, the output would have been be many times longer. Perhaps more useful would be to print the higher level kernel events which DTrace can observe, which can instrument events within functions. Other possible enhancements would be to print function entry and return arguments, and to walk user and kernel data structures to print members of interest.
The colortrace.d script which generated the above output is as follows:
#!/usr/sbin/dtrace -s
/*
* colortrace.d - Trace function, syscall and kernel events, in color.
* Written for DTrace (Solaris 10 3/05).
*
* 26-Jan-2005, ver 1.00
*
* USAGE: colortrace.d -p PID
*
* This script demonstrates some key DTrace features: the capability
* to observe function calls across the entire software stack, and
* to measure timestamps for any event. colortrace.d shows the function
* flow of a process, along with delta times between lines of output.
*
* NOTES: Run this on something small, such as a shell. If you are on
* a multi-CPU server, pbind the process to a single CPU else the output
* may by shuffled.
*/
#pragma D option quiet
#pragma D option switchrate=10
/* see "man -s5 dtterm" for a color list */
inline string RED = "33[31;1m";
inline string BLUE = "33[34;1m";
inline string GREEN = "33[32;1m";
inline string VIOLET = "33[35;1m";
inline string OFF = "33[0m";
dtrace:::BEGIN
{
last = timestamp;
printf("%-12s %16s %s\n", "DELTA(ns)", "TYPE", "FUNCTION");
}
syscall:::entry
/pid == $target/
{
depth++;
printf("%-12d %16s %s%*s -> %s%s\n", timestamp - last, probeprov,
VIOLET, depth, " ", probefunc, OFF);
self->insyscall = 1;
last = timestamp;
}
syscall:::return
/pid == $target/
{
printf("%-12d %16s %s%*s <- %s%s\n", timestamp - last, probeprov,
VIOLET, depth, " ", probefunc, OFF);
depth = depth > 0 ? --depth : 0;
self->insyscall = 0;
last = timestamp;
}
fbt:::entry
/self->insyscall/
{
depth++;
printf("%-12d %16s %s%*s -> %s%s\n", timestamp - last, "kernel",
RED, depth, " ", probefunc, OFF);
last = timestamp;
}
fbt:::return
/self->insyscall/
{
printf("%-12d %16s %s%*s <- %s%s\n", timestamp - last, "kernel",
RED, depth, " ", probefunc, OFF);
depth = depth > 0 ? --depth : 0;
last = timestamp;
}
pid$target:a.out::entry
{
depth++;
printf("%-12d %16s %s%*s -> %s%s\n", timestamp - last, probemod,
BLUE, depth, " ", probefunc, OFF);
last = timestamp;
}
pid$target:a.out::return
{
printf("%-12d %16s %s%*s <- %s%s\n", timestamp - last, probemod,
BLUE, depth, " ", probefunc, OFF);
depth = depth > 0 ? --depth : 0;
last = timestamp;
}
pid$target:lib*::entry
{
depth++;
printf("%-12d %16s %s%*s -> %s%s\n", timestamp - last, probemod,
GREEN, depth, " ", probefunc, OFF);
last = timestamp;
}
pid$target:lib*::return
{
printf("%-12d %16s %s%*s <- %s%s\n", timestamp - last, probemod,
GREEN, depth, " ", probefunc, OFF);
depth = depth > 0 ? --depth : 0;
last = timestamp;
}
Once you pick up the syntax of DTrace programming (which is straightforward and based on C), you'll see that this is a trivial script. The version I demonstrated took minutes to write. I've spent a little more time on this version to make the output neater. A great place to start learning the syntax is the DTrace Guide.
To capture output for this blog entry, I changed the color escape sequences to print HTML font tags. Since the entire output of DTrace can be programmed, we could generate XML if needed.
The times printed in the left column are delta times from the previous event, which will help locate the source of latencys. It can take a little thought to comprehend what they really mean – a large value does not always mean that the named function to the right was slow. If needed, how these time measurements are taken can be customized by modifying the script.
While colortrace.d serves its purpose as a demonstration of DTrace observability, it doesn't actually represent a common use of DTrace. In practice, we use the filtering features of DTrace to only trace events of interest, and the aggregation features of DTrace to summarize data in useful ways.