Upgrade to Pro — share decks privately, control downloads, hide ads and more …

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

Colin Jones
November 10, 2016

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

Colin Jones

November 10, 2016
Tweet

More Decks by Colin Jones

Other Decks in Programming

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
    [email protected]

    View Slide