bouncer icon indicating copy to clipboard operation
bouncer copied to clipboard

Performance issues

Open ppisecky opened this issue 5 years ago • 17 comments

I'm wondering about the performance of Bouncer. Say you want to display a list of 50 items with 4 buttons each - view, edit, delete, force delete. I am currently dealing with a similar scenario and things are noticeably slow - thanks to bouncer it seems.

I have cross-request caching enabled by calling Bouncer::cache() in the boot method of a custom provider (with redis driver). I also call Bouncer after policy checks but I haven't implemented most of them and requests are already taking a bit too long.

I ran a little test in tinker: 196 pre-loaded models, check each for a single ability using a policy method that returns null. The check for these 196 items seems to take 1.7 seconds which, to me, seems like a lot given that I haven't written any conditional logic in my policies, no Controllers have been called or views rendered. Is this normal or have I likely misconfigured something? [RC5, Laravel 5.8]

image

Local homestead environment with XDebug enabled for an API request that fetches a list of 25 items: image

ppisecky avatar May 02 '19 03:05 ppisecky

  1. The first question to ask is whether cache is indeed enabled. Can you check to make sure that Bouncer is not hitting the DB for every check?

  2. The second question would be: do you see this slowdown only when using Bouncer, or do you get similar performance when using policies directly?

    Try return true/false from your policies directly. Do you see any major changes in performance?

JosephSilber avatar May 02 '19 03:05 JosephSilber

You can use barryvdh's debugbar. It has a lot of features for speedtesting, and other stuff as well. For example:

Debugbar::measure('My long operation', function() {
       // Do something…
});

https://github.com/barryvdh/laravel-debugbar

wbunthof avatar May 02 '19 14:05 wbunthof

  1. The first question to ask is whether cache is indeed enabled. Can you check to make sure that Bouncer is not hitting the DB for every check?

