I just read Julia Evans’ great introduction to strace to see what system calls a program is making. It got me excited to try running dtruss (the Mac equivalent) on a simple command. I went with “ls”, and wound up getting 134 (!) system calls. I went through them all, and I learned a lot! Here it is:
Running dtruss
I’m not quite sure, but I think dtruss came pre-installed on my mac. Let’s try it out:
>>> dtruss lsdtrace: failed to initialize dtrace: DTrace requires additional privileges
Oh okay. I’ll use sudo
>>> sudo dtruss lsdtrace: failed to execute ls: dtrace cannot control executables signed with restricted entitlements
Turns out Apple introduced something called System Integrity Protection which prevents you from modifying (or running dtruss on) anything in certain directories, like /bin .
I’m actually a fan of this, because I’m paranoid I’ll accidentally mess up something terribly in my system files. It’s pretty easy to get around in this case. SIP doesn’t prevent us from copying things in that directory, so we’ll make a copy of ls and run that copy.
First, find where ls is stored:
>>> which ls/bin/ls
Then make a copy:
>>> cp /bin/ls /tmp/ls>>> /tmp/lstest.txt
It works!
Okay, now run dtruss again
>>> sudo dtruss /tmp/lsYou should get a TON of output. Stuff like:
SYSCALL(args) = returnthread_selfid(0x0, 0x0, 0x0) = 157179 0csops(0x0, 0x0, 0x7FFF5F137940) = 0 0issetugid(0x0, 0x0, 0x7FFF5F137940) = 0 0…
We can actually get even more output with some flags:
-a : Print all details (system call counts, timestamps, process id and thread id)-f : follow children as they are forked (not actually important for this example since ls doesn’t make any children processes)-s : print stack backtraces. (very helpful when trying to understand why the calls are made)
And lastly, dtruss prints its output to stderr instead of stdout for some reason, so if you redirect to a file, it won’t work unless you use “2>” (2 for file descriptor 2, which is stderr). So the final product is:
>>> sudo dtruss -afs /tmp/ls 2> ~/Desktop/output.txtNow let’s look at the output it produced.
dtruss Output
The command first prints the output of “ls”, which in my case is:
test.txtNext, it prints the headers. Each logged syscall is formatted like:
PID/THRD RELATIVE ELAPSD CPU SYSCALL(args) = returnPID/THRD — The process id / thread id that made the syscall. “ls” happened on one process (65015) and one thread (0x45006d)
RELATIVE — Relative timestamps to the start of the thread (microseconds). In total, this command took 6098 microseconds (6 milliseconds, or 6 thousandths of a second)
ELAPSD — Elapsed time for this system call (microseconds)
CPU — On-cpu time for this system call (microseconds)
SYSCALL — the name of the syscall. It’s hard to find documentation on some of these :( but my general strategy was to first check for a man page, then google it, then make informed guesses if I still can’t find anything.
args — The arguments passed in to the syscall. It prints strings, but if the argument is a pointer to a struct, you’re out of luck in understanding it. If the argument is an integer enum, understanding what it is usually depends on find the documentation for that syscall.
return — The return value of the syscall, plus the value of “errno”
Details on all 134 system calls
1 — thread_selfid
65015/0x45006d: 52 44 0 thread_selfid(0x0, 0x0, 0x0) = 4522093 0The dynamic linker (dyld) is starting up. It uses the Mach microkernel, which is linked w/ the OSX monolithic kernel. mach_init() get’s the current thread id.
The current thread id is 4522093 (base 10) (0x45006D in hex)
For each system call, I’ll include the stack trace at the end:
dyld`__thread_selfid+0xadyld`mach_init+0x13dyld`dyldbootstrap::start(macho_header const*, int, char const**, long, macho_header const*, unsigned long*)+0x161dyld`_dyld_start+0x36ls`0x1
2 — csops
65015/0x45006d: 81 5 2 csops(0x0, 0x0, 0x7FFF53FBE910) = 0 0OSX uses code signing to verify programs have not been modified (the second of Apple’s security measures I learned about today!). Here I assume dyld is verifying it hasn’t been modified
dyld`csops+0xadyld`dyldbootstrap::start(macho_header const*, int, char const**, long, macho_header const*, unsigned long*)+0x200dyld`_dyld_start+0x36ls`0x1
3 — issetugid
65015/0x45006d: 81 1 0 issetugid(0x0, 0x0, 0x7FFF53FBE910) = 0 0From the man page:
The issetugid() system call returns 1 if the process environment or memory address space is considered “tainted’’, and returns 0 otherwise.
dyld is still starting up. It’s doing more assertions.
dyld`issetugid+0xadyld`dyldbootstrap::start(macho_header const*, int, char const**, long, macho_header const*, unsigned long*)+0x200dyld`_dyld_start+0x36ls`0x1
4 — shared_region_check_np
65015/0x45006d: 132 3 1 shared_region_check_np(0x7FFF53FBC818, 0x0, 0x7FFF53FBE910) = 0 0From the comments on this page:
dyld calls this when any process starts to see if the process’s shared region is already set up and ready to use. This call returns the base address of the first mapping in the process’s shared region’s first mapping. dyld will then check what’s mapped at that address.
dyld`syscall+0xadyld`dyld::_main(macho_header const*, unsigned long, int, char const**, char const**, char const**, unsigned long*)+0x7dedyld`dyldbootstrap::start(macho_header const*, int, char const**, long, macho_header const*, unsigned long*)+0x200dyld`_dyld_start+0x36ls`0x1
5 — stat64
65015/0x45006d: 558 1297 420 stat64(“/usr/lib/dtrace/libdtrace_dyld.dylib\0”, 0x7FFF53FBDDA8, 0x7FFF53FBE910) = 0 0Obtaining information about the file /usr/lib/dtrace/libdtrace_dyld.dylib . That means dyld is beginning to load dtrace! dtrace is what dtruss uses to collect system calls.
Looking at this slide deck, I learned that OSX uses the Mach-O binary format, which lists dynamic library dependencies at the beginning of the executable. My guess is that /usr/sbin/dtrace lists libdtrace_dyld.dylib as a dependency.
dyld`stat64+0xadyld`dyld::loadPhase5(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0x6ddyld`dyld::loadPhase4(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0xb4dyld`dyld::loadPhase3(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0x64adyld`dyld::loadPhase1(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0x87dyld`dyld::loadPhase0(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0xd5dyld`dyld::load(char const*, dyld::LoadContext const&)+0xb4dyld`dyld::_main(macho_header const*, unsigned long, int, char const**, char const**, char const**, unsigned long*)+0xb56dyld`dyldbootstrap::start(macho_header const*, int, char const**, long, macho_header const*, unsigned long*)+0x200dyld`_dyld_start+0x36ls`0x1
6 — open
65015/0x45006d: 593 77 30 open(“/usr/lib/dtrace/libdtrace_dyld.dylib\0”, 0x0, 0x0) = 3 0Opening libdtrace_dyld.dylib for reading. Return value is 3, meaning we will refer to this file with the file descriptor “3” from now on
dyld`open+0xadyld`dyld::loadPhase5(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0x2a4dyld`dyld::loadPhase4(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0xb4dyld`dyld::loadPhase3(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0x64adyld`dyld::loadPhase1(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0x87dyld`dyld::loadPhase0(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0xd5dyld`dyld::load(char const*, dyld::LoadContext const&)+0xb4dyld`dyld::_main(macho_header const*, unsigned long, int, char const**, char const**, char const**, unsigned long*)+0xb56dyld`dyldbootstrap::start(macho_header const*, int, char const**, long, macho_header const*, unsigned long*)+0x200dyld`_dyld_start+0x36ls`0x1
7 — pread
65015/0x45006d: 596 6 2 pread(0x3, “\312\376\272\276\0”, 0x1000, 0x0) = 4096 0Reads up to 0x1000 bytes (4096 bytes = 4 kB) from the file into a buffer. Returns 4096 to show that the limit of 4096 bytes were successfully read.
dyld`pread+0xadyld`dyld::loadPhase5(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0x2c6dyld`dyld::loadPhase4(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0xb4dyld`dyld::loadPhase3(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0x64adyld`dyld::loadPhase1(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0x87dyld`dyld::loadPhase0(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0xd5dyld`dyld::load(char const*, dyld::LoadContext const&)+0xb4dyld`dyld::_main(macho_header const*, unsigned long, int, char const**, char const**, char const**, unsigned long*)+0xb56dyld`dyldbootstrap::start(macho_header const*, int, char const**, long, macho_header const*, unsigned long*)+0x200dyld`_dyld_start+0x36ls`0x1
8 — pread
65015/0x45006d: 597 3 1 pread(0x3, “\317\372\355\376\a\0”, 0x1000, 0x1000) = 4096 0Reads up to 4096 more bytes starting at offset 4096. Again, returns 4096, meaning we aren’t done reading the file. When I run
ls -l /usr/lib/dtrace/libdtrace_dyld.dylibI get that the file is 53008 bytes long, meaning we will need a total of 13 calls to pread to load the whole file into memory. Although strangely enough, we never read any more of this file. Maybe it only reads as much as it needs.
dyld`pread+0xadyld`dyld::loadPhase5(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0x2c6dyld`dyld::loadPhase4(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0xb4dyld`dyld::loadPhase3(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0x64adyld`dyld::loadPhase1(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0x87dyld`dyld::loadPhase0(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0xd5dyld`dyld::load(char const*, dyld::LoadContext const&)+0xb4dyld`dyld::_main(macho_header const*, unsigned long, int, char const**, char const**, char const**, unsigned long*)+0xb56dyld`dyldbootstrap::start(macho_header const*, int, char const**, long, macho_header const*, unsigned long*)+0x200dyld`_dyld_start+0x36ls`0x1
9 — fcntl
65015/0x45006d: 602 3 1 fcntl(0x3, 0x61, 0x7FFF53FBC0F0) = 0 0This is performing some command (0x61) on the open file. I can’t find a mapping anywhere from number to command, so I don’t know what command it is running
dyld`__fcntl+0xadyld`ImageLoaderMachO::loadCodeSignature(linkedit_data_command const*, int, unsigned long long, ImageLoader::LinkContext const&)+0x61dyld`ImageLoaderMachOCompressed::instantiateFromFile(char const*, int, unsigned char const*, unsigned long, unsigned long long, unsigned long long, stat const&, unsigned int, unsigned int, linkedit_data_command const*, encryption_info_command const*, ImageLoader::LinkContext const&)+0xf1dyld`ImageLoaderMachO::instantiateFromFile(char const*, int, unsigned char const*, unsigned long long, unsigned long long, stat const&, ImageLoader::LinkContext const&)+0x12bdyld`dyld::loadPhase6(int, stat const&, char const*, dyld::LoadContext const&)+0x192dyld`dyld::loadPhase5(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0x2c6dyld`dyld::loadPhase4(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0xb4dyld`dyld::loadPhase3(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0x64adyld`dyld::loadPhase1(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0x87dyld`dyld::loadPhase0(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0xd5dyld`dyld::load(char const*, dyld::LoadContext const&)+0xb4dyld`dyld::_main(macho_header const*, unsigned long, int, char const**, char const**, char const**, unsigned long*)+0xb56dyld`dyldbootstrap::start(macho_header const*, int, char const**, long, macho_header const*, unsigned long*)+0x200dyld`_dyld_start+0x36ls`0x1
10–14 — mmap
65127/0x451780: 244 27 23 mmap(0x0, 0x670, 0x5, 0x1, 0x3, 0x1000) = 0x102370000 065127/0x451780: 252 6 4 munmap(0x102370000, 0x670) = 0 065127/0x451780: 275 20 17 mmap(0x102373000, 0x2000, 0x5, 0x12, 0x3, 0x1000) = 0x102373000 065127/0x451780: 280 5 3 mmap(0x102375000, 0x1000, 0x3, 0x12, 0x3, 0x3000) = 0x102375000 065127/0x451780: 283 4 3 mmap(0x102376000, 0x2F40, 0x1, 0x12, 0x3, 0x4000) = 0x102376000 0
From the man page:
mmap(void *addr, size_t len, int prot, int flags, int fd, off_t offset);
So that means we are loading the dtrace dylib (from file descriptor 3) into memory. The first call would cause pages starting at 0x0 and continuing for at most 0x670 (1648) bytes to be mapped from “libdtrace_dyld.dylib” starting at byte 0x1000 (4096). Mmap is used to access files so that multiple programs accessing the same files can share the same physical pages.
We’re 11% of the way through all the system calls!
15 — close
65015/0x45006d: 684 5 3 close(0x3) = 0 0We are done loading the dtrace dylib into memory. Close the file.
dyld`close+0xadyld`dyld::loadPhase4(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0xb4dyld`dyld::loadPhase3(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0x64adyld`dyld::loadPhase1(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0x87dyld`dyld::loadPhase0(char const*, char const*, dyld::LoadContext const&, std::__1::vector<char const*, std::__1::allocator<char const*> >*)+0xd5dyld`dyld::load(char const*, dyld::LoadContext const&)+0xb4dyld`dyld::_main(macho_header const*, unsigned long, int, char const**, char const**, char const**, unsigned long*)+0xb56dyld`dyldbootstrap::start(macho_header const*, int, char const**, long, macho_header const*, unsigned long*)+0x200dyld`_dyld_start+0x36ls`0x1
16–58 — stat64
Next we see 43 calls to stat64. They are all coming from a function in dyld called ‘recursiveLoadLibraries’, so I’m guessing dyld is working through libdtrace_dyld.dylib and finding all of its dependencies. Maybe it isn’t opening and reading them either because they are already loaded or because dyld uses lazy loading and won’t read them until it needs them.
These 43 system calls are listed below:
65127/0x451780: 306 15 13 stat64(“/usr/lib/dtrace/libdtrace_dyld.dylib\0”, 0x7FFF5D899328, 0x1) = 0 065127/0x451780: 358 14 13 stat64(“/usr/lib/libutil.dylib\0”, 0x7FFF5D898BA8, 0x1) = 0 065127/0x451780: 375 14 13 stat64(“/usr/lib/libncurses.5.4.dylib\0”, 0x7FFF5D898BA8, 0x1) = 0 065127/0x451780: 391 13 11 stat64(“/usr/lib/libSystem.B.dylib\0”, 0x7FFF5D898BA8, 0x1) = 0 065127/0x451780: 406 12 11 stat64(“/usr/lib/libc++.1.dylib\0”, 0x7FFF5D898AB8, 0x1) = 0 065127/0x451780: 421 12 11 stat64(“/usr/lib/libc++abi.dylib\0”, 0x7FFF5D8989C8, 0x1) = 0 065127/0x451780: 439 15 13 stat64(“/usr/lib/system/libcache.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 455 13 12 stat64(“/usr/lib/system/libcommonCrypto.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 471 12 11 stat64(“/usr/lib/system/libcompiler_rt.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 485 12 11 stat64(“/usr/lib/system/libcopyfile.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 500 12 11 stat64(“/usr/lib/system/libcorecrypto.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 514 12 10 stat64(“/usr/lib/system/libdispatch.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 529 12 11 stat64(“/usr/lib/system/libdyld.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 543 11 10 stat64(“/usr/lib/system/libkeymgr.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 559 13 12 stat64(“/usr/lib/system/liblaunch.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 573 13 11 stat64(“/usr/lib/system/libmacho.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 589 13 12 stat64(“/usr/lib/system/libquarantine.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 604 12 11 stat64(“/usr/lib/system/libremovefile.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 618 13 11 stat64(“/usr/lib/system/libsystem_asl.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 633 12 11 stat64(“/usr/lib/system/libsystem_blocks.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 648 13 12 stat64(“/usr/lib/system/libsystem_c.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 665 13 11 stat64(“/usr/lib/system/libsystem_configuration.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 682 15 13 stat64(“/usr/lib/system/libsystem_coreservices.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 699 14 12 stat64(“/usr/lib/system/libsystem_coretls.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 716 13 12 stat64(“/usr/lib/system/libsystem_dnssd.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 733 14 12 stat64(“/usr/lib/system/libsystem_info.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 752 13 12 stat64(“/usr/lib/system/libsystem_kernel.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 767 13 12 stat64(“/usr/lib/system/libsystem_m.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 783 13 11 stat64(“/usr/lib/system/libsystem_malloc.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 799 13 12 stat64(“/usr/lib/system/libsystem_network.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 815 13 12 stat64(“/usr/lib/system/libsystem_networkextension.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 830 13 12 stat64(“/usr/lib/system/libsystem_notify.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 846 13 12 stat64(“/usr/lib/system/libsystem_platform.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 861 13 11 stat64(“/usr/lib/system/libsystem_pthread.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 878 13 12 stat64(“/usr/lib/system/libsystem_sandbox.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 893 13 11 stat64(“/usr/lib/system/libsystem_secinit.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 908 12 11 stat64(“/usr/lib/system/libsystem_trace.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 924 12 11 stat64(“/usr/lib/system/libunc.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 940 13 11 stat64(“/usr/lib/system/libunwind.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 956 14 12 stat64(“/usr/lib/system/libxpc.dylib\0”, 0x7FFF5D8984F8, 0x1) = 0 065127/0x451780: 991 13 12 stat64(“/usr/lib/libobjc.A.dylib\0”, 0x7FFF5D8977D8, 0x1) = 0 065127/0x451780: 1008 13 11 stat64(“/usr/lib/libauto.dylib\0”, 0x7FFF5D8977D8, 0x1) = 0 065127/0x451780: 1028 13 12 stat64(“/usr/lib/libDiagnosticMessagesClient.dylib\0”, 0x7FFF5D8975A8, 0x1) = 0 0
59 — getpid
65015/0x45006d: 1496 2 0 getpid(0x7FFF8270A740, 0x7FFF53FBC5A8, 0x1) = 65015 0getpid() returns the process ID of the calling process.
The process id is 65015
We’re in a function called “notifyBatchPartial”. My best guess here is we’re notifying the operating system which dylibs we’ve loaded. Either for gathering statistics, or to wake up any processes waiting on those dylibs to be loaded.
dyld`getpid+0x15dyld`coresymbolication_load_notifier+0x35dyld`dyld::notifyBatchPartial(dyld_image_states, bool, char const* (*)(dyld_image_states, unsigned int, dyld_image_info const*))+0x3d2dyld`ImageLoader::link(ImageLoader::LinkContext const&, bool, bool, bool, ImageLoader::RPathChain const&)+0x59dyld`dyld::link(ImageLoader*, bool, bool, ImageLoader::RPathChain const&)+0x95dyld`dyld::_main(macho_header const*, unsigned long, int, char const**, char const**, char const**, unsigned long*)+0xc58dyld`dyldbootstrap::start(macho_header const*, int, char const**, long, macho_header const*, unsigned long*)+0x200dyld`_dyld_start+0x36ls`0x1
60 — open
65015/0x45006d: 1785 83 28 open(“/dev/dtracehelper\0”, 0x2, 0x7FFF53FBE7D0) = 3 0File descriptor 3 now refers to /dev/dtracehelper. I believe this file is used to report information to dtrace. When I try to cat the file, I get “cat: /dev/dtracehelper: Operation not supported by device”, meaning it is not a normal file, but rather some inter-process communication mechanism.
dyld`open+0xadyld`ImageLoader::link(ImageLoader::LinkContext const&, bool, bool, bool, ImageLoader::RPathChain const&)+0x118dyld`dyld::link(ImageLoader*, bool, bool, ImageLoader::RPathChain const&)+0x95dyld`dyld::_main(macho_header const*, unsigned long, int, char const**, char const**, char const**, unsigned long*)+0xc58dyld`dyldbootstrap::start(macho_header const*, int, char const**, long, macho_header const*, unsigned long*)+0x200dyld`_dyld_start+0x36ls`0x1
We are now 45% of the way through the system calls!
61 — ioctl
65015/0x45006d: 4415 2630 2628 ioctl(0x3, 0x80086804, 0x7FFF53FBE758) = 0 0From the man page:
ioctl(int fildes, unsigned long request, …);
The ioctl() function manipulates the underlying device parameters of special files. In particular, many operating characteristics of character special files (e.g. terminals) may be controlled with ioctl() requests. The argument fildes must be an open file descriptor.
I don’t know how to decode the second parameter, but we are somehow manipulating /dev/dtracehelper , most likely reporting system calls or setting up a callback to report system calls.
dyld`__ioctl+0xadyld`dyld::registerDOFs(std::__1::vector<ImageLoader::DOFInfo, std::__1::allocator<ImageLoader::DOFInfo> > const&)+0x112dyld`ImageLoader::link(ImageLoader::LinkContext const&, bool, bool, bool, ImageLoader::RPathChain const&)+0x118dyld`dyld::link(ImageLoader*, bool, bool, ImageLoader::RPathChain const&)+0x95dyld`dyld::_main(macho_header const*, unsigned long, int, char const**, char const**, char const**, unsigned long*)+0xc58dyld`dyldbootstrap::start(macho_header const*, int, char const**, long, macho_header const*, unsigned long*)+0x200dyld`_dyld_start+0x36ls`0x1
62 — close
65015/0x45006d: 4420 6 4 close(0x3) = 0 0We are done with /dev/dtracehelper
dyld`close+0xadyld`ImageLoader::link(ImageLoader::LinkContext const&, bool, bool, bool, ImageLoader::RPathChain const&)+0x118dyld`dyld::link(ImageLoader*, bool, bool, ImageLoader::RPathChain const&)+0x95dyld`dyld::_main(macho_header const*, unsigned long, int, char const**, char const**, char const**, unsigned long*)+0xc58dyld`dyldbootstrap::start(macho_header const*, int, char const**, long, macho_header const*, unsigned long*)+0x200dyld`_dyld_start+0x36ls`0x1
63–81 — dyld::initializeMainExecutable()
We’ve finished loading our dynamic library dependencies and now we’ve started executing the function “dyld::initializeMainExecutable()”. This function makes a lot of system calls that are all doing initialization for dyld. Most of this is boring, but there are a few interesting things to note:
We are now executing code in a dylibs (e.g. libsystem_kernel.dylib) which we called stat64 on earlier. I guess we didn’t have to call read() or mmap() on them because they were already loaded into memory by another process.
dyld checks for a file called /AppleInternal/XBS/.isChrooted, which doesn’t exist for me but presumably exists when you are inside a chroot. Notice that the return value of this syscall is -1, and errno is set.
It also checks for a directory that did not exist for me called /AppleInternal. I think this directory might only exist iPhone?
Codesign is run two more times: on libxpc.dylib and on libsystem_secinit.dylib .
The system calls are:
65015/0x45006d: 4565 12 8 sysctl(0x7FFF53FBDDF0, 0x2, 0x7FFF53FBDE00) = 0 065015/0x45006d: 4570 3 0 thread_selfid(0x7FFF53FBDDF0, 0x2, 0x7FFF53FBDE00) = 4522093 065015/0x45006d: 4574 5 1 bsdthread_register(0x7FFF97670344, 0x7FFF97670334, 0x2000) = 1073741887 065127/0x451780: 4132 4 2 mprotect(0x102371000, 0x88, 0x1) = 0 065127/0x451780: 4134 2 1 mprotect(0x102379000, 0x1000, 0x0) = 0 065127/0x451780: 4135 2 0 mprotect(0x10238F000, 0x1000, 0x0) = 0 065127/0x451780: 4147 2 0 mprotect(0x102390000, 0x1000, 0x0) = 0 065127/0x451780: 4148 2 0 mprotect(0x1023A6000, 0x1000, 0x0) = 0 065127/0x451780: 4161 2 0 mprotect(0x1023A7000, 0x1000, 0x1) = 0 065127/0x451780: 4163 3 1 mprotect(0x102371000, 0x88, 0x3) = 0 065127/0x451780: 4174 2 1 mprotect(0x102371000, 0x88, 0x1) = 0 065015/0x45006d: 4744 3 0 issetugid(0x10BC4C000, 0x88, 0x1) = 0 065015/0x45006d: 5067 3 0 getpid(0x10BC4C000, 0x88, 0x1) = 65015 065015/0x45006d: 5087 14 12 stat64(“/AppleInternal/XBS/.isChrooted\0”, 0x7FFF53FBDD58, 0x1) = -1 Err#265015/0x45006d: 5093 5 3 stat64(“/AppleInternal\0”, 0x7FFF53FBDCC8, 0x1) = -1 Err#265015/0x45006d: 5119 6 2 csops(0xFDF7, 0x7, 0x7FFF53FBD7E0) = 0 065015/0x45006d: 5157 39 36 sysctl(0x7FFF53FBDBA0, 0x4, 0x7FFF53FBD918) = 0 065015/0x45006d: 5164 2 0 csops(0xFDF7, 0x7, 0x7FFF53FBD0D0) = 0 065015/0x45006d: 5210 7 3 proc_info(0x2, 0xFDF7, 0x11) = 56 0
82 — getrlimit
65015/0x45006d: 5355 57 0 getrlimit(0x1008, 0x7FFF53FBEC38, 0x11) = 0 0Now dyld is finally done setting up and we are running code in “ls” itself.
getrlimit gets this process’ limits on system resources like memory, cpu and open files. You can see “ls” is calling a function in libsystem_c.dylib, which I assume is the C standard library.
Our program is kind of bikeshedding here because “ls” just wants to call “setlocale”, but first “setlocale” needs to call “loadlocale”, which needs to open a file, which I’m guessing triggers some lazy initialization that checks our processes maximum number of open files.
libsystem_kernel.dylib`__getrlimit+0xalibsystem_c.dylib`__sinit+0x3alibsystem_pthread.dylib`__pthread_once_handler+0x41libsystem_platform.dylib`_os_once+0x29libsystem_pthread.dylib`pthread_once+0x39libsystem_c.dylib`__sfp+0x34libsystem_c.dylib`fopen$DARWIN_EXTSN+0x38libsystem_c.dylib`__collate_load_tables+0xddlibsystem_c.dylib`loadlocale+0xd8libsystem_c.dylib`setlocale+0x30fls`0x000000010bc41174+0x40libdyld.dylib`start+0x1ls`0x1
83 — open_nocancel
65015/0x45006d: 5397 38 35 open_nocancel(“/usr/share/locale/en_US.UTF-8/LC_COLLATE\0”, 0x0, 0x1B6) = 3 0This is presumably similar to open, but I can’t find documentation on it anywhere.
Opening a file called /usr/share/locale/en_US.UTF-8/LC_COLLATE, getting file descriptor 3.
This /usr/share/locale/en_US.UTF-8/ directory contains lots of information about how to format messages for my locale, like how to format dates and currency, etc.
LC_COLLATE contains characters in alphanumeric order, which is going to determine how the files I’m “ls”-ing are sorted.
libsystem_kernel.dylib`__open_nocancel+0xalibsystem_c.dylib`__collate_load_tables+0xddlibsystem_c.dylib`loadlocale+0xd8libsystem_c.dylib`setlocale+0x30fls`0x000000010bc41174+0x40libdyld.dylib`start+0x1ls`0x1
84 — fstat64
65015/0x45006d: 5400 3 1 fstat64(0x3, 0x7FFF53FBECB8, 0x1B6) = 0 0Gets metadata about the file we just opened, LC_COLLATE. I’m not sure why we need to do this.
libsystem_kernel.dylib`fstat$INODE64+0xalibsystem_c.dylib`__smakebuf+0x2alibsystem_c.dylib`__srefill0+0xe7libsystem_c.dylib`__fread+0xaalibsystem_c.dylib`fread+0x30libsystem_c.dylib`__collate_load_tables+0x105libsystem_c.dylib`loadlocale+0xd8libsystem_c.dylib`setlocale+0x30fls`0x000000010bc41174+0x40libdyld.dylib`start+0x1ls`0x1
85 — read_nocancel
65015/0x45006d: 5407 8 5 read_nocancel(0x3, “1.1A\n\0”, 0x1000) = 2086 0Read up to 4 kB of the file LC_COLLATE. We read 2086 bytes (2 kB) which is the size of the file. You’ll notice the second parameter says “1.1A\n\0” because that’s what’s currently in the buffer that we’re going to overwrite.
libsystem_kernel.dylib`__read_nocancel+0xalibsystem_c.dylib`__srefill1+0x18libsystem_c.dylib`__fread+0x189libsystem_c.dylib`fread+0x30libsystem_c.dylib`__collate_load_tables+0x105libsystem_c.dylib`loadlocale+0xd8libsystem_c.dylib`setlocale+0x30fls`0x000000010bc41174+0x40libdyld.dylib`start+0x1ls`0x1
85 — close_nocancel
65015/0x45006d: 5415 7 4 close_nocancel(0x3) = 0 0We are done with this file, onto the next one.
libsystem_kernel.dylib`__close_nocancel+0xalibsystem_c.dylib`__collate_load_tables+0x3c4libsystem_c.dylib`loadlocale+0xd8libsystem_c.dylib`setlocale+0x30fls`0x000000010bc41174+0x40libdyld.dylib`start+0x1ls`0x1
87–115 — reading the other locale files
We repeat the same process to read into memory the rest of the locale files:
65127/0x451780: 4694 17 16 open_nocancel(“/usr/share/locale/en_US.UTF-8/LC_CTYPE\0”, 0x0, 0x1B6) = 3 065127/0x451780: 4696 2 0 fstat64(0x3, 0x7FFF5D899DF8, 0x1B6) = 0 065127/0x451780: 4700 1 0 fstat64(0x3, 0x7FFF5D899BE8, 0x1B6) = 0 065127/0x451780: 4702 2 0 lseek(0x3, 0x0, 0x1) = 0 065127/0x451780: 4703 1 0 lseek(0x3, 0x0, 0x0) = 0 065127/0x451780: 4705 3 1 read_nocancel(0x3, “RuneMagAUTF-8\0”, 0x1000) = 4096 065127/0x451780: 4716 2 1 read_nocancel(0x3, “\0”, 0x1000) = 4096 065127/0x451780: 4730 2 1 read_nocancel(0x3, “\0”, 0x1000) = 4096 065127/0x451780: 4746 2 1 read_nocancel(0x3, “\0”, 0x1000) = 4096 065127/0x451780: 4760 2 1 read_nocancel(0x3, “\0”, 0x1000) = 4096 065127/0x451780: 4788 2 1 read_nocancel(0x3, “\0”, 0x1000) = 4096 065127/0x451780: 4839 43 42 read_nocancel(0x3, “@\004\031\0”, 0xDDD0) = 56784 065127/0x451780: 4851 4 2 close_nocancel(0x3) = 0 065127/0x451780: 4875 21 19 open_nocancel(“/usr/share/locale/en_US.UTF-8/LC_MONETARY\0”, 0x0, 0x4) = 3 065127/0x451780: 4876 2 0 fstat64(0x3, 0x7FFF5D899E10, 0x4) = 0 065127/0x451780: 4877 2 0 read_nocancel(0x3, “USD \n$\n.\n,\n3;3\n\n-\n2\n2\n1\n0\n1\n0\n1\n1\n\b\0”, 0x22) = 34 065127/0x451780: 4879 3 1 close_nocancel(0x3) = 0 065127/0x451780: 4898 17 16 open_nocancel(“/usr/share/locale/en_US.UTF-8/LC_NUMERIC\0”, 0x0, 0x3) = 3 065127/0x451780: 4899 1 0 fstat64(0x3, 0x7FFF5D899E10, 0x3) = 0 065127/0x451780: 4900 2 0 read_nocancel(0x3, “.\n,\n3;3\n@\004(\0”, 0x8) = 8 065127/0x451780: 4902 3 1 close_nocancel(0x3) = 0 065127/0x451780: 4918 17 15 open_nocancel(“/usr/share/locale/en_US.UTF-8/LC_TIME\0”, 0x0, 0x0) = 3 065127/0x451780: 4919 1 0 fstat64(0x3, 0x7FFF5D899E10, 0x0) = 0 065127/0x451780: 4920 2 0 read_nocancel(0x3, “Jan\nFeb\nMar\nApr\nMay\nJun\nJul\nAug\nSep\nOct\nNov\nDec\nJanuary\nFebruary\nMarch\nApril\nMay\nJune\nJuly\nAugust\nSeptember\nOctober\nNovember\nDecember\nSun\nMon\nTue\nWed\nThu\nFri\nSat\nSunday\nMonday\nTuesday\nWednesday\nThursday\nFriday\nSaturday\n%H:%M:%S\n%m/%d/%Y\n%a %b %e %X %Y\nAM\nP”, 0x179) = 377 065127/0x451780: 4923 3 1 close_nocancel(0x3) = 0 065127/0x451780: 4946 23 22 open_nocancel(“/usr/share/locale/en_US.UTF-8/LC_MESSAGES/LC_MESSAGES\0”, 0x0, 0x8) = 3 065127/0x451780: 4947 2 0 fstat64(0x3, 0x7FFF5D899E10, 0x8) = 0 065127/0x451780: 4948 2 0 read_nocancel(0x3, “^[yYsS].*\n^[nN].*\n\0”, 0x12) = 18 065127/0x451780: 4950 3 1 close_nocancel(0x3) = 0 0
We’re 86% of the way through all the system
116 — ioctl
65015/0x45006d: 5711 3 1 ioctl(0x1, 0x4004667A, 0x7FFF53FBF33C) = -1 Err#25This syscall is trying to issue some command to file descriptor 0x1 (stdout). It’s getting back -1, meaning there was an error. Errno is set to 25, which based on random googling, I think means “Error no 25: Inappropriate ioctl”
This is being used by the cstdlib function “isatty”, presumably to determine if stdout is a tty (which means stdout will print to a terminal)
libsystem_kernel.dylib`__ioctl+0xalibsystem_c.dylib`isatty+0x2bls`0x000000010bc41174+0x50libdyld.dylib`start+0x1ls`0x1
117 — ioctl
65015/0x45006d: 5712 2 0 ioctl(0x1, 0x40487413, 0x7FFF53FBF340) = -1 Err#25“isatty” is calling “ioctl” on stdout again, with a different command I can’t interpret. Presumably it needs to try more than one command to be sure whether or not the file descriptor is a tty.
libsystem_kernel.dylib`__ioctl+0xalibsystem_c.dylib`isatty+0x54ls`0x000000010bc41174+0x50libdyld.dylib`start+0x1ls`0x1
118 — getuid
65015/0x45006d: 5717 2 0 getuid(0x1, 0x40487413, 0x7FFF53FBF340) = 0 0Gets the user id of the user of this process. Who knows why this is needed. We stepped out of “ls” code and we’re back in dyld, which makes me think all that loading of locale files happened inside a callback that “ls” gave to “dyld”
libsystem_kernel.dylib`getuid+0xalibdyld.dylib`start+0x1ls`0x1
119 — stat64
65015/0x45006d: 5731 11 9 stat64(“.\0”, 0x7FFF53FBF258, 0x7FFF53FBF340) = 0 0Grabs metadata about “.”, a file path which refers to the current directory. Finally! This is starting to do the real work of “ls”
libsystem_kernel.dylib`stat$INODE64+0xalibsystem_c.dylib`__fts_open+0x114ls`0x000000010bc41b58+0x3bls`0x000000010bc41174+0x8fclibdyld.dylib`start+0x1ls`0x1
120 — open_nocancel
65015/0x45006d: 5738 8 6 open_nocancel(“.\0”, 0x0, 0x0) = 3 0Opens “.”
libsystem_kernel.dylib`__open_nocancel+0xals`0x000000010bc41b58+0x3bls`0x000000010bc41174+0x8fclibdyld.dylib`start+0x1ls`0x1
121 — fchdir
65015/0x45006d: 5747 3 1 fchdir(0x3, 0x0, 0x0) = 0 0Change current working directory to the path references by file descriptor 3 (“.”)
I guess this is because “ls” optionally takes a path to print out and defaults to the current directory. So it’s treating “.” like it would any other path, and switches over to it (temporarily, I assume)
libsystem_kernel.dylib`fchdir+0xals`0x000000010bc41b58+0x9els`0x000000010bc41174+0x8fclibdyld.dylib`start+0x1ls`0x1
122 — open_nocancel
65015/0x45006d: 5754 7 6 open_nocancel(“.\0”, 0x0, 0x0) = 4 0Opens a second (!?) file descriptor to the current directory. (fd 4)
Okay. I’m curious about what’s going on, so I tried running dtruss and passing “ls” a specific directory. Turns out this is what happens:
- stat64 (syscall #119) : gets metadata about the path provided by the user (“.” if they don’t provide one)
- open_nocancel (syscall #120) : opens “.”, no matter what the user passed in, saves to fd 3
- fchdir (syscall #121) : changes directory to “.”, no matter what they passed in
- open_nocancel (syscall #122) : opens the directory that the user passed in.
So… I’m still confused. Why would we ever change directory to “.” ? Oh well, let’s keep going.
libsystem_kernel.dylib`__open_nocancel+0xals`0x000000010bc41b58+0x159ls`0x000000010bc41174+0x8fclibdyld.dylib`start+0x1ls`0x1
123 — open_nocancel
65015/0x45006d: 5760 7 5 open_nocancel(“.\0”, 0x1100004, 0x0) = 5 0Opens a third fd to “.” (wtf!?)
This call passes some flags in the second parameters. I don’t know how to read them.
We are inside of a function called “fts_children()” which traverse a file hierarchy, so maybe that’s why we’re doing this? So that the code can be more general and handle the case when we want to recursively print all the subdirectories?
libsystem_kernel.dylib`__open_nocancel+0xalibsystem_c.dylib`fts_build+0x31libsystem_c.dylib`fts_children$INODE64+0xc8ls`0x000000010bc41b58+0x159ls`0x000000010bc41174+0x8fclibdyld.dylib`start+0x1ls`0x1
92% of the way there! We’re in the home stretch now.
124 — sysctl
65015/0x45006d: 5764 5 3 sysctl(0x7FFF53FBE938, 0x2, 0x7FFF746DCE00) = 0 0sysctl gets or sets kernel state. I can’t interpret the arguments. We’re still inside of “fts_children()”
libsystem_kernel.dylib`__sysctl+0xalibsystem_c.dylib`__opendir_common+0x7dlibsystem_c.dylib`fts_build+0x31libsystem_c.dylib`fts_children$INODE64+0xc8ls`0x000000010bc41b58+0x159ls`0x000000010bc41174+0x8fclibdyld.dylib`start+0x1ls`0x1
125- fstatfs64
65015/0x45006d: 5766 4 2 fstatfs64(0x5, 0x7FFF53FBE9C8, 0x7FFF746DCE00) = 0 0Gets information about the file system that contains fd 5 (the third file descriptor we opened for “.”). Still inside of “fts_children()”
libsystem_c.dylib`fts_build+0x31libsystem_c.dylib`fts_children$INODE64+0xc8ls`0x000000010bc41b58+0x159ls`0x000000010bc41174+0x8fclibdyld.dylib`start+0x1ls`0x1
126- getdirentries64
65015/0x45006d: 5803 5 3 getdirentries64(0x5, 0x7FD83C801000, 0x1000) = 0 0Okay, I think this is where we’re doing the real work. This reads the contents of the directory referenced by fd 5 (“.”), up to 4096 bytes. 1896 bytes were returned.
libsystem_kernel.dylib`__getdirentries64+0xalibsystem_c.dylib`readdir$INODE64+0x23libsystem_c.dylib`fts_build+0x197libsystem_c.dylib`fts_children$INODE64+0xc8ls`0x000000010bc41b58+0x159ls`0x000000010bc41174+0x8fclibdyld.dylib`start+0x1ls`0x1
127- getdirentries64
65015/0x45006d: 5803 5 3 getdirentries64(0x5, 0x7FD83C801000, 0x1000) = 0 0A second call. No bytes are returned. I think there could be a tiny optimization here by not checking again if fewer than 4096 bytes were returned.
This concludes the call to fts_children()
libsystem_kernel.dylib`__getdirentries64+0xalibsystem_c.dylib`readdir$INODE64+0x23libsystem_c.dylib`fts_build+0x3cflibsystem_c.dylib`fts_children$INODE64+0xc8ls`0x000000010bc41b58+0x159ls`0x000000010bc41174+0x8fclibdyld.dylib`start+0x1ls`0x1
128- close_nocancel
65015/0x45006d: 5807 4 2 close_nocancel(0x5) = 0 0Closing our third opened file
libsystem_kernel.dylib`__close_nocancel+0xalibsystem_c.dylib`fts_children$INODE64+0xc8ls`0x000000010bc41b58+0x159ls`0x000000010bc41174+0x8fclibdyld.dylib`start+0x1ls`0x1
129- fchdir
65015/0x45006d: 6020 2 0 fchdir(0x4, 0x7FD83C801000, 0x1000) = 0 0Changing directory to whatever is referenced by fd 4. This is the directory that the user passed in (or “.” if they didn’t pass in a directory)
libsystem_kernel.dylib`fchdir+0xals`0x000000010bc41b58+0x159ls`0x000000010bc41174+0x8fclibdyld.dylib`start+0x1ls`0x1
130 — close_nocancel
65015/0x45006d: 6022 3 1 close_nocancel(0x4) = 0 0Closes fd 4 (the directory the user passed in).
libsystem_kernel.dylib`__close_nocancel+0xals`0x000000010bc41b58+0x159ls`0x000000010bc41174+0x8fclibdyld.dylib`start+0x1ls`0x1
131 — fstat64
65015/0x45006d: 6033 3 1 fstat64(0x1, 0x7FFF53FBEB08, 0x1000) = 0 0Grab metadata about stdout. We are inside of “putchar()”, so we are probably preparing to print our output.
libsystem_kernel.dylib`fstat$INODE64+0xalibsystem_c.dylib`__smakebuf+0x2alibsystem_c.dylib`__swsetup+0x9blibsystem_c.dylib`__swbuf+0x34libsystem_c.dylib`putchar+0x55ls`0x000000010bc43d4c+0xe0ls`0x000000010bc429ea+0xabls`0x000000010bc4291c+0x9els`0x000000010bc41e8c+0x9e1ls`0x000000010bc41b58+0x1a5ls`0x000000010bc41174+0x8fclibdyld.dylib`start+0x1ls`0x1
132 — fchdir
65015/0x45006d: 6073 2 0 fchdir(0x3, 0x7FFF53FBEB08, 0x1000) = 0 0Change directory back to our original directory. Seems like a strange time to do that. I thought we were starting to output text.
libsystem_kernel.dylib`fchdir+0xals`0x000000010bc41b58+0x272ls`0x000000010bc41174+0x8fclibdyld.dylib`start+0x1ls`0x1
133 — close_nocancel
65015/0x45006d: 6075 3 1 close_nocancel(0x3) = 0 0Close our first file that we opened, “.”
libsystem_kernel.dylib`__close_nocancel+0xals`0x000000010bc41b58+0x272ls`0x000000010bc41174+0x8fclibdyld.dylib`start+0x1ls`0x1
134 — write_nocancel
write_nocancel(0x1, “test.txt\n\004\b\0”, 0x9) = 9 0Finally, we print the list of files. The fruits of all our labor! Interesting to note this happens during a call to exit(). The library we’re using buffers output and flushes it when the program is about to finish.
libsystem_kernel.dylib`__write_nocancel+0xalibsystem_c.dylib`__sflush+0x57libsystem_c.dylib`fflush+0x28libc++.1.dylib`std::__1::__stdoutbuf<char>::sync()+0x89libc++.1.dylib`std::__1::basic_ostream<char, std::__1::char_traits<char> >::flush()+0x44libc++.1.dylib`std::__1::ios_base::Init::~Init()+0x10libsystem_c.dylib`__cxa_finalize_ranges+0x159libsystem_c.dylib`exit+0x37ls`0x000000010bc41174+0x908libdyld.dylib`start+0x1ls`0x1
System Call Counts
dtruss also gives you counts of how many times each system call was used:
CALL COUNTbsdthread_register 1exit 1fcntl 1fstatfs64 1getrlimit 1getuid 1munmap 1proc_info 1shared_region_check_np 1write_nocancel 1close 2getdirentries64 2getpid 2issetugid 2lseek 2open 2pread 2thread_selfid 2csops 3fchdir 3ioctl 3sysctl 3mmap 4fstat64 8mprotect 8close_nocancel 9open_nocancel 9read_nocancel 12stat64 47
Most used was stat64, mostly from when we recursively loaded our dylib dependencies.
Next were read/open/close. This included reading:
- The dtrace dylib
- Locale files
- The directory we printed with ls
Next was mprotect, which came from dyld’s use of malloc.
Next was fstat64, mostly called by fread(), which was used to load the locale files.
Next was mmap, which was used to load the dtrace dylib into memory.
I’ll skip the long tail, but interestingly, the stats show one call to exit(), which was not logged. I guess there’s no time to log it after exiting. But then how did it show up at all?
System Call times
dtruss also gives you how many microseconds each call took. The biggest offenders were:
microseconds syscall83 open(“/dev/dtracehelper\0”, 0x2, 0x7FFF5D8997D0) = 3 079 ioctl(0x3, 0x80086804, 0x7FFF5D899758) = 0 047 thread_selfid(0x0, 0x0, 0x0) = 4528000 043 read_nocancel(0x3, “@\004\031\0”, 0xDDD0) = 56784 037 stat64(“/usr/lib/dtrace/libdtrace_dyld.dylib\0”, 0x7FFF5D898DA8, 0x7FFF5D899910) = 0 0
Not surprisingly, accessing the file system takes a long time.
thread_selfid took a very long time the first time we called, but only only 2 microseconds the second time. Possibly because it was cached the second time, or because we had to wait for the OS to assign it to us the first time. It was also the first system call we made, so maybe the OS was doing some kind of lazy initialization.
Summary
So generally here’s what happened when I ran my command:
- The “ls” executable started by immediately calling into dyld to load dynamic libraries
- dyld called csops to verify itself.
- Dyld read the list of dependencies in the executable’s header recursively resolved their dependencies. dtrace was the only one that wasn’t in memory and need to be read and mmap’ed.
- dyld registered this program with dtrace by calling ioctl on /dev/dtracehelper
- dyld::initializeMainExecutable() ran and did a lot of initialization
- ls loaded locale files
- ls found the directory referenced by “.” and used getdirentries64() to get a list of entries in that directory
- ls generated some formatted output and wrote it to stdout
Other interesting things
dtruss turns out to be a bash script that contains a D program in a string. I looked at the source by running:
>>> which dtruss/usr/bin/dtruss
That script puts a D program into a variable, then passes it as a command line argument to /usr/sbin/dtrace . It also passes the shell command you want to run as another command line argument to dtrace (in this case, “ls”).
I’m still not sure how dtrace inserts itself into the “ls” program I tell it to run. What tells dyld to load libdtrace_dyld.dylib ? Or to open /dev/dtracehelper ? Would it do those things if I wasn’t running dtruss? How are system calls reported back to dtrace? More questions to investigate later.
