Webdriveragent: PageSource is extremely slow on combination of iOS 11 + Xcode 9 beta 6 + Appium 1.7.0 beta

[rajfidel]

The problem

PageSource retrieval is extremely slow on iOS 11 + Xcode 9 beta 6 (had issue on previous betas as well) + Appium 1.7.0 beta (Also had issues on previous 1.6.6 betas)

Got the page source of the Settings app (com.apple.Preferences) and looped it 5 times to get the total time as shown below for the various combinations:
iOS 11 beta 9 + 1.7.0 beta + xcode 9 beta 6 -> 1 min 53 sec, Appium Log with Device logs here
iOS 10.2.1 + 1.7.0 beta + xcode 9 beta 6 -> 0 min 14 sec, Appium Log with Device logs here
iOS 10.2.1 + 1.6.5 + xcode 8.3.3 -> 0 min 6 sec, Appium Log with Device logs here

Pagesource on iOS10 device performs twice as quickly on Appium 1.6.5 when compared to Appium 1.7.0 beta.
iOS 11 + Appium 1.7.0 beta combination is much more slower.

I understand that PageSource should not be used for local processing, and that Xpath can be terribly slow as well. However, in this case, we use it to log PageSource when the test runs into failures for debugging later.

Environment

• Appium version (or git revision) that exhibits the issue: 1.7.0 beta and above
• Last Appium version that did not exhibit the issue (if applicable): 1.6.5
• Desktop OS/version used to run Appium: mac OS Sierra 10.12.6
• Node.js version (unless using Appium.app|exe): 8.1.4
• Mobile platform/version under test: 11.0 beta 9
• Real device or emulator/simulator: real device
• Appium CLI or Appium.app|exe: Appium CLI

[shynkevich-alex]

the same

[cschabetsberger-micro-focus]

In our test app, the /source call also got a lot slower in iOS 11 + Xcode 9.0 (approxymately by the factor of 10 in comparison to iOS 10; both measured with shouldWaitForQuiescence=false). I did some debugging of the WDA and it seems that most of the time is spent in FBXPath.m::recordElementAttributes when reading out element.wdValue, element.wdName, element.wdLabel and element.wdRect. I had element.wdVisible hardcoded to true because that had issues in the past but that is probably slow as well. Do you have any ideas why this got so low?

[mykola-mokhnach]

@cschabetsberger-micro-focus You are 100% correct. Reading all these element attributes is very expensive operation (especially the _visible_ one). This PR should slightly improve the situation for xpath search (because each lookup should literally rebuild the source tree from scratch), but it cannot be applied for page source, since all attribute values should be shown there.

[shynkevich-alex]

When it will be merged?

[cschabetsberger-micro-focus]

I merged the PR into my local WDA copy in order to try it out and it seems to improve the performance significantly. A single getPageSource call takes now ~500ms instead of ~1sec after the first getPageSourc call. However, on iOS 10 a getPageSource call took ~100ms so this still got a lot slower (all test runs executed with shouldWaitForQuiescence=false). To me this looks like that most of the time is spent when XCTest determines element attributes, but I cannot tell for sure because I was not able to profile the code, maybe someone else is.

Could it be that there is a new waitForIdle mechanism that we are not yet aware of?

[mykola-mokhnach]

@cschabetsberger-micro-focus XCTest on Xcode9 SDK does not perform snapshotting anymore by default. Apple has removed it for performance reasons. However, it is also not possible to get the page source tree without it. So WDA team had to reenable snapshots support in XCTest preferences as a workaround. That is why the stuff is slower on iOS 11 in comparison to iOS 10/9.

[cschabetsberger-micro-focus]

@mykola-mokhnach thank you for this explanation!

