466580 - Blank pages trying to access the Bandwagon feed API

Status: VERIFIED FIXED

(addons.mozilla.org Graveyard :: Collections, defect)

Description

[Stephen Donner [:stephend] Not actively reading bugmail]

Attachment: Live HTTP Headers output

When trying to access https://preview.addons.mozilla.org/en-US/firefox/api/1.3/feed/1 from bug 456142, I sometimes get a blank page.

I've captured the Live HTTP Headers output and attached it, above.

Comment 1

[Les Orchard [:lorchard]]

I suspect this may be caused by a clobbering of the DB change needed for the feed:

https://bugzilla.mozilla.org/show_bug.cgi?id=465569#c3

Comment 2

[Les Orchard [:lorchard]]

Wrong lorchard assignee again :)

Comment 3

[Les Orchard [:lorchard]]

So, per bug 465569, it seems that a missing column is not a culprit here. Ugh.

Thinking out loud here, in lieu of access to preview error logs and hoping someone might have some ideas:

* The blank results appear to be intermittent.  But, when they happen, they get cached and stick around.  Throwing random parameters onto the URL to defeat cache appears to show the feed working pretty reliably.

* Sometimes generating the feed output takes upwards of 10 seconds.  Not sure why, but I'm going to poke at profiling / optimizing on my dev machine.

* Given the long response times, is there a timeout on the caching proxy that would cause a blank result by giving up on the origin server and caching the blank?

Comment 4

[Les Orchard [:lorchard]]

I've run the bandwagon feed through Xdebug and KCachegrind and found that one spot where I used $this->publish() to handle some modified addons data caused over 1M recursive calls to _sanitizeArrayForXML().  I'm going to assume that this caused the lengthy response times and in turn caused blank pages to be cached.

Not exactly sure why that happened, but when I switch to $this->set(), the count drops to 116.  I think this should be safe, because the data added to the already-sanitized array should itself also be clean.

So, I've gone ahead and checked this in and will try checking it on preview after waiting awhile for a sync.  I'll also keep poking at the issue to see why the number of calls were so high.

Comment 5

[Les Orchard [:lorchard]]

Okay, I think this is fixed now.  Might still give optimization a few more pokes, but now it looks like it's in the realm of DB hits instead of sanitization calls.

Comment 6

[Les Orchard [:lorchard]]

Per bug 456142, that sanitizing tweak didn't fix things.

Comment 7

[Les Orchard [:lorchard]]

Attachment: optimization patch for publish()

Took a crack at optimizing the XML string sanitizing here, but I want to get a review before checking in to try it on preview.

From KCachegrind comparisons, this revision takes the number of calls to _sanitizeArrayForXML from 1M down to 57k for the Fashion Your Firefox feed (35 items).  It also cuts the response time by a few orders of magnitude on my laptop as well.

I wish I'd caught this performance issue beforehand, but I'd only been using feeds of 2-5 items on my dev machine.

Comment 8

[Les Orchard [:lorchard]]

Oh, and why so many calls to _sanitizeArrayForXML?  Well, the addons data array is very deeply nested and contains quite a lot of detail about the addons, versions, authors, etc.  Next steps might be to further pare down that array to include just what should show up in the feed, but taking it this far should fix the immediate problem of blank feed results

Comment 9

[Laura Thomson :laura]

Comment on attachment 352251 [details] [diff] [review]
optimization patch for publish()

This looks ok for me.  We should make sure to test the existing API calls (stephend?  :) ) to make sure we haven't regressed anything.

Comment 10

[Les Orchard [:lorchard]]

Checked the patch in as r20694

Other API calls look okay to me, but I haven't given it a serious battering or anything.  Hopefully this does it

Comment 11

[Stephen Donner [:stephend] Not actively reading bugmail]

Reopening because this is sadly still happening.

Comment 12

[Les Orchard [:lorchard]]

Looking at this some more on khan, I get the following intermittent error:

