evm metrics collector worker RHVM worker memory threshold while exiting

evm.log

[root@CF-B2B-R0000-58009-test vmdb]# egrep '\[21634\]' log/evm.log
[----] I, [2017-04-11T07:49:35.604649 #40011:1045140]  INFO -- : MIQ(MiqQueue.put) Message id: [11745],  id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [["MiqServer", 1], "evm_worker_start", {:event_details=>"Worker started: ID [42], PID [21634], GUID [ef1e1b5a-1eac-11e7-8366-001a4a22391a]", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker"}]
[----] I, [2017-04-11T07:49:35.604817 #40011:1045140]  INFO -- : MIQ(ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker#start) Worker started: ID [42], PID [21634], GUID [ef1e1b5a-1eac-11e7-8366-001a4a22391a]
[----] I, [2017-04-11T07:49:35.840699 #21634:1045140]  INFO -- : MIQ(ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker::Runner#sync_config) ID [42], PID [21634], GUID [ef1e1b5a-1eac-11e7-8366-001a4a22391a], Zone [default], Active Roles [automate,database_operations,database_owner,ems_inventory,ems_metrics_collector,ems_metrics_coordinator,ems_metrics_processor,ems_operations,event,notifier,reporting,scheduler,user_interface,web_services], Assigned Roles [automate,database_operations,database_owner,ems_inventory,ems_metrics_collector,ems_metrics_coordinator,ems_metrics_processor,ems_operations,event,notifier,reporting,scheduler,user_interface,web_services], Configuration:
[----] I, [2017-04-11T07:49:36.213581 #21634:1045140]  INFO -- : ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker::Runner started. ID [42], PID [21634], GUID [ef1e1b5a-1eac-11e7-8366-001a4a22391a], Zone [default], Role [automate,database_operations,database_owner,ems_inventory,ems_metrics_collector,ems_metrics_coordinator,ems_metrics_processor,ems_operations,event,notifier,reporting,scheduler,user_interface,web_services]
[----] I, [2017-04-11T07:49:37.065817 #40541:1045140]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [11745], MiqWorker id: [1], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [["MiqServer", 1], "evm_worker_start", {:event_details=>"Worker started: ID [42], PID [21634], GUID [ef1e1b5a-1eac-11e7-8366-001a4a22391a]", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker"}], Dequeued in: [1.48175456] seconds
[----] I, [2017-04-11T07:49:37.074959 #40541:1045140]  INFO -- : <AutomationEngine> MiqAeEvent.build_evm_event >> event=<"evm_worker_start"> inputs=<{:event_details=>"Worker started: ID [42], PID [21634], GUID [ef1e1b5a-1eac-11e7-8366-001a4a22391a]", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker", "MiqEvent::miq_event"=>3130, :miq_event_id=>3130, "EventStream::event_stream"=>3130, :event_stream_id=>3130}>
[----] I, [2017-04-11T07:49:37.092159 #40541:1045140]  INFO -- : MIQ(MiqQueue.put) Message id: [11746],  id: [], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: [{:object_type=>"MiqServer", :object_id=>1, :attrs=>{:event_type=>"evm_worker_start", :event_details=>"Worker started: ID [42], PID [21634], GUID [ef1e1b5a-1eac-11e7-8366-001a4a22391a]", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker", "MiqEvent::miq_event"=>3130, :miq_event_id=>3130, "EventStream::event_stream"=>3130, :event_stream_id=>3130}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :automate_message=>nil}]
[----] I, [2017-04-11T07:49:42.359174 #40559:1045140]  INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [11746], MiqWorker id: [3], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [{:object_type=>"MiqServer", :object_id=>1, :attrs=>{:event_type=>"evm_worker_start", :event_details=>"Worker started: ID [42], PID [21634], GUID [ef1e1b5a-1eac-11e7-8366-001a4a22391a]", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker", "MiqEvent::miq_event"=>3130, :miq_event_id=>3130, "EventStream::event_stream"=>3130, :event_stream_id=>3130}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :automate_message=>nil}], Dequeued in: [5.275313561] seconds
[----] I, [2017-04-11T07:49:42.360530 #40559:1045140]  INFO -- : MIQ(MiqAeEngine.deliver) Delivering {:event_type=>"evm_worker_start", :event_details=>"Worker started: ID [42], PID [21634], GUID [ef1e1b5a-1eac-11e7-8366-001a4a22391a]", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker", "MiqEvent::miq_event"=>3130, :miq_event_id=>3130, "EventStream::event_stream"=>3130, :event_stream_id=>3130} for object [MiqServer.1] with state [] to Automate
[----] W, [2017-04-11T07:50:57.579104 #40011:1045140]  WARN -- : MIQ(MiqServer#validate_worker) Worker [ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker] with ID: [42], PID: [21634], GUID: [ef1e1b5a-1eac-11e7-8366-001a4a22391a] process memory usage [420320000] exceeded limit [419430400], requesting worker to exit
[----] I, [2017-04-11T07:50:57.590189 #40011:1045140]  INFO -- : MIQ(MiqQueue.put) Message id: [12120],  id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [["MiqServer", 1], "evm_worker_memory_exceeded", {:event_details=>"Worker [ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker] with ID: [42], PID: [21634], GUID: [ef1e1b5a-1eac-11e7-8366-001a4a22391a] process memory usage [420320000] exceeded limit [419430400], requesting worker to exit", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker"}]
[----] I, [2017-04-11T07:50:57.590369 #40011:1045140]  INFO -- : MIQ(MiqServer#stop_worker) Stopping Worker [ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker] with ID: [42], PID: [21634], GUID: [ef1e1b5a-1eac-11e7-8366-001a4a22391a], status [started]...
[----] I, [2017-04-11T07:50:57.599686 #40011:1045140]  INFO -- : MIQ(MiqQueue.put) Message id: [12121],  id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [["MiqServer", 1], "evm_worker_stop", {:event_details=>"Stopping Worker [ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker] with ID: [42], PID: [21634], GUID: [ef1e1b5a-1eac-11e7-8366-001a4a22391a], status [started]...", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker"}]
[----] I, [2017-04-11T07:50:57.605730 #40011:1045140]  INFO -- : MIQ(MiqServer#worker_set_message) Worker [ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker] with ID: [42], PID: [21634], GUID: [ef1e1b5a-1eac-11e7-8366-001a4a22391a] is being requested to exit
[----] I, [2017-04-11T07:50:58.904968 #40550:1045140]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [12120], MiqWorker id: [2], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [["MiqServer", 1], "evm_worker_memory_exceeded", {:event_details=>"Worker [ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker] with ID: [42], PID: [21634], GUID: [ef1e1b5a-1eac-11e7-8366-001a4a22391a] process memory usage [420320000] exceeded limit [419430400], requesting worker to exit", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker"}], Dequeued in: [1.324277212] seconds
[----] I, [2017-04-11T07:50:58.936448 #40550:1045140]  INFO -- : <AutomationEngine> MiqAeEvent.build_evm_event >> event=<"evm_worker_memory_exceeded"> inputs=<{:event_details=>"Worker [ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker] with ID: [42], PID: [21634], GUID: [ef1e1b5a-1eac-11e7-8366-001a4a22391a] process memory usage [420320000] exceeded limit [419430400], requesting worker to exit", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker", "MiqEvent::miq_event"=>3134, :miq_event_id=>3134, "EventStream::event_stream"=>3134, :event_stream_id=>3134}>
[----] I, [2017-04-11T07:50:58.970107 #40550:1045140]  INFO -- : MIQ(MiqQueue.put) Message id: [12127],  id: [], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: [{:object_type=>"MiqServer", :object_id=>1, :attrs=>{:event_type=>"evm_worker_memory_exceeded", :event_details=>"Worker [ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker] with ID: [42], PID: [21634], GUID: [ef1e1b5a-1eac-11e7-8366-001a4a22391a] process memory usage [420320000] exceeded limit [419430400], requesting worker to exit", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker", "MiqEvent::miq_event"=>3134, :miq_event_id=>3134, "EventStream::event_stream"=>3134, :event_stream_id=>3134}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :automate_message=>nil}]
[----] I, [2017-04-11T07:50:58.995503 #40550:1045140]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [12121], MiqWorker id: [2], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [["MiqServer", 1], "evm_worker_stop", {:event_details=>"Stopping Worker [ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker] with ID: [42], PID: [21634], GUID: [ef1e1b5a-1eac-11e7-8366-001a4a22391a], status [started]...", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker"}], Dequeued in: [1.403959631] seconds
[----] I, [2017-04-11T07:50:59.013913 #40550:1045140]  INFO -- : <AutomationEngine> MiqAeEvent.build_evm_event >> event=<"evm_worker_stop"> inputs=<{:event_details=>"Stopping Worker [ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker] with ID: [42], PID: [21634], GUID: [ef1e1b5a-1eac-11e7-8366-001a4a22391a], status [started]...", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker", "MiqEvent::miq_event"=>3135, :miq_event_id=>3135, "EventStream::event_stream"=>3135, :event_stream_id=>3135}>
[----] I, [2017-04-11T07:50:59.046573 #40550:1045140]  INFO -- : MIQ(MiqQueue.put) Message id: [12128],  id: [], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: [{:object_type=>"MiqServer", :object_id=>1, :attrs=>{:event_type=>"evm_worker_stop", :event_details=>"Stopping Worker [ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker] with ID: [42], PID: [21634], GUID: [ef1e1b5a-1eac-11e7-8366-001a4a22391a], status [started]...", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker", "MiqEvent::miq_event"=>3135, :miq_event_id=>3135, "EventStream::event_stream"=>3135, :event_stream_id=>3135}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :automate_message=>nil}]
[----] I, [2017-04-11T07:51:03.370087 #40567:1045140]  INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [12127], MiqWorker id: [4], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [{:object_type=>"MiqServer", :object_id=>1, :attrs=>{:event_type=>"evm_worker_memory_exceeded", :event_details=>"Worker [ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker] with ID: [42], PID: [21634], GUID: [ef1e1b5a-1eac-11e7-8366-001a4a22391a] process memory usage [420320000] exceeded limit [419430400], requesting worker to exit", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker", "MiqEvent::miq_event"=>3134, :miq_event_id=>3134, "EventStream::event_stream"=>3134, :event_stream_id=>3134}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :automate_message=>nil}], Dequeued in: [4.423320065] seconds
[----] I, [2017-04-11T07:51:03.371530 #40567:1045140]  INFO -- : MIQ(MiqAeEngine.deliver) Delivering {:event_type=>"evm_worker_memory_exceeded", :event_details=>"Worker [ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker] with ID: [42], PID: [21634], GUID: [ef1e1b5a-1eac-11e7-8366-001a4a22391a] process memory usage [420320000] exceeded limit [419430400], requesting worker to exit", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker", "MiqEvent::miq_event"=>3134, :miq_event_id=>3134, "EventStream::event_stream"=>3134, :event_stream_id=>3134} for object [MiqServer.1] with state [] to Automate
[----] I, [2017-04-11T07:51:03.492421 #40559:1045140]  INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [12128], MiqWorker id: [3], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [{:object_type=>"MiqServer", :object_id=>1, :attrs=>{:event_type=>"evm_worker_stop", :event_details=>"Stopping Worker [ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker] with ID: [42], PID: [21634], GUID: [ef1e1b5a-1eac-11e7-8366-001a4a22391a], status [started]...", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker", "MiqEvent::miq_event"=>3135, :miq_event_id=>3135, "EventStream::event_stream"=>3135, :event_stream_id=>3135}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :automate_message=>nil}], Dequeued in: [4.4640241] seconds
[----] I, [2017-04-11T07:51:03.493805 #40559:1045140]  INFO -- : MIQ(MiqAeEngine.deliver) Delivering {:event_type=>"evm_worker_stop", :event_details=>"Stopping Worker [ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker] with ID: [42], PID: [21634], GUID: [ef1e1b5a-1eac-11e7-8366-001a4a22391a], status [started]...", :type=>"ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker", "MiqEvent::miq_event"=>3135, :miq_event_id=>3135, "EventStream::event_stream"=>3135, :event_stream_id=>3135} for object [MiqServer.1] with state [] to Automate
[----] I, [2017-04-11T07:51:11.030961 #21634:1045140]  INFO -- : MIQ(ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker#log_status) [C&U Metrics Collector for RHEV] Worker ID [42], PID [21634], GUID [ef1e1b5a-1eac-11e7-8366-001a4a22391a], Last Heartbeat [2017-04-11 11:50:45 UTC], Process Info: Memory Usage [526888960], Memory Size [948490240], Proportional Set Size: [421044000], Memory % [3.16], CPU Time [6985.0], CPU % [0.01], Priority [23]
[----] I, [2017-04-11T07:51:11.031217 #21634:1045140]  INFO -- : MIQ(ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker::Runner) ID [42] PID [21634] GUID [ef1e1b5a-1eac-11e7-8366-001a4a22391a] Exit request received. Worker exiting.
[----] I, [2017-04-11T07:51:14.191397 #40011:1045140]  INFO -- : MIQ(MiqServer#clean_worker_records) SQL Record for Worker [ManageIQ::Providers::Redhat::InfraManager::MetricsCollectorWorker] with ID: [42], PID: [21634], GUID: [ef1e1b5a-1eac-11e7-8366-001a4a22391a], Status: [stopped] is being deleted