I just did some more testing and noticed that the xcodebuild process seems to consume 1 core on my Mac when I execute the /source command in a loop. This was not the case on iOS 10. I looked through the open files by this xcodebuild process and found out that /private/var/folders/fs/jkgs9nkx3kqcnb7147x2b9y80000gp/T/com.apple.dt.XCTest/IDETestRunSession-F363628D-91F9-49DA-8F2A-CB81BEEA72F2/WebDriverAgentRunner-27C46427-4222-44ED-AEA5-E4D4387453ED/Session-WebDriverAgentRunner-2017-09-25_102453-gYR77B.log gets flooded with messages like "(LOG ARBITER) Discarding message, buffer is full." almost immediately after startup.

You can find the beginning of that log output here: https://pastebin.com/AaEw6dEb

The time between the "Discarding message" gets smaller and smaller and after some time it logs every single millisecond this log message. Could it be that every single attribute read operation in XCTest leads to some communication with the xcodebuild process on the Mac? Furthermore, is it possible that because of that communication with the xcodebuild process, the attribute read operation is so slow?

[akashkhandelwal]

Do we have any workaround for this. Due to this, finding elements for iOS 11 has become tedious for me. Kindly suggest an alternative to fetch the elements unless this gets resolved.

Thanks

[wrathtodd]

@akashkhandelwal If you are using Appium with Facebook Webdriver, try to switch to XCUItest driver. In my case it is still slower than the execution on iOS10, but at least not 2 times slower.

[rajfidel]

You can use iOS class chain and predicates to fetch elements. They are much faster than xpath.

[swapanchhabra]

@wrathtodd

If you are using Appium with Facebook Webdriver, try to switch to XCUItest driver.

We are also facing same issue and we are using facebook webdriver, please let me know how to switch to XCUItest driver for test executions.?

[wrathtodd]

@swachhab

I've used the following caps for that:

      :automationName => "XCUITest",
      :simpleIsVisibleCheck => true,
      :preventWDAAttachments => true

[swapanchhabra]

@wrathtodd thanks for prompt reply
but I am already using

automationName => "XCUITest"
in our code.

[swapanchhabra]

@wrathtodd you reproduced same issue with iOS11?

[wrathtodd]

@swachhab Our sample test suite was taking ~34 mins to execute on iOS 10 and for iOS 11 it becomes somethings like ~59 mins. I guess it is the ':simpleIsVisibleCheck => true' capability, that makes it faster, so that it result into ~43 minutes of execution time. Still longer than it was before, but at least not twice as long

[swapanchhabra]

Ok Thanks a ton @wrathtodd

[bearxc]

if simpleIsVisibleCheck set to true, there is side effect that scroll does not work when try to scroll to invisible component that are off screen ,

[marekcirkos]

Duplicate of https://github.com/facebook/WebDriverAgent/issues/639

[VTINFOJames]

Any progress on getPageSource() with iOS 11 on iPad's? getPageSource() never completes and my JUnit tests time out. I'm using XCUITest and Appium-Desktop 1.7.1 to test a Native application.

[VTINFOJames]

I pulled the WebDriverAgent project #804, replaced my existing WebDriverAgent folder in the Appium-Desktop app with the new version, in Terminal I navigated to the WebDriverAgent folder (Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/appium-xcuitest-driver/WebDriverAgent) and ran the command ./Scripts/bootstrap.sh to pull in dependencies, then opened the WebDriverAgent project in the WebDriverAgent folder, signed the WebDriverAgent components in Xcode and built them to the device (IntegrationApp, WebDriverAgentRunner, WebDriverAgentLib). getPageSource() is still very slow however, it works. The native app I am testing is very robust with many screens layered upon another; each with 1 to 100's of elements. So the slowness may be less of a problem on a less-complex iOS application. I am running Xcode 9.2, iOS 11.2, and Appium-Desktop version 1.2.7. See also #639.

[arunsharma07]

Hello Guys

Did we get any workaround related to getPageSource() slowness issue with iOS 11.2 iPad while using with appium 1.7.1 as terminal appium and appium 1.2.7 as desktop appium console app

Thanks in Advance

[dzaiats]

Hi guys! I found the solution. Use the capability useJSONSource=true. It makes getting of source 2x or 3x faster.