Virtio/Block/Latency - Revision history

Stefanha at 16:02, 2 July 2010

2010-07-02T16:02:35Z

← Older revision		Revision as of 12:02, 2 July 2010
Line 557:		Line 557:
	!Time (us)		!Time (us)
	\|-		\|-
	~~\|Completion interrupt to next virtqueue notify time~~		\|Virtqueue notify to completion interrupt time [aio=native]
	~~\|38.654~~
	\|-
	\|Virtqueue notify to completion interrupt time
	\|147.611		\|147.611
	\|-		\|-
	\|~~Total~~		\|Virtqueue notify to completion interrupt time [aio=threads, old QEMU binary]
	\|~~186~~.~~265~~		\|159.628
	\|-		\|-
	\|		\|
Line 575:		Line 572:
	\|128.862		\|128.862
	\|}		\|}

			Observations:
			* virtqueue_pop 2.560 us is expensive, probably due to vring accesses. RAM API would make this faster since vring could be permanently mapped.
			* Overhead at QEMU level is still 147.611 / 128.862 = 14.5%.

Stefanha at 15:52, 2 July 2010

2010-07-02T15:52:22Z

← Older revision		Revision as of 11:52, 2 July 2010
Line 554:		Line 554:

	{\|		{\|
			!Measure
			!Time (us)
			\|-
	\|Completion interrupt to next virtqueue notify time		\|Completion interrupt to next virtqueue notify time
	\|38.654 us		\|38.654
	\|-		\|-
	\|Virtqueue notify to completion interrupt time		\|Virtqueue notify to completion interrupt time
	\|147.611 us		\|147.611
	\|-		\|-
	\|Total		\|Total
	\|186.265 us		\|186.265
	\|-		\|-
	\|		\|
Line 567:		Line 570:
	\|-		\|-
	\|seqread latency figure from guest		\|seqread latency figure from guest
	\|190.229 us		\|190.229
	\|-		\|-
	\|seqread latency figure from host		\|seqread latency figure from host
	\|128.862 us		\|128.862
	\|}		\|}

Stefanha at 15:50, 2 July 2010

2010-07-02T15:50:54Z

← Older revision		Revision as of 11:50, 2 July 2010
Line 553:		Line 553:
	\|}		\|}

	Completion interrupt to next virtqueue notify time: 38.654 us		{\|
	Virtqueue notify to completion interrupt time: 147.611 us		\|Completion interrupt to next virtqueue notify time
	Total: 186.265 us		\|38.654 us
			\|-
	seqread latency figure from guest: 190.229 us		\|Virtqueue notify to completion interrupt time
			\|147.611 us
			\|-
			\|Total
			\|186.265 us
			\|-
			\|
			\|
			\|-
			\|seqread latency figure from guest
			\|190.229 us
			\|-
			\|seqread latency figure from host
			\|128.862 us
			\|}

Stefanha at 15:46, 2 July 2010

2010-07-02T15:46:58Z

← Older revision		Revision as of 11:46, 2 July 2010
Line 552:		Line 552:
	\|iothread		\|iothread
	\|}		\|}

			Completion interrupt to next virtqueue notify time: 38.654 us
			Virtqueue notify to completion interrupt time: 147.611 us
			Total: 186.265 us

			seqread latency figure from guest: 190.229 us

Stefanha at 15:30, 2 July 2010

2010-07-02T15:30:35Z

