Bug 1264188 - [Scale] - VIMBroker spends ~28s hot on a vcpu while outputting status to vim.log every 15minutes on large scale vmware provider
[Scale] - VIMBroker spends ~28s hot on a vcpu while outputting status to vim....
Status: CLOSED ERRATA
Product: Red Hat CloudForms Management Engine
Classification: Red Hat
Component: Performance (Show other bugs)
5.4.0
Unspecified Unspecified
medium Severity medium
: GA
: 5.5.0
Assigned To: Joe Rafaniello
Alex Krzos
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2015-09-17 15:09 EDT by Alex Krzos
Modified: 2015-12-08 08:31 EST (History)
7 users (show)

See Also:
Fixed In Version: 5.5.0.7
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2015-12-08 08:31:05 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
vim.log output on info showing vim broker status taking ~28s and top output showing 99-100% cpu util on process during status output (2.02 KB, application/zip)
2015-09-17 15:09 EDT, Alex Krzos
no flags Details

  None (edit)
Description Alex Krzos 2015-09-17 15:09:06 EDT
Created attachment 1074561 [details]
vim.log output on info showing vim broker status taking ~28s and top output showing 99-100% cpu util on process during status output

Description of problem:
The VIMBroker spends ~28-30s to dump status to the vim.log however logging level is set to warn by default in advanced configuration thus the worker is busy without actually outputting its status to vim.log.  On long running benchmarks this manifests itself by showing 30s of time where a vcpu is 100% utilized once every 15 minutes.  

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

How reproducible:
Always on 5.4.2.0

Steps to Reproduce:
1. Enable VIMBroker for large scale provider and observe cpu usage
2.
3.

Actual results:
In an idle cfme environment attached to a large scale provider (10,000 VMs), VIMBroker will consume 100% of a single vCPU for 30s every 15 minutes without actually outputting anything to vim.log by default.

Expected results:
Only until you enable vim.log to level info should the actual usage of the cpu really occur.

Additional info:

Attached vim.log showing status taking ~28s and output from top batched at 1s intervals filtered on VIMBroker PID displaying CPU usage
Comment 4 CFME Bot 2015-10-20 11:41:48 EDT
New commit detected on ManageIQ/manageiq/master:
https://github.com/ManageIQ/manageiq/commit/2516030b6747560140ff7da7bf007a8c31bf9825

commit 2516030b6747560140ff7da7bf007a8c31bf9825
Author:     Joe Rafaniello <jrafanie@redhat.com>
AuthorDate: Mon Oct 19 14:22:22 2015 -0400
Commit:     Joe Rafaniello <jrafanie@redhat.com>
CommitDate: Tue Oct 20 09:58:54 2015 -0400

    Sync on lockHash only if we'll log something
    
    For the default logger level, warn, we'll acquire the lock, hold it,
    traverse the in memory cache, never log anything, and finally release
    the lock.
    
    Let's only do this when the log level is high enough to print the
    status as it will slow other threads by holding the lock.
    
    https://bugzilla.redhat.com/show_bug.cgi?id=1264188

 gems/pending/VMwareWebService/MiqVimBroker.rb | 2 ++
 1 file changed, 2 insertions(+)
Comment 6 CFME Bot 2015-10-20 11:56:58 EDT
Detected commit referencing this ticket while ticket status is POST.
Comment 8 CFME Bot 2015-10-21 10:03:13 EDT
Detected commit referencing this ticket while ticket status is MODIFIED.
Comment 10 errata-xmlrpc 2015-12-08 08:31:05 EST
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2015:2551

Note You need to log in before you can comment on or make changes to this bug.