1 OLS SystemTap ScriptFest Handout
   2 --------------------------------
   3 
   4 What is SystemTap?
   5 
   6 SystemTap provides a simple scripting interface to poke into, gather,
   7 visualize, analyze and rectify systemic problems on Linux. It provides a
   8 safe and flexible mechanism to dynamically instrument a Linux system
   9 without modifying source code, recompiling or rebooting.
  10 
  11 SystemTap includes a rich set of predefined probes (tapsets) for key
  12 areas of the Linux OS.  Additional probes can be easily defined as
  13 needed. Customized tapsets can help in understanding, debugging,
  14 monitoring, and tuning of applications and subsystems.
  15 
  16 SystemTap QuickLinks:
  17 ---------------------
  18 Homepage           :: http://sourceware.org/systemtap/ 
  19 Wiki               :: http://sourceware.org/systemtap/wiki
  20 Tutorial           :: http://sourceware.org/systemtap/tutorial/
  21 Language Reference :: http://sourceware.org/systemtap/langref/
  22 Using Markers      :: http://sourceware.org/systemtap/wiki/UsingMarkers
  23 FAQ                :: http://sourceware.org/systemtap/wiki/SystemTapFAQ
  24 Report Bugs        :: http://sourceware.org/systemtap/wiki/HowToReportBugs
  25 OLS2008 Handout    :: http://sourceware.org/systemtap/wiki/ScriptFest
  26 
  27 How to Set Up SystemTap on Fedora
  28 ---------------------------------
  29 
  30 yum install systemtap kernel-devel
  31 yum --enablerepo=fedora-debuginfo --enablerepo=updates-debuginfo install
  32 							kernel-debuginfo
  33 
  34 Instructions for installing SystemTap on other distros are available on
  35 the SystemTap wiki.
  36 Refer http://sourceware.org/systemtap/wiki/SystemtapOnUbuntu to find
  37 instructions for installing SystemTap on Ubuntu.
  38 
  39 Building SystemTap from the Latest Sources
  40 ------------------------------------------
  41 a. Download SystemTap 
  42   git clone git://sources.redhat.com/git/systemtap.git systemtap
  43  	OR
  44   git clone http://sources.redhat.com/git/systemtap.git systemtap
  45  	OR
  46   wget ftp://sources.redhat.com/pub/systemtap/snapshots/latest.tar.bz2 
  47   tar jxf latest.tar.bz2 -C systemtap
  48 
  49 b. Download elfutils
  50  wget ftp://sources.redhat.com/pub/systemtap/elfutils/elfutils-<nnn>.tar.gz
  51  wget ftp://sources.redhat.com/pub/systemtap/elfutils/elfutils-portability.patch
  52  tar xzf elfutils-<nnn>.tar.gz
  53  cd elfutils-<nnn>
  54  patch -p1 < ../elfutils-portability.patch
  55  ELFUTILS_DIR=`pwd`
  56 
  57 c. Build and install 
  58 <Navigate to systemtap source directory.>
  59   ./configure --with-elfutils=$ELFUTILS_DIR
  60   make all check
  61 <This builds SystemTap and runs the testsuite. This takes several minutes.>
  62   make install (as root)
  63 
  64 Verifying SystemTap Installation
  65 ----------------------------------
  66 Run the following command as root:
  67   # stap -ve 'probe begin, kernel.function("do_fork") {log("Success!") exit()}'
  68 <stap should report 5 passes and print "Success!">
  69 
  70 Basics
  71 
  72 SystemTap scripts are written in an awk-like language.  Several sample
  73 scripts are shown later in this document.  A script specifies one or
  74 more events (probepoints) and the instrumentation code (handler) to be
  75 run when that event occurs.  SystemTap parses the script, pulls in
  76 referenced code from the various tapsets (script libraries), and
  77 consults debuginfo from the probed kernel and/or applications to
  78 generate a loadable kernel module.  SystemTap loads the module, which
  79 runs the designated handler each time an event of interest occurs.
  80 Output is directed to stdout of the stap command.  At session close,
  81 SystemTap unloads the module.
  82 
  83 SystemTap has built-in safety features.  Handler routines cannot run for
  84 too long, cannot allocate memory, and cannot perform unsafe operations.
  85 Locking is employed to ensure correctness. Resource limits can be
  86 adjusted using stap -D flags.  Guru mode trades off some safety features
  87 for more power. Scripts run in Guru mode can modify kernel data.
  88 
  89 Refer to the SystemTap Tutorial and the Language Reference guide for
  90 more details.
  91 
  92 Probes associate abstract events with statement blocks (handlers).
  93 Here are some commonly used types of probes.
  94 
  95 probe kernel.function("funcname")
  96 probe kernel.function("funcname").return
  97 probe module("modname").function("funcname")
  98 probe module("modname").function("funcname").return
  99 probe kernel.statement("funcname@pathname:lineno")
 100 probe kernel.statement(0xc0443322).absolute
 101 probe begin
 102 probe end
 103 probe timer.ms(500)
 104 [probe time.ms(5000) would be more clearly expressed as timer.sec(5)]
 105 probe timer.jiffies(N).randomize(M)
 106 
 107 Names of functions, modules, and files can contain wildcard characters
 108 to specify sets of related probepoints.
 109 
 110 Tapsets define auxiliary functions and probe "aliases."  An alias
 111 defines a probepoint and a set of values (e.g., function argument
 112 values) available to any script that uses that alias.  For example,
 113 syscall.read is an alias for kernel.function("sys_read"), and provides
 114 values such as fd and count.
 115 
 116 Variables can be integers, strings, associative arrays, or aggregates
 117 (explained below).  Each variable's type is inferred from its use.
 118 
 119 Comments can be shell-style, C++-style, or C-style.
 120 
 121 Operators use the same general syntax, semantics and precedence as in C
 122 and awk.
 123 
 124 SystemTap supports control-flow statements such as if-else, for, do,
 125 while, break, continue, foreach, next, and return.
 126 
 127 Arrays are implemented as fixed-size hash tables. Arrays are always
 128 global.
 129 
 130 Aggregates are used to collect statistics on numerical values.  Values
 131 are added to aggregates using the <<< operator.  Functions like @count,
 132 @sum, and @max can be used to report statistics from aggregate
 133 variables.
 134 
 135 Refer to the SystemTap Language Reference guide for more details.
 136 
 137 Help via Email/IRC
 138 ------------------
 139 For help with problems in SystemTap, you can send us an email at
 140 systemtap@sources.redhat.com, or join the Systemtap discussion
 141 at #systemtap on irc.freenode.net.
 142 
 143 Sample Scripts
 144 ------------------------------------------------------
 145 #! /usr/bin/env stap
 146 #
 147 # Trace entry and exit of all functions defined in kernel/sched.c.
 148 #
 149 probe begin {
 150   printf ("Collecting data... Type Ctrl-C to exit\n")
 151 }
 152 
 153 probe kernel.function("*@kernel/sched.c") {
 154   printf ("%s -> %s\n", thread_indent(1), probefunc())
 155 }
 156 probe kernel.function("*@kernel/sched.c").return {
 157   printf ("%s <- %s\n", thread_indent(-1), probefunc())
 158 }
 159 -------------------------------------------------------
 160 
 161 
 162 ---------------------------------------------------------
 163 #! /usr/bin/env stap
 164 
 165 # Using statistics and maps to examine kernel memory allocations
 166 
 167 global kmalloc
 168 
 169 probe kernel.function("__kmalloc") {
 170         kmalloc[execname()] <<< $size
 171 }
 172 
 173 # Exit after 10 seconds
 174 probe timer.ms(10000) { exit () }
 175 
 176 probe end {
 177         foreach (name in kmalloc) {
 178                 printf("Allocations for %s\n", name)
 179                 printf("Count:   %d allocations\n", @count(kmalloc[name]))
 180                 printf("Sum:     %d Kbytes\n", @sum(kmalloc[name])/1000)
 181                 printf("Average: %d bytes\n", @avg(kmalloc[name]))
 182                 printf("Min:     %d bytes\n", @min(kmalloc[name]))
 183                 printf("Max:     %d bytes\n", @max(kmalloc[name]))
 184                 print("\nAllocations by size in bytes\n")
 185                 print(@hist_log(kmalloc[name]))
 186                 printf("-------------------------------------------------------\n\n");
 187         }
 188 }
 189 ---------------------------------------------------------
 190 
 191 
 192 ---------------------------------------------------------
 193 #!/usr/bin/env stap
 194 
 195 # This is an example of profiling a specific command or pid.
 196 # It works by recording the time when a system call is entered
 197 # exited. 
 198 
 199 # Usage: prof.stp -c "top -n5"
 200 # Will start up "top" and after 5 iterations, will exit.
 201 #
 202 # Usage: prof.stp -x 3323
 203 # Will profile pid 3323 until it ^c is hit.
 204 #
 205 
 206 probe kernel.function("sys_*").call {
 207         if (target() == tid())
 208                 calltime[tid()] = gettimeofday_us()
 209 }
 210 
 211 probe kernel.function("sys_*").return {
 212         if (target() != tid())  next
 213         now = gettimeofday_us()  
 214         c = calltime[tid()]
 215         if (!c) next
 216         ttime[probefunc()] <<< now - c
 217         delete calltime[tid()]
 218 }
 219 
 220 probe end {
 221         printf("\n")
 222         foreach (x in ttime)
 223                 printf("%-20s\tcalls:%6d\tavg time (us):%5d\ttotal(us):%7d\n", 
 224                         x, @count(ttime[x]), @avg(ttime[x]), @sum(ttime[x]))
 225 }
 226 
 227 global calltime, ttime
 228 ---------------------------------------------------------
 229 
 230 ---------------------------------------------------------
 231 
 232 #! /usr/bin/env stap
 233 # rwtiming.stp
 234 #
 235 # This is a simple example to track the amount of time
 236 # spent doing reads and writes for the various programs running on the
 237 # system.
 238 
 239 probe begin { log("starting probe") }
 240 # Exit after 10 seconds
 241 probe timer.ms(10000) { exit () }
 242 
 243 global names, opens, reads, writes
 244 global entry_opens, entry_reads, entry_writes
 245 global time_opens, time_reads, time_writes
 246 
 247 probe kernel.function("sys_open") {
 248   t=gettimeofday_us(); p=pid(); e=execname();
 249   names[e]=1
 250   opens[e] ++ # plain integer
 251   entry_opens[p] = t;
 252 }
 253 
 254 probe kernel.function("sys_open").return {
 255   t=gettimeofday_us(); p=pid(); e=execname();
 256   time_opens[e] <<< t - entry_opens[p];
 257 }
 258 
 259 probe kernel.function("sys_read") {
 260   t= gettimeofday_us(); p =pid(); e=execname();
 261   names[e]=1
 262   reads[e] <<< $count # statistics
 263   entry_reads[p] = t;
 264 }
 265 
 266 probe kernel.function("sys_read").return {
 267   t=gettimeofday_us(); p=pid(); e=execname();
 268   time_reads[e] <<< t - entry_reads[p];
 269 }
 270 
 271 probe kernel.function("sys_write") {
 272   t=gettimeofday_us(); p=pid(); e=execname();
 273   names[e]=1
 274   writes[e] <<< $count # statistics
 275   entry_writes[p] = t;
 276 }
 277 
 278 probe kernel.function("sys_write").return {
 279   t = gettimeofday_us(); p = pid(); e=execname();
 280   time_writes[e] <<< t - entry_writes[p];
 281 }
 282 
 283 probe end {
 284   foreach(name+ in names) { # sort by names
 285     printf ("process: %s\n", name)
 286     if (opens[name]) {
 287       printf ("opens n=%d\n", opens[name])
 288       print (@hist_log(time_opens[name]))
 289     }
 290     if (@count(reads[name])) {
 291       printf ("reads n=%d, sum=%d, avg=%d\n",
 292          @count(reads[name]), # extracting stat results
 293          @sum(reads[name]),
 294          @avg(reads[name]))
 295       print ("read timing distribution\n")
 296       print (@hist_log(time_reads[name]))
 297     }
 298     if (@count(writes[name])) {
 299       printf ("writes n=%d, sum=%d, avg=%d\n",
 300          @count(writes[name]), # extracting stat results
 301          @sum(writes[name]),
 302          @avg(writes[name]))
 303       print ("write timing distribution\n")
 304       print (@hist_log(time_writes[name]))
 305     }
 306   }
 307 }
 308 ---------------------------------------------------------
 309 ---------------------------------------------------------
 310 #! /usr/bin/env stap
 311 # This is a simple example to demonstrate using markers thro SystemTap. 
 312 # Assuming a marker of the form "trace_mark(Marker1, "count %d", count);"
 313 # is placed in kernel code.
 314 
 315 probe begin { log("starting probe") }
 316 probe kernel.mark("Marker1") {print("Marker1 hit: %d\n", $arg1) }
 317 
 318 ---------------------------------------------------------
 319 
 320 ---------------------------------------------------------
 321 #! /usr/bin/env stap
 322 # Example to demonstrate handling markers that have the same name but
 323 # different format strings thro SystemTap. 
 324 # Assuming a marker of the form 
 325 # "trace_mark(Marker2, "count %d", count);"
 326 # "trace_mark(Marker2, "mesg %s", mesg);"
 327 # is placed in kernel code.
 328 
 329 probe begin { log("starting probe") }
 330 probe kernel.mark("Marker2").format(int) {print("Marker2 taking int hit: %d\n", $arg1) }
 331 probe kernel.mark("Marker2").format(char *) {print("Marker2 taking mesg hit: %s\n", $arg1) }
 332 ---------------------------------------------------------
 333 ---------------------------------------------------------
 334 #! /usr/bin/env stap
 335 #
 336 # Probe a process with pid $1 at its vaddr $2.
 337 #
 338 probe begin {
 339         log("Probing...")
 340 }
 341 probe process($1).statement($2).absolute.return,
 342         process($1).statement($2).absolute
 343 {
 344         log (pp())
 345 }
 346 
 347 ---------------------------------------------------------
 348 ---------------------------------------------------------
 349 #! /usr/bin/env stap
 350 #
 351 # Probe syscalls made by /bin/ls.
 352 #
 353 probe begin {
 354         log("Probing...")
 355 }
 356 probe process("/bin/ls").syscall { printf("|%d", $syscall) }
 357 ---------------------------------------------------------
 358 
 359 
 360 For more examples see testsuite/systemtap.examples directory