yashaka
Why does the browser open for so long?
Here is a simple project: https://github.com/andreirogal/selene-experiments 2 tests pass in 32 seconds! The first start is quick but after very slow.
On a native Selenium WebDriver all launches are fast.
I can't reproduce the issue. On my side, with Mac OS Catalina, Chrome Version 79.0.3945.130 (Official Build) (64-bit) - everything is fine.
To reproduce, I have downloaded your project, added pyproject.toml
[tool.poetry]
name = "selene-experiments"
version = "0.1.0"
description = ""
authors = ["andreirogal:"]
[tool.poetry.dependencies]
python = "^3.7"
selene = {version = "^2.0.0-alpha.21", allow-prereleases = true}
[tool.poetry.dev-dependencies]
pytest = "^3.0"
[build-system]
requires = ["poetry>=1.0.0"]
build-backend = "poetry.masonry.api"
Then being inside project folder:
pyenv local 3.7.3
poetry install
poetry run py.test
And no any delay spotted.
Total run on my side is "2 failed in 24.74 seconds", sometimes near 32s, yes, but I think this is fine taking into account that tests are slow themselves... Look at this video:
https://youtu.be/ul-MbNJDobw
You can clearly see that opening browser takes near 4-5s, which is normal time as I remember... Then 5s is spent just for loading a page - something that is not influenced by selene or selenium... then near 2s we spent for actual test steps, then 2s for timeout waiting in assert, which is as expected, and maybe 1 second to close the browser. That's it - 15s for one test. Then we have another test with 15s more, where we come to near 30s total time execution which is normally fine in this case.
Try to implement same test in raw selenium and show me that it will be faster. Of course it will be faster, because it does not have that selene dynamic smart logic of waiting, etc. But those places where you benefit from raw selenium webdriver are just 2s per test. So, if you make 1.5s for running test steps instead of 2s, this will not result much in total time execution, that is mainly affected by opening browser, loading google.com, and explicit waiting with timeout of 2s.
@andreirogal today i tried to reproduce your issue with pyproject.toml configuration. I have the result in 15.35 seconds total for selene tests - both failing. I saw @yashaka video on youtube and I've noticed that google.com opens instantly, but page loading takes a time and it's waiting much longer on the video than I see now on today's executions.
Here are today's logs from your project execution.
pytest --tb=short tests/test_selene.py15.35s test_selene.logpytest --tb=short tests/test_native_selenium.py22.44s test_native_selenium.log
P.S. I saw that in selene you use 2 sec default timeout and in selenium 5 sec default timeout, i think that's why your selene tests today are faster than selenium.
So I think it was something with connection or browser/webdriver version or google.com site and there is no problem with 2.0.0a21 selene speed. 🙂
@aleksandr-kotlyar now the tests pass in 36s for Selene 2.0.0a21 and 28s for Selenium.
-
poetry run pytest --tb=short .\tests\test_selene.pytest_selene.log session ~36s -
poetry run pytest --tb=short .\tests\test_native_selenium.pytest_native_selenium.log session ~28s
P.S. It's hard for me to tell if it's fast or slow for Selene. :)
@andreirogal It is very interesting. Let's try again with new kind of logs https://github.com/andreirogal/selene-experiments/pull/2 and now with option --tb=no to clean unnecessary stacktraces.
poetry run pytest tests/test_selene.py --tb=no
test_selene.log ~18.12s
poetry run pytest tests/test_native_selenium.py --tb=no
test_native_selenium.log ~24.82s
@aleksandr-kotlyar here are the results after the merge:
-
poetry run pytest tests/test_selene.py --tb=notest_selene ~36s -
poetry run pytest tests/test_native_selenium.py --tb=notest_native_selenium ~26s
Thank you @andreirogal! Interesting thing I see... retry in six times with 2 second pause in your logs: https://github.com/andreirogal/selene-experiments/blob/1f1d69fbdc2c3c542410703eaa3a2a9cda109daf/logs/test_selene_28_03_2021_2.log#L24-L30 and in my logs - no pause between retries - only 3 seconds after the last one:
2021-03-28 14:35:10 [WARNING ] Retrying (Retry(total=2, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.HTTPConnection object at 0x10d607b90>: Failed to establish a new connection: [Errno 61] Connection refused')': /session/571e3b8f5ba6b19b27dc03db0b11b903/title (connectionpool.py: 745)
2021-03-28 14:35:10 [WARNING ] Retrying (Retry(total=1, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.HTTPConnection object at 0x10d5cadd0>: Failed to establish a new connection: [Errno 61] Connection refused')': /session/571e3b8f5ba6b19b27dc03db0b11b903/title (connectionpool.py: 745)
2021-03-28 14:35:10 [WARNING ] Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.HTTPConnection object at 0x10d61cc10>: Failed to establish a new connection: [Errno 61] Connection refused')': /session/571e3b8f5ba6b19b27dc03db0b11b903/title (connectionpool.py: 745)
2021-03-28 14:35:10 [WARNING ] Retrying (Retry(total=2, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.HTTPConnection object at 0x10d5e3f90>: Failed to establish a new connection: [Errno 61] Connection refused')': /session/571e3b8f5ba6b19b27dc03db0b11b903 (connectionpool.py: 745)
2021-03-28 14:35:10 [WARNING ] Retrying (Retry(total=1, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.HTTPConnection object at 0x10d6a3150>: Failed to establish a new connection: [Errno 61] Connection refused')': /session/571e3b8f5ba6b19b27dc03db0b11b903 (connectionpool.py: 745)
2021-03-28 14:35:10 [WARNING ] Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.HTTPConnection object at 0x10d6d9350>: Failed to establish a new connection: [Errno 61] Connection refused')': /session/571e3b8f5ba6b19b27dc03db0b11b903 (connectionpool.py: 745)
2021-03-28 14:35:13 [INFO ] browser start duration: 3.5950987339019775 seconds (test_selene.py: 26)
retry in six times with 2 second pause in your logs:
@aleksandr-kotlyar Yes, I noticed that too. But I can't understand what this is related to.
retry in six times with 2 second pause in your logs:
@aleksandr-kotlyar Yes, I noticed that too. But I can't understand what this is related to.
@andreirogal I think CI will judge our tests: i have MacOS and you have Windows.
Results are:
- On MacOS machine both selene and selenium are fast: 15s selene and 18s selenium.
- On @andreirogal Windows machine test execution time is slow: 36s selene and 28s selenium.
- On GitHub Actions Ubuntu test execution time is: 21s selene and 28s selenium - details but difference from run to run: sometimes 15s selene and 27.75s selenium details
The must be some feature of the Windows environment... I think we can close this issue.
The must be some feature of the Windows environment... I think we can close this issue.
It's still interesting - may be hardware config is different.
@andreirogal Do you have HDD or SSD disk and what processor / memory characteristics do you have on the machine where execute these tests?
I run these tests on i7 2.2 GHz 16 GB Memory and SSD disk.
@aleksandr-kotlyar I run these tests on i7-9750H CPU 2.60GHz, 16 GB Memory, SSD disk and Windows 10 Home v.20H2 OS Build 19042.867
@aleksandr-kotlyar I run these tests on i7-9750H CPU 2.60GHz, 16 GB Memory, SSD disk and Windows 10 Home v.20H2 OS Build 19042.867
Hardware is good. Then it can be an antivirus/firewall (if not custom - then default MS Defender os something like that).
@aleksandr-kotlyar I run these tests on i7-9750H CPU 2.60GHz, 16 GB Memory, SSD disk and Windows 10 Home v.20H2 OS Build 19042.867
Hardware is good. Then it can be an antivirus/firewall (if not custom - then default MS Defender os something like that).
Not sure that it's antivirus. I have analysed logs again https://github.com/andreirogal/selene-experiments/blob/master/logs/test_selene_28_03_2021_2.log and came to conclusion that there is no "gap" between the end of the first test and beginning of the second test. The only one time-spending gap - is when retry's are happening.
2021-03-28 15:43:57 [INFO ] before start browser: 0.0 seconds (test_selene.py: 24)
2021-03-28 15:43:59 [WARNING ] Retrying (Retry(total=2, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.HTTPConnection object at 0x03FA2170>: Failed to establish a new connection: [WinError 10061] No connection could be made because the target machine actively refused it')': /session/4cc042bbbd815aeac156822e94427a11/title (connectionpool.py: 745)
2021-03-28 15:44:01 [WARNING ] Retrying (Retry(total=1, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.HTTPConnection object at 0x0445C3F0>: Failed to establish a new connection: [WinError 10061] No connection could be made because the target machine actively refused it')': /session/4cc042bbbd815aeac156822e94427a11/title (connectionpool.py: 745)
2021-03-28 15:44:03 [WARNING ] Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.HTTPConnection object at 0x0445C890>: Failed to establish a new connection: [WinError 10061] No connection could be made because the target machine actively refused it')': /session/4cc042bbbd815aeac156822e94427a11/title (connectionpool.py: 745)
2021-03-28 15:44:07 [WARNING ] Retrying (Retry(total=2, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.HTTPConnection object at 0x0445C4D0>: Failed to establish a new connection: [WinError 10061] No connection could be made because the target machine actively refused it')': /session/4cc042bbbd815aeac156822e94427a11 (connectionpool.py: 745)
2021-03-28 15:44:09 [WARNING ] Retrying (Retry(total=1, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.HTTPConnection object at 0x0445CBB0>: Failed to establish a new connection: [WinError 10061] No connection could be made because the target machine actively refused it')': /session/4cc042bbbd815aeac156822e94427a11 (connectionpool.py: 745)
2021-03-28 15:44:11 [WARNING ] Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.HTTPConnection object at 0x0445CCF0>: Failed to establish a new connection: [WinError 10061] No connection could be made because the target machine actively refused it')': /session/4cc042bbbd815aeac156822e94427a11 (connectionpool.py: 745)
2021-03-28 15:44:17 [INFO ] browser start duration: 19.854556560516357 seconds (test_selene.py: 26)
15:43:57-15:44:17 - looks like it takes 20 seconds more than could be! But... there is a time between "before start browser" and "browser start duration" if we look at the first test it's about 3.5 seconds:
2021-03-28 15:43:47 [INFO ] before start browser: 0.0 seconds (test_selene.py: 13)
2021-03-28 15:43:50 [INFO ] browser start duration: 3.642312526702881 seconds (test_selene.py: 15)
20 seconds - 3.5 seconds = 16.5 seconds slower test. And it slows only on windows OS. Ubuntu and MacOS doesn't wait between retries.
So, @yashaka I think we should figure out why these retries are happening in selene and fix them. Also it's very interesting why there is a pause between retries on WindowsOS but it's more to urllib3 and WinOS question.
@aleksandr-kotlyar Then I reopen this issue. It's very interesting how it will be resolved)