Mozprofile writes permissions inefficiently

RESOLVED FIXED in mozilla25

Status

Testing
Mozbase
RESOLVED FIXED
4 years ago
4 years ago

People

(Reporter: msucan, Assigned: ahal)

Tracking

unspecified
mozilla25
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(2 attachments)

(Reporter)

Description

4 years ago
Whenever I run mach mochitest-browser foo.js I have to wait 5-10 seconds before the tests start to run, for no obvious reason. See related bug 900438.

Anything I can look into? Thanks!
I noticed this yesterday and was just about to file it. On my fast desktop machine (Ivy Bridge, 32GB ram, build is on an SSD), it takes almost 30 seconds before Firefox gets launched when running "mach mochitest-plain". I don't see any output for most of this time, but my /tmp is on a non-SSD, and I can hear it churning, so something must be hitting the disk a lot.

I'd guess this is either fallout from bug 688667 or bug 865349.
(Reporter)

Comment 2

4 years ago
(In reply to Ted Mielczarek [:ted.mielczarek] (post-vacation backlog) from comment #1)
> I noticed this yesterday and was just about to file it. On my fast desktop
> machine (Ivy Bridge, 32GB ram, build is on an SSD), it takes almost 30
> seconds before Firefox gets launched when running "mach mochitest-plain". I
> don't see any output for most of this time, but my /tmp is on a non-SSD, and
> I can hear it churning, so something must be hitting the disk a lot.

Can you please check if bug 900438 affects you?
(Assignee)

Comment 3

4 years ago
I did a quick profile: http://www.pastebin.mozilla.org/2759289

Looks like the delay is from mozprofile writing permission to the sqlite3 db, bug 688667 is the likely culprit. I wonder what is different about mozprofile vs automation.py :/
(Reporter)

Comment 4

4 years ago
Thanks for the investigation. How can I profile mach myself? To double check if I have the same problem.
(Assignee)

Comment 5

4 years ago
I just used the built-in profiler: http://docs.python.org/2/library/profile.html

Then I wrapped the call to runTests in the testing/mochitest/mach_commands.py. Finally I made runtests return early to avoid profiling things we don't care about.
One way we could improve the permissions code is to move https://github.com/mozilla/mozbase/blob/master/mozprofile/mozprofile/permissions.py#L254-L255 to before the for loop; perhaps this is a slow operation.
(Assignee)

Comment 7

4 years ago
Hah! Good call:

[~/hg/mozilla-central]$ ./mach mochitest-plain                                                                                                                                                              
107
         21029 function calls (20828 primitive calls) in 0.390 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      110    0.254    0.002    0.254    0.002 {method 'execute' of 'sqlite3.Cursor' objects}
        1    0.088    0.088    0.088    0.088 {method 'commit' of 'sqlite3.Connection' objects}
       52    0.004    0.000    0.004    0.000 expatbuilder.py:743(start_element_handler)
      756    0.002    0.000    0.005    0.000 tokenize.py:264(generate_tokens)
Assignee: nobody → ahalberstadt
Status: NEW → ASSIGNED
Component: Mochitest → Mozbase
OS: Linux → All
QA Contact: hskupin
Hardware: x86_64 → All
Summary: Long delay when any mach mochitest-browser/mochitest-chrome command is run → Mozprofile writes permissions inefficiently
(Assignee)

Comment 8

4 years ago
Created attachment 784551 [details] [diff] [review]
Patch 1.0 - make write_db more efficient
Attachment #784551 - Flags: review?(jgriffin)
Comment on attachment 784551 [details] [diff] [review]
Patch 1.0 - make write_db more efficient

Review of attachment 784551 [details] [diff] [review]:
-----------------------------------------------------------------

Cool, thanks!
Attachment #784551 - Flags: review?(jgriffin) → review+
Created attachment 784567 [details] [diff] [review]
Trace mach commands

This patch makes mach dump out function execution. You can use it to
eyeball which functions are taking long to execute.
Assignee: ahalberstadt → gps
No, bzexport, I didn't want to assign this to me.
Assignee: gps → ahalberstadt
(Assignee)

Comment 12

4 years ago
https://github.com/mozilla/mozbase/commit/7a2fb7796778c61ddb744436bf7c3d30c8548a22

I also invoked the cherry pick clause of the mozbase mirroring and pushed to m-c:
https://hg.mozilla.org/integration/mozilla-inbound/rev/019c4e995db4

The reasons are, this is low risk and high pain for developers.
https://hg.mozilla.org/mozilla-central/rev/019c4e995db4
Status: ASSIGNED → RESOLVED
Last Resolved: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla25
(Reporter)

Comment 14

4 years ago
Thank you all for the quick fix. Much better now.
You need to log in before you can comment on or make changes to this bug.