Appium: Test execution is very slow on iOS 13

Created on 29 Oct 2019  Â·  70Comments  Â·  Source: appium/appium

The problem

  • I upgraded appium from 1.14 to 1.15.
  • My test execution on iOS 13 is much slower than iOS 12.
  • Finding an element takes 4-6 seconds now. (driver.find_element_by_accessibility_id)

see comments here: https://discuss.appium.io/t/updated-to-1-15-0-and-ios-13-1-and-tests-became-too-slow/28019
specifically https://discuss.appium.io/t/updated-to-1-15-0-and-ios-13-1-and-tests-became-too-slow/28019/6

Environment

  • Appium version (or git revision) that exhibits the issue: 1.15.1
  • Last Appium version that did not exhibit the issue (if applicable): unknown
  • Desktop OS/version used to run Appium: macOS mojave 10.14.6
  • Node.js version (unless using Appium.app|exe): v12.1.0
  • Npm or Yarn package manager: npm - 6.9.0
  • Mobile platform/version under test: 13.1.2
  • Real device or emulator/simulator: real device not simulator
  • Appium CLI or Appium.app|exe: CLI

Details

Where "foo_bar" is the accessibility to a visible element on screen that can be tapped
driver.find_element_by_accessibility_id("foo_bar").click()
takes several seconds on iOS 13, the same command against the same app on iOS 12 takes less than a second.

Link to Appium logs

still need to fill these out

Create a GIST which is a paste of your _full_ Appium logs, and link them here.
Do _NOT_ paste your full Appium logs here, as it will make this issue very long and hard to read!
If you are reporting a bug, _always_ include Appium logs!

ThirdParty XCUITest
Source
picture owlsnakes
👍3 ❤1

Most helpful comment

@cosminstirbu We are seeing something extremely similar to your case after just upgrading from Xcode 10.3 and iOS 12.2 to Xcode 11.3.1 and iOS 13.3

Often the app will wait 60-70 seconds for tapping

We are on Native iOS / Android apps

picture mrk-han on 3 Feb 2020
👍4

All 70 comments

It is appreciated if you could attach the log with showIOSLog and showXcodeLog caps so that we can take a look if the cause is xctest framework or Appium can improve it. Mostly, maybe Appium was waiting for the response by xctest framework.

KazuCocoa picture KazuCocoa on 29 Oct 2019

Is the target element(s) inside a web view?

mykola-mokhnach picture mykola-mokhnach on 29 Oct 2019

@mykola-mokhnach no webview.

this is RE standard UIButtons

I will attach logs before EOD

owlsnakes picture owlsnakes on 29 Oct 2019

If this is a native app then make sure it stays in idle state. This is the requirement for XCTest to be able to get a snapshot.

mykola-mokhnach picture mykola-mokhnach on 29 Oct 2019

@KazuCocoa do you have a more private way of sharing docs/logs?
there is sometimes sensitive data in the logs.
I can attempt to scrub the logs doing a find & replace, but would have higher confidence if I could share them privately.

owlsnakes picture owlsnakes on 29 Oct 2019

If this is a native app then make sure it stays in idle state. This is the requirement for XCTest to be able to get a snapshot.

It is native app, sorry I should have included that.

Are you referring the snapshot of the View Hierarchy?
how would I ensure that the app stays in idle state?

owlsnakes picture owlsnakes on 29 Oct 2019

Are you referring the snapshot of the View Hierarchy?

I cannot say for sure, since this is in XCTest internals, which is a blackbox for us.

how would I ensure that the app stays in idle state?

Most likely by having the application source with XCode profiling tools.

mykola-mokhnach picture mykola-mokhnach on 29 Oct 2019

I encountered the slowness issue too. For example, one test case used to take 8 minutes to finish on Appium 1.13.0, now it takes 12 minutes using Appium 1.15.1 when I have to run over iOS 13.1, although it runs smoothly. Not sure if you need logs or not, and I could not get my old logs, since Appium 1.13 is not working on my mac anymore.

automationpss picture automationpss on 29 Oct 2019

I created a small 1 button app and will provide logs shortly.

owlsnakes picture owlsnakes on 29 Oct 2019

+1
Also noticed this, running the same tests against iOS 12.4 and iOS 13 , the test-suite takes much longer for the latter. I am using appium 1.16.0-beta.1 and testing both a native and a hybrid app - in both cases the iOS 13 tests take longer to complete.

eleni-salamani picture eleni-salamani on 30 Oct 2019

I upgraded to catalina and executing command on simulators with ios (10,11,12) became extremely slow. Fyi, We have a react-native app.
I tried following to understand but didn't help

  1. Use xcode 10.x and try iOS emulators with iOs (10-12)
  2. Ran tests on appium 1,4 and ,1.5 but no cuange in speed
  3. Built app with xcode 11 but no impact

It seems the problem is when performing actions on simulators.
When using app without appium like user clicking on buttons etcs works fine with any delays in actions

hunzai picture hunzai on 1 Nov 2019

Could you attach the appium server log with enabling showIOSLog showXcodeLog?
They may help to detect if the cause is inside XCTest framework or somewhere

And we already observed issues interactions against elements inside UIWebKit does not work well on iOS 13 in XCTest framework layer(Apple side) since the UIWebKit had been deprecated on iOS 13

KazuCocoa picture KazuCocoa on 2 Nov 2019

Or if someone could run test the interactions via pure XCTest directly if it works well like https://github.com/appium/appium/issues/13455#issuecomment-544117051 , it is very helpful to detect the cause.

KazuCocoa picture KazuCocoa on 2 Nov 2019

Is the target element(s) inside a web view?

Hi @mykola-mokhnach, I have the same issue on an element in webview, input text to element in webview is very slow, inputing 17 characters takes 1 minute and 26 seconds.
`2019-11-05 17:19:25:219 - [debug] [WD Proxy] Proxying [POST /element/DA020000-0000-0000-C769-010000000000/value] to [POST http://localhost:8100/session/4E09AFE6-5E02-4067-8436-6C1376452DAE/element/DA020000-0000-0000-C769-010000000000/value] with body: {"value":["t","e","s","t"," ","n","o","t","e"," ","i","t","a","l","i","c","s"],"text":"test note italics"}

2019-11-05 17:20:51:013 - [debug] [WD Proxy] Got response with status 200: {"value":null,"sessionId":"4E09AFE6-5E02-4067-8436-6C1376452DAE"}`

maggie5750 picture maggie5750 on 5 Nov 2019
👍3

I've encountered this as well.

The only bit of extra insight i can offer is that the slowdown is very noticeable after you perform a scroll.

So in other words, if i have to scroll to find an element (say a button), then, in my case, the test needds ~7-8 minutes to find the button.

"waitForQuiescence" was set to false (no improvement), "useJSONSource" was set to true (no improvement).

All this was observed on a native app on an iOS Simulator.

Hope it helps! :D

Markaleth picture Markaleth on 5 Nov 2019

here is part of showIOSLog

