1397297 - nsCycleCollector::FreeSnowWhite() could be more incremental

Status: RESOLVED FIXED

(Core :: XPCOM, defect, P1)

Description

[Ben Kelly [:bkelly, not reviewing]]

Sometimes we are free'ing cycle collected objects via an idle runnable, like in this profile:

https://perfht.ml/2w7FFwQ

The FreeSnowWhite() loop, though, can sometimes run quite long.  In this case we are free'ing many HTMLImageElement objects and it runs for 77ms.  Since we don't have a strict deadline to meet it would be nice to time-limit the FreeSnowWhite() loop and reschedule another idle runnable to continue if necessary.

Clearly there is some tradeoff against putting work off too long.  Maybe we could be somewhat loose with this time limit and allow it to break a single frame budget.  We should just prevent it from triggering excessive jank.  (In a previous profile I saw this loop take >300ms.)

Maybe a time limit of 40ms (2.5 frames)?

Comment 1

[Ben Kelly [:bkelly, not reviewing]]

I guess the profile in comment 0 is a timed out idle runnable triggering the FreeSnowWhite().

Comment 2

[Olli Pettay [:smaug][[e-mail]]]

One thing to remember that checking the timelimit often is itself slow.
I was trying to make CC's traverse more incremental, but budget checking was showing up in the profiles quite easily.

Comment 3

[Ben Kelly [:bkelly, not reviewing]]

(In reply to Olli Pettay [:smaug] from comment #2)
> One thing to remember that checking the timelimit often is itself slow.
> I was trying to make CC's traverse more incremental, but budget checking was
> showing up in the profiles quite easily.

The way I dealt with that in setTimeout() code was to only check every N items:

http://searchfox.org/mozilla-central/source/dom/base/TimeoutManager.cpp#782

I use N=100 there, but maybe something lower would be better here since the individual steps are probably more expensive here.

Comment 4

[Olli Pettay [:smaug][[e-mail]]]

Sure, that is what cycle collector does too. But because cycle collector touches memory from different areas, any memory access may suddenly be surprisingly slow - or that is what I saw when trying to improve it.
But anyhow, some budgeting here would be good.

Comment 5

[Adam Gashlin (he/him) [:agashlin] (ex-moco)]

I have an initial patch for this, but in order to account for the time it takes to destroy, I had SnowWhiteKiller do the destruction that would normally be done in ~SnowWhiteKiller immediately, while traversing the purple list (the alternative being walking the list, destructing, then walking the list anew, which seems too slow). This can end up adding to the purple list, though, which seems to be leading to crashes.

Unless I'm misreading the comments, the section here [1] seems intended to handle the purple list growing while it is being traversed, but in that case oldLength - newLength is negative and passed in to PopLastN, which takes a uint32_t (and it wouldn't be able to do anything reasonable with a negative anyway). Does this work in general?

I'm not sure what the fix could be in this case, maybe it is just not safe to add to the list while traversing it?

[1] http://searchfox.org/mozilla-central/rev/184f0c7888dd6abb32235377693b7d1fc0b75ac1/xpcom/base/nsCycleCollector.cpp#1132-1151

Comment 6

[Olli Pettay [:smaug][[e-mail]]]

There is a bug there yes. The list grows so very rarely, that I hadn't notice it.

Comment 7

[Adam Gashlin (he/him) [:agashlin] (ex-moco)]

Attachment: skippable SnowWhiteKiller

I've attached the attempt I made, which I strongly suspect still has bugs due to this very suspicious failure in try (Linux debug bc12), which I haven't been able to reproduce:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=93c9acb871397d17d1345c779377585262b7f18e&selectedJob=140030093

It is an assertion failure here:
http://searchfox.org/mozilla-central/rev/ed212c79cfe86357e9a5740082b9364e7f6e526f/xpcom/base/CycleCollectedJSRuntime.cpp#1216

So something is clearly, but rarely, breaking... it may be that this approach is just not going to work, but I can't see why yet.

Comment 8

[Olli Pettay [:smaug][[e-mail]]]

I'm not familiar with the following JS engine output. What edge is gray there and what is black?

