cddl/contrib/dtracetoolkit/Notes/dtruss_notes.txt

   1 **************************************************************************
   2 * The following are additional notes on the dtruss program.
   3 *
   4 * $Id: dtruss_notes.txt 44 2007-09-17 07:47:20Z brendan $
   5 *
   6 * COPYRIGHT: Copyright (c) 2007 Brendan Gregg.
   7 **************************************************************************
   8
   9
  10 * Can I trust the elapsed and on-cpu times?
  11
  12 Firstly, 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
  28 In the above, the slow elapsed times for reads are due to the process context
  29 switching off the CPU while we wait for the next keystroke. For example,
  30 the second line shows an on-CPU time of 45 us and an elapsed time of 357210 us.
  31 In fact, the elapsed times are equal to the inter-keystroke delays.
  32
  33
  34 What about the writes? Their elapsed times are longer than the on-CPU times
  35 also. 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
  58 For every syscall, the elapsed time is around 10 us (microseconds) slower
  59 than the on-cpu time. These aren't micro context switches, this is due to
  60 DTrace slowing down the program! The more closely we measure something the
  61 more we effect it. (See Heisenberg's uncertainty principle).
  62
  63 Ok, so for the above output we can tell that each elapsed time is around 10 us
  64 longer than it should be. That's fine, since it's fairly consistant and not
  65 a huge difference. This is an x86 server with a 867 MHz CPU.
  66
  67
  68 Now 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
  86 Now the time difference is around 40 us, and fairly consistant.
  87
  88
  89 This difference is find so long as we bear it in mind. Or, run DTrace
  90 on faster servers where the difference is much less.
  91
  92
  93
  94 * The output appears shuffled?
  95
  96 Read the answer to this in ALLsnoop_notes.txt.
  97