~1s shutdown delay in xpcshell in xpcom shutdown

RESOLVED FIXED in mozilla17

Status

()

Core
XPCOM
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: gps, Assigned: espindola)

Tracking

Trunk
mozilla17
x86_64
Mac OS X
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment, 1 obsolete attachment)

(Reporter)

Description

5 years ago
Sometime in the past week or so I noticed that my xpcshell tests were executing much slower - about 1s per test slower. I am running debug builds on OS X and building with Clang SVN tip.

Strangely, tests on buildbot don't seem to encounter this delay.

I locally hacked up the xpcshell test runner on my local machine to not buffer process output and was able to obtain wall timings of each line as it is printed. I've isolated the pause to:

0.24 WARNING: nsExceptionService ignoring thread destruction after shutdown: file /Users/gps/src/services-central/xpcom/base/nsExceptionService.cpp, line 166
1.21 WARNING: OOPDeinit() without successful OOPInit(): file /Users/gps/src/services-central/toolkit/crashreporter/nsExceptionHandler.cpp, line 2109

I have no clue what this actually corresponds to. But, it seems to be in the heart of xpcom shutdown.

:anant also experiences this delay on OS X, so I don't think I'm a one-off here.

0.01 make -C . -j8 -s -w xpcshell-tests
0.13 make: Entering directory `/Users/gps/src/services-central/objdir'
5.94 TEST-INFO | /Users/gps/src/services-central/objdir/_tests/xpcshell/chrome/test/unit/test_abi.js | running test ...
6.99 TEST-PASS | /Users/gps/src/services-central/objdir/_tests/xpcshell/chrome/test/unit/test_abi.js | test passed (time: 1051.375ms)
6.99 TEST-INFO | /Users/gps/src/services-central/objdir/_tests/xpcshell/chrome/test/unit/test_bug292789.js | running test ...
8.04 TEST-PASS | /Users/gps/src/services-central/objdir/_tests/xpcshell/chrome/test/unit/test_bug292789.js | test passed (time: 1052.949ms)
8.04 TEST-INFO | /Users/gps/src/services-central/objdir/_tests/xpcshell/chrome/test/unit/test_bug380398.js | running test ...
9.08 TEST-PASS | /Users/gps/src/services-central/objdir/_tests/xpcshell/chrome/test/unit/test_bug380398.js | test passed (time: 1041.118ms)
9.09 TEST-INFO | /Users/gps/src/services-central/objdir/_tests/xpcshell/chrome/test/unit/test_bug397073.js | running test ...
10.15 TEST-PASS | /Users/gps/src/services-central/objdir/_tests/xpcshell/chrome/test/unit/test_bug397073.js | test passed (time: 1063.758ms)
10.15 TEST-INFO | /Users/gps/src/services-central/objdir/_tests/xpcshell/chrome/test/unit/test_bug399707.js | running test ...
11.19 TEST-PASS | /Users/gps/src/services-central/objdir/_tests/xpcshell/chrome/test/unit/test_bug399707.js | test passed (time: 1036.332ms)
11.19 TEST-INFO | /Users/gps/src/services-central/objdir/_tests/xpcshell/chrome/test/unit/test_bug401153.js | running test ...
12.23 TEST-PASS | /Users/gps/src/services-central/objdir/_tests/xpcshell/chrome/test/unit/test_bug401153.js | test passed (time: 1041.417ms)
Fallout from bsmedberg's changes for flash crash reporting?
I don't think so, the "OOPDeinit without successful OOPInit" warning is a longstanding stupid warning that's generally ignorable and should probably be removed.

Time to break out a profiler?
(Reporter)

Comment 3

5 years ago
I broke out iprofiler and traced this down to the allocateBranchIsland call in the mach_override_ptr call in mozilla::PoisonWrite().

https://hg.mozilla.org/mozilla-central/annotate/9b876829ed32/xpcom/build/mozPoisonWriteMac.cpp#l249.

That points to https://hg.mozilla.org/mozilla-central/rev/da871640d448 and bug 732173.

My one profiler run revealed a delay of 926.8ms. Not quite 1 full second, but close.

I can provide full iprofiler/DTPerformanceSession data on request. Just tell me what all you want me to collect.
(Reporter)

Updated

5 years ago
Depends on: 732173
I didn't notice this slowdowns while developing the patch, strange.
What version of OS X are you using. Does the problem also show up in firefox itself? Can you post the .mozconfig you used?
Assignee: nobody → respindola
Status: NEW → ASSIGNED
ok, I was able to reproduce this. I will take a look.
Created attachment 644177 [details] [diff] [review]
fix it

I am sending this upstream, but if we could do the mozilla review in parallel that would be nice.

The problem was that the address space had libsystem_kernel (which contains write) very close to the end and we were walking back one page at a time looking for a place to put the branch island.

This patch changes two things:

* Walk back one map entry at a time, makes a big difference when going past XUL
* Remember the last entry we allocated.

https://tbpl.mozilla.org/?tree=Try&pusher=respindola@mozilla.com
Attachment #644177 - Flags: review?(ted.mielczarek)
Attachment #644177 - Flags: feedback?(gps)
(Reporter)

Comment 7

5 years ago
Comment on attachment 644177 [details] [diff] [review]
fix it

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

This fixes it for me. I'm not qualified to say anything about the magic in your patch :)
Attachment #644177 - Flags: feedback?(gps) → feedback+
Blocks: 770605
Created attachment 644995 [details] [diff] [review]
Just update from upstream

The upstream code review is done, so we can just copy the upstream version to m-c.
Attachment #644177 - Attachment is obsolete: true
Attachment #644177 - Flags: review?(ted.mielczarek)
Attachment #644995 - Flags: review?(ted.mielczarek)
Comment on attachment 644995 [details] [diff] [review]
Just update from upstream

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

Thanks, I really wasn't comfortable reviewing this code, but if it's been reviewed upstream then I'm happy to stamp it.
Attachment #644995 - Flags: review?(ted.mielczarek) → review+
https://hg.mozilla.org/mozilla-central/rev/15bb4fb1096a
Status: ASSIGNED → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla17
You need to log in before you can comment on or make changes to this bug.