Massive CPU consumption on RefreshWorker ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector

[sqrt529]

Hi!
In our Quinteros environment we have several Providers. One of them is VMWare with aproxx. 7000 VMs. This is the one, which burns the CPUs. The EVM Log shows someting like an never ending loop... I tried to increase the workers memory, advanced config to lesser connections, Ruby code in collector.rb to pause for a second if result is empty(and rolled back to original)... I can't figure out how i can bring this to an optimal level, so i decided to ask you for help. Im not sure if this started with the VCenter Version 8 migration, but maybe. The following is a little part from evm log.

TIA, Joe

Jan 14 09:06:49 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 9 updates...
Jan 14 09:06:49 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 9 updates...Complete
Jan 14 09:06:49 miq1 evm[2967530]:  INFO -- evm: EMS: [vCenter 1], id: [13] Saving EMS Inventory...
Jan 14 09:06:49 miq1 evm[2967530]:  INFO -- evm: EMS: [vCenter 1], id: [13] Saving EMS Inventory...Complete
Jan 14 09:06:49 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Saver#post_refresh) EMS: [vCenter 1], id: [13] Performing post-refresh operations for VmOrTemplate instances...
Jan 14 09:06:50 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Saver#post_refresh) EMS: [vCenter 1], id: [13] Performing post-refresh operations for VmOrTemplate instances...Complete
Jan 14 09:06:51 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 74 updates...
Jan 14 09:06:51 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 74 updates...Complete
Jan 14 09:06:51 miq1 evm[2967530]:  INFO -- evm: EMS: [vCenter 1], id: [13] Saving EMS Inventory...
Jan 14 09:06:53 miq1 evm[2967530]:  INFO -- evm: EMS: [vCenter 1], id: [13] Saving EMS Inventory...Complete
Jan 14 09:06:53 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Saver#post_refresh) EMS: [vCenter 1], id: [13] Performing post-refresh operations for VmOrTemplate instances...
Jan 14 09:06:54 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Saver#post_refresh) EMS: [vCenter 1], id: [13] Performing post-refresh operations for VmOrTemplate instances...Complete
Jan 14 09:06:54 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...
Jan 14 09:06:54 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...Complete
Jan 14 09:06:54 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...
Jan 14 09:06:54 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...Complete
Jan 14 09:06:54 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 86 updates...
Jan 14 09:06:54 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 86 updates...Complete
Jan 14 09:06:55 miq1 evm[2967530]:  INFO -- evm: EMS: [vCenter 1], id: [13] Saving EMS Inventory...
Jan 14 09:07:05 miq1 evm[2967530]:  INFO -- evm: EMS: [vCenter 1], id: [13] Saving EMS Inventory...Complete
Jan 14 09:07:05 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Saver#post_refresh) EMS: [vCenter 1], id: [13] Performing post-refresh operations for VmOrTemplate instances...
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Saver#post_refresh) EMS: [vCenter 1], id: [13] Performing post-refresh operations for VmOrTemplate instances...Complete
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...Complete
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...Complete
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...Complete
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...Complete
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...Complete
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...Complete
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...Complete
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...Complete
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...Complete
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...Complete
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 100 updates...Complete
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 56 updates...
Jan 14 09:07:06 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#process_update_set) EMS: [vCenter 1], id: [13] Processing 56 updates...Complete
Jan 14 09:07:08 miq1 evm[2967530]:  INFO -- evm: EMS: [vCenter 1], id: [13] Saving EMS Inventory...
Jan 14 09:07:33 miq1 evm[2967530]:  INFO -- evm: EMS: [vCenter 1], id: [13] Saving EMS Inventory...Complete
Jan 14 09:07:33 miq1 evm[2967530]:  INFO -- evm: MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Saver#post_refresh) EMS: [vCenter 1], id: [13] Performing post-refresh operations for VmOrTemplate instances...

[Fryguy]

@agrare Can you take a look here. The log focuses on the post-refresh operations, which do feel excessive in this case.

[sqrt529]

it would be great to here from you @agrare. What i can say at this point is, i wrote a python script to check how much data the vcenter api sends. I used pyvmomi. And it's not that much for such an environment, so i suggest the high load are follwing processes after the data consumption. There are 2 Workers for VMWare Refresh. I would appreciate a list of potential tuning parameters that we can modify or other useful hints.

[agrare]

Hey @sqrt529 couple of questions:

1. You say quinteros, which tag specifically?
2. There are 2 workers for vmware refresh, there is only ever supposed to be 1 per EMS. Do you have 2 vcenters and thus 2 workers? If you only have 1 vmware provider added there should not be 2 workers this might be related to the issues.
3. What version of vSphere are you using? quinteros only supported 8.0U1 and U2 if I remember correctly

It does look like it re-starts the initial collection. 100 updates is the vsphere maxinum number of updates per page. So Processing 86 updates...Complete would be the end of the initial collection and it should only be small one-off updates after that not go back to 100 Updates.

[sqrt529]

Hey @agrare,

1. MiQ Version: quinteros-2.1.20241007143404_eee4149
2. we've two VCenters, but only one refresh worker process per VCentre [1]
3. We are running vSphere / vCenter Server 8.0 Update 3 (8.0.3), build 24674346.

[1]:

01:53:42 MIQ: Vmware::InfraManager::RefreshWorker id: 26623, queue: ems_11
11:34:28 MIQ: Vmware::InfraManager::RefreshWorker id: 26637, queue: ems_13

[agrare]

Okay thanks @sqrt529 8.0.3 isn't technically supported on that version, but without also seeing errors about missing classes/types from the vmodl that likely isn't the issue.

I'm testing with our 8.0.3.00600 vcenter and I see it sitting at 0% cpu usage when no updates are coming in, with a couple of updates it'll hit 8% while saving and then drop back to 0.

I'm working on a script to dump the XML request/responses to the vCenter to help debug, I'm curious why it looks like it "restarts" the full collection.

[agrare]

Hey @sqrt529 the same script that I've created for https://github.com/orgs/ManageIQ/discussions/23661#discussioncomment-15563544 should also work here.

You two are seeing different behavior, but interestingly both related to PropertyCollector truncated behavior. He is seeing a premature complete update set (full updates continue to come in after) and you're seeing a repeat of the initial update set.