DTrace Topics Quick Wins
From Siwiki
Contents |
[edit] DTrace Topics: Quick Wins
This article is about DTrace Quick Wins, and is part of the DTrace Topics collection. A general understanding of DTrace is assumed knowledge, which can be studied from the DTrace Topics: Intro section.
DTrace is a dynamic troubleshooting and analysis tool first introduced in the Solaris 10 and OpenSolaris operating systems.
Completion 
Difficulty 
Audience New DTrace users
[edit] DTrace Quick Wins
DTrace is a comprehensive tracing framework that can examine the entire software stack, including the kernel. That's the good news. The bad news is that this is an overwhelming amount of visibility, leaving many new users feeling helpless and lost.
There has been much effort to make DTrace more approachable, such as the creation of stable high level providers, and the numerous examples in both the DTrace Guide and the DTraceToolkit. However I am still often asked,
- "Just tell me the top things to try"
This isn't easy to answer for the following reasons:
[edit] The Good
- You may get some quick performance wins
- A very practical way to indroduce you to DTrace
[edit] The Bad
- Can only introduce you to a fraction of the field of DTrace
- Every site is different, there is no one-size-fits-all set of scripts
- Somewhat ill-conceived; DTrace wins often aren't that quick
[edit] The Ugly
- A customer declaring that "DTrace found nothing" after only trying the quick wins
We hope that some of this quick wins do work for you, and that they introduce you to DTrace. They are very generic, and only a fraction of what DTrace can do (see DTrace Topics).
[edit] Process Execution
[edit] How
Trace the creation of new processes using this one-liner,
# dtrace -n 'proc:::exec-success { trace(curpsinfo->pr_psargs); }'
[edit] Examples
The following output caught the execution of man ls, and all the processes which it creates,
dtrace: description 'proc:::exec-success ' matched 1 probe CPU ID FUNCTION:NAME 0 13772 exec_common:exec-success man ls 0 13772 exec_common:exec-success sh -c cd /usr/man; tbl /usr/man/man1/ls.1 |neqn /usr/share/lib/pub/eqnchar - |n 0 13772 exec_common:exec-success tbl /usr/man/man1/ls.1 0 13772 exec_common:exec-success neqn /usr/share/lib/pub/eqnchar - 0 13772 exec_common:exec-success nroff -u0 -Tlp -man - 0 13772 exec_common:exec-success col -x 0 13772 exec_common:exec-success sh -c trap 1 15; /usr/bin/mv -f /tmp/mpY7aGaF /usr/man/cat1/ls.1 2> /dev/nul 0 13772 exec_common:exec-success /usr/bin/mv -f /tmp/mpY7aGaF /usr/man/cat1/ls.1 0 13772 exec_common:exec-success sh -c more /tmp/mpY7aGaF 0 13772 exec_common:exec-success more /tmp/mpY7aGaF ^C
[edit] What to check
- Frequency of process creation
- Process creation costs CPU. Frequent process creation (more than 100 per second) can be a performance issue.
- Process arguments
- Checking the arguments to processes can be a great source for troubleshooting
[edit] Application CPU Sampling
While DTrace is used mostly for tracing, there is plenty of value to be found by using DTrace for sampling. The following samples what an application is doing when it is on-CPU, by aggregating its user-level stack trace.
[edit] How
The following samples the stack trace of processes called top at 1001 Hertz. 1001 Hertz is used so that each sample is roughly equal to 1 millisecond, and to reduce the potential problem of synching with a thread that may fire every second.
# dtrace -n 'profile-1001 /execname == "top"/ { @[ustack()] = count(); }'
- For C++ applications, save the output and translate using c++filt.
- For Java applications, use jstack() instead of ustack().
[edit] Examples
dtrace: description 'profile-1001 ' matched 1 probe
^C
[...]
libc.so.1`__open+0x7
libc.so.1`open+0x97
top`getptable+0xe5
top`get_process_info+0x14
top`main+0x695
top`_start+0x80
36
libc.so.1`getdents64+0x7
libc.so.1`readdir+0x20
top`getptable+0x1f7
top`get_process_info+0x14
top`main+0x695
top`_start+0x80
64
libc.so.1`_read+0x7
top`getptable+0x101
top`get_process_info+0x14
top`main+0x695
top`_start+0x80
287
The above output shows stack traces along with a count of times seen while DTrace was sampling.
The bottom stack was seen 287 times, and the next was seen 64 times. By reading through both stacks carefully, we can see that both were in the top function getptable() - which shows in terms of the top code where CPU time was spent.
[edit] What to Check
- Counts of the most frequent stack traces
- The accuracy of sampling may be sufficient to identify code bottlenecks, which will be seen as either one stack with the largest count, or several stacks which have a common function name and which add to a large count.
[edit] Caveats
- Sampling may miss fleeting events
- Application latency is often caused by time spent off the CPU (due to I/O requests or mutex lock contention), not on the CPU, which won't be identified by on-CPU sampling
Both issues can be solved with additional DTrace commands to trace events.
[edit] Kernel CPU Sampling
While DTrace is used mostly for tracing, there is plenty of value to be found by using DTrace for sampling. The following samples what the kernel is doing when it is on-CPU, by aggregating its kernel-level stack trace.
[edit] How
This one-liner samples the kernel stack trace at 1001 Hertz.
# dtrace -n 'profile-1001 /arg0/ { @[stack()] = count(); }'
[edit] Examples
dtrace: description 'profile-1001 ' matched 1 probe
^C
[...]
unix`bcopy+0xa
nge`nge_m_tx+0x58
dls`dls_tx+0x1d
dld`dld_tx_single+0x2a
dld`str_mdata_fastpath_put+0x7f
ip`tcp_send_data+0x889
ip`tcp_send+0xa7b
ip`tcp_wput_data+0x77f
ip`tcp_rput_data+0x2bb0
ip`squeue_enter_chain+0x11d
ip`ip_input+0x985
dls`i_dls_link_rx+0x2af
mac`mac_rx+0x71
nge`nge_receive+0x47
nge`nge_intr_handle+0xb0
nge`nge_chip_intr+0x6f
unix`av_dispatch_autovect+0x78
unix`dispatch_hardint+0x2f
unix`switch_sp_and_call+0x13
86
unix`kcopy+0x2c
genunix`uiomove+0x8e
genunix`mcopyinuio+0x132
sockfs`sostream_direct+0xd9
sockfs`sotpi_sendmsg+0x3a7
sockfs`sosendmsg+0x1e
iscsi`iscsi_net_tx+0x93
iscsi`iscsi_tx_pdu+0x248
iscsi`iscsi_tx_data+0x153
iscsi`iscsi_tx_r2t+0x64
iscsi`iscsi_tx_cmd+0x50
iscsi`iscsi_cmd_state_pending+0x14d
iscsi`iscsi_cmd_state_machine+0x83
iscsi`iscsi_tx_thread+0x86
iscsi`iscsi_threads_entry+0x15
genunix`taskq_thread+0x1a7
unix`thread_start+0x8
98
unix`mach_cpu_idle+0x6
unix`cpu_idle+0xc8
unix`idle+0x10e
unix`thread_start+0x8
4321
The above output shows kernel stack traces with a count of times seen while DTrace was sampling.
The most frequest stack trace was caused the cpu_idle() function (idle CPUs) at 4321 samples, followed by iscsi code with 98 samples, and then the TCP/IP stack with 86 samples.
[edit] What to Check
- Most frequent stack trace
- The stack traces contain raw kernel function names, which can be deciphered with some research. This will provide a rough idea of where the kernel is spending CPU time.
[edit] Caveats
- Sampling may miss fleeting events
This can be solved using additional DTrace commands to trace rather than sample.
[edit] Physical I/O bytes by process
The following measures requested I/O bytes by using the DTrace io provider. The io provider traces,
- I/O to physical disks
- I/O to disk volumes
- I/O to NFS mounts
These are I/O events from the kernel drivers, and can be described as physical I/O (rather than logical I/O seen at the application level). Additional DTrace syntax can be used to print or filter I/O types.
[edit] How
Trace requested I/O bytes by process using this one liner,
# dtrace -n 'io:::start { @[pid, execname] = sum(args[0]->b_bcount); }'
[edit] Examples
The following output traced disk I/O from both a tar and a find command,
dtrace: description 'io:::start ' matched 6 probes
^C
0 sched 2372608
971 find 3014656
970 tar 4530176
The output columns are PID, process name, and requested I/O bytes while DTrace was tracing.
The tar command requested 4.53 Mbytes of I/O, and the find command requested 3.01 Mbytes. sched represents the kernel and its drivers, which would include file system events such as asynchronous data writes to disk.
[edit] What to Check
- Top byte counts for an interval
- While the performance impact is better measured in units of time consumed, the rate of bytes transferred may be better understood by sysadmins and developers.
- Check who the top processes are which caused I/O, and what their I/O rates are. Any they reasonable considering what work the application and system is performing?
- An unexpected process
- Regular tools like iostat don't tell you who is causing disk I/O. You may find a process chewing disks that shouldn't be running at all, such as someone running a backup running during business hours.
[edit] Physical I/O byte sizes
The following measures requested I/O bytes using the io provider, which measures the I/O events described in the previous section. Here we use the DTrace quantize aggregating function to print a distribution plot.
[edit] How
# dtrace -n 'io:::start { @[execname] = quantize(args[0]->b_bcount); }'
[edit] Examples
dtrace: description 'io:::start ' matched 6 probes
^C
sched
value ------------- Distribution ------------- count
256 | 0
512 |@ 14
1024 |@@@@ 42
2048 |@@@@@@ 61
4096 |@@@@@@ 57
8192 |@@@@ 39
16384 |@@ 24
32768 | 5
65536 |@@@@@@@@@@@@@@@ 150
131072 |@@ 17
262144 | 0
tar
value ------------- Distribution ------------- count
1024 | 0
2048 |@ 13
4096 |@@ 18
8192 |@@@ 30
16384 |@@@@@@@@ 87
32768 |@@@ 31
65536 |@@@@@@@@@@@@@@@@@@@@@@@@ 277
131072 |@ 8
262144 | 0
dd
value ------------- Distribution ------------- count
65536 | 0
131072 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 395
262144 | 0
The above output shows the process name and a distribution plot with the requested I/O transaction size as the "value" and the number of occurances as the "count".
The output shows a dd command requesting 128 Kbyte physical reads, and a tar command requesting a variety of sized reads - mostly in the 64 Kbyte to 128 Kbyte distribution bucket. There was also some activity from sched, the kernel, which can be explained in further detail using additional DTrace commands.
[edit] What to Check
- Most frequent size of I/O
- Physical I/O events have a minimum cost due to various driver and device overheads, and a variable cost due to the transaction size. The best performance is usually found by choosing the largest I/O size. If the distributions show that an application is accessing the disks using many small transactions, it should be worth checking if the application can be tuned to use a larger I/O size.
- Scattered I/O sizes
- This could mean random I/O, which can degrade performance on physical disks. Additional DTrace commands can measure the randomness of disk activity.
