Where is all the time going?
Bernd Wechner
I'm a tad stuck with a slow performing form, like 30s to load,
totally studding, on a high specced local dev machine.
It's a generic CreateView, and the Django Toolbar reports this:
So pretty much all the time is under the timing attribute of "request".
I have real trouble reading the bar graph and understanding the meaning of the attributes and can't find documentation to help me.
I mean request takes apparently 26647ms in this example and loadEvent takes 3 yet they have bars of similar length under Timeline?
Moreover, where is the time actually going? I check the SQL calls on the toolbar and they report " 9.63 ms (5 queries including 2 duplicates )" though again I have no idea what duplicates are and where to find that documented, still it's under 10ms on queries.
So I installed django-extensions and run their profileserver with kcachegring output (because that's the easiest thing I could find to do really) and kcachegrind I find similarly hard to decipher, but what I can see is that it's not in my code ... here's a snapshot of the top consumers (kcachegrind only seems to present ticks not seconds which isn't helpful given no definition of tick, but it looks to be about a millisecond, and 20 seconds are spent in pprint.py)
Now I can't find any reference to pprint.py in my code alas, and would find it helpful if I could work out how it got there so often. I can show the callers in kcachegrind but the only thing coming close to my code is the as_table() method (and that's not wildly close).
I put explicit tracing into my code, with timestamps and while I
override get_context_data and get_query set in the view The
consume intoto an admittedly greed 0.25s, but contributing nothing
to 30s or so page load time.
Playing around in kcachegring with call trees this one looks suspicious:
The send path and _store_template_info lend a clue, so I checked
the Template on the Django Toolbar, and surprisingly indeed there
are 372 templates rendered, of which I am aware of a role in 2
(the base template and create template I'm using) and 370 seem to
be (with abundant spot checking) widgets.
This is relatively new, the form was not this slow until recently
but I've been a tad slow and slack with git commits so can't pull
a recent version up for meaning comparison.
I'll continue to drill down as best I can cutting my teeth at
this, but it seems difficult to divine whence this cometh and why
the time doesn't show up in my get_context_data method at all.
It's like Django is doing something after that to, by way of
widget creation, but it's not even clear this is where the 30
seconds are going and it may be a red herring.
Oh the frustrations ... and learning curve.
All insights gratefully received if there are any on such a vague
presentation (I mean this a form that includes three or so related
model forms (I add them in the context data) but each one only
renders like 5 or so fields and none are wildly big models, with
only a handful of fields.
Regards,
Bernd.
James Schneider
I'm a tad stuck with a slow performing form, like 30s to load, totally studding, on a high specced local dev machine.
It's a generic CreateView, and the Django Toolbar reports this:
Bernd Wechner
If you have the fortitude and kind heart to look at it, sure the code base (just checked in) is here:
https://github.com/bernd-wechner/CoGsit's the Create view on the Session model that is taking 30s to render, no other model, and that one is the central model of interest with a custom form that needs related model forms as well, to wit is a tad complex and I'm experimenting with keeping it as generic as I can for reuse later (DRY), though it is highly experimental and hacked up as I'm learning on the fly.
I'd harboured the slight hope that there might be some experience out there of a more general nature regarding a 30s render time on a simple form and where Django may be sinking all that time, but of course I do appreciate that specifics are always useful in diagnosis. Only that I'm not really expecting anyone to wade knee deep into the code there.
So to be specific the model in question is at line 694:
https://github.com/bernd-wechner/CoGs/blob/master/Leaderboards/models.pyThe view in question is at line 276:
https://github.com/bernd-wechner/CoGs/blob/master/Leaderboards/views.pywhich derives from line 589:
https://github.com/bernd-wechner/CoGs/blob/master/django_generic_view_extensions/__init__.pyand the template is at:
https://github.com/bernd-wechner/CoGs/blob/master/Leaderboards/templates/CoGs/form_data.htmlbut it's a work in progress and full of notes and TODOs and experiments, a learning context while constructing a tool of use ;-).
Really part of me is wondering mainly how from that view Django comes to spend so much time doing stuff and what and I find Kcachegrind a rather steep learning curve itself, so was fishing around for any pointers from experience as to likely causes.
I'm a little time poor so can't push it fast and hard anyhow, (if you look at the timeline on commits) and best clue I have as noted in first post, so far is that it's inside of Django at_store_template_info which has 17506 on it in the call tree which I am guessing might be a call count, and seems large and also it seems clear that pprint.py is the likely main consumer and so Django experience regarding where that is used by Django might be handy. I can drill down into the code base slowly too and will and am, but it's a big slog and learning curve. Hence curious if experienced eyes out there have any tips that might save me time I guess. Certainly don't expect anyone to get knee deep into my code base, though if anyone is willing, heck mentoring is always welcome - anyone above that would surprise me in a sense. I'd be appreciative no less, just not expecting it.
Kind regards,
Bernd.
James Schneider wrote:
--
You received this message because you are subscribed to the Google Groups "Django users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to django-users...@googlegroups.com.
To post to this group, send email to django...@googlegroups.com.
Visit this group at https://groups.google.com/group/django-users.
To view this discussion on the web visit https://groups.google.com/d/msgid/django-users/CA%2Be%2BciWJwNNc2h%3DDL9uiqtMCHfweavCnfnYUc3t2o8M%3D0Qj2-g%40mail.gmail.com.
For more options, visit https://groups.google.com/d/optout.
Thomas Lockhart
James,
If you have the fortitude and kind heart to look at it, sure the code base (just checked in) is here:
https://github.com/bernd-wechner/CoGsit's the Create view on the Session model that is taking 30s to render, no other model, and that one is the central model of interest with a custom form that needs related model forms as well, to wit is a tad complex and I'm experimenting with keeping it as generic as I can for reuse later (DRY), though it is highly experimental and hacked up as I'm learning on the fly.
hth
- Tom
Bernd Wechner
Had a similar thought and while it does have a few drop downs with tens of entries (because the dataset is only nascent and small) I:
- Am rather aghast if tens of entries in a few drop downs
generate 20s page load times so didn't think it a prime
suspect.
- Have the intention of implementing DAL
(Django-autocomplete-light) anyhow as these drop downs won't
be limited to tens, and can easily grow into hundreds and
thousands of options, so need a smarter combo box with some
AJAX (i.e. DAL) anyhow.
- Will likely experiment soon by moving drop-downs to text boxes and seeing if it improves In mean time any other ideas welcome.
Regards,
Bernd.Thomas Lockhart wrote:
--
You received this message because you are subscribed to the Google Groups "Django users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to django-users...@googlegroups.com.
To post to this group, send email to django...@googlegroups.com.
Visit this group at https://groups.google.com/group/django-users.
To view this discussion on the web visit https://groups.google.com/d/msgid/django-users/6759a167-50f9-2c01-b588-a963fd9ec24b%40gmail.com.
James Schneider
James,
If you have the fortitude and kind heart to look at it, sure the code base (just checked in) is here:
https://github.com/bernd-wechner/CoGs
- You didn't mention your specific Django version. If 1.11, try backing it off to 1.10, and if on 1.10, try upgrading to 1.11. The reason being is that there were some significant changes to the template rendering system in 1.11 that may be causing excessive calls.
- Determine how many objects and related objects you are dealing with during the slow page rendering. Your queries may be quick, but coercing a large number of objects into Django models and then coercing them again in to form elements may be problematic.
- Determine where the culprit code in the templates is (or if it is template rendering at fault). Try attaching the view to a blank template and see if you get the same result. If so, start adding pieces of the template back in until you find the problem area. The view/template in question renders several forms. Commenting them out may help track down which form is at fault. There could possibly be a circular dependency somewhere causing the form rendering process to go crazy as well (ie Session ties to League, Location, and Game, but League ties together Location and Game). Given the other optimizations for related models you've added, there might be a loop somewhere. This also feels a bit de-normalized.
- The pprint.py thing is really bugging me, as there shouldn't be any reason to ever call that. Might be useful to do an interactive debug to step through and see what is causing those calls, or if they are red herrings from the profiling process, etc.
Bernd Wechner
Thanks for the quick look, the tips and more. I am using Django 1.11 and given your notes a huge suspect because:
- This slow down is very recent
- very recently I upgraded to 1.11 specifically because I needed a subquery on one view
Onto your other suggestions, I will follow them through, but further notes:
- This is a CreateView that is rendering in 20s so there's no object data per se, except for the widgets for the related models (drop downs). But a quick check reveals (Just loading the page and waiting 20s for it arrive - nuts on a high specced dev machine with dev server and no load) it has 5 drop downs as following sizes:
- 1 value (hardly a drop down ;-)
- 3 values (also hardly a drop down)
- 39 values (a little more, but the day 39 objects slows a server down without surprise is, well in 1965 with punchcards ;-)
- 44 values (ditto)
- 44 values (same related model as previous one).
- I intend to move to DAL (django-autocomplete-light widgets
for these anyhow, because while those list sizes are small a
production site can go into hundreds, thousands, 10s of
thousands ... over time. And this page render time aside, drop
downs are just not practical ...
- pprint.py bugs me too, as I searched my code base for references in case I was using it but failed to find one. Which does not rule it out, just makes it unlikely at present. Yes, a good next step is to load pprint.py set a breakpoint in it, run and check the stack to see how I got there and why. If it's from my code, awesome, I can fix it ;-), if Django is going it, at least one step closer to understanding.
Regards,
Bernd
--
You received this message because you are subscribed to the Google Groups "Django users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to django-users...@googlegroups.com.
To post to this group, send email to django...@googlegroups.com.
Visit this group at https://groups.google.com/group/django-users.
To view this discussion on the web visit https://groups.google.com/d/msgid/django-users/CA%2Be%2BciXnuomTDLD61WEard8-a%3DSRQkZUkHYn6Y_m3UkWVV6w_g%40mail.gmail.com.
James Schneider
James,
Thanks for the quick look, the tips and more. I am using Django 1.11 and given your notes a huge suspect because:
Rolling back to 1.10 is an option for testing, but I need that subquery. I will see how much hassle it is to unwind to 1.10 and check the page render time on that one page.
- This slow down is very recent
- very recently I upgraded to 1.11 specifically because I needed a subquery on one view
Onto your other suggestions, I will follow them through, but further notes: