Open
Bug 1650025
Opened 5 years ago
Updated 4 months ago
[meta] Slow start-up times of Firefox when using remote protocols (WebDriver, CDP)
Categories
(Remote Protocol :: Agent, defect, P3)
Remote Protocol
Agent
Tracking
(Not tracked)
NEW
People
(Reporter: whimboo, Unassigned)
References
(Depends on 3 open bugs)
Details
(Keywords: meta, perf)
Attachments
(2 files)
We got feedback from various people that running automation with Firefox is way slower compared to Chrome. Mostly because the slow start-up times. This bug covers the WebDriver side of automation, when using geckodriver.
Attached you can find a Selenium script that measures the cold startup time of Firefox, by requesting a new instance of Firefox within a loop. Note that each time a new profile is being created. Profile caching will not be used. The end time is taken when the driver is ready to actually receive commands.
The script can be run against both Firefox and Chrome. In the following I run the loop 20 times, and finally print the average startup time. It's done for both non-headless and headless modes.
Measurements are taken with latest releases of geckodriver and chromedriver.
Firefox Release 78.0.1
➜ BINARY=/Applications/Firefox.app/Contents/MacOS/firefox python startup.py
Using firefox to measure startup duration
iteration 1: 4.45146799088
iteration 2: 2.90847682953
iteration 3: 3.00458598137
iteration 4: 3.01021814346
iteration 5: 3.01424908638
iteration 6: 3.10980296135
iteration 7: 3.11819195747
iteration 8: 3.0005300045
iteration 9: 3.00819611549
iteration 10: 2.99976420403
iteration 11: 3.01380300522
iteration 12: 3.11150503159
iteration 13: 3.21737504005
iteration 14: 3.01978302002
iteration 15: 3.01228690147
iteration 16: 3.22333788872
iteration 17: 3.09990501404
iteration 18: 3.16135883331
iteration 19: 4.14165902138
iteration 20: 3.10492086411
Average startup duration: 3.18657089472
➜ BINARY=/Applications/Firefox.app/Contents/MacOS/firefox HEADLESS=1 python startup.py
Using firefox to measure startup duration
iteration 1: 2.90034604073
iteration 2: 2.49079990387
iteration 3: 2.51049518585
iteration 4: 2.80566596985
iteration 5: 2.59591794014
iteration 6: 2.59859585762
iteration 7: 2.60711097717
iteration 8: 2.68736505508
iteration 9: 2.58055496216
iteration 10: 2.58514499664
iteration 11: 2.60672807693
iteration 12: 2.60066604614
iteration 13: 2.61350703239
iteration 14: 2.60180711746
iteration 15: 2.69203495979
iteration 16: 2.69783091545
iteration 17: 2.58636689186
iteration 18: 2.70072317123
iteration 19: 2.58910107613
iteration 20: 2.6913819313
Average startup duration: 2.63710720539
Firefox Nightly 80.0a1
➜ BINARY=/Applications/FirefoxNightly.app/Contents/MacOS/firefox python startup.py
Using firefox to measure startup duration
iteration 1: 3.22954702377
iteration 2: 3.19395089149
iteration 3: 3.20416593552
iteration 4: 3.11253213882
iteration 5: 3.09308719635
iteration 6: 3.21402001381
iteration 7: 3.10821294785
iteration 8: 3.20896410942
iteration 9: 3.21732997894
iteration 10: 3.33088493347
iteration 11: 3.43882799149
iteration 12: 3.31207084656
iteration 13: 3.11740422249
iteration 14: 3.22549796104
iteration 15: 3.20236086845
iteration 16: 3.31545519829
iteration 17: 3.22297096252
iteration 18: 3.20930504799
iteration 19: 3.11179900169
iteration 20: 3.10650110245
Average startup duration: 3.20874441862
➜ BINARY=/Applications/FirefoxNightly.app/Contents/MacOS/firefox HEADLESS=1 python startup.py
Using firefox to measure startup duration
iteration 1: 2.59337687492
iteration 2: 2.68443703651
iteration 3: 2.5913131237
iteration 4: 2.59054613113
iteration 5: 2.70522212982
iteration 6: 2.5802731514
iteration 7: 2.58310985565
iteration 8: 2.69133591652
iteration 9: 3.00055789948
iteration 10: 2.92686200142
iteration 11: 2.79710698128
iteration 12: 2.89351797104
iteration 13: 3.00427985191
iteration 14: 3.00704789162
iteration 15: 2.80452013016
iteration 16: 2.79962205887
iteration 17: 3.02867603302
iteration 18: 2.69222807884
iteration 19: 2.90687990189
iteration 20: 2.79996299744
Average startup duration: 2.78404380083
Chrome
➜ PRODUCT=chrome python startup.py
Using chrome to measure startup duration
iteration 1: 2.70938014984
iteration 2: 1.84689116478
iteration 3: 1.96474099159
iteration 4: 1.84321308136
iteration 5: 1.80805921555
iteration 6: 1.78523612022
iteration 7: 1.84241199493
iteration 8: 1.79677891731
iteration 9: 1.79311704636
iteration 10: 1.76535916328
iteration 11: 1.78647017479
iteration 12: 1.84071493149
iteration 13: 1.79913520813
iteration 14: 1.82780504227
iteration 15: 1.84432983398
iteration 16: 1.88706898689
iteration 17: 1.86261701584
iteration 18: 1.84184002876
iteration 19: 1.81589508057
iteration 20: 1.80926203728
Average startup duration: 1.87351630926
➜ PRODUCT=chrome HEADLESS=1 python startup.py
Using chrome to measure startup duration
iteration 1: 1.58926701546
iteration 2: 1.33530688286
iteration 3: 1.33217692375
iteration 4: 1.33585000038
iteration 5: 1.34048891068
iteration 6: 1.34001803398
iteration 7: 1.33123612404
iteration 8: 1.31963801384
iteration 9: 1.33934092522
iteration 10: 1.33383584023
iteration 11: 1.35895705223
iteration 12: 1.35213017464
iteration 13: 1.3348429203
iteration 14: 1.36129689217
iteration 15: 1.33616495132
iteration 16: 1.33643102646
iteration 17: 1.32758593559
iteration 18: 1.34201693535
iteration 19: 1.34357118607
iteration 20: 1.3299639225
Average startup duration: 1.35100598335
Conclusion
It doesn't matter if tests run in headless or non-headless mode, the time until a new session in Firefox is available is twice that long compared to Chrome. Even with a recent Nightly build I get slightly worse numbers.
Here two startup Gecko profiles as created when running the script:
Non-headless: https://share.firefox.dev/3ij2aIB
Headless: https://share.firefox.dev/2AnxdBP
And here the timings from the geckodriver log file:
1593681435450 mozrunner::runner INFO Running command: "/Applications/Firefox.app/Contents/MacOS/firefox-bin" "-marionette" "-foreground" "-no-remote" "-profile" "/var/folders/c2/q_47wqh13n902fj9_zxczclr0000gn/T/rust_mozprofilet0Asy8"
1593681435451 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1:60389
1593681436013 Marionette TRACE Marionette enabled
1593681436085 Marionette TRACE Received observer notification toplevel-window-ready
1593681437492 Marionette TRACE Received observer notification marionette-startup-requested
1593681437492 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
1593681437504 Marionette TRACE All scripts recorded.
1593681437504 Marionette DEBUG Setting recommended pref apz.content_response_timeout to 60000
1593681437504 Marionette DEBUG Setting recommended pref browser.contentblocking.introCount to 99
1593681437504 Marionette DEBUG Setting recommended pref browser.download.panel.shown to true
1593681437504 Marionette DEBUG Setting recommended pref browser.newtabpage.enabled to false
1593681437505 Marionette DEBUG Setting recommended pref browser.pagethumbnails.capturing_disabled to true
1593681437505 Marionette DEBUG Setting recommended pref browser.search.update to false
1593681437505 Marionette DEBUG Setting recommended pref browser.tabs.disableBackgroundZombification to false
1593681437505 Marionette DEBUG Setting recommended pref browser.tabs.remote.separatePrivilegedContentProcess to false
1593681437505 Marionette DEBUG Setting recommended pref browser.tabs.unloadOnLowMemory to false
1593681437505 Marionette DEBUG Setting recommended pref browser.tabs.warnOnCloseOtherTabs to false
1593681437505 Marionette DEBUG Setting recommended pref browser.tabs.warnOnOpen to false
1593681437506 Marionette DEBUG Setting recommended pref browser.usedOnWindows10.introURL to
1593681437506 Marionette DEBUG Setting recommended pref browser.urlbar.suggest.searches to false
1593681437506 Marionette DEBUG Setting recommended pref datareporting.policy.dataSubmissionPolicyAccepted to false
1593681437506 Marionette DEBUG Setting recommended pref dom.disable_beforeunload to true
1593681437506 Marionette DEBUG Setting recommended pref dom.disable_open_during_load to false
1593681437506 Marionette DEBUG Setting recommended pref dom.file.createInChild to true
1593681437506 Marionette DEBUG Setting recommended pref dom.max_chrome_script_run_time to 0
1593681437507 Marionette DEBUG Setting recommended pref dom.max_script_run_time to 0
1593681437507 Marionette DEBUG Setting recommended pref dom.push.connection.enabled to false
1593681437507 Marionette DEBUG Setting recommended pref extensions.getAddons.cache.enabled to false
1593681437507 Marionette DEBUG Setting recommended pref extensions.getAddons.discovery.api_url to data:,
1593681437508 Marionette DEBUG Setting recommended pref network.http.prompt-temp-redirect to false
1593681437508 Marionette DEBUG Setting recommended pref privacy.trackingprotection.enabled to false
1593681437508 Marionette DEBUG Setting recommended pref security.fileuri.strict_origin_policy to false
1593681437508 Marionette DEBUG Setting recommended pref security.notification_enable_delay to 0
1593681437508 Marionette DEBUG Setting recommended pref signon.autofillForms to false
1593681437508 Marionette DEBUG Setting recommended pref signon.rememberSignons to false
1593681437509 Marionette DEBUG Setting recommended pref toolkit.cosmeticAnimations.enabled to false
1593681437547 Marionette INFO Listening on port 60389
1593681437547 Marionette DEBUG Marionette is listening
1593681437639 Marionette DEBUG Accepted connection 0 from 127.0.0.1:60430
1593681437639 geckodriver::marionette DEBUG Connection to Marionette established on 127.0.0.1:60389.
1593681437640 Marionette DEBUG 0 -> [0,1,"WebDriver:NewSession",{"acceptInsecureCerts":true,"browserName":"firefox"}]
1593681437640 Marionette WARN TLS certificate errors will be ignored for this session
1593681437655 Marionette TRACE [17] Frame script loaded
1593681437656 Marionette TRACE [17] Frame script registered
1593681437661 Marionette DEBUG 0 <- [1,1,null,{"sessionId":"7f654c62-0cf8-f249-8ce0-b6b95e98fba4","capabilities":{"browserName":"firefox","browserVersion":"78.0. ... /rust_mozprofilet0Asy8","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
1593681437663 webdriver::server DEBUG <- 200 OK {"value":{"sessionId":"7f654c62-0cf8-f249-8ce0-b6b95e98fba4","capabilities":{"acceptInsecureCerts":true,"browserName":"firefox","browserVersion":"78.0.1","moz:accessibilityChecks":false,"moz:buildID":"20200630195452","moz:geckodriverVersion":"0.26.0","moz:headless":false,"moz:processID":87896,"moz:profile":"/var/folders/c2/q_47wqh13n902fj9_zxczclr0000gn/T/rust_mozprofilet0Asy8","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"pageLoadStrategy":"normal","platformName":"mac","platformVersion":"19.5.0","rotatable":false,"setWindowRect":true,"strictFileInteractability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
[..]
As this log states the time between starting the command and the new session returned is actually only 2211 milliseconds. So that means we spend about 1s in Selenium or geckodriver too when creating the session.
|
Reporter | |
Comment 1•5 years ago
|
||
I enhanced the script locally to get some more details for the extra time as spent in Selenium / geckodriver:
results:
iteration 1: 1593681800.03 - 1593681802.83 = 2.80135393143
geckodriver log:
1593681801060 mozrunner::runner INFO Running command: "/Applications/FirefoxNightly.app/Contents/MacOS/firefox" "-marionette" "-headless" "-foreground" "-no-remote" "-profile" "/var/folders/c2/q_47wqh13n902fj9_zxczclr0000gn/T/rust_mozprofilefhvZd3"
[..]
1593681802831 webdriver::server DEBUG <- 200 OK {"value":{"sessionId":"37a28997-0b5d-5d44-8b12-7aba61fd28e4","capabilities":{"acceptInsecureCerts":true,"browserName":"firefox","browserVersion":"80.0a1","moz:accessibilityChecks":false,"moz:buildID":"20200629154604","moz:geckodriverVersion":"0.26.0","moz:headless":true,"moz:processID":89073,"moz:profile":"/var/folders/c2/q_47wqh13n902fj9_zxczclr0000gn/T/rust_mozprofilefhvZd3","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"pageLoadStrategy":"normal","platformName":"mac","platformVersion":"19.5.0","rotatable":false,"setWindowRect":true,"strictFileInteractability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
This indeed shows that we spend the 1s somewhere in between calling webdriver.Firefox() in Selenium and geckodriver starting the binary.
|
||
Comment 2•5 years ago
|
||
I used the following script:
import requests
import subprocess
import sys
import time
import threading
class OutputHandler(threading.Thread):
daemon = True
def run(self):
t0, stdout = self._args
t_prev = None
while True:
line = stdout.readline()
if not line:
break
timestamp, rest = line.split("\t", 1)
t = int(timestamp)
delta_start = t - t0
if t_prev is not None:
delta_prev = t - t_prev
else:
delta_prev = delta_start
t_prev = t
sys.stdout.write("%d %d %s" % (delta_start, delta_prev, rest))
t0 = time.time() * 1000
try:
proc = subprocess.Popen([sys.argv[1], "--log=trace", "--port=4444"],
stdout=subprocess.PIPE, universal_newlines=True)
output_handler = OutputHandler(args=(t0, proc.stdout))
output_handler.start()
resp = requests.post("http://localhost:4444/session", json={"capabilities": {}})
session_id = resp.json()["value"]["sessionId"]
resp = requests.delete("http://localhost:4444/session/%s" % session_id)
finally:
proc.kill()
output_handler.join()
And got the following output (first column is time since start, second is time since previous log entry):
4 4 geckodriver DEBUG Listening on 127.0.0.1:4444
13 9 webdriver::server DEBUG -> POST /session {"capabilities": {}}
19 6 mozrunner::runner INFO Running command: "/usr/bin/firefox" "--marionette" "-foreground" "-no-remote" "-profile" "/tmp/rust_mozprofileRFqLqT"
20 1 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1:45079
2543 2523 Marionette TRACE Marionette enabled
2818 275 Marionette TRACE Received observer notification toplevel-window-ready
7732 4914 Marionette TRACE Received observer notification marionette-startup-requested
7733 1 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
7882 149 Marionette TRACE All scripts recorded.
7882 0 Marionette DEBUG Setting recommended pref apz.content_response_timeout to 60000
7883 1 Marionette DEBUG Setting recommended pref browser.contentblocking.introCount to 99
7884 1 Marionette DEBUG Setting recommended pref browser.download.panel.shown to true
7884 0 Marionette DEBUG Setting recommended pref browser.newtabpage.enabled to false
7887 3 Marionette DEBUG Setting recommended pref browser.pagethumbnails.capturing_disabled to true
7888 1 Marionette DEBUG Setting recommended pref browser.search.update to false
7889 1 Marionette DEBUG Setting recommended pref browser.tabs.disableBackgroundZombification to false
7889 0 Marionette DEBUG Setting recommended pref browser.tabs.remote.separatePrivilegedContentProcess to false
7890 1 Marionette DEBUG Setting recommended pref browser.tabs.unloadOnLowMemory to false
7890 0 Marionette DEBUG Setting recommended pref browser.tabs.warnOnCloseOtherTabs to false
7890 0 Marionette DEBUG Setting recommended pref browser.tabs.warnOnOpen to false
7891 1 Marionette DEBUG Setting recommended pref browser.usedOnWindows10.introURL to
7891 0 Marionette DEBUG Setting recommended pref browser.urlbar.suggest.searches to false
7894 3 Marionette DEBUG Setting recommended pref datareporting.policy.dataSubmissionPolicyAccepted to false
7894 0 Marionette DEBUG Setting recommended pref dom.disable_beforeunload to true
7895 1 Marionette DEBUG Setting recommended pref dom.disable_open_during_load to false
7896 1 Marionette DEBUG Setting recommended pref dom.file.createInChild to true
7896 0 Marionette DEBUG Setting recommended pref dom.max_chrome_script_run_time to 0
7897 1 Marionette DEBUG Setting recommended pref dom.max_script_run_time to 0
7900 3 Marionette DEBUG Setting recommended pref dom.push.connection.enabled to false
7901 1 Marionette DEBUG Setting recommended pref extensions.getAddons.cache.enabled to false
7901 0 Marionette DEBUG Setting recommended pref extensions.getAddons.discovery.api_url to data:,
7902 1 Marionette DEBUG Setting recommended pref network.http.prompt-temp-redirect to false
7902 0 Marionette DEBUG Setting recommended pref privacy.trackingprotection.enabled to false
7902 0 Marionette DEBUG Setting recommended pref security.fileuri.strict_origin_policy to false
7902 0 Marionette DEBUG Setting recommended pref security.notification_enable_delay to 0
7903 1 Marionette DEBUG Setting recommended pref signon.autofillForms to false
7908 5 Marionette DEBUG Setting recommended pref signon.rememberSignons to false
7910 2 Marionette DEBUG Setting recommended pref toolkit.cosmeticAnimations.enabled to false
8085 175 Marionette INFO Listening on port 45079
8085 0 Marionette DEBUG Marionette is listening
8149 64 Marionette DEBUG Accepted connection 0 from 127.0.0.1:37282
8151 2 geckodriver::marionette DEBUG Connection to Marionette established on 127.0.0.1:45079.
8155 4 Marionette DEBUG 0 -> [0,1,"WebDriver:NewSession",{}]
8247 92 Marionette TRACE [6] Frame script loaded
8250 3 Marionette TRACE [6] Frame script registered
8269 19 Marionette DEBUG 0 <- [1,1,null,{"sessionId":"c80ef5bc-a6a5-4611-8ece-091d49f2cbf4","capabilities":{"browserName":"firefox","browserVersion":"77.0. ... /rust_mozprofileRFqLqT","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
8323 54 webdriver::server DEBUG <- 200 OK {"value":{"sessionId":"c80ef5bc-a6a5-4611-8ece-091d49f2cbf4","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"77.0.1","moz:accessibilityChecks":false,"moz:buildID":"20200602222727","moz:geckodriverVersion":"0.26.0","moz:headless":false,"moz:processID":1210969,"moz:profile":"/tmp/rust_mozprofileRFqLqT","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"pageLoadStrategy":"normal","platformName":"linux","platformVersion":"5.4.0-33-generic","rotatable":false,"setWindowRect":true,"strictFileInteractability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
8332 9 webdriver::server DEBUG -> DELETE /session/c80ef5bc-a6a5-4611-8ece-091d49f2cbf4
8338 6 Marionette DEBUG 0 -> [0,2,"Marionette:Quit",{"flags":["eForceQuit"]}]
8339 1 Marionette INFO Stopped listening on port 45079
8477 138 Marionette TRACE Received observer notification quit-application
8494 17 Marionette DEBUG 0 <- [1,2,null,{"cause":"shutdown"}]
8576 82 webdriver::server DEBUG Deleting session
8593 17 Marionette DEBUG 0 -> [0,3,"Marionette:Quit",{"flags":["eForceQuit"]}]
8594 1 Marionette DEBUG 0 <- [1,3,{"error":"invalid session id","message":"Tried to run command without establishing a connection","stacktrace":"WebDriver ... t@chrome://marionette/content/server.js:249:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:501:20\n"},null]
8675 81 Marionette DEBUG Closed connection 0
9270 595 Marionette TRACE Received observer notification xpcom-will-shutdown
9270 0 Marionette DEBUG Resetting recommended pref apz.content_response_timeout
9270 0 Marionette DEBUG Resetting recommended pref browser.contentblocking.introCount
9271 1 Marionette DEBUG Resetting recommended pref browser.download.panel.shown
9271 0 Marionette DEBUG Resetting recommended pref browser.newtabpage.enabled
9272 1 Marionette DEBUG Resetting recommended pref browser.pagethumbnails.capturing_disabled
9272 0 Marionette DEBUG Resetting recommended pref browser.search.update
9272 0 Marionette DEBUG Resetting recommended pref browser.tabs.disableBackgroundZombification
9274 2 Marionette DEBUG Resetting recommended pref browser.tabs.remote.separatePrivilegedContentProcess
9275 1 Marionette DEBUG Resetting recommended pref browser.tabs.unloadOnLowMemory
9275 0 Marionette DEBUG Resetting recommended pref browser.tabs.warnOnCloseOtherTabs
9275 0 Marionette DEBUG Resetting recommended pref browser.tabs.warnOnOpen
9275 0 Marionette DEBUG Resetting recommended pref browser.usedOnWindows10.introURL
9276 1 Marionette DEBUG Resetting recommended pref browser.urlbar.suggest.searches
9277 1 Marionette DEBUG Resetting recommended pref datareporting.policy.dataSubmissionPolicyAccepted
9277 0 Marionette DEBUG Resetting recommended pref dom.disable_beforeunload
9277 0 Marionette DEBUG Resetting recommended pref dom.disable_open_during_load
9277 0 Marionette DEBUG Resetting recommended pref dom.file.createInChild
9277 0 Marionette DEBUG Resetting recommended pref dom.max_chrome_script_run_time
9278 1 Marionette DEBUG Resetting recommended pref dom.max_script_run_time
9280 2 Marionette DEBUG Resetting recommended pref dom.push.connection.enabled
9280 0 Marionette DEBUG Resetting recommended pref extensions.getAddons.cache.enabled
9280 0 Marionette DEBUG Resetting recommended pref extensions.getAddons.discovery.api_url
9280 0 Marionette DEBUG Resetting recommended pref network.http.prompt-temp-redirect
9280 0 Marionette DEBUG Resetting recommended pref privacy.trackingprotection.enabled
9280 0 Marionette DEBUG Resetting recommended pref security.fileuri.strict_origin_policy
9281 1 Marionette DEBUG Resetting recommended pref security.notification_enable_delay
9281 0 Marionette DEBUG Resetting recommended pref signon.autofillForms
9282 1 Marionette DEBUG Resetting recommended pref signon.rememberSignons
9283 1 Marionette DEBUG Resetting recommended pref toolkit.cosmeticAnimations.enabled
9284 1 Marionette DEBUG Marionette stopped listening
9899 615 geckodriver::marionette DEBUG Browser process stopped: exit code: 0
9915 16 webdriver::server DEBUG <- 200 OK {"value":null}
My conclusion from that is ~all the time is waiting for Firefox/marionette to start. The only significant time inside GeckoDriver is polling for the connection to be open. I tried changing the polling interval to 10ms rather than 100ms, but didn't see much difference. So unless I'm mistaken, GeckoDriver isn't a bottleneck but Marionette startup is, and Selenium may be.
|
|
Reporter | |
Comment 3•5 years ago
|
||
So with more debug logs in geckodriver I was able to nail it down a bit further. Here the timings:
SystemTime { tv_sec: 1593686977, tv_nsec: 448298000 } started main
SystemTime { tv_sec: 1593686977, tv_nsec: 448402000 } after make app
SystemTime { tv_sec: 1593686977, tv_nsec: 448565000 } after marionette handler
SystemTime { tv_sec: 1593686977, tv_nsec: 448721000 } server started
SystemTime { tv_sec: 1593686977, tv_nsec: 448754000 } entered server's run command
SystemTime { tv_sec: 1593686978, tv_nsec: 457244000 } handle web driver message
SystemTime { tv_sec: 1593686978, tv_nsec: 457279000 } handle command
SystemTime { tv_sec: 1593686978, tv_nsec: 457290000 } begin create_connection
SystemTime { tv_sec: 1593686978, tv_nsec: 458147000 } begin of start_browser
1593686978462 mozrunner::runner INFO Running command: "/Applications/Firefox.app/Contents/MacOS/firefox-bin" "-marionette" "-headless" "-foreground" "-no-remote" "-profile" "/var/folders/c2/q_47wqh13n902fj9_zxczclr0000gn/T/rust_mozprofileXqOorj"
As you can see we entered the server's run command in webdriver, which basically waits for commands. But the first command gets received about 1s later on. So whatever Selenium is doing the new session command is getting send out with a delay. I poked around in the Selenium code and found the following code for starting up the driver service:
As you can see if the driver is not connectable the next attempt to connect will be made 1s later. If that is the right delay is questionable given that the driver should start and have the socket ready instantly; compared to the start-up of the browser. But there is still a quite small race here, so that in case the driver takes a little bit too long to start the listening socket a full second is spend before trying again.
|
|
Reporter | |
Comment 4•5 years ago
|
||
Ok, I raised the Selenium specific performance issue as: https://github.com/SeleniumHQ/selenium/issues/8477
|
||
Comment 5•5 years ago
|
||
As one suspected issue is disk access, the profiles should be re-recorded with disk i/o tracing enabled.
|
||
Comment 6•5 years ago
|
||
I added the following timings to check when I worked on the Selenium issue and was not able to recreate the 1s delay as it never entered the 2nd loop. There is a chance that using a dict here to collect data may slow down the code by 12ms that :whimboo mentioned to me but I feel that is highly doubtful
|
||
Comment 7•5 years ago
|
||
(In reply to :Harald Kirschner :digitarald from comment #5)
As one suspected issue is disk access, the profiles should be re-recorded with disk i/o tracing enabled.
The 2 profiles have the file I/O (mainthreadio,fileio,fileioall) features. I think they are not recorded because this wasn't a nightly build.
|
|
Reporter | |
Comment 8•5 years ago
|
||
Here a recorded profile with a Nightly build: https://share.firefox.dev/2C28LXb
(In reply to David Burns :automatedtester from comment #6)
Created attachment 9161005 [details]
timings checkI added the following timings to check when I worked on the Selenium issue and was not able to recreate the 1s delay as it never entered the 2nd loop. There is a chance that using a dict here to collect data may slow down the code by 12ms that :whimboo mentioned to me but I feel that is highly doubtful
I applied your patch and that's what I get with the 1s delay between the connection attempts:
{
'beforeProcessStart': 1593767783.748409,
'afterProcessStart': 1593767783.758836,
'loopCount': 1,
'beforeCheckProcessRunningTime0': 1593767783.758841,
'afterCheckProcessRunningTime0': 1593767783.758899,
'beforeCheckConnectableTime0': 1593767783.7589,
'beforeCheckProcessRunningTime1': 1593767784.7641,
'afterCheckProcessRunningTime1': 1593767784.764135,
'beforeCheckConnectableTime1': 1593767784.764136,
'afterCheckIsConnectable1': 1593767784.765288
}
When I reduce the wait duration for the loop from 1s to just 10ms I also only get a single iteration:
{
'beforeProcessStart': 1593767978.261259,
'afterProcessStart': 1593767978.268726,
'loopCount': 1,
'beforeCheckProcessRunningTime0': 1593767978.268753,
'afterCheckProcessRunningTime0': 1593767978.268818,
'beforeCheckConnectableTime0': 1593767978.268819,
'beforeCheckProcessRunningTime1': 1593767978.282264,
'afterCheckProcessRunningTime1': 1593767978.282282,
'beforeCheckConnectableTime1': 1593767978.282283,
'afterCheckIsConnectable1': 1593767978.283126
}
Overall it's a reduction of the start-up time for Firefox through Selenium from 3.2s to around 2.1s, which is 33%.
Severity: -- → S3
|
|
Reporter | |
Updated•2 years ago
|
|
|
Reporter | |
Comment 9•2 years ago
|
||
Given that geckodriver would only cover WebDriver classic and we have BiDi as well now, lets move this bug to the Remote Protocol / Agent component.
Component: geckodriver → Agent
Product: Testing → Remote Protocol
Summary: [meta] Slow start-up times of Firefox when using geckodriver → [meta] Slow start-up times of Firefox when using remote protocols (WebDriver, CDP)
You need to log in
before you can comment on or make changes to this bug.
Description
•