← Older revision		Revision as of 11:30, 2 July 2010
Line 470:		Line 470:
	=== Read request lifecycle ===		=== Read request lifecycle ===

			The following data shows the code path executed in QEMU when the seqread benchmark runs inside the guest:
	{\|		{\|
	!Trace event		!Trace event

Stefanha at 15:27, 2 July 2010

2010-07-02T15:27:36Z

← Older revision		Revision as of 11:27, 2 July 2010
Line 467:		Line 467:
	* The Linux AIO eventfd() could be modified to reduce latency in the case where a single AIO request has completed. The read() = -EAGAIN could be avoided by not looping in qemu_laio_completion_cb(). The iothread select(2) call should detect that more AIO events have completed since the file descriptor is still readable next time around the main loop. This increases latency when AIO requests complete while still in qemu_laio_completion_cb().		* The Linux AIO eventfd() could be modified to reduce latency in the case where a single AIO request has completed. The read() = -EAGAIN could be avoided by not looping in qemu_laio_completion_cb(). The iothread select(2) call should detect that more AIO events have completed since the file descriptor is still readable next time around the main loop. This increases latency when AIO requests complete while still in qemu_laio_completion_cb().
	* The standard deviation of the iothread return from select(2) is high. There is no complicated code in the path, I think iothread lock contention occassionally causes high latency here. Most of the time select_post only takes 1 us, not 8 us as suggested by the mean.		* The standard deviation of the iothread return from select(2) is high. There is no complicated code in the path, I think iothread lock contention occassionally causes high latency here. Most of the time select_post only takes 1 us, not 8 us as suggested by the mean.

			=== Read request lifecycle ===

			{\|
			!Trace event
			!Time since previous event (us)
			!Thread
			\|-
			\|main_loop_wait_entry
			\|0.265
			\|iothread
			\|-
			\|main_loop_wait_pre_select
			\|0.422
			\|iothread
			\|-
			\|post_kvm_run
			\|35.678
			\|vcpu
			\|-
			\|virtio_queue_notify
			\|0.694
			\|vcpu
			\|-
			\|virtqueue_pop
			\|2.560
			\|vcpu
			\|-
			\|laio_submit
			\|1.012
			\|vcpu
			\|-
			\|laio_submit_done
			\|16.313
			\|vcpu
			\|-
			\|kvm_run_exit_io_done
			\|0.923
			\|vcpu
			\|-
			\|pre_kvm_run
			\|0.273
			\|vcpu
			\|-
			\|main_loop_wait_post_select
			\|118.307
			\|iothread
			\|-
			\|qemu_laio_completion_cb
			\|0.410
			\|iothread
			\|-
			\|qemu_laio_enqueue_completed
			\|1.624
			\|iothread
			\|-
			\|virtio_blk_rw_complete
			\|0.318
			\|iothread
			\|-
			\|virtio_notify
			\|1.282
			\|iothread
			\|-
			\|kvm_set_irq_level
			\|0.269
			\|iothread
			\|-
			\|kvm_set_irq_level_done
			\|3.626
			\|iothread
			\|-
			\|main_loop_wait_iohandlers_done
			\|1.337
			\|iothread
			\|-
			\|main_loop_wait_timers_done
			\|0.741
			\|iothread
			\|-
			\|main_loop_wait_exit
			\|0.211
			\|iothread
			\|}

Stefanha at 15:22, 2 July 2010

2010-07-02T15:22:21Z

← Older revision		Revision as of 11:22, 2 July 2010
Line 466:		Line 466:
	* The VIRTIO_PCI_QUEUE_NOTIFY pio has a latency of over 22 us! This is largely due to io_submit() taking 16 us. It would be interesting to using ioeventfd for VIRTIO_PCI_QUEUE_NOTIFY pio so that the iothread performs the io_submit() instead of the vcpu thread. This will increase latency but should reduce guest system time stealing.		* The VIRTIO_PCI_QUEUE_NOTIFY pio has a latency of over 22 us! This is largely due to io_submit() taking 16 us. It would be interesting to using ioeventfd for VIRTIO_PCI_QUEUE_NOTIFY pio so that the iothread performs the io_submit() instead of the vcpu thread. This will increase latency but should reduce guest system time stealing.
	* The Linux AIO eventfd() could be modified to reduce latency in the case where a single AIO request has completed. The read() = -EAGAIN could be avoided by not looping in qemu_laio_completion_cb(). The iothread select(2) call should detect that more AIO events have completed since the file descriptor is still readable next time around the main loop. This increases latency when AIO requests complete while still in qemu_laio_completion_cb().		* The Linux AIO eventfd() could be modified to reduce latency in the case where a single AIO request has completed. The read() = -EAGAIN could be avoided by not looping in qemu_laio_completion_cb(). The iothread select(2) call should detect that more AIO events have completed since the file descriptor is still readable next time around the main loop. This increases latency when AIO requests complete while still in qemu_laio_completion_cb().
			* The standard deviation of the iothread return from select(2) is high. There is no complicated code in the path, I think iothread lock contention occassionally causes high latency here. Most of the time select_post only takes 1 us, not 8 us as suggested by the mean.

Stefanha at 15:17, 2 July 2010

2010-07-02T15:17:43Z

← Older revision		Revision as of 11:17, 2 July 2010
Line 464:		Line 464:

	Observations on this data:		Observations on this data:
	* The VIRTIO_PCI_QUEUE_NOTIFY pio has a latency of over 22 us! This is largely due to io_submit() taking 16 us.		* The VIRTIO_PCI_QUEUE_NOTIFY pio has a latency of over 22 us! This is largely due to io_submit() taking 16 us. It would be interesting to using ioeventfd for VIRTIO_PCI_QUEUE_NOTIFY pio so that the iothread performs the io_submit() instead of the vcpu thread. This will increase latency but should reduce guest system time stealing.
			* The Linux AIO eventfd() could be modified to reduce latency in the case where a single AIO request has completed. The read() = -EAGAIN could be avoided by not looping in qemu_laio_completion_cb(). The iothread select(2) call should detect that more AIO events have completed since the file descriptor is still readable next time around the main loop. This increases latency when AIO requests complete while still in qemu_laio_completion_cb().

Stefanha at 15:10, 2 July 2010

2010-07-02T15:10:17Z

← Older revision		Revision as of 11:10, 2 July 2010
Line 462:		Line 462:

	The *_post statistics show the time spent inside QEMU userspace after a system call.		The *_post statistics show the time spent inside QEMU userspace after a system call.

			Observations on this data:
			* The VIRTIO_PCI_QUEUE_NOTIFY pio has a latency of over 22 us! This is largely due to io_submit() taking 16 us.

Stefanha at 15:02, 2 July 2010

2010-07-02T15:02:13Z

← Older revision		Revision as of 11:02, 2 July 2010
Line 353:		Line 353:
	!Total (s)		!Total (s)
	\|-		\|-
	\|select		\|select()
	\|210480		\|210480
	\|0.000271		\|0.000271
Line 369:		Line 369:
	\|1.879496		\|1.879496
	\|-		\|-
	\|read		\|read()
	\|418439		\|418439
	\|0.000001		\|0.000001
Line 385:		Line 385:
	\|0.459388		\|0.459388
	\|-		\|-
	\|io_getevents		\|io_getevents()
	\|204800		\|204800
	\|0.000001		\|0.000001
Line 401:		Line 401:
	\|0.388233		\|0.388233
	\|-		\|-
	\|ioctl		\|ioctl(KVM_IRQ_LINE)
	\|204829		\|204829
	\|0.000004		\|0.000004