Closed Bug 1141220 Opened 7 years ago Closed 11 months ago

Incredibly long load time and "dead" accessible objects seen with certain sites

Categories

(Core :: Disability Access APIs, defect)

x86_64
Linux
defect
Not set
normal

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: jdiggs, Unassigned)

References

(Blocks 2 open bugs)

Details

(Keywords: perf, Whiteboard: [needs profile with stacks])

Attachments

(3 files, 1 obsolete file)

Steps to reproduce:
1. Disable accessibility support in GNOME
2. Load http://njt.hu/cgi_bin/njt_doc.cgi?docid=159096.239298
3. Launch the attached pyatspi accessible-event listener in a terminal
4. Repeat step 2

Expected results: There would not be a startling difference in the load time in step 2 versus that in step 4. There would not be any "dead" accessibles added as children.

Actual results: In step 2, the page loads in a few seconds. In step 4, on my machine, it loads in 40. And there are plenty of dead accessible children added as seen in the output below.

Note: I don't see the bug when the content is saved locally, or I'd attach that file. Sorry!

$ ./childenchanged.py 
[autocomplete | Search or enter address] [push button | Location]
object:state-changed:busy(1, 0, 0)
	source: [document frame | Nemzeti Jogszabálytár]
	host_application: [application | Firefox]
[document frame | Nemzeti Jogszabálytár] [section | ]
[document frame | Nemzeti Jogszabálytár] [link | 1]
[document frame | Nemzeti Jogszabálytár] [link | 2]
[document frame | Nemzeti Jogszabálytár] [link | 3]
[document frame | Nemzeti Jogszabálytár] [link | 4]
[document frame | Nemzeti Jogszabálytár] [link | 5]
[document frame | Nemzeti Jogszabálytár] [link | 6]
[document frame | Nemzeti Jogszabálytár] [link | 7]
[document frame | Nemzeti Jogszabálytár] [link | ]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[document frame | Nemzeti Jogszabálytár] [DEAD]
[autocomplete | Search or enter address] [DEAD]
[section | a Polgári Törvénykönyvről] [section | ]
[document frame | Nemzeti Jogszabálytár] [section | ]
[document frame | Nemzeti Jogszabálytár] [section | ]
object:state-changed:busy(0, 0, 0)
	source: [document frame | Nemzeti Jogszabálytár]
	host_application: [application | Firefox]
LOAD TIME: 40.0776
Attached file profile.json.tar.gz
Attached file profile-results.tar.gz
Followed different instructions to get a profile. Sorry for the noise.
profile doesn't show much unfortunately, it looks like we "just" create the tree, that's what most time is spent for
Joanie checked out that multi process is not issue here (browser.tabs.remote.autostart is off), I don't see any problems when VO running or DOMi. So it has to be something linux specific. Trevor, do you have ideas?
Flags: needinfo?(tbsaunde+mozbugs)
In the about:config I found the following values:

