#6677 User profile's list of projects is slow to build

v1.2.0
closed
General
2015-08-20
2013-09-19
No

With 54 projects, a ridiculous amount of ming & mongo calls are executed on a profile page:

{
    "url": "/u/brondsem/profile/",
    "uptime": 1820,
    "call_counts": {
        "socket_write": 1,
        "jinja": 1,
        "mongo": 30396,
        "total": 1,
        "socket_read": 14,
        "ming": 1102
    },
    "request_category": "profile",
    "timings": {
        "mongo": 2618,
        "ming": 1328,
        "socket_write": 0,
        "socket_read": 93,
        "total": 4528,
        "jinja": 4478
    }
}

Discussion

1 2 > >> (Page 1 of 2)
  • Dave Brondsema

    Dave Brondsema - 2013-09-19

    If we end up needing a data structure to cache this, we may want to plan ahead for the possibility of sorting by project activity, registration date, etc.

     
  • Dave Brondsema

    Dave Brondsema - 2013-09-20
    • Size: --> 2
     
  • Dave Brondsema

    Dave Brondsema - 2013-09-20
    • Milestone: forge-oct-04 --> forge-oct-18
     
  • Dave Brondsema

    Dave Brondsema - 2013-10-04
    • Milestone: forge-oct-18 --> forge-nov-01
     
  • Dave Brondsema

    Dave Brondsema - 2013-10-21
    • Milestone: forge-nov-01 --> forge-nov-15
     
  • Dave Brondsema

    Dave Brondsema - 2013-11-01
    • Milestone: forge-nov-15 --> forge-nov-29
     
  • Dave Brondsema

    Dave Brondsema - 2013-11-15
    • Milestone: forge-nov-29 --> forge-dec-13
     
  • Dave Brondsema

    Dave Brondsema - 2013-11-15
    • Labels: performance --> performance, 42cc
    • Status: open --> in-progress
     
  • Dave Brondsema

    Dave Brondsema - 2013-12-03
    • Size: 2 --> 0
     
  • Dave Brondsema

    Dave Brondsema - 2013-12-13
    • Milestone: forge-dec-13 --> forge-dec-27
     
  • Dave Brondsema

    Dave Brondsema - 2014-01-02
    • Milestone: forge-dec-27 --> forge-jan-10
     
  • Anonymous - 2014-01-02

    Originally by: kharechko

    Hi. I have tried to reproduce the bug. Have created 50+ empty projects. Ping /u/root/profile/ but my numbers much less then yours:

    {"url": "/u/root/profile/", "uptime": 6,
     "call_counts": {"total": 1, "ming": 572, "jinja": 1, "mongo": 505}, "request_category": "profile",
     "timings": {"total": 1275, "ming": 342, "jinja": 991, "mongo": 178}}
    

    can you give more details? I am interested in type of queries to mongo. can you give me mongo profiling information?

    mongo shell> db.setProfilingLevel(0); db.system.profile.drop(); db.createCollection( "system.profile", { capped: true, size:4000000 } ); db.setProfilingLevel(2)
    bash> curl http://localhost:8080/u/root/profile/
    bash> mongodump -d allura -c system.profile
    
     
  • Dave Brondsema

    Dave Brondsema - 2014-01-02

    Here's updated profile data. I know we've made some tweaks recently to how the ming & mongo methods are counted to make them more accurate. I think the ming call counts are still about 2x actual so that timing is accurate. (That is, 2 ming methods for every 1 query).

    {"url": "/u/brondsem/profile/", "uptime": 482,
     "call_counts": {"total": 1, "sqlalchemy": 1, "ming": 1155, "jinja": 1, "mongo": 1993}, "request_category": "profile",
     "timings": {"total": 2787, "sqlalchemy": 2, "ming": 923, "jinja": 2698, "mongo": 1439}}}
    

    So those are closer to what you got, but still higher. This is from our production system so it'll take me some time to get more detailed data.

     
  • Anonymous - 2014-01-02

    Originally by: kharechko

    Please look to Allura/allura/ext/user_profile/templates/user_index.html

    {% for p in user.my_projects() %}                                       
      {% if h.has_access(p, 'read')() %}
          <li>      
              <a class="project-name" href="{{p.url()}}">{{p.name}}</a>       
          </li>
      {% endif %}
    {% endfor %}
    

    If user.my_projects() called, is it really necessary to check "if h.has_access(p, 'read')()". I have tried to removed this condition and number of mongo calls have decreased twice.

    with "if h.has_access(p, 'read')()":

    > db.system.profile.find({ns: 'allura.project_role'}).sort( { ts : -1 }).count()
    176
    > db.system.profile.find().sort( { ts : -1 }).count()
     263
    

    without "if h.has_access(p, 'read')()":

    > db.system.profile.find({ns: 'allura.project_role'}).sort( { ts : -1 }).count()
    66
    > db.system.profile.find().sort( { ts : -1 }).count()
    157
    
    [stats] {"url": "/u/root/profile", "uptime": 15, "call_counts": {"total": 1, "ming": 510, "jinja": 1, "mongo": 348}, "request_category": "profile", "timings": {"total": 1300, "ming": 345, "jinja": 996, "mongo": 129}}
    
    >
    
     

    Last edit: Anonymous 2015-06-28
  • Igor Bondarenko - 2014-01-03
    • status: in-progress --> code-review
     
  • Igor Bondarenko - 2014-01-03

    Closed #499. je/42cc_6677

    Removed has_access call, as Mykola described earlier. I don't think we need that, since my_projects() returns project for which user has a named role, and I doubt that named roles without read permissions is useful.

    If I'm wrong, and we do need that check, we still could reduce mongo call count implementing this check inside my_projects(), I think.

    Implemented fix cuts mongo calls count in half. If that's not enough we'll need mongo profiling information (as Mykola mentioned above) to investigate further.

     
  • Dave Brondsema

    Dave Brondsema - 2014-01-03
    • status: code-review --> in-progress
     
  • Dave Brondsema

    Dave Brondsema - 2014-01-03

    git blame on that line points to 4818583b and [#2235], which explains why that check is important: a project that has restricted 'read' access shouldn't be shown to a user (or anonymous visitor) that doesn't have that permission.

     

    Related

    Tickets: #2235

  • Dave Brondsema

    Dave Brondsema - 2014-01-10
    • Milestone: forge-jan-10 --> forge-backlog
     
  • Igor Bondarenko - 2014-01-30
    • status: in-progress --> code-review
     
  • Igor Bondarenko - 2014-01-30

    Closed #512. Force-pushed je/42cc_6677

    This change drops mongo call_counts from 376 to 74 on my test project. I don't sure about my_projects persmission checks, though. Look at it carefully, please.

     
  • Cory Johns - 2014-02-04

    Historically, a ProjectRole with an empty roles list was automatically created for a user when they viewed any given project. We've since optimized that to only upsert when explicitly needed, but just because there exists a ProjectRole for a given User / Project combination doesn't mean that user actually has any access to the project. Also, there could be no ProjectRole for a given user, but the project could allow *anonymous read, in which case it should be shown to the user.

    We could check to see if c.user == self to skip the has_access checks, but in most cases we're still going to need to call has_access. :-/

    The optimization to pull in all Projects at once instead of using role.project is good, and should be extended to my_projects_by_role_name. Also, since that is now a separate method to avoid the extra queries needed by the reaching logic, please also make the parameter non-optional.

     
  • Cory Johns - 2014-02-04
    • status: code-review --> open
     
  • Igor Bondarenko - 2014-02-12
    • status: open --> code-review
     
  • Igor Bondarenko - 2014-02-12

    Closed #532. Force-pushed je/42cc_6677

     
1 2 > >> (Page 1 of 2)

Log in to post a comment.