search

ui5-community / wdi5

official UI5 end-to-end test framework for UI5 web-apps. wdi5 = Webdriver.IO + UI5 Test API
https://ui5-community.github.io/wdi5/
Apache License 2.0
102 stars 43 forks source link

call to get ui5 control is slow #196

Closed edvardas-kireilis closed 2 years ago

edvardas-kireilis commented 2 years ago

Describe the bug We started using wdi5 service in wdio tests and we noticed that it takes 1.2 or more second for any interaction with ui5 control to happen. I.e. to retrieve a proxy object of a Title or a Tile takes time. And after adding additional time logging I saw that most of the time is used waiting for sap.ui.test.RecordReplay.waitForUI5() function execution. This ui5 library function is checking if all the waiters are not waiting. That includes promise waiter which gets two primises just before calling waitForUI5(). One promise comes from puppeteer library and another from the waitForUI5 method itself.

Few questions come to mind while investigating this slow performance:

  1. Does anyone gets this slow performance (~1200ms) from the wdi5 browser.asControl function? I have checked that wdio DOM element access has very small 30-60ms response.
  2. Am I doing something wrong with my selectors or configuration?
  3. Could it be that that is another issue with wdi5 or there is a slow inherited waitForUI5 function logic in ui5 library.

Also I have switched from puppeteer to selenium driver and then only one promise was is _promiseWaiter object internal watch list. But that did not reduce delay of waitForUI5() execution.

To Reproduce Call browser.asControl() to get a proxy object of any ui5 control. It should take around 1.2 seconds.

Expected behavior I expect the control search to take 100ms or less.

vobu commented 2 years ago

Hi, first of all: thanks for providing detailed info and context: 👍 Please try the most recent wdi5 version 0.9.0-rc1: npm i wdio-ui5-service@latest we've done major rehaul work from 0.8 → 0.9; the RC1 is safe to use, no api signatures will change, only additions and eventual fixes will get in

edvardas-kireilis commented 2 years ago

Hi, thank you for fast response. I have tested this issue with 0.9.0-rc1 version. The issue persists.

Just to illustrate the performance issue I am adding changes which helped me to track the slow but. As you can see waitForUI5 takes around 1.2 seconds.

This is my changes to track time in getControl():

async function clientSide_getControl(controlSelector) {
    controlSelector = await Promise.resolve(controlSelector) // to plug into fluent async api
    return await browser.executeAsync((controlSelector, done) => {
        const printTime = (message) => {
            const d = new Date()
            console.log(`${d.getHours()}:${d.getMinutes()}:${d.getSeconds()}.${d.getMilliseconds()} -::- ${message}`)
        }
        const waitForUI5Options = Object.assign({}, window.wdi5.waitForUI5Options)
        if (controlSelector.timeout) {
            waitForUI5Options.timeout = controlSelector.timeout
        }
        printTime('Starting waitForUI5')
        window.bridge
            .waitForUI5(waitForUI5Options)
            .then(() => {
                printTime('Starting retrieving control')
                window.wdi5.Log.info("[browser wdi5] locating " + JSON.stringify(controlSelector))
                controlSelector.selector = window.wdi5.createMatcher(controlSelector.selector)
                const element = window.bridge.findDOMElementByControlSelector(controlSelector)
                printTime('Completed retrieving control')
                return element
            })
            .then((domElement) => {
                // window.wdi5.Log.info('[browser wdi5] control located! - Message: ' + JSON.stringify(domElement));
                // ui5 control
                printTime('Retrieving a control again')
                const ui5Control = window.wdi5.getUI5CtlForWebObj(domElement)
                printTime('Getting control id')
                const id = ui5Control.getId()
                printTime('Control id retrieved')
                window.wdi5.Log.info(`[browser wdi5] control with id: ${id} located!`)
                const aProtoFunctions = window.wdi5.retrieveControlMethods(ui5Control)
                // @type [String, String?, String, "Array of Strings"]
                done(["success", domElement, id, aProtoFunctions])
            })
            .catch((error) => {
                window.wdi5.Log.error("[browser wdi5] ERR: ", error)
                done(["error", error.toString()])
            })
    }, controlSelector)
}

