GNOME Bugzilla – Bug 349956
Orca causes gedit Print Dialog to slow down.
Last modified: 2008-07-22 19:24:03 UTC
Something to be investigated further. * Start up Orca. * Start up gedit. * Hit Control-P to bring up the Print dialog. Mine has two entries in it. Create a PDF Document Generic Postscript The "Generic Postscript" one is initially selected. * Hit the Up arrow to move the selection to the other printer. With Orca running it takes several seconds for this to happen. No COMM_FAILURES noticed or Tracebacks, but something is definitely not copacetic here.
Something is definitely odd. It looks like we need to do some profiling at some point to check out what's going on.
At http://www.gnome.org/~richb/Orca/349956-trace.txt is a file which contains Orca trace information (with time differences) from the time when it it's just spoken about the "Generic Postscript" printer to the time that it speaks the "Create a PDF Document" line. At about line 3903 in this file, you will see that there are several occurances of: if settings.gilSleepTime: time.sleep(settings.gilSleepTime) return True These are taking up a lot of the "wait" time. It's the calls above this in the debug.txt which would appear to be the cause of the slowdown. Will, perhaps you can cast yor eye over this and provide a clue to what's going on here...
The sleep in question is happening as a gidle thread, which is called where there's supposedly nothing going on. If you'd like to play around to see if this really has an impact, set the settings.gilSleepTime to 0, and it will prevent the sleep from happening.
Setting the gilSleepTime to 0 improves the responsiveness somewhat, but it's still slower then if Orca isn't running. Further investigation is needed...
Created attachment 74974 [details] Timing values after pressing Up in the gedit Print dialog. I made the following changes to focus_tracking_presenter.py: Index: focus_tracking_presenter.py =================================================================== RCS file: /cvs/gnome/orca/src/orca/focus_tracking_presenter.py,v retrieving revision 1.87 diff -u -r1.87 focus_tracking_presenter.py --- focus_tracking_presenter.py 14 Oct 2006 23:25:33 -0000 1.87 +++ focus_tracking_presenter.py 18 Oct 2006 20:33:22 -0000 @@ -78,6 +78,8 @@ self._enqueueEventCount = 0 self._dequeueEventCount = 0 + self.startClockTime = time.time() + ######################################################################## # # # METHODS FOR KEEPING TRACK OF LISTENERS REGISTERED WITH ATSPI # @@ -614,6 +616,10 @@ if (not debug.eventDebugFilter) \ or (debug.eventDebugFilter \ and debug.eventDebugFilter.match(event.type)): + self.currentClockTime = time.time() + print "^^^^^ NON-EVENT TIME: ", \ + (self.currentClockTime - self.startClockTime) + self.startClockTime = self.currentClockTime debug.println(debug.eventDebugLevel, "\nvvvvv PROCESS OBJECT EVENT %s vvvvv" \ % event.type) @@ -621,6 +627,12 @@ if (not debug.eventDebugFilter) \ or (debug.eventDebugFilter \ and debug.eventDebugFilter.match(event.type)): + + self.currentClockTime = time.time() + print "^^^^^ EVENT TIME: ", \ + (self.currentClockTime - self.startClockTime) + self.startClockTime = self.currentClockTime + debug.println(debug.eventDebugLevel, "^^^^^ PROCESS OBJECT EVENT %s ^^^^^\n" \ % event.type) This gave us two types of timings: 1/ "EVENT TIME:" lines for the amount of time it took to process each type of accessibility event. 2/ "NON-EVENT TIME:" lines for the time between the end of one such event being processed and the next one arriving. This gives us some interesting information: The time delays occurs for NON-EVENT TIME. In particular, at: line 369 - 3.947 seconds line 389 - 0.447 seconds line 409 - 0.447 seconds line 429 - 0.527 seconds line 449 - 0.207 seconds line 469 - 0.367 seconds In each case, the accessibility event received just afterwards was an "object:children-changed:add" for a gedit combo box: line 369 3.947 seconds ---------------------- vvvvv PROCESS OBJECT EVENT object:children-changed:add vvvvv OBJECT EVENT: object:children-changed:add detail=(0,0) app.name='gedit' name='A4' role='combo box' state='ENABLED FOCUSABLE SENSITIVE VISIBLE' relations='LABELLED_BY LABELLED_BY' line 389 - 0.447 seconds ---------------------- vvvvv PROCESS OBJECT EVENT object:children-changed:add vvvvv OBJECT EVENT: object:children-changed:add detail=(0,0) app.name='gedit' name='Straight' role='combo box' state='ENABLED FOCUSABLE SENSITIVE VISIBLE' relations='LABELLED_BY LABELLED_BY' line 409 - 0.447 seconds ---------------------- vvvvv PROCESS OBJECT EVENT object:children-changed:add vvvvv OBJECT EVENT: object:children-changed:add detail=(0,0) app.name='gedit' name='Portrait' role='combo box' state='ENABLED FOCUSABLE SENSITIVE VISIBLE' relations='LABELLED_BY LABELLED_BY' line 429 - 0.527 seconds ---------------------- vvvvv PROCESS OBJECT EVENT object:children-changed:add vvvvv OBJECT EVENT: object:children-changed:add detail=(0,0) app.name='gedit' name='Plain' role='combo box' state='ENABLED FOCUSABLE SENSITIVE VISIBLE' relations='LABELLED_BY LABELLED_BY' line 449 - 0.207 seconds ---------------------- vvvvv PROCESS OBJECT EVENT object:children-changed:add vvvvv OBJECT EVENT: object:children-changed:add detail=(0,0) app.name='gedit' name='No options are defined' role='combo box' state='ENABLED FOCUSABLE SENSITIVE VISIBLE' relations='LABELLED_BY LABELLED_BY' line 469 - 0.367 seconds ---------------------- vvvvv PROCESS OBJECT EVENT object:children-changed:add vvvvv OBJECT EVENT: object:children-changed:add detail=(0,0) app.name='gedit' name='Default' role='combo box' state='ENABLED FOCUSABLE SENSITIVE SHOWING VISIBLE' relations='LABELLED_BY' If I was betting money, I'd place it on a performance problem somewhere in the atk/gail implementation of combo boxes. Still investigating...
Created attachment 75036 [details] Simple Python script that just uses at-spi (no Orca code involved).
Created attachment 75037 [details] Output from running the bug_349956.py Python at-spi script. This shows that if Orca isn't involved, the timing for moving from one line in the gedit Printer dialog to the one above, is similar to when Orca isn't running. In other words, sadly this is an Orca performance problem.
The problem is in the __blockPreventor() method in atspi.py: def __blockPreventor(self): """[[[TODO: HACK to attempt to prevent deadlocks. We call time.sleep here as a means to sidestep the global interpreter lock (GIL).]]] """ if settings.gilSleepTime: time.sleep(settings.gilSleepTime) return True If I change it to comment out the two lines: if settings.gilSleepTime: time.sleep(settings.gilSleepTime) then the timing delay goes away (i.e. it's almost the same speed as if Orca wasn't running).
I added a new setting to settings.py called useBlockPreventor (with a default value of False). If True, and gilSleepTime is not zero, then the gobject idle handler called __blockPreventor() is installed. This is not the default anymore, and therefore this problem goes away. If we start seeing hangs again, then we can toggle the default value for the useBlockPreventor setting. Changes checked into CVS HEAD. Closing as FIXED.