Timeout accessing bugs' attachments using the API

[Ursula Junque]

OOPS-1686A1008

https://api.launchpad.net/1.0/bugs/426116/attachments

SQL time: 11116 ms
Non-sql time: 5957 ms
Total time: 17073 ms
Statement Count: 658

Individual statements are fastish.

These four appear to be repeated per-attachment (or something: 142 repeats!)
1 142 3217 22 3195 launchpad-main-master SELECT Message.datecreated, Message.id, Message.owner, Message.parent, Message.raw, Message.rfc822msgid, Message.subject, "_prejoin1".account, "_prejoin1".creation_comment, "_prejoin1".creation_rationale, "_prejoin1".datecreated, "_prejoin1".defaultmembershipperiod, "_prejoin1".defaultrenewalperiod, "_prejoin1".displayname, "_prejoin1".hide_email_addresses, "_prejoin1".homepage_content, "_prejoin1".icon, "_prejoin1".id, "_prejoin1".logo, "_prejoin1".mailing_list_auto_subscribe_policy, "_prejoin1".merged, "_prejoin1".mugshot, "_prejoin1".name, "_prejoin1".personal_standing, "_prejoin1".personal_standing_reason, "_prejoin1".registrant, "_prejoin1".renewal_policy, "_prejoin1".subscriptionpolicy, "_prejoin1".teamdescription, "_prejoin1".teamowner, "_prejoin1".verbose_bugnotifications, "_prejoin1".visibility FROM BugMessage, Message LEFT JOIN Person AS "_prejoin1" ON Message.owner = "_prejoin1".id WHERE BugMessage.bug = %s AND Message.id = BugMessage.message AND (1=1) ORDER BY Message.datecreated, Message.id
2 142 2798 19 2779 launchpad-main-master SELECT BugTask.assignee, BugTask.bug, BugTask.bugwatch, BugTask.date_assigned, BugTask.date_closed, BugTask.date_confirmed, BugTask.date_fix_committed, BugTask.date_fix_released, BugTask.date_incomplete, BugTask.date_inprogress, BugTask.date_left_closed, BugTask.date_left_new, BugTask.date_triaged, BugTask.datecreated, BugTask.distribution, BugTask.distroseries, BugTask.id, BugTask.importance, BugTask.milestone, BugTask.owner, BugTask.product, BugTask.productseries, BugTask.sourcepackagename, BugTask.status, BugTask.statusexplanation, BugTask.targetnamecache, "_prejoin1".account, "_prejoin1".creation_comment, "_prejoin1".creation_rationale, "_prejoin1".datecreated, "_prejoin1".defaultmembershipperiod, "_prejoin1".defaultrenewalperiod, "_prejoin1".displayname, "_prejoin1".hide_email_addresses, "_prejoin1".homepage_content, "_prejoin1".icon, "_prejoin1".id, "_prejoin1".logo, "_prejoin1".mailing_list_auto_subscribe_policy, "_prejoin1".merged, "_prejoin1".mugshot, "_prejoin1".name, "_prejoin1".personal_standing, "_prejoin1".personal_standing_reason, "_prejoin1".registrant, "_prejoin1".renewal_policy, "_prejoin1".subscriptionpolicy, "_prejoin1".teamdescription, "_prejoin1".teamowner, "_prejoin1".verbose_bugnotifications, "_prejoin1".visibility, "_prejoin2".owner, "_prejoin2".active, "_prejoin2".answers_usage, "_prejoin2".autoupdate, "_prejoin2".blueprints_usage, "_prejoin2".bug_reported_acknowledgement, "_prejoin2".bug_reporting_guidelines, "_prejoin2".bug_supervisor, "_prejoin2".bugtracker, "_prejoin2".date_next_suggest_packaging, "_prejoin2".datecreated, "_prejoin2".description, "_prejoin2".development_focus, "_prejoin2".displayname, "_prejoin2".downloadurl, "_prejoin2".driver, "_prejoin2".enable_bug_expiration, "_prejoin2".freshmeatproject, "_prejoin2".homepage_content, "_prejoin2".homepageurl, "_prejoin2".icon, "_prejoin2".id, "_prejoin2".lastdoap, "_prejoin2".license_approved, "_prejoin2".license_info, "_prejoin2".reviewed, "_prejoin2".logo, "_prejoin2".max_bug_heat, "_prejoin2".mugshot, "_prejoin2".name, "_prejoin2".official_answers, "_prejoin2".official_blueprints, "_prejoin2".official_malone, "_prejoin2".official_rosetta, "_prejoin2".private_bugs, "_prejoin2".programminglang, "_prejoin2".project, "_prejoin2".registrant, "_prejoin2".remote_product, "_prejoin2".reviewer_whiteboard, "_prejoin2".screenshotsurl, "_prejoin2".security_contact, "_prejoin2".sourceforgeproject, "_prejoin2".summary, "_prejoin2".title, "_prejoin2".translation_focus, "_prejoin2".translationgroup, "_prejoin2".translationpermission, "_prejoin2".translations_usage, "_prejoin2".wikiurl, "_prejoin3".id, "_prejoin3".name, "_prejoin4".account, "_prejoin4".creation_comment, "_prejoin4".creation_rationale, "_prejoin4".datecreated, "_prejoin4".defaultmembershipperiod, "_prejoin4".defaultrenewalperiod, "_prejoin4".displayname, "_prejoin4".hide_email_addresses, "_prejoin4".homepage_content, "_prejoin4".icon, "_prejoin4".id, "_prejoin4".logo, "_prejoin4".mailing_list_auto_subscribe_policy, "_prejoin4".merged, "_prejoin4".mugshot, "_prejoin4".name, "_prejoin4".personal_standing, "_prejoin4".personal_standing_reason, "_prejoin4".registrant, "_prejoin4".renewal_policy, "_prejoin4".subscriptionpolicy, "_prejoin4".teamdescription, "_prejoin4".teamowner, "_prejoin4".verbose_bugnotifications, "_prejoin4".visibility, "_prejoin5".bug, "_prejoin5".bugtracker, "_prejoin5".datecreated, "_prejoin5".id, "_prejoin5".last_error_type, "_prejoin5".lastchanged, "_prejoin5".lastchecked, "_prejoin5".next_check, "_prejoin5".owner, "_prejoin5".remote_importance, "_prejoin5".remotebug, "_prejoin5".remotestatus FROM BugTask LEFT JOIN Person AS "_prejoin1" ON BugTask.assignee = "_prejoin1".id LEFT JOIN Product AS "_prejoin2" ON BugTask.product = "_prejoin2".id LEFT JOIN SourcePackageName AS "_prejoin3" ON BugTask.sourcepackagename = "_prejoin3".id LEFT JOIN Person AS "_prejoin4" ON BugTask.owner = "_prejoin4".id LEFT JOIN BugWatch AS "_prejoin5" ON BugTask.bugwatch = "_prejoin5".id WHERE BugTask.bug = 426116 AND (1=1) ORDER BY BugTask.id
3 142 1329 9 1320 launchpad-main-master SELECT Bug.date_last_message, Bug.date_last_updated, Bug.date_made_private, Bug.datecreated, Bug.description, Bug.duplicateof, Bug.heat, Bug.heat_last_updated, Bug.id, Bug.latest_patch_uploaded, Bug.message_count, Bug.name, Bug.number_of_duplicates, Bug.owner, Bug.private, Bug.security_related, Bug.title, Bug.users_affected_count, Bug.users_unaffected_count, Bug.who_made_private FROM Bug, BugMessage WHERE BugMessage.message = %s AND Bug.id = BugMessage.bug ORDER BY Bug.id DESC LIMIT 1
4 142 847 5 842 launchpad-main-master SELECT COUNT(*) FROM Bug, BugMessage WHERE BugMessage.message = %s AND Bug.id = BugMessage.bug

