КатегорииLinksUnix Tutorial
Personal Development Ruslan Valiev Solaris Performance Team Damien Farnham Fintan Ryan Nicky Veitch Niall Mullen Sean McGrath DTrace Bryan Cantrill Brendan Gregg ZFS Tim Foster General Ben Rockwood Learning Solaris 10 Privacy policy |
Wednesday, January 12. 2005
DTrace: aggregation functions ... Posted by Gleb Reys
in DTrace at
19:26
Comments (0) Trackbacks (0) Defined tags for this entry: dtrace
DTrace: aggregation functions (aggregations)
Quite often it is more important for you to see the whole picture, rather than to know each case when a particular probe fires. For instance, observing a process which consumes a lot of CPU time according to prstat, we ask ourselves: what is this process doing? And often we think about the overall number of system calls executed by this process, and not every particular one of these system calls.
DTrace aggregations are created specifically for answering such questions. Working with sets of numerical data, aggregation functions help us to easily determing average, min and max values of data sets, count numbers and sums of elements in these data sets, and even build frequency distributions. More information can be found here, but today I'll show only few examples of using aggregations. DTrace stores the results of aggregation functions in objects called aggregations. The syntax is: @name[ keys ] = aggfunc ( args ); here: name - name of our aggregation keys - index keys, very similar to those of associative arrays. aggfunc - aggregation function args - function arguments, usually it's a set of numerical data Today I'll use sum aggregation function, which as it's obvious from the name, helps us calculate the sum of a numerical data set, Only the current value of the aggregation function is stored in the memory, it's calculated off the previous function argument values. Then the function is calculated for the current value of the argument, and this result is applied to the current aggregation value. For basic analysis you can use as few aggregations keys as you can - for instance, use only PID, without specifying thread ID as another index key.You can even use execname - but keep in mind that there might be more than one process running on your system with the same name. Still, execname-based aggregation will be quite useful to track what's getting most of our system's attention: Here's our script: CODE: #!/usr/sbin/dtrace -s #pragma D option quiet syscall:::entry { self->ts=timestamp; } syscall:::return { self->elapsed = timestamp - self->ts; @time[execname]=sum(self->elapsed); } END { printf("\n%20s %20s\n", "Execname", "Time elapsed"); printa("%20s %20@u\n", @time); } Save it into a file, do chmod a+x on this file and start it. You'll get an output similar to this: CODE: Execname Time elapsed xscreensaver 5710 gnome-smproxy 6886 wnck-applet 7735 gnome-panel 52032 metacity 54430 gnome-settings-d 60419 vim 66452 mixer_applet2 670078802 gnome-netstatus- 819836799 nautilus 900025830 Xorg 1074783431 gnome-terminal 1074816530 firefox-bin 2000076871 dtrace 9843796821648 The time in the last column is given in nanoseconds, so don't be scared with such huge numbers :) For timing some actions in your script timestamp proves to be VERY useful. It's a nanoseconds counter which increments from an arbitrary point, so it can be used for relative computations only. Now you can look at the output and notice how much of unnecessary actions is happening on my laptop with started Gnome ;) If you want a deeper analysis, you can make our script a bit more complex, and you'll get a powerful tool for determining what process was doing what on our system, and for how long. CODE: #!/usr/sbin/dtrace -s #pragma D option quiet syscall:::entry { self->ts=timestamp; } syscall:::return { self->elapsed = timestamp - self->ts; @time[execname,probefunc,pid,tid]=sum(self->elapsed); } END { printf("\n%20s %20s %8s %7s %20s\n", "Execname", "Syscall", "Process", "Thread", "Time elapsed"); printa("%20s %20s %8d %7d %20@u\n", @time); } If you save this code into syscalls.d and start the script, you'll probably get something similar (I've deleted lots of lines to save up some space): CODE: Execname Syscall Process Thread Time elapsed gnome-terminal read 7199 1 12867 Xorg read 6953 1 13769 dtrace brk 7331 1 33647 dtrace schedctl 7331 1 39320 gnome-terminal write 7199 1 48052 Xorg writev 6953 1 57112 gnome-terminal pollsys 7199 1 646816 dtrace lwp_park 7331 1 44817217 Xorg pollsys 6953 1 46936244 dtrace ioctl 7331 1 9269224066655 If you leave such a script running for a couple of minutes, you'll get a very long output with the list of every process running on your system all the system calls it's been executing, with the time spent by each thread of each process. Friday, January 7. 2005
DTrace: $target macro variable Posted by Gleb Reys
in DTrace at
18:34
Comments (0) Trackback (1) Defined tags for this entry: dtrace
DTrace: $target macro variable
Macro variables are meant to make your life MUCH easier when scripting with DTrace. Names of such variables must begin with a $ sign, and DTrace will automatically replace all the macro variables with the appropriate values when parsing your script.
Full list of macro variables can be found here, I will only talk about $target variable this time. $target specifies the PID of the process you associate with your DTrace script. DTrace has two useful command line options which can be used not only when running a dtrace command, but also when running DTrace-scripts: ./script.d -c xterm This command asks DTrace to run a command which follows the -c option, and process the actual script.d only after this. Our macro variable, $target, will containt a PID of the started command we specified - xterm in this example. ./script.d -p 654 This is a similar way of running a DTrace script, only we notify DTrace that we'd like to work with the process with PID of 654. This way of using DTrace is especially useful as you don't have to start or restart an already running process. $target will contain the PID specified in the command line - 654 in this example. $target may be used like this: CODE: #!/usr/sbin/dtrace -s #pragma D option quiet syscall:::entry, syscall:::return /pid == $target/ { printf("%d/%d: %s:%s\n", pid, tid, probefunc, probename); } If you execute this script, you'll probably get an output like this: CODE: ./script.d -c xterm 26525/1: munmap:entry 26525/1: munmap:return 26525/1: mmap:entry 26525/1: mmap:return 26525/1: setcontext:entry 26525/1: setcontext:return 26525/1: getrlimit:entry 26525/1: getrlimit:return 26525/1: getpid:entry 26525/1: getpid:return ... Just a little bit later I'll talk about aggregations - yet another one of the wonderful DTrace features, and then I'll be able to give you more interesting and useful examples of DTrace scripting. Thursday, January 6. 2005
More on how DTrace works Posted by Gleb Reys
in DTrace at
01:12
Comments (0) Trackbacks (0) Defined tags for this entry: dtrace
More on how DTrace works
Just went to BigAdmin: DTrace once again, and bumped into this useful link - and decided to highlight it yet again.
This link leads to a pdf-file with the technical paper of the three guys who created DTrace - Bryan M. Cantrill, Michael W. Shapiro and Adam H. Leventhal, for the last USENIX conference. The title is: Dynamic Instrumentation of Production Systems. Apart from listing all the advantages of DTrace, the paper also gives a thorough conceptual description of DTrace dynamic tracing mechanisms DTrace - I highly recommend you read it. Tuesday, December 14. 2004
DTrace options: flowindent Posted by Gleb Reys
in DTrace at
19:26
Comments (0) Trackbacks (0) Defined tags for this entry: dtrace
DTrace options: flowindent
One of the most useful (for me) options in DTrace is flowindent. All it does is indent the entry to each function with "->", and mark the return from this function with "<-". Doesn't seem like much, does it? But just look at the results!
The following example catches all the probes of the fbt provided. By default (that's our case since we're not changing any other options but flowindent), DTrace registers and prints to the standard output all the probes matched in the tracing process. Here is our script: CODE: #!/usr/sbin/dtrace -s fbt::: /execname == "dtrace"/ { } And this is the output we'll get by running this script: CODE: dtrace: script './try5.d' matched 32659 probes CPU ID FUNCTION:NAME 1 2027 xc_sync:entry 1 819 xc_do_call:entry 1 1210 mutex_vector_enter:entry 1 1238 lock_set_spl:entry 1 2353 splx:entry 1 15484 apic_setspl:entry 1 15485 apic_setspl:return 1 2354 splx:return 1 1239 lock_set_spl:return 1 1211 mutex_vector_enter:return 1 821 xc_common:entry 1 15510 apic_send_ipi:entry 1 15511 apic_send_ipi:return ... But if we only add the flowindent option to our script (you can also achieve the same result by using -F dtrace command line option), the output is going to appear much more readable and easy to follow: Our new script: CODE: #!/usr/sbin/dtrace -s #pragma D option flowindent fbt::: /execname == "dtrace"/ { } And this is the output we'll get: CODE: dtrace: script './try5.d' matched 32659 probes
CPU FUNCTION 1 -> xc_sync 1 -> xc_do_call 1 -> mutex_vector_enter 1 -> lock_set_spl 1 -> splx 1 -> apic_setspl 1 <- apic_setspl 1 <- splx 1 <- lock_set_spl 1 <- mutex_vector_enter 1 -> xc_common 1 -> apic_send_ipi 1 <- apic_send_ipi ... Friday, December 10. 2004
DTrace: predicates Posted by Gleb Reys
in DTrace at
19:52
Comments (0) Trackbacks (0) Defined tags for this entry: dtrace
DTrace: predicates
You don't have conditional statements like if..then..else in DTrace, instead of them predicates are used.
Predicates are slash (/) wrapped conditions which are put right after the lines of probe definitions, defining whether DTrace should or should not executre the code of such probes. Here's an example. The following script will print the list of all system calls, excluding write, for all the processes currently running on our system. Since DTrace tracks events on a thread-level, you can see in this example that some PIDs are the same. This is because these lines were printed by probes fired for different threads of the same process: CODE: #!/usr/sbin/dtrace -s #pragma D option quiet syscall::: /probefunc != "write"/ { printf("probefunc: %s, pid: %d, execname: %s\n", probefunc, pid, execname); } When you execute this script, you'll get something similar to this: CODE: probefunc: ioctl, pid: 28603, execname: dtrace probefunc: ioctl, pid: 28603, execname: dtrace probefunc: ioctl, pid: 28603, execname: dtrace probefunc: ioctl, pid: 28603, execname: dtrace probefunc: ioctl, pid: 28603, execname: dtrace probefunc: sysconfig, pid: 28603, execname: dtrace probefunc: sysconfig, pid: 28603, execname: dtrace probefunc: sysconfig, pid: 28603, execname: dtrace probefunc: sysconfig, pid: 28603, execname: dtrace probefunc: sigaction, pid: 28603, execname: dtrace probefunc: sigaction, pid: 28603, execname: dtrace probefunc: sigaction, pid: 28603, execname: dtrace probefunc: sigaction, pid: 28603, execname: dtrace ... As you can see, our script even took a note of all the dtrace syscalls which was used to run the script. To exclude dtrace from our data, we should alter the predicate to include one more condition: CODE: /probefunc != "write" && execname != "dtrace"/ this will result in our output including all the processes but dtrace. In this example, we can see a couple of my rxvt terminals and java: CODE: probefunc: pollsys, pid: 28411, execname: rxvt probefunc: ioctl, pid: 28411, execname: rxvt probefunc: ioctl, pid: 28411, execname: rxvt probefunc: pollsys, pid: 28411, execname: rxvt probefunc: pollsys, pid: 28406, execname: rxvt probefunc: ioctl, pid: 28406, execname: rxvt probefunc: ioctl, pid: 28406, execname: rxvt probefunc: pollsys, pid: 28406, execname: rxvt probefunc: lwp_cond_wait, pid: 27870, execname: java_vm probefunc: lwp_cond_signal, pid: 27870, execname: java_vm probefunc: lwp_cond_signal, pid: 27870, execname: java_vm probefunc: lwp_cond_wait, pid: 27870, execname: java_vm ... Predicates allow you to use any constants and variables defined earlier in the code, or standard ones, just like the ones shows in my examples. And if you keep in mind, that local variables are unique on thread-level, you can build up pretty complex constructions. Thread-specific local variables are defined with the help of self indicator and a special -> operator, for instance: self->flag = 1;. My next example will print only one message for each write syscall of every thread. As you can see in the code, every time we note a thread returning from write syscall, we mark this thread with a local variable, so that we know the thread has been processedt: self->processed = 1;. Next time a write probe fires for this thread, the predicate will take care of it and skip the probe code execution if needed: CODE: #!/usr/sbin/dtrace -s #pragma D option quiet syscall::write:return / self->processed == 0/ { printf("tid: %d, pid: %d, execname: %s\n", tid, pid, execname); self->processed = 1; } As it's clearly seen, every thread has been registered only once: CODE: tid: 1, pid: 21583, execname: soffice.bin tid: 4, pid: 21750, execname: thunderbird-bin tid: 4, pid: 27406, execname: mozilla-bin tid: 1, pid: 27406, execname: mozilla-bin tid: 1, pid: 21450, execname: icewm tid: 4, pid: 21583, execname: soffice.bin tid: 1, pid: 21750, execname: thunderbird-bin tid: 1, pid: 28636, execname: dtrace It's impossibly to even try to cover all different ways of using DTrace predicates in only one entry, so I think I'll call it a day. Next time I'll show a few more ways of making your life easier. |