[task 2017-10-26T23:06:35.589Z] 23:06:35     INFO - GECKO(1090) | Found black to gray edge to Object XULElement 0xd28fbfa0
[task 2017-10-26T23:06:35.591Z] 23:06:35     INFO - GECKO(1090) |   from Object Proxy 0xe2120310 proxy target edge
[task 2017-10-26T23:06:35.593Z] 23:06:35     INFO - GECKO(1090) |   from Object Object 0xe3034670 object slot edge
[task 2017-10-26T23:06:35.595Z] 23:06:35     INFO - GECKO(1090) |   from Object Proxy 0xe350fbb0 proxy target edge
[task 2017-10-26T23:06:35.597Z] 23:06:35     INFO - GECKO(1090) |   from Object XULElement 0xd28fbfa0 object slot edge
[task 2017-10-26T23:06:35.601Z] 23:06:35     INFO - GECKO(1090) |   from root Preserved wrapper

Comment 9

[Olli Pettay [:smaug][[e-mail]]]

Hmm, is that a bit old tree which you used to push this. jonco changed something related recently.

Comment 10

[Steve Fink [:sfink] [:s:]]

I believe "Object XULElement 0xd28fbfa0" is gray, and "Object Proxy 0xe2120310" (and everything else in the path to the root) is black. (Edges aren't gray or black. I guess they're strong or weak.)

Comment 11

[Olli Pettay [:smaug][[e-mail]]]

oh, sure, objects are black/gray :)

What is that  from root Preserved wrapper then?
Do all those from... mean a black->gray?

Comment 12

[Steve Fink [:sfink] [:s:]]

The way I read it, there is an all-black path from "Preserved wrapper" up until "Object Proxy 0xe2120310", and only the last "Object XULElement 0xd28fbfa0" is gray. Looking at the code... yeah, I think that's all this is saying.

Comment 13

[Jon Coppeard (:jonco)]

