VMware Cloud Community
flynmooney
Enthusiast
Enthusiast
Jump to solution

Power On and vMotions stuck with "invoking prechecks"

We've recently started doing policy based storage and now are noticing sometimes with a "power on" task or when VMs are migrated either user or DRS initiated the task gets stuck for 3-5 minutes with "invoking prechecks" in the task details.

I tailed the vpxd log today during a migration and noticed that it seems the policy based storage is causing some headaches.

Has anyone run into this before and is there an easy solution?  We're using this for SRM and now have SRM working the way we want but these delayed migrations and power on's don't work for us.

2017-11-09T13:47:13.175Z info vpxd[7FAAC72E9700] [Originator@6876 sub=vpxLro opID=979D0DE7-0000094A-fe] [VpxLRO] -- BEGIN task-2823881 -- vm-20066 -- vim.VirtualMachine.migrate -- 520d1ccf-d75a-0ce4-5f30-409cd1145712(524c731f-297d-6b90-48d0-8a9ef3473746)

2017-11-09T13:47:13.247Z warning vpxd[7FAACF0E3700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-8c] NotifyChange: null collector in filter: (0x7fab3f0574d0, null)

2017-11-09T13:47:13.247Z warning vpxd[7FAACF0E3700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-8c] NotifyChange: null collector in filter: (0x7fab19d9d7c0, null)

2017-11-09T13:47:13.247Z warning vpxd[7FAACF0E3700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-8c] NotifyChange: null collector in filter: (0x7faaf9c0e4d0, null)

2017-11-09T13:47:13.247Z warning vpxd[7FAACF0E3700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-8c] NotifyChange: null collector in filter: (0x7fab4ad679e0, null)

2017-11-09T13:47:13.247Z warning vpxd[7FAACF0E3700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-8c] NotifyChange: null collector in filter: (0x7fab029e5740, null)

2017-11-09T13:47:13.247Z warning vpxd[7FAACF0E3700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-8c] NotifyChange: null collector in filter: (0x7fab0a2a8930, null)

2017-11-09T13:47:13.247Z warning vpxd[7FAACF0E3700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-8c] NotifyChange: null collector in filter: (0x7fab0d625d70, null)

2017-11-09T13:47:13.247Z warning vpxd[7FAACF0E3700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-8c] NotifyChange: null collector in filter: (0x7faaf29d8210, null)

2017-11-09T13:47:13.247Z warning vpxd[7FAACF0E3700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-8c] NotifyChange: null collector in filter: (0x7fab7216b4a0, null)

2017-11-09T13:47:13.280Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: PbmFunctionTracer: Entering PreMigrateCheckCallback

2017-11-09T13:47:13.280Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: PbmFunctionTracer: Entering QueryAssociatedProfiles

2017-11-09T13:47:13.280Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: PbmFunctionTracer: Entering QueryAssociatedProfilesCache

2017-11-09T13:47:13.280Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: ~PbmFunctionTracer: Leaving  QueryAssociatedProfilesCache

2017-11-09T13:47:13.280Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: ~PbmFunctionTracer: Leaving  QueryAssociatedProfiles

2017-11-09T13:47:13.280Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: CheckForDatastoreDefaultFlagAndUpdate: Profile filled from source profile: 4f67c7f0-b2aa-4652-b2e3-5ff9859ed9a7

2017-11-09T13:47:13.280Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: PbmFunctionTracer: Entering GetPolicyBlob

2017-11-09T13:47:13.280Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: RetrieveContentAsString: Retrieve profile content for profile 4f67c7f0-b2aa-4652-b2e3-5ff9859ed9a7, datastore-15463

2017-11-09T13:50:08.016Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] RetrieveContentAsString [RetrieveContentAsString] took 174735 ms

2017-11-09T13:50:08.016Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: ~PbmFunctionTracer: Leaving  GetPolicyBlob

2017-11-09T13:50:08.016Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] GetPolicyBlob [GetPolicyBlob] took 174735 ms

2017-11-09T13:50:08.016Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] ProcessProfiles [ProcessProfiles] took 174735 ms

