Linux-Trace-Devel Archive on lore.kernel.org
 help / Atom feed
* Re: Mapping vsock events from guest to host
       [not found] <20190210211317.04f208f1@vmware.local.home>
@ 2019-02-11 17:50 ` Steven Rostedt
  0 siblings, 0 replies; 1+ messages in thread
From: Steven Rostedt @ 2019-02-11 17:50 UTC (permalink / raw)
  To: Tzvetomir Stoyanov; +Cc: Slavomir Kaslev, Yordan Karadzhov, linux-trace-devel


I did a bit more investigation on the guest side, and also followed the
kernel code to see how vsock works. I found the function that is called
that triggers the host to take over to read the vsock packet. It's
vp_notify:

/* the notify function used when creating a virt queue */
bool vp_notify(struct virtqueue *vq)
{
	/* we write the queue's selector into the notification register to
	 * signal the other end */
	iowrite16(vq->index, (void __iomem *)vq->priv);
	return true;
}


Now I did:

 # trace-cmd record -p function -l vp_notify -e vsock -e sched_waking -e sched_switch ./vsock-agent 824

Which gives me:

    sshd-2396    0.... 245253.091020: function:             vp_notify
    sshd-2396    0d... 245253.091075: sched_switch:         sshd:2396 [120] D ==> vsock-agent:29742 [120]
vsock-ag-29742   0.... 245253.091201: print:                tracing_mark_write: received 'hello'
vsock-ag-29742   0.... 245253.091213: virtio_transport_alloc_pkt: 3:824 -> 2:207129201 len=6 type=STREAM op=RW flags=0
vsock-ag-29742   0d... 245253.091215: sched_waking:         comm=kworker/0:1 pid=29648 prio=120 target_cpu=000
vsock-ag-29742   0d... 245253.091220: sched_switch:         vsock-agent:29742 [120] S ==> kworker/0:1:29648 [120]
kworker/-29648   0.... 245253.091224: function:             vp_notify
kworker/-29648   0d... 245253.091245: sched_switch:         kworker/0:1:29648 [120] R ==> vsock-agent:29742 [120]
vsock-ag-29742   0.... 245253.091250: print:                tracing_mark_write: wrote 'hello'
vsock-ag-29742   0.... 245253.091259: virtio_transport_alloc_pkt: 3:824 -> 2:207129201 len=0 type=STREAM op=SHUTDOWN flags=0x3
vsock-ag-29742   0d... 245253.091260: sched_waking:         comm=kworker/0:1 pid=29648 prio=120 target_cpu=000
vsock-ag-29742   0d... 245253.091264: sched_switch:         vsock-agent:29742 [120] R ==> kworker/0:1:29648 [120]
kworker/-29648   0d... 245253.091267: sched_switch:         kworker/0:1:29648 [120] R ==> vsock-agent:29742 [120]
vsock-ag-29742   0d... 245253.091290: sched_switch:         vsock-agent:29742 [120] D ==> swapper/0:0 [120]

The events of interest are:

vsock-ag-29742   0.... 245253.091213: virtio_transport_alloc_pkt: 3:824 -> 2:207129201 len=6 type=STREAM op=RW flags=0
vsock-ag-29742   0d... 245253.091215: sched_waking:         comm=kworker/0:1 pid=29648 prio=120 target_cpu=000
vsock-ag-29742   0d... 245253.091220: sched_switch:         vsock-agent:29742 [120] S ==> kworker/0:1:29648 [120]
kworker/-29648   0.... 245253.091224: function:             vp_notify

The vsock-agent allocates packet (that we see in the above event), and
then wakes up the kworker to do the work for it (it's not done by an
interrupt). The the kworker runs the virtio work queue that passes the
information to the host via the vp_notify.


As we can see, on my machine, the vp_notify is 11us after the transport
packet, and because other tasks can get in the way, they can cause a
nasty jitter. What's also bothersome about this is that we can see that
vp_notify is called with preemption and interrupts enabled. This means
that it is possible that the recording of the vp_notify() function
entry and the actual call to the iowrite can be interrupted!

Now, we really should be flexible and allow other methods (like the p2p
round trip as a backup if we can't do what I'm about to suggest).
We should enable the function tracer and only trace vp_notify (via
set_ftrace_filter, which works in instances). Enable sched_switch and
sched_wakeup events, also enable interrupt events. If we see the
vp_notify followed by a sched_switch without any interrupts happening,
(or a NEED_SCHED flag set in the event of the sched_switch) we can
safely assume that nothing preempted that vp_notify.

kworker/-29648   0.... 245253.091224: function:             vp_notify
kworker/-29648   0d... 245253.091245: sched_switch:         kworker/0:1:29648 [120] R ==> vsock-agent:29742 [120]

Like the above, we don't see a 'N' flag, nor any interrupts (although I
wasn't tracing them :-)

This compared to the kvm_exit on the host that we talked about should
be a fairly good estimate of how the client and host clocks are synced.

-- Steve



^ permalink raw reply	[flat|nested] 1+ messages in thread

only message in thread, back to index

Thread overview: (only message) (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
     [not found] <20190210211317.04f208f1@vmware.local.home>
2019-02-11 17:50 ` Mapping vsock events from guest to host Steven Rostedt

Linux-Trace-Devel Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/linux-trace-devel/0 linux-trace-devel/git/0.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 linux-trace-devel linux-trace-devel/ https://lore.kernel.org/linux-trace-devel \
		linux-trace-devel@vger.kernel.org linux-trace-devel@archiver.kernel.org
	public-inbox-index linux-trace-devel


Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.linux-trace-devel


AGPL code for this site: git clone https://public-inbox.org/ public-inbox