BugTask:+index timeout due to high cpu time rendering many bug tasks in bug 230350

[Robert Collins]

OOPS-1927B436
OOPS-1880F2434

Branch: launchpad-rev-12432
Revno: 12432
SQL time: 2582 ms
Non-sql time: 12602 ms
Total time: 15184 ms
Statement Count: 315

[William Grant (wgrant)]

OOPS-1962DU69 is a bit more modern. 5s gap between 59 and 60, and 59 should only have returned a single row.

[William Grant (wgrant)]

OOPS-1943DR70 shows the same thing.

[Gary Poster (gary)]

I did a kcachegrind profile of this. I was disappointed with its ability to accurately identify/show caller/callee relationships beyond a high level. I may look at the raw files more later. The profiles do seem to indicate that the cost is happening somewhere within pagetemplate rendering--which really could indicate really any number of causes, since I'm not able to drill down deep enough to know. KCacheGrind allows a maximum of 499 calls shown, which is not nearly enough, thanks at least in part to the page template code itself.

Next steps are to examine the DB records and see if I can find something unusual about this bug, perhaps on the basis of some of the queries before the 5s gap; and failing that to grope through the profile log itself.

[Gary Poster (gary)]

Looks like this bug has 159 bug tasks, associated with 158 unique source packages. That's the obvious problem, looking through the SQL, and there are no other candidates that I see. That rings a bell: I wonder if this is a dupe.

[Gary Poster (gary)]

bug 636158 seems to be the closest parallel. Fix Released. This looks like we need another increment of work on the problem.

[Robert Collins (lifeless)]

Data point: the last time I saw very high CPU it was due to storm
object comparisons:

if A == B, when A and B are storm objects (e.g. SQLBase derived) is
very expensive; any algorithm which involves a lot of such comparisons
will lead to high python time.

e.g. if A in something
-> fine if something is a dict or set
-> trouble if something is a list or tuple

-Rob

[Launchpad QA Bot (lpqabot)]

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

[Henning Eggers (henninge)]

QA note: The bugs from the OOPSes still time out on qastaging but then that is qastaging. We will have to wait until it hits production to know if the bug is actually fixed.

I verified that other bugs still display properly and that bugtasks are not expandable when there are 10 or more of them (many_bugtasks).

[Gary Poster (gary)]

As Henning notes, this seems to be an insufficient improvement. It's fine to go out to production, but this needs more analysis and work.

[Данило Шеган (danilo)]

I got it loaded on the first attempt today on production in 7.6s. Loading it with ++oops++ got me:

    At least 802 queries/external actions issued in 6.34 seconds OOPS-2050H26

[Launchpad QA Bot (lpqabot)]

r13772 in stable (http://bazaar.launchpad.net/~launchpad-pqm/launchpad/stable/revision/13772) is part of this bug's fix.

[Launchpad QA Bot (lpqabot)]

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

[William Grant (wgrant)]

Bad, but untagged revert in r13794.

[Launchpad QA Bot (lpqabot)]

r13820 in stable (http://bazaar.launchpad.net/~launchpad-pqm/launchpad/stable/revision/13820) is part of this bug's fix.

[Launchpad QA Bot (lpqabot)]

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

[Gary Poster (gary)]

I'm moving on. Note that this bug (230350) has many bug tasks, and many branches. As of this writing, it has about 50% more bugtasks than any other bug in Launchpad, and also the most branches.