Today I needed to know why a certain process (81113) suddenly increases its memory. One of my guesses was that it could have something to do with a NFS mount where the relevant process sometimes needs to grab data from. I wanted to know exactly how long it takes to open a file from the NFS server. And here's how I did it.

First I launched a basic dtrace system call looking for files opened by PID 81113.

As additional information I printed out the current timestamp (in nanoseconds). This output gave me information about which file was opened at which time.

Thanks to the timestamp information it is possible to find out how long it took until the file was opened/accessed. To do that, it is necessary to combine syscall::open:entry (the request) and syscall::open:return (the return) and take both timestamps (once at the entry and then at the return):

As you can see, there are two syscall providers launched within the same dtrace command. At execution of the first provider the current timestamp is placed in a variable (self->start) and the filename with its full path is also set into a variable (self->file).
The second syscall provider is then launched and this time there's actually the output (printf) of the values. Instead of just returning the second timestamp, a subtraction of timestamps took place (current timestamp - self->start = time difference). At the end self->start is reset to 0 again.

To filter only the very slow access times, it is possible to create an "if statement" to the dtrace command. In this case I'd like to see only the lines where the access time was longer than 100000ns: