Collecting data with DTraceTools

Modified: 11 Mar 2016 16:17 UTC

DTrace is a sophisticated framework for developing scripts that aid in troubleshooting performance issues on production systems in real-time. [Cloud Analytics](Built-in Cloud Analytics.html), which is available for free in the Joyent Public Cloud, is built off of DTrace. However, you can also use DTrace directly on systems you provision in the Joyent Public Cloud through dtracetools.

About the dtracetools package

The dtracetools package is available through the pkgsrc repository and includes several pre-defined DTrace scripts specifically tailored towards common use cases in the Joyent Public Cloud. The package is installed by default on all available images in the Joyent Public Cloud. All DTrace scripts this package installs are located in /opt/local/bin/ and are prefixed with dtrace-*.

The initial version of dtracetools first appeared in the 2011Q4 pkgsrc branch. You can install dtracetools from pkgsrc by running this:

pkgin in dtracetools

Helpful DTrace commands

Here are a few helpful DTrace commands you can use to uncover latency issues with MySQL, MongoDB, and PHP.

Viewing MongoDB commands per second

Use dtrace-mongocmd.d:

# dtrace-mongocmd.d -p `pgrep -x mongod`
dtrace: script '/opt/local/bin/dtrace-mongocmd.d' matched 2 probes
CPU     ID                    FUNCTION:NAME
6  71046                         :tick-1s
6  71046                         :tick-1s
6  71046                         :tick-1s mongo cmds/s: 18
6  71046                         :tick-1s mongo cmds/s: 0
6  71046                         :tick-1s mongo cmds/s: 0
6  71046                         :tick-1s mongo cmds/s: 0
6  71046                         :tick-1s mongo cmds/s: 0
6  71046                         :tick-1s mongo cmds/s: 0
6  71046                         :tick-1s mongo cmds/s: 18
6  71046                         :tick-1s mongo cmds/s: 0
6  71046                         :tick-1s mongo cmds/s: 0
^C

Viewing MySQL queries longer than one millisecond

Use dtrace-mysql_pid_slow.d:

# dtrace-mysql_pid_slow.d -p `pgrep -x mysqld` 1
Tracing... Min query time: 1000000 ns.

TIME(ms) CPU(ms)  QUERY
91       3        show databases\0
27       0        select * from mysql.user\0
^C

Viewing MySQL query latency in a distribution

Use dtrace-mysql_pid_latency.d:

# dtrace-mysql_pid_latency.d -p `pgrep -x mysqld`
Tracing PID 10630... Hit Ctrl-C to end.
MySQL queries/second: 1; query latency (ns):

value  ------------- Distribution ------------- count
131072 |                                         0
262144 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
524288 |                                         0
^C

MySQL queries/second: 1; query latency (ns):

value  ------------- Distribution ------------- count
65536 |                                         0
131072 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
262144 |                                         0

Viewing MySQL query average execution time

Use dtrace-mysql_pid_avg.d:

# dtrace-mysql_pid_avg.d -p `pgrep -x mysqld`
Tracing PID 10630...
TIME                    QUERIES 1+sec_Qs  AVG(ms)  MAX(ms)
2012 Oct 19 15:23:07          1        0        0        0
2012 Oct 19 15:23:08          1        0        0        0
2012 Oct 19 15:23:09          0        0        0        0
^C

Viewing PHP function call counts

Use dtrace-php_funccalls.d:

# dtrace-php_funccalls.d
Tracing... Hit Ctrl-C to end.
^C
FILE                             FUNC                                CALLS
blah.php                         blastoff                                4
blah.php                         launch                                  4
blah.php                         one                                     4
blah.php                         sleep                                   4
blah.php                         three                                   4
blah.php                         two                                     4

Viewing PHP function flow

Use dtrace-php_flow.d:

# dtrace-php_flow.d
TIME(us)         -- FUNC
20578568252193   <- sleep
20578568252218   -> launch
20578568252229     -> three
20578568252269       -> two
20578568252282         -> one
20578568252296           -> blastoff
20578568252314           <- blastoff
20578568252320         <- one
20578568252324       <- two
20578568252329     <- three
20578568252333   <- launch
20578568252341   -> sleep