Skip to content
This repository has been archived by the owner on Apr 22, 2024. It is now read-only.

Commit

Permalink
Initial commit.
Browse files Browse the repository at this point in the history
  • Loading branch information
nickbruun committed Nov 11, 2014
0 parents commit 3f21c2d
Show file tree
Hide file tree
Showing 3 changed files with 271 additions and 0 deletions.
9 changes: 9 additions & 0 deletions Makefile
Original file line number Diff line number Diff line change
@@ -0,0 +1,9 @@
PREFIX ?= /usr/local

all: osxkerneltracer

osxkerneltracer: main.go
go build -o osxkerneltracer .

install: osxkerneltracer
install osxkerneltracer "$(PREFIX)/bin/osxkerneltracer"
44 changes: 44 additions & 0 deletions README.md
Original file line number Diff line number Diff line change
@@ -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
218 changes: 218 additions & 0 deletions main.go
Original file line number Diff line number Diff line change
@@ -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)))
}
}

0 comments on commit 3f21c2d

Please sign in to comment.