[orca] Chromium: Add some extra debugging output

[Joanmarie Diggs <joanied src gnome org>]

commit 8a00381bbe1652b123aeff66ff864e69bec34559
Author: Joanmarie Diggs <jdiggs igalia com>
Date:   Wed Nov 21 16:12:38 2018 -0500

    Chromium: Add some extra debugging output

 src/orca/scripts/toolkits/Chromium/script.py          |  5 ++++-
 .../scripts/toolkits/Chromium/script_utilities.py     | 19 ++++++++++++++-----
 2 files changed, 18 insertions(+), 6 deletions(-)
---
diff --git a/src/orca/scripts/toolkits/Chromium/script.py b/src/orca/scripts/toolkits/Chromium/script.py
index 3840f8c78..319ed561e 100644
--- a/src/orca/scripts/toolkits/Chromium/script.py
+++ b/src/orca/scripts/toolkits/Chromium/script.py
@@ -32,6 +32,7 @@ __copyright__ = "Copyright (c) 2018 Igalia, S.L."
 __license__   = "LGPL"
 
 import pyatspi
+import time
 
 from orca import debug
 from orca import orca
@@ -130,8 +131,10 @@ class Script(web.Script):
 
         # HACK: Remove this once Chromium emits focus changes after window activation.
         if event.detail1 and role == pyatspi.ROLE_FRAME:
+            startTime = time.time()
             focusedObject = self.utilities.focusedObject(event.source)
-            msg = "CHROMIUM: NO INITIAL FOCUS HACK. Focused object: %s" % focusedObject
+            msg = "CHROMIUM: NO INITIAL FOCUS HACK. Focused object: %s - %.4fs" % \
+                (focusedObject, time.time()-startTime)
             debug.println(debug.LEVEL_INFO, msg, True)
             if focusedObject:
                 orca.setLocusOfFocus(event, focusedObject)
diff --git a/src/orca/scripts/toolkits/Chromium/script_utilities.py 
b/src/orca/scripts/toolkits/Chromium/script_utilities.py
index cca8582ee..b1b4b4fa5 100644
--- a/src/orca/scripts/toolkits/Chromium/script_utilities.py
+++ b/src/orca/scripts/toolkits/Chromium/script_utilities.py
@@ -32,6 +32,7 @@ __copyright__ = "Copyright (c) 2018 Igalia, S.L."
 __license__   = "LGPL"
 
 import pyatspi
+import time
 
 from orca import debug
 from orca import orca_state
@@ -69,8 +70,9 @@ class Utilities(web.Utilities):
                     return True
                 return False
 
+            startTime = time.time()
             result = self.findAllDescendants(frame, _include, _exclude)
-            msg = "CHROMIUM: NO EMBEDDED RELATION HACK: %s has %i docs." % (frame, len(result))
+            msg = "CHROMIUM: NO EMBEDDED RELATION HACK - %.4fs" % (time.time()-startTime)
             debug.println(debug.LEVEL_INFO, msg, True)
 
         self._documentsEmbeddedBy[hash(frame)] = result
@@ -128,12 +130,16 @@ class Utilities(web.Utilities):
             return False
 
         # HACK: Remove this once Chromium adds active state to popup frames.
-        if self._isFrameContainerForBrowserUIPopUp(window):
+        startTime = time.time()
+        result = self._isFrameContainerForBrowserUIPopUp(window)
+        msg = "CHROMIUM: _isFrameContainerForBrowser() - %.4fs" % (time.time()-startTime)
+        debug.println(debug.LEVEL_INFO, msg, True)
+
+        if result:
             msg = "CHROMIUM: POPUP MISSING STATE ACTIVE HACK: %s can be active window" % window
             debug.println(debug.LEVEL_INFO, msg, True)
-            return True
 
-        return False
+        return result
 
     def treatAsMenu(self, obj):
         if not obj:
@@ -173,7 +179,10 @@ class Utilities(web.Utilities):
 
         if self.isDocument(topLevel) and orca_state.activeWindow \
            and orca_state.activeWindow.getApplication() == self._script.app:
-            if pyatspi.findDescendant(topLevel, lambda x: x == topLevel):
+            startTime = time.time()
+            descendant = pyatspi.findDescendant(topLevel, lambda x: x == topLevel)
+            msg = "CHROMIUM: findDescendant() - %.4fs" % (time.time()-startTime)
+            if descendant:
                 msg = "CHROMIUM: HACK: Returning %s as top level" % orca_state.activeWindow
                 debug.println(debug.LEVEL_INFO, msg, True)
                 return orca_state.activeWindow