Distribution:+assignments is taking a long time maybe 20% of the time

This is now down to 76 queries and 13 seconds : not brilliant, but we have some breathing room.

Fixed in stable r11483 <http://bazaar.launchpad.net/~launchpad-pqm/launchpad/stable/revision/11483>.

Updated staging oops: https://lp-oops.canonical.com/oops.py/?oopsid=OOPS-1707S287

https://staging.launchpad.net/ubuntu/+assignments

SQL time: 875 ms
Non-sql time: 12600 ms
Total time: 13475 ms
Statement Count: 20

The sql overhead is Not-A-Problem now, so we need to get a kcachegrind profile and see whats going on.

(Unless, of course, its in the incremental fetches which we don't yet profile - see 'oops may be underrepresenting sql time'.

Just used Gary's shiny new ++profile++show,log on this.

16 seconds are spent in _load_objects_storm in 30K calls : we're pulling 30K full objects out of the DB, which is moderately high. The page was killed at 25 seconds by doing a query.

3000 calls to _load_objects
3000 to load_objects
30K to _load_object
  4.5 K to add_to_alive (3.5%)
  4.5K to get_object_info (20%)
  11K to set_values (42%)

One possibility is that the 'for value in values' check for non-null rows is expensive.

Another possibility is that that is cheap and what we're seeing is mainly coming from the other cases - given the set_values case should run always when we get past the null-row check, we can say that 65% of the time is dealing with found objects, and nearly 30% ?! inline or dealing with NULL objects. Looks like we should be able to short circuit the NULL check by looking at the primary key: if those rows are NULL, the whole thing is NULL.

We also may be pulling too much data back still; am going to recheck the previous query and make sure its not returning too many rows. That wouldn't alter the efficiency of the storm code but it would mean we're overworking it.

The query returns 3000 rows; for all specifications in Ubuntu ever, thats not unreasonable. A quick check shows they are not duplicated.

The 30K objects come from this:
3000 rows
10 classes per row (spec, (person, email, address):drafter, (person, email, address):approver (person, email, address):assignee)

So, making storm more efficient here is probably a big win, but fairly hard to do. One thing we can do is tune the preloading stuff to not load the objects, just the ids - enough to be sure its sufficient. I'll start on this now, and separately file a bug on storm about efficient in load_object.

https://lp-oops.canonical.com/oops.py/?oopsid=1711S6 the oops (ignore the totals on the left, that was a temporary bug, fixed in edge, not deployed on staging yet). The log lines are correct though.

I tried changing this to a 2-query form.

https://lp-oops.canonical.com/oops.py/?oopsid=OOPS-1711S60 is an example of the result.

In a different oops (-59) it does execute both queries, and we could see that on the SQL side it is slower (2 seconds vs 800ms) and on the python side it is /slightly/ faster.

In thie linked oops, (ignore the SQL time: 1001297 ms, Non-sql time: -981318 ms) figures - they are due to the sentinel showing the non-run query at the end - there is a clear 12 second gap between:
 - the execute returning to storm
 - the query for Person being executed.

So parsing the 3000 narrower rows(Specification only) took 12 seconds (including pulling out their related people IDs and building the next query) under the profiler (vs 16 for the very fat rows). This suggests a storm bug to me and I'm going to follow up on the storm bug I filed as a result of the first profile.

the patch - http://paste.ubuntu.com/489589/ - applies to db-stable cleanly. Or my lp:~lifeless/launchpad/bug-618367 branch.

So this page grows indefinitely, but its not really valuable to look at all releases at once. I'm going to exercise my new found batching skillz to batch it in 500 row blocks.

Fixed in stable r11558 <http://bazaar.launchpad.net/~launchpad-pqm/launchpad/stable/revision/11558>.

Verified on edge.