[Fri Dec 12 14:30:23 2008] [error] [client 10.2.72.11] PHP Stack trace:
[Fri Dec 12 14:30:23 2008] [error] [client 10.2.72.11] PHP   1. {main}() /home/lorchard/devel/mozilla/addons-trunk/site/app/webroot/index.php:0
[Fri Dec 12 14:30:23 2008] [error] [client 10.2.72.11] PHP   2. Dispatcher->dispatch() /home/lorchard/devel/mozilla/addons-trunk/site/app/webroot/index.php:82
[Fri Dec 12 14:30:23 2008] [error] [client 10.2.72.11] PHP   3. Dispatcher->_invoke() /home/lorchard/devel/mozilla/addons-trunk/site/cake/dispatcher.php:245
[Fri Dec 12 14:30:23 2008] [error] [client 10.2.72.11] PHP   4. call_user_func_array() /home/lorchard/devel/mozilla/addons-trunk/site/cake/dispatcher.php:263
[Fri Dec 12 14:30:23 2008] [error] [client 10.2.72.11] PHP   5. ApiController->collections_feed() /home/lorchard/devel/mozilla/addons-trunk/site/cake/dispatcher.php:0
[Fri Dec 12 14:30:23 2008] [error] [client 10.2.72.11] PHP   6. ApiController->publish() /home/lorchard/devel/mozilla/addons-trunk/site/app/controllers/api_controller.php:492
[Fri Dec 12 14:30:23 2008] [error] [client 10.2.72.11] PHP   7. ApiController->_sanitizeArrayForXML() /home/lorchard/devel/mozilla/addons-trunk/site/app/controllers/api_controller.php:936
[Fri Dec 12 14:30:23 2008] [error] [client 10.2.72.11] PHP   8. ApiController->_sanitizeArrayForXML() /home/lorchard/devel/mozilla/addons-trunk/site/app/controllers/api_controller.php:982
[Fri Dec 12 14:30:23 2008] [error] [client 10.2.72.11] PHP   9. ApiController->_sanitizeArrayForXML() /home/lorchard/devel/mozilla/addons-trunk/site/app/controllers/api_controller.php:982
[Fri Dec 12 14:30:23 2008] [error] [client 10.2.72.11] PHP  10. ApiController->_sanitizeArrayForXML() /home/lorchard/devel/mozilla/addons-trunk/site/app/controllers/api_controller.php:982
[Fri Dec 12 14:30:23 2008] [error] [client 10.2.72.11] PHP  11. ApiController->_sanitizeArrayForXML() /home/lorchard/devel/mozilla/addons-trunk/site/app/controllers/api_controller.php:982
[Fri Dec 12 14:30:23 2008] [error] [client 10.2.72.11] PHP  12. ApiController->_sanitizeArrayForXML() /home/lorchard/devel/mozilla/addons-trunk/site/app/controllers/api_controller.php:982
[Fri Dec 12 14:30:23 2008] [error] [client 10.2.72.11] PHP  13. preg_replace() /home/lorchard/devel/mozilla/addons-trunk/site/app/controllers/api_controller.php:988

So, while I think there's some caching magic yet to be dealt with, this introduces a new wrinkle.

Comment 13

[Les Orchard [:lorchard]]

Oh, wait, I left out the first and most important line of the error:

[Fri Dec 12 14:31:27 2008] [error] [client 10.2.72.11] PHP Fatal error:  Allowed memory size of 16777216 bytes exhausted (tried to allocate 89 bytes) in /home/lorchard/devel/mozilla/addons-trunk/site/app/controllers/api_controller.php on line 988

Comment 14

[Les Orchard [:lorchard]]

Okay.  Finally, I think r21186 should fix this.

Comment 15

[Stephen Donner [:stephend] Not actively reading bugmail]

Verified FIXED, w00t!

https://preview.addons.mozilla.org/en-US/firefox/api/1.3/feed/1 is now returning the feed data 100% of the time for me (been checking off and on for ~ 2 hours, now).