(In reply to Adam Gashlin [:agashlin] from comment #7)
This is an existing issue (bug 1399866) and not a problem with your code.

"black to gray edge" means edge from a black object to a gray object.  The edge in question is between Proxy 0xe2120310 (black) to XULElement 0xd28fbfa0 (gray) in the log output above.  I've landed a patch to make this output clearer and more detailed.  Note that the example above is a cycle (gray to black edges are not a problem).

Comment 14

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 8926491 [details] [diff] [review]
skippable SnowWhiteKiller

>diff --git a/js/xpconnect/src/XPCJSRuntime.cpp b/js/xpconnect/src/XPCJSRuntime.cpp
>--- a/js/xpconnect/src/XPCJSRuntime.cpp
>+++ b/js/xpconnect/src/XPCJSRuntime.cpp
>@@ -121,7 +121,9 @@ public:
>   NS_IMETHOD Run() override
>   {
>       TimeStamp start = TimeStamp::Now();
>-      bool hadSnowWhiteObjects = nsCycleCollector_doDeferredDeletion();
>+      js::SliceBudget budget = js::SliceBudget(js::TimeBudget(10));
Quite high, given that iCC slice budget (kICCSliceBudget) is 3ms


>   ~SnowWhiteKiller()
>   {
>     for (auto iter = mObjects.Iter(); !iter.Done(); iter.Next()) {
>       SnowWhiteObject& o = iter.Get();
>-      if (!o.mRefCnt->get() && !o.mRefCnt->IsInPurpleBuffer()) {
>-        mCollector->RemoveObjectFromGraph(o.mPointer);
>-        o.mRefCnt->stabilizeForDeletion();
>-        {
>-          JS::AutoEnterCycleCollection autocc(mCollector->Runtime()->Runtime());
>-          o.mParticipant->Trace(o.mPointer, *this, nullptr);
>-        }
>-        o.mParticipant->DeleteCycleCollectable(o.mPointer);
>+      KillObject(o);
>+    }
>+  }
>+
>+  void
>+  KillObject(SnowWhiteObject& o) {
Arguments should be in form aName.
{ goes to its own line.


>   bool
>   Visit(nsPurpleBuffer& aBuffer, nsPurpleBufferEntry* aEntry)
>   {
>+    if (mBudget) {
>+      if (mBudget->isOverBudget()) {
>+        return false;
>+      }
>+      mBudget->step(100);
This should have some comment why 100

Comment 15

[Olli Pettay [:smaug][[e-mail]]]

I think this is qf:p1.

Comment 16

[Olli Pettay [:smaug][[e-mail]]]

Adam, could you perhaps update this and push to try?

Comment 17

[Adam Gashlin (he/him) [:agashlin] (ex-moco)]

Attachment: skippable SnowWhiteKiller

I took your suggestions, now running in try here:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=362beb3cbad3f1e8052e1185e424934d1187a12c

I also made a microbenchmark that I will attach shortly.

Comment 18

[Adam Gashlin (he/him) [:agashlin] (ex-moco)]

Attachment: Test GC interference with timers

This does some allocation/deallocation and then immediately runs setTimeout with 20 ms a few times. With the patch from comment 17 the delays are more consistently close to 20 ms.

Comment 19

[Vicky Chin [:vchin]]

Any updates on this, Adam?

Comment 20

[Jim Mathies [:jimm]]

(In reply to Vicky Chin [:vchin] from comment #19)
> Any updates on this, Adam?

Hey Vicky, sorry, Adam is not currently working on quantum flow bugs. I don't see him having cycles for work like this for a while.

Comment 21

[Olli Pettay [:smaug][[e-mail]]]

I could take a look at this during 64 cycle, I think.

Comment 22

[Olli Pettay [:smaug][[e-mail]]]

Attachment: skippablesnowwhitekiller5-with_tweaks.diff

This is Adam's patch with some minor naming tweaks and 
-      return NS_IdleDispatchToCurrentThread(self.forget(), 2500);
+      return NS_IdleDispatchToCurrentThread(self.forget(), 500);


remote: 
remote: View your change here:
remote:   https://hg.mozilla.org/try/rev/567133b914edc860a14c2d92d1e14569d09def89
remote: 
remote: Follow the progress of your build on Treeherder:
remote:   https://treeherder.mozilla.org/#/jobs?repo=try&revision=567133b914edc860a14c2d92d1e14569d09def89
remote: recorded changegroup in replication log in 0.007s

Comment 23

[Olli Pettay [:smaug][[e-mail]]]

I'd say that try run looks quite reasonable, so I'll try to land this.

Comment 24

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/8c763e66ba84
make SnowWhite freeing more incremental, r=smaug

Comment 25

[Daniel Varga [:dvarga]]

https://hg.mozilla.org/mozilla-central/rev/8c763e66ba84

Comment 26

[Natalia Csoregi [:nataliaCs]]

There are lots of mochitest failures, such as:
push: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=e123d0aa911c4fa3501042d2febecac1a2766b60&filter-searchStr=debug-mochitest-a11y%20m(a11y)&group_state=expanded&selectedJob=191797688 that started to spike in the last few days.

failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=191797688&repo=mozilla-inbound&lineNumber=6973

06:30:47     INFO - GECKO(7704) | Assertion failure: JS_IsExceptionPending(cx), at z:/build/build/src/obj-firefox/dom/bindings/EventListenerBinding.cpp:30
06:30:59     INFO - GECKO(7704) | #01: mozilla::EventListenerManager::HandleEventSubType(mozilla::EventListenerManager::Listener *,mozilla::dom::Event *,mozilla::dom::EventTarget *) [dom/events/EventListenerManager.cpp:1099]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #02: mozilla::EventListenerManager::HandleEventInternal(nsPresContext *,mozilla::WidgetEvent *,mozilla::dom::Event * *,mozilla::dom::EventTarget *,nsEventStatus *,bool) [dom/events/EventListenerManager.cpp:1333]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #03: mozilla::EventTargetChainItem::HandleEvent(mozilla::EventChainPostVisitor &,mozilla::ELMCreationDetector &) [dom/events/EventDispatcher.cpp:423]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #04: mozilla::EventTargetChainItem::HandleEventTargetChain(nsTArray<mozilla::EventTargetChainItem> &,mozilla::EventChainPostVisitor &,mozilla::EventDispatchingCallback *,mozilla::ELMCreationDetector &) [dom/events/EventDispatcher.cpp:673]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #05: mozilla::EventDispatcher::Dispatch(nsISupports *,nsPresContext *,mozilla::WidgetEvent *,mozilla::dom::Event *,nsEventStatus *,mozilla::EventDispatchingCallback *,nsTArray<mozilla::dom::EventTarget *> *) [dom/events/EventDispatcher.cpp:1112]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #06: mozilla::EventDispatcher::DispatchDOMEvent(nsISupports *,mozilla::WidgetEvent *,mozilla::dom::Event *,nsPresContext *,nsEventStatus *) [dom/events/EventDispatcher.cpp:1197]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #07: nsINode::DispatchEvent(mozilla::dom::Event &,mozilla::dom::CallerType,mozilla::ErrorResult &) [dom/base/nsINode.cpp:1088]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #08: mozilla::dom::EventTarget::DispatchEvent(mozilla::dom::Event &) [dom/events/EventTarget.cpp:197]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #09: mozilla::AsyncEventDispatcher::Run() [dom/events/AsyncEventDispatcher.cpp:74]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #10: nsThread::ProcessNextEvent(bool,bool *) [xpcom/threads/nsThread.cpp:1182]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #11: NS_ProcessNextEvent(nsIThread *,bool) [xpcom/threads/nsThreadUtils.cpp:519]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #12: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate *) [ipc/glue/MessagePump.cpp:97]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #13: MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:319]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #14: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:299]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #15: nsBaseAppShell::Run() [widget/nsBaseAppShell.cpp:160]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #16: nsAppShell::Run() [widget/windows/nsAppShell.cpp:415]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #17: nsAppStartup::Run() [toolkit/components/startup/nsAppStartup.cpp:291]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #18: XREMain::XRE_mainRun() [toolkit/xre/nsAppRunner.cpp:4764]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #19: XREMain::XRE_main(int,char * * const,mozilla::BootstrapConfig const &) [toolkit/xre/nsAppRunner.cpp:4909]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #20: XRE_main(int,char * * const,mozilla::BootstrapConfig const &) [toolkit/xre/nsAppRunner.cpp:5001]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #21: NS_internal_main(int,char * *,char * *) [browser/app/nsBrowserApp.cpp:311]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #22: wmain [toolkit/xre/nsWindowsWMain.cpp:140]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #23: static int __scrt_common_main_seh() [f:/dd/vctools/crt/vcstartup/src/startup/exe_common.inl:283]
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #24: KERNEL32.DLL + 0x12774
06:30:59     INFO - 
06:30:59     INFO - GECKO(7704) | #25: ntdll.dll + 0x70d61
06:30:59     INFO - 
06:30:59     INFO - TEST-INFO | Main app process: exit 1
06:30:59     INFO - Buffered messages logged at 06:30:46
06:30:59     INFO - must wait for load
06:30:59     INFO - Buffered messages finished
06:30:59    ERROR - TEST-UNEXPECTED-FAIL | accessible/tests/mochitest/treeupdate/test_doc.html | application terminated with exit code 1
06:30:59     INFO - runtests.py | Application ran for: 0:04:56.418000
06:30:59     INFO - zombiecheck | Reading PID log: c:\users\task_1533277265\appdata\local\temp\tmpoc4o7apidlog
06:30:59     INFO - ==> process 7704 launched child process 2928 ("Z:\task_1533277265\build\application\firefox\plugin-container.exe" --channel="7704.0.566805368\929802240" "C:\Users\task_1533277265\AppData\Local\Temp\tmp1nelh4.mozrunner\plugins\nptest.dll" -greomni "Z:\task_1533277265\build\application\firefox\omni.ja" -appomni "Z:\task_1533277265\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1533277265\build\application\firefox\browser" - 7704 "\\.\pipe\gecko-crash-server-pipe.7704" 2912 plugin)
06:30:59     INFO - ==> process 7704 launched child process 4608 ("Z:\task_1533277265\build\application\firefox\plugin-container.exe" --channel="7704.3.1457387503\1313345907" "C:\Users\task_1533277265\AppData\Local\Temp\tmp1nelh4.mozrunner\plugins\nptest.dll" -greomni "Z:\task_1533277265\build\application\firefox\omni.ja" -appomni "Z:\task_1533277265\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1533277265\build\application\firefox\browser" - 7704 "\\.\pipe\gecko-crash-server-pipe.7704" 3584 plugin)
06:30:59     INFO - ==> process 7704 launched child process 1936 ("Z:\task_1533277265\build\application\firefox\firefox.exe" -contentproc --channel="7704.6.568959864\1231855281" -childID 1 -isForBrowser -prefsHandle 3544 -prefMapHandle 4040 -prefsLen 1 -prefMapSize 190382 -schedulerPrefs 0001,2 -parentBuildID 20180803034955 -greomni "Z:\task_1533277265\build\application\firefox\omni.ja" -appomni "Z:\task_1533277265\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1533277265\build\application\firefox\browser" - 7704 "\\.\pipe\gecko-crash-server-pipe.7704" 3636 tab)
06:30:59     INFO - zombiecheck | Checking for orphan process with PID: 2928
06:30:59     INFO - zombiecheck | Checking for orphan process with PID: 4608
06:30:59     INFO - zombiecheck | Checking for orphan process with PID: 1936
06:30:59     INFO - mozcrash Copy/paste: Z:\task_1533277265\build\win32-minidump_stackwalk.exe c:\users\task_1533277265\appdata\local\temp\tmp1nelh4.mozrunner\minidumps\4f2880cc-79ed-4b04-abdd-9d4a5a7baa00.dmp Z:\task_1533277265\build\symbols
06:31:07     INFO - mozcrash Saved minidump as Z:\task_1533277265\build\blobber_upload_dir\4f2880cc-79ed-4b04-abdd-9d4a5a7baa00.dmp
06:31:07     INFO - mozcrash Saved app info as Z:\task_1533277265\build\blobber_upload_dir\4f2880cc-79ed-4b04-abdd-9d4a5a7baa00.extra
06:31:07     INFO - PROCESS-CRASH | accessible/tests/mochitest/treeupdate/test_doc.html | application crashed [@ mozilla::dom::EventListener::HandleEvent(JSContext *,JS::Handle<JS::Value>,mozilla::dom::Event &,mozilla::ErrorResult &)]


Retriggering/ backfilling lead us to https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-searchStr=a11y&tochange=8c763e66ba84b13e2d83beb58ea108817aa6d53e&fromchange=69e4230dc38a574338a89588f3c954258b5422d5&group_state=expanded with https://hg.mozilla.org/integration/mozilla-inbound/rev/8c763e66ba84b13e2d83beb58ea108817aa6d53e being the culprit.

@smaug is there any chance you could take a look at this?

Comment 27

[Dorel Luca [:dluca]]

Backed out changeset 8c763e66ba84 (bug 1397297) for frequent mochitest failures. a=backout 

Log:
https://treeherder.mozilla.org/logviewer.html#?job_id=191963750&repo=mozilla-inbound
TEST-START | accessible/tests/mochitest/treeupdate/test_bug1189277.html
22:11:53     INFO - GECKO(3860) | ++DOMWINDOW == 277 (17C78000) [pid = 3860] [serial = 865] [outer = 17C60EC0]
22:11:53     INFO - GECKO(3860) | --DOMWINDOW == 276 (1DF82800) [pid = 3860] [serial = 787] [outer = 00000000] [url = chrome://mochikit/content/tests/SimpleTest/iframe-between-tests.html]
22:11:53     INFO - GECKO(3860) | --DOMWINDOW == 275 (1C12AC00) [pid = 3860] [serial = 792] [outer = 00000000] [url = chrome://mochitests/content/a11y/accessible/tests/mochitest/tree/test_gencontent.html]
22:11:53     INFO - GECKO(3860) | --DOMWINDOW == 274 (1DF7C800) [pid = 3860] [serial = 786] [outer = 00000000] [url = chrome://mochitests/content/a11y/accessible/tests/mochitest/tree/test_filectrl.html]
22:11:53     INFO - GECKO(3860) | Assertion failure: JS_IsExceptionPending(cx), at z:/build/build/src/obj-firefox/dom/bindings/EventListenerBinding.cpp:30
22:12:04     INFO - GECKO(3860) | #01: mozilla::dom::EventListener::HandleEvent<mozilla::dom::EventTarget *>(mozilla::dom::EventTarget * const &,mozilla::dom::Event &,mozilla::ErrorResult &,char const *,mozilla::dom::CallbackObject::ExceptionHandling,JS::Realm *) [s3:gecko-generated-sources:0384e79ee46ca9f3c4b5ade264338740634b9529012db1cbefa8f7a8aafcc2af6d8a1f96ff257b6fd363a30f1422945345b4a0b732edad9041457a263bf3ac41/dist/include/mozilla/dom/EventListenerBinding.h::66]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #02: mozilla::EventListenerManager::HandleEventSubType(mozilla::EventListenerManager::Listener *,mozilla::dom::Event *,mozilla::dom::EventTarget *) [dom/events/EventListenerManager.cpp:1099]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #03: mozilla::EventListenerManager::HandleEventInternal(nsPresContext *,mozilla::WidgetEvent *,mozilla::dom::Event * *,mozilla::dom::EventTarget *,nsEventStatus *,bool) [dom/events/EventListenerManager.cpp:1333]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #04: mozilla::EventTargetChainItem::HandleEvent(mozilla::EventChainPostVisitor &,mozilla::ELMCreationDetector &) [dom/events/EventDispatcher.cpp:423]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #05: mozilla::EventTargetChainItem::HandleEventTargetChain(nsTArray<mozilla::EventTargetChainItem> &,mozilla::EventChainPostVisitor &,mozilla::EventDispatchingCallback *,mozilla::ELMCreationDetector &) [dom/events/EventDispatcher.cpp:673]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #06: mozilla::EventDispatcher::Dispatch(nsISupports *,nsPresContext *,mozilla::WidgetEvent *,mozilla::dom::Event *,nsEventStatus *,mozilla::EventDispatchingCallback *,nsTArray<mozilla::dom::EventTarget *> *) [dom/events/EventDispatcher.cpp:1110]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #07: mozilla::EventDispatcher::DispatchDOMEvent(nsISupports *,mozilla::WidgetEvent *,mozilla::dom::Event *,nsPresContext *,nsEventStatus *) [dom/events/EventDispatcher.cpp:1190]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #08: nsINode::DispatchEvent(mozilla::dom::Event &,mozilla::dom::CallerType,mozilla::ErrorResult &) [dom/base/nsINode.cpp:1088]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #09: mozilla::dom::EventTarget::DispatchEvent(mozilla::dom::Event &) [dom/events/EventTarget.cpp:197]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #10: mozilla::AsyncEventDispatcher::Run() [dom/events/AsyncEventDispatcher.cpp:74]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #11: nsThread::ProcessNextEvent(bool,bool *) [xpcom/threads/nsThread.cpp:1182]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #12: NS_ProcessNextEvent(nsIThread *,bool) [xpcom/threads/nsThreadUtils.cpp:519]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #13: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate *) [ipc/glue/MessagePump.cpp:97]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #14: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:325]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #15: MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:319]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #16: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:299]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #17: nsBaseAppShell::Run() [widget/nsBaseAppShell.cpp:160]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #18: nsAppShell::Run() [widget/windows/nsAppShell.cpp:415]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #19: nsAppStartup::Run() [toolkit/components/startup/nsAppStartup.cpp:291]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #20: XREMain::XRE_mainRun() [toolkit/xre/nsAppRunner.cpp:4806]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #21: XREMain::XRE_main(int,char * * const,mozilla::BootstrapConfig const &) [toolkit/xre/nsAppRunner.cpp:4951]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #22: XRE_main(int,char * * const,mozilla::BootstrapConfig const &) [toolkit/xre/nsAppRunner.cpp:5043]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #23: mozilla::BootstrapImpl::XRE_main(int,char * * const,mozilla::BootstrapConfig const &) [toolkit/xre/Bootstrap.cpp:49]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #24: NS_internal_main(int,char * *,char * *) [browser/app/nsBrowserApp.cpp:311]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #25: wmain [toolkit/xre/nsWindowsWMain.cpp:140]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #26: static int __scrt_common_main_seh() [f:/dd/vctools/crt/vcstartup/src/startup/exe_common.inl:283]
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #27: kernel32.dll + 0x53c45
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #28: ntdll.dll + 0x637f5
22:12:04     INFO - 
22:12:04     INFO - GECKO(3860) | #29: ntdll.dll + 0x637c8
22:12:04     INFO - 
22:12:04     INFO - TEST-INFO | Main app process: exit 1
22:12:04     INFO - Buffered messages finished
22:12:04    ERROR - TEST-UNEXPECTED-FAIL | accessible/tests/mochitest/treeupdate/test_bug1189277.html | application terminated with exit code 1
22:12:04     INFO - runtests.py | Application ran for: 0:04:15.116000
22:12:04     INFO - zombiecheck | Reading PID log: c:\users\task_1533333010\appdata\local\temp\tmpvxhimbpidlog
22:12:04     INFO - ==> process 3860 launched child process 4644 ("Z:\task_1533333010\build\application\firefox\plugin-container.exe" --channel="3860.0.1439394959\1118636315" "C:\Users\task_1533333010\AppData\Local\Temp\tmpbwptkp.mozrunner\plugins\nptest.dll" -greomni "Z:\task_1533333010\build\application\firefox\omni.ja" -appomni "Z:\task_1533333010\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1533333010\build\application\firefox\browser" - 3860 "\\.\pipe\gecko-crash-server-pipe.3860" 2344 plugin)
22:12:04     INFO - ==> process 3860 launched child process 6092 ("Z:\task_1533333010\build\application\firefox\plugin-container.exe" --channel="3860.3.545706244\1563220319" "C:\Users\task_1533333010\AppData\Local\Temp\tmpbwptkp.mozrunner\plugins\nptest.dll" -greomni "Z:\task_1533333010\build\application\firefox\omni.ja" -appomni "Z:\task_1533333010\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1533333010\build\application\firefox\browser" - 3860 "\\.\pipe\gecko-crash-server-pipe.3860" 2508 plugin)
22:12:04     INFO - ==> process 3860 launched child process 4360 ("Z:\task_1533333010\build\application\firefox\firefox.exe" -contentproc --channel="3860.6.731921174\2036636285" -childID 1 -isForBrowser -prefsHandle 3028 -prefMapHandle 2068 -prefsLen 1 -prefMapSize 190214 -schedulerPrefs 0001,2 -parentBuildID 20180803210019 -greomni "Z:\task_1533333010\build\application\firefox\omni.ja" -appomni "Z:\task_1533333010\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1533333010\build\application\firefox\browser" - 3860 "\\.\pipe\gecko-crash-server-pipe.3860" 2992 tab)
22:12:04     INFO - zombiecheck | Checking for orphan process with PID: 4360
22:12:04     INFO - zombiecheck | Checking for orphan process with PID: 6092
22:12:04     INFO - zombiecheck | Checking for orphan process with PID: 4644
22:12:04     INFO - mozcrash Copy/paste: Z:\task_1533333010\build\win32-minidump_stackwalk.exe c:\users\task_1533333010\appdata\local\temp\tmpbwptkp.mozrunner\minidumps\58b6ccdc-e830-4d89-b025-6e31f9dfc948.dmp Z:\task_1533333010\build\symbols
22:12:18     INFO - mozcrash Saved minidump as Z:\task_1533333010\build\blobber_upload_dir\58b6ccdc-e830-4d89-b025-6e31f9dfc948.dmp
22:12:18     INFO - mozcrash Saved app info as Z:\task_1533333010\build\blobber_upload_dir\58b6ccdc-e830-4d89-b025-6e31f9dfc948.extra
22:12:18     INFO - PROCESS-CRASH | accessible/tests/mochitest/treeupdate/test_bug1189277.html | application crashed [@ mozilla::dom::EventListener::HandleEvent(JSContext *,JS::Handle<JS::Value>,mozilla::dom::Event &,mozilla::ErrorResult &)]
22:12:18     INFO - Crash dump filename: c:\users\task_1533333010\appdata\local\temp\tmpbwptkp.mozrunner\minidumps\58b6ccdc-e830-4d89-b025-6e31f9dfc948.dmp
22:12:18     INFO - Operating system: Windows NT
22:12:18     INFO -                   6.1.7601 Service Pack 1
22:12:18     INFO - CPU: x86
22:12:18     INFO -      GenuineIntel family 6 model 63 stepping 2
22:12:18     INFO -      8 CPUs
22:12:18     INFO - 
22:12:18     INFO - GPU: UNKNOWN

Backout:
https://hg.mozilla.org/integration/autoland/rev/4e56a2f51ad739ca52046723448f3129a58f1666

Comment 28

[Olli Pettay [:smaug][[e-mail]]]

Pushed to try with the patch for bug 1451172

remote: View the pushlog for these changes here:
remote:   https://hg.mozilla.org/try/pushloghtml?changeset=4996baae6020ce3c772f8958b82e8664354d9b05
remote: 
remote: Follow the progress of your build on Treeherder:
remote:   https://treeherder.mozilla.org/#/jobs?repo=try&revision=4996baae6020ce3c772f8958b82e8664354d9b05
remote: recorded changegroup in replication log in 0.009s

Comment 29

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/b7c54bc98cc7
make SnowWhite freeing more incremental, r=smaug

Comment 30

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/mozilla-central/rev/b7c54bc98cc7