diff --git a/Makefile b/Makefile new file mode 100644 index 0000000..b38a79e --- /dev/null +++ b/Makefile @@ -0,0 +1,9 @@ +PREFIX ?= /usr/local + +all: osxkerneltracer + +osxkerneltracer: main.go + go build -o osxkerneltracer . + +install: osxkerneltracer + install osxkerneltracer "$(PREFIX)/bin/osxkerneltracer" diff --git a/README.md b/README.md new file mode 100644 index 0000000..968bd7a --- /dev/null +++ b/README.md @@ -0,0 +1,44 @@ +# Mac OS X kernel tracer + +When the Mac OS X Mach kernel starts vomiting uncontrollably, dtrace is the tool of choice for getting a sniff of what's going on. However, when things actually do go wrong, the last thing you want to need doing is to be typing in dtrace commands from your phone. Based on Brendan Gregg's excellent [hotkernel](http://www.brendangregg.com/DTrace/hotkernel), `osxkerneltracer` makes it easy to get a sampling call trace dump from your kernel. + +## Building and running + +`osxkerneltracer` is written in Go and therefore needs the Go toolchain to compile. If you're any kind of power user, [Homebrew](http://brew.sh/) will get you there in a jiffy. Building and installing the application is then a simple call to `make` away: + + $ make all install + +Getting a trace is now simple when your system goes AWOL, but remember that root privileges are required for tracing the kernel: + + $ sudo osxkerneltracer + +The output will look something like the following: + + Module | Method | Calls | Share + -------+----------------------------+-------+----------- + kernel | machine_idle+0x1fd | 72179 | 98.5271 % + kernel | 0xffffff8013552880+0x313 | 349 | 0.4764 % + vmmon | Task_Switch+0xed1 | 169 | 0.2307 % + kernel | processor_idle+0xc5 | 127 | 0.1734 % + kernel | processor_idle+0xb4 | 30 | 0.0410 % + kernel | ipc_mqueue_post+0x227 | 22 | 0.0300 % + kernel | 0xffffff8013552880+0x3bf | 18 | 0.0246 % + kernel | machine_idle+0x1ff | 11 | 0.0150 % + kernel | thread_block_reason+0xbe | 10 | 0.0137 % + kernel | lck_mtx_lock_spin+0x28 | 9 | 0.0123 % + kernel | processor_idle+0xab | 8 | 0.0109 % + kernel | thread_continue+0x43 | 8 | 0.0109 % + kernel | vnode_iterate+0x1e9 | 8 | 0.0109 % + kernel | processor_idle+0xda | 7 | 0.0096 % + vmmon | Task_Switch+0xf74 | 7 | 0.0096 % + kernel | hfs_lock+0x1f | 6 | 0.0082 % + kernel | processor_idle+0xdf | 6 | 0.0082 % + kernel | thread_call_enter1+0x2b5 | 6 | 0.0082 % + kernel | lck_rw_lock_exclusive+0x24 | 5 | 0.0068 % + kernel | processor_idle+0xbb | 5 | 0.0068 % + kernel | wait_queue_wakeup_all+0xb9 | 5 | 0.0068 % + .. + +If you want to trace a duration other than the default 5 seconds, pass the duration as a flag argument: + + $ sudo osxkerneltracer -d 10s diff --git a/main.go b/main.go new file mode 100644 index 0000000..163df30 --- /dev/null +++ b/main.go @@ -0,0 +1,218 @@ +package main + +import ( + "bytes" + "flag" + "fmt" + "os" + "os/exec" + "regexp" + "sort" + "strconv" + "strings" + "time" +) + +var ( + callsExpr = regexp.MustCompile("^(.*?)`(.*?) (\\d+)$") +) + +// Trace call. +type TraceCall struct { + // Module. + Module string + + // Method. + Method string + + // Calls. + Calls uint64 +} + +// Trace. +type Trace []TraceCall + +// Longest trace method name length. +func (t Trace) LongestMethodNameLength() (l int) { + l = 0 + + for _, c := range t { + cl := len(c.Method) + if cl > l { + l = cl + } + } + + return +} + +// Longest trace module name length. +func (t Trace) LongestModuleNameLength() (l int) { + l = 0 + + for _, c := range t { + cl := len(c.Module) + if cl > l { + l = cl + } + } + + return +} + +// Maximum number of calls for any call in the trace. +func (t Trace) MaximumCalls() (m uint64) { + m = 0 + + for _, c := range t { + if c.Calls > m { + m = c.Calls + } + } + + return +} + +// Total number of calls in the trace. +func (t Trace) TotalCalls() (s uint64) { + s = 0 + + for _, c := range t { + s += c.Calls + } + + return +} + +func (t Trace) Len() int { return len(t) } +func (t Trace) Swap(i, j int) { t[i], t[j] = t[j], t[i] } +func (t Trace) Less(i, j int) bool { + a, b := &t[i], &t[j] + + if a.Calls > b.Calls { + return true + } else if a.Calls == b.Calls { + if a.Module < b.Module { + return true + } else if a.Module == b.Module { + return a.Method < b.Method + } else { + return false + } + } else { + return false + } +} + +func main() { + // Parse arguments. + duration := flag.Duration("d", 5 * time.Second, "trace duration") + flag.Parse() + + // Set up to run dtrace. + cmd := exec.Command("/usr/sbin/dtrace", "-n", ` +#pragma D option quiet +profile:::profile-1001hz +/arg0/ +{ + @pc[arg0] = count(); +} +dtrace:::END +{ + printa("%a %@d\n", @pc); +}`) + + var outputBuffer bytes.Buffer + cmd.Stdout = &outputBuffer + cmd.Stderr = os.Stderr + + // Start running dtrace. + if err := cmd.Start(); err != nil { + os.Stderr.Write([]byte("Failed to start kernel trace\n")) + os.Exit(1) + } + + os.Stderr.Write([]byte(fmt.Sprintf("Running trace for %v...\n", *duration))) + + // Wait for dtrace to either fail or for the trace period to end. + timerChan := time.After(*duration) + errChan := make(chan error) + + go func() { + errChan <- cmd.Wait() + }() + + select { + case <-errChan: + os.Stderr.Write([]byte("Kernel trace failed\n")) + os.Exit(1) + + case <-timerChan: + cmd.Process.Signal(os.Interrupt) + } + + // Wait for the dtrace process to finish running. + if err := <- errChan; err != nil { + os.Stderr.Write([]byte("Kernel trace failed\n")) + os.Exit(1) + } + + // Parse the kernel trace. + outputLines := strings.Split(string(outputBuffer.Bytes()), "\n") + trace := make(Trace, 0, len(outputLines)) + + for _, l := range outputLines { + l = strings.TrimSpace(l) + if l == "" { + continue + } + + m := callsExpr.FindStringSubmatch(l) + if m == nil { + continue + } + + calls, _ := strconv.ParseUint(m[3], 10, 64) + + trace = append(trace, TraceCall{ + Module: m[1], + Method: m[2], + Calls: calls, + }) + } + + // Output the kernel trace. + sort.Sort(trace) + + moduleNameTitle := "Module" + moduleNameWidth := trace.LongestModuleNameLength() + if moduleNameWidth < len(moduleNameTitle) { + moduleNameWidth = len(moduleNameTitle) + } + + methodNameTitle := "Method" + methodNameWidth := trace.LongestMethodNameLength() + if methodNameWidth < len(methodNameTitle) { + methodNameWidth = len(methodNameTitle) + } + + callsTitle := "Calls" + maximumCalls := trace.MaximumCalls() + callsWidth := len(fmt.Sprintf("%d", maximumCalls)) + if callsWidth < len(callsTitle) { + callsWidth = len(callsTitle) + } + + shareTitle := "Share" + shareWidth := 10 + totalCalls := trace.TotalCalls() + + lineFormat := fmt.Sprintf("%%-%ds | %%-%ds | %%%ds | %%%ds\n", moduleNameWidth, methodNameWidth, callsWidth, shareWidth) + fmt.Printf(lineFormat, moduleNameTitle, methodNameTitle, callsTitle, shareTitle) + + fmt.Printf("%s-+-%s-+-%s-+-%s\n", strings.Repeat("-", moduleNameWidth), strings.Repeat("-", methodNameWidth), strings.Repeat("-", callsWidth), strings.Repeat("-", shareWidth)) + + for _, c := range trace { + fmt.Printf(lineFormat, c.Module, c.Method, fmt.Sprintf("%d", c.Calls), fmt.Sprintf("%.4f %%", float32(c.Calls * 100) / float32(totalCalls))) + } +}