Five tools in five minutes?
What’s that supposed to mean, you will be asking! Well, one week ago at Trivadis Tech Event, I had the honor of being invited to participate in the Oracle Lightning Talks session organised by my colleague Ludovico Caldara, where every topic has to be presented in five minutes (which of course makes for quite an interesting “listening experience” for the audience …).
To sort of “maximize the mismatch”, I chose to present on Linux tracing tools – not one (normally you’d need hours to explain just one) – but five, one for every minute 😉
So here’s my personal list of appetizers, you’ll find some links at the end to really get you started:
So, strace, you will be thinking, that sounds a bit boring, doesn’t it? Well, perhaps, but it’s a good tool to start an investigation. Oracle has its “wait event lingo”, – but what’s going on underneath?
Here for example, we’re stracing the CKPT process, who says he’s doing a control file parallel write. With strace we can see the asynchronous IO request it issued (io_submit), the two file descriptors it was issued to, and how the process waits for completion in a blocking IO call (io_getevents):
$ strace -tt -f -e write=all -v -s 100 -p $(pgrep ora_ckpt)
So strace can be useful, but beware, it will slow down the process being traced – check out Brendan Gregg’s post “Strace Wow Much Syscall” (nice title isn’t it ;-)) listed in the appendix. Speaking of whom …
… Brendan Gregg has a very nice collection of scripts on github, following the unix/linux philosophy, “one tool one purpose”.
Here, for example, I’m using iolatency to get a meaningful representation of IO latencies to a voting disk on one of my VMs:
$ lsblk/dev/vdb $ ./iolatency –d 251,16
Or check out execsnoop, which shows newly created processes on the system – just watch how clusterware is constantly monitoring itself and others …
Useful little scripts, you could write them yourself!
Just have a look at what’s to be discovered in …
The /proc filesystem
Its content doesn’t always come as nicely formatted as the /proc/meminfo us DBAs are used to using ;-), but it may be possible to look in the kernel source to figure out what it means… For example, you might look in fs/proc/stat.c to figure out this:
$ cat /proc/stat
And perhaps even more helpful, we have lots of per-process information under /proc/<pid>/.
For example, process memory mappings, like this one here of the Oracle log writer:
$ cat /proc/$(pgrep ora_lgwr)/maps
Ok. Two left, time for the big shots… Enter –
Perf has many uses, but one of the most frequent probably is sampling on-cpu functions. Say I want to determine how much overhead it is setting statistics_level to all.
I‘m executing a simple two-table join, first with statistics_level set to all, and then, with statistics_level set to typical, and for both, I sample what runs on cpu using perf. The result: not much of a difference!
$ perf record -p -o all_hj.data sleep 30 $ perf record -p -o typ_hj.data sleep 30 $ perf diff typ_hj.data all_hj.data
Well. Oracle was doing a hash join. Now I do the same, forcing a nested loop join, what happens?
$ perf record -p -o all_nl.data sleep 30 $ perf record -p -o typ_nl.data sleep 30 $ perf diff typ_nl.data all_nl.data
Oracle spends 26% of the time in a vdso call, getting the current time from the operating system!
That‘s just one example of what you can do with perf, there’s numerous others – and possibly an even more amazing tool is …
Using systemtap, I can profile user-space (here: Oracle) functions.
This all builds upon the awesome investigations of two guys, Luca Canali and Frits Hoogland, whose work you will find linked in the appendix.
So say I’d like compare two versions of a Java program, one hard parsing all the time (using plain java.sql.Statement) and another that uses bind variables (by means of java.sql.PreparedStatement). What are they doing „under the hood“, and how long do these operations take?
This is one thing I could do: get a latency histogram of the Oracle function kksParseCursor. First, the case of doing a hard parse every time: Most parses take between 128 and 512 ms.
Then we have the code using bind variables – most parses take less than 8 ms here…
Again, this is just a starting point … possibilities are endless. So to get you started, have a look at the appendix, and: enjoy!
Appendix: What to Read
System Tap into Oracle for Fun and Profit
Life of an Oracle I/O: Tracing Logical and Physical I/O with SystemTap
Linux strace doesn’t lie after all.
How long does a logical IO take?
strace Wow Much Syscall