200ms penalty in admin console when using django-azure-auth

[ahjulstad]

For some reason, requests to the admin console take 200ms longer (700ms vs 500ms) when the django-azure-auth middleware is enabled. This seems a bit excessive.

I have tried different session engines and caches, but no big change. I am using the middleware to protect all endpoints. My db is a postgres server which is a small distance away. Single queries take approx 40ms.

The performance numbers are measured on my laptop, using runserver to run django, but I haven't found any significant differences when running elsewhere.

django               5.0.6    A high-level Python web framework that encourages rapid development and clean, pragmatic design.
django-azure-auth    1.3.0    A simple Django app for user authentication with Azure Active Directory/Entra ID.
django-debug-toolbar 4.4.2    A configurable set of panels that display various debug information about the current request/response.
django-filter        24.2     Django-filter is a reusable Django application for allowing users to filter querysets dynamically.
djangorestframework  3.15.1   Web APIs for Django, made easy.

Some example profile extracts:

CALL    CUMTIME PER TOTTIME PER COUNT
- site-packages\debug_toolbar\panels/__init__.py in process_request(195)
0.593   0.593   0.000   0.000   1
    - site-packages\django\core\handlers/exception.py in inner(52)
0.593   0.593   0.000   0.000   1
        + site-packages\django\utils/deprecation.py in __call__(127)
0.593   0.085   0.000   0.000   1
        + site-packages\django\core\handlers/base.py in _get_response(174)
0.166   0.166   0.000   0.000   1
        - site-packages\azure_auth/middleware.py in __call__(12)
0.593   0.593   0.000   0.000   1
            + site-packages\django\utils/functional.py in inner(249)
0.272   0.272   0.000   0.000   1
            + site-packages\django\core\handlers/exception.py in inner(52)
0.166   0.166   0.000   0.000   1
            + site-packages\azure_auth/handlers.py in get_token_from_cache(69)
0.152   0.152   0.000   0.000   1

Get get_token_from_cache call appears 15 times in the profiler output from the django debug toolbar.

I am new to django, so apologies if I am missing something obvious. Pointers most welcome.

[regoawt]

Hi, thanks for the report.

Is this something that definitely only happens when interacting with the admin console, or that it is most noticeable when doing so?

[ahjulstad]

I experience similar behaviour also for API pages generated by django rest framework and 'normal' pages. On a very simple template render I get 500ms with the decorator @azure_auth_required and 330ms without. The SQL is three queries at 35ms each. It does not seem to matter if I use the middleware or the decorator.

It seems a lot of initialisation happens on every call. For example, by adding some debugging on the msal package, it does the outgoing network request at ..../.well-known/openid-configuration at every single call, which takes around 122 milliseconds.

I am looking at msal.authority, starting at line ~208.

def tenant_discovery(tenant_discovery_endpoint, http_client, **kwargs):
    starttime = time.time()
    print("requesting oidc discovery")
    # Returns Openid Configuration
    resp = http_client.get(tenant_discovery_endpoint, **kwargs)
    if resp.status_code == 200:
        print(f"oidc discovery request completed, {(time.time()-starttime) * 1000} milliseconds")
        return json.loads(resp.text)  # It could raise ValueError

[regoawt]

Thanks for the update. I would expect the added latency to be similar in calls to admin and non-admin authenticated pages, so that's good to know.

More generally, it seems you are correct that there is an unnecessary amount of latency added as a token is requested on each call. The ID token claims are saved on the session so I think it should just check the expiry of that first before calling out to Azure via MSAL. Thank you for pointing this out!

I'll record some baseline request profiles to validate that the change has (hopefully) improved the latency.

[regoawt]

@ahjulstad I've made a 1.4.1a0 prerelease which seems to have reduced request latency by around 200ms like you mentioned. Are you able to try it and see it has resolved the issue for you as well? I'll make a full release in a couple of days.

[ahjulstad]

Thank you. Yes, this seems to work. If it was possible to avoid the select from auth_user query on every access, it would trim of an additional 30ms (for me at least). Maybe there is a cache functionality that can be used.

SELECT …
  FROM "auth_user"
 WHERE "auth_user"."id" = 1
 LIMIT 21

---

The information contained in this message may be CONFIDENTIAL and is intended for the addressee only. Any unauthorized use, dissemination of the information or copying of this message is prohibited. If you are not the addressee, please notify the sender immediately by return e-mail and delete this message. Thank you

[regoawt]

Glad to hear it.

Re the query, I think that's probably because there's a request.user call in your code somewhere - maybe in a template?

[regoawt]

Resolved in release 1.4.1.