[Robert Collins (lifeless)]

setting the status/importance as per zer-oops-policy

[Robert Collins (lifeless)]

https://lp-oops.canonical.com/oops.py/?oopsid=1700S32 - I got a profile of this ( on a different bug but should be the same issue).

kcachegrind suggests that message_to_canonical_url_data is a key culprit.

[Robert Collins (lifeless)]

(Just journaling as i dig)
each attachment's API json data has a 'message_link' (presumably to the message that attached the attachment).
If this is being recalculated each time, that would drive the queries.

[Robert Collins (lifeless)]

There is an optimised - IIndexedMessage - code path, which isn't being taken, so 25% of the queries are the count() - checking if there is a bug for the message. 25% are reloading the bug we already have, 25% reloading the bug task we already have.

[Robert Collins (lifeless)]

Ok, so it was O(N^2) in message link calculation, and also we were double-querying LibraryFileAlias (once to filter attachments, and once to retrieve the LFA content).

Both issues are fixed in my branch, though its a tad ugly.

[Robert Collins (lifeless)]

This now appears much healthier on edge. \o/

[Launchpad QA Bot (lpqabot)]

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

[Abel Deuring (adeuring)]

yay! The total request time, as seen from a client, is quite good now:

b = lp.bugs[426116]
t1 = time(); print len(list(b.attachments)); print time() - t1

shows times between 2.2 and 4.2 seconds on edge

[Bryce Harrington (bryce)]

I re-checked the test_attachments.py script I did for reporting bug #424671, and measured about a 35-40% reduction in run time for the particular case I'm interested in. However, the script terminates with an assertion so I can't be certain the performance improvement is real or just that the script exits early... I'll optimistically assume the former. :-) Details can be viewed on that bug report.

For timeout/oops with attachments, bug #317094 has been my test case (reported as launchpad bug #583553); I examined this with several folk at the epic without success. Unfortunately it still times out:

https://bugs.edge.launchpad.net/ubuntu/+source/xf86-input-evtouch/+bug/317094
https://lp-oops.canonical.com/oops.py/?oopsid=OOPS-1713EB2411

However, despite this problem, it appears the time has improved a good deal:

WAS:
SQL time: 5202 ms
Non-sql time: 15510 ms
Total time: 20712 ms
Statement Count: 506

IS:
SQL time: 6168 ms
Non-sql time: 7378 ms
Total time: 13546 ms
Statement Count: 413

Anyway, I don't know how accurate or relevant all this data is, but it suggests to me things are getting measurably better, although still generally broken.

[Robert Collins (lifeless)]

Bryce, this bug is about API use, that test url and OOPS are about bug
*pages*, so entirely irrelevant here.

I see in other bugs that you have shown better stats on API behaviour,
so I'm guessing this was just a c&p to the wrong bug.