Some SQL queries make debug toolbar rendering very slow

[alkihis]

Hi, I recently migrated to the last version of django debug toolbar (3.1.1) and I experienced one major performance issue.

When a view makes a "huge" (in textual form) SQL request, rendering of toolbar is very, very slow.
The view takes around 1s to render, and the toolbar around 58-59s on my machine.

The problem is kind of solved by commenting stack.enable_grouping(), in function parse_sql of panels/sql/utils.py (line 34).

[EXAMPLE] This is the kind of request that's causing the problem:

SELECT ••• FROM "sample" LEFT OUTER JOIN "sample_parents" ON ("sample"."id" = "sample_parents"."from_sample_id") INNER JOIN "sample_parents" T4 ON ("sample"."id" = T4."to_sample_id") WHERE T4."from_sample_id" IN (856, 858, 860, 862, 900, 1154, 1155, 1156, [...more than 2K numbers...], 29583) GROUP BY ("sample_parents"."from_sample_id"), "sample"."id"

I know the problem is linked to sqlparse package, but disable grouping (or, make it as an option) doesn't make a big difference in results presentation.

Thank you!

Configuration:

• Python 3.7.9
• Django-debug-toolbar 3.1.1
• PostgreSQL 12
• sqlparse 0.4.1

[tim-schilling]

That seems reasonable. Would you mind creating a PR?

As an aside, you can improve your queries performance (and the toolbars) if you can adjust your Sample queryset such that the

to_sample_ids = list(Sample.objects.filter(some_filtering=values))
Sample.objects.filter(from_sample__to_sample__id__in=to_sample_ids)

To:

Sample.objects.filter(from_sample__to_sample__some_filtering=values)

PostgreSQL queries that use massive IN collections perform poorly. Converting the query to use a subquery that fetches those ids will significantly improve the performance of your query.

[alkihis]

Thanks for the quick reply!

I agree with your suggestion ; unfortunately, code that causing this kind of query is slightly more complicated than that, but I'm working on fixing it.

I've made a PR #1404 whose add a new setting in order to control behavior of SQL token grouping. It should be set to False when performance issues are encountered.

[federicobond]

I ran into this problem too. I worked on a patch that avoids parsing really long queries, and instead defaults to plaintext formatting. This solution would not require the user to be aware of the existence of a long query affecting the performance of the debug_toolbar beforehand.

Is this something you would be interested in?

[tim-schilling]

@federicobond Yes, but before you dive into that, please try #1438 (you'll need to install from source) to see if that resolves your issue.

[federicobond]

Yes, #1438 does fix the problem for me, at the expense of not prettifying every other SQL query.

The PRETTIFY_SQL setting works well as a temporary measure when you are already aware of this problem and debug_toolbar is just making it harder for you to continue work on your project, but not when you are left wondering what is causing your development environment to take >30s to render a view that loads just fine in production.

I propose we always do a "graceful degradation" to non-prettified queries for extremely long queries, so that debug_toolbar does not hinder but instead becomes a helpful tool in diagnosing the root cause problem.

[tim-schilling]

Ah, that's a good idea! If possible, it would be nice to add in a notice that it automatically made that decision for a specific query.

[AgarwalPragy]

Spent a good 4 hours today isolating this issue to django-debug-toolbar 😓
Any update on this?

[tim-schilling]

Unfortunately, no. @AgarwalPragy and @federicobond, do you know what the cutoff should be for determining a "large query" to use a non-prettified query?

[oliwarner]

Also spent a bizarre amount of time banging my head against the wall, at first just suffering with 3s long pageloads in dev and then trying to profile out the problem and finding what you've all found over a year ago.

This seems like a stupid problem to have. What's the resistance to doing something here?

We can't defer loading (without serious extra work storing request IDs, queries in session, etc), turning prettification off entirely is undesirable, and this halfway-house of a timeout fallback is still inefficient (not to mention that it's been stuck in purgatory for a year), so could we just send plaintext queries (and their language vendor) out in the response and prettify them client-side? Something like https://github.com/zeroturnaround/sql-formatter seems ideal.

Then it only impacts people opening the SQL tab.

[matthiask]

No resistance at all, it's just a matter of priorities.

I don't see any slowdown related to django-debug-toolbar even on sites with bad amounts of complicated SQL queries. Therefore it's not my itch to scratch.

(As you know nobody is paid to work on this.)

[edmenendez]

This is also impacting us. Turning off the SQL panel produces a 10x+ performance improvement in an admin page.

[matthiask]

@edmenendez Does switching of PRETTIFY_SQL help? Do you have a way of profiling this, to find out where most of the time is lost?

[edmenendez]

Setting PRETTIFY_SQL to False does not help. The only thing that helps is turning off the SQL panel. DDT tells me most of the extra time is being spent in the request. DDT Template Profile says almost all the extra time is in admin/change_list.html. @matthiask

[tim-schilling]

@edmenendez how many queries does that view generate?

[edmenendez]

~300, mostly small lookups. Another bit which might be useful to know, before upgrade from version 2.0, that same page performed fine. @tim-schilling

[danlamanna]

Cross linking #1752 which may have helped.

[tim-schilling]

This should be improved by #710