[W3C (9f1cdb97)] Encountered internal error running command: NoSuchDriverError: A session is either terminated or not started [W3C (9f1cdb97)] at asyncHandler (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/appium-base-driver/lib/protocol/protocol.js:252:15) [W3C (9f1cdb97)] at asyncHandler (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/appium-base-driver/lib/protocol/protocol.js:432:15) [W3C (9f1cdb97)] at Layer.handle [as handle_request] (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/layer.js:95:5) [W3C (9f1cdb97)] at next (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/route.js:137:13) [W3C (9f1cdb97)] at Route.dispatch (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/route.js:112:3) [W3C (9f1cdb97)] at Layer.handle [as handle_request] (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/layer.js:95:5) [W3C (9f1cdb97)] at /Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:281:22 [W3C (9f1cdb97)] at param (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:354:14) [W3C (9f1cdb97)] at param (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:365:14) [W3C (9f1cdb97)] at Function.process_params (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:410:3) [W3C (9f1cdb97)] at next (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:275:10) [W3C (9f1cdb97)] at logger (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/morgan/index.js:144:5) [W3C (9f1cdb97)] at Layer.handle [as handle_request] (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/layer.js:95:5) [W3C (9f1cdb97)] at trim_prefix (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:317:13) [W3C (9f1cdb97)] at /Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:284:7 [W3C (9f1cdb97)] at Function.process_params (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:335:12) [W3C (9f1cdb97)] at next (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:275:10) [W3C (9f1cdb97)] at /Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/body-parser/lib/read.js:130:5 [W3C (9f1cdb97)] at invokeCallback (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/raw-body/index.js:224:16) [W3C (9f1cdb97)] at done (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/raw-body/index.js:213:7) [W3C (9f1cdb97)] at IncomingMessage.onEnd (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/raw-body/index.js:273:7) [W3C (9f1cdb97)] at IncomingMessage.emit (events.js:182:13) [W3C (9f1cdb97)] at endReadableNT (_stream_readable.js:1090:12) [W3C (9f1cdb97)] at process._tickCallback (internal/process/next_tick.js:63:19) [HTTP] <-- DELETE /wd/hub/session/9f1cdb97-0458-4f48-9a09-7cd0f8511b62 404 3 ms - 3235 [HTTP] [HTTP] --> DELETE /wd/hub/session/9f1cdb97-0458-4f48-9a09-7cd0f8511b62 [HTTP] {} [W3C (9f1cdb97)] Encountered internal error running command: NoSuchDriverError: A session is either terminated or not started [W3C (9f1cdb97)] at asyncHandler (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/appium-base-driver/lib/protocol/protocol.js:252:15) [W3C (9f1cdb97)] at asyncHandler (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/appium-base-driver/lib/protocol/protocol.js:432:15) [W3C (9f1cdb97)] at Layer.handle [as handle_request] (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/layer.js:95:5) [W3C (9f1cdb97)] at next (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/route.js:137:13) [W3C (9f1cdb97)] at Route.dispatch (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/route.js:112:3) [W3C (9f1cdb97)] at Layer.handle [as handle_request] (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/layer.js:95:5) [W3C (9f1cdb97)] at /Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:281:22 [W3C (9f1cdb97)] at param (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:354:14) [W3C (9f1cdb97)] at param (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:365:14) [W3C (9f1cdb97)] at Function.process_params (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:410:3) [W3C (9f1cdb97)] at next (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:275:10) [W3C (9f1cdb97)] at logger (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/morgan/index.js:144:5) [W3C (9f1cdb97)] at Layer.handle [as handle_request] (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/layer.js:95:5) [W3C (9f1cdb97)] at trim_prefix (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:317:13) [W3C (9f1cdb97)] at /Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:284:7 [W3C (9f1cdb97)] at Function.process_params (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:335:12) [W3C (9f1cdb97)] at next (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/express/lib/router/index.js:275:10) [W3C (9f1cdb97)] at /Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/body-parser/lib/read.js:130:5 [W3C (9f1cdb97)] at invokeCallback (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/raw-body/index.js:224:16) [W3C (9f1cdb97)] at done (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/raw-body/index.js:213:7) [W3C (9f1cdb97)] at IncomingMessage.onEnd (/Applications/Appium.app/Contents/Resources/app/node_modules/appium/node_modules/raw-body/index.js:273:7) [W3C (9f1cdb97)] at IncomingMessage.emit (events.js:182:13) [W3C (9f1cdb97)] at endReadableNT (_stream_readable.js:1090:12) [W3C (9f1cdb97)] at process._tickCallback (internal/process/next_tick.js:63:19) [HTTP] <-- DELETE /wd/hub/session/9f1cdb97-0458-4f48-9a09-7cd0f8511b62 404 3 ms - 3235 [HTTP] [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.717 Df testmanagerd[13848:34b45] 15:01:03.718 testmanagerd[13848:215877] Got snapshot for {pid=16102} {uid=[ID:9999 hash:0x7cb8facc40000000]} [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.717 Df testmanagerd[13848:34b45] 15:01:03.718 testmanagerd[13848:215877] Restored original AX timeout 15.0s (axerror? 0) [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.719 Df testmanagerd[13848:34b45] 15:01:03.720 testmanagerd[13848:215877] App orientation is 0 (not portrait) and UITextEffectsWindow window Window, 0x7ff8b375bd30 is not main window [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.719 Df testmanagerd[13848:34b45] 15:01:03.720 testmanagerd[13848:215877] Leaving frame unchanged for Window, 0x7ff8b375bd30: either already correct or we can't detect it. [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.720 Df testmanagerd[13848:34b45] 15:01:03.720 testmanagerd[13848:215877] App orientation is 0 (not portrait) and UIStatusBarWindow window Window, 0x7ff8b3759840 is not main window [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.720 Df testmanagerd[13848:34b45] 15:01:03.720 testmanagerd[13848:215877] Leaving frame unchanged for Window, 0x7ff8b3759840: either already correct or we can't detect it. [HTTP] <-- DELETE /wd/hub/session/9f1cdb97-0458-4f48-9a09-7cd0f8511b62 - - ms - - [HTTP] [Xcode] t = 95.82s Find: Descendants matching type Sheet [Xcode] [Xcode] t = 95.83s Terminate com.yyy.app.yyy:15903 [Xcode] [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.739 Df testmanagerd[13848:34b45] 15:01:03.739 testmanagerd[13848:215877] Terminating com.yyy.app.yyy [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.741 Df SpringBoard[11727:36144] [com.apple.FrontBoard:Common] [com.yyy.app.yyy] Executing termination for reason killed for non-specific reason with request: [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.741 E SpringBoard[11727:36148] [com.apple.UIKit:KeyboardArbiter] HW kbd: Failed to set (null) as keyboard focus [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.741 Df SpringBoard[11727:36147] [com.apple.UserNotifications:Connections] connection invalidated [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.755 Df mediaremoted[11717:2c160] [com.apple.amp.mediaremote:MediaRemote] Client invalidated. [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.756 Df mediaremoted[11717:2c160] [com.apple.amp.mediaremote:ExternalDevice] [ExternalDeviceServer] Removing television endpoint for client [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.756 Df mediaremoted[11717:2c160] [com.apple.amp.mediaremote:MediaRemote] [MRDNowPlayingOriginClient] Removing now playing client <_MRNowPlayingClientProtobuf: 0x7fdbdf70adc0> { [IOSSimulatorLog] [IOS_SYSLOG_ROW] bundleIdentifier = "com.apple.WebKit"; [IOSSimulatorLog] [IOS_SYSLOG_ROW] processIdentifier = 16102; [IOSSimulatorLog] [IOS_SYSLOG_ROW] processUserIdentifier = 1576642196; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.756 Df mediaremoted[11717:2c160] [com.apple.amp.mediaremote:MediaRemote] [MRDNowPlayingClient] Updating displayName from (null) to (null) for path origin-iOS Simulator-1280262988/client-com.apple.WebKit-16102/player-(null) [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.756 Df mediaremoted[11717:2c160] [com.apple.amp.mediaremote:MediaRemote] [MRDNowPlayingClient] Updating parentAppBundleIdentifier from (null) to (null) for path origin-iOS Simulator-1280262988/client-com.apple.WebKit-16102/player-(null) [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.802 E backboardd[11731:35691] [com.apple.BaseBoard:Common] Unable to get short BSD proc info for 15903: No such process [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.803 E mediaremoted[11717:2c160] [com.apple.launchservices:default] Error getting name for com.apple.WebKit: Error Domain=NSOSStatusErrorDomain Code=-50 "(null)" [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.804 Df mediaremoted[11717:2c160] [com.apple.amp.mediaremote:MediaRemote] [MRDNowPlayingClient] Initializing displayName to (null) for path origin-iOS Simulator-1280262988/client-com.apple.WebKit-16102/player-(null) [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.803 E backboardd[11731:35691] [com.apple.BaseBoard:Common] Unable to get proc info for 15903: Undefined error: 0 [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.804 Df mediaremoted[11717:2c160] [com.apple.amp.mediaremote:MediaRemote] Removing client [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.804 A mediaremoted[11717:2c160] (CoreFoundation) Sending Updated Preferences to System CFPrefsD [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.805 Df assertiond[11734:352e4] [com.apple.assertiond:process_info] [yyy:15903] Port death watcher fired. [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.805 Df assertiond[11734:352e4] [com.apple.assertiond:process_assertion] Server invalidated [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.805 Df assertiond[11734:352e4] [com.apple.assertiond:assertion] Client relinquished [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.805 Df assertiond[11734:352e4] [com.apple.assertiond:process_assertion] [yyy:15903] Ignoring assertion remove, because we are terminated or pending termination [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.805 Df assertiond[11734:352e4] [com.apple.assertiond:process_info] Process exited: [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.806 Df assertiond[11734:3614e] [com.apple.assertiond:process_info] [yyy:15903] Invalidating... [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.809 Df assertiond[11734:352e4] [com.apple.assertiond:process_info] Created BKApplicationStateServerClient for [11717:mediaremoted] -> [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.810 Df assertiond[11734:352e4] [com.apple.assertiond:process_info] Removed BKApplicationStateServerClient for [11717:mediaremoted] -> { [IOSSimulatorLog] [IOS_SYSLOG_ROW] interested apps = { [IOSSimulatorLog] [IOS_SYSLOG_ROW] com.apple.WebKit; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.810 Df mediaremoted[11717:2c160] [com.apple.amp.mediaremote:MediaRemote] Client invalidated. [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.811 Df mediaremoted[11717:2c160] [com.apple.amp.mediaremote:ExternalDevice] [ExternalDeviceServer] Removing television endpoint for client [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.811 Df mediaremoted[11717:2c160] [com.apple.amp.mediaremote:MediaRemote] [MRDNowPlayingOriginClient] Removing now playing client <_MRNowPlayingClientProtobuf: 0x7fdbdf108c70> { [IOSSimulatorLog] [IOS_SYSLOG_ROW] bundleIdentifier = "com.apple.WebKit"; [IOSSimulatorLog] [IOS_SYSLOG_ROW] processIdentifier = 16101; [IOSSimulatorLog] [IOS_SYSLOG_ROW] processUserIdentifier = 1576642196; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.811 Df mediaremoted[11717:2c160] [com.apple.amp.mediaremote:MediaRemote] [MRDNowPlayingClient] Updating displayName from (null) to (null) for path origin-iOS Simulator-1280262988/client-com.apple.WebKit-16101/player-(null) [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.811 Df mediaremoted[11717:2c160] [com.apple.amp.mediaremote:MediaRemote] [MRDNowPlayingClient] Updating parentAppBundleIdentifier from (null) to (null) for path origin-iOS Simulator-1280262988/client-com.apple.WebKit-16101/player-(null) [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.811 E mediaremoted[11717:2c160] [com.apple.launchservices:default] Error getting name for com.apple.WebKit: Error Domain=NSOSStatusErrorDomain Code=-50 "(null)" [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.812 Df mediaremoted[11717:2c160] [com.apple.amp.mediaremote:MediaRemote] [MRDNowPlayingClient] Initializing displayName to (null) for path origin-iOS Simulator-1280262988/client-com.apple.WebKit-16101/player-(null) [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.812 Df mediaremoted[11717:2c160] [com.apple.amp.mediaremote:MediaRemote] Removing client [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.812 A mediaremoted[11717:2c160] (CoreFoundation) Sending Updated Preferences to System CFPrefsD [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.813 Df assertiond[11734:3614f] [com.apple.assertiond:process_info] Created BKApplicationStateServerClient for [11717:mediaremoted] -> [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:03.814 Df assertiond[11734:3614f] [com.apple.assertiond:process_info] Removed BKApplicationStateServerClient for [11717:mediaremoted] -> { [IOSSimulatorLog] [IOS_SYSLOG_ROW] interested apps = { [IOSSimulatorLog] [IOS_SYSLOG_ROW] com.apple.WebKit; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.000 Df assertiond[11734:352e4] [com.apple.assertiond:process_info] [yyy:15903] Got exit context: [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.001 Df SpringBoard[11727:36148] [com.apple.FrontBoard:Common] exited. [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.001 Df assertiond[11734:352e4] Deleted job with label: UIKitApplication:com.yyy.app.yyy[0x990c][11734] [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.001 Df SpringBoard[11727:35ec1] [com.apple.FrontBoard:Common] [FBProcessManager] Removing: [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.001 Df assertiond[11734:3614f] [com.apple.assertiond:process_info] [yyy:15903] Terminating because the job-submitter has disconnected. [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.001 Df SpringBoard[11727:2bf52] [com.apple.FrontBoard.workspace:Common] Process exited: -> { [IOSSimulatorLog] [IOS_SYSLOG_ROW] stateAtExit = ; [IOSSimulatorLog] [IOS_SYSLOG_ROW] terminationRequest = ; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.002 Df assertiond[11734:352e4] [com.apple.assertiond:process_info] [yyy:15903] Deleted launchd job with label: UIKitApplication:com.yyy.app.yyy[0x990c][11734] [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.001 Df SpringBoard[11727:2bf52] [com.apple.SpringBoard.buttons:Lock] reconfigured lock button: [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.002 Df assertiond[11734:352e4] [com.apple.assertiond:process_info] [yyy:15903] Invalidation complete. [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.001 Df SpringBoard[11727:2bf52] [com.apple.SpringBoard:Common] Application process state changed for com.yyy.app.yyy: (null) [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.002 Df assertiond[11734:3614c] [com.apple.assertiond:process_info] Checking for deferred bootstrap request for com.yyy.app.yyy [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.003 Df SpringBoard[11727:2bf52] [com.apple.FrontBoard.workspace:Transaction] Running for transition request: [IOSSimulatorLog] [IOS_SYSLOG_ROW] { [IOSSimulatorLog] [IOS_SYSLOG_ROW] applicationContext = entities = { [IOSSimulatorLog] [IOS_SYSLOG_ROW] SBLayoutRolePrimary = ; [IOSSimulatorLog] [IOS_SYSLOG_ROW] }; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.003 Df SpringBoard[11727:2bf52] [com.apple.BackBoard:OrientationGlobal] Not animating wallpaper orientation to portrait (1) in 0.00 because it's already in that orientation [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.004 Df assertiond[11734:352e4] [com.apple.assertiond:process_info] [yyy:15903] Removing client: [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.005 Df assertiond[11734:352e4] [com.apple.assertiond:process_info] [yyy:15903] No clients remain. [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.003 Df testmanagerd[13848:3060b] 15:01:04.003 testmanagerd[13848:198155] AX Notification 1021 (0x7ff8b3501b70) [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.004 Df SpringBoard[11727:2bf52] [com.apple.SpringBoard:IdleTimer] SBIdleTimerGlobalCoordinator - _setIdleTimerWithDescriptor: reason:"SBAppDidEnterBackground"] [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.006 A locationd[11733:2bf54] CL: notifyClientsWithData (Fallback) [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.006 Df homed[11779:35996] [com.apple.HomeKit:app.monitor] Received app state changed with info { [IOSSimulatorLog] [IOS_SYSLOG_ROW] BKSApplicationStateAppIsFrontmost = 0; [IOSSimulatorLog] [IOS_SYSLOG_ROW] BKSApplicationStateExitReasonKey = 5; [IOSSimulatorLog] [IOS_SYSLOG_ROW] BKSApplicationStateExtensionKey = 0; [IOSSimulatorLog] [IOS_SYSLOG_ROW] SBApplicationStateDisplayIDKey = "com.yyy.app.yyy"; [IOSSimulatorLog] [IOS_SYSLOG_ROW] SBApplicationStateKey = 1; [IOSSimulatorLog] [IOS_SYSLOG_ROW] SBApplicationStateProcessIDKey = 15903; [IOSSimulatorLog] [IOS_SYSLOG_ROW] SBApplicationStateRunningReasonsKey = ( [IOSSimulatorLog] [IOS_SYSLOG_ROW] { [IOSSimulatorLog] [IOS_SYSLOG_ROW] SBApplicationStateRunningReasonAssertionIdentifierKey = Resume; [IOSSimulatorLog] [IOS_SYSLOG_ROW] SBApplicationStateRunningReasonAssertionReasonKey = 10000; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] ); [IOSSimulatorLog] [IOS_SYSLOG_ROW] SBMostElevatedStateForProcessID = 1; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.003 Df testmanagerd[13848:3060b] 15:01:04.004 testmanagerd[13848:198155] Calling handler for AX notification 1021:{ [IOSSimulatorLog] [IOS_SYSLOG_ROW] pid = 15903; [IOSSimulatorLog] [IOS_SYSLOG_ROW] suspended = 1; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.006 Df assertiond[11734:3614f] [com.apple.assertiond:assertion] -[BKAssertion dealloc] - <0x7fea04e06500> [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.006 Df testmanagerd[13848:3062a] 15:01:04.006 testmanagerd[13848:198186] Got application state update: com.yyy.app.yyy (15903) -> 1 [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.008 Df assertiond[11734:3614f] [com.apple.assertiond:process_info] Created BKApplicationStateServerClient for [11717:mediaremoted] -> [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.006 Df testmanagerd[13848:34b45] 15:01:04.007 testmanagerd[13848:215877] -[XCTestSession applicationWithBundleID:didUpdatePID:andState:] com.yyy.app.yyy 15903 1 [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.009 Df mediaremoted[11717:2c160] [com.apple.amp.mediaremote:MediaRemote] [MRDNowPlayingOriginClient] Reloaded now playing app from datasource: <_MRNowPlayingClientProtobuf: 0x7fdbdd5013e0> { [IOSSimulatorLog] [IOS_SYSLOG_ROW] processIdentifier = 0; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.009 Df assertiond[11734:3614f] [com.apple.assertiond:process_info] Removed BKApplicationStateServerClient for [11717:mediaremoted] -> [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.006 Df testmanagerd[13848:34b45] 15:01:04.007 testmanagerd[13848:215877] Target app was terminated; removing process assertion: 15903 [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.010 Df sharingd[11732:2c22e] [com.apple.sharing:Daemon] SystemUI changed: 0x0 -> 0x10 [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.008 Df SpringBoard[11727:2bf52] [com.apple.BackBoard:OrientationGlobal] Set wallpaper orientation source to SBUIController [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.008 Df SpringBoard[11727:2bf52] [com.apple.BackBoard:OrientationGlobal] Not animating wallpaper orientation to portrait (1) in 0.00 because it's already in that orientation [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.010 A SpringBoard[11727:36148] (CoreFoundation) Sending Updated Preferences to System CFPrefsD [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.013 A SpringBoard[11727:36148] (CoreFoundation) Loading Preferences From System CFPrefsD For Search List [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.013 Df SpringBoard[11727:2bf52] [com.apple.SpringBoard:IdleTimer] SBIdleTimerGlobalCoordinator - _setIdleTimerWithDescriptor: reason:"SBWorkspaceActiveProviderChanged:SBAppDidEnterForeground"] [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.015 Df SpringBoard[11727:2bf52] [com.apple.BackBoard:OrientationDevice] SB orientation locked: NO; user lock: NO, was stale: NO, orientation: unknown (0) overrides: NO, [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.018 Df SpringBoard[11727:2bf52] [com.apple.SpringBoard:StatusBarish] removing status bar settings assertion after 95.473972 seconds: { [IOSSimulatorLog] [IOS_SYSLOG_ROW] settings = ; [IOSSimulatorLog] [IOS_SYSLOG_ROW] level = app switcher; [IOSSimulatorLog] [IOS_SYSLOG_ROW] reason = App Switcher Visible; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.021 Df SpringBoard[11727:2bf52] [com.apple.SpringBoard:Common] Front display did change: (null) [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.024 Df SpringBoard[11727:2bf52] [com.apple.FrontBoard.workspace:Transaction] Root transaction complete: [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.025 A SpringBoard[11727:2bf52] [switcher snapshot cache] cache update requested [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.025 A SpringBoard[11727:2bf52] [switcher snapshot cache] update App Layout priority list [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.025 A SpringBoard[11727:2bf52] [switcher snapshot cache] cache disabled, priority are now default App Layouts [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.025 A SpringBoard[11727:2bf52] [switcher snapshot cache] purge low priority snapshots [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.025 A SpringBoard[11727:2bf52] [switcher snapshot cache] purge low priority snapshot requests [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.025 A SpringBoard[11727:2bf52] [switcher snapshot cache] enqueue snapshot request load if necessary [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.029 Df SpringBoard[11727:2bf52] [com.apple.SpringBoard:IdleTimer] SBIdleTimerGlobalCoordinator - _setIdleTimerWithDescriptor: reason:"SBWorkspaceActiveProviderChanged:SBApplicationSceneDestroyed"] [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.048 Df testmanagerd[13848:3060b] 15:01:04.048 testmanagerd[13848:198155] AX Notification 4002 (0x7ff8b3501b70) [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.048 Df testmanagerd[13848:3060b] 15:01:04.048 testmanagerd[13848:198155] Calling handler for AX notification 4002:{ [IOSSimulatorLog] [IOS_SYSLOG_ROW] controllerClass = SBMainWorkspaceApplicationSceneLayoutElementViewController; [IOSSimulatorLog] [IOS_SYSLOG_ROW] event = ViewDidDisappear; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.048 Df testmanagerd[13848:3060b] 15:01:04.049 testmanagerd[13848:198155] Got user testing notification with payload { [IOSSimulatorLog] [IOS_SYSLOG_ROW] controllerClass = SBMainWorkspaceApplicationSceneLayoutElementViewController; [IOSSimulatorLog] [IOS_SYSLOG_ROW] event = ViewDidDisappear; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.048 Df testmanagerd[13848:3060b] 15:01:04.049 testmanagerd[13848:198155] AX Notification 4002 (0x7ff8b3501b70) [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.049 Df testmanagerd[13848:3060b] 15:01:04.049 testmanagerd[13848:198155] Calling handler for AX notification 4002:{ [IOSSimulatorLog] [IOS_SYSLOG_ROW] controllerClass = SBDeviceApplicationSceneViewController; [IOSSimulatorLog] [IOS_SYSLOG_ROW] event = ViewDidDisappear; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.049 Df testmanagerd[13848:3060b] 15:01:04.049 testmanagerd[13848:198155] Got user testing notification with payload { [IOSSimulatorLog] [IOS_SYSLOG_ROW] controllerClass = SBDeviceApplicationSceneViewController; [IOSSimulatorLog] [IOS_SYSLOG_ROW] event = ViewDidDisappear; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.049 Df testmanagerd[13848:3060b] 15:01:04.050 testmanagerd[13848:198155] AX Notification 4002 (0x7ff8b3501b70) [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.049 Df testmanagerd[13848:3060b] 15:01:04.050 testmanagerd[13848:198155] Calling handler for AX notification 4002:{ [IOSSimulatorLog] [IOS_SYSLOG_ROW] controllerClass = SBMainSwitcherViewController; [IOSSimulatorLog] [IOS_SYSLOG_ROW] event = ViewDidDisappear; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.050 Df testmanagerd[13848:3060b] 15:01:04.050 testmanagerd[13848:198155] Got user testing notification with payload { [IOSSimulatorLog] [IOS_SYSLOG_ROW] controllerClass = SBMainSwitcherViewController; [IOSSimulatorLog] [IOS_SYSLOG_ROW] event = ViewDidDisappear; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.050 Df testmanagerd[13848:3060b] 15:01:04.050 testmanagerd[13848:198155] AX Notification 4002 (0x7ff8b3501b70) [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.050 Df testmanagerd[13848:3060b] 15:01:04.051 testmanagerd[13848:198155] Calling handler for AX notification 4002:{ [IOSSimulatorLog] [IOS_SYSLOG_ROW] controllerClass = SBDeckSwitcherViewController; [IOSSimulatorLog] [IOS_SYSLOG_ROW] event = ViewDidDisappear; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [IOSSimulatorLog] [IOS_SYSLOG_ROW] 2019-11-06 15:01:04.051 Df testmanagerd[13848:3060b] 15:01:04.051 testmanagerd[13848:198155] Got user testing notification with payload { [IOSSimulatorLog] [IOS_SYSLOG_ROW] controllerClass = SBDeckSwitcherViewController; [IOSSimulatorLog] [IOS_SYSLOG_ROW] event = ViewDidDisappear; [IOSSimulatorLog] [IOS_SYSLOG_ROW] } [Xcode] t = 96.85s Wait for com.yyy.app.yyy to become Not Running [Xcode] [WD Proxy] Got response with status 200: { [WD Proxy] "value" : null, [WD Proxy] "sessionId" : "3FF45E34-A7A0-47B1-AAB4-37FC7C600C0F" [WD Proxy] } [DevCon Factory] Releasing connections for 4378754F-8BB4-42E0-B196-0552D483D238 device on any port number [DevCon Factory] Found cached connections to release: ["4378754F-8BB4-42E0-B196-0552D483D238:8100"] [DevCon Factory] Cached connections count: 0 [XCUITest] Not clearing log files. UseclearSystemFilescapability to turn on. [IOSSimulatorLog] Stopping iOS log capture [BaseDriver] Event 'quitSessionFinished' logged at 1573048864765 (15:01:04 GMT+0100 (CET)) [W3C (9f1cdb97)] Received response: null [W3C (9f1cdb97)] But deleting session, so not returning [W3C (9f1cdb97)] Responding to client with driver.deleteSession() result: null

hunzai picture hunzai on 6 Nov 2019

hm, it looks Xcode/XCTest side waited for the condition where Appium cannot influence.

[IOSSimulatorLog] [IOS_SYSLOG_ROW]     controllerClass = SBDeckSwitcherViewController;
[IOSSimulatorLog] [IOS_SYSLOG_ROW]     event = ViewDidDisappear;
[IOSSimulatorLog] [IOS_SYSLOG_ROW] }
[Xcode]     t =    96.85s Wait for com.yyy.app.yyy to become Not Running
[Xcode]
KazuCocoa picture KazuCocoa on 8 Nov 2019

Is it the same issue? 7-8 minutes vs 4-5 seconds.

EstevanBR picture EstevanBR on 10 Nov 2019

possibly. The slowness looks XCTest side (As Appium, Appium was waiting for the result by XCTest framework)

KazuCocoa picture KazuCocoa on 10 Nov 2019

If it helps more look at the following time to execute from xcode side

[debug] [W3C (5ed62a24)] at XCUITestDriver.doNativeFind (/Applications/Appium.app/Contents/Resources/app/node_modules/appium-xcuitest-driver/lib/commands/find.js:126:11) [debug] [W3C (5ed62a24)] at process._tickCallback (internal/process/next_tick.js:68:7) [info] [HTTP] <-- POST /wd/hub/session/5ed62a24-1ab2-482d-9dd1-a7a6b34ac753/element 404 535 ms - 459 [info] [HTTP] [info] [HTTP] --> POST /wd/hub/session/5ed62a24-1ab2-482d-9dd1-a7a6b34ac753/element [info] [HTTP] {"using":"accessibility id","value":"qa-settings"} [debug] [W3C (5ed62a24)] Calling AppiumDriver.findElement() with args: ["accessibility id","qa-settings","5ed62a24-1ab2-482d-9dd1-a7a6b34ac753"] [debug] [XCUITest] Executing command 'findElement' [debug] [BaseDriver] Valid locator strategies for this request: xpath, id, name, class name, -ios predicate string, -ios class chain, accessibility id [debug] [BaseDriver] Waiting up to 0 ms for condition [debug] [WD Proxy] Matched '/element' to command name 'findElement' [debug] [WD Proxy] Proxying [POST /element] to [POST http://localhost:8100/session/13DD7A9D-C355-4270-BC0F-5824A8EA4C5F/element] with body: {"using":"accessibility id","value":"qa-settings"} [error] [Xcode] t = 139.35s Find the Application 'com.yyy.app.xxx' [error] [Xcode] [error] [Xcode] t = 139.35s Requesting snapshot of accessibility hierarchy for app with pid 5792 [error] [Xcode] [error] [Xcode] t = 139.38s Checking existence of"qa-settings" Any [error] [Xcode] [error] [Xcode] t = 139.38s Requesting snapshot of accessibility hierarchy for app with pid 5792 [error] [Xcode]

hunzai picture hunzai on 11 Nov 2019

It's odd to me because XCUITests themselves aren't slow (maybe I need to verify that assumption).

do we need to open an issue w/ Apple?

owlsnakes picture owlsnakes on 13 Nov 2019

It is appreciated if you could have an app and a scenario with pure XCTest to compare the result/logs with appium. i.e. send key slowness case https://github.com/appium/appium/issues/13455#issuecomment-544117051

Enabling useFirstMatch via settings api will help if you compare _find element_ performance with XCUITest.
http://appium.io/docs/en/advanced-concepts/settings/

If we can find the cause in XCTest/Xcode side...

KazuCocoa picture KazuCocoa on 13 Nov 2019

So I don't think I'm able to provide that log. I hope someone else with a developer account can.

owlsnakes picture owlsnakes on 16 Nov 2019

It is appreciated if you could have an app and a scenario with pure XCTest to compare the result/logs with appium. i.e. send key slowness case #13455 (comment)

Enabling useFirstMatch via settings api will help if you compare _find element_ performance with XCUITest.
http://appium.io/docs/en/advanced-concepts/settings/

It is appreciated if you could have an app and a scenario with pure XCTest to compare the result/logs with appium. i.e. send key slowness case

You mean I should implement test in iOS XCUITest ? If yes then I have to learn first how to write UI tests in iOS., I am unfortunately not familiar with

hunzai picture hunzai on 17 Nov 2019

I created a simple app like below and measured the result.

test code

  • Appium (Ruby client, with useFirstMatch)
puts Benchmark.measure {
  @driver.find_element(:accessibility_id, 'Button'  ).click
}
  • XCTest (Swift) (Picked the first measurement since it could cache)
    func testExample() {
        measureMetrics([XCTPerformanceMetric.wallClockTime], automaticallyStartMeasuring: true, for: {
            XCUIApplication().buttons["Button"].tap()
        })
    }

Result

  • Xcode 11.2, iOS 13.2.2, iPhone 8 simulator

    • Appium (1.16-beta)



      • 0.62s



    • XCTest



      • 0.61s



  • Xcode 11.2, iOS 12.4, iPhone 8 simulator

    • Appium (1.16-beta)



      • 0.41s



    • XCTest



      • 0.60s



XCTest were almost the same. Appium became almost same time as vanilla XCTest in iOS13.
Appium was faster than XCTest for iOS 12.4...?

KazuCocoa picture KazuCocoa on 18 Nov 2019
🎉2

Awesome.
@KazuCocoa what about without useFirstMatch? - afaik that flag will change/break existing tests which is not ideal for us.

Thank you.

owlsnakes picture owlsnakes on 18 Nov 2019
👍1

@owlsnakes
useFirstMatch potentially causes https://github.com/appium/appium/issues/10101 , but not sure recent Xcode and iOS versions. The setting follows vailla XCTest's firstMatch. You can expect a sort of better performance in search elements. I set the setting to make the comparison fair.
(But my record in the above was no change with/without useFirstMatch)

KazuCocoa picture KazuCocoa on 19 Nov 2019

@owlsnakes
useFirstMatch potentially causes #10101 , but not sure recent Xcode and iOS versions. The setting follows vailla XCTest's firstMatch. You can expect a sort of better performance in search elements. I set the setting to make the comparison fair.
(But my record in the above was no change with/without useFirstMatch)

I am also facing same issue and useFirstMatch did not help. Created issue #13540 which was closed but it is still unresolved. If anyone finds a workaround/solution please share.

khubaib321 picture khubaib321 on 19 Nov 2019

@KazuCocoa I just realized, your results are from ios simulator.

Can you test on a real device?

owlsnakes picture owlsnakes on 21 Nov 2019

I will upgrade my device to ios 13.2.2, but on the current ios 13 version it has, it is still slow (note I am not using useFirstMatch)

owlsnakes picture owlsnakes on 21 Nov 2019

Roughly checked. I only have iPhone SE, iOS 13.2.2 so could not compare with the older version.

  • appium

    • with useFirstMatch



      • 0.81 ~ 0.85 sec



    • without useFirstMatch



      • 0.85 ~ 0.9 sec



  • xcuitest (Rarely the time took over a couple of seconds. Potentially Appium will also have a similar situation, I assume)

    • 0.7 ~ 0.8

KazuCocoa picture KazuCocoa on 21 Nov 2019

I encountered the slowness issue too. For example, one test case used to take 8 minutes to finish on Appium 1.13.0, now it takes 12 minutes using Appium 1.15.1 when I have to run over iOS 13.1, although it runs smoothly. Not sure if you need logs or not, and I could not get my old logs, since Appium 1.13 is not working on my mac anymore.

I'm really curious about the discrepancies here. Some users get slow performance w/ ios 13, others it seems to be fine.

EstevanBR picture EstevanBR on 21 Nov 2019

Closed as third party issue

mykola-mokhnach picture mykola-mokhnach on 26 Nov 2019

im also facing this, the test run really slow on 13.1 OS version. I checked the server log seems the driver didn't receive idle state from the app (or take longer time). everything fine in ios 12.

ganjarpanji picture ganjarpanji on 3 Dec 2019

I created a sample app in ios 13.

I found that finding elements was fast. it was clicking them that was slow.
until I used:

# idk which of these actually makes it faster.
"includeNonModalElements": True
"useFirstMatch": True
"snapshotTimeout": 1

after that clicking was very fast.

however my original app that my job requires to me automate did not see any such improvement. :(
Wish I could figure out why.

EDIT: scratch that, I commented out all 3 of those lines, and it was fast. idk why it was slow the first time.

owlsnakes picture owlsnakes on 10 Dec 2019
👍2 ❤1

Ok I've found that if you disable animations, ios 13 is faster.

func application(_ application: UIApplication, didFinishLaunchingWithOptions launchOptions: [UIApplication.LaunchOptionsKey: Any]?) -> Bool {
    UIView.setAnimationsEnabled(false)
}
owlsnakes picture owlsnakes on 31 Dec 2019
👀2

or... it was resolved by XCode 11.3. @ganjarpanji do you still see this on XCode 11.3?

owlsnakes picture owlsnakes on 31 Dec 2019
👀1

Ok I've found that if you disable animations, ios 13 is faster.

func application(_ application: UIApplication, didFinishLaunchingWithOptions launchOptions: [UIApplication.LaunchOptionsKey: Any]?) -> Bool {
    UIView.setAnimationsEnabled(false)
}

is this should be done in the app side?
will try out Xcode 11.3 today, thanks for the update :)

ganjarpanji picture ganjarpanji on 31 Dec 2019

is this should be done in the app side?

Yes, it is in AppDelegate as far as I know of.
The animation setting affects only the app scope. (I mean it does not affect system-wide, so we cannot add it in appium/WDA)

KazuCocoa picture KazuCocoa on 31 Dec 2019

The issue waiting app for idle still occurred with my app though (Xcode 11.3).
unfortunately, i dont have any access to the app code. even if i have it, i cannot disable the app animation only for testing.

ganjarpanji picture ganjarpanji on 31 Dec 2019

you might be able to disable it by Disabling Motion in the accessibility
settings on the device. I'm not %100 sure about that.
What I noticed was that even without the animations disabled, it seemed to
have better performance on XCode 11.3
or perhaps it was a new ios 13 version.

it's hard to know what changed, but I definitely see better performance now.

On Tue, Dec 31, 2019 at 12:20 AM Ganjar P M notifications@github.com
wrote:

The issue waiting app for idle still occurred with my app though (Xcode
11.3).
unfortunately, i dont have any access to the app code. even if i have it,
i cannot disable the app animation only for testing.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/appium/appium/issues/13503?email_source=notifications&email_token=AMB7ZNUXMTPIJYAEWNQKNGLQ3L6EJA5CNFSM4JGCETY2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEH34RVQ#issuecomment-569886934,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AMB7ZNSDA2OULEDOFHR2YMDQ3L6EJANCNFSM4JGCETYQ
.

owlsnakes picture owlsnakes on 31 Dec 2019

Hello,

We're reporting the same issue.

We have a sample project where you can have a look at the logs.

This is the log from running Appium 1.16.0 with Xcode 10.3 and iOS 12.4 simulator. As you can see the tests took 4.4814 minutes to run.

This is the log from running Appium 1.16.0 with Xcode 11.3.1 with iOS 13.3 simulator. As you can see this one took 6.5901 minutes to run.

By scanning the logs I've noticed that the /click commands on iOS 13 take significantly longer (many of them take over 1 second and there is one that took 61524 ms).

The project can be found here - https://github.com/FortechRomania/iOS-android-specflow-example.

cosminstirbu picture cosminstirbu on 30 Jan 2020

@cosminstirbu thanks, this information is already something to work with. Since iOS 13 Apple has fixed bugs in the native tap implementation we enabled it by default

If this is what is causing performance issues then it would be still possible to use touch actions as a workaround, such as instead of calling element.click() one could could create a new TouchActions instance and call its tap method with the particular element, like it is actually done in WDA. Try it and see if the performance is better then.

mykola-mokhnach picture mykola-mokhnach on 30 Jan 2020

Indeed there is a visible improvement after using new TouchAction(Driver).Tap(webElement).Perform(); instead of Click() (all occurrences were replaced).

As it can be seen here and here (two consecutive runs), the duration time dropped from 6.5901 minutes to approx 5.4 minutes.

There still is another minute that is spent (compared to iOS 12) can't really tell where :-?

We'll configure our real tests to use this approach as well and see what improvements this brings to a large codebase of Appium tests.

cosminstirbu picture cosminstirbu on 30 Jan 2020

In our production tests suite (184 tests), even after we've implemented the workaround, the duration increased from 2h 55m with Xcode 10.3 and iOS 12.4 to 5h 35m with Xcode 11.3.1 and iOS 13.3

cosminstirbu picture cosminstirbu on 2 Feb 2020
👍3

@cosminstirbu We are seeing something extremely similar to your case after just upgrading from Xcode 10.3 and iOS 12.2 to Xcode 11.3.1 and iOS 13.3

Often the app will wait 60-70 seconds for tapping

We are on Native iOS / Android apps

mrk-han picture mrk-han on 3 Feb 2020
👍4

After further investigations my team found something even more interesting (and silly).

In our production test suite, we were using iPhone 7 simulator. Unfortunately, as of Xcode 11, there isn't a default iPhone 7 simulator, so Appium created one (and teared it down) every test ..., adding more than one minute per test.

After switching to iPhone 8 simulator, everything is back to normal, we have 3h test execution time on iOS 13 with iPhone 8 simulator and Click() workaround.

cosminstirbu picture cosminstirbu on 4 Feb 2020
👍1

After further investigations my team found something even more interesting (and silly).

In our production test suite, we were using iPhone 7 simulator. Unfortunately, as of Xcode 11, there isn't a default iPhone 7 simulator, so Appium created one (and teared it down) every test ..., adding more than one minute per test.

After switching to iPhone 8 simulator, everything is back to normal, we have 3h test execution time on iOS 13 with iPhone 8 simulator and Click() workaround.

What about real devices?

dron4ik86 picture dron4ik86 on 4 Feb 2020
👍1

Our device tests still run on iOS 12 for now, however I don't except significant differences if we include the Click() workaround. Once we migrate to iOS 13 for our device tests as well, I'll come back with our results.

cosminstirbu picture cosminstirbu on 4 Feb 2020

Our device tests still run on iOS 12 for now, however I don't except significant differences if we include the Click() workaround. Once we migrate to iOS 13 for our device tests as well, I'll come back with our results.

hi @cosminstirbu , what is the stack of your team development, please? I meant is your team building native apps or hybrid apps? our team used the Ionic and I use the webdriverio appium to automate the apps, but after I upgraded real devices to iOS 13, the tests running very slow. I yet to implement the workaround solution. Thanks

anhmainvg picture anhmainvg on 4 Feb 2020
👍1

Hi @anhmainvg - we're building native apps, we don't interact with any embedded web views so I can't tell if those were impacted by the iOS 13 migration.

cosminstirbu picture cosminstirbu on 4 Feb 2020
👍1

I'll try implementing this .tap() workaround and report on the results.

Update:
In our particular scenario, we would scroll to a MobileElement and the simulator would hang for 70 seconds as the xcode logs would wait for app to be idle.

We implemented the click() workaround posted, and tried turning waitForQuiescence to false which seems to have helped this situation. Will continue to report results...

mrk-han picture mrk-han on 4 Feb 2020

@mykola-mokhnach Will Appium need a minor release to see https://github.com/appium/WebDriverAgent/pull/278 effects? Or can we pass in something to manually target that release or snapshot of WDA

mrk-han picture mrk-han on 4 Feb 2020

@mrk-han If you re-install the beta of appium (npm uninstall -g appium && npm install -g appium@beta) you ought to get the latest dependencies, including the change in appium-webdriveragent.

imurchie picture imurchie on 4 Feb 2020
👍2

After further investigations my team found something even more interesting (and silly).

In our production test suite, we were using iPhone 7 simulator. Unfortunately, as of Xcode 11, there isn't a default iPhone 7 simulator, so Appium created one (and teared it down) every test ..., adding more than one minute per test.

After switching to iPhone 8 simulator, everything is back to normal, we have 3h test execution time on iOS 13 with iPhone 8 simulator and Click() workaround.

IIRC the original issue (related to element lookup and/or clicking) only happened on real devices, the ios 13 slowness was not present when using simulator.

owlsnakes picture owlsnakes on 4 Feb 2020

@imurchie Thank you! This is great.

mrk-han picture mrk-han on 5 Feb 2020

FWIW, I was seeing very long click times doing some testing on an ios simulator yesterday. OSX 10.15.1, xcode 11.3.1, ios 13.3 iphone 8 simulator. Click times were taking ~ 120s.

Based on this thread I installed a ios 12.4 simulator and re-ran the tests. Clicks were fast, but somehow the initial driver start, took a long time. In other words the simulator would respond to clicks quickly, but only after a long delay starting up. The app was visible but the initial POST to /session took a long time to respond.

Next, I switched back to ios 13.3 simulator. Now things appear to be working -- fast startup and fast clicks.

FWIW.

SeanFelipe picture SeanFelipe on 24 Mar 2020
👍1

I'm still having this issue.

ios 13.3
appium 1.17

RIP I guess?

owlsnakes picture owlsnakes on 24 Apr 2020
👍1

I'm still having this issue.

ios 13.3
appium 1.17

RIP I guess?

the same problem...:(

dron4ik86 picture dron4ik86 on 27 Apr 2020

You can try out appium@rc which will be 1.17.1
It has commits until 2.14.2 in https://github.com/appium/WebDriverAgent/commits/master
Appium 1.17.0 has the version 2.7.4.

It is appreciated if you can detect the cause is XCTest framework side or Appium still facing

KazuCocoa picture KazuCocoa on 27 Apr 2020
👍2

Hi @KazuCocoa When will Appium 1.17.1 official version be released?

d-rai picture d-rai on 27 Apr 2020

You can try out appium@rc which will be 1.17.1
It has commits until 2.14.2 in https://github.com/appium/WebDriverAgent/commits/master
Appium 1.17.0 has the version 2.7.4.

It is appreciated if you can detect the cause is XCTest framework side or Appium still facing

Moving from appium 1.17 to 1.17.1-rc.1 made my test duration decreased from 146022ms to 21096ms.

Thank you

domignace picture domignace on 11 May 2020
👀1

You can try out appium@rc which will be 1.17.1
It has commits until 2.14.2 in https://github.com/appium/WebDriverAgent/commits/master
Appium 1.17.0 has the version 2.7.4.
It is appreciated if you can detect the cause is XCTest framework side or Appium still facing

Moving from appium 1.17 to 1.17.1-rc.1 made my test duration decreased from 146022ms to 21096ms.

Thank you

Hello! can you post the desired capabilities you are using?

owlsnakes picture owlsnakes on 11 May 2020

I'll try implementing this .tap() workaround and report on the results.

Update:
In our particular scenario, we would scroll to a MobileElement and the simulator would hang for 70 seconds as the xcode logs would wait for app to be idle.

We implemented the click() workaround posted, and tried turning waitForQuiescence to false which seems to have helped this situation. Will continue to report results...

So is this workaround in 1.17? or the latest rc?

owlsnakes picture owlsnakes on 11 May 2020

Here is an implementation of the workaround described by @mrk-han

def click(e: WebElement):
    TouchAction(e.parent).tap(e).perform()

WebElement.click = click

in the form of a pytest fixture (which will let you use the workaround without changing your scripts at all, assuming you use pytest)

import pytest

from appium.webdriver.common.touch_action import TouchAction
from appium.webdriver.webelement import WebElement


@pytest.fixture(scope="function", autouse=True)
def tap_workaround():
    def click(e: WebElement):
        # e.parent is an instance of WebDriver
        TouchAction(e.parent).tap(e).perform()

    WebElement.click = click
owlsnakes picture owlsnakes on 11 May 2020

You can try out appium@rc which will be 1.17.1
It has commits until 2.14.2 in https://github.com/appium/WebDriverAgent/commits/master
Appium 1.17.0 has the version 2.7.4.
It is appreciated if you can detect the cause is XCTest framework side or Appium still facing

Moving from appium 1.17 to 1.17.1-rc.1 made my test duration decreased from 146022ms to 21096ms.
Thank you

Hello! can you post the desired capabilities you are using?

My config file to launch the appium server: 

{
   "appium:platformName": "iOS",
   "appium:platformVersion": "13.4.1",
   "appium:deviceName": "iPhone",
   "appium:udid": "XXXXXXXX-XXXXXXXXXXXXXXXX",
   "appium:automationName": "XCUITest",
   "xcodeOrgId": "YYYYYYYYYY",
   "xcodeSigningId": "iPhone Developer: XXXXX YYYYY (ZZZZZZZZZZ)",
   "autoWebviewTimeout": 10000,
   "newCommandTimeout": 300000
}

I'm using webdriverio, here is the iosCaps from the caps.js file:

const iosCaps = {
  platformName: 'iOS',
  automationName: 'XCUITest',
  deviceName: process.env.IOS_DEVICE_NAME || 'iPhone',
  platformVersion: process.env.IOS_PLATFORM_VERSION || '13.4.1',
  app: undefined, // Will be added in tests
  udid: 'XXXXXXXX-XXXXXXXXXXXXXXXX',
  nativeWebTap: true,
};

And the server config part:

const serverConfig = {
  host: process.env.APPIUM_HOST || 'localhost',
  port: process.env.APPIUM_PORT || 4723,
  path: '/wd/hub',
  logLevel: 'debug'
  // logLevel: 'info'
};

My application is an hybrid application, once in the webview I don't use any button. The tests only gather text results from the web page.

domignace picture domignace on 12 May 2020

many thanks @KazuCocoa and @owlsnakes (for raising and struggling with this issue). My automation works again on iOS 13.4.1 after a very long time RIP

I have installed the latest appium 1.17.1 and run the WebdriverAgentRunner app (with the edited product bundle Identifier to replace the default one) instead of the previous running Integration App

anhmainvg picture anhmainvg on 18 May 2020
❤1

@anhmainvg

I don't want to assume anything so please correct me if I'm wrong.

When you say they "work" again, does that also mean that it's not slow? or is it still slow?

I haven't tried the latest official 1.17.1, but I did try the 1.17.1 rc 1, and I still had terribly slow performance.

owlsnakes picture owlsnakes on 18 May 2020

It is appreciated if you can detect the cause is XCTest framework side or Appium still facing

Why is this issue closed if we are not sure where the issue lies?

owlsnakes picture owlsnakes on 18 May 2020

hi @owlsnakes , it's not slow.

I don't use the workaround solution above.

I will continue to evaluate the performance. Here below is my log snippet and some results of execution

https://gist.github.com/anhmainvg/252eda58ae6328b4fe9dea7fd90f632c

results

anhmainvg picture anhmainvg on 19 May 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

andreiaionitoaiesv picture andreiaionitoaiesv  Â·  54Comments
suswari picture suswari  Â·  54Comments
ethanclose picture ethanclose  Â·  61Comments
wodeta33 picture wodeta33  Â·  58Comments
korenevichev picture korenevichev  Â·  55Comments