Closed Bug 900444 Opened 6 years ago Closed 6 years ago

Mozprofile writes permissions inefficiently

Categories

(Testing :: Mozbase, defect)

defect
Not set

Tracking

(Not tracked)

RESOLVED FIXED
mozilla25

People

(Reporter: msucan, Assigned: ahal)

Details

Attachments

(2 files)

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.
(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?
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 :/
Thanks for the investigation. How can I profile mach myself? To double check if I have the same problem.
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.
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
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+
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
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
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla25
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.