773903 - ~1s shutdown delay in xpcshell in xpcom shutdown

Status: RESOLVED FIXED

(Core :: XPCOM, defect)

Description

[Gregory Szorc [:gps]]

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)

Comment 1

[(not currently active) Ted Mielczarek]

Fallout from bsmedberg's changes for flash crash reporting?

Comment 2

[Benjamin Smedberg]

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?

Comment 3

[Gregory Szorc [:gps]]

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.

Comment 4

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

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?

Comment 5

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

ok, I was able to reproduce this. I will take a look.

Comment 6

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

Attachment: 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=[e-mail]

Comment 7

[Gregory Szorc [:gps]]

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 :)

Comment 8

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

Attachment: Just update from upstream

The upstream code review is done, so we can just copy the upstream version to m-c.

Comment 9

[(not currently active) 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.

Comment 10

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/15bb4fb1096a