trace: Trace posix-aio-compat syscall blocking time
commitdeaa69d19c14b0ce902c9f5f10455f9cbefeff5b
authorStefan Hajnoczi <stefanha@linux.vnet.ibm.com>
Thu, 27 May 2010 07:24:35 +0000 (27 08:24 +0100)
committerStefan Hajnoczi <stefanha@linux.vnet.ibm.com>
Thu, 3 Jun 2010 12:02:01 +0000 (3 13:02 +0100)
treea846d7f2429b5f3b6febdcaa8c16645e4d8fbb50
parent146aefa56aa7e84953a21eac80cb0ec9961025c8
trace: Trace posix-aio-compat syscall blocking time

This patch traces posix-aio-compat syscall blocking time for each
request.  This can be used to understand how much time is spent in the
host kernel servicing I/O requests.

./configure --trace-backend=simple [...]
make
x86_64-softmmu/qemu-system-x86_64 [...]

The file /tmp/trace.log will contain binary trace data, which can be
formatted using simpletrace.py like this:

posix_aio_process_queue 1159.647 acb=0x2b933c0 opaque=0x2d8b630 type=0x2
ret=0x0 blocking_duration=0x22a1005

The "blocking_duration" is the duration in nanoseconds spent performing
the I/O operation in the AIO helper thread.  Note that "type" can be
used to distinguish read (1), write (2), ioctl (4), and flush (8)
requests.

The following generates a histogram of posix-aio-compat syscall blocking
times at millisecond granularity:

./simpletrace.py trace-events /tmp/trace.log | \
awk '
{
split($6,fields,"=");
print int(sprintf("%d\n", fields[2]) / 1000000)
}' | \
sort | uniq -c | sort -nk 2

Note that the blocking time also includes work done to prepare for the
syscall.  Under normal operation this additional time should be small.

Signed-off-by: Stefan Hajnoczi <stefanha@linux.vnet.ibm.com>
posix-aio-compat.c
trace-events