Bug 916794

Summary: pulp-admin orphan list, Performance & Memory concerns (~17 minutes and consuming consuming ~1.65GB memory)
Product: [Retired] Pulp Reporter: John Matthews <jmatthew>
Component: user-experienceAssignee: Jason Connor <jconnor>
Status: CLOSED CURRENTRELEASE QA Contact: Preethi Thomas <pthomas>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: unspecifiedCC: jason.dobies, mmccune, skarmark
Target Milestone: ---Keywords: Triaged
Target Release: 2.1.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-04-08 16:02:49 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:

Description John Matthews 2013-02-28 22:40:36 UTC
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

Comment 1 John Matthews 2013-02-28 23:11:46 UTC
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.

Comment 2 John Matthews 2013-02-28 23:13:51 UTC
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.

Comment 3 John Matthews 2013-02-28 23:30:49 UTC
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

Comment 4 Jay Dobies 2013-03-05 15:02:53 UTC
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.

Comment 5 Jason Connor 2013-03-20 19:54:09 UTC
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

Comment 6 Jeff Ortel 2013-03-21 14:47:31 UTC
build: 2.1.0-0.25.beta

Comment 7 Preethi Thomas 2013-03-28 20:44:08 UTC
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 ~]#

Comment 8 Preethi Thomas 2013-04-08 16:02:49 UTC
Pulp 2.1 released 


http://www.pulpproject.org/2013/04/05/pulp-2-1-0-released/