Find opportunities to speed up MFTF tests #652

filmaj · 2019-11-05T20:53:37Z

Is your feature request related to a problem? Please describe.
It was discussed today in the community call with @drpayyne and @semajeg that the MFTF tests, when running locally, seem to have different performance profiles and bottlenecks depending on
each developer's system. Given MFTF is based on Selenium, this is not entirely surprising, but e.g. on my system most tests run in under one minute (the entire suite of 26 tests runs in ~25 mins for me), whereas others have described 4-5 minute runs for certain tests.

One area of opportunity seems to be a common teardown clause for many tests: resetting the Adobe Stock Search grid filters. This is called via resetAdminDataGridToDefaultView - which actually is not part of this project (on my instance it is present under app/code/Magento/Ui/Test/Mftf/ActionGroup/AdminDataGridFilterActionGroup.xml). This seems to take 2-3 minutes to complete on certain contributors' machines: @drpayyne @semajeg. Gentlemen, do I have the details there correct? Any further details you could provide? I think it would be helpful to get the full mftf run:test output as well as saving the Selenium server output and attaching it to this issue. I have experience with Selenium (I used to work at a Selenium SaaS) so I will take a look and see if anything in those logs stand out.

Another one seems to be a common setup clause for many tests: loading the Media Gallery and then clicking into the Adobe Stock search grid. I recently modified the open media gallery ActionGroup to have two waitForPage statements (I provided comments to clarify why), but perhaps this is not optimal.

Describe the solution you'd like
Would be great to have sub-1-minute tests for all contributors.

Describe alternatives you've considered

I have found that using headless chrome for testing does speed up things quite a bit. To do so, in an embedded MFTF setup, I add the --headless option to the chrome capabilities options list at the bottom of the dev/tests/acceptance/tests/function.suite.yml file. My usual approach is to use headless when running the entire suite of tests (i.e. vendor/bin/mftf run:group adobe_stock_integration_suite --remove -vvv) and remove that option when running individual tests when debugging failures (i.e. vendor/bin/mftf run:test AdminAdobeStockImagePreviewKeywordsSearchTest --remove).

The text was updated successfully, but these errors were encountered:

gareth-e-james · 2019-11-05T23:42:06Z

Thanks @filmaj that does sum it up pretty well, I've been having a bit of a dig to try to understand more as to why it takes so long to run on my local system and I can at least explain some of it:

So the output from a local run of AdminAdobeStockImagePreviewSameModelSeeMoreTest is as follows:

Signature: Magento\AcceptanceTest\_adobe_stock_integration_suite\Backend\AdminAdobeStockImagePreviewSameModelSeeMoreTestCest:AdminAdobeStockImagePreviewSameModelSeeMoreTest

Test: tests/functional/Magento/FunctionalTest/_generated/adobe_stock_integration_suite/AdminAdobeStockImagePreviewSameModelSeeMoreTestCest.php:AdminAdobeStockImagePreviewSameModelSeeMoreTest

Scenario --

 

/******** Beginning execution of adobe_stock_integration_suite suite before block ********/

Entering Action Group [loginAsAdmin] LoginAsAdminExiting Action Group [loginAsAdmin] LoginAsAdminEntering Action Group [setCorrectModuleConfig] AdminAdobeStockSetConfigActionGroupExiting Action Group [setCorrectModuleConfig] AdminAdobeStockSetConfigActionGroup

/******** Execution of adobe_stock_integration_suite suite before block complete ********/

[loginAsAdmin] LoginAsAdmin

  [navigateToAdmin] am on page "/index.php/backend/admin"

  [fillUsername] fill field "#username","localadmin"

  [fillPassword] fill field "#login","AUDSrsMc4LVUnfzE"

  [clickLogin] click ".actions .action-primary"

  [clickLoginWaitForPageLoad] wait for page load 30

  [closeAdminNotification] close admin notification 

[openMediaGalleryForPage] AdminOpenMediaGalleryForPageNoEditorActionGroup

  [amOnPagePagesGrid] am on page "/index.php/backend/cms/page"

  [waitForPageLoad] wait for page load 10

  [clickAddNewPage] click "#add"

  [clickAddNewPageWaitForPageLoad] wait for page load 30

  [clickExpandContent] click "div[data-index=content]"

  [waitForShowHideButton] wait for element visible "#togglecms_page_form_content",10

  [HideEditor] click "#togglecms_page_form_content"

  [waitForInsertImageButton] wait for element visible ".scalable.action-add-image.plugin",10

  [clickInsertImage] click ".scalable.action-add-image.plugin"

  [waitForMediaGallery] wait for page load 10

  [] javascript ERROR(SEVERE) - https://app.adobestockdev.test/static/version1571605855/adminhtml/Magento/backend/en_US/mage/adminhtml/browser.js 91:47 Unc

[openAdobeStockPanel] AdminAdobeStockOpenPanelFromMediaGalleryActionGroup

  [openAdobeStockPanel] click "[data-ui-id=wysiwyg-images-content-search-adobe-stock-button]"

  [waitForAdobeStockPanelOpen] wait for page load 10

[countWithoutModelFilter] grab text from "//*[@id='adobe-stock-images-search-modal']//*[text()='records found']/parent::div"

