|
http://prefetch.net/blog/index.php/category/solaris-dtrace/page/2/ DTraceToolkit presentation slides Tonight I gave a talk at the local opensolaris users group titled “DTrace for SysAdmins: An introduction to the DTraceToolkit.” I would like to thank everyone for coming out, and for putting up with my broken voice (I am currently getting over a cold). I put the presentation slides up on prefetch.net, and I hope everyone will snag the latest version of the toolkit and test it out! 30 Jul
Useful
DTrace links I came across a couple of super useful DTrace links, and thought I would pass them on: Brendan Gregg’s DTrace presentation in London: Opensolaris student guide (the chapter on using DTrace to debug
device drivers is awesome): I have spent a fair amount of time in the past few weeks reading through RFC 1813 (NFSv3), and wanted to find a way to see if a given client operation resulted in a physical or logical I/O operation. Since the DTrace FBT provider allows you to observe entry and exit from 99.999% of the functions in the Solaris kernel, I decided DTrace would be ideal for answering this question. After reading through the vast majority of the NFSv3 client source code on opensolaris.org, I crafted a DTrace program named nfstrace to display NFSv3 client operations by process: $ nfstrace Executable Operation Type Time Size Path mkdir nfs3_lookup physical 359953 N/A /opt/nfs/htdocs/test mkdir nfs3_getattr logical 17481 N/A /opt/nfs/htdocs/test mkdir nfs3_getattr logical 7577 N/A /opt/nfs/htdocs/test mkdir nfs3_mkdir physical 843500 N/A /opt/nfs/htdocs/test/test rmdir nfs3_access logical 19772 N/A /opt/nfs/htdocs/test rmdir nfs3_lookup logical 69222 N/A /opt/nfs/htdocs/test/test rmdir nfs3_access logical 7744 N/A /opt/nfs/htdocs/test rmdir nfs3_rmdir physical 1390474 N/A /opt/nfs/htdocs/test/test touch nfs3_access logical 19566 N/A /opt/nfs/htdocs/test touch nfs3_lookup logical 68824 N/A /opt/nfs/htdocs/test/1 touch nfs3_getattr logical 17842 N/A /opt/nfs/htdocs/test/1 touch nfs3_access logical 7746 N/A /opt/nfs/htdocs/test touch nfs3_lookup logical 26527 N/A /opt/nfs/htdocs/test/1 touch nfs3_setattr logical 597203 N/A /opt/nfs/htdocs/test/1 ln nfs3_lookup physical 299999 N/A /opt/nfs/htdocs/test/2 ln nfs3_access physical 20033 N/A /opt/nfs/htdocs/test ln nfs3_lookup physical 222977 N/A /opt/nfs/htdocs/test/2 ln nfs3_access physical 9553 N/A /opt/nfs/htdocs/test ln nfs3_lookup physical 222109 N/A /opt/nfs/htdocs/test/2 ln nfs3_symlink physical 899939 N/A /opt/nfs/htdocs/test/2 -> /opt/nfs/htdocs/test/1 cat nfs3_access logical 19528 N/A /opt/nfs/htdocs/test cat nfs3_lookup logical 67471 N/A /opt/nfs/htdocs/test/2 cat nfs3_access logical 7722 N/A /opt/nfs/htdocs/test cat nfs3_lookup logical 26941 N/A /opt/nfs/htdocs/test/1 cat nfs3_access physical 278486 N/A /opt/nfs/htdocs/test/1 cat nfs3_getattr logical 17554 N/A /opt/nfs/htdocs/test/1 cat nfs3_read logical 54848 8192 /opt/nfs/htdocs/test/1 cat nfs3_read logical 10082 8192 /opt/nfs/htdocs/test/1 bash nfs3_access logical 19707 N/A /opt/nfs/htdocs/test bash nfs3_lookup logical 66602 N/A /opt/nfs/htdocs/test/. bash nfs3_access logical 7740 N/A /opt/nfs/htdocs/test cp nfs3_write physical 38821 3935 /opt/nfs/htdocs/test/99 The script leverages the fact that each file system implements a set of operations call VOPS (VNODE Operations), which are called by the Solaris kernel in response to a system call that operates on a file or directory in a given file system. In the case of NFSv3, when you issue a read(2) system call, the kernel will determine that the operation applies to a file on an NFSv3 share, and will invoke nfs3_read, which is the NFSv3-specific read routine. For further details on VNODE Operations, VFS and the NFS implementation, I will refer you to Solaris and UNIX internals. 22 Apr
DTrace
timestamps While rereading several sections in the Solaris DTrace user guide, I came across the following descriptions for the timestamp and vtimestamp variables: uint64_t timestamp: The current value of a nanosecond timestamp counter. This counter increments from an arbitrary point in the past and should only be used for relative computations. uint64_t vtimestamp: The current value of a nanosecond timestamp counter that is virtualized to the amount of time that the current thread has been running on a CPU, minus the time spent in DTrace predicates and actions. This counter increments from an arbitrary point in the past and should only be used for relative time computations. After reading this, it dawned on me that some of the scripts I wrote should have used vtimestamp instead of timestamp (blocking operations can really skew the results). Luckily I foudn this now, so I can take advatnage of it whiel debugging problems in the future. While reading through the NFS RFCs this week, I decided to write nfsclientstats.pl to view NFS operations by process: $ nfsclientstats.pl process read write readdir getattr setattr lookup access create remove rename mkdir rmdir mkdir 0 0 0 380 0 190 0 0 0 0 190 0 mv 0 0 0 189 0 1890 2079 0 0 189 0 0 orca 3328 194 0 5496 6 6882 8246 12 0 0 0 0 rm 0 0 760 950 0 2850 5320 0 190 0 0 190 touch 0 0 0 378 189 1512 1323 189 0 0 0 0 process read write readdir getattr setattr lookup access create remove rename mkdir rmdir mkdir 0 0 0 386 0 193 0 0 0 0 193 0 mv 0 0 0 195 0 1950 2145 0 0 195 0 0 orca 3110 169 0 8312 22 10434 12476 44 0 0 0 0 rm 0 0 780 975 0 2925 5460 0 195 0 0 195 touch 0 0 0 388 194 1552 1358 194 0 0 0 0 The script uses the DTrace FBT provider, and produces output that is greater than 80-characters. If you are an 80-column purist, you might want to refrain from downloading the script. ;) Hope folks find this useful! After learning about fsstat , I decided to create a similar program that used DTrace (fsstat uses libkstat). After reading through syscall.h and reviewing the system calls available in the syscall provider, I created dfsstat.pl: $ dfsstat.pl 5 process open close read write stat creat link unlink symlink mkdir rmdir cat 148 148 74 37 111 0 0 0 0 0 0 dfsstat.pl 0 0 6 0 0 0 0 0 0 0 0 dtrace 0 0 0 7 0 0 0 0 0 0 0 ln 111 74 0 0 185 0 0 0 37 0 0 mkdir 148 111 0 0 148 0 0 0 0 37 0 mv 111 74 0 0 111 0 0 0 0 0 0 rm 370 259 0 0 370 0 0 222 0 0 37 test.sh 0 222 0 37 0 74 0 0 0 0 0 touch 111 222 0 0 407 148 0 0 0 0 0 Hope folks find this useful. 30 Mar
Debugging
DTrace While catching up on the DTrace discussion list tonight, I came across a cool DTrace debugging recommendation from Adam Leventhal. Adam mentioned using the DTRACE_DEBUG flag, which will cause libdtrace to spew tons of debugging data each time dtrace is invoked: $ export DTRACE_DEBUG=1 $ dtrace -n ’syscall:::entry { @calls[execname] = count(); }’ libdtrace DEBUG: opened provider fasttrap libdtrace DEBUG: opened provider fbt libdtrace DEBUG: opened provider lockstat libdtrace DEBUG: opened provider profile libdtrace DEBUG: opened provider sdt libdtrace DEBUG: opened provider systrace libdtrace DEBUG: opened 64-bit module unix (/platform/sun4u/kernel/sparcv9/unix) [0] libdtrace DEBUG: opened 64-bit module krtld (misc/sparcv9/krtld) [1] libdtrace DEBUG: opened 64-bit module genunix (/platform/sun4u/kernel/sparcv9/genunix) [2] libdtrace DEBUG: opened 64-bit module platmod (/platform/SUNW,Ultra-5_10/kernel/misc/sparcv9/platmod) [3] libdtrace DEBUG: opened 64-bit module SUNW,UltraSPARC-IIi (/platform/sun4u/kernel/cpu/sparcv9/SUNW,UltraSPARC-IIi) [4] libdtrace DEBUG: opened 64-bit module specfs (/kernel/fs/sparcv9/specfs) [6] libdtrace DEBUG: opened 64-bit module dtrace (/kernel/drv/sparcv9/dtrace) [7] [ ...... ] dtrace: description 'syscall:::entry ' matched 225 probes ^C utmpd 2 fmd 4 inetd 4 svc.configd 5 svc.startd 5 sshd 16 nscd 77 ipmon 94 mysqld 149 dtrace 1784 libdtrace DEBUG: dt_buf_destroy(section headers): size=1024 resizes=1 libdtrace DEBUG: dt_buf_destroy(string table): size=512 resizes=0 libdtrace DEBUG: dt_buf_destroy(loadable data): size=512 resizes=0 libdtrace DEBUG: dt_buf_destroy(unloadable data): size=512 resizes=0 libdtrace DEBUG: dt_buf_destroy(probe data): size=512 resizes=0 libdtrace DEBUG: dt_buf_destroy(probe args): size=512 resizes=0 libdtrace DEBUG: dt_buf_destroy(probe offs): size=512 resizes=0 libdtrace DEBUG: dt_buf_destroy(probe rels): size=512 resizes=0 This is super cool, and useful for tracking down problems, or learning more about what DTrace does behind the scenes. If you live in the Atlanta, GA area, you might be interested to know that Jarod Jenson will be talking about DTrace April 19th at the Marriott Perimeter Center. The event is being put on by Sun FREE of charge, and will be way better than any training course you could take on the subject ( there is one exception; a class by Brendan Gregg would be just as awesome )! Sun is requiring pre-registration to ensure that enough seats are available, and the meeting will be held at a swank location! I plan to wander to the event with Clay, and I am hoping to learn more about DTrace, the DVM provider, debugging and DTrace implementation details. Jarod is one of the smartest people at Sun, and the Atlanta SysAdmin community is truly fortunate to get him for a day. If you can make time, I HIGHLY recommend wandering to the Marriott to hear Jarod talk! You WILL NOT be disappointed! |
