search

orf / django-debug-toolbar-template-timings

A django-debug-toolbar panel that displays template rendering times for your Django application
https://pypi.python.org/pypi/django-debug-toolbar-template-timings
MIT License
296 stars 28 forks source link

Sum of Query Duration lines on Template Timings panel vs. total ms on SQL panel? #13

Closed npinchot closed 10 years ago

npinchot commented 11 years ago

I'm not sure what the measurement criteria differences are between the sum of the Query Duration lines on the Template Timings panel and the total query ms on the SQL panel. As I understood it, the SQL panel shows the total query execution time (round trip database time).

On the example screenshot, and in my testing, I'm seeing the sum of the Query Duration lines to be greater than the total query ms on the SQL panel. For example, I have a django admin page that shows 124.43 ms total query time, and has two Query Duration lines (73.951 ms and 223.318 ms) that total 297.269 ms. Just to be clear, I'm not saying either is incorrect, I'm just curious as to why the difference? What is Query Duration measuring (and if you're familiar, what is the query ms on the SQL toolbar measuring)?

orf commented 11 years ago

I see that as well, I'm not too sure why. The template-timings panel uses very similar code to the SQL panel, however the template-timings panel only takes into account SQL that is executed during template rendering, other queries that are used inside views/middleware are not taken into account. That would mean the SQL panel time > template-timings panel time, but that doesn't seem to be the case. I will investigate more later today.

orf commented 11 years ago

I've managed to track this down. The library copies the SQL panels method of logging queries (replacing BaseDatabaseWrapper.cursor), however it appears that both the SQL panel and template-timings hooking into this causes queries to get executed twice, the hook (in most cases the SQL one) gets the correct query time and the second hook (template-timings) gets a greatly inflated query time including result processing overhead.

I've fixed this by hooking the SQLPanels report function instead, meaning it wont work unless the SQL panel is enabled. Thanks for the report, I will update the library on PyPi soonish.

Edit: That being said, I don't know if the SQL percentage is worth keeping now, perhaps the actual query duration (including creating model instances) would be a more valuable insight?