Viewing busy code paths with DTrace


Periodically I want to see the busiest application and system code paths on a system. Prior to Solaris 10, this was a difficult questions to answer without custom instrumentation. Now that we have DTrace, we can use the DTrace profile provider and an aggregation to view the busiest code paths in the kernel:

$ dtrace -n 'profile-1001 {@[stack(20)]=count()} END{trunc(@,2)}'

dtrace: description 'profile-1001 ' matched 2 probes
^C
CPU ID FUNCTION:NAME
0 2 :END


unix`atomic_cas_32+0x10
ufs`ufs_scan_inodes+0xf4
ufs`ufs_update+0x1e9
ufs`ufs_sync+0x213
genunix`fsop_sync_by_kind+0x36
genunix`fsflush+0x3e2
unix`thread_start+0x8
11

unix`cpu_halt+0x100
unix`idle+0x3f
unix`thread_start+0x8
3978

To see the busiest userland code paths, we can aggregate on the executable and userland stack frames, but only when we are in user context (arg1 indicates which context we are in):

$ dtrace -n 'profile-1001 /arg1/ {@[execname,ustack()]=count()} END{trunc(@,2)}'

dtrace: description 'profile-1001 ' matched 2 probes
^C
CPU ID FUNCTION:NAME
0 2 :END

kcfd
libmd.so.1`SHA1Transform+0x2ef
libmd.so.1`SHA1Update+0xb6
libelfsign.so.1`soft_digest_update+0x48
libelfsign.so.1`C_DigestUpdate+0xd7
libelfsign.so.1`_C01A7C0D+0x2d
libelfsign.so.1`elfsign_hash_common+0x175
libelfsign.so.1`_C01A7A0C+0x16
libelfsign.so.1`_C01A7A0D+0x23d
kcfd`kcfd_process_request+0x17e
libc.so.1`__door_return+0x60
12
sshd
libc.so.1`memcpy+0x6b
libcrypto.so.0.9.8`HMAC_Init_ex+0x1b2
libcrypto.so.0.9.8`HMAC_Init+0x3d
sshd`mac_compute+0x34
sshd`packet_send2+0x23c
sshd`packet_send+0x1b
sshd`channel_output_poll+0x1d2
sshd`server_loop2+0xe6
sshd`do_authenticated2+0xe
sshd`do_authenticated+0x3b
sshd`main+0x1081
sshd`_start+0x7a
52

This is huge, and with two lines of DTrace, you can dynamically view the busiest code paths in kernel and user context. Nice!

This article was posted by Matty on 2007-03-03 11:14:00 -0400 -0400