Skip to content

Address misleading garbage handler warnings and fix another reference cycle#11552

Merged
michaelDCurran merged 2 commits into
masterfrom
fixGarbageHandler
Sep 4, 2020
Merged

Address misleading garbage handler warnings and fix another reference cycle#11552
michaelDCurran merged 2 commits into
masterfrom
fixGarbageHandler

Conversation

@michaelDCurran

@michaelDCurran michaelDCurran commented Sep 4, 2020

Copy link
Copy Markdown
Member

Link to issue number:

Closes #11539

Summary of the issue:

GarbageHandler is printing quite a lot of warnings about objects, especially after interacting with an edit field in Mozilla Firefox.
There are two specific issues here, both illustrated in #11539.
Note that in #11539 it mentions the warnings appearing when loading pages. I think this is simply because a lot of objects are suddenly created / destroyed when loading pages and thus the garbage collector happens to run. But the underlying issue has already happened when starting to interact with a previous edit field.

1. Lots of warnings about IAccessibleText, IAccessibleAction etc:

There is still a possible reference cycle on ia2Web.editor due to MozillaCompoundTextInfo caching lastCaretObj. A previous pr tried to address this by removing this reference in event_loseFocus. However, there are times where this is cached outside of the focus, such as when fetching the caret when changing review modes, or pressing enter on an edit field switching from browseMode to focus mode.
Warnings such as the following are produced:

WARNING - garbageHandler.notifyObjectDeletion (13:46:35.453) - MainThread (20312):
Deleting unreachable object <NVDAObjects.Dynamic_EditableTextWithAutoSelectDetectionEditorMozillaIAccessible object at 0x068760F0>
WARNING - garbageHandler.notifyObjectDeletion (13:46:35.453) - MainThread (20312):
Deleting unreachable object <POINTER(IAccessibleAction) ptr=0x31abc84 at 67e4120>
WARNING - garbageHandler.notifyObjectDeletion (13:46:35.453) - MainThread (20312):
Deleting unreachable object <POINTER(IAccessibleText) ptr=0x31abad4 at 67e4350>
WARNING - garbageHandler.notifyObjectDeletion (13:46:35.453) - MainThread (20312):
Deleting unreachable object <POINTER(IAccessible2) ptr=0x31ab96c at 67e4210>

In these cases, as the object is never reused anyway, the caching makes no sense. We should only cache the caret if the compoundTextInfo is on the current focus.

2. Misleading warnings about WavePlayer:

As we log an error when garbageHandler is notified about the first object deletion in a collection run, incorrect logic around the report count meant that we were tracking the deletion of the WavePlayer that played the error sound for that error message. In fact it started producing silly stack traces where we were starting to recurse into notifyOfObjectDeletion:

  File "garbageHandler.pyc", line 23, in __del__
  File "garbageHandler.pyc", line 63, in notifyObjectDeletion
  File "logging\__init__.pyc", line 1407, in error
  File "logHandler.pyc", line 160, in _log
  File "logging\__init__.pyc", line 1514, in _log
  File "logging\__init__.pyc", line 1524, in handle
  File "logging\__init__.pyc", line 1586, in callHandlers
  File "logHandler.pyc", line 279, in handle
  File "nvwave.pyc", line 567, in playWaveFile
  File "nvwave.pyc", line 490, in __del__
  File "garbageHandler.pyc", line 23, in __del__
  File "garbageHandler.pyc", line 63, in notifyObjectDeletion
WARNING - garbageHandler.notifyObjectDeletion (13:46:35.047) - MainThread (20312):
Deleting unreachable object <nvwave.WavePlayer object at 0x067FDCD0>

Similarly: The final error logged when the garbage collection finished was happening before we had cleared the garbage collection threadID, thus again, the WavePlayer for that error, also was classed as being inappropriately deleted.

Description of how this pull request fixes the issue:

1. Lots of warnings about IAccessibleText, IAccessibleAction

MozillaCompoundTextInfo now only caches lastCaretObj if the compoundTextInfo is for the current focus. There is no benefit to doing it at other times, and it would not be cleaned up.

2. Misleading warnings about WavePlayer:

  • changed the initial log.error when the first object is deleted in a collection to a log.warning.
  • Increased the report count before that first log message to ensure that we don't start tracking things recursively.
  • Cleared the collection threadID in the gc hook before the final log.error, so that anything that happens in that log.error is not tracked as an inappropriate object deletion by the collector.

Testing performed:

  • With NVDA, opened google.com in Firefox. In browse mode, pressed 'e' to jump to the search edit field. Pressed enter to go into focus mode. opened the Python console and did a gc.collect(). Before this fix many wrnings about IAccessibleText objects were logged. Now there are none.
  • Ensured that, without that caret caching fix, that the warnings no longer contain WavePlayer as one of the objects.
  • Tested navigating around complex editor content documents such as an html message in Thunderbird, a file in vsCode, to ensure that performance when arrowing was not degraded by this pr (I.e. caret caching for the focus was still working).

Known issues with pull request:

None.

Change log entry:

None needed.

…ample) don't get logged as an object being cleaned up by the garbage collector.

Specifically:
* change the first log.error to a log.warning (so the error sound does not play). Note that this message still must be logged as it is the one that contains the stack trace showing where the garbage collection is running.
* Increase the report count before logging any message in notifyOfObjectDeletion so that any objects deleted in the log calls themselves don't get tracked as the first  object to be deleted.
* Clear the garbage collection threadID in the gc hook before logging the final error, otherwise that error (and the error sound) is tracked as an object deletion.
…nfo is on the current focus, otherwise the caretObj may not be cleaned up and a reference cycle may remain.
@michaelDCurran michaelDCurran added this to the 2020.3 milestone Sep 4, 2020
@michaelDCurran michaelDCurran merged commit 0b21e78 into master Sep 4, 2020
@michaelDCurran michaelDCurran deleted the fixGarbageHandler branch September 4, 2020 20:45
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Lots of garbage collection messages when loading Gmail in Firefox

3 participants