885444 - AJAX call on a Drupal site freezes in non-javascript area, high CPU usage.

Status: NEW

(Core :: Layout, defect)

Description

[antony lovric]

Attachment: LabelsForeverAjaxHang.png

User Agent: Mozilla/5.0 (compatible; MSIE 10.0; Windows NT 6.1; WOW64; Trident/6.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0; .NET4.0C; .NET4.0E)

Steps to reproduce:

Windows XP/7 connecting to a Drupal 7 Install on Ubuntu, 

Opened a page on a Drupal site that uses AJAX:

http://labelsforever.com/en/content/photo-labels

Switch the theme, once or twice, the spinner freezes, that's the issue.

Tried to diagnose with a trial version of AxaxDynaTrace, JavaScript/Rendering/Network appear almost idle, CPU is maxed out.


Actual results:

  Seems that after the AJAX request is sent AND a reply received, Firefox goes into some kind of busy loop, CPU increases until loop/block clears.


Expected results:

  Form content should have been replaced.

Comment 1

[antony lovric]

By 'Switch the theme, once or twice', I mean the label's theme (choosing a photo border from the slider), not the Drupal theme, sorry for the confusion.

Comment 2

[antony lovric]

  One other small note, I tried to reproduce the issue with an older build of FF (sitting on a VM in the office here, FF 12) and the issue was not present.

Comment 3

[Josh Matthews [:jdm]]

Is there any chance you could help narrow the regression range by using http://mozilla.github.com/mozregression/?

Comment 4

[antony lovric]

  Hey Josh, sure I can run the regression (cool tool btw).  I started at 2010-01-01 and let the tool run from there.

mozregression --good=2010-01-01

[OK] 			10.0a1  (2011-09-28)
[OK] 			17.0a1 (2012-08-10)
[BAD] 			21.0a1 (2013-01-16)
[NOT AS BAD] 	        19.0a1 (2012-10-28)
[OK]	 		18.0a1 (2012-09-18)
[BAD]			18.0a1 (2012-10-08)
[BAD]			18.0a1 (2012-09-28)
[BAD]			18.0a1 (2012-09-23)
[BAD]			18.0a1 (2012-09-20)
[BAD]			18.0a1 (2012-09-19)

-more targeted
mozregression --good=2012-09-17 --bad=2012-9-19

'19.0a1 (2012-10-28)' might be a error in my judgement but 2012-09-18 is clearly good and all nightly builds AFTER have the hang / pause after the request completes.

Comment 5

[Josh Matthews [:jdm]]

Thanks! Going by the revisions of the Windows builds for 9/18 and 9/19, that suggests the following regression range: http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=0d3b17a88d5f&tochange=80499f04e875

Comment 6

[Josh Matthews [:jdm]]

I can reproduce this easily on Fedora, too.

Comment 7

[antony lovric]

  Thanks Josh.

Comment 8

[Josh Matthews [:jdm]]

Figuring out what's happening in the busy loop would be really useful. Would you mind gathering some profiling data by following the steps at https://developer.mozilla.org/en-US/docs/Performance/Reporting_a_Performance_Problem? I'd do it myself, but the profiler doesn't give useful data on Linux systems.

Comment 9

[antony lovric]

Attachment: Profiler Run #1

Profiler output from 1st run

Comment 10

[antony lovric]

Attachment: Profiler Run #2

Should have zipped these together....

Comment 11

[Josh Matthews [:jdm]]

It's actually easier to upload the profile results to the server, since you then receive a link you can share in Bugzilla.

Comment 12

[antony lovric]

doh!

Comment 13

[Josh Matthews [:jdm]]

Antony, given that I haven't figured out how to use the files you attached yet, could you just do another profiler run and paste the link to the uploaded profile here?

Comment 14

[antony lovric]

  Hey Josh, the profiler is not working right now.  On the nightly build it fails to load the url for the profiler-consuming site.  

From:https://addons.mozilla.org/en-US/firefox/addon/gecko-profiler/?src=api

'Not available for Firefox 25.0' - Nightly is @ 25.01a right now ;(

  I can't install 24.X right now, try the profiler analyse, download the file: (not explaining that)

goto:http://people.mozilla.com/~bgirard/cleopatra/ with FF, and click upload.

Comment 15

[antony lovric]

  (sorry, forgot to mention to select the file in comment #14)

Comment 16

[Josh Matthews [:jdm]]

You can use https://github.com/bgirard/Gecko-Profiler-Addon/raw/master/geckoprofiler.xpi instead.

Comment 17

[antony lovric]

Couldn't get the built-in profile to save/share the profile, also, it doesn't show the red (busy) portion of the request? 

Anyways, I uploaded the profile files to the link in comment #14 and said 'share' on the bottom left, here are the links to the shared profiles.

http://people.mozilla.com/~bgirard/cleopatra/#report=6aba5fc4c84a8d4b42ba3b2cfb813f877b2de035

http://people.mozilla.com/~bgirard/cleopatra/#report=4395f6920521c10c45f351f7e319e77b79cee242

Comment 18

[Josh Matthews [:jdm]]

Perfect! The profiles show us spending about ~40% of time performing layout (and the timeline shows lots of synchronous layout calls occurring, which would make sense), especially font shaping, and about ~5% of time executing Dupal AJAX code. Alice, would you be able to bisect the regression range any further for us?

Comment 19

[antony lovric]

..I was looking at the profiler output and noticed that @ 49% of the time was spent in NtUserWaitMessage called from nsBaseAppShell::OnProcessNextEvent(nsIThreadInternal *,bool,unsigned int).  I don't know much about the code though...

Comment 20

[Alice0775 White]

Regression window(m-c)
Good:
http://hg.mozilla.org/mozilla-central/rev/2e429432490c
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/18.0 Firefox/18.0 ID:20120918023002
Bad:
http://hg.mozilla.org/mozilla-central/rev/e4757379b99a
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/18.0 Firefox/18.0 ID:20120918044902
Pushlog:
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=2e429432490c&tochange=e4757379b99a


Regression window(m-i)
Good:
http://hg.mozilla.org/integration/mozilla-inbound/rev/27f122beb4f5
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/18.0 Firefox/18.0 ID:20120917154902
Bad:
http://hg.mozilla.org/integration/mozilla-inbound/rev/49bc46738815
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:18.0) Gecko/18.0 Firefox/18.0 ID:20120917164302
Pushlog:
http://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=27f122beb4f5&tochange=49bc46738815

In local build
Last Good: e016faeb6b15
First Bad: 1d8ff0faf0fa

Triggered by:
	1d8ff0faf0fa	Mats Palmgren — Bug 791601. r=roc

Comment 21

[BugBot [:suhaib / :marco/ :calixte]]

The bug assignee is inactive on Bugzilla, so the assignee is being reset.