locked
PERF WARNING: FindTopLevelWindowHelper::FindAllDescendents

    Question

  • Dear All,

    Haven't written a post so far, but now i'm on the production release of VS2010 and having some issue with the execution period of the actions of the test methods. I've ran  the executor in debug and got the following results: On almost each action steps i'm getting one of those:

    V, 3856, 14, 2010/08/05, 14:59:19.218, 568837930, QTAgent32.exe, AL : Constructing UITestControl from queryId: ;[VisibleOnly]ControlType='MenuBar' && Name='Menu Bar'

    I, 3856, 14, 2010/08/05, 14:59:19.224, 568858567, QTAgent32.exe, ManagedWrapper : FindFromPartialQueryId with QID:;[VisibleOnly]ControlType='MenuBar' && Name='Menu Bar'

    I, 3856, 14, 2010/08/05, 14:59:19.233, 568892974, QTAgent32.exe, ManagedWrapper : ResetSkipStep()

    V, 3856, 14, 2010/08/05, 14:59:19.248, 568944042, QTAgent32.exe, FindTopLevelWindowHelper - Pass 1 - SearchInMinWindows, SmartMatch flags set to false and SearchRetryCount 1

    V, 3856, 14, 2010/08/05, 14:59:19.249, 568948668, QTAgent32.exe, QueryId : Creating QueryId from: ;[VisibleOnly]ControlType='MenuBar' && Name='Menu Bar'

    V, 3856, 14, 2010/08/05, 14:59:19.249, 568948833, QTAgent32.exe, QueryId : Creating SingleQueryId from: [VisibleOnly]ControlType='MenuBar' && Name='Menu Bar'

    I, 3856, 14, 2010/08/05, 14:59:37.102, 632854996, QTAgent32.exe, Playback - Element Found: ;[VisibleOnly]ControlType='MenuBar' && Name='Menu Bar'

    W, 3856, 14, 2010/08/05, 14:59:37.102, 632858212, QTAgent32.exe, PERF WARNING: FindTopLevelWindowHelper::FindAllDescendents: took 17854 ms. Expected it to take maximum 500 ms.

    The first question I'd like to ask is what exactly is FindTopLevelWindowHelper::FindAllDescendents ? How can i improve so that it's not taking so long, what are the requirements for that? Also from what'ive observed is that for each test method within the class that search is performed each time, no matter that it's already done. Is that correct?

    The second extract from the log is saying:

    V, 3856, 14, 2010/08/05, 15:00:14.209, 765679184, QTAgent32.exe, QueryId : Creating SingleQueryId from: [MSAA, VisibleOnly]ControlType='Client' && Name='Untitled Message'

    V, 3856, 14, 2010/08/05, 15:00:14.209, 765679498, QTAgent32.exe, QueryId : Creating SingleQueryId from: [MSAA, VisibleOnly]ControlType='Client' && Name='Message'

    I, 3856, 14, 2010/08/05, 15:00:14.209, 765680462, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >

    I, 3856, 14, 2010/08/05, 15:00:14.211, 765686985, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 2088, ThreadId = 2812, ThreadState = Wait, ThreadWaitReason = UserRequest

    W, 3856, 14, 2010/08/05, 15:00:20.034, 786532257, QTAgent32.exe, Playback - [WARNING] Internal warning: Element "[MSAA, VisibleOnly]ControlType='Client' && Name='Untitled Message'" was not found, so all intermediate elements were ignored. To improve performance replace this element Id with another Id or exclude it from QueryId. If this element is the target element, replace or remove intermediate elements

    I, 3856, 14, 2010/08/05, 15:00:20.534, 788322125, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >

    I, 3856, 14, 2010/08/05, 15:00:20.549, 788373619, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 2088, ThreadId = 2812, ThreadState = Wait, ThreadWaitReason = UserRequest

    I, 3856, 14, 2010/08/05, 15:00:21.449, 791597006, QTAgent32.exe, Playback - < WaitForReady mechanism is called for: >

    I, 3856, 14, 2010/08/05, 15:00:21.450, 791602067, QTAgent32.exe, ThreadInfo : GetThreadWaitReason : ProcId = 2088, ThreadId = 2812, ThreadState = Wait, ThreadWaitReason = UserRequest

    I, 3856, 14, 2010/08/05, 15:00:21.796, 792838025, QTAgent32.exe, Playback - Element Found: ;[MSAA, VisibleOnly]ControlType='Client' && Name='Untitled Message';[MSAA, VisibleOnly]ControlType='Client' && Name='Message'

    W, 3856, 14, 2010/08/05, 15:00:21.796, 792839316, QTAgent32.exe, PERF WARNING: FindAllDescendents: took 7587 ms. Expected it to take maximum 500 ms.

    How can i fix this one, because no matter that it's failing the test is going ok. Where and on what need to focus so that can speed up that search.

    Your help will be highly appreciated.

    Regards,

    Kaloyan

     

     

     

     

    Thursday, August 05, 2010 2:52 PM

