Bug 1122810

Summary: Slow hammer startup times (1.3+ seconds)
Product: Red Hat Satellite 6 Reporter: Dominic Cleal <dcleal>
Component: HammerAssignee: Tomas Strachota <tstrachota>
Status: CLOSED NEXTRELEASE QA Contact: Roman Plevka <rplevka>
Severity: medium Docs Contact:
Priority: high    
Version: 6.0.3CC: abradshaw, bkearney, cwelton, dcaplan, mkollar, mmccune, peter.vreman, sthirugn, tstrachota
Target Milestone: UnspecifiedKeywords: Performance, Triaged
Target Release: Unused   
Hardware: Unspecified   
OS: Unspecified   
URL: http://projects.theforeman.org/issues/14092
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-08-01 20:01:20 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
Bug Depends On: 1315660    
Bug Blocks: 1122832    

Description Dominic Cleal 2014-07-24 07:10:59 UTC
Description of problem:
When running "hammer --help", it's taking in excess of 1.3 seconds.  This makes it inefficient for use in a shell script, particularly when needing to retrieve IDs or run checks in other commands.

Version-Release number of selected component (if applicable):
rubygem-hammer_cli-0.1.1-5.el6sat
rubygem-hammer_cli_foreman-0.1.1-9.el6sat

How reproducible:
Always

Steps to Reproduce:
1. time hammer --help
2.
3.

Actual results:
>= 1.3 seconds

Expected results:
< 0.5 seconds?

Comment 1 Dominic Cleal 2014-07-24 07:11:15 UTC
Created redmine issue http://projects.theforeman.org/issues/6761 from this bug

Comment 4 Bryan Kearney 2014-08-06 12:05:08 UTC
Moving to POST since upstream bug http://projects.theforeman.org/issues/6761 has been closed
-------------
Tomáš Strachota
Most time consuming turned out to be command and option definition that takes place at class level. Lazy loading of subcommands strips most of the unnecessary requires.

My measurements showed times slightly <0.5s for hammer -h (or around 0.8 when running in bundler).

https://github.com/theforeman/hammer-cli/pull/126
https://github.com/theforeman/hammer-cli-foreman/pull/139
https://github.com/Katello/hammer-cli-katello/pull/210


-------------
Anonymous
Applied in changeset commit:hammer-cli-foreman|4fbd36b414aaf030e9dfda79fe4ccdd304d9faa7.

Comment 5 Tazim Kolhar 2014-10-17 08:01:03 UTC
VERIFED :

# rpm -qa | grep rubygem-hammer_cli
rubygem-hammer_cli_foreman_tasks-0.0.3-2.201409091410gitc96619d.git.0.37f3704.el6.noarch
rubygem-hammer_cli_foreman-0.1.3-1.201410151235gitbc8c449.el6.noarch
rubygem-hammer_cli_katello-0.0.6-1.201410161327gite14cd51.git.0.a8188a8.el6.noarch
rubygem-hammer_cli-0.1.3-1.201409240954gitf3c47c7.el6.noarch
rubygem-hammer_cli_import-0.10.4-1.el6.noarch


# time hammer --help

real	0m6.881s
user	0m0.684s
sys	0m0.241s