2017-11-09T13:50:08.016Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] GetAndSetVmHomeProfileFromRelocate [GetAndSetVmHomeProfileFromRelocate] took 174735 ms

2017-11-09T13:50:08.016Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] FillRelocateSpecWithSourceVmHome [FillRelocateSpecWithSourceVmHome] took 174735 ms

2017-11-09T13:50:08.016Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: CheckForDatastoreDefaultFlagAndUpdate: Profile filled from source profile: 4f67c7f0-b2aa-4652-b2e3-5ff9859ed9a7

2017-11-09T13:50:08.016Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: PbmFunctionTracer: Entering GetPolicyBlob

2017-11-09T13:50:08.016Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: RetrieveContentAsString: Retrieve profile content for profile 4f67c7f0-b2aa-4652-b2e3-5ff9859ed9a7, datastore-15463

2017-11-09T13:50:54.596Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] RetrieveContentAsString [RetrieveContentAsString] took 46580 ms

2017-11-09T13:50:54.596Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: ~PbmFunctionTracer: Leaving  GetPolicyBlob

2017-11-09T13:50:54.596Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] GetPolicyBlob [GetPolicyBlob] took 46580 ms

2017-11-09T13:50:54.596Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] ProcessProfiles [ProcessProfiles] took 46580 ms

2017-11-09T13:50:54.596Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: CheckForDatastoreDefaultFlagAndUpdate: Profile filled from source profile: 4f67c7f0-b2aa-4652-b2e3-5ff9859ed9a7

2017-11-09T13:50:54.596Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: PbmFunctionTracer: Entering GetPolicyBlob

2017-11-09T13:50:54.596Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: RetrieveContentAsString: Retrieve profile content for profile 4f67c7f0-b2aa-4652-b2e3-5ff9859ed9a7, datastore-15463

2017-11-09T13:50:56.800Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: ~PbmFunctionTracer: Leaving  GetPolicyBlob

2017-11-09T13:50:56.800Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: CheckForDatastoreDefaultFlagAndUpdate: Profile filled from source profile: 4f67c7f0-b2aa-4652-b2e3-5ff9859ed9a7

2017-11-09T13:50:56.800Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: PbmFunctionTracer: Entering GetPolicyBlob

2017-11-09T13:50:56.800Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: RetrieveContentAsString: Retrieve profile content for profile 4f67c7f0-b2aa-4652-b2e3-5ff9859ed9a7, datastore-15463

2017-11-09T13:50:57.238Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: ~PbmFunctionTracer: Leaving  GetPolicyBlob

2017-11-09T13:50:57.238Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: CheckForDatastoreDefaultFlagAndUpdate: Profile filled from source profile: 4f67c7f0-b2aa-4652-b2e3-5ff9859ed9a7

2017-11-09T13:50:57.238Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: PbmFunctionTracer: Entering GetPolicyBlob

2017-11-09T13:50:57.238Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: RetrieveContentAsString: Retrieve profile content for profile 4f67c7f0-b2aa-4652-b2e3-5ff9859ed9a7, datastore-15463

2017-11-09T13:50:57.304Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: ~PbmFunctionTracer: Leaving  GetPolicyBlob

2017-11-09T13:50:57.304Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: CheckForDatastoreDefaultFlagAndUpdate: Profile filled from source profile: 4f67c7f0-b2aa-4652-b2e3-5ff9859ed9a7

2017-11-09T13:50:57.304Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: PbmFunctionTracer: Entering GetPolicyBlob

2017-11-09T13:50:57.304Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: RetrieveContentAsString: Retrieve profile content for profile 4f67c7f0-b2aa-4652-b2e3-5ff9859ed9a7, datastore-15463

2017-11-09T13:50:57.369Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: ~PbmFunctionTracer: Leaving  GetPolicyBlob

2017-11-09T13:50:57.369Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] FillRelocateSpecWithSourceVm [FillRelocateSpecWithSourceVm] took 224089 ms

2017-11-09T13:50:57.369Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: ~PbmFunctionTracer: Leaving  PreMigrateCheckCallback

2017-11-09T13:50:57.369Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PreMigrateCheckCallback [PreMigrateCheckCallback] took 224089 ms