Well from what I understand Telescope can't capture Bouncer cache hits but Redis seems to have the bouncer data stored. As far as DB queries go I can't see any being executed that would relate to bouncer outside of one where I need to query the users roles (but that doesn't get called in the example below).

  1. The second question would be: do you see this slowdown only when using Bouncer, or do you get similar performance when using policies directly? Try return true/false from your policies directly. Do you see any major changes in performance?

So here is a tiny test where I check 25 orders for various rules. Delete and force delete both return false while update returns null from the policy method.

image

I've been thinking and one crucial detail that I have forgotten about is that for the role being checked (accountant) I have bound the update ability to their own orders only. The thing that might be problematic there is that different roles can own the order in different ways and at the time this seemed like the only way to set that up:

Bouncer::ownedVia(Order::class, function ($order, $user) {
    if ($user->isAn('account-manager') && $user->id == $order->assigned_user_id) {
        return true;
    }

    if ($user->isAn('accountant') && $user->id == $order->invoicing_user_id) {
        return true;
    }

    if ($user->isAn('salesperson') && $user->id == $order->sales_representative_id) {
        return true;
    }

    return false;
});

But from what I understand Bouncer caches role checks as well so that should not be a problem.

image

And while we're at it for order items (children of an order) I've implemented a similar logic - user is an owner if they own the order. And the parent order is (generally) eager loaded:

Bouncer::ownedVia(OrderItem::class, function ($order_item, $user) {
      return Bouncer::getClipboard()->isOwnedBy($user, $order_item->order);
});

But the example above was run on Orders directly. The output from clockwork profiler seems to indicate to me that attribute casting is what's taking the longest.

@woetroe0803 I'll try debugbar tomorrow because I've been setting up clockwork and blackfire yesterday and I don't want to go through that again right now.

EDIT: I've just verified that Redis is being queried by bouncer using redis-cli monitor

image

ppisecky avatar May 02 '19 16:05 ppisecky

Just to add more context: there are 101 abilities, 11 roles and 242 permissions in the tables. The accountant role has 45 permissions.

ppisecky avatar May 02 '19 21:05 ppisecky

@JosephSilber So from what I can gather from the source code it seems like every time an ability check is run the CachedClipboard loads the the user's abilities from the cache which means they have to be deserialized. Doing this 130 times is, in my estimation, what impacts the performance. The way I figure I can get around this is to not only enable cross request cache-ing, but also keep the abilities / roles in memory for the request duration. In my case ability checks only ever really run for the authenticated user using the app so this shouldn't clog the memory.

To achieve this I've created a custom clipboard that overrides the CachedClipboard:

<?php
namespace App\Overrides;

use Silber\Bouncer\CachedClipboard;
use Illuminate\Database\Eloquent\Model;

class AdvancedCachedClipboard extends CachedClipboard {

    protected $abilities = array();
    protected $roles = array();

    /**
     * Get the given authority's abilities.
     *
     * @param  \Illuminate\Database\Eloquent\Model  $authority
     * @param  bool  $allowed
     * @return \Illuminate\Database\Eloquent\Collection
     */
    public function getAbilities(Model $authority, $allowed = true)
    {
        $key = $this->getCacheKey($authority, 'abilities', $allowed);

        if (!isset($this->abilities[$key])) {
            $this->abilities[$key] = parent::getAbilities($authority, $allowed);
        }

        return $this->abilities[$key];
    }
    
    /**
     * Get the given authority's roles.
     *
     * @param  \Illuminate\Database\Eloquent\Model  $authority
     * @return \Illuminate\Support\Collection
     */
    public function getRoles(Model $authority)
    {
        $key = $this->getCacheKey($authority, 'roles');

        if (!isset($this->roles[$key])) {
            $this->roles[$key] = parent::getRoles($authority);
        }

        return $this->roles[$key];
    }

    /**
     * Clear the cache.
     *
     * @param  null|\Illuminate\Database\Eloquent\Model  $authority
     * @return $this
     */
    public function refresh($authority = null)
    {
        parent::refresh($authority);

        if (is_null($authority)) {
            $this->abilities = array();
            $this->roles = array();
        }

        return $this;
    }

    /**
     * Clear the cache for the given authority.
     *
     * @param  \Illuminate\Database\Eloquent\Model  $authority
     * @return $this
     */
    public function refreshFor(Model $authority)
    {
        parent::refreshFor($authority);

        unset($this->abilities[$this->getCacheKey($authority, 'abilities', true)]);
        unset($this->abilities[$this->getCacheKey($authority, 'abilities', false)]);
        unset($this->roles[$this->getCacheKey($authority, 'roles')]);

        return $this;
    }
}

And then in my service provider I just swap the clipboard instance during registration.

/**
 * Swap the clipboard used by bouncer.
 *
 * @return void
 */
public function register()
{
    Bouncer::setClipboard(new AdvancedCachedClipboard(new ArrayStore));
}

And the boot method later replaces ArrayStore with redis cache using Bouncer::cache().

This does seem to provide a decent performance boost. Does it seem like a reasonable approach to you?

ppisecky avatar May 07 '19 12:05 ppisecky

I can confirm this increases my performance as well. A request that took 10s now takes 2.5s.

ipontt avatar May 14 '19 21:05 ipontt

@JosephSilber and maybe others. So I had some time to think about this a bit more and here is another improvement that I discovered but it is mostly related to Laravel Models.

With the Cliboard optimization above a request to a resource index where I needed to check multiple permissions took on average about 2.7 seconds (out of 7 calls, local env.).

I looked again at the profiling results (sample is in my original post) and I've tried to determine why methods like getCasts, getCastType, getAttributeValue etc. are being called so often. It seems like in order to get Model attributes Laravel uses the getAttribute function each time the attribute is read. Within this call Laravel checks every single time to see if the attribute has to be cast and then it casts the raw value every time. In my case when loading the resource index mentioned above I hit around 300+ gates which results it this method being called more than 17000 times (ran out of memory when counting).

Because it seems like it is mostly just the id and identifier that is ever read from the ability I've decided to extend the Ability model in the following way.

<?php

namespace App\Models;

use Silber\Bouncer\Database\Ability as BouncerAbility;

class Ability extends BouncerAbility
{
    protected $attributeCache = [];

    public function getAttribute($key)
    {
        if (!isset($this->attributeCache[$key])) {
            $this->attributeCache[$key] = parent::getAttribute($key);
        }

        return $this->attributeCache[$key];
    }

    public function setAttribute($key, $value)
    {
        if (isset($this->attributeCache[$key])) {
            unset($this->attributeCache[$key]);
        }

        return parent::setAttribute($key, $value);
    }
}

The purpose is to reduce the amount of casting and other nested calls that occur. With these changes in place I now get a response time of 1.7 seconds in local env for the same resource index (7 attempts again, same resource pages).

I think this needs some further considerations because part of the getAttribute call that happens in the Illuminate\Database\Eloquent\Concerns\HasAttributes trait also checks if the request attribute is a relation and if it hasn't been loaded it does so. But for the time being it seems to fit my use case. Here's the relevant framework implementation:

/**
     * Get an attribute from the model.
     *
     * @param  string  $key
     * @return mixed
     */
    public function getAttribute($key)
    {
        if (! $key) {
            return;
        }

        // If the attribute exists in the attribute array or has a "get" mutator we will
        // get the attribute's value. Otherwise, we will proceed as if the developers
        // are asking for a relationship's value. This covers both types of values.
        if (array_key_exists($key, $this->attributes) ||
            $this->hasGetMutator($key)) {
            return $this->getAttributeValue($key);
        }

        // Here we will determine if the model base class itself contains this given key
        // since we don't want to treat any of those methods as relationships because
        // they are all intended as helper methods and none of these are relations.
        if (method_exists(self::class, $key)) {
            return;
        }

        return $this->getRelationValue($key);
    }

EDIT: Obviously in order to avoid undesired effects a second check could be added to both functions to only cache specific attributes .. && in_array($key, ['id', 'identifier'].

ppisecky avatar Jul 24 '19 17:07 ppisecky

Bouncer v1.0.0-rc.6 Laravel v5.5.40 PHP 7.1.24 Collecting abilities directly from models instead of pluck collection speeds up my app 2 times when everything is cached (0.67s vs 1.35s). @JosephSilber please check possibility to add it to next release

protected function findMatchingAbility($abilities, $applicable, $model, $authority)
{
    $abilitiesMap = collect();
    /** @var Ability $ability */
    foreach ($abilities->all() as $ability) {
        $abilitiesMap->put($ability->getAttributeValue('id'), $ability->getIdentifierAttribute());
    }

    if ($id = $this->getMatchedAbilityId($abilitiesMap, $applicable)) {
        return $id;
    }

    if ($this->isOwnedBy($authority, $model)) {
        return $this->getMatchedAbilityId(
            $abilitiesMap,
            $applicable->map(function ($identifier) {
                return $identifier.'-owned';
            })
        );
    }
}

net53 avatar Sep 05 '19 10:09 net53

I don't know if this belongs here, but while checking our application for performance with the debug bar, I found out that on unprivileged users a huge amount of eloquent models get hydrated.

pageload on privileged user (allowed everything) grafik

pageload on unprivileged user (allowed some abilities, some forbidden abilities) grafik

on events you see that there are ~4300 more events and these are all eloquent.retrieved App\Ability. We got 336 abilities on that system and 36 Gate checks on this page (which is the highest amount we got). If there are fewer gate checks the amount is of course smaller but always around factor 10.

UPDATE: After fixing another problem that caused long page loads, this turns out to be responsible for roughly 0.2s and 5mb more memory. So not as critical as I thought. But is this expected/wanted behaviour?

cschra avatar Jan 27 '20 09:01 cschra

@JosephSilber Chiming in here, we have a similar issue. On a simple page where we check one ability ($this->authorize('view-admin-dashboard');), it runs 2 (almost duplicate) queries (one for checking the forbidden abilities and another for the allowed) and hydrates 120 Ability models. On more complex pages, it runs hundreds of queries and hydrates several hundreds of thousands ability models.

Started debugging this, but unsure where to look. If we check one ability, shouldn't it do a query to find the ability and check if the user is allowed to do it? Currently, it fetches all abilities for all the user's rules, I think.

sebastiaanluca avatar Nov 22 '20 18:11 sebastiaanluca

Bouncer loads all of the user's abilities, and caches them (either for the current request, or for all subsequent requests). This is useful for pages that do multiple checks on a single page, so that we don't have to go back to the DB constantly.

If:

  1. You don't want to use cross-request caching, and...
  2. You're not doing multiple auth checks on a single page, and...
  3. You have many abilities for a single user...

...then you may wish to completely disable the cache:

Bouncer::dontCache();

With this setting, only the specific abilities required for the current auth heck will be loaded from the DB.

JosephSilber avatar Nov 23 '20 17:11 JosephSilber

Thanks for getting back to me so quickly, @JosephSilber!

We did the checks with both cache on (our default setting) and cache off, but didn't notice any difference. When cross-request caching is on, it performs the 2 queries once and caches it for the next requests. It loads 120 Ability models. With caching off, it performs the (AFAIK same) 2 queries on each page visit, plus it loads 120 Ability models. It does this for one authorization/ability check on a nearly empty page/layout and controller (to rule out any other interference). On more complex pages, the loaded models count is through the roof 😄

I thought this was standard behavior, but since you say it should only fetch the one ability from the database when not caching, I'm assuming we're doing something wrong?

This is our auth service provider setup for Bouncer:

public function boot(): void
{
    $this->bouncer()->useUserModel(User::class);
    $this->bouncer()->runAfterPolicies();
    $this->bouncer()->cache();
}

private function bouncer(): Bouncer
{
    return app(Bouncer::class);
}

We're on the latest version of both Laravel and Bouncer.

Query 1

select * from `abilities` where (exists (select * from `roles` inner join `permissions` on `roles`.`id` = `permissions`.`entity_id` where `permissions`.`ability_id` = `abilities`.`id` and `permissions`.`forbidden` = 1 and `permissions`.`entity_type` = 'roles' and (exists (select * from `users` inner join `assigned_roles` on `users`.`id` = `assigned_roles`.`entity_id` where `assigned_roles`.`role_id` = `roles`.`id` and `assigned_roles`.`entity_type` = 'user' and `users`.`id` = 1993))) or exists (select * from `users` inner join `permissions` on `users`.`id` = `permissions`.`entity_id` where `permissions`.`ability_id` = `abilities`.`id` and `permissions`.`forbidden` = 1 and `permissions`.`entity_type` = 'user' and `users`.`id` = 1993) or exists (select * from `permissions` where `permissions`.`ability_id` = `abilities`.`id` and `permissions`.`forbidden` = 1 and `entity_id` is null))
    0. 1
    1. roles
    2. user
    3. 1993
    4. 1
    5. user
    6. 1993
    7. 1
Query 2

select * from `abilities` where (exists (select * from `roles` inner join `permissions` on `roles`.`id` = `permissions`.`entity_id` where `permissions`.`ability_id` = `abilities`.`id` and `permissions`.`forbidden` = 0 and `permissions`.`entity_type` = 'roles' and (exists (select * from `users` inner join `assigned_roles` on `users`.`id` = `assigned_roles`.`entity_id` where `assigned_roles`.`role_id` = `roles`.`id` and `assigned_roles`.`entity_type` = 'user' and `users`.`id` = 1993) or `level` < (select max(level) from `roles` where exists (select * from `users` inner join `assigned_roles` on `users`.`id` = `assigned_roles`.`entity_id` where `assigned_roles`.`role_id` = `roles`.`id` and `assigned_roles`.`entity_type` = 'user' and `users`.`id` = 1993)))) or exists (select * from `users` inner join `permissions` on `users`.`id` = `permissions`.`entity_id` where `permissions`.`ability_id` = `abilities`.`id` and `permissions`.`forbidden` = 0 and `permissions`.`entity_type` = 'user' and `users`.`id` = 1993) or exists (select * from `permissions` where `permissions`.`ability_id` = `abilities`.`id` and `permissions`.`forbidden` = 0 and `entity_id` is null))
    0. 0
    1. roles
    2. user
    3. 1993
    4. user
    5. 1993
    6. 0
    7. user
    8. 1993
    9. 0

sebastiaanluca avatar Nov 23 '20 17:11 sebastiaanluca

To help you see this for yourself, I created a demo repo with the most minimalist setup.

Look at the atomic commits, and check out the readme on how to run it yourself.


With caching off, it performs the (AFAIK same) 2 queries on each page visit, plus it loads 120 Ability models

It does not. With caching off, it performs these 2 queries:

  1. Making sure there's no forbidding ability:

    select exists(
        select *
        from `abilities`
        where (
            exists (
                select *
                from `roles`
                inner join `permissions`
                    on `roles`.`id` = `permissions`.`entity_id`
                    where `permissions`.`ability_id` = `abilities`.`id`
                    and `permissions`.`forbidden` = 1
                    and `permissions`.`entity_type` = 'roles'
                    and (
                        exists (
                            select *
                            from `users`
                            inner join `assigned_roles`
                                on `users`.`id` = `assigned_roles`.`entity_id`
                                where `assigned_roles`.`role_id` = `roles`.`id`
                                and `assigned_roles`.`entity_type` = 'App\\Models\\User'
                                and `users`.`id` = 1
                            )
                    )
            )
            or exists (
                select *
                from `users`
                inner join `permissions`
                    on `users`.`id` = `permissions`.`entity_id`
                    where `permissions`.`ability_id` = `abilities`.`id`
                    and `permissions`.`forbidden` = 1
                    and `permissions`.`entity_type` = 'App\\Models\\User'
                    and `users`.`id` = 1
            )
            or exists (
                select *
                from `permissions`
                where `permissions`.`ability_id` = `abilities`.`id`
                and `permissions`.`forbidden` = 1
                and `entity_id` is null
            )
        )
        and `only_owned` = 0
        and (
            `name` = 'whatever'
            and `entity_type` is null
            or (
                `name` = '*'
                and (
                    `entity_type` is null
                    or `entity_type` = '*'
                )
            )
        )
    ) as `exists`
    

    As you can see, this query loads no abilities at all.

  2. Getting the permitting ability:

    select *
    from `abilities`
    where (
        exists (
            select *
            from `roles` inner join `permissions`
            on `roles`.`id` = `permissions`.`entity_id`
            where `permissions`.`ability_id` = `abilities`.`id`
            and `permissions`.`forbidden` = 0
            and `permissions`.`entity_type` = 'roles'
            and (
                exists (
                    select *
                    from `users`
                    inner join `assigned_roles`
                        on `users`.`id` = `assigned_roles`.`entity_id`
                        where `assigned_roles`.`role_id` = `roles`.`id`
                        and `assigned_roles`.`entity_type` = 'App\\Models\\User'
                        and `users`.`id` = 1
                )
                or `level` < (
                    select max(level)
                    from `roles`
                    where exists (
                        select *
                        from `users` inner join `assigned_roles`
                            on `users`.`id` = `assigned_roles`.`entity_id`
                            where `assigned_roles`.`role_id` = `roles`.`id`
                            and `assigned_roles`.`entity_type` = 'App\\Models\\User'
                            and `users`.`id` = 1
                    )
                )
            )
        )
        or exists (
            select *
            from `users`
            inner join `permissions`
                on `users`.`id` = `permissions`.`entity_id`
                where `permissions`.`ability_id` = `abilities`.`id`
                and `permissions`.`forbidden` = 0
                and `permissions`.`entity_type` = 'App\\Models\\User'
                and `users`.`id` = 1
        )
        or exists (
            select *
            from `permissions`
            where `permissions`.`ability_id` = `abilities`.`id`
            and `permissions`.`forbidden` = 0
            and `entity_id` is null
        )
    )
    and `only_owned` = 0
    and (
        `name` = 'whatever'
        and `entity_type` is null
        or (
            `name` = '*'
            and (
                `entity_type` is null
                or `entity_type` = '*'
            )
        )
    ) limit 1
    

    As you can see, this query only loads a single ability model.

JosephSilber avatar Nov 29 '20 19:11 JosephSilber

Thank you for going out of your way to set this up, I appreciate it. I'll do a proper debug later on to see what's going on and let you know the results.

sebastiaanluca avatar Nov 30 '20 11:11 sebastiaanluca

class AdvancedCachedClipboard extends CachedClipboard {

This saved about 400 Ability model hydrations on our largest index list page (100 records, each checking if the user can view/edit/delete/view a subitem). Only about 30ms total, but every bit helps. Thanks!

briano-jabico avatar Dec 03 '20 07:12 briano-jabico

I feel like this needs to be mentioned as a "gotcha" of sorts. I wasn't aware Bouncer was deserialising and rehydrating every ability model whenever you checked an ability. This can lead to pretty bad performance in certain circumstances.

jasonlewis avatar Jan 13 '21 05:01 jasonlewis

class AdvancedCachedClipboard extends CachedClipboard {

Also to chime in on this one - the above extension of the CachedClipboard gave us a very noticeable boost in performance, so thanks for that suggestion. The proposed thread-caching solution seems to be equal on memory usage but overall much more efficient in performance due to the reduced model counts. Here's the difference that change has made on one of our pages, using a user with a relatively small subset of abilities compared with the average user of our platform:

CleanShot 2024-02-26 at 11 56 23

(we have a LOT of bouncer checks running within a single request!)

Nutickets avatar Feb 26 '24 12:02 Nutickets