The Wall

Still Writing

2011-12-31T23:24:00.000-08:00

I haven't posted here in a few years, but I have been busy writing material, particularly for:

The DTrace book: which has over 1,000 pages, much of it new content. This ate over a year of my spare time (and Jim's).

dtrace.org/blogs/brendan: my professional blog, for posts related to my work (although it's still mostly a spare time project). This was formerly on blogs.oracle.com/brendan, and before that on blogs.sun.com/brendan.

For more of my recent writing, I've updated a summary under the Documentation section on my homepage, which includes posts from my dtrace.org blog and other places.

I'll post more here in the coming year: this blog is for purely personal posts and projects (like the DTraceToolkit).

DTrace in New York

2008-06-24T08:23:00.000-07:00

Back in February I gave several DTrace talks in New York, including one at the New York OpenSolaris User Group meeting (NYCOSUG). I used an updated slide deck and was asked to put the PDF on my blog; I think Isaac must have beaten me to it and put it here (thanks!). I did intend to blog about this in case anyone was looking - sorry for the delay.

The NYCOSUG had a good turn out and asked some great questions, allowing me to deviate from the prepared slides and cover other things of interest (which is the value of an in-person presentation.) After the presentation I realised there was one point I could have explained better, which would make an interesting blog post.

I started with the following simple demos - the point of these is to build on something commonly understood (such as the behaviour of fork() and exec()), to introduce something new - DTrace.

Tracing exec():

# dtrace -n 'syscall::exec*: { trace(execname); }'
dtrace: description 'syscall::exec*: ' matched 4 probes
CPU     ID                    FUNCTION:NAME
  0  98087                      exece:entry   bash                             
  0  98088                     exece:return   ls                               
^C

In the above output, we traced an exece() system call - printing the current process name when we entered and returned from that system call. That process name changed from "bash" to "ls" (I executed "ls -l" in another window), which is what exec() does - replaces the current process image with another.

While unsuprising, the significance is that we are able to dymanically trace this kernel activity whenever we would like, along with thousands of other kernel events. I could, for example, trace the time taken for exec() to execute; or the exit status when exec() returned along with the error code; I can also trace the internal operation of exec() with enough detail to fill hundreds of pages (I just counted 47396 lines of output when tracing every kernel function entry and return during exec()).

Now to trace fork():

# dtrace -n 'syscall::fork*: { trace(pid); }'
dtrace: description 'syscall::fork*: ' matched 6 probes
CPU     ID                    FUNCTION:NAME
  0  98227                    forksys:entry     87417
  0  98228                   forksys:return     90769
  0  98228                   forksys:return     87417
^C

The above system call has one entry and two returns - which is what we expect from the fork() family.

Simple as this is, some interesting behaviour is already visible. Note that the parent returned before the child? On the fork() entry, the parent's PID is traced (87417), however the child PID (90769) appears first on return.

It's possible that the output could be shuffled due to how DTrace uses per-CPU buffers to minimise performance impact; to double check, add a "timestamp" column and post sort:

# dtrace -n 'syscall::fork*: { printf("%d %d", timestamp, pid); }' -o /tmp/out.dtrace
dtrace: description 'syscall::fork*: ' matched 6 probes
# sort -n +3 /tmp/out.dtrace
CPU     ID                    FUNCTION:NAME
  1  98227                    forksys:entry 268361844462135 87417
  1  98228                   forksys:return 268361844960455 90968
  0  98228                   forksys:return 268361844965924 87417

I asked the audience - why does the child return from fork() before the parent? I added that this was a very difficult question!

Someone responded to say that this was how all operating systems worked - the parent process waits for the child to complete. I said I was just tracing fork() and the parent could be scheduled first - but deliberately isn't, and explained why. My answer left them confused - and it struck me afterwards that I should have explained this better.

Consider this:

# dtrace -n 'syscall::fork*:,syscall::wait*: { trace(pid); }'
dtrace: description 'syscall::fork*:,syscall::wait*: ' matched 10 probes
CPU     ID                    FUNCTION:NAME
  0  98227                    forksys:entry    87417
  0  98228                   forksys:return    91088
  0  98228                   forksys:return    87417
  0  98163                    waitsys:entry    87417
  0  98164                   waitsys:return    87417
^C

In the above output we can see both fork() and wait(), and we can discuss behaviour such as the parent process waiting for the child to complete (since I was in a shell running foreground commands.)

But I was actually asking a much deeper question, that of thread scheduling immediately after the fork() system call, and before the parent has called wait(). Immediately after fork() you have two threads - which should go on-CPU first? The parent, so that it can get to wait() sooner and before the child may have exited? Or is there a reason to schedule the child first?

As DTrace shows, the child is getting scheduled first, and the reason is one of performance. The source code explains in uts/common/disp/ts.c :


/*
 * Child is placed at back of dispatcher queue and parent gives
 * up processor so that the child runs first after the fork.
 * This allows the child immediately execing to break the multiple
 * use of copy on write pages with no disk home. The parent will
 * get to steal them back rather than uselessly copying them.
 */
static void
ts_forkret(kthread_t *t, kthread_t *ct)

The fork() system call creates a clone of the parent, but rather than copy all memory pages to a new address space (which would add significant latency during process creation), Solaris bumps a reference counter on those memory pages to remember that two process refer to the same data. If one writes to a memory page later, this triggers a "copy on write" to create a private writable copy for that process. This means that expensive memory copies are only performed when needed - or if needed. Since a child process is likely to call exec(), it is likely to simply drop many existing memory references for the new process image, so copying those bytes would have been wasted cycles anyway.

However if the parent is scheduled first - before the child has had a chance to exec() - then the parent may continue writing to its address space, triggering copy on writes. Then the child executes, calls exec(), and drops those newly copied pages anyway - which were copied in vain. To avoid this, the child is scheduled first - to call exec() as soon as possible, as described in the comment above.

I learned about this behaviour when reading Solaris Internals 1st edition; but that was a time before DTrace and OpenSolaris. It's great that we all can now both read the code, and use DTrace to see it in operation.

DTraceToolkit in MacOS X

2008-02-18T01:19:00.002-08:00

Apple included DTrace in MacOS X 10.5 (Leopard), released in October 2007. It's great to have DTrace available in MacOS X for its powerful application and kernel performance analysis. To think that there is now another kernel we can examine using DTrace is exciting - it's like discovering a new planet in the solar system.

Apart from kernel analysis, DTrace also improves general usability by answering every day questions like: why are my disks rattling? or why does my browser keep hanging? Although, your average user may not write DTrace scripts to answer these questions themselves (it's better if they do), but instead use prewritten scripts.

MacOS X includes a collection of DTrace scripts in /usr/bin, mostly from the DTraceToolkit:

leopard# grep -l DTrace /usr/bin/*
/usr/bin/bitesize.d
/usr/bin/cpuwalk.d
/usr/bin/creatbyproc.d
/usr/bin/dappprof
/usr/bin/dapptrace
/usr/bin/diskhits
/usr/bin/dispqlen.d
/usr/bin/dtruss
/usr/bin/errinfo
/usr/bin/execsnoop
/usr/bin/fddist
/usr/bin/filebyproc.d
/usr/bin/hotspot.d
/usr/bin/httpdstat.d
/usr/bin/iofile.d
/usr/bin/iofileb.d
/usr/bin/iopattern
/usr/bin/iopending
/usr/bin/iosnoop
/usr/bin/iotop
/usr/bin/kill.d
/usr/bin/lastwords
/usr/bin/loads.d
/usr/bin/newproc.d
/usr/bin/opensnoop
/usr/bin/pathopens.d
/usr/bin/pidpersec.d
/usr/bin/plockstat
/usr/bin/priclass.d
/usr/bin/pridist.d
/usr/bin/procsystime
/usr/bin/runocc.d
/usr/bin/rwbypid.d
/usr/bin/rwbytype.d
/usr/bin/rwsnoop
/usr/bin/sampleproc
/usr/bin/seeksize.d
/usr/bin/setuids.d
/usr/bin/sigdist.d
/usr/bin/syscallbypid.d
/usr/bin/syscallbyproc.d
/usr/bin/syscallbysysc.d
/usr/bin/topsyscall
/usr/bin/topsysproc
/usr/bin/weblatency.d

That's 44 DTraceToolkit scripts, plus plockstat from Solaris 10. While the DTraceToolkit now has over 200 scripts, it makes sense to pick out the most useful scripts for inclusion in /usr/bin.

Popular scripts such as iosnoop can now be run by MacOS X users:


leopard# iosnoop
  UID   PID D    BLOCK   SIZE       COMM PATHNAME
  501   130 R 31987472  40960   Terminal ??/dyld/dyld_shared_cache_i386
  501   130 R  7879952   8192   Terminal ??/SearchManager.nib/keyedobjects.nib
  501   130 R 32132304  12288   Terminal ??/dyld/dyld_shared_cache_i386
  501   130 R 32132528   4096   Terminal ??/dyld/dyld_shared_cache_i386
  501   130 R 32047696  12288   Terminal ??/dyld/dyld_shared_cache_i386
  501   130 R 32132592   4096   Terminal ??/dyld/dyld_shared_cache_i386
  501   130 R 32131512  12288   Terminal ??/dyld/dyld_shared_cache_i386
  501   130 R 32033296  12288   Terminal ??/dyld/dyld_shared_cache_i386
  501   130 R 32044488   4096   Terminal ??/dyld/dyld_shared_cache_i386
  501   130 R 32045064   4096   Terminal ??/dyld/dyld_shared_cache_i386
  501   130 R 32131344   4096   Terminal ??/dyld/dyld_shared_cache_i386
  501   130 R 32048680  16384   Terminal ??/dyld/dyld_shared_cache_i386
  501   130 R 32132544   8192   Terminal ??/dyld/dyld_shared_cache_i386
  501   130 R 32049296  12288   Terminal ??/dyld/dyld_shared_cache_i386
   -1     0 W 32482848  86016 kernel_task ??/vm/swapfile2
   -1     0 W 32483040 135168 kernel_task ??/vm/swapfile2
  501   130 R 32044672   4096   Terminal ??/dyld/dyld_shared_cache_i386
  501   130 R 32132656  12288   Terminal ??/dyld/dyld_shared_cache_i386
[...]

The man pages are conveniently included in /usr/share/man.

I had been making preperations in the latest DTraceToolkit (0.99) for MacOS X DTrace, such as putting an "OS" field into the man pages and figuring out how to support different versions of the same script (tcpsnoop_snv, etc). Hopefully many scripts will run on both Solaris and MacOS X (especially if they use stable providers), however I expect there will be some that are specific to each. Now that QNX DTrace also exists, there is additional need for identifying OS specifics in the DTraceToolkit.

It's been great news for DTrace, Sun and Apple - who have not only gained the best performance and debugging tool available, but also the existing DTrace community.

Browsable DTraceToolkit

2008-02-17T23:19:00.002-08:00

Stefan Parvu has created browsable HTML versions of the DTraceToolkit on the DTT test page. See DTraceToolkit ver 0.99 to browse that version.

A goal of the DTraceToolkit is to provide documented examples of DTrace scripting, in addition to what is available in the DTrace Guide. However these examples have been reaching a limited audience of those who download, unzip, and browse through the text files.

Now that the DTraceToolkit is browsable online, its contents can be found by internet search engines. This should help people not only find examples of DTrace usage, but also solutions to some common observability problems.

There have been a few other items of DTraceToolkit news which I'll blog about soon. Please excuse my infrequent blog postings - I've been busy since joining Sun on a particular project which consumes most of my spare time. It will be worth it, which should be clear once I can start posting about it on my Sun blog.

DTraceToolkit ver 0.99

2007-10-05T23:13:00.000-07:00

I've released DTraceToolkit ver 0.99 - a major release. If you haven't encountered it before, the DTraceToolkit is a collection of opensource scripts for:

solving various troubleshooting and performance issues
demonstrating what is possible with DTrace (seeing is believing)
learing DTrace by example

The DTraceToolkit isn't Sun's standard set of Solaris performance tools, or, everything that DTrace can do. It is a handy collection of documented and tested DTrace tools that are useful in most situations. It's certainly not a substitute for learning DTrace properly and writing your own custom scripts - although it should help you do that by providing working examples of code. It is certainly better than not using DTrace at all, if you didn't have the time to learn DTrace.

DTraceToolkit 0.96

18 months ago I released version 0.96 of the DTraceToolkit. The Bin directory, which contains symlinks to all the scripts, looked like this,

DTraceToolkit version 0.96
Click for a larger image. That collection of scripts provides various views of system behaviour and of the interaction of applications with the system. A general theme, if there was one, was that of easy system observability - illuminating system internals that were either difficult or impossible to see before. There were 104 scripts in that release - although that is just the tip of an iceberg.

DTraceToolkit 0.99

In the last 18 months, DTrace has been expanding its horizons through the creation of numerous new DTrace providers. There are now providers for Java, JavaScript, Perl, Python, Php, Ruby, Shell and Tcl, and more on the way. The iceberg of system observability is now just one in a field of icebergs, with more rising above the surface as time goes by. It's about time the DTraceToolkit was updated to refelect the trajectory of DTrace itself - which isn't just about system observability - it is the observability of life, the universe, and everything.

This new version of the DTraceToolkit does has a theme - that of programing language visibility, which covers several of the new DTrace providers that now exist. The Bin directory of the toolkit now contains 230 scripts, and looks like,

Below I've highlighted most of the new contents, grouped by language that they trace,

DTraceToolkit version 0.99
I've placed language scripts in their own subdirectories, each of which include a "Readme" file to document suggestions for where to find the provider and how to get it installed and working. Some of these providers do require downloading of source, patching, and compiling, which may take you some time. Both C and C++ are supported by numerous scripts, but don't have a prefix to group them like the other languages do; I hope to fix this in the next release, and actually have C and C++ subdirectories.

DTraceToolkit 0.99 change summary:

New script categories: Java, JavaScript, Perl, Php, Python, Ruby, Shell and Tcl
Many new scripts (script count has doubled)
Many new example files (since there is one per script)
A new Code directory for sample target code (used by the example files)
Several bug fixes, numerous updates
Updated versions of tcpsnoop/tcptop for OpenSolaris/Solaris Nevada circa late 2007

For each language, there is about a dozen scripts to provide:

general observability (such as function and object counts, function flows)
performance observability (on-cpu/elapsed times, function inclusive/exclusive times, memory allocation)
some paths for deeper analysis (syscall and library tracing, stacks, etc)

Screenshots

Now for some examples. I'll demonstrate PHP, but the following applies to all the new languages supported in the toolkit (look in the Example directory for the language that interests you). Here is a sample PHP program that appears in the toolkit as Code/Php/func_abc.php,

/opt/DTT> cat -n Code/Php/func_abc.php 
  1  <?php
  2  function func_c()
  3  {
  4          echo "Function C\n";
  5          sleep(1);
  6  }
  7
  8  function func_b()
  9  {
 10          echo "Function B\n";
 11          sleep(1);
 12          func_c();
 13  }
 14
 15  function func_a()
 16  {
 17          echo "Function A\n";
 18          sleep(1);
 19          func_b();
 20  }
 21
 22  func_a();
 23  ?>

For general observability there are scripts such as php_funccalls.php, for counting function calls,

# php_funccalls.d 
Tracing... Hit Ctrl-C to end.
^C
FILE                             FUNC                                CALLS
func_abc.php                     func_a                                  1
func_abc.php                     func_b                                  1
func_abc.php                     func_c                                  1
func_abc.php                     sleep                                   3

The above output showed that sleep() was called three times, and the user defined functions were each called once - as we would have assumed from the source. With DTrace you can check your assumptions through tracing, which is often a useful excercise. I've solved many performance issues by examining areas that seem almost too obvious to bother checking.

The following script is both for general and performance observability. It prints function flow along with delta times,

# php_flowtime.d
  C TIME(us)         FILE             DELTA(us)  -- FUNC
  0 3646108339057    func_abc.php             9 -> func_a
  0 3646108339090    func_abc.php            32   -> sleep
  0 3646109341043    func_abc.php       1001953   <- sleep
  0 3646109341074    func_abc.php            31   -> func_b
  0 3646109341098    func_abc.php            23     -> sleep
  0 3646110350712    func_abc.php       1009614     <- sleep
  0 3646110350745    func_abc.php            32     -> func_c
  0 3646110350768    func_abc.php            23       -> sleep
  0 3646111362323    func_abc.php       1011554       <- sleep
  0 3646111362351    func_abc.php            27     <- func_c
  0 3646111362361    func_abc.php            10   <- func_b
  0 3646111362370    func_abc.php             9 <- func_a
^C

Delta times, in this case, show the time from the line on which they appear to the previous line. The large delta times visible show that from when the sleep() function completed to when it began, took around 1.0 seconds of elapsed time. As we'd expect from the source. Both CPU (C) and time since boot (TIME(us)) are printed in case the output is shuffled on multi-CPU systems, and requires post sorting.

A more consise way to examine elapsed times may be php_calltime.d, a script that can be useful for performance analysis,

# php_calltime.d
Tracing... Hit Ctrl-C to end.
^C

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

Exclusive function elapsed times (us),
FILE                 TYPE       NAME                                TOTAL
func_abc.php         func       func_c                                330
func_abc.php         func       func_b                                367
func_abc.php         func       func_a                                418
func_abc.php         func       sleep                             3025644
-                    total      -                                 3026761

Inclusive function elapsed times (us),
FILE                 TYPE       NAME                                TOTAL
func_abc.php         func       func_c                            1010119
func_abc.php         func       func_b                            2020118
func_abc.php         func       sleep                             3025644
func_abc.php         func       func_a                            3026761

The exclusive function elapsed times show which functions cused the latency - which identifies sleep() clocking a total of 3.0 seconds (as it was called three times). The inclusive times show which higher level functions the latency occured in, the largest being func_a() since every other function were called within it. There isn't a total line printed for inclusive times - since it wouldn't make much sense to do so (that column sums to 9 seconds, which is more confusing than of actual use).

As a starting point for deeper analysis, the following script adds syscall tracing to the PHP function flows, and adds terminal escape colours (see Notes/ALLcolors_notes.txt for notes on using colors with DTrace),

# php_syscolors.d
C    PID/TID   DELTA(us)              FILE:LINE TYPE     -- NAME
0  18426/1             8      func_abc.php:22   func     -> func_a
0  18426/1            41      func_abc.php:18   func       -> sleep
0  18426/1            15                 ":-    syscall      -> nanosleep
0  18426/1       1008700                 ":-    syscall      <- nanosleep
0  18426/1            30      func_abc.php:18   func       <- sleep
0  18426/1            42      func_abc.php:19   func       -> func_b
0  18426/1            28      func_abc.php:11   func         -> sleep
0  18426/1            14                 ":-    syscall        -> nanosleep
0  18426/1       1010083                 ":-    syscall        <- nanosleep
0  18426/1            29      func_abc.php:11   func         <- sleep
0  18426/1            43      func_abc.php:12   func         -> func_c
0  18426/1            28      func_abc.php:5    func           -> sleep
0  18426/1            14                 ":-    syscall          -> nanosleep
0  18426/1       1009794                 ":-    syscall          <- nanosleep
0  18426/1            28      func_abc.php:5    func           <- sleep
0  18426/1            34      func_abc.php:6    func         <- func_c
0  18426/1            18      func_abc.php:13   func       <- func_b
0  18426/1            17      func_abc.php:20   func     <- func_a
0  18426/1            21                 ":-    syscall  -> fchdir
0  18426/1            19                 ":-    syscall  <- fchdir
0  18426/1             9                 ":-    syscall  -> close
0  18426/1            13                 ":-    syscall  <- close
0  18426/1            35                 ":-    syscall  -> semsys
0  18426/1            12                 ":-    syscall  <- semsys
0  18426/1             7                 ":-    syscall  -> semsys
0  18426/1             7                 ":-    syscall  <- semsys
0  18426/1            66                 ":-    syscall  -> setitimer
0  18426/1             8                 ":-    syscall  <- setitimer
0  18426/1            39                 ":-    syscall  -> read
0  18426/1            14                 ":-    syscall  <- read
0  18426/1            11                 ":-    syscall  -> writev
0  18426/1            22                 ":-    syscall  <- writev
0  18426/1            23                 ":-    syscall  -> write
0  18426/1           110                 ":-    syscall  <- write
0  18426/1            61                 ":-    syscall  -> pollsys

From that output we can see that PHP's sleep() is implemented by the syscall nanosleep(), and that it appears that writes are buffered and written later.

Understanding the language scripts

The scripts are potentially confusing for a couple of reasons; understanding these will help explain how best to use these scripts.

Firstly, some of the scripts print out an event "TYPE" field (eg, "syscall" or "func"), and yet the script only traces one type of event (eg, "func"). Why print a field that will always contain the same data? Sounds like it might be a copy-n-paste error. This is in fact deliberate so that the scripts form better templates for expansion, and was something I learnt while using the scripts to analyse a variety of problems. I would frequently have a script that measured functions and wanted to add syscalls, library calls or kernel events, to customise that script for a particular problem. When adding these other event types, it was much easier (often trivial) if the script already had a "TYPE" field. So now most of them do.

Also, there are variants of scripts that provide very similar tracing at different depths of detail. Why not one script that does everything, with the most detail? Here I'll use the Tcl provider to explain why,

The tcl_proccalls.d script counts procedure calls, here it is tracing the Code/Tcl/func_slow.tcl program in the toolkit, which calls loops within functions:

# tcl_proccalls.d
Tracing... Hit Ctrl-C to end.
^C
 PID    COUNT PROCEDURE
183083        1 func_a
183083        1 func_b
183083        1 func_c
183083        1 tclInit

Ok, that's a very high level view of Tcl activity. There is also tcl_calls.d to count Tcl commands as well as procedures:

# tcl_calls.d
Tracing... Hit Ctrl-C to end.
^C
 PID TYPE     NAME                                                    COUNT
[...]
183086 proc     func_a                                                      1
183086 proc     func_b                                                      1
183086 proc     func_c                                                      1
183086 proc     tclInit                                                     1
[...]
183086 cmd      if                                                          8
183086 cmd      info                                                       11
183086 cmd      file                                                       12
183086 cmd      proc                                                       12

(Output truncated). Now we have a deeper view of Tcl operation. Finally there is tcl_ins.d to count Tcl instructions:

# tcl_ins.d
Tracing... Hit Ctrl-C to end.
^C
 PID TYPE     NAME                                                    COUNT
[...]
16005 inst     jump1                                                      14
16005 inst     pop                                                        18
16005 inst     invokeStk1                                                 53
16005 inst     add                                                    600000
16005 inst     concat1                                                600000
16005 inst     exprStk                                                600000
16005 inst     lt                                                     600007
16005 inst     storeScalar1                                           600016
16005 inst     done                                                   600021
16005 inst     loadScalar1                                           1200020
16005 inst     push1                                                 4200193

There are such large counts since this script is tracing the low level instructions used to execute the loops in this code.

So the question is: why three scripts and not one that counts everything? Why not tcl_megacount.d? There are at least three reasons behind this.

1. You don't pull out a microscope if you are looking for your umbrella. Tracing everything can really bog you down in detail, when higher level views are frequently sufficient for solving issues. It's a matter of the right tool for the job. Try the higher level scripts first, then dig deeper as needed.

2. Measuring at such a low level can have a significant performance impact. I'll demonstrate this by using ptime as a easy (but rough) measurement of run time for the Code/Tcl/func_slow.tcl sample program.

Here is func_slow.tcl running with no DTrace enabled as a baseline:

# ptime ./func_slow.tcl > /dev/null

real        3.306
user        3.276
sys         0.005

Now while tcl_proccalls.d is tracing procedure calls:

# ptime ./func_slow.tcl > /dev/null

real        3.311
user        3.270
sys         0.006

Now while tcl_calls.d is tracing both Tcl procedures and commands:

#  ptime ./func_slow.tcl > /dev/null

real        3.313
user        3.283
sys         0.006

Finally with tcl_ins.d tracing Tcl instructions:

# ptime ./func_slow.tcl > /dev/null

real       20.438
user       20.278
sys         0.010

Ow! Our target application is running 7 times slower? This isn't supposed to happen, is there something wrong with DTrace or the Tcl provider? Well, there isn't, the problem is that of tracing 9 million events during a 3 second program. The overheads of DTrace are miniscule, however if you multiply them (or anything) by ridiculously large numbers they'll eventually become measurable. 9 million events is a lot of events - and you wouldn't normally care about tracing Tcl instructions anyway. It's great to have this capability, if it is ever needed.

3. Example programs. Writing mega powerful DTrace scripts often means mega confusing scripts to read. People use the DTraceToolkit as a collection of example code to learn from, so keeping things simple if possible, should help.

Documentation

It usually takes more time to document a script than it takes to write it. I feel strongly about creating quality IT documentation, so I'm reluctant to skip this step. The strategy used in the toolkit is, by subdirectory name,

Scripts - these have a standard header plus inline comments.
Examples - this is a directory of example files that demonstrate each script, providing screenshots and interpretations of the output. Particular attention has been made to explain relevant details, especially caveats, no matter how obvious they may seem.
Notes - this is a directory of files that comment on a variety of topics that are relevant to multiple scripts. There are many more notes files in this toolkit release.
Man pages - there is a directory for these, which are useful for looking up field definitions and units. To be honest, I frequently use the Examples directory for reminders on what each tool does rather than the Man pages.

Since there were over 100 new scripts in this release, over 100 new example files needed to be written. Fortunately I had help from Claire Black (my wife), who as an ex-SysAdmin and Solaris Instructor had an excellent background for what people needed to know and how to express it. Unfortunately for her, she only had about 4 days from when I completed these scripts to when the documentation was due for inclusion on the next OpenSolaris Starter Kit disc. Despite the time constraint she has done a great job, and there is always the next release for her to spend more time fleshing out the examples further. I'm also aiming to collect more real-world example outputs for the next release (eg, Mediawiki analysis for the PHP scripts).

Testing

Stefan Parvu has helped out again by running every script on a variety of platforms, which is especially important now that I don't have a SPARC server at the moment. He has posted the results on the DTraceToolkit Testing Room, and did find a few bugs which I fixed before release.

Personal

It has been about 18 months since the last release. In case anyone was wondering, there are several reasons why, briefly: I moved to the US, began a new job in Sun engineering, left most of my development servers behind in Australia, brought the DTraceToolkit dev environment over on a SPARC UFS harddisk (which I still can't read), and got hung up on what to do with the fragile tcp* scripts. The main reason would be having less spare time as I learnt the ways of Sun engineering.

I also have a Sun blog now, here. I'm not announcing the DTraceToolkit there since it isn't a Sun project; it's a spare time project by myself and others of the OpenSolaris community.

Future

The theme for the next release may be storage: I'd like to spend some time seeing what can be done for ZFS, for iSCSI (using the new provider), and NFS.

Updates from California

2006-12-14T00:00:00.000-08:00

Since I've been quiet for a while on this blog and on OpenSolaris mailing lists, here is a quick update about myself and my projects.

I got married, ditched my old car, left the instructing/consulting scene in Australia/APAC, and moved to California to work as a developer at Sun. I brought along whatever I could fit in airline luggage, which included a laptop, hard disks, some books, clothes, and my fencing gear. Since then, I've been busy getting up to speed with some interesting projects, some of which I've discussed on my Sun blog.

OpenSolaris projects such as the DTraceToolkit will remain OpenSolaris projects; and other open source projects such as Chaosreader will of course remain open source. I'll post updates about them to this blog and will continue working on them as I always have done - as a spare time hobby.

Progress on these other projects has been on hold since I left Australia and powered down my array of test and development servers (and sadly powered down "mars", my main server which had an uptime of over 400 days). I began rebuilding my development environment last night, when I powered on the disk containing the DTraceToolkit build files for the first time in three months. I'm looking forward to adding some more scripts, and more documentation to guide people through the toolkit.

And finally, living in the US has been great - however the following items were quite difficult to find:

cricket coverage
authentic ginger beer

I can now listen to Star 101.3 again, but I've lost access to both the ABC and BBC's online radio coverage of the Ashes Cricket series - which seems to be blocked from the US!

No more Star 101.3

2006-08-13T22:03:00.000-07:00

If you are in Australia, that is.

Sometime last year I went looking for a decent Internet radio station, as I'm often online on my laptop, but not ofter near radios or reliable reception. I found Star 101.3 FM, and it was good. It happens to be based in the US.

My day would often begin with info bytes from John Tesh followed by hours of music (ok, sometimes they play the same music ;-). When I'd hear "Don Bleu in the morning", I'd know I'd stayed up a bit too late!

Recently Star 101.3 pulled the plug for international listeners "due to licensing restrictions". Ok, I can understand that may well be the case, and I'm glad it lasted as long as it did. If you are in the US you can still listen.

Brendan Clones #2

2006-08-13T00:38:00.000-07:00

Several months ago several of the Brendan clones were photographed while working on the DTraceToolkit.

More recently they were photographed again, this time working on Solaris Internals and Solaris Performance and Tools. For the first time all of the Brendan clones were involved on the one project, with most of them pictured here. Click for a larger photo:

Sleeping Brendan is busy sleeping, Engineer Brendan is studying Solaris Internals 1st edition, and Master Brendan is looking on. The remaining Brendans are meticulously checking facts, reading source code, writing DTrace scripts and testing them.

Of course, photographer Brendan is behind the camera, taking the photo.

How much CPU does a down interface chew?

2006-08-11T07:28:00.000-07:00

While teaching a DTrace class in Sydney this week I ran an ad-lib demo that took a mysterous and suprising turn. I think you'll find this quite interesting.

One of my favourite DTrace demos begins by asking how much CPU a busy network interface will consume. About 2 in 10 people will know the answer - a lot! But how did you measure this on older Solaris? After all, if it really is "a lot", then we really want a value! 20% of a CPU? 50%?

I was demonstrating on an Ultra 10, with a 333 MHz CPU and a 100 Mbit/sec interface (hme0). Even with the numerous TCP/IP performance enhancements in Solaris 10, driving 100 Mbit/sec on an Ultra 10 will still hurt.

From another host, I sent a large file over the network to drive the interface at capacity. I thought I'd start by showing how busy the network interface was by using the sysperfstat tool from the K9Toolkit (I usually use nicstat, I thought this would be a nice change). sysperfstat ran for a few seconds, then I began the bulk network transfer:

$ /brendan/K9Toolkit/sysperfstat 1
    Time    %CPU   %Mem  %Disk   %Net     CPU    Mem   Disk    Net
19:24:27    5.24  33.52   0.52   0.07    0.05   0.00   0.01   0.00
19:24:28    7.35  33.53   1.29   0.00    0.00   0.00   0.00   0.00
19:24:29    7.48  33.53   0.00   0.00    0.00   0.00   0.00   0.00
19:24:30   39.65  33.79   1.27  51.27    3.69   0.00   0.00   0.00
19:24:32   65.67  33.79   0.00 173.14    1.28   0.00   0.00   0.00
19:24:34   68.35  33.79   0.00 173.03    0.00   0.00   0.00   0.00
19:24:37   80.12  33.79   0.00 176.33    0.82   0.00   0.00   0.00
19:24:39   76.97  33.79   0.00 178.12    0.43   0.00   0.00   0.00
19:24:41   76.08  33.79   1.61 164.82    1.37   0.00   0.00   0.00
19:24:44   80.18  33.79   0.00 177.68    0.38   0.00   0.00   0.00

Oh dear! I was expecting %Net to reach around 90%, not over 170%!

Both the Net and Disk percentages are in terms of a single interface or disk, as from experience this has shown to be more useful than a global percentage (which CPU and Mem use). 170% could indicate that I have two network interfaces running at around 85%. But why? I had only initiated one network transfer to the hme0 address.

... The system had become so heavily loaded that sysperfstat's interval of 1 second became 2 and sometimes 3 seconds. Good thing I never assumed sleep(1) would actually sleep for 1 second only - sysperfstat uses delta times from kstat measurements.

Demonstrations are much more exciting when even you don't know of the outcome. So why did we hit 170% utilisation? Maybe another network interface was doing traffic that I didn't know about:

# ifconfig -a
lo0: flags=2001000849<UP,LOOPBACK,RUNNING,MULTICAST,IPv4,VIRTUAL> mtu 8232 index 1
        inet 127.0.0.1 netmask ff000000
hme0: flags=1000863<UP,BROADCAST,NOTRAILERS,RUNNING,MULTICAST,IPv4> mtu 1500 index 2
        inet 192.168.1.13 netmask ffffff00 broadcast 192.168.1.255
        ether 8:0:20:b0:7a:18
qfe0: flags=1000862<BROADCAST,NOTRAILERS,RUNNING,MULTICAST,IPv4> mtu 1500 index 3
        inet 10.1.2.3 netmask ff000000 broadcast 10.255.255.255
        ether 8:0:20:b0:7a:18
#

No answers there. hme0 is "UP", qfe0 is both down and has an address class that we aren't using anywhere at this site. So qfe0 can't be doing anything, right?

$ /brendan/K9Toolkit/nicstat 1
    Time   Int   rKb/s   wKb/s   rPk/s   wPk/s    rAvs    wAvs   %Util     Sat
19:25:34  qfe0    3.77    0.00    2.98    0.00  1292.8   42.00    0.03    0.00
19:25:34  hme0    4.69    0.42    3.77    5.92  1272.9   72.52    0.04    0.00
    Time   Int   rKb/s   wKb/s   rPk/s   wPk/s    rAvs    wAvs   %Util     Sat
19:25:36  qfe0 10435.6    0.00  8642.5    0.00  1236.4    0.00   85.49    0.00
19:25:36  hme0 10394.1   818.6  8601.4 15524.7  1237.4   54.00   91.86    0.00
    Time   Int   rKb/s   wKb/s   rPk/s   wPk/s    rAvs    wAvs   %Util     Sat
19:25:39  qfe0 10469.2    0.00  8744.1    0.00  1226.0    0.00   85.76    0.00
19:25:39  hme0 10451.4   828.3  8732.5 15708.5  1225.5   54.00   92.40    0.00

Woah - this "down" qfe0 with a dummy address is 85% busy - somthing really strange is going on!

I had began this demo to show %CPU for busy interfaces, which leads us to run the the DTrace based "intrstat" tool - new to Solaris 10. This shows us how much CPU our network interface interrupts are consuming, and now I had a renewed interest in what it had to say:

# intrstat 1

      device |      cpu0 %tim
-------------+---------------
       hme#0 |      1232 32.8
       m64#0 |         0  0.0
       qfe#0 |      1140 37.8
        su#0 |         0  0.0
        su#1 |         0  0.0
      uata#0 |         0  0.0

      device |      cpu0 %tim
-------------+---------------
       hme#0 |      1233 32.9
       m64#0 |         0  0.0
       qfe#0 |      1138 37.8
        su#0 |         0  0.0
        su#1 |         0  0.0
      uata#0 |         1  0.0
...

hme0 is consuming 33% of CPU0, quite a substantial amount - considering this is just a 100 Mbit/sec interface. That's where the planned demo would have ended.

However qfe0 is consuming 37.8% of CPU0 - this is really frightening! Remember, I am sending traffic to hme0's address, and qfe0 is not marked "UP". This is a dead interface with a dummy address - and it is consuming a LOT of CPU! (perhaps it is talking to other dead interfaces? ;-)

I began thinking outside the box, and Scott was around to help. We found that the room was connected to a hub, both hme0 and qfe0 were connected to this same hub, and they both had the same ethernet address. So while qfe0 eventually rejected the packets that it could see, it had to walk through much kernel code to get to that point - consuming CPU cycles and incrementing kstats. (a clue from the nicstat output was that qfe0 was receiving but not sending - so it wasn't taking part in a connection).

I unplugged qfe0 and the problem vanished. Easy. However associating CPU load with a down interface is far from easy!

...

As an aside, I also ask how we measure how utilised the network interfaces are. Very few people have been able to answer this - and it is a topic I hope chapter 7 of this book will increase awareness for. (eg, nicstat or sysperfstat from the K9Toolkit).

Solaris Performance and Tools

2006-08-08T10:04:00.000-07:00

Both Solaris Internals 2nd Edition and Solaris Performance and Tools are available to purchase, and copies have now began arriving around the World. They are both incredible books, covering an enormous range of topics with details not found anywhere else.

During my years working in the field of performance, I've taught numerous performance classes for Sun Microsystems where I gained both the experience and understanding of how to best teach performance. I have also written numerous open source programs for performance monitoring, such as tools in the DTraceToolkit and the K9Toolkit. It was a privilege to share the best of my performance knowledge and teaching experience by co-authoring Solaris Performance and Tools with Richard and Jim. We were fortunate to have many other subject matter experts also contribute to this book, including Mike Shapiro and Jon Haslam.

For Solaris Performance and Tools, it is exciting to see a book that covers both DTrace and mdb in detail, with practical examples. And Solaris Internals 2nd Edition is fascinating for understanding the kernel, with the numerous Solaris 10 enhancements. I hope people enjoy them both.

Solaris Internals 2nd Edition - available!

2006-07-23T23:25:00.000-07:00

Great news! Solaris Internals 2nd Edition is now available to purchase from sites such as Amazon. Amazon writes "Availability: Usually ships within 24 hours" - so in less than a day (I imagine a business day, if you are in the US), you could be holding this landmark book.

I've studied this edition from cover to cover, and it is incredible to see such a wide range of topics covered well, and at such a unique depth. It is the reference for the Solaris 10 and OpenSolaris kernel, and is written in an endearing way that makes this enormous topic very approachable.

I can't wait to get my hard copy of this book. I really enjoyed studying the content the first time, and I'll really enjoy revisiting the chapters.

2006-07-18T05:50:00.000-07:00

DTrace Slides

The slides I used for the recent DTrace Workshop in London have been put online by Context-Switch. This DTrace presentation covers my own method of teaching DTrace, which begins with a summary of performance monitoring tools in Solaris 9 and their limitations.

The slides also document many of the strategies I use for DTrace analysis, and is the first time they have been listed together online. They are,

DTrace Strategies

Snoop or Summary

Drill Down Analysis

Frequency Count

Known Count

Aggregate Stacks

Elapsed Time

On-CPU Time

Milestones

See chapters 5 and 10 from the slides for details.

The slides are used in conjunction with additional live demonstrations and student labs. They also assume that the almost released book, Solaris Performance and Tools can be used as a reference.

2006-06-27T19:28:00.000-07:00

Offline

I've been mostly offline for a few weeks, and this will continue for a few more. I'm in the middle of at 6 weeks of travel (London, London, Perth, Canberra, Melbourne, Tokyo, ...?), much of which is spent at hotels without Internet access or at airports (and all of it without access to my DTrace development servers at home, in Sydney).

By a stroke of luck I am actually in Sydney on the 6th of July (inbetween flights), and should be at the next meeting for SOSUG.

2006-05-31T09:12:00.001-07:00

DTraceTazTool - alpha release

Several years ago, Richard McDougall wrote taztool - a GUI to display disk activity in an amazing and intuitive way. It used TNF trace data - a predecessor of DTrace.

In Janurary 2006 I began writing a DTrace version of taztool: DTraceTazTool. I wrote it using GTK and DTrace. Since then, the DTrace JNI has been released, and I've paused developing DTraceTazTool until I've taken a long look at Java 1.5. Until then, I'm releasing where I am at with the GTK/C version, on my DTrace website.

This is an alpha release - I'm still adding functionality, working through a todo list and fixing bugs. I'm releasing it early as it is already somewhat useful, and a great demo of DTrace. Probably the next feature I'll add is the ability to trace an entire disk at a time (rather than per-slice).

The following screenshot shows a UFS file system that was archived using the tar command. For the top plot: the requested block location is on the Y-axis, time is the X-axis, and the colour reflects the number of requests for that location (many == red). The bottom plot shows maximum and average seek distance.

DTraceTazTool already has some tunable options, such as the size of the pixels drawn and the sample rate,

DTraceTazTool needs to either run as root, or as a user with the dtrace_kernel privilege.

I hope you enjoy the tool so far. I'll post about updates as I complete them.

2006-05-28T10:14:00.000-07:00

Book Updates

Jim did post an entry about Solaris Internals 2nd edition and Sun Performance and Tuning. We are all now eagerly awaiting the publication of these books.

An article about these books was posted on sunflash.sun.com (login required), a website of Sun events.

And some updates were made to the Prentice Hall website for these books (Solaris Internals 2nd edition, Sun Performance and Tools).

2006-05-28T08:29:00.000-07:00

DTracing Scheduling Classes

I've recently been working on some new killer DTrace scripts, and the DTrace UK Workshops. I thought I'd take a break and share something interesting.

The following is from the DTraceToolkit, and is one of my favourite tool example files (Docs/Examples/priclass_example.txt). I'm a firm believer in providing examples, and plan to enhance the existing examples in the toolkit further. There also seems to be a trend to include more examples in Solaris man pages (such as zfs and zpool), which is great to see.

The following is a demonstration of the priclass.d script.

The script was run for several seconds then Ctrl-C was hit. During this time, other processes in different scheduling classes were running.

# ./priclass.d
Sampling... Hit Ctrl-C to end.
^C

  IA
           value  ------------- Distribution ------------- count
              40 |                                         0
              50 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 30
              60 |                                         0

  SYS
           value  ------------- Distribution ------------- count
             < 0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  4959
               0 |                                         0
              10 |                                         0
              20 |                                         0
              30 |                                         0
              40 |                                         0
              50 |                                         0
              60 |                                         30
              70 |                                         0
              80 |                                         0
              90 |                                         0
             100 |                                         0
             110 |                                         0
             120 |                                         0
             130 |                                         0
             140 |                                         0
             150 |                                         0
             160 |                                         50
          >= 170 |                                         0

  RT
           value  ------------- Distribution ------------- count
              90 |                                         0
             100 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 110
             110 |                                         0

  TS
           value  ------------- Distribution ------------- count
             < 0 |                                         0
               0 |@@@@@@@@@@@@@@@                          2880
              10 |@@@@@@@                                  1280
              20 |@@@@@                                    990
              30 |@@@@@                                    920
              40 |@@@@                                     670
              50 |@@@@                                     730
              60 |                                         0

The output is quite interesting, and illustrates neatly the behaviour of different scheduling classes.

The IA interactive class had 30 samples of a 50 to 59 priority, a fairly high priority. This class is used for interactive processes, such as the windowing system. I had clicked on a few windows to create this activity.

The SYS system class has had 4959 samples at a < 0 priority - the lowest, which was for the idle thread. There are a few samples at higher priorities, including some in the 160 to 169 range (the highest), which are for interrupt threads. The system class is used by the kernel.

The RT real time class had 110 samples in the 100 to 109 priority range. This class is designed for real-time applications, those that must have a consistant response time regardless of other process activity. For that reason, the RT class trumps both TS and IA. I created these events by running "prstat -R" as root, which runs prstat in the real time class.

The TS time sharing class is the default scheduling class for the processes on a Solaris system. I ran an infinite shell loop to create heavy activity, "while :; do :; done", which shows a profile that leans towards lower priorities. This is deliberate behaivour from the time sharing class, which reduces the priority of CPU bound processes so that they interefere less with I/O bound processes. The result is more samples in the lower priority ranges.

2006-05-08T22:11:00.000-07:00

Ged - GUI-ed

I've just uploaded Ged to the Specials collection - it is a GUI front-end to the "ed" line editor, and has been written for Java 1.5 using Swing. It enhances "ed" in several ways, such as providing optional themes, sound effects, and a stunning splash screen rendered in POV-ray.[1]

ok, the real reason I'm coding in Java/Swing is to test drive the new Java 1.5 features and the Swing API. I've coded in Java before, however the last few years I've been using mostly Shell, Perl, C and DTrace. There are some really great features in Java 1.5 to try out. I'm also planning on writing some more freeware GUI-based programs; such as performance monitoring tools (DTrace) and Games.

In the past I've coded in OSF/Motif, GTK 2.0, Java/AWT and now Java/Swing. It's hard to choose a single winner - they each have different pros and cons; however I do like coding in both GTK and Swing.

For now, enjoy Ged. No, I didn't write "ed" itself in Java - it borrows /bin/ed. Of course - I could write "ed" entirerly in Java, which would make Ged more portable, but there are higher things on my todo list!

[1] which was then mutilated by downsampling to "classic" 2-bit colour.

2006-04-25T09:39:00.000-07:00

Learn DTrace @ London

During the past five years I've delivered many training events across Australia and Asia; however this will be my first event in Europe.

I will be delivering two 3-day classes near the London area (Egham), from June 7th-9th and June 12th-14th, 2006. The website is here, and seats are currently available (but won't be forever).

These are special classes that will cover not only DTrace, but most importantly the "DTrace Mentality" - strategies used to tackle problems, and a workshop of mystery problems to practice on. I'll also discuss the DTraceToolkit and other performance tools.

There are currently no plans to run these classes again, so as far as I know - this is it.

I'm really looking forward to these events. And beforehand, please think of what problems have stumped you in the past on Solaris - especially statistics that you were unable to measure, so that you can ask me in person. If I can't answer it, I'll try to write the script that can. And if the script is useful, it may end up in the DTraceToolkit!

2006-04-25T08:05:00.000-07:00

DTraceToolkit ver 0.96

I've just uploaded the latest build of DTraceToolkit, which now contains 104 scripts!

12 scripts have been added and 46 scripts were updated - this is a BIG revision. Since there have been so many new changes, I'm holding the version number below 1.00 until the dust has settled (I was keeping version number equal to the script count, however I'll hold back on that for a while).

This is the first rev to include a few scripts written by other people - Richard McDougall and Jonathan Adams, who can both write DTrace well and more importantly, have an exceptional understanding of subtle kernel nuances.

This rev has had another small style change (which is why so many scripts were updated). I've also began writing a document called the "DTraceToolkit Style Guide", which documents the style and programming best practices used by the scripts in the toolkit. I'll post more about that later.

Stefan Parvu helped out with platform testing, which is crucial. Some of the tcp scripts had began not working on newer builds (since they are fbt based, and fbt is not a stable interface (and not supposed to be)). They have been fixed (for now!).

As usual, check locations such as Docs/Examples for examples of the newly added scripts in action. Enjoy!

2006-04-19T05:36:00.000-07:00

Tokyo, Japan

A few weeks ago I was in Tokyo to deliver a couple of Solaris 10 events for Sun. It was the time of year for cherry blossoms, and a great time to take photos. I've just added a series of them to the cityscapes on my website.

2006-04-04T20:25:00.000-07:00

Solaris Internals 2nd Edition

This book (now 2 volumes) has been sent to the publisher!

Jim and Richard have again made a remarkable effort to create a unique and valuable reference. It covers an incredible range of topics, each with useful explinations you won't find anywhere else.

Richard has posted an entry to describe the books, and links to their tables of contents.

I'm very proud to have helped out, including authoring material for the 2nd volume. For many years I've taught Solaris performance classes for Sun, engaged in Solaris performance consulting, and more recently written freeware performance tools - such as the DTraceToolkit. It's been a privilege to share my most useful knowledge in this way.

I have provided scripts inline (listing the source) wherever possible - giving the reader the choice of either using the script, or reading and understanding the script internals - and making their own customisations. We do often discuss such tool internals - which is appropriate for Solaris Internals.

I've also carefully studied both volumes in detail - and it is truly incredible what they cover. This will open the lid on many new topics that have previously not been discussed or exposed. Other engineers and experts have helped out, providing many valuable insights - especially when discussing technology that they themselves created.

I think this has a wider audience than the first edition as we discuss topics closer to home for sysadmins, support staff and developers - such as performance observability and debugging. Check the table of contents for the second volume to see what I mean.

It's now up to the publisher to print out the book. If there is any news on this we can share, we will. Check our blogs (Richard, Jim, and me).

I've been somewhat quiet on the OpenSolaris scene during the last several weeks - this is why! I'm now "back" :)

2006-02-13T16:24:00.000-08:00

Learn DTrace, visit Sydney

Sun is borrowing me to deliver a 3-day DTrace class in Sydney, starting on the 6th of March (assuming enough students sign up). I love DTrace, and teaching it on behalf of Sun is a great privilege.

Occasionally, Australian IT workers will be lucky enough to visit the US (or elsewhere) to attend unique training classes. Classes that aren't taught anywhere else in the World. While it's no holiday (it can be hard work), it does make for a fantastic break from sitting behind a desk day after day (or sitting in a cold server room).

Please let me return the favour and give you an excuse to visit Sydney, Australia! Where else in the World will you be taught DTrace from the author of the DTraceToolkit?

I have taught DTrace before: be prepared for some really intense training! We usually drink lots of coffee, finish later than usual, and cover a lot more than is in the notes. I encourage students to bring in their work problems and get me to solve them (live, in front of the class!).

Ok, I know many companies may choke at the thought of paying for flights to Australia + hotel + training. But if you do wangle it, then I'll see you on the 6th (and the weather is usually great that time of year. ;)

2006-02-07T19:22:00.000-08:00

OpenSolaris Games

The OpenSolaris Games community has opened. It exists to list games, provide install instructions, develop new games, and to give us an excuse to play games.

There are tons of games out there that will work on OpenSolaris. These include RougeLike games, such as NetHack, Angband, ZAngband, ToME, etc, and ports of the Doom engine. I've linked to a modest collection on the website, which will gradually grow as others help out.

Please post game URLs to the mailing list, and help out where you can. There are many games and many genres, and to cover them properly on a website will need a lot of help from the OpenSolaris community.

So far, most of the games are hosted on Blastwave - thanks to Dennis and team for making them available.

...

I have actually written games in the past, although they wern't very good games. These include xpong written entirerly in dtksh, and a port of "Hunt the Wumpus" as an mdb loadable module. I'm also helping with other projects to write decent games, including a curses based shoot-em-up written by Boyd; more on that later.

2006-01-27T02:55:00.000-08:00

checkcable 0.95

checkcable has been updated. It now uses the Perl library Sun::Solaris::Kstat again, where possible. The first version did this for all cards, but the Kstat data wasn't reliable and sadly I had to wrap ndd instead (boring!).

If you haven't seen it before, checkcable produces the following output,

   # checkcable
   Interface   Link Duplex  Speed  AutoNEG
   hme0          UP   FULL    100       ON

It has been written to support dmfe, bge, ce, rtls, ge, hme, and a few others. It occasionally gets updated to support extra cards (see the HISTORY list). Many people have emailed me about this program over the years - thanks for your support. If you do send me updates to the code, please follow the style. These days I'm following "Perl Best Practices" by O'Reilly (yes Mark, you've guilted me into it :-).

In similar news, Alan has been working on bringing Kstat.pm into the OpenSolaris build, which all of my Sun::Solaris::Kstat tools use. Thank you Alan!

2006-01-11T07:59:00.000-08:00

Brendan Clones

Recently James Dickens figured out that I'm a member of a family of Brendan clones, and suggested that there may be 1000 Brendan clones in Australia. Now that the cat's out of the bag, let me clear up a few things and introduce the gang. Firstly, there isn't 1000 of us - it's more like a dozen, however the number does vary. The following is a photo of 7 Brendan clones busy working.

Sitting on the close left is documentation Brendan, and on the far left is testing Brendan - who is always busy testing programs in a variety of scenarios. Documentation Brendan takes the most interesting tests from testing Brendan and turns them into example documentation. Documentation Brendan also sometimes answers emails when email Brendan is travelling for work (as is the case here).

On the close right is programmer Brendan hard at work typing code. Sitting on the far right is creative Brendan, making suggestions to programmer Brendan. Creative Brendan maintains the enormous todo list for all the Brendan clones.

Sitting under the desk reading is study Brendan, who is currently studying "Solaris Systems Programming" by Rich Teer. Study Brendan is always reading, and reads textbooks from cover to cover. If he isn't careful he may need to get glasses (or borrow them from engineer Brendan, who isn't pictured here).

Sleeping on the floor is sleeping Brendan, who sleeps on behalf of all the Brendan clones.

Standing with the cricket bat is master Brendan, who creates Brendan clones and destroys the ones not working hard enough. Programmer Brendan calls him "homicidal maniac Brendan", and only gets away with it as he works so hard.

Out of shot is TV Brendan, watching the Australia vs South Africa test cricket series. And (of course) photographer Brendan is taking the photo.

2006-01-11T07:11:00.000-08:00

DTraceToolkit ver 0.92
I've just uploaded the latest version of the DTraceToolkit. A number of niggling issues have been fixed, and a few scripts added.

The next few releases should be about polishing other components of the toolkit - such as documentation and examples, rather than simply adding more scripts.

I hope you find the toolkit useful.

2006-01-10T01:51:00.000-08:00

findbill

I just made a quick update to findbill, a simple Perl program that scans a disk to find where backup UFS superblocks are. Most of the time sysadmins use "newfs -N" for this - however if you have tuned file system parameters "newfs -N" doesn't always work.

The output now includes information from the superblocks: last write time and mountpoint, if available. This should help identify what are false positives - such as older superblocks from a previous filesystem that haven't been overwritten.

# findbill /dev/rdsk/c0d0s3
Searching /dev/rdsk/c0d0s3,

Type     Block    Time last written         Mountpoint
UFS      16       Sun Jan  8 16:11:42 2006  /extra1
UFS      32       Sun Apr 17 18:28:54 2005
UFS      32352    Sun Apr 17 18:28:54 2005
UFS      64672    Sun Apr 17 18:28:54 2005
UFS      96992    Sun Apr 17 18:28:54 2005
UFS      129312   Sun Apr 17 18:28:54 2005
UFS      161632   Sun Apr 17 18:28:54 2005
UFS      193952   Sun Apr 17 18:28:54 2005
^C

It's called "findbill" as I've heard the UFS magic number (0x011954, which we scan for) is either Bill Joy's or Marshall Kirk McKusick's birthday (the FFS authors). The UFS cylinder block magic number (0x090255) looks suspicious too.

findbill also identifies superblocks from MTB_UFS - the revamped UFS for the world of terabyte filesystems (UFS lives!).

2006-01-04T22:29:00.000-08:00

3d Photos

I've uploaded new photos to my website, including some of San Francisco and the Grand Canyon. I've also uploaded a few 3d anaglyphs (red/cyan glasses) taken at Beijing,

I created these anaglyphs using the freeware tool AnaBuilder, and are available in full resolution (downsampling anaglyphs can sometimes cause odd JPEG artifacts). Anaglyphs may give way to autostereo displays in the future (no glasses required), or even VR displays if they ever take of, so keep hold of the original left/right pair. In the meantime anaglyphs are fine.

Hopefully I'll inspire others to try 3d photography. :-)

2005-12-10T22:30:00.000-08:00

Solaris Performance Metrics

I've uploaded the first paper in a series I'm writing on Solaris performance monitoring metrics, it covers "disk utilisation by process" (AKA "utilization"). I've also created a website where the paper can be downloaded, and a cover photo,

... Which readers of Sun Performance and Tuning may find familiar. :-)

While writing freeware such as the DTraceToolkit, I'm often asked to explain the performance metrics I've choosen in greater detail. These papers will serve as a reference that I can point people to.

I began writing these over a year ago, before I had access to the kernel code. I liked to believe that it wasn't such a problem, yet with hindsight it was. The OpenSolaris project and being able to read through kernel code, has really made writing these documents possible!

2005-12-04T05:57:00.000-08:00

Advanced DTrace Video

To see Bryan Cantrill speak about various advanced DTrace topics, see the recent SOSUG (Sydney OpenSolaris User Group) videos that Alan organised to have put online. You'll also find a ZFS presentation by James.

In other news, I just uploaded the DTraceToolkit version 0.89, which has had a few changes to the way TCP is measured.

2005-11-30T09:49:00.000-08:00

DTraceToolkit 0.88

I've just uploaded the latest version of the DTraceToolkit, version 0.88 (88 scripts). I've updated the OpenSolaris DTraceToolkit site to point to the new version. This version has many updated scripts and a few new ones.

Between 0.80 and 1.00 I'll be doing more work revisiting code and retesting code rather than adding scripts.

2005-11-30T09:38:00.000-08:00

Homepage

Let me explain what is going on with my homepage URL for future reference.

My homepage is at http://www.brendangregg.com. It's a DNS pointer that points to wherever my homepage actually lives, which may well change - however my name will not!

And yes, it is likely that my actual homepage may move at some point. Some people have experienced DNS problems with the current location (users.tpg.com.au), and I've just uploaded a new DTraceToolkit and have almost run out of space!,

1070 files used (10%) - authorized: 10000 files
30688 Kbytes used (99%) - authorized: 30720 Kb

If you've linked to www.brendangregg.com, then no problem - it will always point to the right place (which is why I have the thing - I have been through a painful website move in the past).

2005-11-29T23:52:00.000-08:00

Sys Admin Magazine

The December, 2005 copy contains an article on the DTraceToolkit written by Ryan Matteson. Grab a copy! The article is "Observing I/O Behavior with the DTraceToolkit", and is quite good. It was also selected as the feature article - which means it will be available online for some time,

http://www.samag.com/documents/sam0512a/

Thanks Matty, and Sys Admin Magazine!

2005-11-24T09:25:00.000-08:00

DTrace Translators

While teaching a DTrace class in Sydney, I've been asked about translators. They are quite useful, so I've prepared the following as a quick demo.

This is a DTrace program to trace the time() syscall, print the process, it's parent, it's grand-parent, and so on.

#!/usr/sbin/dtrace -s

/* Declare Translator */

typedef struct ancestory {
        string me;              /* my cmd */
        string p;               /* parent cmd */
        string gp;              /* grand-parent cmd */
        string ggp;             /* great-grand-parent cmd */
        string gggp;            /* great-great-grand-parent cmd */
} ancestory_t;

translator ancestory_t < struct _kthread *T > {

        /* fetch my details */
        me = T->t_procp->p_user.u_comm;

        /* fetch anscestor details if they exist */
        p = T->t_procp->p_parent != NULL ?
            T->t_procp->p_parent->p_user.u_comm :
            "<none>";
        gp = T->t_procp->p_parent != NULL ?
            T->t_procp->p_parent->p_parent != NULL ?
            T->t_procp->p_parent->p_parent->p_user.u_comm :
            "<none>" : "<none>";
        ggp = T->t_procp->p_parent != NULL ?
            T->t_procp->p_parent->p_parent != NULL ?
            T->t_procp->p_parent->p_parent->p_parent != NULL ?
            T->t_procp->p_parent->p_parent->p_parent->p_user.u_comm :
            "<none>" : "<none>" : "<none>";
        gggp = T->t_procp->p_parent != NULL ?
            T->t_procp->p_parent->p_parent != NULL ?
            T->t_procp->p_parent->p_parent->p_parent != NULL ?
            T->t_procp->p_parent->p_parent->p_parent->p_parent != NULL ?
            T->t_procp->p_parent->p_parent->p_parent->p_parent->p_user.u_comm :
            "<none>" : "<none>" : "<none>" : "<none>";
};

inline ancestory_t *ancestors = xlate <ancestory_t *> (curthread);

/* Main Program */

syscall::gtime:entry
{
        printf("%s, %s, %s, %s, %s", ancestors->me,
            ancestors->p, ancestors->gp, ancestors->ggp, ancestors->gggp);
}

The main program at the end is quite consise, it prints the details from "ancestors". The translator has walked the p_parent pointers carefully, returning "<none>" if the pointer is NULL. ("ancestors->me" is unnecessary since we have "execname", I've included it as a simple demonstration).

The output is,

# ./transdemo.d
dtrace: script './transdemo.d' matched 1 probe
CPU     ID                    FUNCTION:NAME
  0   6615                      gtime:entry bash, sh, bash, sshd, sshd
  0   6615                      gtime:entry date, bash, sh, bash, sshd
  0   6615                      gtime:entry bash, sh, bash, sshd, sshd
  0   6615                      gtime:entry nscd, init, sched, <none>, <none>
  0   6615                      gtime:entry nscd, init, sched, <none>, <none>
  0   6615                      gtime:entry nscd, init, sched, <none>, <none>
  0   6615                      gtime:entry nscd, init, sched, <none>, <none>
[...]

Without our careful pointer tests, the NULL parent pointers would have caused DTrace to print errors rather than our "<none>" keywords.

The "Declare Translator" section can be cut-n-pasted into a new .d file in /usr/lib/dtrace (eg, /usr/lib/dtrace/anscestors.d) where it will be automatically imported by every future DTrace script.

Take a look under /usr/lib/dtrace at the existing translator scripts, they are quite fascinating.

2005-11-19T19:55:00.000-08:00

ZFS

The doors have been flung open for ZFS, Sun's "last word in filsystems". It's now in OpenSolaris and there is a ZFS Community page where you can find introductions, demonstrations, and advanced discussions. We don't know when ZFS will appear in Solaris 10, but for it to appear in OpenSolaris shows that the process has began.

ZFS raises the bar for filesystems to a new height, and even changes the way you think about filesystems. Let me provide a quick demo, although I don't have an array of spare disks handy - you'll need to pretend that each of these 1 Gb slices is actually a seperate disk,

# zpool create apps mirror c0t1d0s0 c0t1d0s1 mirror c0t1d0s3 c0t1d0s4

That's it - 1 command for a ZFS pool, that is both mirrored and dynamically striped (think RAID 1+0), 256 bit checksum'd, remounted on boot, and can be grown to a virtually unlimited size.

Lets run a few status commands to check it worked.

# zpool list
NAME                    SIZE    USED   AVAIL    CAP  HEALTH     ALTROOT
apps                   1.98G   33.0K   1.98G     0%  ONLINE     -
#
# zpool status
  pool: apps
 state: ONLINE
 scrub: none requested
config:

        NAME          STATE     READ WRITE CKSUM
        apps          ONLINE       0     0     0
          mirror      ONLINE       0     0     0
            c0t1d0s0  ONLINE       0     0     0
            c0t1d0s1  ONLINE       0     0     0
          mirror      ONLINE       0     0     0
            c0t1d0s3  ONLINE       0     0     0
            c0t1d0s4  ONLINE       0     0     0
#
# df -h -F zfs
Filesystem             size   used  avail capacity  Mounted on
apps                   2.0G     8K   2.0G     1%    /apps

The size of 2 Gb is correct, and the "zpool status" command neatly prints the layout.

Now perhaps a slightly more realistic demo (although still no seperate disks, sorry). Rather than having all the disks combine to one filesystem, ZFS is really intended to combine disks into pools, and then have multiple filesystems share a pool. The following quick demo shows this,

# zpool create fast mirror c0t1d0s0 c0t1d0s1 mirror c0t1d0s3 c0t1d0s4
# zfs create fast/apps
# zfs create fast/oracle
# zfs create fast/home
# zfs set mountpoint=/export/home fast/home
# zfs set compression=on fast/home
# zfs set quota=500m fast/home
# zfs list
NAME                   USED  AVAIL  REFER  MOUNTPOINT
fast                  91.0K  1.97G   9.5K  /fast
fast/apps                8K  1.97G     8K  /fast/apps
fast/home                8K   500M     8K  /export/home
fast/oracle              8K  1.97G     8K  /fast/oracle

Each filesystem may have different options set, such as quotas, reservations and compression. If a filesystem was running out of space, quotas can be changed live with a single command. If the pool was running out of space, disks can be added live with a single command.

As a programmer there are times when you encounter something that is so elegant and obvious that you are struck with a feeling that it is right. For a moment you can clearly see what the developer was thinking and that they achieved it perfectly. ZFS is one of those moments.

2005-10-08T21:16:00.000-07:00

Network Monitoring

The network often gets blamed for performance issues in Solaris. How busy are your network interfaces? How do you find out?

Many sysadmins are using "netstat -i" and looking at packet counts. Packet counts turn out to be not as useful as they seem - you don't know if they are big packets or small packets, so you really don't how utilised the network interface is.

I've written an website on network monitoring, to cover how to discover what is really happening on your network. To do this I use a variety to tools, including some based on Kstat and DTrace.

2005-09-26T00:52:00.000-07:00

mdb ::wumpus

I've added another program to the "specials" page - a site of, erm, quite special software indeed.

It's a loadable module for the Solaris Modular Debugger command. It provides a new dmcd "::wumpus". A screenshot should say all,

# mdb
> ::load wumpus
> ::wumpus
INSTRUCTIONS (Y-N)
?N
HUNT THE WUMPUS

I SMELL A WUMPUS!
BATS NEARBY!
YOU ARE IN ROOM 17
TUNNELS LEAD TO 7 16 18      

SHOOT OR MOVE (S-M)
?

It uses the code from ESR's classic wumpus clone. (I checked with him to make sure he didn't mind wumpus being ported to such an unusual place).

If you haven't seen "Hunt the Wumpus" before, it's a classic text game originally written in BASIC.

2005-09-26T00:44:00.000-07:00

DTraceToolkit 0.84

The latest version of the DTraceToolkit has been uploaded. Visit the OpenSolaris
DTraceToolkit site to download it.

Since version 0.82 I've updated several scripts and added a couple. Between now and version 1.00 there will be an emphasis on revisiting code, enhancing existing programs and writing more documentation.

2005-08-27T20:03:00.000-07:00

APC

Australian Personal Computer magazine is Australia's leading computer magazine, with the first issue printed in 1980. It's especially popular with PC or Windows enthusiasts, or those who work in that industry. People in the Unix, Linux or Solaris community don't seem to read it as much.

Recently I wrote a workshop for the September issue that gave a detailed summary of configuring networking in Solaris 10. Networking has changed in Solaris 10, and it was great to cover what's new and how to use it (including SMF, ipnodes and IP Filter). I've spoken to a number of Solaris people about the article and most of them are suprised - APC is running articles on Solaris?

Yes, APC is running articles on Solaris! And Linux, and Unix in general.

APC July 2005 included Solaris 10 on the cover DVD, and a workshop to cover installing Solaris 10 and Windows, duel boot.

APC August 2005 had an article on the future of chip technologies, covering Sun's Niagara CPU.

APC September 2005 included a workshop on configuring networking on Solaris 10.

If you aren't reading it and you live in Australia (or can arrange mail subscription?) it may well be worth a look. http://www.apcmag.com

2005-06-27T05:19:00.000-07:00

DExplorer

I've just uploaded dexplorer ver 0.75, and it's shaping up to be quite a useful tool.
It runs a series of DTrace scripts that monitor generic system activity, and saves the output in a .tar.gz file with a meaningful structure,

http://www.opensolaris.org/os/community/dtrace/dexplorer
http://www.brendangregg.com/dtrace.html#DExplorer

The idea came from David Visser, Christopher Wells, and several other guys I met while in Melbourne, Australia last week. It's a great idea - it makes a lot of sense.

Here I've expanded a .tar.gz file created by dexplorer to demo the contents,

# find de_jupiter_200506272230 -type f
de_jupiter_200506272230/Cpu/interrupt_by_cpu
de_jupiter_200506272230/Cpu/interrupt_time
de_jupiter_200506272230/Cpu/dispqlen_by_cpu
de_jupiter_200506272230/Cpu/sdt_count
de_jupiter_200506272230/Disk/pgpgin_by_process
de_jupiter_200506272230/Disk/fileopen_count
de_jupiter_200506272230/Disk/sizedist_by_process
de_jupiter_200506272230/Mem/minf_by_process
de_jupiter_200506272230/Mem/vminfo_by_process
de_jupiter_200506272230/Net/mib_data
de_jupiter_200506272230/Net/tcpw_by_process
de_jupiter_200506272230/Proc/sample_process
de_jupiter_200506272230/Proc/syscall_by_process
de_jupiter_200506272230/Proc/syscall_count
de_jupiter_200506272230/Proc/readb_by_process
de_jupiter_200506272230/Proc/writeb_by_process
de_jupiter_200506272230/Proc/sysinfo_by_process
de_jupiter_200506272230/Proc/newprocess_count
de_jupiter_200506272230/Proc/signal_count
de_jupiter_200506272230/Proc/syscall_errors
de_jupiter_200506272230/Info/uname-a
de_jupiter_200506272230/Info/psrinfo-v
de_jupiter_200506272230/Info/prtconf
de_jupiter_200506272230/Info/df-k
de_jupiter_200506272230/Info/ifconfig-a
de_jupiter_200506272230/Info/ps-o
de_jupiter_200506272230/Info/uptime
de_jupiter_200506272230/log

Lots of goodies to pick over.

The names of the files should indicate their contents. Many of them contain quite generic data, the idea is that one dexplorer file should contain as many statistics as possible.

Check for updates. I'll also throw it in the DTraceToolkit.

2005-06-26T01:11:00.000-07:00

Created This

G'Day,

Back in 1996 I created a personal website to host various stuff, including artwork I had created using Povray. It also contained a message board called "The Wall", inspired by message boards I had been using on BBSes. People thought it was a dumb idea, some even horrified with the audacity of a personal website. I deleted it. Times have changed - personal websites are now more acceptable, and message boards or "blogs" are commonplace. "The Wall" is back.

Recently I have been doing various tricks with code, especially DTrace and OpenSolaris, and a blog seems like a useful way to share them. You'll probably find postings on computer programming languages including C, Perl, shell scripting and DTrace, plus various other topics of interest - AI programming, photography, rocketry, engineering, particle physics, beer, gaming, etc.

I'll try to get to the point. I'll also try to spell correctly. :-)

Enjoy.

Brendan

[Sydney, Australia]