2017-11-09T13:50:57.369Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] InvokeListenerPrecheck [PbmCallBack] took 224089 ms

2017-11-09T13:50:57.370Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [WorkflowImpl] Execute local action vpx.vmprov.SelectDestination (1%)

2017-11-09T13:50:57.371Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [WorkflowImpl] Execute local action vpx.vmprov.CheckCompatibility (1%)

2017-11-09T13:50:57.372Z info vpxd[7FAAC72E9700] [Originator@6876 sub=vpxLro opID=979D0DE7-0000094A-fe-20-26] [VpxLRO] -- BEGIN task-internal-63197966 --  -- VmTestDriver --

2017-11-09T13:50:57.374Z info vpxd[7FAAC72E9700] [Originator@6876 sub=vpxLro opID=979D0DE7-0000094A-fe-20-26] [VpxLRO] -- FINISH task-internal-63197966

2017-11-09T13:50:57.374Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [WorkflowImpl] Execute local action vpx.vmprov.ReserveDirectory (5%)

2017-11-09T13:50:57.396Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [WorkflowImpl] Execute local action vpx.vmprov.ComputeSpecs (1%)

2017-11-09T13:50:57.396Z error vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [ComputeSpecsImpl] Cannot find virtual nic for vnic type vSphereProvisioning

2017-11-09T13:50:57.403Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [WorkflowImpl] Execute local action vpx.vmprov.InvokeCallbacks (5%)

2017-11-09T13:50:57.403Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [CallbackManager] Invoke pre callback on AutoStartManager

2017-11-09T13:50:57.403Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [CallbackManager] Invoke pre callback on ContextValidator

2017-11-09T13:50:57.403Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [CallbackManager] Invoke pre callback on DAS

2017-11-09T13:50:57.403Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [CallbackManager] Invoke pre callback on DVS

2017-11-09T13:50:57.403Z info vpxd[7FAAC72E9700] [Originator@6876 sub=coreanchor opID=979D0DE7-0000094A-fe-20] [MoDVSwitch::UpdatePortProxyHostInt] updating port [9303] proxy host to [host-10067]

2017-11-09T13:50:57.413Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [CallbackManager] Invoke pre callback on EventEmitter

2017-11-09T13:50:57.413Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [CallbackManager] Invoke pre callback on InvtId

2017-11-09T13:50:57.413Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [CallbackManager] Invoke pre callback on Iofilter

2017-11-09T13:50:57.413Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [CallbackManager] Invoke pre callback on MetadataHandler

2017-11-09T13:50:57.413Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [CallbackManager] Invoke pre callback on PbmCallBack

2017-11-09T13:50:57.413Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: PbmFunctionTracer: Entering PreMigrateCallback

2017-11-09T13:50:57.413Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: PbmFunctionTracer: Entering FillSpec

2017-11-09T13:50:57.413Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: FillConfigSpec:  ConfigSpec is NULL

2017-11-09T13:50:57.413Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: ~PbmFunctionTracer: Leaving  FillSpec

2017-11-09T13:50:57.413Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: ~PbmFunctionTracer: Leaving  PreMigrateCallback

2017-11-09T13:50:57.413Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [CallbackManager] Invoke pre callback on PermissionsHandler

2017-11-09T13:50:57.413Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [CallbackManager] Invoke pre callback on VApp

2017-11-09T13:50:57.413Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [CallbackManager] Invoke pre callback on ResManager

2017-11-09T13:50:57.413Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [CallbackManager] Invoke pre callback on DRM

2017-11-09T13:50:57.413Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [CallbackManager] Invoke pre callback on ResourceReservation

2017-11-09T13:50:57.416Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [CallbackManager] Invoke pre callback on OCM

2017-11-09T13:50:57.416Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [CallbackManager] Invoke pre callback on StorageListeners

2017-11-09T13:50:57.437Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [WorkflowImpl] Execute local action vpx.vmprov.PrepareSource (1%)

2017-11-09T13:50:57.505Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [WorkflowImpl] Execute local action vpx.vmprov.PrepareDestination (1%)

