Bug 1628031

Hi Gellert,

While looking at the logs, we noticed the dequeue times are very high. We suspect that's at least partially responsible for the Service provision failure shown in the log snippets below.

In the log snippet below, the request was put on the queue and waited 4029 seconds to be delivered/processed.

Also, we noticed that the CatalogItemInitialization method is being called twice in Service/Provisioning/StateMachines which will add to the provisioning processing time.

Could you ask the customer:

1 Are they having performance issues in other areas besides Service provisioning?
2 How many Services or other types of provisioning are they doing at a time?
3 Have they reviewed the appliance configuration to see if it needs adjustments?
   (We're seeing workers getting killed as well.)
4 How often does Service Provision fail?
5 Have they upgraded since the problem was reported?
6 Can you ask the customer to supply logs showing a Service provisioning success and failure.
   (Providing request ID's for both)

Request:

[----] I, [2018-08-27T14:04:32.513220 #42209:fcb124]  INFO -- : Q-task_id([service_template_provision_task_99000000001229]) MIQ(MiqQueue.put) Message id: [99000017040827],  id: [], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Ta      sk id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [100], State: [ready], Deliver On: [2018-08-27 12:05:32 UTC], Data: [], Args: [{:object_type=>"ServiceTemplateProvisionTask", :object_id=>99000000001229, :namespace=>"AutomationManagement/AnsibleTower/Service/P      rovisioning/StateMachines", :class_name=>"Provision", :instance_name=>"CatalogItemInitialization", :automate_message=>"create", :attrs=>{"request"=>"clone_to_service", :service_action=>"Provision", "Service::Service"=>99000000001226}, :user_id=>99000000000003, :miq_group_id=>9900      0000000019, :tenant_id=>99000000000001, :state=>"sequencer", :ae_fsm_started=>nil, :ae_state_started=>"2018-08-27 11:54:27 UTC", :ae_state_retries=>4, :ae_state_previous=>"---\n\"/ManageIQ/AutomationManagement/AnsibleTower/Service/Provisioning/StateMachines/Provision/CatalogItemI      nitialization\":\n  ae_state: sequencer\n  ae_state_retries: 4\n  ae_state_started: 2018-08-27 11:54:27 UTC\n  ae_state_max_retries: 100\n"}]

Queue responding: 

[----] I, [2018-08-27T15:11:41.597239 #42209:fcb124]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [99000017040827], MiqWorker id: [99000000295240], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id      : [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [100], State: [dequeue], Deliver On: [2018-08-27 12:05:32 UTC], Data: [], Args: [{:object_type=>"ServiceTemplateProvisionTask", :object_id=>99000000001229, :namespace=>"AutomationManagement/AnsibleTower/Service/Prov      isioning/StateMachines", :class_name=>"Provision", :instance_name=>"CatalogItemInitialization", :automate_message=>"create", :attrs=>{"request"=>"clone_to_service", :service_action=>"Provision", "Service::Service"=>99000000001226}, :user_id=>99000000000003, :miq_group_id=>9900000      0000019, :tenant_id=>99000000000001, :state=>"sequencer", :ae_fsm_started=>nil, :ae_state_started=>"2018-08-27 11:54:27 UTC", :ae_state_retries=>4, :ae_state_previous=>"---\n\"/ManageIQ/AutomationManagement/AnsibleTower/Service/Provisioning/StateMachines/Provision/CatalogItemInit      ialization\":\n  ae_state: sequencer\n  ae_state_retries: 4\n  ae_state_started: 2018-08-27 11:54:27 UTC\n  ae_state_max_retries: 100\n"}], Dequeued in: [4029.124412259] seconds

Thanks

Billy