browser.tabs.remote.autostart;false
browser.tabs.remote.autostart.1;true
browser.tabs.remote.autostart.disabled-because-using-a11y;true
(In reply to José Vilmar Estácio de Souza from comment #5)
> In the about:config I found the following values:
> 
> browser.tabs.remote.autostart;false
> browser.tabs.remote.autostart.1;true
> browser.tabs.remote.autostart.disabled-because-using-a11y;true

the last pref should make a trick to not run Firefox in multiprocess mode, but to be on a safe side it's good to have 2nd pref off as well.
(In reply to alexander :surkov from comment #6)
> 
> the last pref should make a trick to not run Firefox in multiprocess mode,
> but to be on a safe side it's good to have 2nd pref off as well.

I set the three options to false but the result is the same. A lot of dead objects.
I'm not  sure what you want to know, I can reproduce this being bad, and it looks like orca / dbus isn't eating up cpu, but firefox isn't at 100% cpu either.
Flags: needinfo?(tbsaunde+mozbugs)
(In reply to Trevor Saunders (:tbsaunde) from comment #8)
> I'm not  sure what you want to know, I can reproduce this being bad, and it
> looks like orca / dbus isn't eating up cpu, but firefox isn't at 100% cpu
> either.

I wanted you to help to spot what takes it so long and why it's special to linux.
(In reply to alexander :surkov from comment #9)
> (In reply to Trevor Saunders (:tbsaunde) from comment #8)
> > I'm not  sure what you want to know, I can reproduce this being bad, and it
> > looks like orca / dbus isn't eating up cpu, but firefox isn't at 100% cpu
> > either.
> 
> I wanted you to help to spot what takes it so long and why it's special to
> linux.

Well, I have no idea off hand, and I don't have time to debug it before sometime in april at least.
Some other observations which may or may not point at a possible cause:

1. Problem doesn't happen if I save the content locally and view that in an otherwise equal set up.

2. Even if there is nothing listening, the page takes a little extra time to load. (Little == a few seconds, but still noticeable).

3. When I try viewing the same page on my Mac with Firefox, the amount of time it takes the page to load is significantly longer if VoiceOver is running. VoiceOver announces that Firefox is busy, and very little of the page is rendered for another 10ish seconds.

4. Problem does not happen with WebKitGtk + Orca or the listener. (The delay in page loading is no longer than it is without Orca or a listener. And when Orca or a listener is running, there are no dead accessibles.)

5. Problems does not happen with Safari + VoiceOver. (The delay in page loading is no longer than it is without VoiceOver. And with VoiceOver running, it immediately indicates it's 90 percent complete and right after that starts presenting the page.)

I do not recall at what point WebKit begins creating the accessible tree, but I'm thinking it might be after the render tree is completed. I can look into that later. In the meantime.... Any chance Gecko builds the accessible tree at the same time as the render tree? If so, and if building the render tree is blocked by whatever causes the several-second delay for non a11y users, could that be the source of the a11y delay on both the Mac (at least my Mac) and in Linux? Assuming I'm not already talking utter nonsense... Then the difference for Linux might be that AT-SPI2 times out so as not to hang the desktop waiting on a possibly-blocked app. That would explain the Zombie children.

Alex: If memory serves me, you stated you were not seeing this delay on your Mac with VoiceOver running. Or did you mean you didn't see anything bad happen or a 40 second delay? Or did you mean it's just as fast with VoiceOver running as without?
(In reply to Joanmarie Diggs from comment #11)
> Some other observations which may or may not point at a possible cause:
> 
> 1. Problem doesn't happen if I save the content locally and view that in an
> otherwise equal set up.
> 
> 2. Even if there is nothing listening, the page takes a little extra time to
> load. (Little == a few seconds, but still noticeable).

cc'ing Boris for ideas. Some background: there's a web page that takes noticable time to reload with a11y enabled, it takes no time if saved locally. Accessibility engine just listens WillRefresh of RefreshDriver. What magic may happen for locally saved page?
(In reply to Joanmarie Diggs from comment #11)

> Alex: If memory serves me, you stated you were not seeing this delay on your
> Mac with VoiceOver running. Or did you mean you didn't see anything bad
> happen or a 40 second delay? Or did you mean it's just as fast with
> VoiceOver running as without?

I run again, I don't see 40 seconds but I see a lag. I profiled it but nothing suspicious so far, looks like routine work http://people.mozilla.org/~bgirard/cleopatra/#report=07000f39bbe87afe5a05bc788e0a5fe4f4ce21a9&selection=0,1,2,3,4,21
No idea offhand, sorry.  Apart from the obvious much lower latency and probably lack of incremental loading for file://
Alex: Is the accessibility tree being created at the same time as the render tree? If so, is there a reason for doing that? Or could you first create the render tree completely and then create the accessibility tree?
(In reply to Joanmarie Diggs from comment #15)
> Alex: Is the accessibility tree being created at the same time as the render
> tree? If so, is there a reason for doing that? Or could you first create the
> render tree completely and then create the accessibility tree?

in general rendering and accessible tree creation are async, we accumulate changes on a11y side and then, when layout says us, we start processing.
As an experiment, I modified the original accessible event listener to disable all pyatspi caching for Firefox. The result is that the dead accessible problem stops. But the page loading time does not decrease at all (i.e. still nearly 40 seconds on my machine).
Attachment #8574791 - Attachment is obsolete: true
Comment on attachment 8574804 [details]
profile-results.tar.gz

I took a look at the inverted callstack and list the top 3 (wish I could cut and paste from cleopatra). Everything runs off of nsRefreshDriver::Tick.

~17% spent in PLDHashEntryHdr* PLDHashTable::SearchTable<(PLDHashTable::SearchReason>0)

~12% of the time in GetOrCreateAccessible

~6.7% in isShadowInsertionPoint (Do we slow down that much having to check for shadow DOM?)
(I should have mentioned that was from a subrange in the full profile)
(In reply to David Bolter [:davidb] from comment #18)
> Comment on attachment 8574804 [details]
> profile-results.tar.gz
> 
> I took a look at the inverted callstack and list the top 3 (wish I could cut
> and paste from cleopatra). Everything runs off of nsRefreshDriver::Tick.

did we decide this was specific to linux or not?  if its linux specific I'd be skeptical that this profile shows everything.

> ~17% spent in PLDHashEntryHdr*
> PLDHashTable::SearchTable<(PLDHashTable::SearchReason>0)

called from where?

> ~12% of the time in GetOrCreateAccessible
> 
> ~6.7% in isShadowInsertionPoint (Do we slow down that much having to check
> for shadow DOM?)

some of it might be just renaming from stuff that also deals with xbl but *shrug*
Joanie can you profile FF Nightly? We can get full stacks that way.
Flags: needinfo?(jdiggs)
(In reply to David Bolter [:davidb] from comment #21)
> Joanie can you profile FF Nightly? We can get full stacks that way.

myself I'd think it'd e best to find someone willingto use a system profile to be sure we don't miss stuff.
(In reply to David Bolter [:davidb] from comment #21)
> Joanie can you profile FF Nightly? We can get full stacks that way.

I did profile FF Nightly, current on the day I did the profile.

I just asked in IRC if perhaps you meant a debug nightly as opposed to a release nightly, but Trev stated that "profiling a debug build won't produce anything useful". So.... <insert shrug here>

Clearing the needinfo because I don't know what info I can provide. Sorry!
Flags: needinfo?(jdiggs)
OK maybe I misunderstood. Let me get out of the middle. Vladan?
Flags: needinfo?(vdjeric)
(In reply to Joanmarie Diggs from comment #23)

> I just asked in IRC if perhaps you meant a debug nightly as opposed to a
> release nightly, but Trev stated that "profiling a debug build won't produce
> anything useful". So.... <insert shrug here>

It makes sense but the data might be less valuable because in the past Trev added some heavy debug checks.
(In reply to Joanmarie Diggs from comment #23)
> (In reply to David Bolter [:davidb] from comment #21)
> > Joanie can you profile FF Nightly? We can get full stacks that way.
> 
> I did profile FF Nightly, current on the day I did the profile.

Profiling should be done with a release Nightly.
The profile David attached in comment 18 didn't have native stacks, only pseudostacks.
@Joanmarie: Check the "Breakpad" box in the profiler panel (under the globe) to get full native stacks on Nightly.
Flags: needinfo?(vdjeric)
> @Joanmarie: Check the "Breakpad" box in the profiler panel (under the globe) to get full native stacks on Nightly.
Flags: needinfo?(jdiggs)
Keywords: perf
Status: NEW → RESOLVED
Closed: 11 months ago
Flags: needinfo?(jdiggs)
Resolution: --- → INCOMPLETE
Whiteboard: [needs profile with stacks]
You need to log in before you can comment on or make changes to this bug.