[expandImagePreview] AdminAdobeStockExpandImagePreviewActionGroup

  [clickOnThumbnail] click "aside.adobe-stock-modal [data-role=grid-wrapper] img[data-role=thumbnail]"

  [waitForImagePreviewToExpand] wait for loading mask to disappear 

[getFileAttributeValue] grab text from "//*[@id='adobe-stock-images-search-modal']//div[@data-role='image-attributes-value']//span[text()='File #']/parent::div//div[@clas..."

[clickOnTabMoreForThisModel] click "//*[@id='model_tab']"

[clickOnSeeMore] click "//div[@aria-labelledby='model_tab']//div[@class='see-more-wrapper']"

[waitForGridReload] wait for page load 10

[verifyAppliedFilter] AssertsFilterResultsActionGroup

  [expandFiltersToCheckAppliedFilter] click ".adobe-stock-images-search-modal-content button[data-action='grid-filter-expand']"

  [verifyAppliedFilter] see "296592057","//*[@id='adobe-stock-images-search-modal']//div[@class='admin__current-filters-list-wrap']//span[contains( ., '296592057')]"

[countWithAppliedFilter] grab text from "//*[@id='adobe-stock-images-search-modal']//*[text()='records found']/parent::div"

[checkThatResultCountChangesAfterFilterApplied] assert not contains "2334 records found","124127565 records found"

[resetAdminDataGridToDefaultView] resetAdminDataGridToDefaultView

  [openViewBookmarks] click "div.admin__data-grid-action-bookmarks button[data-bind='toggleCollapsible']"

  [openViewBookmarksWaitForPageLoad] wait for page load 30

  [selectDefaultGridView] click "//div[contains(@class, 'admin__data-grid-action-bookmarks')]/ul/li/div/a[text() = 'Default View']"

  [selectDefaultGridViewWaitForPageLoad] wait for page load 30

  [seeDefaultViewSelected] see "Default View","div.admin__data-grid-action-bookmarks button[data-bind='toggleCollapsible']"

  [seeDefaultViewSelectedWaitForPageLoad] wait for page load 30

[logout] logout

  [amOnPage] am on page "/index.php/backend/admin/auth/logout/"

 PASSED 

/******** Beginning execution of adobe_stock_integration_suite suite after block ********/

 

/******** Execution of adobe_stock_integration_suite suite after block complete ********/

--------------------------------------------------------------------------------

119x DEPRECATION: Calling the "Symfony\Component\EventDispatcher\EventDispatcherInterface::dispatch()" method with the event name as the first argument is deprecated since Symfony 4.3, pass it as the second argument and provide the event object as the first argument instead. /Users/Gareth/Sites/adobestockdev/vendor/symfony/event-dispatcher/EventDispatcher.php:58

 Time: 5.69 minutes, Memory: 116.00MB

So it takes almost 6 minutes to run.

What I noticed is that for each of the ramp up and ramp down bits, after each click there is a "wait for page load 30" and this seemed to be where it was hanging around the most for me. I had a dig a bit more into why this was happening and found some interesting stuff.

So for example, take the "openViewBookmarks", which is part of the core magento action group "resetAdminDataGridToDefaultView" defined in "app/code/Magento/Ui/Test/Mftf/ActionGroup/AdminDataGridFilterActionGroup.xml":

    <actionGroup name="resetAdminDataGridToDefaultView">
        <annotations>
            <description>Resets an Admin Grid page to the 'Default View'.</description>
        </annotations>
        
        <click selector="{{AdminDataGridHeaderSection.bookmarkToggle}}" stepKey="openViewBookmarks"/>
        <click selector="{{AdminDataGridHeaderSection.bookmarkOption('Default View')}}" stepKey="selectDefaultGridView"/>
        <see selector="{{AdminDataGridHeaderSection.bookmarkToggle}}" userInput="Default View" stepKey="seeDefaultViewSelected"/>
    </actionGroup>

The interesting bit is that there are no page load waits defined there there, but in my test run, they definitely happen! Turns out it's down to the section definition. See "app/code/Magento/Ui/Test/Mftf/Section/AdminDataGridHeaderSection.xml":

        <element name="bookmarkToggle" type="button" selector="div.admin__data-grid-action-bookmarks button[data-bind='toggleCollapsible']" timeout="30"/>
        <element name="bookmarkOption" type="button" selector="//div[contains(@class, 'admin__data-grid-action-bookmarks')]/ul/li/div/a[text() = '{{label}}']" parameterized="true" timeout="30"/>

Both "bookmarkToggle" and bookmarkOption have a timeout value of 30, which upon doing a bit of digging, led me to the "insertWaits" function in "vendor/magento/magento2-functional-testing-framework/src/Magento/FunctionalTestingFramework/Test/Util/ActionMergeUtil.php". Which has the following code:

    /**
     * Runs through the prepared orderedSteps and calls insertWait if a step requires a wait after it.
     *
     * @return void
     */
    private function insertWaits()
    {
        foreach ($this->orderedSteps as $step) {
            if ($step->getTimeout()) {
                $waitStepAttributes = [self::WAIT_ATTR => $step->getTimeout()];
                $waitStep = new ActionObject(
                    $step->getStepKey() . self::WAIT_ACTION_SUFFIX,
                    self::WAIT_ACTION_NAME,
                    $waitStepAttributes,
                    $step->getStepKey(),
                    self::DEFAULT_WAIT_ORDER
                );
                $this->insertStep($waitStep);
            }
        }
    }

