Bug 1519953

Summary: Logging of the server process memory/cpu (MiqServer.log_status) is incorrect
Product: Red Hat CloudForms Management Engine Reporter: Joe Rafaniello <jrafanie>
Component: ApplianceAssignee: Joe Rafaniello <jrafanie>
Status: CLOSED CURRENTRELEASE QA Contact: Dmitry Misharov <dmisharo>
Severity: high Docs Contact:
Priority: high    
Version: 5.7.0CC: abellott, cpelland, dmisharo, jhardy, obarenbo, simaishi
Target Milestone: GAKeywords: TestOnly
Target Release: 5.10.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: 5.10.0.0 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1519986 1519987 1519988 (view as bug list) Environment:
Last Closed: 2018-06-21 20:47:44 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1519986, 1519987, 1519988    

Description Joe Rafaniello 2017-12-01 18:56:06 UTC
Description of problem: According to the MiqServer.log_status log lines, the same server process cpu time and memory jumps up and down.  It is actually logging the process information for the worker running the task, not the actual server process itself.


Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1. Run an appliance for more than 10 minutes
2. Look at the MiqServer.log_status log lines every 5 minutes
3. CPU Time is clearly wrong as this value should never go down, but it does in our logs with several workers. 

Actual results:

CPU time goes from 47,331,089 to 15,970,987 five minutes later and back to 47,336,822 minutes later.  Note, the memory is going up and down.

[----] I, [2017-10-27T03:38:05.397959 #1906:9d3140]  INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_status) [EVM Server (2485)] Process info: Memory Usage [1216200704], Memory Size [2563485696], Proportional Set Size: [1108330000], Memory % [7.3], CPU Time [10606001.0], CPU % [1.26], Priority [30]
[----] I, [2017-10-27T03:43:08.426006 #60405:9d3140]  INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_status) [EVM Server (2485)] Process info: Memory Usage [652361728], Memory Size [1021591552], Proportional Set Size: [580377000], Memory % [3.92], CPU Time [47331089.0], CPU % [5.62], Priority [21]
[----] I, [2017-10-27T03:48:02.865969 #44140:9d3140]  INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_status) [EVM Server (2485)] Process info: Memory Usage [1107316736], Memory Size [2548826112], Proportional Set Size: [995872000], Memory % [6.65], CPU Time [15970987.0], CPU % [3.59], Priority [30]
[----] I, [2017-10-27T03:53:03.344190 #1922:9d3140]  INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_status) [EVM Server (2485)] Process info: Memory Usage [652374016], Memory Size [1021591552], Proportional Set Size: [580378000], Memory % [3.92], CPU Time [47336822.0], CPU % [5.62], Priority [21]
[----] I, [2017-10-27T03:58:06.160892 #1906:9d3140]  INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_status) [EVM Server (2485)] Process info: Memory Usage [1216172032], Memory Size [2563485696], Proportional Set Size: [1108302000], Memory % [7.3], CPU Time [10617177.0], CPU % [1.26], Priority [30]

Expected results:  MiqServer.log_status should show the actual server process memory/cpu information and not the worker process that handles the message.  :-(



Additional info:

Comment 2 Joe Rafaniello 2017-12-01 18:57:17 UTC
Upstream PR merged: https://github.com/ManageIQ/manageiq/pull/16460