module.exports = {
    clientSide_getControl
}

this is the console output:

2022-03-22 19:10:49.064699 FLP Bootstrap Scheduling Agent :: MODULE 'schedulingAgent' /undefined/ : Loading finished - FLPScheduler 
VM800:6 19:10:59.287 -::- Starting waitForUI5
VM800:6 19:11:0.499 -::- Starting retrieving control
Log.js?eval:456 2022-03-22 19:11:00.498100 [browser wdi5] locating {"forceSelect":true,"selector":{"controlType":"sap.m.GenericTile","properties":[{"header":"Product Explorer"}]},"wdio_ui5_key":"sap.m.GenericTile_-_-_-_[{\"header\":\"Product Explorer\"}]"} -  
Log.js?eval:456 2022-03-22 19:11:00.502000 Found a DOM reference for the control 'Element sap.m.GenericTile#__tile0'. Executing 'sap.ui.test.actions.Press' on the DOM element with ID '__tile0' -  sap.ui.test.actions.Press
VM800:6 19:11:0.503 -::- Completed retrieving control
VM800:6 19:11:0.503 -::- Retrieving a control again
VM800:6 19:11:0.503 -::- Getting control id
VM800:6 19:11:0.503 -::- Control id retrieved
Log.js?eval:456 2022-03-22 19:11:00.502699 [browser wdi5] control with id: __tile0 located! -  
VM820:6 19:11:0.664 -::- Starting waitForUI5
VM820:6 19:11:1.873 -::- Starting retrieving control
Log.js?eval:456 2022-03-22 19:11:01.872699 [browser wdi5] locating {"forceSelect":true,"selector":{"controlType":"sap.m.GenericTile","properties":[{"header":"Product Explorer"}]},"wdio_ui5_key":"sap.m.GenericTile_-_-_-_[{\"header\":\"Product Explorer\"}]"} -  
Log.js?eval:456 2022-03-22 19:11:01.874500 Found a DOM reference for the control 'Element sap.m.GenericTile#__tile0'. Executing 'sap.ui.test.actions.Press' on the DOM element with ID '__tile0' -  sap.ui.test.actions.Press
VM820:6 19:11:1.876 -::- Completed retrieving control
VM820:6 19:11:1.876 -::- Retrieving a control again
VM820:6 19:11:1.876 -::- Getting control id
VM820:6 19:11:1.876 -::- Control id retrieved
Log.js?eval:456 2022-03-22 19:11:01.875100 [browser wdi5] control with id: __tile0 located! -  
Log.js?eval:456 2022-03-22 19:11:03.299699 Outer shell hash changed from 'Shell-home' to 'Product-display' -  sap.ushell.services.ShellNavigation
Log.js?eval:456 2022-03-22 19:11:03.313899 Tile clicked: -  sap.ushell.ui.launchpad.Tile
VM867:6 19:11:3.378 -::- Starting waitForUI5
Log.js?eval:456 2022-03-22 19:11:03.420600 NavTargetResolution: custom resolver DefaultAdapter resolves #Product-display -  
Log.js?eval:456 2022-03-22 19:11:03.606899 LoaderExtensions.registerResourcePath ('sap/epd/ps/app/explorer', 'resources/sap/epd/ps/app/explorer') -  
Log.js?eval:456 2022-03-22 19:11:03.609300 Loading manifest via URL: resources/sap/epd/ps/app/explorer/manifest.json?sap-language=EN -  
Log.js?eval:456 2022-03-22 19:11:03.665899 Including /resources/sap/f/themes/sap_fiori_3/library.css -  sap.ui.core.Core.includeLibraryTheme() -  
Log.js?eval:456 2022-03-22 19:11:03.699399 Including /resources/sap/uxap/themes/sap_fiori_3/library.css -  sap.ui.core.Core.includeLibraryTheme() -
vobu commented 2 years ago

