[libvirt] help debugging event timing

[Eric Blake]

In my recent work on events, I'm running into something where I'm
stumped on timing behavior.  I'm using
virEventRegisterDefaultImpl()/virEventRunDefaultImpl() as my event loop,
and trying to test that an event is firing correctly.

With the test:///default (or any other local URI), if I register an
event callback function, the callback gets invoked almost right after
the event happens.  This is the same behavior under test in our
testsuite (in objecteventtest.c). But with qemu:///system (or any other
remote URI), when I register an event callback function, my callback
does not get invoked until I make some other RPC call on the connection.
 At first, I thought the events were not being wired up at all, and that
I was just blocking forever because I missed something, but while
stepping through gdb on the client side, I noticed that calling
virConnectDomainEventDeregisterAny() in my shutdown code then indeed
proceeded to go through the entire backlog of events that had been
generated, but at that point I was no longer registered so my callback
was not called.  So I ended up using virEventAddTimeout() to set up a
periodic interrupt (at 10 seconds, slow enough to see the delays), where
in the handler I called virConnectGetLibVersion() as a way to force RPC
traffic and at least get events as a result of my timer.  If it matters,
I was initially using keepalive_interval=-1 in
/etc/libvirt/libvirtd.conf in order to avoid killing my debug sessions;
but even when I switched to keepalive_interval=3, I'm still seeing the
same delayed behavior (if the keepalive were to make a difference, I
would have expected seeing the event at 3 seconds instead of my timer at
10 seconds).

I thought that the RPC protocol was supposed to allow asynchronous
events, and with minimal downtime.  gdb in libvirtd says that
remoteDispatchObjectEventSend() is called in a timely manner, but that
merely queues things up, and I got lost trying to follow where
virNetSocketUpdateIOCallback() turned into something that wakes up the
actual write() to the socket.  On the other side, I don't see a call to
virDomainEventDispatchDefaultFunc() which then calls my callback until
the next RPC call/response, but again, I got lost on trying to trace
whether a read() of the socket was getting data in a timely manner but
just not firing anything in my event loop, or whether things were
getting stuck client side after the read but with nothing waking up my
event loop.  Any advice on how to better debug where things are getting
stuck, to determine whether the holdup is in the server not sending or
in the client not being responsive to the send?  Is it something where
systemtap might give me a better picture?  Or better yet, a patch to fix
the problem would be nice.

-- 
Eric Blake   eblake redhat com    +1-919-301-3266
Libvirt virtualization library http://libvirt.org

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 604 bytes
Desc: OpenPGP digital signature
URL: <http://listman.redhat.com/archives/libvir-list/attachments/20140101/be8fc490/attachment-0001.sig>