Upgrade to Pro
— share decks privately, control downloads, hide ads and more …
Speaker Deck
Features
Speaker Deck
PRO
Sign in
Sign up for free
Search
Search
Diving into the Details with DTrace! (RubyConf ...
Search
Colin Jones
November 10, 2016
Programming
2
460
Diving into the Details with DTrace! (RubyConf 2016 edition)
Colin Jones
November 10, 2016
Tweet
Share
More Decks by Colin Jones
See All by Colin Jones
A Bug's Life: What if `select` is Broken After All?
trptcolin
0
150
Underestimated costs of microservice architectures
trptcolin
3
1.5k
FP vs. OOP: Beyond the Bikeshed
trptcolin
0
410
Diving into the Details with DTrace
trptcolin
3
510
Adopting FP: the good, the familiar, and the unknown
trptcolin
0
230
Finding out what's *really* going on, with DTrace!
trptcolin
1
370
Beyond top: Command-Line Monitoring on the JVM (ClojureRemote)
trptcolin
0
130
Beyond top: Command-Line Monitoring on the JVM (JavaOne 2015)
trptcolin
1
670
ZooKeeper: Wait-free coordination for Internet-scale systems
trptcolin
2
180
Other Decks in Programming
See All in Programming
Swift Concurrency - 状態監視の罠
objectiveaudio
2
450
Conquering Massive Traffic Spikes in Ruby Applications with Pitchfork
riseshia
0
150
あなたの知らない「動画広告」の世界 - iOSDC Japan 2025
ukitaka
0
360
開発者への寄付をアプリ内課金として実装する時の気の使いどころ
ski
0
340
複雑化したリポジトリをなんとかした話 pipenvからuvによるモノレポ構成への移行
satoshi256kbyte
1
750
AIで開発生産性を上げる個人とチームの取り組み
taniigo
0
130
Goで実践するドメイン駆動開発 AIと歩み始めた新規プロダクト開発の現在地
imkaoru
2
150
GitHub Actions × AWS OIDC連携の仕組みと経緯を理解する
ota1022
0
240
CSC509 Lecture 03
javiergs
PRO
0
320
uniqueパッケージの内部実装を支えるweak pointerの話
magavel
0
900
メモリ不足との戦い〜大量データを扱うアプリでの実践例〜
kwzr
1
780
Build your own WebP codec in Swift
kishikawakatsumi
2
900
Featured
See All Featured
Thoughts on Productivity
jonyablonski
70
4.9k
Fight the Zombie Pattern Library - RWD Summit 2016
marcelosomers
234
17k
Building a Modern Day E-commerce SEO Strategy
aleyda
43
7.7k
Responsive Adventures: Dirty Tricks From The Dark Corners of Front-End
smashingmag
252
21k
I Don’t Have Time: Getting Over the Fear to Launch Your Podcast
jcasabona
33
2.4k
Performance Is Good for Brains [We Love Speed 2024]
tammyeverts
12
1.1k
Being A Developer After 40
akosma
91
590k
The Web Performance Landscape in 2024 [PerfNow 2024]
tammyeverts
9
850
Distributed Sagas: A Protocol for Coordinating Microservices
caitiem20
333
22k
The Illustrated Children's Guide to Kubernetes
chrisshort
48
51k
Why You Should Never Use an ORM
jnunemaker
PRO
59
9.6k
No one is an island. Learnings from fostering a developers community.
thoeni
21
3.5k
Transcript
Diving into the details with DTrace! Colin Jones @trptcolin
systems applications
problems solutions
problems solutions
What even is DTrace?
DTrace is… strace
DTrace is… strace++
strace++ $ sudo dtrace -qn ' syscall:::entry { @[probefunc, execname]
= count(); } dtrace:::END { trunc(@, 10); printa(@); }'
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
DTrace is… strace++ system resources
system resources $ sudo dtrace -qn ' vminfo:::maj_fault { @[execname]
= sum(arg0); }'
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
DTrace is… strace++ system resources statically-defined tracing
statically-defined tracing $ sudo dtrace -qn ' mysql*::: { @[probename]
= count(); } dtrace:::END { trunc(@, 10); printa(@); }'
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
DTrace is… strace++ system resources statically-defined tracing dynamic tracing
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; }'
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
DTrace is… strace++ system resources statically-defined tracing dynamic tracing
Weird slowness… it happens
Slooooooooow tests (…sometimes)
Multiple tests, multiple machines
Affects some teammates worse than others
annoying productivity-sapping stressful
Hypotheses?
Use DTrace!
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); }
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
System resources CPU Memory Disk Network
CPU? $ sudo dtrace -qn ' profile-997 { @[execname] =
count(); } '
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
CPU? $ sudo dtrace -qn ' profile-997 /execname=="kernel_task"/ { @[stack()]
= count(); } '
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
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
System resources CPU Memory Disk Network
Network connections https://github.com/brendangregg/DTrace-book-scripts/blob/master/Chap6/soconnect_mac.d
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
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; }
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
Now we know what to fix!
What did we learn?
Specific vs. General
DTrace is… strace++ system resources statically-defined tracing dynamic tracing
You can do it!
Where can we learn more?
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
Scripts that ship with OS X find /usr/bin -name "*.d"
more DTrace scripts https://github.com/brendangregg/DTrace-book-scripts Examples
DTrace: not just performance performance: not just DTrace Extrapolate
Try it out!
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
Thanks! Colin Jones @trptcolin
[email protected]