Answers

  • The CodedUI Test playback engine search has an intricate logic. In brief, it tries to search for TopLevelWindow first and then does another pass to search for controls within the matched top level window. Depending on the level of accessibility support in the application, the QueryID (a.k.a. search condition) generated may or may not be good enough during recording. To limit the search path, you may try extending the QueryId hierarchy.

    For example, a {TLE (TopLevelElement) -> A ->B } search condition will be slower to find match compared to {TLE (TopLevelElement) -> X -> A ->B } since the search will be restricted to the subtree under X. However, at the same time, there are resilience issues associated with extending the QueryId. What if the control 'X' is removed from the application at later point of time? The search "may" fail or be too slow. I say "may" because there is an SkipIntermediateElements playback setting which can be used to ignore all intermediate controls and search B directly under TLE. This is the exact reason you are seeing this error message:

    W, 3856, 14, 2010/08/05, 15:00:20.034, 786532257, QTAgent32.exe, Playback - [WARNING] Internal warning: Element "[MSAA, VisibleOnly]ControlType='Client' && Name='Untitled Message'" was not found, so all intermediate elements were ignored. To improve performance replace this element Id with another Id or exclude it from QueryId. If this element is the target element, replace or remove intermediate elements

    The whole idea is to keep an "ideal" search hierarchy to keep a balance between per and resilience.

    There are other factors which could affect the performance of search too. 

    1. Element WFR is one such reason. If the control is busy running in UI thread, there will be delays. There is a WaitForReady setting in playback.playbacksetting which you can try tweaking around, but again be sure what you are doing, else there can be unexpected issues.

    2. If you application is minimized, the search attempts to find the target control within minimized windows in second pass.

    3. If the top level window title is dynamic, SmartMatch would kick in at a later pass. [This can also be tweaked in playback.playbacksettings]

    Hope these information help.

     

    Friday, August 06, 2010 3:38 AM
  • "You mention  "I say "may" because there is an SkipIntermediateElements playback setting which can be used to ignore all intermediate controls and search B directly under TLE" and i'd like to ask whether such search will help ignoring the other elements. How is this affecting on performance. Is it going to be slow?"

    -- No. It is infact set to true. The issue is, it can give some false positives. For example, say one hierarhcy is TLE -> X - Y and there is another hierarchy TLE -> Z -> Y. If you record on the second Y and SkipIntermediate is set to true (a.k.a. Playback.PlaybackSetting.MatchExactHierarhcy is set to false), then you can get the match for first Y (ONLY IF SEARCH FOR control 'Z' FAILS). SkipIntermediateElements is used as a fallback in second pass of search, not in first pass.

    "is this what you meant by writing for the WFR and why should i use global playback settings, can i use control.WaitForControlReady() ?"

    -- Implicitly, the Coded UI Test playback engine does a WaitForControlReady before performing actions. What I mentioned earlier was, you can disable this WFR if it is slowing things too much. But there is not always guarantee that the subsequent action will work.

    "Also i'm seeing that for the same tests set execution i'm getting different PERF warning values for the same actions. Some time it is 8 seconds next run it is 16. The machine is not loaded only the tests are running."

    -- Check the logs. You can figure from timestamp which actions are taking more time. Again, I think it has to be the WaitForReady.

    "There is a one more thing I have a WPF window that is showing on exact action. When i'm doing that action i use wpfWindow.WaitForControlExists() but an error message is showing and screenshot is recorded. Is this normal and how i can tweak in order to get rid of those errors in the logs ?"

    -- Try specifying a larger timeout value in the WaitForControlExists(timeout);

     

     

    Thursday, August 12, 2010 1:03 AM
  • Have you considered the possibility that the control might be taking different amount of time across different runs to become "ready". The logs essentially say that it timed out in that run because within a stipulated time the control did not come to ready state. Am I still missing something here?

     

    Tuesday, August 17, 2010 8:59 AM