2017-11-09T13:50:57.548Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [WorkflowImpl] Execute local action vpx.vmprov.InitiateDestination (1%)

2017-11-09T13:50:57.901Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [WorkflowImpl] Execute local action vpx.vmprov.InitiateSource (76%)

2017-11-09T13:51:01.928Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [WorkflowImpl] Execute local action vpx.vmprov.SwitchHostAndPool (1%)

2017-11-09T13:51:01.952Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=VmprovUtil opID=979D0DE7-0000094A-fe-20] [PatchConfig] Not persisting the serial port network backings. If you have VMs with network backings for serial ports, please set config option: vpxd.SerialPort.PersistNetworkBacking.

2017-11-09T13:51:01.959Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7fab3f0574d0, null)

2017-11-09T13:51:01.959Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7fab19d9d7c0, null)

2017-11-09T13:51:01.959Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7faaf9c0e4d0, null)

2017-11-09T13:51:01.959Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7fab4ad679e0, null)

2017-11-09T13:51:01.959Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7fab029e5740, null)

2017-11-09T13:51:01.959Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7fab0a2a8930, null)

2017-11-09T13:51:01.959Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7fab0d625d70, null)

2017-11-09T13:51:01.959Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7faaf29d8210, null)

2017-11-09T13:51:01.959Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7fab7216b4a0, null)

2017-11-09T13:51:01.991Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: PbmFunctionTracer: Entering PostMigrateCallback

2017-11-09T13:51:01.991Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: ReconfigVmAssociations: Reconfigure profile association for vm vm-20066

2017-11-09T13:51:01.991Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: PbmFunctionTracer: Entering ReconfigVmAssociations

2017-11-09T13:51:02.135Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: ~PbmFunctionTracer: Leaving  ReconfigVmAssociations

2017-11-09T13:51:02.135Z info vpxd[7FAAC72E9700] [Originator@6876 sub=pbm opID=979D0DE7-0000094A-fe-20] PBMCallback: ~PbmFunctionTracer: Leaving  PostMigrateCallback

2017-11-09T13:51:02.136Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=VmprovUtil opID=979D0DE7-0000094A-fe-20] [PatchConfig] Not persisting the serial port network backings. If you have VMs with network backings for serial ports, please set config option: vpxd.SerialPort.PersistNetworkBacking.

2017-11-09T13:51:02.142Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7fab3f0574d0, null)

2017-11-09T13:51:02.142Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7fab19d9d7c0, null)

2017-11-09T13:51:02.142Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7faaf9c0e4d0, null)

2017-11-09T13:51:02.142Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7fab4ad679e0, null)

2017-11-09T13:51:02.142Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7fab029e5740, null)

2017-11-09T13:51:02.142Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7fab0a2a8930, null)

2017-11-09T13:51:02.142Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7fab0d625d70, null)

2017-11-09T13:51:02.142Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7faaf29d8210, null)

2017-11-09T13:51:02.142Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20] NotifyChange: null collector in filter: (0x7fab7216b4a0, null)

2017-11-09T13:51:02.142Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [WorkflowImpl] Execute local action vpx.vmprov.CompleteSource (1%)

2017-11-09T13:51:02.160Z info vpxd[7FAAEEBD7700] [Originator@6876 sub=InvtHostCnx opID=979D0DE7-0000094A-fe-20-23] Not persisting vFlash resource runtime info. If you have hosts configured with vFlash resource, please set vpxd config option: vpxd.PersistVFlashRuntimeInfo to true.

2017-11-09T13:51:02.190Z info vpxd[7FAAC72E9700] [Originator@6876 sub=VmProv opID=979D0DE7-0000094A-fe-20] [WorkflowImpl] Execute local action vpx.vmprov.CompleteDestination (1%)

2017-11-09T13:51:02.225Z info vpxd[7FAAD17B0700] [Originator@6876 sub=InvtHostCnx opID=979D0DE7-0000094A-fe-20-94] Not persisting vFlash resource runtime info. If you have hosts configured with vFlash resource, please set vpxd config option: vpxd.PersistVFlashRuntimeInfo to true.

