For example, the following D statements access an associative
array, whose values must all be type int
and
whose tuples must all have signature
string,int
, setting an element to 456 and
then incrementing it to 457:
a["hello", 123] = 456; a["hello", 123]++;
Now let us use an associative array in a D program. Type the
following program and save it in a file named
rwtime.d
:
syscall::read:entry, syscall::write:entry /pid == $1/ { ts[probefunc] = timestamp; } syscall::read:return, syscall::write:return /pid == $1 && ts[probefunc] != 0/ { printf("%d nsecs", timestamp - ts[probefunc]); }
As with stracerw.d, specify the ID of the shell process when you execute rwtime.d. If you type a few shell commands, you will see the time elapsed during each system call. Type in the following command and then press return a few times in your other shell:
#dtrace -s rwtime.d `/usr/bin/pgrep -n bash`
dtrace: script 'rwtime.d' matched 4 probes CPU ID FUNCTION:NAME 0 8 write:return 51962 nsecs 0 8 write:return 45257 nsecs 0 8 write:return 40787 nsecs 1 6 read:return 925959305 nsecs 1 8 write:return 46934 nsecs 1 8 write:return 41626 nsecs 1 8 write:return 176839 nsecs ...^C
#
To trace the elapsed time for each system call, you must
instrument both the entry to and return from
read()
and write()
and
measure the time at each point. Then, on return from a given
system call, you must compute the difference between our first
and second timestamp. You could use separate variables for each
system call, but this would make the program annoying to extend
to additional system calls. Instead, it is easier to use an
associative array indexed by the probe function name. The
following is the first probe clause:
syscall::read:entry, syscall::write:entry /pid == $1/ { ts[probefunc] = timestamp; }
This clause defines an array named ts
and
assigns the appropriate member the value of the DTrace variable
timestamp
. This variable returns the value of
an always-incrementing nanosecond counter. When the entry
timestamp is saved, the corresponding return probe samples
timestamp
again and reports the difference
between the current time and the saved value:
syscall::read:return, syscall::write:return /pid == $1 && ts[probefunc] != 0/ { printf("%d nsecs", timestamp - ts[probefunc]); }
The predicate on the return probe requires that DTrace is
tracing the appropriate process and that the corresponding
entry
probe has already fired and assigned
ts[probefunc]
a non-zero value. This trick
eliminates invalid output when DTrace first starts. If your
shell is already waiting in a read()
system
call for input when you execute dtrace, the
read:return
probe fires without a preceding
read:entry
for this first
read()
and ts[probefunc]
will evaluate to zero because it has not yet been assigned.