This means that when generating the tests, it sees the 30s timeout in the section definition and adds a wait in there.

I have no idea, however, why this would affect me, but not others. Perhaps theres an MFTF/selenium setting that makes it ignore timeouts?

For context, I'm running Selenium standalone with the following command:

java -jar selenium-server-standalone-3.141.59.jar

With the chrome driver for mac 64 bit

Possible suggestion if it's not just an isolated issue: perhaps we do away with relying on these core ramp-up and ramp-downs and write our own? We can use the "waitForElementVisible" to wait for selected elements to appear on the page rather than a defined time period?

See https://devdocs.magento.com/mftf/docs/test/actions.html#waitforelementvisible)

gareth-e-james · 2019-11-06T00:12:28Z

Further note:

I changed the timeouts in AdminDataGridHeaderSection.xml to 5, and this reduced the test to the following:

Time: 2.5 minutes, Memory: 116.00MB

I'm going to set up the project on a different PC (much more powerful, and ubuntu instead of Mac) later in the week, and will report back with the stats I get there :)

gareth-e-james · 2019-11-06T00:27:32Z

One last comment for now (sorry for the spam!)

I noticed this output from the selenium command:

Starting ChromeDriver 77.0.3865.40 (f484704e052e0b556f8030b65b953dce96503217-refs/branch-heads/3865@{#442}) on port 30665
Only local connections are allowed.
Please protect ports used by ChromeDriver and related test frameworks to prevent access by malicious code.
[1572999372.918][WARNING]: This version of ChromeDriver has not been tested with Chrome version 78.
[1572999373.494][WARNING]: This version of ChromeDriver has not been tested with Chrome version 78.

So I updated my chromedriver to the correct version for my chrome version, but it didn't make a difference, other than removing that warning :(

selenium.jar output was:

00:20:56.023 INFO [ActiveSessionFactory.apply] - Capabilities are: {
  "browserName": "chrome",
  "chromeOptions": {
    "args": [
      "--window-size=1280,1024",
      "--disable-extensions",
      "--enable-automation",
      "--disable-gpu",
      "--enable-Passthrough"
    ],
    "w3c": false
  }
}
00:20:56.025 INFO [ActiveSessionFactory.lambda$apply$11] - Matched factory org.openqa.selenium.grid.session.remote.ServicedSession$Factory (provider: org.openqa.selenium.chrome.ChromeDriverService)
Starting ChromeDriver 78.0.3904.70 (edb9c9f3de0247fd912a77b7f6cae7447f6d3ad5-refs/branch-heads/3904@{#800}) on port 44104
Only local connections are allowed.
Please protect ports used by ChromeDriver and related test frameworks to prevent access by malicious code.
00:21:02.187 INFO [ProtocolHandshake.createSession] - Detected dialect: OSS
00:21:02.787 INFO [RemoteSession$Factory.lambda$performHandshake$0] - Started new session eee05ec6e7cbd484f4c3e06a16826819 (org.openqa.selenium.chrome.ChromeDriverService)
00:21:28.028 INFO [ActiveSessionFactory.apply] - Capabilities are: {
  "browserName": "chrome",
  "chromeOptions": {
    "args": [
      "--window-size=1280,1024",
      "--disable-extensions",
      "--enable-automation",
      "--disable-gpu",
      "--enable-Passthrough"
    ],
    "w3c": false
  }
}
00:21:28.028 INFO [ActiveSessionFactory.lambda$apply$11] - Matched factory org.openqa.selenium.grid.session.remote.ServicedSession$Factory (provider: org.openqa.selenium.chrome.ChromeDriverService)
Starting ChromeDriver 78.0.3904.70 (edb9c9f3de0247fd912a77b7f6cae7447f6d3ad5-refs/branch-heads/3904@{#800}) on port 18987
Only local connections are allowed.
Please protect ports used by ChromeDriver and related test frameworks to prevent access by malicious code.
00:21:33.884 INFO [ProtocolHandshake.createSession] - Detected dialect: OSS
00:21:33.942 INFO [RemoteSession$Factory.lambda$performHandshake$0] - Started new session cfe96082ad95c8c61b46f585ade660c7 (org.openqa.selenium.chrome.ChromeDriverService)
00:25:51.011 INFO [ActiveSessionFactory.apply] - Capabilities are: {
  "browserName": "chrome",
  "chromeOptions": {
    "args": [
      "--window-size=1280,1024",
      "--disable-extensions",
      "--enable-automation",
      "--disable-gpu",
      "--enable-Passthrough"
    ],
    "w3c": false
  }
}
00:25:51.012 INFO [ActiveSessionFactory.lambda$apply$11] - Matched factory org.openqa.selenium.grid.session.remote.ServicedSession$Factory (provider: org.openqa.selenium.chrome.ChromeDriverService)
Starting ChromeDriver 78.0.3904.70 (edb9c9f3de0247fd912a77b7f6cae7447f6d3ad5-refs/branch-heads/3904@{#800}) on port 37460
Only local connections are allowed.
Please protect ports used by ChromeDriver and related test frameworks to prevent access by malicious code.
00:25:55.809 INFO [ProtocolHandshake.createSession] - Detected dialect: OSS
00:25:56.007 INFO [RemoteSession$Factory.lambda$performHandshake$0] - Started new session c02882152d2d40b2b44c98268d3f8fd5 (org.openqa.selenium.chrome.ChromeDriverService)
00:25:56.228 INFO [ActiveSessions$1.onStop] - Removing session c02882152d2d40b2b44c98268d3f8fd5 (org.openqa.selenium.chrome.ChromeDriverService)

rogyar · 2019-11-06T08:08:26Z

Hi @filmaj @semajeg.
Could you provide the exact command for running the MFTF tests in this case, please? I just want to make sure that we all are on the same page.

Thank you!

drpayyne · 2019-11-06T08:11:50Z

Here's something which took forever on my machine: TWELVE minutes, to be precise. Maybe since this is a long test, but I see lots of <waitForPageLoad/>s which I feel is ran until timed out.

$ vendor/bin/mftf run:test AdminAdobeStockListingStateTest --remove

removed files and directory /var/www/html/adobe-stock/dev/tests/acceptance/tests/functional/Magento/FunctionalTest/_generated
Generate Tests Command Run
Codeception PHP Testing Framework v2.4.5
Powered by PHPUnit 6.5.14 by Sebastian Bergmann and contributors.
[Groups] adobe_stock_integration_suite 

Magento\FunctionalTestingFramework.functional Tests (1) ------------------------
Modules: \Magento\FunctionalTestingFramework\Module\MagentoWebDriver, \Magento\FunctionalTestingFramework\Helper\Acceptance, \Magento\FunctionalTestingFramework\Helper\MagentoFakerData, \Magento\FunctionalTestingFramework\Module\MagentoSequence, \Magento\FunctionalTestingFramework\Module\MagentoAssert, Asserts
--------------------------------------------------------------------------------
AdminAdobeStockListingStateTestCest: Admin adobe stock listing state test
Signature: Magento\AcceptanceTest\_adobe_stock_integration_suite\Backend\AdminAdobeStockListingStateTestCest:AdminAdobeStockListingStateTest
Test: tests/functional/Magento/FunctionalTest/_generated/adobe_stock_integration_suite/AdminAdobeStockListingStateTestCest.php:AdminAdobeStockListingStateTest
Scenario --

/******** Beginning execution of adobe_stock_integration_suite suite before block ********/
Entering Action Group [loginAsAdmin] LoginAsAdminExiting Action Group [loginAsAdmin] LoginAsAdminEntering Action Group [setCorrectModuleConfig] AdminAdobeStockSetConfigActionGroupExiting Action Group [setCorrectModuleConfig] AdminAdobeStockSetConfigActionGroup
/******** Execution of adobe_stock_integration_suite suite before block complete ********/
[loginAsAdmin] LoginAsAdmin
  [navigateToAdmin] am on page "/admin/admin"
  [fillUsername] fill field "#username","admin"
  [fillPassword] fill field "#login","Passw0rd"
  [clickLogin] click ".actions .action-primary"
  [clickLoginWaitForPageLoad] wait for page load 30
  [clickDontAllowButtonIfVisible] conditional click ".modal-popup .action-secondary",".modal-popup .action-secondary",true
  [closeAdminNotification] close admin notification 
[openMediaGalleryForPage] AdminOpenMediaGalleryForPageNoEditorActionGroup
  [amOnPagePagesGrid] am on page "/admin/cms/page"
  [waitForPageLoad] wait for page load 10
  [clickAddNewPage] click "#add"
  [clickAddNewPageWaitForPageLoad] wait for page load 30
  [clickExpandContent] click "div[data-index=content]"
  [waitForInsertImageButton] wait for element visible ".scalable.action-add-image.plugin",10
  [clickInsertImage] click ".scalable.action-add-image.plugin"
  [] wait for initial media gallery load, where the gallery chrome loads (and triggers loading modal)
  [waitForMediaGalleryInitialLoad] wait for page load 10
  [] javascript ERROR(SEVERE) - https://adobe-stock.site/pub/static/version1573020017/adminhtml/Magento/backend/en_US/mage/adminhtml/browser.js 91:47 Uncau
  [] wait for second media gallery load, where the gallery images load (and triggers loading modal once more)
  [waitForMediaGallerySecondaryLoad] wait for page load 10
[openAdobeStockPanel] AdminAdobeStockOpenPanelFromMediaGalleryActionGroup
  [openAdobeStockPanel] click "[data-ui-id=wysiwyg-images-content-search-adobe-stock-button]"
  [waitForAdobeStockPanelOpen] wait for page load 10
[expandFilters1] AdminAdobeStockExpandFiltersActionGroup
  [expandFilters] click ".adobe-stock-images-search-modal-content button[data-action='grid-filter-expand']"
  [waitForFiltersOpen] wait for page load 10
[applyIsolatedFilter] AdminAdobeStockApplyIsolatedFilterActionGroup
  [selectIsolatedAssetsFilter] click "//*[@id='adobe-stock-images-search-modal']//input[@name='isolated_filter']"
  [clickOnApplyFilters] click "button[data-action='grid-filter-apply']"
  [clickOnApplyFiltersWaitForPageLoad] wait for page load 30
[expandFilters] AdminAdobeStockExpandFiltersActionGroup
  [expandFilters] click ".adobe-stock-images-search-modal-content button[data-action='grid-filter-expand']"
  [waitForFiltersOpen] wait for page load 10
[userChoseAndApplyColorFilter] AdminApplyColorFilterValue
  [openColorPicker] click "//*[@id='adobe-stock-images-search-modal']//div[@class='sp-preview']"
  [choseColor] click "//*[@id='html-body']//span[@title='#000000']"
  [ApplyColor] click "//*[@id='html-body']//div[@class='sp-picker-container']//button[@class='sp-choose']"
  [clickOnApplyFilters] click "button[data-action='grid-filter-apply']"
  [clickOnApplyFiltersWaitForPageLoad] wait for page load 30
[expandFilters2] AdminAdobeStockExpandFiltersActionGroup
  [expandFilters] click ".adobe-stock-images-search-modal-content button[data-action='grid-filter-expand']"
  [waitForFiltersOpen] wait for page load 10
[setOrientationFilterToHorizontal] AdminFilterResultsActionGroup
  [clickOnFilter] click "//select[@name='orientation_filter']"
  [selectFilter] click "//select[@name='orientation_filter']/option[@data-title='Horizontal']"
  [clickOnApplyFilters] click "button[data-action='grid-filter-apply']"
  [clickOnApplyFiltersWaitForPageLoad] wait for page load 30
[expandFilters3] AdminAdobeStockExpandFiltersActionGroup
  [expandFilters] click ".adobe-stock-images-search-modal-content button[data-action='grid-filter-expand']"
  [waitForFiltersOpen] wait for page load 10
[see32imagesOnTheSecondPage] AdminUserApplySafeSearchFilterActionGroup
  [selectSafeSearchFilter] click "//*[@id='adobe-stock-images-search-modal']//input[@name='offensive_filter']"
  [clickOnApplyFilters] click "button[data-action='grid-filter-apply']"
  [clickOnApplyFiltersWaitForPageLoad] wait for page load 30
[openNextPage] AdminAdobeStockOpenNextPageActionGroup
  [clickNextPage] click "div.admin__data-grid-pager > button.action-next"
  [clickNextPageWaitForPageLoad] wait for page load 30
  [waitForNextPageToLoad] wait for loading mask to disappear 
[expandImagePreview] AdminAdobeStockExpandImagePreviewActionGroup
  [clickOnThumbnail] click "aside.adobe-stock-modal [data-role=grid-wrapper] img[data-role=thumbnail]"
  [waitForImagePreviewToExpand] wait for loading mask to disappear 
[saveImagePreview] AdminAdobeStockSavePreviewActionGroup
  [clickOnSavePreview] click "//button[@class='action-secondary']//span[text()='Save Preview']"
  [waitForPageLoad] wait for page load 10
[assertImageSaved] AdminAssertAdobeStockImageSavedActionGroup
  [waitForMaskDisappeared] wait for page load 10
  [generatedImage] grab value from "input[data-role='adobe-stock-image-name-field']"
  [clickOnPopupConfirm] click "//*[@class='action-primary action-accept']"
  [waitForMaskDisappeared1] wait for page load 10
  [assertSavedImage] see element "//img[contains(@alt,'screaming-creepy-character-cover')]"
[openAdobeStockPanel] AdminAdobeStockOpenPanelFromMediaGalleryActionGroup
  [openAdobeStockPanel] click "[data-ui-id=wysiwyg-images-content-search-adobe-stock-button]"
  [waitForAdobeStockPanelOpen] wait for page load 10
[seeSecondPage] AdminAssertAdobeStockCurrentPageNumberActionGroup
  [seeCorrectCurrentPageNumber] see in field "div.admin__data-grid-pager > input[data-ui-id='current-page-input']","2"
[verifyAppliedFilter1] AssertsFilterResultsActionGroup
  [expandFiltersToCheckAppliedFilter] click ".adobe-stock-images-search-modal-content button[data-action='grid-filter-expand']"
  [verifyAppliedFilter] see "Isolated Only","//*[@id='adobe-stock-images-search-modal']//div[@class='admin__current-filters-list-wrap']//span[contains( ., 'Isolated Only')]"
[verifyAppliedFilter2] AssertsFilterResultsActionGroup
  [expandFiltersToCheckAppliedFilter] click ".adobe-stock-images-search-modal-content button[data-action='grid-filter-expand']"
  [verifyAppliedFilter] see "#000000","//*[@id='adobe-stock-images-search-modal']//div[@class='admin__current-filters-list-wrap']//span[contains( ., '#000000')]"
[resetAdminDataGridToDefaultView] resetAdminDataGridToDefaultView
  [openViewBookmarks] click "div.admin__data-grid-action-bookmarks button[data-bind='toggleCollapsible']"
  [openViewBookmarksWaitForPageLoad] wait for page load 30
  [selectDefaultGridView] click "//div[contains(@class, 'admin__data-grid-action-bookmarks')]/ul/li/div/a[text() = 'Default View']"
  [selectDefaultGridViewWaitForPageLoad] wait for page load 30
  [seeDefaultViewSelected] see "Default View","div.admin__data-grid-action-bookmarks button[data-bind='toggleCollapsible']"
  [seeDefaultViewSelectedWaitForPageLoad] wait for page load 30
[logout] logout
  [amOnPage] am on page "/admin/admin/auth/logout/"
 PASSED 


/******** Beginning execution of adobe_stock_integration_suite suite after block ********/

/******** Execution of adobe_stock_integration_suite suite after block complete ********/
--------------------------------------------------------------------------------
241x DEPRECATION: Calling the "Symfony\Component\EventDispatcher\EventDispatcherInterface::dispatch()" method with the event name as the first argument is deprecated since Symfony 4.3, pass it as the second argument and provide the event object as the first argument instead. /var/www/html/adobe-stock/vendor/symfony/event-dispatcher/EventDispatcher.php:58


Time: 12.65 minutes, Memory: 120.00MB

OK (1 test, 5 assertions)

This is how I start the Selenium server: (version is shown here)

$ java -Dwebdriver.chrome.driver=chromedriver -jarelenium-server-standalone-3.141.59.jar

Maybe this could help, @rogyar. Thanks.

gareth-e-james · 2019-11-06T09:16:00Z

@rogyar the command was:

vendor/bin/mftf run:test AdminAdobeStockImagePreviewSameModelSeeMoreTest --remove

also tried it without the --remove , didn't make any difference

filmaj · 2019-11-06T12:41:55Z

@semajeg @drpayyne could you do me a favour and also attach or link to the full output of your java -jar selenium.jar run during the test run? If you could isolate the output to just the test run that would help (it will be very long!). Also let me know what test you ran coupled with the selenium.jar output and I will make sure to run the same test on my setup.

On first glance, the MFTF output is the same as mine, but my setup does not get stuck on the 'optionally wait for 30 seconds' bits you pointed out, @semajeg, so...

filmaj · 2019-11-06T12:43:48Z

One thing I noticed is that both of you have [] javascript ERROR(SEVERE) in your MFTF output. The actual error gets cut off (it looks to be 'uncaught exception').

Can you check whether you see any JS errors when you open the Media Gallery on your instances by checking in your browser developer console?

drpayyne · 2019-11-06T12:52:48Z

@filmaj Regarding the JS error, this is my console when I open the Media Gallery.

Error source: lib/web/mage/adminhtml/browser.js:92

drpayyne · 2019-11-06T13:13:59Z

@filmaj, regarding the java output for the test mentioned above (the 12 minute one!):

$ java -Dwebdriver.chrome.driver=chromedriver -jar selenium-server-standalone-3.141.59.jar 
18:29:16.351 INFO [GridLauncherV3.parse] - Selenium server version: 3.141.59, revision: e82be7d358
18:29:16.403 INFO [GridLauncherV3.lambda$buildLaunchers$3] - Launching a standalone Selenium Server on port 4444
2019-11-06 18:29:16.432:INFO::main: Logging initialized @244ms to org.seleniumhq.jetty9.util.log.StdErrLog
18:29:16.568 INFO [WebDriverServlet.<init>] - Initialising WebDriverServlet
18:29:16.620 INFO [SeleniumServer.boot] - Selenium Server is up and running on port 4444
18:29:43.647 INFO [ActiveSessionFactory.apply] - Capabilities are: {
  "browserName": "chrome",
  "chromeOptions": {
    "args": [
      "--window-size=1280,1024",
      "--disable-extensions",
      "--enable-automation",
      "--disable-gpu",
      "--enable-Passthrough"
    ],
    "w3c": false
  }
}
18:29:43.648 INFO [ActiveSessionFactory.lambda$apply$11] - Matched factory org.openqa.selenium.grid.session.remote.ServicedSession$Factory (provider: org.openqa.selenium.chrome.ChromeDriverService)
Starting ChromeDriver 77.0.3865.40 (f484704e052e0b556f8030b65b953dce96503217-refs/branch-heads/3865@{#442}) on port 1853
Only local connections are allowed.
Please protect ports used by ChromeDriver and related test frameworks to prevent access by malicious code.
18:29:44.114 INFO [ProtocolHandshake.createSession] - Detected dialect: OSS
18:29:44.377 INFO [RemoteSession$Factory.lambda$performHandshake$0] - Started new session 06755745b5a55b5e08a01f33cc3d80b2 (org.openqa.selenium.chrome.ChromeDriverService)
18:29:55.034 INFO [ActiveSessionFactory.apply] - Capabilities are: {
  "browserName": "chrome",
  "chromeOptions": {
    "args": [
      "--window-size=1280,1024",
      "--disable-extensions",
      "--enable-automation",
      "--disable-gpu",
      "--enable-Passthrough"
    ],
    "w3c": false
  }
}
18:29:55.034 INFO [ActiveSessionFactory.lambda$apply$11] - Matched factory org.openqa.selenium.grid.session.remote.ServicedSession$Factory (provider: org.openqa.selenium.chrome.ChromeDriverService)
Starting ChromeDriver 77.0.3865.40 (f484704e052e0b556f8030b65b953dce96503217-refs/branch-heads/3865@{#442}) on port 3914
Only local connections are allowed.
Please protect ports used by ChromeDriver and related test frameworks to prevent access by malicious code.
18:29:55.317 INFO [ProtocolHandshake.createSession] - Detected dialect: OSS
18:29:55.398 INFO [RemoteSession$Factory.lambda$performHandshake$0] - Started new session 5278bc5cac2116dfca5858f85f7866c2 (org.openqa.selenium.chrome.ChromeDriverService)
18:42:20.426 INFO [ActiveSessionFactory.apply] - Capabilities are: {
  "browserName": "chrome",
  "chromeOptions": {
    "args": [
      "--window-size=1280,1024",
      "--disable-extensions",
      "--enable-automation",
      "--disable-gpu",
      "--enable-Passthrough"
    ],
    "w3c": false
  }
}
18:42:20.426 INFO [ActiveSessionFactory.lambda$apply$11] - Matched factory org.openqa.selenium.grid.session.remote.ServicedSession$Factory (provider: org.openqa.selenium.chrome.ChromeDriverService)
Starting ChromeDriver 77.0.3865.40 (f484704e052e0b556f8030b65b953dce96503217-refs/branch-heads/3865@{#442}) on port 16160
Only local connections are allowed.
Please protect ports used by ChromeDriver and related test frameworks to prevent access by malicious code.
18:42:20.721 INFO [ProtocolHandshake.createSession] - Detected dialect: OSS
18:42:20.755 INFO [RemoteSession$Factory.lambda$performHandshake$0] - Started new session e055f8d0434d22b8b75f1ca3a757d48b (org.openqa.selenium.chrome.ChromeDriverService)
18:42:21.020 INFO [ActiveSessions$1.onStop] - Removing session e055f8d0434d22b8b75f1ca3a757d48b (org.openqa.selenium.chrome.ChromeDriverService)

filmaj · 2019-11-06T13:58:56Z

Can you tweak the capabilities passed to chromedriver to enable chromedriver to do verbose logging and logging to a specific path? In my (embedded MFTF) setup, I had to edit dev/tests/acceptance/tests/function.suite.yml - near the bottom of this file is a set of options passed to chromedriver. Add --verbose and --log-path=some/path/to/chromedriver.log to the options, run the test again, and attach (or link to) the resulting (likely super lengthy) chromedriver log. Please and thank you!

EDIT: wait, no, those are chrome options, not chromedriver options. Hmm... let me look around on how to do this.

filmaj · 2019-11-06T14:07:14Z

Try running:

java -Dwebdriver.chrome.driver=chromedriver -Dselenium.LOGGER.level=INFO -Dwebdriver.chrome.logfile=/Path/to/chromedriver.log -jar selenium-standalone.jar

... and then attach or link to chromedriver.log, please.

filmaj · 2019-11-06T15:58:45Z

Had an opportunity to dig into this a bit deeper with @drpayyne. Some interesting findings.

First, the waitForPageLoad mechanism seems to rely on checking if jQuery is reporting itself as active or not (you can read more information on how this property works here). Essentially, every time an AJAX request is fired off, jQuery increments the active counter, and every time jQuery finishes handling the AJAX request response, the active counter is decremented. In @drpayyne's case, by inspecting the chromedriver logs, we were able to determine that the JavaScript the waitForPageLoad command is executing was something like jQuery.active === 0 - but for @drpayyne, active was always returning 1.

Second was going back to the JavaScript exception reported in the MFTF output (javascript ERROR(SEVERE)). By looking at the stack trace for this exception, we could see that this occurred in an AJAX callback handler - meaning jQuery was unable to finish dealing with an AJAX request and also implying that, therefore, was unable to decrement the active counter.

So the working hypothesis at this point is that it is this JavaScript exception that is the root cause of the slowdowns, because it causes jQuery to report itself as still working on AJAX requests, which then causes each waitForPageLoad to timeout (meaning, a full 30 second wait at each waitForPageLoad execution).

We need to get to the bottom of this exception. So, three requests for you @drpayyne and @semajeg:

Can you both post the full stack trace for this exception? It seems to happen when loading the Media Gallery in your browsers. So, please load the Media Gallery, open the browser developer console, and copy the stack trace and paste it in this issue.
Can you both please post the operating system and version as well as browser and version you are seeing this exception in?
Can you include the version of Magento core you are using?

That should help me dig deeper to understand where in the client side code this issue is happening and why.

Thanks!

drpayyne · 2019-11-06T16:13:51Z

Thanks for the detailed review and assistance, @filmaj! Here are my environment logs and details:
The browser console throws this error:

Uncaught TypeError: Cannot read property 'targetElementId' of undefined
    at jQuery.fn.init.<anonymous> (browser.js:92)
    at fire (jquery.js:3238)
    at Object.fireWith [as resolveWith] (jquery.js:3368)
    at done (jquery.js:9846)
    at XMLHttpRequest.callback (jquery.js:10317)

and browser.js is lib/web/mage/adminhtml/browser.js.

Environment is Ubuntu 18.04.3 LTS and Chromium Version 77.0.3865.90 (Official Build) Built on Ubuntu, running on Ubuntu 18.04 (64-bit).

Magento version is 2.3-develop branch of magento/magento2 repository.

Hope this helps, thank you!

gareth-e-james · 2019-11-06T23:34:12Z

Thanks for all the info @filmaj! I think you may have hit the nail on the head with the JS error being the problem! I'm getting exactly the same error as @drpayyne, so I'm getting the error on line 92 of /lib/web/mage/adminhtml/browser.js too, the code on that line is:

self.targetElementId = options.targetElementId;

I think the reason for the JS error is that the onclick for the "Insert image..." button doesn't provide any "options" to the openDialog function (I think the html for it gets generated in
lib/internal/Magento/Framework/Data/Form/Element/Editor.php, line 292).

So options is undefined, hence the error after the ajax to load the slideout modal. I don't that is unexpected behaviour, but I think this is a actually bug in core Magento introduced fairly recently in that js file as that line was added that line changed 2 months ago, see line 92 in https://github.com/magento/magento2/blame/2.3-develop/lib/web/mage/adminhtml/browser.js

Looks like this PR added the line magento/magento2#24333

It's likely you're not seeing the error because you have an older copy of the repo. I'm running a clone of the 2.3-develop branch from just before MLEU (so Oct 20th ish) which included the PR that introduced this.

As a test, I changed my local version of browser.js to wrap that line in an if statement:

if (options && options.targetElementId) {
    self.targetElementId=options.targetElementId;
}

I then reran the test I was running before, and it runs in 1.35 minutes (down from 5.69). Tbh, a lot of time is now in the setup before selenium even gets going, so I think I've hit the limit on what my old mac can do, but it's more respectable than almost 6 mins!

So the JS error must be screwing around with chromedrive/selenium as you've said.

For extra context, I'm running the following:

OS: MacOS 10.13.6
Browser: Chrome 78.0.3904.87

filmaj · 2019-11-07T15:46:07Z

Thanks for the info @semajeg. Indeed I am running the tagged 2.3.3 version of magento core, and the setting of targetElementId is not present in browser.js in my instance.

So, at least we have a workaround to speed up the tests: be defensive when attempting to use the options.targetElementId property.

I'm gonna queue up a task to see if I can reproduce this issue with latest magento locally, and if so, file an issue on magento2 core.

filmaj · 2019-11-08T22:17:14Z

BTW can confirm that when moving to latest develop of magento2 core, I have the JS exception causing the same slowdowns in the tests. @semajeg's workaround worked great, thankfully.

rogyar · 2019-11-11T16:18:00Z

I can confirm that the provided workaround works like a charm.

I believe Magento Core Team should address this issue

sivaschenko · 2019-11-18T21:35:40Z

@filmaj should this ticket be closed as the fix is delivered to magento2 core with magento/magento2#25556 ?

filmaj · 2019-11-18T21:36:36Z

Yep, good catch!

filmaj added the MFTF tests MFTF tests coverage label Nov 5, 2019

filmaj assigned rogyar Nov 5, 2019

m2-community-project bot added the Progress: dev in progress label Nov 5, 2019

filmaj mentioned this issue Nov 7, 2019

MFTF Automation for: User locates licensed and uploaded image inside Media Gallery #639

Merged

sivaschenko added this to the Phase 2: License Images milestone Nov 14, 2019

filmaj closed this as completed Nov 18, 2019

m2-community-project bot removed the Progress: dev in progress label Nov 18, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Find opportunities to speed up MFTF tests #652

Find opportunities to speed up MFTF tests #652

filmaj commented Nov 5, 2019

gareth-e-james commented Nov 5, 2019

gareth-e-james commented Nov 6, 2019

gareth-e-james commented Nov 6, 2019

rogyar commented Nov 6, 2019

drpayyne commented Nov 6, 2019 •

edited

Loading

gareth-e-james commented Nov 6, 2019

filmaj commented Nov 6, 2019

filmaj commented Nov 6, 2019

drpayyne commented Nov 6, 2019 •

edited

Loading

drpayyne commented Nov 6, 2019

filmaj commented Nov 6, 2019 •

edited

Loading

filmaj commented Nov 6, 2019 •

edited

Loading

filmaj commented Nov 6, 2019

drpayyne commented Nov 6, 2019 •

edited

Loading

gareth-e-james commented Nov 6, 2019 •

edited

Loading

filmaj commented Nov 7, 2019

filmaj commented Nov 8, 2019

rogyar commented Nov 11, 2019 •

edited

Loading

sivaschenko commented Nov 18, 2019

filmaj commented Nov 18, 2019

Find opportunities to speed up MFTF tests #652

Find opportunities to speed up MFTF tests #652

Comments

filmaj commented Nov 5, 2019

gareth-e-james commented Nov 5, 2019

gareth-e-james commented Nov 6, 2019

gareth-e-james commented Nov 6, 2019

rogyar commented Nov 6, 2019

drpayyne commented Nov 6, 2019 • edited Loading

gareth-e-james commented Nov 6, 2019

filmaj commented Nov 6, 2019

filmaj commented Nov 6, 2019

drpayyne commented Nov 6, 2019 • edited Loading

drpayyne commented Nov 6, 2019

filmaj commented Nov 6, 2019 • edited Loading

filmaj commented Nov 6, 2019 • edited Loading

filmaj commented Nov 6, 2019

drpayyne commented Nov 6, 2019 • edited Loading

gareth-e-james commented Nov 6, 2019 • edited Loading

filmaj commented Nov 7, 2019

filmaj commented Nov 8, 2019

rogyar commented Nov 11, 2019 • edited Loading

sivaschenko commented Nov 18, 2019

filmaj commented Nov 18, 2019

drpayyne commented Nov 6, 2019 •

edited

Loading

drpayyne commented Nov 6, 2019 •

edited

Loading

filmaj commented Nov 6, 2019 •

edited

Loading

filmaj commented Nov 6, 2019 •

edited

Loading

drpayyne commented Nov 6, 2019 •

edited

Loading

gareth-e-james commented Nov 6, 2019 •

edited

Loading

rogyar commented Nov 11, 2019 •

edited

Loading