2017-11-09T13:51:02.233Z warning vpxd[7FAAD17B0700] [Originator@6876 sub=VmprovUtil opID=979D0DE7-0000094A-fe-20-94] [PatchConfig] Not persisting the serial port network backings. If you have VMs with network backings for serial ports, please set config option: vpxd.SerialPort.PersistNetworkBacking.

2017-11-09T13:51:02.266Z warning vpxd[7FAAD17B0700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20-94] NotifyChange: null collector in filter: (0x7fab3f0574d0, null)

2017-11-09T13:51:02.266Z warning vpxd[7FAAD17B0700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20-94] NotifyChange: null collector in filter: (0x7fab19d9d7c0, null)

2017-11-09T13:51:02.266Z warning vpxd[7FAAD17B0700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20-94] NotifyChange: null collector in filter: (0x7faaf9c0e4d0, null)

2017-11-09T13:51:02.266Z warning vpxd[7FAAD17B0700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20-94] NotifyChange: null collector in filter: (0x7fab4ad679e0, null)

2017-11-09T13:51:02.266Z warning vpxd[7FAAD17B0700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20-94] NotifyChange: null collector in filter: (0x7fab029e5740, null)

2017-11-09T13:51:02.266Z warning vpxd[7FAAD17B0700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20-94] NotifyChange: null collector in filter: (0x7fab0a2a8930, null)

2017-11-09T13:51:02.266Z warning vpxd[7FAAD17B0700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20-94] NotifyChange: null collector in filter: (0x7fab0d625d70, null)

2017-11-09T13:51:02.266Z warning vpxd[7FAAD17B0700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20-94] NotifyChange: null collector in filter: (0x7faaf29d8210, null)

2017-11-09T13:51:02.266Z warning vpxd[7FAAD17B0700] [Originator@6876 sub=PropertyCollector opID=979D0DE7-0000094A-fe-20-94] NotifyChange: null collector in filter: (0x7fab7216b4a0, null)

2017-11-09T13:51:02.269Z warning vpxd[7FAAC72E9700] [Originator@6876 sub=VpxProfiler opID=979D0DE7-0000094A-fe-20] VpxLro::LroMain [TotalTime] took 228989 ms

2017-11-09T13:51:02.269Z info vpxd[7FAAC72E9700] [Originator@6876 sub=vpxLro opID=979D0DE7-0000094A-fe-20] [VpxLRO] -- FINISH task-internal-63197537

2017-11-09T13:51:02.271Z warning vpxd[7FAACC893700] [Originator@6876 sub=VpxProfiler opID=979D0DE7-0000094A-fe-20-TaskLoop-103f83ac] TaskLoop [TotalTime] took 4746 ms

2017-11-09T13:51:02.273Z warning vpxd[7FAAFC50A700] [Originator@6876 sub=VpxProfiler opID=979D0DE7-0000094A-fe-20-TaskLoop-dadba5b] TaskLoop [TotalTime] took 4812 ms

2017-11-09T13:51:02.274Z info vpxd[7FAAC72E9700] [Originator@6876 sub=vpxLro opID=979D0DE7-0000094A-fe] [VpxLRO] -- FINISH task-2823881

Reply
0 Kudos
1 Solution

Accepted Solutions
flynmooney
Enthusiast
Enthusiast
Jump to solution

With a little help from VMware we were able to determine that we were well over the operation limits of storage policy based protection groups for SRM.  6.x max is 32 storage policies.  We were at 70.  Once these were removed our slowness issues were abated.

VMware Knowledge Base KB 2119336

View solution in original post

Reply
0 Kudos
2 Replies
mhampto
VMware Employee
VMware Employee
Jump to solution

Has this delay appeared once the policy's were employed? When running these power on's is it multiple VM's at a time? If so, may also be worth looking at the latency that is seen on the storage.

Reply
0 Kudos
flynmooney
Enthusiast
Enthusiast
Jump to solution

With a little help from VMware we were able to determine that we were well over the operation limits of storage policy based protection groups for SRM.  6.x max is 32 storage policies.  We were at 70.  Once these were removed our slowness issues were abated.

VMware Knowledge Base KB 2119336

Reply
0 Kudos