Diving into the Details with DTrace! (RubyConf 2016 edition)

Transcript

1. Diving into the details
   with DTrace!
   Colin Jones
   @trptcolin
   

   View Slide

2. systems applications
   

   View Slide

3. problems
   solutions
   

   View Slide

4. problems solutions
   

   View Slide

5. What even is DTrace?
   

   View Slide

6. DTrace is…
   strace
   

   View Slide

7. DTrace is…
   strace++
   

   View Slide

8. strace++
   $ sudo dtrace -qn '
   syscall:::entry {
   @[probefunc, execname] = count();
   }
   dtrace:::END {
   trunc(@, 10); printa(@);
   }'
   

   View Slide

9. strace++
   $ sudo dtrace -qn 'syscall:::entry {
   @[probefunc, execname] = count();
   }
   dtrace:::END { trunc(@, 10); printa(@); }'
   ^C
   read Slack 1993
   select Slack 2017
   kevent_qos Slack 2660
   kevent_qos WindowServer 2801
   psynch_cvsignal Box Sync 2873
   psynch_cvwait Box Sync 2873
   select Box Sync 4780
   madvise Slack 5783
   bsdthread_ctl Slack 6910
   workq_kernreturn Slack 10622
   

   View Slide

10. DTrace is…
    strace++
    system resources
    

    View Slide

11. system resources
    $ sudo dtrace -qn '
    vminfo:::maj_fault {
    @[execname] = sum(arg0);
    }'
    

    View Slide

12. system resources
    $ sudo dtrace -qn 'vminfo:::maj_fault {
    @[execname] = sum(arg0);
    }'
    ^C
    2BUA8C4S2C.com.a 1
    mdworker 2
    Google Chrome 12
    mds_stores 116
    Google Chrome He 252
    

    View Slide

13. DTrace is…
    strace++
    system resources
    statically-defined tracing
    

    View Slide

14. statically-defined tracing
    $ sudo dtrace -qn '
    mysql*::: {
    @[probename] = count();
    }
    dtrace:::END {
    trunc(@, 10); printa(@);
    }'
    

    View Slide

15. statically-defined tracing
    $ sudo dtrace -qn 'mysql*::: { @[probename] = count(); }
    dtrace:::END { trunc(@, 10); printa(@); }'
    ^C
    query-exec-start 3
    query-parse-done 3
    query-parse-start 3
    query-start 3
    select-done 3
    select-start 3
    net-read-done 18
    net-read-start 18
    net-write-done 18
    net-write-start 18
    

    View Slide

16. DTrace is…
    strace++
    system resources
    statically-defined tracing
    dynamic tracing
    

    View Slide

17. Dynamic tracing
    $ sudo dtrace -qn '
    fbt:mach_kernel::entry {
    self->in = timestamp;
    }
    fbt:mach_kernel::return /self->in/ {
    @ = quantize(timestamp - self->in)
    self->in = 0;
    }'
    

    View Slide

18. Dynamic tracing
    $ sudo dtrace -n 'fbt:mach_kernel::entry { self->in = timestamp; }
    fbt:mach_kernel::return /self->in/
    { @ = quantize(timestamp - self->in); self->in = 0; }'
    dtrace: description 'fbt:mach_kernel::entry ' matched 24482 probes
    ^C
    value ------------- Distribution ------------- count
    256 | 0
    512 |@@@@@@@@@@@@@@@@@@ 13521
    1024 |@@@@@@@@@@@@@@@@@@@ 14961
    2048 |@@@ 2172
    4096 | 79
    8192 | 71
    16384 | 7
    32768 | 3
    65536 | 3
    131072 | 2
    262144 | 0
    

    View Slide

19. DTrace is…
    strace++
    system resources
    statically-defined tracing
    dynamic tracing
    

    View Slide

20. Weird slowness…
    it happens
    

    View Slide

21. Slooooooooow tests
    (…sometimes)
    

    View Slide

22. Multiple tests,
    multiple machines
    

    View Slide

23. Affects some teammates
    worse than others
    

    View Slide

24. annoying
    productivity-sapping
    stressful
    

    View Slide

25. Hypotheses?
    

    View Slide

26. Use DTrace!
    

    View Slide

27. Rule out the usual suspect(s)?
    ruby*:::gc-mark-begin
    {
    self->mark_begin = timestamp;
    }
    ruby*:::gc-mark-end
    /self->mark_begin/
    {
    self->duration = (timestamp - self->mark_begin) / 1000000;
    self->phase = "mark";
    self->mark_begin = 0;
    }
    ruby*:::gc-*-end
    /self->duration/
    {
    printf("%-8d %-8d %-8s\n", pid, self->duration, self->phase);
    }
    

    View Slide

28. Garbage collection?
    $ sudo ruby-gc.d
    PID TIME(ms) PHASE
    30152 7 mark
    30152 33 mark
    30152 7 mark
    30152 9 mark
    30152 38 mark
    30152 17 mark
    30152 16 mark
    30152 17 mark
    30152 22 mark
    30152 71 mark
    30152 22 mark
    30152 6 sweep
    30152 3 sweep
    30152 4 sweep
    30152 1 sweep
    30152 23 mark
    

    View Slide

29. System resources
    CPU
    Memory
    Disk
    Network
    

    View Slide

30. CPU?
    $ sudo dtrace -qn '
    profile-997 { @[execname] = count(); }
    '
    

    View Slide