Hi @edvardas-kireilis, first of all thanks for providing detailed info + context and for already digging quite deep 👍 we brainstormed over your issue and will give a couple of ideas a try. that being said, i can state that no one has reported these long waiting times before. that's why we have the hunch that the FLP might be involved into things - so double checking here: judging by your logs above, you're testing a UI5 app, starting off from a tile in the FLP, correct?

edvardas-kireilis commented 2 years ago

Hi Volker. You are correct. We are starting using FLP and app tile. I would like to add that there seems to be a consistency with every browser.asControl() call. I have tried to use custom waitForUI5 function logic replacing promise into callbacks. I managed to reduce overall asControl() execution time from 1.2sec to 0.3sec. But the time varies now. Maybe wdi5 library could try this approach as well. But for that to work puppeteer has to be replaced with selenium driver because puppeteer is adding a promise of it's own.

Thank you for you quick response. Looking forward to a resolution.

edvardas-kireilis commented 2 years ago

Hi. Is there any update on the ideas to solve this issue?

vobu commented 2 years ago

are you using puppeteer with the WebDriver protocol as a capability? anyway, could you please share your wdio.conf.(j|t)s? and the test code in question?

edvardas-kireilis commented 2 years ago

As a side note: it would be nice to be able to configure window.wdi5.waitForUI5Options.interval value which currently is 400 ms. Maybe reduction of it could speed up the execution in some cases.

vobu commented 2 years ago

As a side note: it would be nice to be able to configure window.wdi5.waitForUI5Options.interval value which currently is 400 ms. Maybe reduction of it could speed up the execution in some cases.

+1 - we've also seen that already and tracked it in #143

edvardas-kireilis commented 2 years ago

It seems that puppeteer is use by default, unless selenium driver is configured. This is my relevant configuration


exports.config = {
  specs: [
    './test/wdi5/specs/**/*.spec.js'
  ],
  exclude: [
  ],

  maxInstances: 1,

  capabilities: [{
    maxInstances: 1,
    browserName: 'chrome',
    acceptInsecureCerts: false
  }],
  logLevel: 'warn',

  bail: 0,

  baseUrl: 'http://localhost:50001',

  connectionRetryTimeout: 1000 * 60 * 30,

  connectionRetryCount: 3,

  services: [
    'ui5',
    ['selenium-standalone', { drivers: { firefox: '0.29.1', chrome: true, chromiumedge: 'latest' } }]
   // puppeteer is used if above is not added
  ],

  framework: 'mocha',

  reporters: [
    'spec',
    ['junit', {
      outputDir: './'
    }]
  ],

  //
  // Options to be passed to Mocha.
  // See the full list at http://mochajs.org/
  mochaOpts: {
    timeout: 1000 * 60 * 30
  },

  wdi5: {
    screenshotPath: path.join(exports.getResultLocation(), 'screenshots'), // [optional] using the project root
    screenshotsDisabled: false, // [optional] {Boolean}; if set to true screenshots won't be taken and not written to file system
    logLevel: 'error', // [optional] error | verbose | silent
    platform: 'browser',
    url: '/flpSandbox.html#Shell-home', 
    deviceType: 'web', // [mandatory] native | web
    skipInjectUI5OnStart: true,
    waitForUI5Timeout: 1000 * 60 * 40 // [optional] maximum waiting time while checking for UI5 availability
  }
}
vobu commented 2 years ago

thanks for providing the config. We have up to date

in any of our test suites. I'll take this as the opportunity to do so, including adding performance-relevant metrics → #202. Then we'll be able to investigate any potential performance bottlenecks. That being said, this setup will take us a while - so asking for your patience until ~ end of next week. Or, since you obviously have a very good grasp on WebdriverIO + wdi5 in general and already put in metrics, we'd very much appreciate you PR-ing some wdio-setup with puppeteer and WebDriver, e.g. in /examples/ui5-js-app. That would give us all a head-start 🤗

edvardas-kireilis commented 2 years ago

PR to improve to fix this issue: https://github.com/js-soft/wdi5/pull/209

But let's pause on pushing this change for a bit.