BugTask:+index timeout due to high cpu time rendering many bug tasks in bug 230350
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
| Launchpad itself |
Critical
|
Unassigned |
Bug Description
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
Related branches
- Jeroen T. Vermeulen (community): Approve on 2011-08-31
-
Diff: 173 lines (+87/-8)5 files modifiedlib/lp/bugs/browser/bugtask.py (+9/-4)
lib/lp/bugs/browser/tests/test_bugtask.py (+42/-0)
lib/lp/bugs/model/bug.py (+2/-2)
lib/lp/code/model/branchcollection.py (+11/-2)
lib/lp/code/model/tests/test_branchcollection.py (+23/-0)
description: | updated |
William Grant (wgrant) wrote : | #1 |
William Grant (wgrant) wrote : | #2 |
OOPS-1943DR70 shows the same thing.
Changed in launchpad: | |
assignee: | nobody → Gary Poster (gary) |
Gary Poster (gary) wrote : | #3 |
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) wrote : | #4 |
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.
summary: |
- BugTask:+index timeout due to high cpu time rendering bug 230350 + BugTask:+index timeout due to high cpu time rendering many bug tasks in + bug 230350 |
Gary Poster (gary) wrote : | #5 |
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) wrote : Re: [Bug 724025] Re: BugTask:+index timeout due to high cpu time rendering bug 230350 | #6 |
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
Changed in launchpad: | |
status: | Triaged → In Progress |
Launchpad QA Bot (lpqabot) wrote : | #7 |
Fixed in stable r13658 <http://
tags: | added: qa-needstesting |
Changed in launchpad: | |
status: | In Progress → Fix Committed |
Henning Eggers (henninge) wrote : | #8 |
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).
tags: |
added: qa-ok removed: qa-needstesting |
Gary Poster (gary) wrote : | #9 |
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.
Changed in launchpad: | |
status: | Fix Committed → In Progress |
Данило Шеган (danilo) wrote : | #10 |
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) wrote : | #11 |
r13772 in stable (http://
tags: |
added: qa-needstesting removed: qa-ok |
tags: |
added: qa-ok removed: qa-needstesting |
Launchpad QA Bot (lpqabot) wrote : | #12 |
Fixed in stable r13789 <http://
tags: |
added: qa-needstesting removed: qa-ok |
Changed in launchpad: | |
status: | In Progress → Fix Committed |
William Grant (wgrant) wrote : | #13 |
Bad, but untagged revert in r13794.
tags: |
added: qa-ok removed: qa-needstesting |
Changed in launchpad: | |
status: | Fix Committed → In Progress |
Launchpad QA Bot (lpqabot) wrote : | #14 |
r13820 in stable (http://
tags: |
added: qa-needstesting removed: qa-ok |
tags: |
added: qa-bad removed: qa-needstesting |
Launchpad QA Bot (lpqabot) wrote : | #15 |
Fixed in stable r13850 <http://
tags: |
added: qa-needstesting removed: qa-bad |
Changed in launchpad: | |
status: | In Progress → Fix Committed |
tags: |
added: qa-ok removed: qa-needstesting |
Changed in launchpad: | |
assignee: | Gary Poster (gary) → nobody |
status: | Fix Committed → Triaged |
Gary Poster (gary) wrote : | #16 |
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.
OOPS-1962DU69 is a bit more modern. 5s gap between 59 and 60, and 59 should only have returned a single row.