All replies

  • The CodedUI Test playback engine search has an intricate logic. In brief, it tries to search for TopLevelWindow first and then does another pass to search for controls within the matched top level window. Depending on the level of accessibility support in the application, the QueryID (a.k.a. search condition) generated may or may not be good enough during recording. To limit the search path, you may try extending the QueryId hierarchy.

    For example, a {TLE (TopLevelElement) -> A ->B } search condition will be slower to find match compared to {TLE (TopLevelElement) -> X -> A ->B } since the search will be restricted to the subtree under X. However, at the same time, there are resilience issues associated with extending the QueryId. What if the control 'X' is removed from the application at later point of time? The search "may" fail or be too slow. I say "may" because there is an SkipIntermediateElements playback setting which can be used to ignore all intermediate controls and search B directly under TLE. This is the exact reason you are seeing this error message:

    W, 3856, 14, 2010/08/05, 15:00:20.034, 786532257, QTAgent32.exe, Playback - [WARNING] Internal warning: Element "[MSAA, VisibleOnly]ControlType='Client' && Name='Untitled Message'" was not found, so all intermediate elements were ignored. To improve performance replace this element Id with another Id or exclude it from QueryId. If this element is the target element, replace or remove intermediate elements

    The whole idea is to keep an "ideal" search hierarchy to keep a balance between per and resilience.

    There are other factors which could affect the performance of search too. 

    1. Element WFR is one such reason. If the control is busy running in UI thread, there will be delays. There is a WaitForReady setting in playback.playbacksetting which you can try tweaking around, but again be sure what you are doing, else there can be unexpected issues.

    2. If you application is minimized, the search attempts to find the target control within minimized windows in second pass.

    3. If the top level window title is dynamic, SmartMatch would kick in at a later pass. [This can also be tweaked in playback.playbacksettings]

    Hope these information help.

     

    Friday, August 06, 2010 3:38 AM
  • Hello Thank you very much for the info i have more questions.

    You mention  "I say "may" because there is an SkipIntermediateElements playback setting which can be used to ignore all intermediate controls and search B directly under TLE" and i'd like to ask whether such search will help ignoring the other elements. How is this affecting on performance. Is it going to be slow?

    About point  1. Element WFR is one such reason. If the control is busy running in UI thread, there will be delays. There is a WaitForReady setting in playback.playbacksetting which you can try tweaking around, but again be sure what you are doing, else there can be unexpected issues.

    I'm seeing such an error messages

    W, 3852, 14, 2010/08/10, 11:01:49.908, 1336666010, QTAgent32.exe, Playback - [WARNING] Internal warning: Timeout for thread state based WFR expired. Consider calling SetRobustnessLevel(0) or SetRobustnessLevelEx with proper parameters

    W, 3852, 14, 2010/08/10, 11:02:50.170, 1552376723, QTAgent32.exe, Playback - [WARNING] Internal failure: Timeout for process performance counters based WFR expired. Consider calling SetRobustnessLevel(0), SetRobustnessLevel(1) or SetRobustnessLevelEx with proper parameters

    W, 3852, 14, 2010/08/10, 11:03:50.550, 1768508562, QTAgent32.exe, Playback - [WARNING] Internal warning: Timeout for thread state based WFR expired. Consider calling SetRobustnessLevel(0) or SetRobustnessLevelEx with proper parameters

    W, 3852, 14, 2010/08/10, 11:04:50.629, 1983566375, QTAgent32.exe, Playback - [WARNING] Internal failure: Timeout for process performance counters based WFR expired. Consider calling SetRobustnessLevel(0), SetRobustnessLevel(1) or SetRobustnessLevelEx with proper parameters

     

    is this what you meant by writing for the WFR and why should i use global playback settings, can i use control.WaitForControlReady() ?

    Also i'm seeing that for the same tests set execution i'm getting different PERF warning values for the same actions. Some time it is 8 seconds next run it is 16. The machine is not loaded only the tests are running.

    There is a one more thing I have a WPF window that is showing on exact action. When i'm doing that action i use wpfWindow.WaitForControlExists() but an error message is showing and screenshot is recorded. Is this normal and how i can tweak in order to get rid of those errors in the logs ? The error is

    W, 3852, 14, 2010/08/10, 11:19:02.890, 5034270132, QTAgent32.exe, Playback - [WARNING] Internal warning: Window Not Found: ControlType='Window' && Name='Login' && ClassName=>'HwndWrapper'

    E, 3852, 14, 2010/08/10, 11:19:02.891, 5034271186, QTAgent32.exe, Playback - {11} [FAILED] Function ElementFetcher::FindScreenElement failed to locate UI element (Searching: ;ControlType='Window' && Name='Login' && ClassName=>'HwndWrapper') (The object specified was not found.)

     

     

     

    Wednesday, August 11, 2010 6:49 AM
  • "You mention  "I say "may" because there is an SkipIntermediateElements playback setting which can be used to ignore all intermediate controls and search B directly under TLE" and i'd like to ask whether such search will help ignoring the other elements. How is this affecting on performance. Is it going to be slow?"

    -- No. It is infact set to true. The issue is, it can give some false positives. For example, say one hierarhcy is TLE -> X - Y and there is another hierarchy TLE -> Z -> Y. If you record on the second Y and SkipIntermediate is set to true (a.k.a. Playback.PlaybackSetting.MatchExactHierarhcy is set to false), then you can get the match for first Y (ONLY IF SEARCH FOR control 'Z' FAILS). SkipIntermediateElements is used as a fallback in second pass of search, not in first pass.

    "is this what you meant by writing for the WFR and why should i use global playback settings, can i use control.WaitForControlReady() ?"

    -- Implicitly, the Coded UI Test playback engine does a WaitForControlReady before performing actions. What I mentioned earlier was, you can disable this WFR if it is slowing things too much. But there is not always guarantee that the subsequent action will work.

    "Also i'm seeing that for the same tests set execution i'm getting different PERF warning values for the same actions. Some time it is 8 seconds next run it is 16. The machine is not loaded only the tests are running."

    -- Check the logs. You can figure from timestamp which actions are taking more time. Again, I think it has to be the WaitForReady.

    "There is a one more thing I have a WPF window that is showing on exact action. When i'm doing that action i use wpfWindow.WaitForControlExists() but an error message is showing and screenshot is recorded. Is this normal and how i can tweak in order to get rid of those errors in the logs ?"

    -- Try specifying a larger timeout value in the WaitForControlExists(timeout);

     

     

    Thursday, August 12, 2010 1:03 AM
  • Thank you very much, comments inline.

     

    "There is a one more thing I have a WPF window that is showing on exact action. When i'm doing that action i use wpfWindow.WaitForControlExists() but an error message is showing and screenshot is recorded. Is this normal and how i can tweak in order to get rid of those errors in the logs ?"

    -- Try specifying a larger timeout value in the WaitForControlExists(timeout);

    The control is waited and finally found this is what i was saying. The issue is that during that wait with WaitForControlExists at least one time it is error out like (I mean erroring in the log) that and taking screenshot. I've seen it always when I'm doing WaitForControlExists and it appears to me like a bug.

    Thursday, August 12, 2010 2:39 PM
  • What do you think is this expected ?

    Friday, August 13, 2010 1:12 PM
  • Have you considered the possibility that the control might be taking different amount of time across different runs to become "ready". The logs essentially say that it timed out in that run because within a stipulated time the control did not come to ready state. Am I still missing something here?

     

    Tuesday, August 17, 2010 8:59 AM
  • Hi Tapas,

    I am having "

    W, 3852, 14, 2010/08/10, 11:01:49.908, 1336666010, QTAgent32.exe, Playback - [WARNING] Internal warning: Timeout for thread state based WFR expired. Consider calling SetRobustnessLevel(0) or SetRobustnessLevelEx with proper parameters

    "

    at randam places during the playback. I don't understand why and how to get rid of it. Can you please help.


    Indrojeet

    Thursday, August 16, 2012 8:36 PM