Description of problem: I setup a new pulp on a m1.large instance (~7.5GB RAM and no swap), after syncing/deleting a repo I attempting to run: "pulp-admin orphan list". It ran for 3 minutes then failed with a "MemoryError". Note: I did not restart pulp after the sync. I ran the sync then delete, then orphan list. Version-Release number of selected component (if applicable): # rpm -qa | grep pulp m2crypto-0.21.1.pulp-8.el6.x86_64 python-oauth2-1.5.170-3.pulp.el6.noarch pulp-puppet-plugins-2.0.8-1.noarch python-pulp-rpm-extension-2.0.8-1.noarch pulp-rpm-admin-extensions-2.0.8-1.noarch python-isodate-0.5.0-1.pulp.el6.noarch python-pulp-puppet-common-2.0.8-1.noarch python-rhsm-1.8.0-1.pulp.el6.x86_64 pulp-server-2.0.8-1.noarch pulp-rpm-plugins-2.0.8-1.noarch pulp-selinux-2.0.8-1.noarch python-pulp-client-lib-2.0.8-1.noarch python-pulp-bindings-2.0.8-1.noarch pulp-admin-client-2.0.8-1.noarch pulp-puppet-admin-extensions-2.0.8-1.noarch python-pulp-common-2.0.8-1.noarch python-pulp-rpm-common-2.0.8-1.noarch mod_wsgi-3.3-4.pulp.el6.x86_64 pulp-builtins-admin-extensions-2.0.8-1.noarch How reproducible: Steps to Reproduce: 1) Adjust Pulp to use 4 threads for syncing # cat /usr/lib/pulp/plugins/importers/yum_importer/yum_importer.conf { "num_threads": 4 } 2) Synced a small repo of 3 packages http://jmatthews.fedorapeople.org/pulp_unittest/ 3) Synced RHEL 6.2 X86_64 from RH CDN. pulp-admin rpm repo create --repo-id rhel6_x86_64 --feed-ca ./cdn.redhat.com-chain.crt --feed-cert ./1359391926_4512.crt --feed-key ./1359391926_4512.key --feed https://cdn.redhat.com/content/dist/rhel/rhui/server/6/6.2/x86_64/os 4) Deleted Repo RHEL 6.2 X86_64 5) Run: pulp-admin orphan list Note: This was run after Repo was deleted and task showed: pulp-admin repo tasks list --repo-id rhel6_x864 +----------------------------------------------------------------------+ Tasks +----------------------------------------------------------------------+ Operations: delete Resources: rhel6_x864 (repository) State: Successful Start Time: 2013-02-28T22:05:08Z Finish Time: 2013-02-28T22:05:10Z Result: N/A Task Id: 6580dc7f-8d62-4d6a-a592-0e3f17014e49 [root@ec2-50-17-33-189 ~]# pulp-admin repo list +----------------------------------------------------------------------+ Repositories +----------------------------------------------------------------------+ Id: pulp_unittest Display Name: pulp_unittest Description: None Content Unit Count: 61 Actual results: # time pulp-admin orphan list &> orphan.list real 3m12.158s user 2m1.903s sys 0m5.497s # cat orphan.list An unexpected error has occurred. More information can be found in the client log file ~/.pulp/admin.log. 2013-02-28 17:12:49,023 - ERROR - Client-side exception occurred Traceback (most recent call last): File "/usr/lib/python2.6/site-packages/pulp/client/extensions/core.py", line 478, in run exit_code = Cli.run(self, args) File "/usr/lib/python2.6/site-packages/okaara/cli.py", line 921, in run exit_code = command_or_section.execute(self.prompt, remaining_args) File "/usr/lib/python2.6/site-packages/pulp/client/extensions/extensions.py", line 224, in execute return self.method(*arg_list, **clean_kwargs) File "/usr/lib/python2.6/site-packages/pulp/client/commands/unit.py", line 104, in run orphans = self.context.server.content_orphan.orphans().response_body File "/usr/lib/python2.6/site-packages/pulp/bindings/content.py", line 27, in orphans return self.server.GET(self.PATH) File "/usr/lib/python2.6/site-packages/pulp/bindings/server.py", line 84, in GET return self._request('GET', path, queries) File "/usr/lib/python2.6/site-packages/pulp/bindings/server.py", line 139, in _request self.api_responses_logger.info("Response body :\n %s\n" % json.dumps(response_body, indent=2)) File "/usr/lib64/python2.6/json/__init__.py", line 237, in dumps **kw).encode(obj) File "/usr/lib64/python2.6/json/encoder.py", line 368, in encode return ''.join(chunks) MemoryError Additional info: Note memory usage is quite high in main wsgi process. from top: 25291 apache 20 0 6246m 4.6g 1888 S 0.9 63.0 208:46.29 httpd from pmap -d: mapped: 6526976K writeable/private: 5324176K shared: 1004K from ps auxf: USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND mongodb 24472 3.6 0.7 1797896 58268 ? Sl 10:41 14:44 /usr/bin/mongod --quiet -f /etc/mongodb.conf run root 25289 0.0 0.0 206560 3608 ? Ss 13:06 0:04 /usr/sbin/httpd apache 25291 82.2 64.6 6526976 4943052 ? Sl 13:06 208:44 \_ (wsgi:pulp) apache 25292 0.2 0.0 209052 6812 ? S 13:06 0:45 \_ /usr/sbin/httpd apache 25293 0.2 0.0 209052 6804 ? S 13:06 0:45 \_ /usr/sbin/httpd apache 25294 0.2 0.0 209048 6808 ? S 13:06 0:44 \_ /usr/sbin/httpd apache 25295 0.2 0.0 209052 6804 ? S 13:06 0:44 \_ /usr/sbin/httpd apache 25296 0.3 2.3 380820 178628 ? S 13:06 0:56 \_ /usr/sbin/httpd apache 25297 0.2 0.0 209052 6804 ? S 13:06 0:44 \_ /usr/sbin/httpd apache 25298 0.2 0.0 209052 6804 ? S 13:06 0:45 \_ /usr/sbin/httpd apache 25299 0.3 1.5 319988 117740 ? S 13:06 0:55 \_ /usr/sbin/httpd Sync output. cat /usr/lib/pulp/plugins/importers/yum_importer/yum_importer.conf { "num_threads": 4 } # time pulp-admin rpm repo sync run --repo-id rhel6_x864 +----------------------------------------------------------------------+ Synchronizing Repository [rhel6_x864] +----------------------------------------------------------------------+ This command may be exited by pressing ctrl+c without affecting the actual operation on the server. Downloading metadata... [\] ... completed Downloading repository content... [==================================================] 100% RPMs: 7281/7281 items Delta RPMs: 0/0 items Tree Files: 6/6 items Files: 0/0 items ... completed Importing errata... [\] ... completed Importing package groups/categories... [/] ... completed Publishing packages... [==================================================] 100% Packages: 7281/7281 items ... completed Publishing distributions... [==================================================] 100% Distributions: 6/6 items ... completed Generating metadata [/] ... completed Publishing repository over HTTPS [-] ... completed real 174m3.440s user 4m27.888s sys 0m19.161s
Restarted Apache and Mongo No other operations were run root 7728 0.1 0.0 206560 5836 ? Ss 17:45 0:00 /usr/sbin/httpd apache 7730 1.0 0.5 1048808 41124 ? Sl 17:45 0:00 \_ (wsgi:pulp) apache 7731 0.0 0.0 208212 6092 ? S 17:45 0:00 \_ /usr/sbin/httpd apache 7732 0.0 0.0 208212 6092 ? S 17:45 0:00 \_ /usr/sbin/httpd apache 7733 0.0 0.0 208212 6092 ? S 17:45 0:00 \_ /usr/sbin/httpd apache 7734 0.0 0.0 208212 6092 ? S 17:45 0:00 \_ /usr/sbin/httpd apache 7735 0.0 0.0 208212 6096 ? S 17:45 0:00 \_ /usr/sbin/httpd apache 7736 0.0 0.0 208212 6092 ? S 17:45 0:00 \_ /usr/sbin/httpd apache 7737 0.0 0.0 208212 6092 ? S 17:45 0:00 \_ /usr/sbin/httpd apache 7738 0.0 0.0 208212 6092 ? S 17:45 0:00 \_ /usr/sbin/httpd mongodb 7792 1.3 0.4 775900 32548 ? Sl 17:46 0:00 /usr/bin/mongod --quiet -f /etc/mongodb.conf run # time pulp-admin orphan list &> orphan.list real 17m46.740s user 16m12.143s sys 0m9.459s root 7728 0.0 0.0 206560 5836 ? Ss 17:45 0:00 /usr/sbin/httpd apache 7730 4.5 22.0 2752916 1689444 ? Sl 17:45 1:01 \_ (wsgi:pulp) apache 7731 0.0 0.0 208212 6096 ? S 17:45 0:00 \_ /usr/sbin/httpd apache 7732 0.0 0.0 208212 6092 ? S 17:45 0:00 \_ /usr/sbin/httpd apache 7733 0.0 0.0 208212 6092 ? S 17:45 0:00 \_ /usr/sbin/httpd apache 7734 0.0 0.0 208212 6092 ? S 17:45 0:00 \_ /usr/sbin/httpd apache 7735 0.8 2.6 407172 206324 ? S 17:45 0:11 \_ /usr/sbin/httpd apache 7736 0.0 0.0 208212 6092 ? S 17:45 0:00 \_ /usr/sbin/httpd apache 7737 0.0 0.0 208212 6092 ? S 17:45 0:00 \_ /usr/sbin/httpd apache 7738 0.0 0.0 208212 6092 ? S 17:45 0:00 \_ /usr/sbin/httpd mongodb 7792 1.2 4.6 1741588 356424 ? Sl 17:46 0:16 /usr/bin/mongod --quiet -f /etc/mongodb.conf run Saw memory consumption in wsgi process jump quickly from: ~1.0GB/.040GB to ~2.7GB/1.7GB Roughly 1.65GB diff from running this query.
My thoughts: 1) Possible issue with performance of "pulp-admin orphan list", maybe some mongo queries need to be tuned. 2) Issue in comment #0 about seeing MemoryError was probably hit since after the initial sync we were already consuming close to ~6GB of memory.
Interesting how it looks like running a removal on the orphan packages was much quicker: ~1 minute opposed to when I ran a list ~17minutes. I kicked off a pulp-admin orphan remove --all # pulp-admin tasks list +----------------------------------------------------------------------+ Tasks +----------------------------------------------------------------------+ Operations: Resources: orphans (content_unit) State: Successful Start Time: 2013-02-28T23:21:20Z Finish Time: 2013-02-28T23:22:25Z Result: N/A Task Id: bd47d4ee-7cff-41ed-b181-a334480765a7
John's looking into if this occurs when passing the -s flag. My suspicion is that the sheer amount of units that were orphaned when he ran this was crushing the JSON serialization. The remove not only has to run the same query but delete files on disk, which leads me to believe the query is performing fine and the issue is elsewhere. If the summary view turns out to be as efficient as I'm hoping, this bug will turn into changing the default view for orphan list to be the summary and adding a --details option if the user is suicidal.
I changed the way orphans are looked up and the amount of data that gets gathered with each orphan. Changes in master and pulp-2.1
build: 2.1.0-0.25.beta
moving to verified [root@cloud-qe-8 ~]# rpm -q pulp-server pulp-server-2.1.0-0.26.beta.noarch [root@cloud-qe-8 ~]# [root@cloud-qe-8 ~]# time pulp-admin orphan list +----------------------------------------------------------------------+ Summary +----------------------------------------------------------------------+ Distribution: 1 Erratum: 44 Package Category: 10 Package Group: 202 Rpm: 4477 Total: 4734 real 2m1.260s user 0m1.003s sys 0m0.059s [root@cloud-qe-8 ~]# [root@cloud-qe-8 ~]# ps auxf | grep wsgi root 23795 0.0 0.0 103244 824 pts/1 S+ 16:40 0:00 \_ grep wsgi apache 23753 3.2 0.2 1197348 48724 ? Sl 16:39 0:01 \_ (wsgi:pulp) [root@cloud-qe-8 ~]# pmap -d 23753 | tail -n 1 mapped: 1197348K writeable/private: 255104K shared: 996K [root@cloud-qe-8 ~]# pmap -d 23753 | tail -n 1 mapped: 1197348K writeable/private: 255368K shared: 996K [root@cloud-qe-8 ~]#
Pulp 2.1 released http://www.pulpproject.org/2013/04/05/pulp-2-1-0-released/