1791373 - Excessive usage of "path_exists" when copying the profile onto the device spams the geckodriver log

Status: RESOLVED INACTIVE

(Testing :: geckodriver, defect)

Description

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Might be related to bug 1757721 because we keep too many backups of prefs.js around. There are a lot of calls to ls -l that also prints all found files and details to the log:

https://treeherder.mozilla.org/logviewer?job_id=390722213&repo=autoland&lineNumber=101515

[task 2022-09-17T19:13:54.396Z] 19:13:54     INFO - PID 4103 | 1663442034394	mozdevice	TRACE	execute_host_command: >> "shell:ls /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile"
[task 2022-09-17T19:13:54.406Z] 19:13:54     INFO - PID 4103 | 1663442034405	mozdevice	TRACE	execute_host_command: << "user.geckodriver_backup_22\n"
[..]
[task 2022-09-17T19:14:12.716Z] 19:14:12     INFO - PID 4103 | 1663442052715	mozdevice	TRACE	execute_host_command: >> "shell:ls /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile"
[task 2022-09-17T19:14:12.840Z] 19:14:12     INFO - PID 4103 | 1663442052833	mozdevice	TRACE	execute_host_command: << "cert9.db                    user.geckodriver_backup_23 \nkey4.db                     user.geckodriver_backup_24 \npkcs11.txt                  user.geckodriver_backup_25 \nprefs.js                    user.geckodriver_backup_26 \nuser.geckodriver_backup     [..]
[task 2022-09-17T19:14:12.879Z] 19:14:12     INFO - PID 4103 | 1663442052878	geckodriver::android	DEBUG	Content of generated GeckoView config file:

Alone the above preparation of the profile takes 18s!

I would suggest that we do not print all the details to the log and maybe stop it completely for calls to ls -l.

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2]]

After some checks I feel that disabling logging for only a single command is not great. It would still be good to see what gets send and received when trace logs are enabled. As such I would suggest that we better continue with the proper truncation of the log output only over on bug 1611004 and leave the behavior here as is (not creating all the backups see bug 1757721 should actually help a lot).

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Actually the problem here is copying the profile folder onto the device. We run the path_exists check for each and every file that gets copied. As such as more files we are copying as more log entries we will see:

1:34.22 pid:5549 1663670237293	mozdevice	TRACE	execute_host_command: >> "shell:ls /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile"
 1:34.22 pid:5549 1663670237297	mozdevice	TRACE	execute_host_command: << "user.geckodriver_backup\n"
 1:34.23 pid:5549 1663670237300	mozdevice	TRACE	execute_host_command: >> "host:transport:emulator-5554"
 1:34.23 pid:5549 1663670237300	mozdevice	TRACE	execute_host_command: << []
 1:34.23 pid:5549 1663670237300	mozdevice	TRACE	execute_host_command: >> "shell:ls /sdcard/Android/data/org.mozilla.geckoview.test_runner/files/test_root/org.mozilla.geckoview.test_runner-geckodriver-profile"
 1:34.23 pid:5549 1663670237304	mozdevice	TRACE	execute_host_command: << "pkcs11.txt  user.geckodriver_backup\n"
 1:34.23 pid:5549 1663670237309	mozdevice	TRACE	execute_host_command: >> "host:transport:emulator-5554"
 1:34.23 pid:5549 1663670237309	mozdevice	TRACE	execute_host_command: << []

I think that the code for copying a whole folder should only check the path existence once.

Comment 3

[BugBot [:suhaib / :marco/ :calixte]]

The severity field is not set for this bug.
:whimboo, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 4

[Julian Descottes [:jdescottes]]

@Henrik: Now that both bug 1611004 and bug 1757721 have been fixed, do you think we should still keep this bug open or is this good enough?

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I would close it for now given that it might need some more refactoring that we do not have the time for at the moment and the reduction of the amount of logs has indeed reduced a lot! Lets reopen in case it becomes relevant again.