Where is all the time going?

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.