[PATCH] Tickets are slow with large amount of users and permissions

[ants.aasma@…]

TicketSystem.get_ticket_fields() implements an extremely inefficient algorithm to find users that have a certain permission (O(n²_users * perms_per_user_avg)). I have added a more efficient function to PermissionSystem that enables querying users having a specified permission directly. It correctly resolves group memberships and hierarchical permissions.

[ants.aasma@…]

Patch

[Christopher Lenz]

I'll look into this tomorrow. Candidate for being backported to 0.10-stable.

[ants.aasma@…]

Second version of the patch. Using the env.get_known_users() interface to get users.

[Christopher Lenz]

Slightly modified patch applied in [4625].

[Eli Carter]

This change did not account for the magic 'authenticated' group, causing the regression reported in #4630. See [5849]. We went back to a very inefficient solution, so we need to improve that.

[ants.aasma@…]

Adds support for the implicit group providers

[ants.aasma@…]

Diff against the previous implementation to highlight the changes.

[ants.aasma@…]

Attached a fix that accounts for the group providers. This would be a lot more efficient, if the group providers had an get_group_members method.

This isn't tested, because I don't have a test enviroment set up nor the time to do so. But I figured I'd get the code out there if anyone has.

[ants.aasma@…]

Already spotted an oops, line 168 in new should read:

                        implicit_groups[groupname] = set([username])

(missing list brackets from set construction)

[Christian Boos]

#8034 / #8212 are recent duplicates. Especially #8212 somewhat proving the "back to a very inefficient solution" part of comment:3…

I see there is a patch here that has been overlooked (attachment:get_users_with_permission.groupprovider_fix.patch​).

[Christian Boos]

The above patch fails on the regression test for #4630:

FAIL: Test for regression of http://trac.edgewall.org/ticket/4630 b
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\Workspace\src\trac\repos\0.11-stable\trac\ticket\tests\functional.py", line 941, in runTest
    self.assertEqual(users, ['admin', 'user'])
AssertionError: [u'a', u'i', u'd', u'admin', u'user', u'm', u'n'] != ['admin', 'user']

[fabien]

Hi, I also have the same problem with a setup using 1000 users. It's slow when "restrict_owner = true"…

I modified eventually_restrict_owner to not check for permissions (not needed for my config), and now it's much faster, but not as fast as without restrict_owner… Maybe it would help to cache users and permissions ?

[Chris Everest <ceverest@…>]

In regard to this ticket I am also seeing significant performance decreases using restrict_owner in combination with the PrivateTicket plugin and a large user base. The main cause of the performance hit is in perms.py.

IPermissionStore.get_user_permissions() is calling 'SELECT username,action FROM permission' against all users in the system. This has caused 1000's of database queries for each page request to display a single ticket.

I have added two levels of caching to reduce this performance issue and provided a patch. Pulling from existing cache logic in DefaultPermissionPolicy.check_permission() I created new cache logic in PermissionSystem.get_users_with_permission() and IPermissionStore.get_user_permissions().

The cache in IPermissionStore.get_user_permissions() is the more effective change as it limits the query 'SELECT username,action FROM permission' to one execution and uses the cached results for each additional check of that routine, per page request.

The cache in PermissionSystem.get_users_with_permission() is not activated as often, but will certianly avoid redundant calls to its subroutines/methods.

In each case, the cache variables are very small and should only survive a single page request, thus uncompromising any security or permissions.

[Chris Everest <ceverest@…>]

Add caching logic to perms.py

[Remy Blank]

#9184 was closed as a duplicate, and contains a patch to increase the permission cache duration.

[Ismael de Esteban <ismael@…>]

#9184 Makes a big improvement when you have many users and restrict_owner option.

We can consider to include that since it has make a big improvement in the instance I use.

[anonymous]

any solution to this huge problem?

[Christian Boos]

No.

(answer designed to be as useful as the question…)

For the longer run, see TracDev/Proposals/EvenFinerGrainedPermissions#Performance.

[osimons]

Helping out with a user on IRC, we've done some profiling of requests and looking into what actually takes time on a project with 1800 authenticated users (using the DefaultPermissionStore). In summary - all times should be seen as relative of course:

• ~2.5 seconds = restrict owner false
• ~63 seconds = restrict owner true
• ~14 seconds = restrict owner true, with caching full permissions table by a simple patch that just stores the table after first read and reuses it for any subsequent use (not for production use, but a test to see how much the SQL impacts times in a single process setting)
• ~40 seconds = restrict owner true, using @cached decorator on the get_all_permissions() output (+ invalidate code when granting or revoking permissions). This obviously re-introduces som SQL calls to handle cache status.

Having 1800 users requires creating 1800 permission caches and checking the permission against each one. It it bound to take time. 40 seconds is of course better than 63 seconds, but still too much work involved. 14 seconds would only be attainable if we used something like self.config.touch() to invalidate the cached permissions table across processes…

Further it may well be more useful to cache the actual list made by eventually_restrict_owner() and store it for each ticket. Then we'd need an IPermissionChangeListener interface so that others can listen in on changes and invalidate caches (#3302).

[peter@…]

Said user on IRC.

[osimons]

Replying to osimons:

Further it may well be more useful to cache the actual list made by eventually_restrict_owner() and store it for each ticket. Then we'd need an IPermissionChangeListener interface so that others can listen in on changes and invalidate caches (#3302).

No, that won't be good. Users can be added and removed from that list without an actual permission change - new users could register, sessions purged, or a security policy could change which users are approved. Anything really. So, bad idea.

[verm]

I hit this problem tonight.. I spent a couple of hours tracing it back using a 1GB tracefile from python -m trace -t tracd.. It was running 13,000 queries per ticket. This bumped it from taking ~14 seconds per ticket to instantaneous. I'm also running the ​FlexibleAssignTo plugin which requires restrict_owner to be true in order to work.

If there's a way to make this plugin work without restrict_owner being set then it'll be a great workaround.

[verm]

To be clear, I'm not asking for any support for the FlexibleAssignTo plugin I added it in case anyone else was interested in poking around.

[Remy Blank]

#10647 was closed as a duplicate.

[Peter Suter]

Use @cached decorator on get_all_permissions()

[Peter Suter]

Replying to osimons:

• ~2.5 seconds = restrict owner false
• ~63 seconds = restrict owner true
• ~40 seconds = restrict owner true, using @cached decorator

I think attachment:T4245-CachePermissionsTable.patch​ implements the same idea, right?

I tested this on a synthetic Trac environment with 2500 authenticated users, populated in cmd.exe by running this for 15 minutes or so:

for /L %i in (1,1,2500) do (
    trac-admin tracenv session add user%i
    trac-admin tracenv permission add user%i TICKET_MODIFY
)

• ~1 second = restrict owner false
• ~22 seconds = restrict owner true
• ~3 seconds = restrict owner true, using @cached decorator patch

Any idea why this quite a bit more effective in this synthetic case than in your (presumably real world) scenario?

[osimons]

Replying to psuter:

Replying to osimons:

• ~2.5 seconds = restrict owner false
• ~63 seconds = restrict owner true
• ~40 seconds = restrict owner true, using @cached decorator

I think attachment:T4245-CachePermissionsTable.patch​ implements the same idea, right?

Looks like it. Basically just caching the "SELECT username, action FROM permission" db query as your patch implements.

• ~1 second = restrict owner false
• ~22 seconds = restrict owner true
• ~3 seconds = restrict owner true, using @cached decorator patch

Any idea why this quite a bit more effective in this synthetic case than in your (presumably real world) scenario?

No idea. I can't find the details of the exchange anymore, and have no real knowledge of how the users system was configured, the plugins added, or the data it contained. Your known data is a better benchmark as I see it.

[peter@…]

Replying to osimons:

Replying to psuter:

Any idea why this quite a bit more effective in this synthetic case than in your (presumably real world) scenario?

No idea. I can't find the details of the exchange anymore, and have no real knowledge of how the users system was configured, the plugins added, or the data it contained. Your known data is a better benchmark as I see it.

Our exchange was on IRC, I still have the same system running, and I can do more testing if seriously required, although if I'm going to do Trac work right now I'd prefer to focus on the Git plugin. Thanks!

[Peter Suter]

Hearing about the effect of the patch on real data might be helpful.

Unless anyone can see a problem with the patch, we could also just apply it. I think it will help, it's just not clear how much.

[osimons]

My original caching patch - suspiciously similar, but uses a copy of the list instead.

[osimons]

I found my original patch, it is pretty much like yours - only it uses a copy of the result instead of returning it directly. I suppose that is a precaution that I need not have taken, and may also account for the relative difference in speed between the result sets?

See attachment:t4245-trac_cached_perm_rows-012-r10790.diff​

[Peter Suter]

Hm, one crucial thing that seems missing there is a change to the repeated query​ in DefaultPermissionStore.get_user_permissions(). Replace that with something like rows = self.get_all_permissions() and it performs just about the same in my test. (~3 seconds) Without that I don't see an improvement at all. (~22 seconds)

(Tested on trunk.)

[osimons]

Goodie. Then I see no reason not to commit what you have?

[Peter Suter]

Committed in [11032].

[Remy Blank]

Not sure if this would gain much, but you could even simplify the query:

    return [(username, action) for username, action in  
            self.env.db_query("SELECT username, action FROM permission")]

by substituting:

    return self.env.db_query("SELECT username, action FROM permission")

ConnectionWrapper.execute() (which is called by env.db_query()) already returns a list of all rows.

[Peter Suter]

attachment:profile.txt​ contains some ​a request profiling results. If I'm reading this right:

1. restrict_owner = true, no caching: ~70 seconds
2. restrict_owner = true, caching: ~2.2 seconds
3. restrict_owner = false: ~1 second

In case 1 time is mostly spent querying SQL in get_user_permissions, as we already knew. In both case 2 and 3 most time seems to be spent in Genshi. I'm not sure where the additional ~1.2 seconds in case 2 now come from. Possibly mostly from Genshi processing the 2500 user drop-down options?

Replying to rblank:

Not sure if this would gain much, but you could even simplify the query:

It makes virtually no difference (as this is cached?) but simplifying code is always good. :)

[osimons]

Out of curiosity, could you check the status of the Genshi speedups on your test setup? How do the numbers compare depending on speedups availability? Of primary interest is the ~2.2 seconds test, and as you say I also have a feeling much of the difference is added Genshi work.

See comment:7:ticket:10635 - and perhaps we'll see a 10% improvement here too?

[Peter Suter]

So far I was using Genshi 0.7dev-r1162 (without speedups). I appended a test run with speedups to attachment:profile.txt​. At ~2.1 seconds it's only a ~5% improvement.

[andrew.hardy@…]

Was this problem ever resolved? I seem to have a similar problem with Trac 0.12.

[Ryan J Ollos]

Moved ticket assigned to next-stable-1.0.x since maintenance of 1.0.x is coming to a close. Please move the ticket back if it's critical to fix on 1.0.x.

[Ryan J Ollos]

Milestone renamed