1************************************************************************** 2* The following are additional notes on the dtruss program. 3* 4* $Id: dtruss_notes.txt,v 1.1.1.1 2015/09/30 22:01:09 christos Exp $ 5* 6* COPYRIGHT: Copyright (c) 2007 Brendan Gregg. 7************************************************************************** 8 9 10* Can I trust the elapsed and on-cpu times? 11 12Firstly, lets see dtruss do something cool, 13 14 # dtruss -eo -n bash 15 PID/LWP ELAPSD CPU SYSCALL(args) = return 16 6215/1: 57 37 write(0x2, "h\0", 0x1) = 1 0 17 6215/1: 357210 45 read(0x0, "e\0", 0x1) = 1 0 18 6215/1: 53 37 write(0x2, "e\0", 0x1) = 1 0 19 6215/1: 359510 46 read(0x0, "l\0", 0x1) = 1 0 20 6215/1: 57 42 write(0x2, "l\0", 0x1) = 1 0 21 6215/1: 166495 47 read(0x0, "l\0", 0x1) = 1 0 22 6215/1: 56 40 write(0x2, "l\0", 0x1) = 1 0 23 6215/1: 346076 44 read(0x0, "o\0", 0x1) = 1 0 24 6215/1: 54 38 write(0x2, "o\0", 0x1) = 1 0 25 6215/1: 349852 45 read(0x0, " \0", 0x1) = 1 0 26 6215/1: 54 39 write(0x2, " \0", 0x1) = 1 0 27 28In the above, the slow elapsed times for reads are due to the process context 29switching off the CPU while we wait for the next keystroke. For example, 30the second line shows an on-CPU time of 45 us and an elapsed time of 357210 us. 31In fact, the elapsed times are equal to the inter-keystroke delays. 32 33 34What about the writes? Their elapsed times are longer than the on-CPU times 35also. Did we context switch off for them too? ... Lets run a different demo, 36 37 # dtruss -eo date 38 ELAPSD CPU SYSCALL(args) = return 39 Mon Jul 25 21:41:40 EST 2005 40 44 23 resolvepath("/usr/bin/date\0", 0x80476CC, 0x3FF) = 13 0 41 10 1 sysconfig(0x6, 0xB25A1, 0xFEC1D444) = 4096 0 42 36 28 resolvepath("/usr/lib/ld.so.1\0", 0x80476CC, 0x3FF) = 12 0 43 18 9 xstat(0x2, 0x8047FEB, 0x8047AF8) = 0 0 44 25 16 open("/var/ld/ld.config\0", 0x0, 0x0) = -1 Err#2 45 27 18 xstat(0x2, 0xD27FBF38, 0x80473B0) = 0 0 46 17 9 resolvepath("/lib/libc.so.1\0", 0x8047438, 0x3FF) = 14 0 47 21 13 open("/lib/libc.so.1\0", 0x0, 0x0) = 3 0 48 30 22 mmap(0x10000, 0x1000, 0x5) = -763559936 0 49 15 6 mmap(0x10000, 0xCE000, 0x0) = -764411904 0 50 24 16 mmap(0xD2700000, 0xB5A45, 0x5) = -764411904 0 51 21 12 mmap(0xD27C6000, 0x5EB3, 0x3) = -763600896 0 52 18 9 mmap(0xD27CC000, 0x15C0, 0x3) = -763576320 0 53 14 5 munmap(0xD27B6000, 0x10000) = 0 0 54 186 176 memcntl(0xD2700000, 0x1B8D8, 0x4) = 0 0 55 17 7 close(0x3) = 0 0 56 [...] 57 58For every syscall, the elapsed time is around 10 us (microseconds) slower 59than the on-cpu time. These aren't micro context switches, this is due to 60DTrace slowing down the program! The more closely we measure something the 61more we effect it. (See Heisenberg's uncertainty principle). 62 63Ok, so for the above output we can tell that each elapsed time is around 10 us 64longer than it should be. That's fine, since it's fairly consistant and not 65a huge difference. This is an x86 server with a 867 MHz CPU. 66 67 68Now lets try the same on an Ultra 5 with a 360 MHz CPU, 69 70 # dtruss -eo date 71 ELAPSD CPU SYSCALL(args) = return 72 216 142 resolvepath("/usr/bin/date\0", 0xFFBFF338, 0x3FF) = 13 0 73 234 187 resolvepath("/usr/lib/ld.so.1\0", 0xFFBFF338, 0x3FF) = 12 0 74 113 67 stat("/usr/bin/date\0", 0xFFBFF818, 0xFFBFFFEB) = 0 0 75 136 90 open("/var/ld/ld.config\0", 0x0, 0x0) = -1 Err#2 76 107 61 stat("/opt/onbld/lib/libc.so.1\0", 0xFFBFF330, 0xFFBFF55C) = -1 Err#2 77 98 54 stat("/opt/SUNWspro/lib/libc.so.1\0", 0xFFBFF330, 0xFFBFF55C) = -1 Err#2 78 96 53 stat("/opt/SUNWmlib/lib/libc.so.1\0", 0xFFBFF330, 0xFFBFF55C) = -1 Err#2 79 97 54 stat("/usr/sfw/lib/libc.so.1\0", 0xFFBFF330, 0xFFBFF55C) = -1 Err#2 80 96 53 stat("/lib/libc.so.1\0", 0xFFBFF330, 0xFFBFF55C) = 0 0 81 134 92 resolvepath("/lib/libc.so.1\0", 0xFFBFEF30, 0x3FF) = 14 0 82 109 69 open("/lib/libc.so.1\0", 0x0, 0x0) = 3 0 83 177 132 mmap(0x10000, 0x2000, 0x5) = -12976128 0 84 [...] 85 86Now the time difference is around 40 us, and fairly consistant. 87 88 89This difference is find so long as we bear it in mind. Or, run DTrace 90on faster servers where the difference is much less. 91 92 93 94* The output appears shuffled? 95 96Read the answer to this in ALLsnoop_notes.txt. 97 98