Thanks for the report. From a terminal please run 'virt-manager --debug', reproduce the issue, and attach the full terminal output to this bug.

Created attachment 1554220 [details]
virt-manager --debug output

I have started virt-manager with the --debug option, then connected to the local hypervisor, then waited for it to connect.

Once it connected I've started one of our integration tests, which runs a VM on the local hypervisor. The vm, called "kstest-rootpw-basic_(8e9d5f7c-a17c-4428-b7e2-0b720d4dcbde)" did show up in virt-manager after a while but remained there after it finished it's run and was removed from the hypervisor.

Next I've started the integration test again, which added a new VM called "kstest-rootpw-basic_(e5b95fa9-b967-4f95-9723-27f58f479617)". This one did not show up in the VM list at all. 

After the second VM finished and was removed I've quit virt-manager and saved the log.

Thanks for the info. that debug output you are showing is connecting to an ssh connection: qemu+ssh://root@cobra04/system. Is that the local system? If so please try connecting to qemu:///system (not over ssh) and see if it makes any diffference. If it's not the local system, what's the ping round trip?

There's a log message right after connection: Tick is slow, not running at requested rate. This means the polling queue is backed up. Usually means the link is very high latency, but in your case it might be due to all the libvirt objects (domains and pools mostly). You have far more libvirt objects then I typically see on a single system
In fact it seems to take over a minute just to poll for all objects. In the main manager window, does it show the connection in 'connecting...' state for a long time?
There's also quite a few running VMs on that machine, is it overloaded?
Additionally there's a lot of storage pools that seem to be temporary and abandoned. All the kstest-* pools. If these are created by your test suite then you should remove them. it could be tickling something pathological in libvirt or virt-manager

So those are a few things to try. I see you filed 1698077 too, the issues are probably related

(In reply to Cole Robinson from comment #3)
> Thanks for the info. that debug output you are showing is connecting to an
> ssh connection: qemu+ssh://root@cobra04/system. Is that the local system? If
> so please try connecting to qemu:///system (not over ssh) and see if it
> makes any diffference. If it's not the local system, what's the ping round
> trip?
The qemu+ssh://root@cobra04/system is a hypervisor on a local network, quemu//system is
the local one. So I've disabled all auto-connects and only connected manually to
the local hypervisor and at least in this configuration things works as expected:
- connection is instant
- API-created test VMs show up and vanish as expected
Interestingly, the stale kstest- pools are still there in the logs as well,
even though I don't see the slow connects anymore in this config.
- even the VM CPU stats are updated correctly

So it seems like this bug is related to being connected to multiple hypervisors
at the same time. Is there perhaps some single global loop polling everything (all hypervisors and their VMs) in order ?
(I hope not. :P) Or the polling for some reason degrading to serial polling of all
the hypervisors and VMs in order. That would explain:
- the CPU stats no updating - they just update so slowly they appear unmoving and don't really show any variation (I've notiuced the stats do update in my case, just very very slowly, taking a sample like every 5 minutes when connected to multiple hypervisors)
- new VMs not showing up, dead VMs not vanishing, if there are some timeouts for the events related to this
- connecting taking ages, if it interacts with the serial polling loop

> 
> There's a log message right after connection: Tick is slow, not running at
> requested rate. This means the polling queue is backed up. Usually means the
> link is very high latency, but in your case it might be due to all the
> libvirt objects (domains and pools mostly). You have far more libvirt
> objects then I typically see on a single system
> In fact it seems to take over a minute just to poll for all objects. In the
> main manager window, does it show the connection in 'connecting...' state
> for a long time?
> There's also quite a few running VMs on that machine, is it overloaded?
> Additionally there's a lot of storage pools that seem to be temporary and
> abandoned. All the kstest-* pools. If these are created by your test suite
> then you should remove them. it could be tickling something pathological in
> libvirt or virt-manager
How do I remove or even list those ? As mentioned above, even when I connect to
just the local hypervisor and things are fast, I still see those stale pools
in the log. On the other hand if I visit the "Details" dialog of the local hypervisor
connection and visit the "Storage" tab, its just showing the contents of the local "~Downloads"
directory. The stale pools are nowhere to be found in the GUI as far as I can tell.

> 
> So those are a few things to try. I see you filed 1698077 too, the issues
> are probably related
Yep & the "stats not updating" bug (bug 1693707) most likely as well.

