Find element command extremely slow in v4.21.1

[aksh-02]

We're using appium v1.21.0 for android app testing. Intermittently we notice find element commands taking ~20 seconds. We've reduced waitForIdleTimeout and that didn't reduce the time significantly. On debugging further through adb logcat logs

02-02 12:50:10.571  3339  3708 I appium  : channel read: POST /wd/hub/session/f75680dc-eae2-41f7-8f7b-fbf9b1769db1/element
02-02 12:50:10.572  3339  3708 I appium  : FindElement command
02-02 12:50:10.573  3339  3708 I appium  : method: 'xpath', selector: '//*[@text='All']', contextId: ''
02-02 12:50:10.574  3339  3708 I appium  : Waiting up to 3000ms for the device to idle
02-02 12:50:13.602  3339  3708 I appium  : The following attributes will be included to the page source: [text]
02-02 12:50:28.535  3339  3708 I appium  : Took 1ms to retrieve 1 matches for '//*[@text='All']' XPath query
02-02 12:50:28.537  3339  3708 I appium  : AppiumResponse: {\"sessionId\":\"f75680dc-eae2-41f7-8f7b-fbf9b1769db1\",\"value\":{\"ELEMENT\":\"09e05c03-0926-4220-9c1f-c8d383aa49ad\",\"element-6066-11e4-a52e-4f735466cecf\":\"09e05c03-0926-4220-9c1f-c8d383aa49ad\"}}

From these logs, I see the time is being taken in this part of the code

    public NodeInfoList findNodes(String xpathSelector, boolean multiple) {
        try {
            XPATH.compile(xpathSelector, Filters.element());
        } catch (IllegalArgumentException e) {
            throw new InvalidSelectorException(e);
        }

        try {
            RESOURCES_GUARD.acquire();
        } catch (InterruptedException e) {
            throw new UiAutomator2Exception(e);
        }
        try (InputStream xmlStream = toStream(true)) {
            final Document document = SAX_BUILDER.build(xmlStream);
            final XPathExpression<org.jdom2.Attribute> expr = XPATH
                    .compile(String.format("(%s)/@%s", xpathSelector, UI_ELEMENT_INDEX), Filters.attribute());
            final NodeInfoList matchedNodes = new NodeInfoList();

So It might be either toStream or SAX_BUILDER.build functions, but I'm not able to debug any further because of no Info logs there (wasn't able to change log-level to debug either)

Initially I though, since this was happening intermittently this might be a resource crunch issue, But I didn't see any such crunch while monitoring host or adb shell metrics.

This is my session create request body

{
  "customData": {},
  "desiredCapabilities": {
    "adbExecTimeout": "120000",
    "appActivity": "<activity>",
    "appPackage": "<pkg>",
    "autoAcceptAlerts": true,
    "automationName": "uiautomator2",
    "chromeOptions": {
      "args": [],
      "w3c": false
    },
    "chromedriverExecutable": "chromeDriver-103.0",
    "deviceName": "Galaxy Fold",
    "headless": false,
    "nativeWebScreenshot": true,
    "newCommandTimeout": 0,
    "orientation": "PORTRAIT",
    "platformName": "android",
    "platformVersion": "13",
    "udid": "emulator-5554",
    "uiautomator2ServerLaunchTimeout": "60000",
    "waitForIdleTimeout": 3000,
    "waitForQuiescence": false
  }
}

[mykola-mokhnach]

02-02 12:50:10.574 3339 3708 I appium : Waiting up to 3000ms for the device to idle 02-02 12:50:13.602 3339 3708 I appium : The following attributes will be included to the page source: [text] 02-02 12:50:28.535 3339 3708 I appium : Took 1ms to retrieve 1 matches for '//*[@text='All']' XPath query

Most likely this is an idling issue. You see the above wait times out after 3 seconds, which means the main UI thread is still busy. This is easy to validate if you just terminate the application under test and try to perform the lookup on any other system or third-party app control to make sure it is fast enough.

[mykola-mokhnach]

02-02 12:50:28.535 3339 3708 I appium : Took 1ms to retrieve 1 matches for '//*[https://github.com/text='All']' XPath query

This is the log for the internal xpath lookup performance, although it does not log how much time it takes to build the XML from the actual accessibility layer.

[aksh-02]

This is the log for the internal xpath lookup performance, although it does not log how much time it takes to build the XML from the actual accessibility layer.

right that's why I think the time is being taken here

        try (InputStream xmlStream = toStream(true)) {
            final Document document = SAX_BUILDER.build(xmlStream);

[aksh-02]

You see the above wait times out after 3 seconds, which means the main UI thread is still busy.

What can be done to optimize this. Also for more context, this seems to be working fine on a real device but is too slow on an emulator

[mykola-mokhnach]

https://www.reddit.com/r/androiddev/comments/m179hb/identify_when_the_application_is_doing_too_much/

[aksh-02]

although it does not log how much time it takes to build the XML from the actual accessibility layer.

would this also get affected by the UI thread being busy. Also, In that case should we not be seeing ANR errors.