From deaa69d19c14b0ce902c9f5f10455f9cbefeff5b Mon Sep 17 00:00:00 2001 From: Stefan Hajnoczi Date: Thu, 27 May 2010 08:24:35 +0100 Subject: [PATCH] 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 --- posix-aio-compat.c | 10 +++++ trace-events | 123 +++++++++++++++++++++++++++-------------------------- 2 files changed, 72 insertions(+), 61 deletions(-) rewrite trace-events (63%) diff --git a/posix-aio-compat.c b/posix-aio-compat.c index 2b426aa220..2fa8fcce1a 100644 --- a/posix-aio-compat.c +++ b/posix-aio-compat.c @@ -48,6 +48,7 @@ struct qemu_paiocb { QTAILQ_ENTRY(qemu_paiocb) node; int aio_type; ssize_t ret; + uint64_t blocking_duration; int active; struct qemu_paiocb *next; @@ -313,6 +314,7 @@ static void *aio_thread(void *unused) ssize_t ret = 0; qemu_timeval tv; struct timespec ts; + uint64_t start_timestamp, duration; qemu_gettimeofday(&tv); ts.tv_sec = tv.tv_sec + 10; @@ -334,6 +336,9 @@ static void *aio_thread(void *unused) idle_threads--; mutex_unlock(&lock); + clock_gettime(CLOCK_MONOTONIC, &ts); + start_timestamp = ts.tv_sec * 1000000000LL + ts.tv_nsec; + switch (aiocb->aio_type & QEMU_AIO_TYPE_MASK) { case QEMU_AIO_READ: case QEMU_AIO_WRITE: @@ -351,8 +356,12 @@ static void *aio_thread(void *unused) break; } + clock_gettime(CLOCK_MONOTONIC, &ts); + duration = ts.tv_sec * 1000000000LL + ts.tv_nsec - start_timestamp; + mutex_lock(&lock); aiocb->ret = ret; + aiocb->blocking_duration = duration; idle_threads++; mutex_unlock(&lock); @@ -457,6 +466,7 @@ static int posix_aio_process_queue(void *opaque) } /* remove the request */ *pacb = acb->next; + trace_posix_aio_process_queue(acb, acb->common.opaque, acb->aio_type, ret, acb->blocking_duration); /* call the callback */ acb->common.cb(acb->common.opaque, ret); qemu_aio_release(acb); diff --git a/trace-events b/trace-events dissimilarity index 63% index 6992cd5d5a..6b489ad434 100644 --- a/trace-events +++ b/trace-events @@ -1,61 +1,62 @@ -# Trace events for debugging and performance instrumentation -# -# This file is processed by the tracetool script during the build. -# -# To add a new trace event: -# -# 1. Choose a name for the trace event. Declare its arguments and format -# string. -# -# 2. Call the trace event from code using trace_##name, e.g. multiwrite_cb() -> -# trace_multiwrite_cb(). The source file must #include "trace.h". -# -# Format of a trace event: -# -# [disable] ( [, ] ...) "" -# -# Example: qemu_malloc(size_t size) "size %zu" -# -# The "disable" keyword will build without the trace event. -# -# The must be a valid as a C function name. -# -# Types should be standard C types. Use void * for pointers because the trace -# system may not have the necessary headers included. -# -# The should be a sprintf()-compatible format string. - -# qemu-malloc.c -qemu_malloc(size_t size, void *ptr) "size %zu ptr %p" -qemu_realloc(void *ptr, size_t size, void *newptr) "ptr %p size %zu newptr %p" -qemu_free(void *ptr) "ptr %p" - -# osdep.c -qemu_memalign(size_t alignment, size_t size, void *ptr) "alignment %zu size %zu ptr %p" -qemu_valloc(size_t size, void *ptr) "size %zu ptr %p" -qemu_vfree(void *ptr) "ptr %p" - -# hw/virtio.c -virtio_reset(void *vdev) "vdev %p" -virtio_queue_set_addr(void *vdev, int n, target_phys_addr_t addr) "vdev %p n %d addr 0x%lx" -virtio_add_queue(void *vdev, void *vq, int n, int queue_size) "vdev %p vq %p n %d queue_size %d" -virtio_common_init(void *vdev, int device_id) "vdev %p device_id %d" -virtqueue_fill(void *vq, const void *elem, unsigned int len, unsigned int idx) "vq %p elem %p len %u idx %u" -virtqueue_flush(void *vq, unsigned int count) "vq %p count %u" -virtqueue_pop(void *vq, void *elem, unsigned int in_num, unsigned int out_num) "vq %p elem %p in_num %u out_num %u" -virtio_queue_notify(void *vdev, int n, void *vq) "vdev %p n %d vq %p" -virtio_notify(void *vdev, void *vq) "vdev %p vq %p" - -# block.c -multiwrite_cb(void *mcb, int ret) "mcb %p ret %d" -bdrv_aio_multiwrite(void *mcb, int num_callbacks, int num_reqs) "mcb %p num_callbacks %d num_reqs %d" -bdrv_aio_multiwrite_earlyfail(void *mcb) "mcb %p" -bdrv_aio_multiwrite_latefail(void *mcb, int i) "mcb %p i %d" - -# hw/virtio-blk.c -virtio_blk_req_complete(void *req, int status) "req %p status %d" -virtio_blk_rw_complete(void *req, int ret) "req %p ret %d" -virtio_blk_handle_write(void *req, unsigned long sector, unsigned long nsectors) "req %p sector %lu nsectors %lu" - -# posix-aio-compat.c -paio_submit(void *acb, void *opaque, unsigned long sector_num, unsigned long nb_sectors, unsigned long type) "acb %p opaque %p sector_num %lu nb_sectors %lu type %lu" +# Trace events for debugging and performance instrumentation +# +# This file is processed by the tracetool script during the build. +# +# To add a new trace event: +# +# 1. Choose a name for the trace event. Declare its arguments and format +# string. +# +# 2. Call the trace event from code using trace_##name, e.g. multiwrite_cb() -> +# trace_multiwrite_cb(). The source file must #include "trace.h". +# +# Format of a trace event: +# +# [disable] ( [, ] ...) "" +# +# Example: qemu_malloc(size_t size) "size %zu" +# +# The "disable" keyword will build without the trace event. +# +# The must be a valid as a C function name. +# +# Types should be standard C types. Use void * for pointers because the trace +# system may not have the necessary headers included. +# +# The should be a sprintf()-compatible format string. + +# qemu-malloc.c +disable qemu_malloc(size_t size, void *ptr) "size %zu ptr %p" +disable qemu_realloc(void *ptr, size_t size, void *newptr) "ptr %p size %zu newptr %p" +disable qemu_free(void *ptr) "ptr %p" + +# osdep.c +disable qemu_memalign(size_t alignment, size_t size, void *ptr) "alignment %zu size %zu ptr %p" +disable qemu_valloc(size_t size, void *ptr) "size %zu ptr %p" +disable qemu_vfree(void *ptr) "ptr %p" + +# hw/virtio.c +disable virtio_reset(void *vdev) "vdev %p" +disable virtio_queue_set_addr(void *vdev, int n, target_phys_addr_t addr) "vdev %p n %d addr 0x%lx" +disable virtio_add_queue(void *vdev, void *vq, int n, int queue_size) "vdev %p vq %p n %d queue_size %d" +disable virtio_common_init(void *vdev, int device_id) "vdev %p device_id %d" +disable virtqueue_fill(void *vq, const void *elem, unsigned int len, unsigned int idx) "vq %p elem %p len %u idx %u" +disable virtqueue_flush(void *vq, unsigned int count) "vq %p count %u" +disable virtqueue_pop(void *vq, void *elem, unsigned int in_num, unsigned int out_num) "vq %p elem %p in_num %u out_num %u" +disable virtio_queue_notify(void *vdev, int n, void *vq) "vdev %p n %d vq %p" +disable virtio_notify(void *vdev, void *vq) "vdev %p vq %p" + +# block.c +disable multiwrite_cb(void *mcb, int ret) "mcb %p ret %d" +disable bdrv_aio_multiwrite(void *mcb, int num_callbacks, int num_reqs) "mcb %p num_callbacks %d num_reqs %d" +disable bdrv_aio_multiwrite_earlyfail(void *mcb) "mcb %p" +disable bdrv_aio_multiwrite_latefail(void *mcb, int i) "mcb %p i %d" + +# hw/virtio-blk.c +disable virtio_blk_req_complete(void *req, int status) "req %p status %d" +disable virtio_blk_rw_complete(void *req, int ret) "req %p ret %d" +disable virtio_blk_handle_write(void *req, unsigned long sector, unsigned long nsectors) "req %p sector %lu nsectors %lu" + +# posix-aio-compat.c +disable paio_submit(void *acb, void *opaque, unsigned long sector_num, unsigned long nb_sectors, unsigned long type) "acb %p opaque %p sector_num %lu nb_sectors %lu type %lu" +posix_aio_process_queue(void *acb, void *opaque, int type, int ret, uint64_t blocking_duration) "acb %p opaque %p type %d ret %d blocking_duration %lx" -- 2.11.4.GIT