Systems Performance 2nd Ed.



BPF Performance Tools book

Recent posts:
Blog index
About
RSS

Colortrace

29 Jan 2007

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.