Last Comment Bug 773903 - ~1s shutdown delay in xpcshell in xpcom shutdown
: ~1s shutdown delay in xpcshell in xpcom shutdown
Product: Core
Classification: Components
Component: XPCOM (show other bugs)
: Trunk
: x86_64 Mac OS X
: -- normal (vote)
: mozilla17
Assigned To: Rafael Ávila de Espíndola (:espindola) (not reading bugmail)
: Nathan Froyd [:froydnj]
Depends on: 732173
Blocks: 770605
  Show dependency treegraph
Reported: 2012-07-13 19:09 PDT by Gregory Szorc [:gps]
Modified: 2012-07-24 03:01 PDT (History)
6 users (show)
See Also:
Crash Signature:
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---

fix it (8.93 KB, patch)
2012-07-19 21:48 PDT, Rafael Ávila de Espíndola (:espindola) (not reading bugmail)
gps: feedback+
Details | Diff | Splinter Review
Just update from upstream (7.32 KB, patch)
2012-07-23 11:20 PDT, Rafael Ávila de Espíndola (:espindola) (not reading bugmail)
ted: review+
Details | Diff | Splinter Review

Description User image Gregory Szorc [:gps] 2012-07-13 19:09:28 PDT
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 User image Ted Mielczarek [:ted.mielczarek] 2012-07-16 09:27:26 PDT
Fallout from bsmedberg's changes for flash crash reporting?
Comment 2 User image Benjamin Smedberg [:bsmedberg] 2012-07-16 09:54:51 PDT
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 User image Gregory Szorc [:gps] 2012-07-18 15:19:25 PDT
I broke out iprofiler and traced this down to the allocateBranchIsland call in the mach_override_ptr call in mozilla::PoisonWrite().

That points to 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 User image Rafael Ávila de Espíndola (:espindola) (not reading bugmail) 2012-07-19 05:48:27 PDT
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 User image Rafael Ávila de Espíndola (:espindola) (not reading bugmail) 2012-07-19 07:58:50 PDT
ok, I was able to reproduce this. I will take a look.
Comment 6 User image Rafael Ávila de Espíndola (:espindola) (not reading bugmail) 2012-07-19 21:48:59 PDT
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.
Comment 7 User image Gregory Szorc [:gps] 2012-07-20 11:33:32 PDT
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 User image Rafael Ávila de Espíndola (:espindola) (not reading bugmail) 2012-07-23 11:20:48 PDT
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.
Comment 9 User image Ted Mielczarek [:ted.mielczarek] 2012-07-23 11:27:14 PDT
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 User image Ed Morley [:emorley] 2012-07-24 03:01:20 PDT

Note You need to log in before you can comment on or make changes to this bug.