MacOSXでプログラムのシステムコールが呼ばれる様を時系列で表示する


dtrussというコマンドを使う。Linuxでいうstraceのようなもの。

## テストプログラム

```
package main

import "fmt"

func main() {
  fmt.Println("Hello, 世界")
}
```

## コンパイラでビルド

```
[go-testcode]$ go build test.go
[go-testcode]$ ./test
Hello, 世界
[go-testcode]$
```

### dtruss を使う

dtruss -a でCPUサイクル,システムコールの経過時間をマイクロ秒で表示する

```
[go-testcode]$ sudo dtruss -a ./test
Password:
fatal error: runtime: bsdthread_register error

runtime stack:
runtime.throw(0x142f95)
	/usr/local/Cellar/go/1.3/libexec/src/pkg/runtime/panic.c:520 +0x69
runtime.goenvs()
	/usr/local/Cellar/go/1.3/libexec/src/pkg/runtime/os_darwin.c:88 +0x62
runtime.schedinit()
	/usr/local/Cellar/go/1.3/libexec/src/pkg/runtime/proc.c:164 +0x76
_rt0_go()
	/usr/local/Cellar/go/1.3/libexec/src/pkg/runtime/asm_amd64.s:91 +0x114
	PID/THRD  RELATIVE  ELAPSD    CPU SYSCALL(args) 		 = return
42864/0x10f0b6:        32      53      0 thread_selfid(0x0, 0x1DC0, 0x7FFF64B85550)		 = 1110198 0
42864/0x10f0b6:        65      15     12 open(".\0", 0x0, 0x1)		 = 3 0
42864/0x10f0b6:        68       4      2 fstat64(0x3, 0x7FFF5FBFF0E0, 0x0)		 = 0 0
42864/0x10f0b6:        74       5      3 fcntl(0x3, 0x32, 0x7FFF5FBFF3A0)		 = 0 0
42864/0x10f0b6:        77       5      2 close(0x3)		 = 0 0
42864/0x10f0b6:        83       7      5 stat64("/Users/HOGEUSER/tmp/go/go/01\0", 0x7FFF5FBFF050, 0x0)		 = 0 0
42864/0x10f0b6:        90       2      0 csops(0x0, 0x0, 0x7FFF5FBFF364)		 = 0 0
42864/0x10f0b6:        91       2      0 issetugid(0x0, 0x0, 0x0)		 = 0 0
42864/0x10f0b6:       123       3      0 shared_region_check_np(0x7FFF5FBFD298, 0x1000, 0x4)		 = 0 0
42864/0x10f0b6:       130       5      3 stat64("/usr/lib/dtrace/libdtrace_dyld.dylib\0", 0x7FFF5FBFE448, 0x7FFF5FBFF380)		 = 0 0
42864/0x10f0b6:       143      13     11 open("/usr/lib/dtrace/libdtrace_dyld.dylib\0", 0x0, 0x0)		 = 3 0
42864/0x10f0b6:       624       8      5 stat64("/usr/lib/libc++.1.dylib\0", 0x7FFF5FBFE258, 0x7FFF5FBFF0F0)		 = 0 0
42864/0x10f0b6:       634       3      2 stat64("/usr/lib/libSystem.B.dylib\0", 0x7FFF5FBFE258, 0x7FFF5FBFF0F0)		 = 0 0
42864/0x10f0b6:       639       2      1 stat64("/usr/lib/libc++abi.dylib\0", 0x7FFF5FBFE158, 0x7FFF5FBFEFF0)		 = 0 0
42864/0x10f0b6:       645       3      2 stat64("/usr/lib/system/libcache.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       650       3      1 stat64("/usr/lib/system/libcommonCrypto.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       654       2      1 stat64("/usr/lib/system/libcompiler_rt.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       658       2      1 stat64("/usr/lib/system/libcopyfile.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       662       2      1 stat64("/usr/lib/system/libcorecrypto.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       666       2      1 stat64("/usr/lib/system/libdispatch.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       670       2      1 stat64("/usr/lib/system/libdyld.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       673       2      1 stat64("/usr/lib/system/libkeymgr.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       677       2      1 stat64("/usr/lib/system/liblaunch.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       681       2      1 stat64("/usr/lib/system/libmacho.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       684       2      1 stat64("/usr/lib/system/libquarantine.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       688       2      1 stat64("/usr/lib/system/libremovefile.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       692       2      1 stat64("/usr/lib/system/libsystem_asl.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       699       2      1 stat64("/usr/lib/system/libsystem_blocks.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       703       2      1 stat64("/usr/lib/system/libsystem_c.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       708       3      1 stat64("/usr/lib/system/libsystem_configuration.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       712       2      1 stat64("/usr/lib/system/libsystem_dnssd.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       716       2      1 stat64("/usr/lib/system/libsystem_info.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       720       2      1 stat64("/usr/lib/system/libsystem_kernel.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       724       2      1 stat64("/usr/lib/system/libsystem_m.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       728       3      1 stat64("/usr/lib/system/libsystem_malloc.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       732       2      1 stat64("/usr/lib/system/libsystem_network.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       737       3      1 stat64("/usr/lib/system/libsystem_notify.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       741       3      1 stat64("/usr/lib/system/libsystem_platform.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       745       3      1 stat64("/usr/lib/system/libsystem_pthread.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       749       3      1 stat64("/usr/lib/system/libsystem_sandbox.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       754       2      1 stat64("/usr/lib/system/libsystem_stats.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       758       2      1 stat64("/usr/lib/system/libunc.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       762       3      1 stat64("/usr/lib/system/libunwind.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       767       3      1 stat64("/usr/lib/system/libxpc.dylib\0", 0x7FFF5FBFDCC8, 0x7FFF5FBFEB60)		 = 0 0
42864/0x10f0b6:       785       2      1 stat64("/usr/lib/libobjc.A.dylib\0", 0x7FFF5FBFCF08, 0x7FFF5FBFDDA0)		 = 0 0
42864/0x10f0b6:       791       2      1 stat64("/usr/lib/libauto.dylib\0", 0x7FFF5FBFCF08, 0x7FFF5FBFDDA0)		 = 0 0
42864/0x10f0b6:       808       3      1 stat64("/usr/lib/libDiagnosticMessagesClient.dylib\0", 0x7FFF5FBFC898, 0x7FFF5FBFD730)		 = 0 0
42864/0x10f0b6:     89501    1074     25 select(0x0, 0x0, 0x0, 0x0, 0x7FFF5FBFFB90)		 = 0 0
42864/0x10f0b6:     89531    1215     28 select(0x0, 0x0, 0x0, 0x0, 0x7FFF5FBFFB90)		 = 0 0
42864/0x10f0b6:     89543      15      9 write(0x2, "fatal error: \0", 0xD)		 = 13 0
42864/0x10f0b6:     89546       4      1 write(0x2, "runtime: bsdthread_register error\0", 0x21)		 = 33 0
42864/0x10f0b6:     89547       2      0 write(0x2, "\n\0", 0x1)		 = 1 0
42864/0x10f0b6:     89549       2      0 write(0x2, "\nruntime stack:\n\0", 0x10)		 = 16 0
42864/0x10f0b6:     89557       2      0 write(0x2, "runtime.throw\0", 0xD)		 = 13 0
42864/0x10f0b6:     89558       2      0 write(0x2, "(\0", 0x1)		 = 1 0
42864/0x10f0b6:     89560       2      0 write(0x2, "0x142f95\0", 0x8)		 = 8 0
42864/0x10f0b6:     89561       1      0 write(0x2, ")\n\0", 0x2)		 = 2 0
42864/0x10f0b6:     89563       2      0 write(0x2, "\t\0", 0x1)		 = 1 0
42864/0x10f0b6:     89564       2      0 write(0x2, "/usr/local/Cellar/go/1.3/libexec/src/pkg/runtime/panic.c\0", 0x38)		 = 56 0
42864/0x10f0b6:     89565       2      0 write(0x2, ":\0", 0x1)		 = 1 0
42864/0x10f0b6:     89566       2      0 write(0x2, "520\0", 0x3)		 = 3 0
42864/0x10f0b6:     89567       1      0 write(0x2, " +\0", 0x2)		 = 2 0
42864/0x10f0b6:     89568       2      0 write(0x2, "0x69\0", 0x4)		 = 4 0
42864/0x10f0b6:     89569       2      0 write(0x2, "\n\0", 0x1)		 = 1 0
42864/0x10f0b6:     89570       2      0 write(0x2, "runtime.goenvs\0", 0xE)		 = 14 0
42864/0x10f0b6:     89571       2      0 write(0x2, "(\0", 0x1)		 = 1 0
42864/0x10f0b6:     89572       2      0 write(0x2, ")\n\0", 0x2)		 = 2 0
42864/0x10f0b6:     89573       2      0 write(0x2, "\t\0", 0x1)		 = 1 0
42864/0x10f0b6:     89574       2      0 write(0x2, "/usr/local/Cellar/go/1.3/libexec/src/pkg/runtime/os_darwin.c\0", 0x3C)		 = 60 0
42864/0x10f0b6:     89575       1      0 write(0x2, ":\0", 0x1)		 = 1 0
42864/0x10f0b6:     89576       2      0 write(0x2, "88\0", 0x2)		 = 2 0
42864/0x10f0b6:     89577       2      0 write(0x2, " +\0", 0x2)		 = 2 0
42864/0x10f0b6:     89578       2      0 write(0x2, "0x62\0", 0x4)		 = 4 0
42864/0x10f0b6:     89578       2      0 write(0x2, "\n\0", 0x1)		 = 1 0
42864/0x10f0b6:     89580       1      0 write(0x2, "runtime.schedinit\0", 0x11)		 = 17 0
42864/0x10f0b6:     89581       2      0 write(0x2, "(\0", 0x1)		 = 1 0
42864/0x10f0b6:     89582       2      0 write(0x2, ")\n\0", 0x2)		 = 2 0
42864/0x10f0b6:     89583       2      0 write(0x2, "\t\0", 0x1)		 = 1 0
42864/0x10f0b6:     89584       2      0 write(0x2, "/usr/local/Cellar/go/1.3/libexec/src/pkg/runtime/proc.c\0", 0x37)		 = 55 0
42864/0x10f0b6:     89585       1      0 write(0x2, ":\0", 0x1)		 = 1 0
42864/0x10f0b6:     89586       2      0 write(0x2, "164\0", 0x3)		 = 3 0
42864/0x10f0b6:     89586       2      0 write(0x2, " +\0", 0x2)		 = 2 0
42864/0x10f0b6:     89587       1      0 write(0x2, "0x76\0", 0x4)		 = 4 0
42864/0x10f0b6:     89588       1      0 write(0x2, "\n\0", 0x1)		 = 1 0
42864/0x10f0b6:     89589       1      0 write(0x2, "_rt0_go\0", 0x7)		 = 7 0
42864/0x10f0b6:     89590       1      0 write(0x2, "(\0", 0x1)		 = 1 0
42864/0x10f0b6:     89591       2      0 write(0x2, ")\n\0", 0x2)		 = 2 0
42864/0x10f0b6:     89594       2      0 write(0x2, "\t\0", 0x1)		 = 1 0
42864/0x10f0b6:     89595       1      0 write(0x2, "/usr/local/Cellar/go/1.3/libexec/src/pkg/runtime/asm_amd64.s\0", 0x3C)		 = 60 0
42864/0x10f0b6:     89596       1      0 write(0x2, ":\0", 0x1)		 = 1 0
42864/0x10f0b6:     89597       2      0 write(0x2, "91\0", 0x2)		 = 2 0
42864/0x10f0b6:     89598       2      0 write(0x2, " +\0", 0x2)		 = 2 0
42864/0x10f0b6:     89599       2      0 write(0x2, "0x114\0", 0x5)		 = 5 0
42864/0x10f0b6:     89600       2      0 write(0x2, "\n\0", 0x1)		 = 1 0
42864/0x10f0b6:       522    1229    378 pread(0x3, "\312\376\272\276\0", 0x1000, 0x0)		 = 4096 0
42864/0x10f0b6:       527      58      3 pread(0x3, "\317\372\355\376\a\0", 0x1000, 0x1000)		 = 4096 0
42864/0x10f0b6:       539       4      1 fcntl(0x3, 0x3D, 0x7FFF5FBFC7B0)		 = 0 0
42864/0x10f0b6:       554      14      9 mmap(0x179000, 0x2000, 0x5, 0x12, 0x3, 0x1000)		 = 0x179000 0
42864/0x10f0b6:       557       5      3 mmap(0x17B000, 0x1000, 0x3, 0x12, 0x3, 0x3000)		 = 0x17B000 0
42864/0x10f0b6:       561       5      3 mmap(0x17C000, 0x2050, 0x1, 0x12, 0x3, 0x4000)		 = 0x17C000 0
42864/0x10f0b6:       583       6      3 close(0x3)		 = 0 0
42864/0x10f0b6:       594       3      0 getpid(0x7FFF5FBFF158, 0x178004, 0xEA60)		 = 42864 0
42864/0x10f0b6:      1152      63     19 open("/dev/dtracehelper\0", 0x2, 0x7FFF5FBFF250)		 = 3 0
42864/0x10f0b6:     88492   87342  87339 ioctl(0x3, 0x80086804, 0x7FFF5FBFF1D8)		 = 0 0
42864/0x10f0b6:     88499       8      5 close(0x3)		 = 0 0
42864/0x10f0b6:     88565       6      3 __sysctl(0x7FFF5FBFEBF8, 0x2, 0x7FFF5FBFEC08)		 = 0 0
42864/0x10f0b6:     88567       2      0 thread_selfid(0x7FFF78931310, 0x7FFF78931258, 0x10101)		 = 1110198 0
42864/0x10f0b6:     88568       2      0 bsdthread_register(0x7FFF8D835FBC, 0x7FFF8D835FAC, 0x2000)		 = 0 0
42864/0x10f0b6:     88627       4      2 mprotect(0x17F000, 0x88, 0x1)		 = 0 0
42864/0x10f0b6:     88630       2      0 mprotect(0x181000, 0x1000, 0x0)		 = 0 0
42864/0x10f0b6:     88631       2      0 mprotect(0x197000, 0x1000, 0x0)		 = 0 0
42864/0x10f0b6:     88641       1      0 mprotect(0x198000, 0x1000, 0x0)		 = 0 0
42864/0x10f0b6:     88642       1      0 mprotect(0x1AE000, 0x1000, 0x0)		 = 0 0
42864/0x10f0b6:     88656       2      0 mprotect(0x1AF000, 0x1000, 0x1)		 = 0 0
42864/0x10f0b6:     88658       2      1 mprotect(0x17F000, 0x88, 0x3)		 = 0 0
42864/0x10f0b6:     88668       2      1 mprotect(0x17F000, 0x88, 0x1)		 = 0 0
42864/0x10f0b6:     88682       2      0 issetugid(0x7FFF795F7480, 0x7FFFFFE00034, 0x7FFFFFE00036)		 = 0 0
42864/0x10f0b6:     88878       2      0 getpid(0x1, 0x1B0000, 0x49656E69)		 = 42864 0
42864/0x10f0b6:     88883       4      1 __mac_syscall(0x7FFF8CA6EE3F, 0x2, 0x7FFF5FBFEA78)		 = 0 0
42864/0x10f0b6:     88887       5      3 stat64("/AppleInternal\0", 0x7FFF5FBFEAF8, 0x0)		 = -1 Err#2
42864/0x10f0b6:     88900       3      0 audit_session_self(0x7FFF5FBFE9B0, 0x7FFF5FBFE7E8, 0x4)		 = 4099 0
42864/0x10f0b6:     88901       2      0 geteuid(0x7FFF5FBFE9B0, 0x7FFF5FBFE7E8, 0x0)		 = 0 0
42864/0x10f0b6:     88901       2      0 getegid(0x7FFF5FBFE9B0, 0x7FFF5FBFE7E8, 0x0)		 = 0 0
42864/0x10f0b6:     88903       3      0 getaudit_addr(0x7FFF5FBFEA88, 0x30, 0x0)		 = 0 0
42864/0x10f0b6:     88904       2      0 csops(0xA770, 0x7, 0x7FFF5FBFE670)		 = -1 Err#22
42864/0x10f0b6:     89025       5      2 __sysctl(0x7FFF5FBFFC30, 0x2, 0x7FFF5FBFFC2C)		 = 0 0
42864/0x10f0b6:     89048      20     18 open("/dev/urandom\0", 0x0, 0x0)		 = 3 0
42864/0x10f0b6:     89055       9      7 read(0x3, "_s\t\225\236G\341\004\317\355\037\367\023\b\264Dk\230DUr\330\001E\263\272D\a\267\340\244\n\0", 0x20)		 = 32 0
42864/0x10f0b6:     89058       4      2 close(0x3)		 = 0 0
42864/0x10f0b6:     89337     245    241 mmap(0xC000000000, 0x2208002000, 0x0, 0x1002, 0xFFFFFFFF, 0x0)		 = 0xC000000000 0
42864/0x10f0b6:     89370       3      0 mmap(0x0, 0x40000, 0x3, 0x1002, 0xFFFFFFFF, 0x0)		 = 0x1B1000 0
42864/0x10f0b6:     89381       4      2 mmap(0xC208000000, 0x100000, 0x3, 0x1012, 0xFFFFFFFF, 0x0)		 = 0xC208000000 0
42864/0x10f0b6:     89385       3      1 mmap(0xC207FF0000, 0x10000, 0x3, 0x1012, 0xFFFFFFFF, 0x0)		 = 0xC207FF0000 0
42864/0x10f0b6:     89386       3      1 mmap(0xC000000000, 0x1000, 0x3, 0x1012, 0xFFFFFFFF, 0x0)		 = 0xC000000000 0
42864/0x10f0b6:     89387       2      0 mmap(0x0, 0x10000, 0x3, 0x1002, 0xFFFFFFFF, 0x0)		 = 0x300000 0
42864/0x10f0b6:     89426       3      0 mmap(0x0, 0x15F8F8, 0x3, 0x1002, 0xFFFFFFFF, 0x0)		 = 0x310000 0
42864/0x10f0b6:     89472       2      0 bsdthread_register(0x292A0, 0x0, 0x0)		 = -1 Err#22

CALL                                        COUNT
__mac_syscall                                   1
audit_session_self                              1
exit                                            1
fstat64                                         1
getaudit_addr                                   1
getegid                                         1
geteuid                                         1
ioctl                                           1
read                                            1
shared_region_check_np                          1
__sysctl                                        2
bsdthread_register                              2
csops                                           2
fcntl                                           2
getpid                                          2
issetugid                                       2
pread                                           2
select                                          2
thread_selfid                                   2
close                                           4
open                                            4
mprotect                                        8
mmap                                           10
stat64                                         39
write                                          45

[go-testcode]$
```




## 情報源

* [dtruss(1m) Mac OS X Manual Page](https://developer.apple.com/library/mac/documentation/Darwin/Reference/ManPages/man1/dtruss.1m.html)