Looks like I've found where the stale pools are hidden - apparently the "Details" dialog has a glitch where the listing to the left appears to be empty, but actually is not. This is likely due to alignment of the labels in the list on the left, that should be left aligned but are right aligned so any short volume labels only show white space and you will only see the few long labels in the list.

Created attachment 1554487 [details]
default sizing of the Details dialog

Created attachment 1554488 [details]
resized Details dialog showing the previously hidden pool entries on the left

Yeah that UI bit is definitely funky, fixed upstream by ellipsizing the labels:

commit 274d686252196375c35f3ecc29f14d13e4af7892 (HEAD -> master, origin/master, origin/HEAD)
Author: Cole Robinson <crobinso>
Date:   Thu Apr 18 15:31:14 2019 -0400

    host: Ellipsize long net/pool object names
    
    https://bugzilla.redhat.com/show_bug.cgi?id=1698088#c5
    
    Reported-by: Martin Kolman <mkolman>

(In reply to Martin Kolman from comment #4)
> (In reply to Cole Robinson from comment #3)
> > Thanks for the info. that debug output you are showing is connecting to an
> > ssh connection: qemu+ssh://root@cobra04/system. Is that the local system? If
> > so please try connecting to qemu:///system (not over ssh) and see if it
> > makes any diffference. If it's not the local system, what's the ping round
> > trip?
> The qemu+ssh://root@cobra04/system is a hypervisor on a local network,
> quemu//system is
> the local one. So I've disabled all auto-connects and only connected
> manually to
> the local hypervisor and at least in this configuration things works as
> expected:
> - connection is instant
> - API-created test VMs show up and vanish as expected
> Interestingly, the stale kstest- pools are still there in the logs as well,
> even though I don't see the slow connects anymore in this config.
> - even the VM CPU stats are updated correctly
> 
> So it seems like this bug is related to being connected to multiple
> hypervisors
> at the same time. Is there perhaps some single global loop polling
> everything (all hypervisors and their VMs) in order ?
> (I hope not. :P) Or the polling for some reason degrading to serial polling
> of all

Yes we have a single worker thread that serializes the connection stats polling. It's on
my todo to move that to investigate moving to one thread per connection. More than that
probably isn't going to help much due to libvirt's locking model. Truthfully I don't spend
much effort trying to optimtize the case of multiple open connections

It seems like something really pathological is happening in your case but the logs don't
give enough info. I don't really understand why it takes minutes to open that single
connection, is it network round trip is horrible, or libvirt takes seconds to respond to
an API? If you do 'virsh --connect qemu+ssh://root@cobra04/system' from a remote machine,
are commands like 'list --all' noticably slow? Or 'dumpxml $vmname' ?

The logs also show you have python-libguestfs installed which is doing a bunch of its
own libvirt API calls for each VM. You can turn that off in Edit->Preferences. You can
also tweak polling parameters there too. If you intend to have multiple connections
open regularly maybe you

But basically if there's a remote connection and round trip time is slow as dirt there
isn't much virt-manager can do, the experience is always going to suck.

(In reply to Cole Robinson from comment #9)
> Yes we have a single worker thread that serializes the connection stats
> polling. It's on
> my todo to move that to investigate moving to one thread per connection.
> More than that
> probably isn't going to help much due to libvirt's locking model. Truthfully
> I don't spend
> much effort trying to optimize the case of multiple open connections

Actually it will significantly help. There is no global locking client side in libvirt, and obviously server side would be a different daemon for each connection. So one thread per connection will give full concurrency between connections.

You can actually get even better than that and use one thread per object type. ie one for virDomain, one for virNetwork, one for virStoragePool if you want to, as the drivers won't contend with each other. 

Having said that, we shouldn't need to be polling just to list objects anymore - only need to do a bulk list once, and then everything can be event driven. So only need polling to refresh usage / performance stats

(In reply to Cole Robinson from comment #8)
> Yeah that UI bit is definitely funky, fixed upstream by ellipsizing the
> labels:
> 
> commit 274d686252196375c35f3ecc29f14d13e4af7892 (HEAD -> master,
> origin/master, origin/HEAD)
> Author: Cole Robinson <crobinso>
> Date:   Thu Apr 18 15:31:14 2019 -0400
> 
>     host: Ellipsize long net/pool object names
>     
>     https://bugzilla.redhat.com/show_bug.cgi?id=1698088#c5
>     
>     Reported-by: Martin Kolman <mkolman>

Nice, thanks! :)(In reply to Cole Robinson from comment #9)

> (In reply to Martin Kolman from comment #4)
> > (In reply to Cole Robinson from comment #3)
> > > Thanks for the info. that debug output you are showing is connecting to an
> > > ssh connection: qemu+ssh://root@cobra04/system. Is that the local system? If
> > > so please try connecting to qemu:///system (not over ssh) and see if it
> > > makes any diffference. If it's not the local system, what's the ping round
> > > trip?
> > The qemu+ssh://root@cobra04/system is a hypervisor on a local network,
> > quemu//system is
> > the local one. So I've disabled all auto-connects and only connected
> > manually to
> > the local hypervisor and at least in this configuration things works as
> > expected:
> > - connection is instant
> > - API-created test VMs show up and vanish as expected
> > Interestingly, the stale kstest- pools are still there in the logs as well,
> > even though I don't see the slow connects anymore in this config.
> > - even the VM CPU stats are updated correctly
> > 
> > So it seems like this bug is related to being connected to multiple
> > hypervisors
> > at the same time. Is there perhaps some single global loop polling
> > everything (all hypervisors and their VMs) in order ?
> > (I hope not. :P) Or the polling for some reason degrading to serial polling
> > of all
> 
> Yes we have a single worker thread that serializes the connection stats
> polling. It's on
> my todo to move that to investigate moving to one thread per connection.
> More than that
> probably isn't going to help much due to libvirt's locking model. Truthfully
> I don't spend
> much effort trying to optimtize the case of multiple open connections
I don't really know about any other usable remote libvirt client other than virt-manager
(haven't really seen every using something else for this) so I would guess the number
of people using at least one remote connection would not be that small.

My case is also something I wold not really call pathological, there is:
- connection to the localhost libvirt
- 2-3 connections to shared hypervisor machines on LAN with statically allocated VMs (~10 per hypervisor)
- 2-3 connections to hypervisors running on an openstack instance with dynamically allocated test machines
Though the opesntack hypervisors might indeed be a bit outliers.

> 
> It seems like something really pathological is happening in your case but
> the logs don't
> give enough info. I don't really understand why it takes minutes to open
> that single
> connection, is it network round trip is horrible, or libvirt takes seconds
> to respond to
> an API?
Looks like the long connection time & stats updates might have been due to all the stale pools
not visible due to the UI glitch. When I manually deleted all of them one-by-one it's much better,
connections don't take nearly so long anymore and the stats update reasonably quickly.

I will continue monitoring the situation but this might really have been the root cause,
if the single thread enumerated all the stale pool junk on every poll for example.


> If you do 'virsh --connect qemu+ssh://root@cobra04/system' from a
> remote machine,
> are commands like 'list --all' noticably slow? Or 'dumpxml $vmname' ?
> 
> The logs also show you have python-libguestfs installed which is doing a
> bunch of its
> own libvirt API calls for each VM.
That is expected during the test run - we use libguestfs to retrieve test results from the dynamically created VM and that's likely also visible in the logs.

> You can turn that off in
> Edit->Preferences. You can
> also tweak polling parameters there too. If you intend to have multiple
> connections
> open regularly maybe you
> 
> But basically if there's a remote connection and round trip time is slow as
> dirt there
> isn't much virt-manager can do, the experience is always going to suck.
After clearing the stale pools there is still the issue of the hypervisor VM listing not being updated (eq. this bug). Even when the connection phase no longer takes so long & the graphs get updated, the VM list still does not get updated correctly. I will try to gather more data about this, but there are definitely still ghost VMs for the list sometimes for VMs that finished their run and were shutdown and removed by the test automation. These vanish when I reconnect to the hypervisor, with the listing being correct again right after the new connection is established.

This hints me on a local client issue.

(In reply to Daniel Berrange from comment #10)
> (In reply to Cole Robinson from comment #9)
> > Yes we have a single worker thread that serializes the connection stats
> > polling. It's on
> > my todo to move that to investigate moving to one thread per connection.
> > More than that
> > probably isn't going to help much due to libvirt's locking model. Truthfully
> > I don't spend
> > much effort trying to optimize the case of multiple open connections
> 
> Actually it will significantly help. There is no global locking client side
> in libvirt, and obviously server side would be a different daemon for each
> connection. So one thread per connection will give full concurrency between
> connections.
Sounds good! Because, if I understand things correctly, with the current single thread design
one hypervisor that is overloaded or has bad network can slow down or break updates for all
other active connections, right ? 

> 
> You can actually get even better than that and use one thread per object
> type. ie one for virDomain, one for virNetwork, one for virStoragePool if
> you want to, as the drivers won't contend with each other. 
> 
> Having said that, we shouldn't need to be polling just to list objects
> anymore - only need to do a bulk list once, and then everything can be event
> driven. So only need polling to refresh usage / performance stats
This sounds to me that this would fix the case of many (stale) pools lagging the updates
if the list is pulled only once and then only individual events are processed.

On the other hand I wonder how the hypervisor VM list can currently get out of date if the full list gets polled
every time. That would be something I would expect with an event driven connection, which is apparently not
the case yet.

(In reply to Daniel Berrange from comment #10)
> (In reply to Cole Robinson from comment #9)
> > Yes we have a single worker thread that serializes the connection stats
> > polling. It's on
> > my todo to move that to investigate moving to one thread per connection.
> > More than that
> > probably isn't going to help much due to libvirt's locking model. Truthfully
> > I don't spend
> > much effort trying to optimize the case of multiple open connections
> 
> Actually it will significantly help. There is no global locking client side
> in libvirt, and obviously server side would be a different daemon for each
> connection. So one thread per connection will give full concurrency between
> connections.
> 

I said 'more than that' as in something like a threadpool or a thread per
object, will start hitting libvirt driver locks.

> You can actually get even better than that and use one thread per object
> type. ie one for virDomain, one for virNetwork, one for virStoragePool if
> you want to, as the drivers won't contend with each other. 
> 

Right but IMO this starts getting into the 'is it even worth the dev effort'
territory. I'll consider it though when I added the thread per connection.

> Having said that, we shouldn't need to be polling just to list objects
> anymore - only need to do a bulk list once, and then everything can be event
> driven. So only need polling to refresh usage / performance stats

Right, that's what we do provided dest libvirt is new enough. Reporters initial
connection is taking an incredibly long time though which backs up everything
else. On conn startup we do a List but we also cache XML for every
object, and do some other cache priming like checking managed save state,
so total API calls before the connection open is complete scales with the
number of total objects.

(In reply to Cole Robinson from comment #13)
> (In reply to Daniel Berrange from comment #10)
> > (In reply to Cole Robinson from comment #9)
> > > Yes we have a single worker thread that serializes the connection stats
> > > polling. It's on
> > > my todo to move that to investigate moving to one thread per connection.
> > > More than that
> > > probably isn't going to help much due to libvirt's locking model. Truthfully
> > > I don't spend
> > > much effort trying to optimize the case of multiple open connections
> > 
> > Actually it will significantly help. There is no global locking client side
> > in libvirt, and obviously server side would be a different daemon for each
> > connection. So one thread per connection will give full concurrency between
> > connections.
> > 
> 
> I said 'more than that' as in something like a threadpool or a thread per
> object, will start hitting libvirt driver locks.

If it is only read operations few locks will get in the way. For example you can query XML for every guest in parallel without hitting lock blocking.

> > You can actually get even better than that and use one thread per object
> > type. ie one for virDomain, one for virNetwork, one for virStoragePool if
> > you want to, as the drivers won't contend with each other. 
> > 
> 
> Right but IMO this starts getting into the 'is it even worth the dev effort'
> territory. I'll consider it though when I added the thread per connection.

NB the secondary drivers will each eventually be moving into their own respective daemon processes, so conceptually it makes sense to treat the object types as concurrently usable

> 
> > Having said that, we shouldn't need to be polling just to list objects
> > anymore - only need to do a bulk list once, and then everything can be event
> > driven. So only need polling to refresh usage / performance stats
> 
> Right, that's what we do provided dest libvirt is new enough. Reporters
> initial
> connection is taking an incredibly long time though which backs up everything
> else. On conn startup we do a List but we also cache XML for every
> object, and do some other cache priming like checking managed save state,
> so total API calls before the connection open is complete scales with the
> number of total objects.

Most of the APIs should be fairly lockless, as the data each fetches is specific to each guest. Even the bulk stats APIs which fetch data for many guests should not be limited by locks, as they'll only need read locks, not write locks.

Of course more threads only helps up to the point you hit the thread worker limit in libvirtd. After that you're just using RAM for thread stacks, with no benefit. So I wouldn't do one thread per guest - no more than 20 threads per connection. Probably even just 3/4/5 is enough to make a big difference to initial startup, especially if proactive caching calls were backgrounded in virt-manager too.

(In reply to Martin Kolman from comment #12)
> (In reply to Daniel Berrange from comment #10)
> > (In reply to Cole Robinson from comment #9)
> > > Yes we have a single worker thread that serializes the connection stats
> > > polling. It's on
> > > my todo to move that to investigate moving to one thread per connection.
> > > More than that
> > > probably isn't going to help much due to libvirt's locking model. Truthfully
> > > I don't spend
> > > much effort trying to optimize the case of multiple open connections
> > 
> > Actually it will significantly help. There is no global locking client side
> > in libvirt, and obviously server side would be a different daemon for each
> > connection. So one thread per connection will give full concurrency between
> > connections.
> Sounds good! Because, if I understand things correctly, with the current
> single thread design
> one hypervisor that is overloaded or has bad network can slow down or break
> updates for all
> other active connections, right ? 
> 

Yes. Typically the only polling virt-manager does for latest libvirt is a
single getAllStats API call on every connection every 3 seconds. These
calls are invoked from a single queue, so they are serialized. However
when there's async stuff happening like VMs being created/removed/edited,
libguestfs doing it's thing etc, that will trigger a lot of libvirt API
calls, and these are all invoked from the same queue. So if one connection
has a lot of activity and API calls are noticeably slow to begin with,
the queue can get dominated by those backed up requests.

I added this bug to track adding one thread per connection, and possibly
more work: https://bugzilla.redhat.com/show_bug.cgi?id=1702397

> > 
> > You can actually get even better than that and use one thread per object
> > type. ie one for virDomain, one for virNetwork, one for virStoragePool if
> > you want to, as the drivers won't contend with each other. 
> > 
> > Having said that, we shouldn't need to be polling just to list objects
> > anymore - only need to do a bulk list once, and then everything can be event
> > driven. So only need polling to refresh usage / performance stats
> This sounds to me that this would fix the case of many (stale) pools lagging
> the updates
> if the list is pulled only once and then only individual events are
> processed.
> 
> On the other hand I wonder how the hypervisor VM list can currently get out
> of date if the full list gets polled
> every time. That would be something I would expect with an event driven
> connection, which is apparently not
> the case yet.

Yes this bit is interesting. If you could reproduce again with the current
state and post debug output, it will be interesting. The main thing is to
see if virt-manager is logging anything about events from the missing
domains. If the logs don't contain relevant 'domain lifecycle event' messages
then there's probably a bug outside of virt-manager's connection handling.

It would be interesting to try also doing

  virsh --connect qemu+ssh://... event --all --loop

From the client host when reproducing with virt-manager, and see if it notices
events from the VMs or state changes that virt-manager misses.

*** Bug 1698077 has been marked as a duplicate of this bug. ***

(In reply to Cole Robinson from comment #15)
> Yes this bit is interesting. If you could reproduce again with the current
> state and post debug output, it will be interesting. The main thing is to
> see if virt-manager is logging anything about events from the missing
> domains. If the logs don't contain relevant 'domain lifecycle event' messages
> then there's probably a bug outside of virt-manager's connection handling.
> 
> It would be interesting to try also doing
> 
>   virsh --connect qemu+ssh://... event --all --loop
> 
> From the client host when reproducing with virt-manager, and see if it
> notices
> events from the VMs or state changes that virt-manager misses.
Working on it - seems to happen much less often once I cleaned up the stale pools, will attach a log next time I manage to reproduce it.

BTW, looks like the stale pools happen when I manually select "delete" on a running temporary VM, the results in a stale domain on the server. Have not investigated it further yet, if it also happens for manually created VMs or just ones created and managed by our test automation.

Looks like the test suite is using a new temporary directory and pointing the vm install to some disk image or similar in that tempdir. virt-install will then create a storage pool around that tempdir so we can use libvirt to get some info about the contained files, like raw vs qcow2 format. Those pools exist forever though unless explicitly deleted, and they are really only required for the initial VM setup. You can change the test suite to do a pool-destroy + pool-undefine after the VM is running and it won't affect anything, it's just deleting a libvirt XML file and nothing in the directory will be touched.

Let's close this until you hit another reproducer and we can go from there