31. CPU?
    $ sudo dtrace -qn 'profile-997 { @[execname] = count(); }'
    ^C
    [...]
    Box Sync 3
    Google Drive 3
    ruby 3
    Google Chrome 9
    systemstatsd 11
    iTerm 14
    Google Chrome He 24
    WindowServer 25
    hidd 26
    Box Sync Monitor 47
    kernel_task 9527
    

    View Slide

32. CPU?
    $ sudo dtrace -qn '
    profile-997 /execname=="kernel_task"/
    { @[stack()] = count(); }
    '
    

    View Slide

33. CPU?
    $ sudo dtrace -qn 'profile-997 /execname=="kernel_task"/
    { @[stack()] = count(); }'
    ^C
    [...]
    kernel`0xffffff80010f3d30+0x358
    kernel`0xffffff800158d890+0x793
    kernel`kevent+0x44
    kernel`unix_syscall64+0x251
    kernel`hndl_unix_scall64+0x16
    116
    kernel`processor_idle+0x107
    121
    kernel`machine_idle+0x2e0
    kernel`call_continuation+0x17
    82967
    

    View Slide

34. CPU
    $ sudo dtrace -qn 'profile-997 { @[execname] = count(); }'
    ^C
    [...]
    Box Sync 3
    Google Drive 3
    ruby 3
    Google Chrome 9
    systemstatsd 11
    iTerm 14
    Google Chrome He 24
    WindowServer 25
    hidd 26
    Box Sync Monitor 47
    kernel_task 9527
    

    View Slide

35. System resources
    CPU
    Memory
    Disk
    Network
    

    View Slide

36. Network connections
    https://github.com/brendangregg/DTrace-book-scripts/blob/master/Chap6/soconnect_mac.d
    

    View Slide

37. Network connections
    https://github.com/brendangregg/DTrace-book-scripts/blob/master/Chap6/soconnect_mac.d
    $ sudo soconnect_mac.d
    PID PROCESS FAM ADDRESS PORT LAT(us) RESULT
    88161 ruby 2 127.0.0.1 5432 144 Success
    88161 ruby 2 127.0.0.1 5432 171 Success
    88161 ruby 2 127.0.0.1 5432 150 Success
    114 AirPlayXPCHelper 2 192.168.1.27 7000 1762 In progress
    88161 ruby 2 127.0.0.1 5432 141 Success
    88161 ruby 2 127.0.0.1 5432 179 Success
    88161 ruby 2 127.0.0.1 5432 137 Success
    88161 ruby 2 72.52.4.119 80 29977 Success
    88161 ruby 2 72.52.4.119 80 42121 Success
    88161 ruby 2 72.52.4.119 80 29471 Success
    88161 ruby 2 72.52.4.119 80 29360 Success
    88161 ruby 2 72.52.4.119 80 34731 Success
    88161 ruby 2 72.52.4.119 80 28824 Success
    

    View Slide

38. DNS
    pid$target::getaddrinfo:entry
    {
    self->start = timestamp;
    self->host = copyinstr(arg0);
    }
    pid$target::getaddrinfo:return
    /self->start/
    {
    this->now = (timestamp - timezero) / 1000000;
    this->time = (timestamp - self->start) / 1000000;
    printf("%-8d %-8d %s\n", this->now, this->time, self->host);
    self->start = 0; self->host = 0;
    }
    

    View Slide

39. DNS
    $ sudo dns_latency.d -p 41161
    Password:
    TICK ms HOST
    74450 274 redclay.local
    74734 0 redclay.local
    105006 30075 someplace.com
    145171 30075 someplace.com
    145191 1 redclay.local
    145192 0 redclay.local
    177055 0 example.com
    252314 2 redclay.local
    252315 0 redclay.local
    284392 0 example.com
    

    View Slide

40. Now we know what to fix!
    

    View Slide

41. What did we learn?
    

    View Slide

42. Specific vs. General
    

    View Slide

43. DTrace is…
    strace++
    system resources
    statically-defined tracing
    dynamic tracing
    

    View Slide

44. You can do it!
    

    View Slide

45. Where can we learn more?
    

    View Slide

46. Brendan Gregg's blog:
    http://www.brendangregg.com/dtrace.html
    The DTrace guide
    http://dtrace.org/guide
    DTrace: Dynamic Tracing in Oracle Solaris,
    Mac OS X, and FreeBSD
    http://amzn.to/2bqBczw
    Read
    

    View Slide

47. Scripts that ship with OS X
    find /usr/bin -name "*.d"
    more DTrace scripts
    https://github.com/brendangregg/DTrace-book-scripts
    Examples
    

    View Slide

48. DTrace: not just performance
    performance: not just DTrace
    Extrapolate
    

    View Slide

49. Try it out!
    

    View Slide

50. DTrace & SIP on El Capitan: http://internals.exposed/blog/dtrace-vs-sip.html
    Julia Evans' strace zine: http://jvns.ca/blog/2015/04/14/strace-zine/
    Jeff Hodges "Notes on Distributed Systems for Young Bloods": http://bit.ly/2b2mxLf
    Brendan Gregg's blog: http://www.brendangregg.com/dtrace.html
    The DTrace guide: http://dtrace.org/guide
    DTrace book: http://amzn.to/2bqBczw
    DTrace Toolkit: https://github.com/opendtrace/toolkit
    DTrace book scripts: https://github.com/brendangregg/DTrace-book-scripts
    SystemTap (Linux): https://sourceware.org/systemtap/
    bcc: https://github.com/iovisor/bcc
    Resources
    

    View Slide

51. Thanks!
    Colin Jones
    @trptcolin
    colin@8thlight.com
    

    View Slide