Hide Forgot
Description of problem: Running rhsm-debug on a simple rhel7 VM installation takes around 90s: # time rhsm-debug system --sos --no-archive --destination /var/tmp/out/ Wrote: /var/tmp/out//rhsm-debug-system-20140627-165705 real 1m26.624s user 0m6.045s sys 0m0.384s This is run by default by sos and on a typical install now accounts for around 1/3rd of the total runtime: # time sosreport -vv --batch [...] real 2m41.154s user 0m57.406s sys 0m11.706s We really need to get this down or we'll have to make collection of the rhsm-debug data optional. Version-Release number of selected component (if applicable): # rpm -q subscription-manager subscription-manager-1.10.14-7.el7.x86_64 How reproducible: 100% on my systems Steps to Reproduce: 1. time rhsm-debug system --sos --no-archive --destination /var/tmp/out/ Actual results: Routinely over 90s to generate ~16M of json data. Expected results: Ideally less than 10s for a default run. The rhsm-debug script is by far the longest-running command we call today: Commands: 'selinuxconlist' 0.219773s 'sh' 0.221468s 'nmcli' 0.227090s 'systemctl' 0.232961s 'lsof' 0.306699s 'sadf' 0.337759s 'ls' 0.409806s 'lsusb' 0.484617s 'tuned-adm' 0.494981s 'parted' 1.025333s 'firewall-cmd' 1.067522s 'lsinitrd' 1.360956s 'grub2-mkconfig' 2.074552s 'semodule' 3.628310s 'yum' 4.272996s 'rpm' 4.824193s 'subscription-manager' 11.536240s 'journalctl' 17.303878s 'stap-report' 19.274455s 'rhsm-debug' 93.130227s Additional info:
Seems like most of the time is going in getSubscriptionList: 138655/41032 2.669 0.000 5.625 0.000 connection.py:390(_decode_dict) 8 0.000 0.000 6.194 0.774 decoder.py:360(decode) 8 0.000 0.000 6.194 0.774 __init__.py:293(loads) 8 0.569 0.071 6.194 0.774 decoder.py:371(raw_decode) 4515293/1222201 3.725 0.000 6.691 0.000 encoder.py:341(_iterencode_dict) 3603979/1221546 2.613 0.000 7.549 0.000 encoder.py:288(_iterencode_list) 1222210 0.903 0.000 8.458 0.000 encoder.py:417(_iterencode) 6 0.509 0.085 9.027 1.505 encoder.py:186(encode) 6 0.025 0.004 9.052 1.509 __init__.py:193(dumps) 6 0.002 0.000 9.071 1.512 debug_commands.py:191(_write_flat_file) 1 0.000 0.000 9.569 9.569 connection.py:984(getPoolsList) 4388 0.051 0.000 21.238 0.005 socket.py:336(read) 4388 0.040 0.000 21.296 0.005 httplib.py:637(_safe_read) 8 0.033 0.004 22.250 2.781 httplib.py:579(_read_chunked) 8 0.002 0.000 22.251 2.781 httplib.py:534(read) 8 0.000 0.000 32.910 4.114 httplib.py:363(_read_status) 8 0.000 0.000 32.941 4.118 httplib.py:1009(getresponse) 8 0.000 0.000 32.941 4.118 httplib.py:402(begin) 2284 0.102 0.000 33.847 0.015 socket.py:406(readline) 1 0.000 0.000 51.713 51.713 connection.py:1128(getSubscriptionList) 18616 54.769 0.003 54.769 0.003 {M2Crypto.__m2crypto.ssl_read} 18616 0.041 0.000 54.810 0.003 Connection.py:210(_read_bio) 18616 0.042 0.000 54.852 0.003 Connection.py:226(read) 8 0.001 0.000 66.293 8.287 connection.py:421(_request) 8 0.001 0.000 66.297 8.287 connection.py:553(request_get) 1 0.031 0.031 74.103 74.103 debug_commands.py:72(_do_command) 1 0.000 0.000 75.566 75.566 cli.py:146(main) 1 0.000 0.000 75.566 75.566 managercli.py:301(main) Which'd fit with the size of the json archives: # ll -h /var/tmp/out/rhsm-debug-system-20140630-896709/ total 18M -rw-r--r--. 1 root root 19K Jun 30 13:09 compliance.json -rw-r--r--. 1 root root 11K Jun 30 13:09 consumer.json -rw-r--r--. 1 root root 13K Jun 30 13:09 entitlements.json -rw-r--r--. 1 root root 480K Jun 30 13:09 pools.json -rw-r--r--. 1 root root 17M Jun 30 13:09 subscriptions.json -rw-r--r--. 1 root root 192 Jun 30 13:09 version.json
This is a large amount of data. It is expected that it will take time to collect. As this is a 1 off type of tool that is run as part of manual troubleshooting, I'd say that 90 seconds is not prohibitive.
> is run as part of manual troubleshooting Not really. Running rhsm-debug by default in sos was requested in bug 1039036. This measn it runs every time a user runs sosreport (or when sos is run under automation e.g. via abrt, rhev-log-collector, rhs-log-collector etc.). 90s is an eternity in terms of an interactive support data collector tool and we routinely get complaints from customers and GSS associates about the time taken for sos to complete. As I said in comment #0 rhsm-debug is accounting for as much as 50% of our total runtime in a single command. If this can't be improved in subscription-manager I'll file a bug against sos to have this command disabled from 7.1 onwards.
Incidentally the hosts I'm testing on collect ~160M of data in the remaining run time. That's around ten times the quantity of data generated by rhsm-debug in about the same period of time so I don't think the quantity argument in comment #3 really stands.
Do those hosts collect it across the network from another machine that is concurrently handling a large number of entitlements? This data is not coming from the client, but rather out of the entitlement engine. If the subscription data is not needed, then file an RFE to make it a conditional part of this process.
It is also worth noting that the subscription data is compiled in the adapter layer at the entilement engine. This layer is controlled at stage and production by IT. These adapters pull the subscription data from additional systems. This would be the point of bottleneck.
> Do those hosts collect it across the network from another machine that is > concurrently handling a large number of entitlements? I don't know; this is just using the default configuration with public RHN hosts. The only host I see the process connecting to is subcription.rhn.redhat.com. > This data is not coming from the client, but rather out of the entitlement > engine. In that case is there any need to generate it during collection? Can it be generated after-the-fact on an analysis host or does it require private key material from the client (that we deliberately don't collect)? > If the subscription data is not needed I'm not really the person to make that call; the rhsm team requested we collect 'rhsm-debug system --sos --no-archive' by default when sos is run. If that's not needed (or if there are additional options we should pass to remove unneeded data) then it's easy enough to make that change but it's hard for me to evaluate what is and isn't needed to support these components.
I would say to remove getSubscriptionList call from rhsm_debug. Looks like it can be huge, or almost empty depending on server permission set up. The data is potentially useful for debugging subscription issues, but not 90s worth. It's also not used by subscription-manager directly. Tempting to say to remove all the calls that hit the network, since theoretically that data should be available to the folks doing the troubleshooting. I don't think that is actually always the case, and it loses some of the snapshot-in-time value, but it would be quicker and simpler.
will, go back on what said. Go ahead with removing it.
Added --no-subscriptions option to the rhsm-debug command commit 68a1a418c27172c4fb851d536813f8060f4d3d1f
comment 11 has been committed to master which will show up in versions >= subscription-manager-1.12.7-1 which will be delivered with RHEL6.6 and subsequently RHEL7.1 and beyond.
Acking 7.1
Verifying Version... [root@jsefler-os7 ~]# rpm -q subscription-manager subscription-manager-1.13.9-1.el7.x86_64 [root@jsefler-os7 ~]# rhsm-debug system --help Usage: rhsm-debug system [OPTIONS] Assemble system information as a tar file or directory Options: -h, --help show this help message and exit --proxy=PROXY_URL proxy URL in the form of proxy_hostname:proxy_port --proxyuser=PROXY_USER user for HTTP proxy with basic authentication --proxypassword=PROXY_PASSWORD password for HTTP proxy with basic authentication --destination=DESTINATION the destination location of the result; default is /tmp --no-archive data will be in an uncompressed directory --sos only data not already included in sos report will be collected --no-subscriptions exclude subscription data ^^^^^^^^^^^^^^^^^^ VERIFIED" The newly implemented --no-subscriptions appears in the command help. [root@jsefler-os7 ~]# subscription-manager register --serverur=https://jsefler-os-candlepin.usersys.redhat.com:8443/candlepin Username: testuser1 Password: Organization: admin The system has been registered with ID: f63d7339-3e5b-41ed-8c75-de8f21f66fd9 [root@jsefler-os7 ~]# time rhsm-debug system --sos --no-archive --destination /tmp/test Wrote: /tmp/test/rhsm-debug-system-20141121-274525 real 0m2.578s user 0m1.486s sys 0m0.177s [root@jsefler-os7 ~]# ls -l /tmp/test/rhsm-debug-system-20141121-274525 total 1940 -rw-r--r--. 1 root root 543 Nov 21 15:57 compliance.json -rw-r--r--. 1 root root 10337 Nov 21 15:57 consumer.json -rw-r--r--. 1 root root 2 Nov 21 15:57 entitlements.json -rw-r--r--. 1 root root 275794 Nov 21 15:57 pools.json -rw-r--r--. 1 root root 1680220 Nov 21 15:57 subscriptions.json -rw-r--r--. 1 root root 185 Nov 21 15:57 version.json [root@jsefler-os7 ~]# ^^^^^^^^^^^^^^^^^^ NOTICE: without specifying --no-subscriptions, the rhsm-debug took 2.578 seconds and wrote a large subscriptions.json file that was retrieved from the server. [root@jsefler-os7 ~]# time rhsm-debug system --sos --no-archive --destination /tmp/test --no-subscriptions Wrote: /tmp/test/rhsm-debug-system-20141121-959727 real 0m1.328s user 0m0.688s sys 0m0.141s [root@jsefler-os7 ~]# ls -l /tmp/test/rhsm-debug-system-20141121-959727 total 296 -rw-r--r--. 1 root root 543 Nov 21 16:02 compliance.json -rw-r--r--. 1 root root 10337 Nov 21 16:02 consumer.json -rw-r--r--. 1 root root 2 Nov 21 16:02 entitlements.json -rw-r--r--. 1 root root 275794 Nov 21 16:02 pools.json -rw-r--r--. 1 root root 185 Nov 21 16:02 version.json [root@jsefler-os7 ~]# VERIFIED: when specifying --no-subscriptions, the rhsm-debug took 1.328 seconds (50% faster) and did not retrieve a subscriptions.json file from the server.
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://rhn.redhat.com/errata/RHBA-2015-0502.html