Comment 6 Dominic Cleal 2014-10-17 08:08:10 UTC
(In reply to Dominic Cleal from comment #0)
> Actual results:
> >= 1.3 seconds
> 
> Expected results:
> < 0.5 seconds?

(In reply to Tazim Kolhar from comment #5)
> # time hammer --help
> 
> real	0m6.881s

6 is greater than 0.5 seconds... in fact, it's worse than the 1.3 seconds I noted in comment #0.  Why is that verified?

Comment 7 Dominic Cleal 2014-10-17 12:45:05 UTC
I'd like a second verification please for the reason in comment #6.  It might be best to establish a baseline of your installation on 6.0.4 too.

Comment 8 Tazim Kolhar 2014-11-14 14:09:40 UTC
FAILEDQA

# rpm -qa | grep foreman
foreman-selinux-1.8.0-0.develop.201410280941git10de1c5.el6.noarch
foreman-1.8.0-0.develop.201411131901gitd5f92b3.el6.noarch
ruby193-rubygem-foreman_hooks-0.3.7-2.el6.noarch
qe-foreman-rhel65.usersys.redhat.com-foreman-client-1.0-1.noarch
qe-foreman-rhel65.usersys.redhat.com-qpid-client-cert-1.0-1.noarch
foreman-ovirt-1.8.0-0.develop.201411131901gitd5f92b3.el6.noarch
qe-foreman-rhel65.usersys.redhat.com-apache-1.0-1.noarch
ruby193-rubygem-foreman_docker-0.2.0-2.el6.noarch
rubygem-hammer_cli_foreman-0.1.3-1.201411121216git9381fc5.el6.noarch
ruby193-rubygem-foreman_discovery-1.4.0-2.el6.noarch
foreman-libvirt-1.8.0-0.develop.201411131901gitd5f92b3.el6.noarch
qe-foreman-rhel65.usersys.redhat.com-parent-cert-1.0-1.noarch
ruby193-rubygem-foreman_bootdisk-4.0.0-1.el6.noarch
foreman-proxy-1.8.0-0.develop.201411121327gitab6edc2.el6.noarch
qe-foreman-rhel65.usersys.redhat.com-puppet-client-1.0-1.noarch
foreman-compute-1.8.0-0.develop.201411131901gitd5f92b3.el6.noarch
foreman-gce-1.8.0-0.develop.201411131901gitd5f92b3.el6.noarch
rubygem-hammer_cli_foreman_tasks-0.0.3-2.201409091410gitc96619d.git.0.37f3704.el6.noarch
qe-foreman-rhel65.usersys.redhat.com-foreman-proxy-1.0-1.noarch
qe-foreman-rhel65.usersys.redhat.com-qpid-broker-1.0-1.noarch
foreman-postgresql-1.8.0-0.develop.201411131901gitd5f92b3.el6.noarch
foreman-vmware-1.8.0-0.develop.201411131901gitd5f92b3.el6.noarch
foreman-release-1.8.0-0.develop.201411131901gitd5f92b3.el6.noarch
ruby193-rubygem-foreman-tasks-0.6.10-1.el6.noarch

# time hammer --help

real	0m1.532s
user	0m0.689s
sys	0m0.297s


1 > 0.5

# hammer --version
 
hammer (0.1.3)
 * hammer_cli_import (0.10.4)
 * hammer_cli_katello (0.0.6)
 * hammer_cli_foreman (0.1.3)

Comment 9 Peter Vreman 2015-07-17 16:20:29 UTC
With Sat6.1.0 for me it is still 2+ seconds

# time hammer --help > /dev/null

real    0m2.281s
user    0m1.942s
sys     0m0.336s

# time hammer --version
hammer (0.1.4.11)
 * hammer_cli_foreman (0.1.4.14)
 * hammer_cli_foreman_bootdisk (0.1.2.7)
 * hammer_cli_foreman_discovery (0.0.1.10)
 * hammer_cli_foreman_docker (unknown version)
 * hammer_cli_gutterball (unknown version)
 * hammer_cli_import (0.10.17)
 * hammer_cli_katello (0.0.7.15)

real    0m2.219s
user    0m1.892s
sys     0m0.326s

Comment 10 Tomas Strachota 2015-11-30 13:56:20 UTC
I did some testing for Sat 6.1.4 on RHEL 7.1 and it seems to be a bit better:

time hammer --help > /dev/null
real	0m1.584s
user	0m1.453s
sys	0m0.130s

time hammer --version > /dev/null
real	0m1.532s
user	0m1.408s
sys	0m0.123s

Some deeper benchmarking discovered following pain points:
- Loading translations and searching for them in multiple FastGettext domains is quite time consuming.
- Requiring 'hammer_cli' library itself takes about 0.5s. One of the reasons seems to be that loading the 'restclient' dependency takes about 0.3s


I did some measurements with multi-domain translation switched off: 

time hammer --help > /dev/null
real	0m1.109s
user	0m1.017s
sys	0m0.092s

time hammer --version > /dev/null
real	0m1.080s
user	0m0.994s
sys	0m0.085s

Comment 11 Tomas Strachota 2016-03-08 11:34:40 UTC
I added a dependent bug for the multidomain translations performance problem as it's one of the steps towards better performance:
https://bugzilla.redhat.com/show_bug.cgi?id=1315660

Comment 12 Mike McCune 2016-03-13 21:30:21 UTC
With pre-Beta builds of 6.2 I'm seeing between 0.5 and 1.5 seconds:

real	0m0.743s
real	0m1.582s
real	0m0.673s

on various hardware

Comment 16 Roman Plevka 2016-05-13 15:03:57 UTC
FAILEDQA

sat 6.2.0 Beta GA11

I'm seeing times between 1.9 and 2.0s

real	0m2.019s
user	0m1.744s
sys	0m0.264s

Comment 18 Peter Vreman 2016-06-16 16:21:15 UTC
As initiator of the original request to create this BZ. For me the results are acceptable now for adhoc commandline usage.

The initial latency as can be seen with --version and --help is not perfect, but good enough. Also the rest of the commands that really request and present content are feeling as quick responses.

For real performance in automation the API can be used. It is much faster as shown below with the content view listing. Using the API also prevents overhead of date structure handling to generate output by hammer and then parse the output in the automation script again.


[crash] root@li-lc-1578:~# time hammer --version > /dev/null

real    0m1.380s
user    0m1.213s
sys     0m0.155s
[crash] root@li-lc-1578:~# time hammer --help > /dev/null

real    0m1.413s
user    0m1.243s
sys     0m0.157s

[crash] root@li-lc-1578:~# time hammer -c/opt/hoici/etc/sat6/hammer-hoici.yaml product list --organization=Hilti --per-page=9999 | wc -l
41

real    0m3.600s
user    0m1.343s
sys     0m0.163s

[crash] root@li-lc-1578:~# time hammer -c/opt/hoici/etc/sat6/hammer-hoici.yaml content-view list --organization=Hilti --per-page=9999 | wc -l
28

real    0m2.210s
user    0m1.575s
sys     0m0.189s

Compare with the API it is still slow

[crash] root@li-lc-1578:~# time curl -K /opt/hoici/etc/sat6/curl-hoici.conf "-HContent-Type: application/json" "-d{\"per_page\":9999}" -XGET https://localhost/katello/api/v2/content_views | wc -c
95913

real    0m0.380s
user    0m0.039s
sys     0m0.028s

Comment 19 Bryan Kearney 2016-10-07 13:51:27 UTC
*** Bug 1105535 has been marked as a duplicate of this bug. ***

Comment 20 Bryan Kearney 2017-02-09 20:46:58 UTC
This apepears to be improved for 6.3. I am moving this to POST and removing the FailedQA flag.

Comment 24 Bryan Kearney 2017-08-01 20:01:20 UTC
The fix to this bug will be delivered with release 6.3 of Satellite.