Closed Bug 1005317 Opened 11 years ago Closed 10 years ago

Mochitest timing out when using OMTC on windows

Categories

(Core :: General, defect)

Product:
Core
Component:
General
Platform:
x86_64
Windows 8.1
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED DUPLICATE of bug 937306

People

(Reporter: bas.schouten, Unassigned)

Details

Currently when using OMTC on windows, we're facing a number of mochitests timing out. It appears that all of them timing out is a result of some focus related issues.

Sometimes they actually time out like here:

https://tbpl.mozilla.org/php/getParsedLog.php?id=38922035&tree=Try&full=1#error0

And sometimes they just take a very long time:

https://tbpl.mozilla.org/php/getParsedLog.php?id=38956363&tree=Try&full=1

(in both cases look at test_alert_noobserve)

I've installed Windows 7 on a MacMini but sadly I can't repro it there either. I've added more printfs and such to try and figure out what's going on, but at this point I'm a little at a loss as to what could be the cause of the issues.
Hrm, so the timing thing might've been off. I'm not sure but I still believe it's event related. Note I instrumented nsWindow::OnPaint with a printf, and that seems to only execute when the test resumes in the noobserve test:

https://tbpl.mozilla.org/php/getParsedLog.php?id=38960006&tree=Try&full=1
I tried to confirm my 'focus' theory but I might not be recording focus correctly? I ended up setting a printf in nsWindow::SetInputContext but that might not work for windows with no inputs or anything like that. I do get some notifications but nothing too interesting:

No long freeze:

https://tbpl.mozilla.org/php/getParsedLog.php?id=39020245&tree=Try&full=1

Long freeze:

https://tbpl.mozilla.org/php/getParsedLog.php?id=39020233&tree=Try&full=1

Both wrt the noobserve test.
Summary: Mochtest timing out when using OMTC on windows → Mochitest timing out when using OMTC on windows
Here's the flow of window messages when things go bad, the last message before the long wait seems to be a WM_NCPAINT message:

08:12:55     INFO -  2328 INFO TEST-START | /tests/toolkit/components/alerts/test/test_alerts_noobserve.html
08:12:55     INFO -  Message: WND: 00090176, MSG: 528, WPARAM: 00000001, LPARAM: 0002017A
08:12:55     INFO -  Message: WND: 00090176, MSG: 528, WPARAM: 00000001, LPARAM: 0001017E
08:12:55     INFO -  Message: WND: 00090176, MSG: 15, WPARAM: 00000000, LPARAM: 00000000
08:12:55     INFO -  Onpaint received.Onpaint executed.Message: WND: 00090176, MSG: 133, WPARAM: 00000001, LPARAM: 00000000
08:15:12     INFO -  [4040] WARNING: pipe error: 109: file c:/builds/moz2_slave/try-w32-0000000000000000000000/build/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 310
08:15:12     INFO -  Message: WND: 00090176, MSG: 12, WPARAM: 00000000, LPARAM: 1741A328
08:15:12     INFO -  Message: WND: 00090176, MSG: NPP_Destroy
08:15:12     INFO -  NPP_Destroy
08:15:12     INFO -  NPP_Destroy
08:15:12     INFO -  NPP_Destroy
08:15:12     INFO -  NPP_Destroy
08:15:12     INFO -  NPP_Destroy
08:15:12     INFO -  70, WPARAM: 00000000, LPARAM: 0027DD90
08:15:12     INFO -  Message: WND: 00090176, MSG: 131, WPARAM: 00000001, LPARAM: 0027DD64
08:15:12     INFO -  Message: WND: 00090176, MSG: 71, WPARAM: 00000000, LPARAM: 0027DD90
08:15:12     INFO -  Message: WND: 00090176, MSG: 70, WPARAM: 00000000, LPARAM: 0027DE24
08:15:12     INFO -  Message: WND: 00090176, MSG: 131, WPARAM: 00000001, LPARAM: 0027DDF8
08:15:12     INFO -  Message: WND: 00090176, MSG: 71, WPARAM: 00000000, LPARAM: 0027DE24
08:15:12     INFO -  Message: WND: 0001017E, MSG: 70, WPARAM: 00000000, LPARAM: 0027D97C
08:15:12     INFO -  Message: WND: 0001017E, MSG: 131, WPARAM: 00000001, LPARAM: 0027D950
08:15:12     INFO -  Message: WND: 0001017E, MSG: 71, WPARAM: 00000000, LPARAM: 0027D97C
08:15:12     INFO -  Message: WND: 0002017A, MSG: 70, WPARAM: 00000000, LPARAM: 0027D968
08:15:12     INFO -  Message: WND: 0002017A, MSG: 131, WPARAM: 00000001, LPARAM: 0027D93C
08:15:12     INFO -  Message: WND: 0002017A, MSG: 71, WPARAM: 00000000, LPARAM: 0027D968
08:15:12     INFO -  Message: WND: 00090176, MSG: 70, WPARAM: 00000000, LPARAM: 0027DD6C
08:15:12     INFO -  Message: WND: 00090176, MSG: 131, WPARAM: 00000001, LPARAM: 0027DD40
08:15:12     INFO -  Message: WND: 00090176, MSG: 71, WPARAM: 00000000, LPARAM: 0027DD6C
08:15:12     INFO -  Message: WND: 00090176, MSG: 70, WPARAM: 00000000, LPARAM: 0027DDEC
08:15:12     INFO -  Message: WND: 00090176, MSG: 131, WPARAM: 00000001, LPARAM: 0027DDC0
08:15:12     INFO -  Message: WND: 00090176, MSG: 71, WPARAM: 00000000, LPARAM: 0027DDEC
08:15:12     INFO -  Message: WND: 00090176, MSG: 70, WPARAM: 00000000, LPARAM: 0027DE80
08:15:12     INFO -  Message: WND: 00090176, MSG: 71, WPARAM: 00000000, LPARAM: 0027DE80
08:15:12     INFO -  Message: WND: 00090176, MSG: 70, WPARAM: 00000000, LPARAM: 0027DDC8
08:15:12     INFO -  Message: WND: 00090176, MSG: 131, WPARAM: 00000001, LPARAM: 0027DD9C
08:15:12     INFO -  Message: WND: 00090176, MSG: 71, WPARAM: 00000000, LPARAM: 0027DDC8
08:15:12     INFO -  Message: WND: 0001017E, MSG: 70, WPARAM: 00000000, LPARAM: 0027EE88
08:15:12     INFO -  Message: WND: 0001017E, MSG: 34, WPARAM: 00000000, LPARAM: 00000000
08:15:12     INFO -  Message: WND: 0001017E, MSG: 71, WPARAM: 00000000, LPARAM: 0027EE88
08:15:12     INFO -  Message: WND: 0001017E, MSG: 70, WPARAM: 00000000, LPARAM: 0027F14C
08:15:12     INFO -  Message: WND: 0001017E, MSG: 34, WPARAM: 00000000, LPARAM: 00000000
08:15:12     INFO -  Message: WND: 00090176, MSG: 70, WPARAM: 00000000, LPARAM: 0027F198
08:15:12     INFO -  Message: WND: 00090176, MSG: 71, WPARAM: 00000000, LPARAM: 0027F198
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 0002017A, MSG: 144, WPARAM: 00000000, LPARAM: 00000000
08:15:12     INFO -  Message: WND: 00090176, MSG: 528, WPARAM: 00000002, LPARAM: 0002017A
08:15:12     INFO -  Message: WND: 0002017A, MSG: 2, WPARAM: 00000000, LPARAM: 00000000
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:12     INFO -  Message: WND: 00040160, MSG: 32, WPARAM: 00040160, LPARAM: 02000001
08:15:12     INFO -  Message: WND: 00040160, MSG: 512, WPARAM: 00000000, LPARAM: 0062002B
08:15:12     INFO -  Message: WND: 00090176, MSG: 15, WPARAM: 00000000, LPARAM: 00000000
08:15:12     INFO -  Onpaint received.Onpaint executed.Message: WND: 00090176, MSG: 133, WPARAM: 00000001, LPARAM: 00000000
08:15:12     INFO -  Message: WND: 00090176, MSG: 20, WPARAM: 03010040, LPARAM: 00000000
08:15:12     INFO -  Message: WND: 0001017E, MSG: 15, WPARAM: 00000000, LPARAM: 00000000
08:15:12     INFO -  Onpaint received.Onpaint executed.Message: WND: 0001017E, MSG: 133, WPARAM: 00000001, LPARAM: 00000000
08:15:12     INFO -  Message: WND: 0001017E, MSG: 20, WPARAM: 0201004C, LPARAM: 00000000
08:15:16     INFO -  Requesting flush renderingRendering flushed!Message: WND: 00090176, MSG: 24, WPARAM: 00000000, LPARAM: 00000000
08:15:16     INFO -  Message: WND: 00090176, MSG: 70, WPARAM: 00000000, LPARAM: 0027F6F8
08:15:16     INFO -  Message: WND: 00090176, MSG: 71, WPARAM: 00000000, LPARAM: 0027F6F8
08:15:16     INFO -  Message: WND: 00090176, MSG: 144, WPARAM: 00000000, LPARAM: 00000000
08:15:16     INFO -  Message: WND: 00090176, MSG: 2, WPARAM: 00000000, LPARAM: 00000000
08:15:16     INFO -  Message: WND: 0001017E, MSG: 2, WPARAM: 00000000, LPARAM: 00000000
08:15:16     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:16     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:16     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:16     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:16     INFO -  ###!!! [Child][DispatchAsyncMessage] Error: Route error: message sent to unknown actor ID
08:15:16     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:16     INFO -  ###!!! [Child][DispatchAsyncMessage] Error: Route error: message sent to unknown actor ID
08:15:16     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:16     INFO -  ###!!! [Child][DispatchAsyncMessage] Error: Route error: message sent to unknown actor ID
08:15:16     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:16     INFO -  ###!!! [Child][DispatchAsyncMessage] Error: Route error: message sent to unknown actor ID
08:15:16     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:16     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:16     INFO -  Message: WND: 00040160, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
08:15:16     INFO -  Message: WND: 00040160, MSG: 32, WPARAM: 00040160, LPARAM: 02000001
08:15:16     INFO -  Message: WND: 00040160, MSG: 512, WPARAM: 00000000, LPARAM: 0062002B
08:15:17     INFO -  2329 INFO TEST-INFO | MEMORY STAT vsize after test: 827437056
08:15:17     INFO -  2330 INFO TEST-INFO | MEMORY STAT vsizeMaxContiguous after test: 609943552
08:15:17     INFO -  2331 INFO TEST-INFO | MEMORY STAT residentFast after test: 227614720
08:15:17     INFO -  2332 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 56946996
08:15:17     INFO -  2333 INFO TEST-END | /tests/toolkit/components/alerts/test/test_alerts_noobserve.html | finished in 141901ms
This is a good run with no noticeable delay:

09:36:17     INFO -  2328 INFO TEST-START | /tests/toolkit/components/alerts/test/test_alerts_noobserve.html
09:36:17     INFO -  Message: WND: 0009017A, MSG: 528, WPARAM: 00000001, LPARAM: 0002017C
09:36:17     INFO -  Message: WND: 0009017A, MSG: 528, WPARAM: 00000001, LPARAM: 00020180
09:36:17     INFO -  Message: WND: 0009017A, MSG: 12, WPARAM: 00000000, LPARAM: 1EAA1BF8
09:36:17     INFO -  Message: WND: 0009017A, MSG: 70, WPARAM: 00000000, LPARAM: 0031DDDC
09:36:17     INFO -  Message: WND: 0009017A, MSG: 131, WPARAM: 00000001, LPARAM: 0031DDB0
09:36:17     INFO -  Message: WND: 0009017A, MSG: 71, WPARAM: 00000000, LPARAM: 0031DDDC
09:36:17     INFO -  Message: WND: 0009017A, MSG: 70, WPARAM: 00000000, LPARAM: 0031DE70
09:36:17     INFO -  Message: WND: 0009017A, MSG: 131, WPARAM: 00000001, LPARAM: 0031DE44
09:36:17     INFO -  Message: WND: 0009017A, MSG: 71, WPARAM: 00000000, LPARAM: 0031DE70
09:36:17     INFO -  Message: WND: 00020180, MSG: 70, WPARAM: 00000000, LPARAM: 0031D9C8
09:36:17     INFO -  Message: WND: 00020180, MSG: 131, WPARAM: 00000001, LPARAM: 0031D99C
09:36:17     INFO -  Message: WND: 00020180, MSG: 71, WPARAM: 00000000, LPARAM: 0031D9C8
09:36:17     INFO -  Message: WND: 0002017C, MSG: 70, WPARAM: 00000000, LPARAM: 0031D9B4
09:36:17     INFO -  Message: WND: 0002017C, MSG: 131, WPARAM: 00000001, LPARAM: 0031D988
09:36:17     INFO -  Message: WND: 0002017C, MSG: 71, WPARAM: 00000000, LPARAM: 0031D9B4
09:36:17     INFO -  Message: WND: 0009017A, MSG: 70, WPARAM: 00000000, LPARAM: 0031DDB8
09:36:17     INFO -  Message: WND: 0009017A, MSG: 131, WPARAM: 00000001, LPARAM: 0031DD8C
09:36:17     INFO -  Message: WND: 0009017A, MSG: 71, WPARAM: 00000000, LPARAM: 0031DDB8
09:36:17     INFO -  Message: WND: 0009017A, MSG: 70, WPARAM: 00000000, LPARAM: 0031DE38
09:36:17     INFO -  Message: WND: 0009017A, MSG: 131, WPARAM: 00000001, LPARAM: 0031DE0C
09:36:17     INFO -  Message: WND: 0009017A, MSG: 71, WPARAM: 00000000, LPARAM: 0031DE38
09:36:17     INFO -  Message: WND: 0009017A, MSG: 70, WPARAM: 00000000, LPARAM: 0031DECC
09:36:17     INFO -  Message: WND: 0009017A, MSG: 71, WPARAM: 00000000, LPARAM: 0031DECC
09:36:17     INFO -  Message: WND: 0009017A, MSG: 70, WPARAM: 00000000, LPARAM: 0031DE14
09:36:17     INFO -  Message: WND: 0009017A, MSG: 131, WPARAM: 00000001, LPARAM: 0031DDE8
09:36:17     INFO -  Message: WND: 0009017A, MSG: 71, WPARAM: 00000000, LPARAM: 0031DE14
09:36:17     INFO -  Message: WND: 00020180, MSG: 70, WPARAM: 00000000, LPARAM: 0031EED4
09:36:17     INFO -  Message: WND: 00020180, MSG: 34, WPARAM: 00000000, LPARAM: 00000000
09:36:17     INFO -  Message: WND: 00020180, MSG: 71, WPARAM: 00000000, LPARAM: 0031EED4
09:36:17     INFO -  Message: WND: 00020180, MSG: 70, WPARAM: 00000000, LPARAM: 0031F198
09:36:17     INFO -  Message: WND: 00020180, MSG: 34, WPARAM: 00000000, LPARAM: 00000000
09:36:17     INFO -  Message: WND: 0009017A, MSG: 70, WPARAM: 00000000, LPARAM: 0031F1E4
09:36:17     INFO -  Message: WND: 0009017A, MSG: 71, WPARAM: 00000000, LPARAM: 0031F1E4
09:36:17     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:17     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:17     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:17     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:17     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:17     INFO -  Message: WND: 0002017C, MSG: 144, WPARAM: 00000000, LPARAM: 00000000
09:36:17     INFO -  Message: WND: 0009017A, MSG: 528, WPARAM: 00000002, LPARAM: 0002017C
09:36:17     INFO -  Message: WND: 0002017C, MSG: 2, WPARAM: 00000000, LPARAM: 00000000
09:36:17     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:17     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:17     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:17     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:17     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:17     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:17     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:17     INFO -  Message: WND: 00010164, MSG: 32, WPARAM: 00010164, LPARAM: 02000001
09:36:17     INFO -  Message: WND: 00010164, MSG: 512, WPARAM: 00000000, LPARAM: 0062002B
09:36:17     INFO -  Message: WND: 0009017A, MSG: 15, WPARAM: 00000000, LPARAM: 00000000
09:36:17     INFO -  Onpaint received.Onpaint executed.Message: WND: 0009017A, MSG: 133, WPARAM: 00000001, LPARAM: 00000000
09:36:17     INFO -  Message: WND: 0009017A, MSG: 20, WPARAM: 07010041, LPARAM: 00000000
09:36:17     INFO -  Message: WND: 00020180, MSG: 15, WPARAM: 00000000, LPARAM: 00000000
09:36:17     INFO -  Onpaint received.Onpaint executed.Message: WND: 00020180, MSG: 133, WPARAM: 00000001, LPARAM: 00000000
09:36:17     INFO -  Message: WND: 00020180, MSG: 20, WPARAM: 130106A6, LPARAM: 00000000
09:36:21     INFO -  Requesting flush renderingRendering flushed!Message: WND: 0009017A, MSG: 24, WPARAM: 00000000, LPARAM: 00000000
09:36:21     INFO -  Message: WND: 0009017A, MSG: 70, WPARAM: 00000000, LPARAM: 0031F534
09:36:21     INFO -  Message: WND: 0009017A, MSG: 71, WPARAM: 00000000, LPARAM: 0031F534
09:36:21     INFO -  Message: WND: 0009017A, MSG: 144, WPARAM: 00000000, LPARAM: 00000000
09:36:21     INFO -  Message: WND: 0009017A, MSG: 2, WPARAM: 00000000, LPARAM: 00000000
09:36:21     INFO -  Message: WND: 00020180, MSG: 2, WPARAM: 00000000, LPARAM: 00000000
09:36:21     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:21     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:21     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:21     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:21     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:21     INFO -  ###!!! [Child][DispatchAsyncMessage] Error: Route error: message sent to unknown actor ID
09:36:21     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:21     INFO -  ###!!! [Child][DispatchAsyncMessage] Error: Route error: message sent to unknown actor ID
09:36:21     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:21     INFO -  ###!!! [Child][DispatchAsyncMessage] Error: Route error: message sent to unknown actor ID
09:36:21     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:21     INFO -  ###!!! [Child][DispatchAsyncMessage] Error: Route error: message sent to unknown actor ID
09:36:21     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:21     INFO -  Message: WND: 00010164, MSG: 132, WPARAM: 00000000, LPARAM: 00660035
09:36:21     INFO -  Message: WND: 00010164, MSG: 32, WPARAM: 00010164, LPARAM: 02000001
09:36:21     INFO -  Message: WND: 00010164, MSG: 512, WPARAM: 00000000, LPARAM: 0062002B
09:36:22     INFO -  2329 INFO TEST-INFO | MEMORY STAT vsize after test: 852201472
09:36:22     INFO -  2330 INFO TEST-INFO | MEMORY STAT vsizeMaxContiguous after test: 644284416
09:36:22     INFO -  2331 INFO TEST-INFO | MEMORY STAT residentFast after test: 358744064
09:36:22     INFO -  2332 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 55188596
09:36:22     INFO -  2333 INFO TEST-END | /tests/toolkit/components/alerts/test/test_alerts_noobserve.html | finished in 5089ms
So note that in these two traces the point where all seems to go wrong is the WM_NCPAINT message, I decided to add some more diagnostics and the following interesting info came out of that:

22:08:43     INFO -  Onpaint received.Onpaint executed.Message: WND: 00090174, MSG: 133, WPARAM: 00000001, LPARAM: 00000000
22:10:59     INFO -  Ignoring NCPAINT CustomNonClientMessage processed..Message processed..Message: WND: 00090174, MSG: 12, WPARAM: 00000000, LPARAM: 1677F758
22:10:59     INFO -  Message processed..NPP_Destroy

Note that the NC_PAINT message comes in before the pause, and it gets finished after. This is interesting, hopefully this is not just because of how the mochitest frameworks reports things. I've added some additional diagnostics specifically for this issue. This exact situation does not seem to occur on some of the other timeouts, but they are all showing WM_NCPAINT messages -close- to timing out, so I'm hoping the underlying issues are still the same.
Looks like this was a wrong trail, it appears our try server framework only returns printfs after a newline has been passed, the actual log looks like this:

17:49:41     INFO -  2328 INFO TEST-START | /tests/toolkit/components/alerts/test/test_alerts_noobserve.html
17:49:41     INFO -  Message: WND: 000A0174, MSG: 528, WPARAM: 00000001, LPARAM: 00020180
17:49:41     INFO -  CWPCPWPI - P0WPI - P1
17:49:41     INFO -  WPI - P2
17:49:41     INFO -  WPI - P3
17:49:41     INFO -  Point 1Point 2Point 3WPI - P4
17:49:41     INFO -  WPI - P5
17:49:41     INFO -  Message processed..
17:49:41     INFO -  Message: WND: 000A0174, MSG: 528, WPARAM: 00000001, LPARAM: 00010184
17:49:41     INFO -  CWPCPWPI - P0WPI - P1
17:49:41     INFO -  WPI - P2
17:49:41     INFO -  WPI - P3
17:49:41     INFO -  Point 1Point 2Point 3WPI - P4
17:49:41     INFO -  WPI - P5
17:49:41     INFO -  Message processed..
17:49:41     INFO -  Message: WND: 000A0174, MSG: 15, WPARAM: 00000000, LPARAM: 00000000
17:49:41     INFO -  CWPCPWPI - P0WPI - P1
17:49:41     INFO -  WPI - P2
17:49:41     INFO -  WPI - P3
17:49:41     INFO -  Point 1Point 2Point 3OP - P1
17:49:41     INFO -  OP - P2
17:49:41     INFO -  OP - P3
17:49:41     INFO -  OP - P4
17:49:41     INFO -  Message: WND: 000A0174, MSG: 133, WPARAM: 00000001, LPARAM: 00000000
17:49:41     INFO -  CWPCPWPI - P0WPI - P1
17:49:41     INFO -  WPI - P2
17:49:41     INFO -  WPI - P3
17:49:41     INFO -  Point 1Point 2Point 3Ignoring NCPAINT CustomNonClientWPI - P4
17:49:41     INFO -  WPI - P5
17:49:41     INFO -  Message processed..
17:49:41     INFO -  OP - P5
17:49:41     INFO -  OP - P6
17:49:41     INFO -  OP - P7
17:49:41     INFO -  OP - P8
17:49:41     INFO -  OP - P9
17:49:41     INFO -  OP - P10
17:49:41     INFO -  Message processed..
17:51:58     INFO -  NPP_Destroy
17:51:58     INFO -  NPP_Destroy
17:51:58     INFO -  NPP_Destroy
17:51:58     INFO -  NPP_Destroy
17:51:58     INFO -  NPP_Destroy
17:51:58     INFO -  NPP_Destroy
17:51:58     INFO -  Message: WND: 000A0174, MSG: 12, WPARAM: 00000000, LPARAM: 14EA1BA8
17:51:58     INFO -  CWPCPWPI - P0WPI - P1
17:51:58     INFO -  WPI - P2
17:51:58     INFO -  WPI - P3
17:51:58     INFO -  Point 1Point 2Point 3WPI - P4
17:51:58     INFO -  WPI - P5
It should be noted though that the WM_PAINT and subsequent WM_NCPAINT in the parent window, are still the two events that distinguish the working from the non-working case.
I'm able to reproduce the test_alerts_noobserve.html locally. STR:

1) run the alert set of tests using mach:

mach mochitest-plain toolkit/components/alerts/test/

2) don't touch the mouse or keyboard such that no events get sent to the test frame

result: test times out

Note, before the time out, if you move the mouse over the window a bit, the alert will display and the test will pass.

3) disable omtc, run test again

result: alert is displayed and test passes with or without mouse movement.

Looks like this might have something to do with event processing.
The main thread is sitting is nsAppShell::ProcessNextNativeEvent's call to WaitMessage() here, which explains why a simple mouse move gets things going again. Not sure how we end up in this state yet. 

Clearly omtc is interfering with our thread event processing in some way causing us to get into an unexpected wait state for native events.

0:11.06 2 INFO TEST-PASS | /tests/toolkit/components/alerts/test/test_alerts_noobserve.html | Alerts should not be present at the start of the test.
0:11.06 3 INFO TEST-PASS | /tests/toolkit/components/alerts/test/test_alerts_noobserve.html | Alerts service exists in this application
0:11.06 4 INFO TEST-PASS | /tests/toolkit/components/alerts/test/test_alerts_noobserve.html | Alerts service is available
0:11.06 CreateWindow: 0x0F08AC
0:11.08 0x0F08AC - 0x0210 WM_PARENTNOTIFY
0:11.08 CreateWindow: 0x15085A
0:11.08 5 INFO TEST-PASS | /tests/toolkit/components/alerts/test/test_alerts_noobserve.html | showAlertNotification() succeeded
0:11.09 0x0F08AC - 0x0210 WM_PARENTNOTIFY
0:11.09 CreateWindow: 0x2E057A
0:11.09 ProcessNextNativeEvent mayWait=0
0:11.09 ProcessNextNativeEvent exit
0:11.11 0x0F08AC - 0x000C WM_SETTEXT
0:11.11 0x0F08AC - 0x0046 WM_WINDOWPOSCHANGING
0:11.11 0x0F08AC - 0x0083 WM_NCCALCSIZE
0:11.11 0x0F08AC - 0x0047 WM_WINDOWPOSCHANGED
0:11.11 0x2E057A - 0x0046 WM_WINDOWPOSCHANGING
0:11.11 0x2E057A - 0x0022 WM_CHILDACTIVATE
0:11.11 0x2E057A - 0x0047 WM_WINDOWPOSCHANGED
0:11.11 0x2E057A - 0x0046 WM_WINDOWPOSCHANGING
0:11.11 0x2E057A - 0x0022 WM_CHILDACTIVATE
0:11.11 0x0F08AC - 0x0046 WM_WINDOWPOSCHANGING
0:11.11 0x0F08AC - 0x0047 WM_WINDOWPOSCHANGED
0:11.11 0x15085A - 0x0090 Unknown
0:11.11 0x0F08AC - 0x0210 WM_PARENTNOTIFY
0:11.11 0x15085A - 0x0002 WM_DESTROY
0:11.11 ProcessNextNativeEvent mayWait=0
0:11.11 ProcessNextNativeEvent exit
0:11.11 ProcessNextNativeEvent mayWait=1
0:11.11 0x0F08AC - 0x000F WM_PAINT
0:11.12 0x0F08AC - 0x0085 WM_NCPAINT
0:11.12 0x0F08AC - 0x0014 WM_ERASEBKGND
0:11.12 0x2E057A - 0x000F WM_PAINT
0:11.12 0x2E057A - 0x0085 WM_NCPAINT
0:11.12 0x2E057A - 0x0014 WM_ERASEBKGND
(freeze)
(In reply to Jim Mathies [:jimm] from comment #9)
> The main thread is sitting is nsAppShell::ProcessNextNativeEvent's call to
> WaitMessage() here, which explains why a simple mouse move gets things going
> again. Not sure how we end up in this state yet. 
> 
> Clearly omtc is interfering with our thread event processing in some way
> causing us to get into an unexpected wait state for native events.

This is awesome work. I still can't reproduce on my machines but it's awesome that you can. I'll try some settings things tomorrow and see if things change. FWIW, I noticed that if I make WM_PAINT -not- do a BeginPaint and EndPaint, but rather a ValidateRgn (probably a better idea when using OMTC regardless, but that's another point). It gets to the -next- event and then just sits there (a WM_SETTEXT, which should just get ignored because !mCustomNonClient, on try).

Any chance you could look into this further?

Any chance you could look into this further?
I'm thinking one of the things that could occur is a race condition if WaitMessage isn't working properly, perhaps some events are generated from the Compositor thread? Which arrive after PeekMessage but before WaitMessage, WaitMessage should return for those but who knows.. Maybe there's a bug?

It's interesting that this occurs on Win7 but not Win8. I've pushed a run to try that replaces WaitMessage by a MsgWaitForMultipleObjects call. I'm not sure this will change anything, but I figured it'd be interesting to try.
ISTR nrc making some changes to do with PeekMessage. Adding ni?
Flags: needinfo?(ncameron)
Bug 896896 and bug 937306. It looks like people have ran into, and found this bug before. I'll work on a fix.
Flags: needinfo?(ncameron)
Depends on: 937306
I can confirm this is due to a lost async callback native event - 

0:15.96 ScheduleNativeEventCallback PostMessage
0:15.96 2 INFO TEST-PASS | /tests/toolkit/components/alerts/test/test_alerts_noobserve.html | Alerts should not be present at the start of the test.
0:15.96 3 INFO TEST-PASS | /tests/toolkit/components/alerts/test/test_alerts_noobserve.html | Alerts service exists in this application
0:15.96 4 INFO TEST-PASS | /tests/toolkit/components/alerts/test/test_alerts_noobserve.html | Alerts service is available
0:15.96 CreateWindow: 0x4906D4
0:15.96 0x4906D4 - 0x0210 WM_PARENTNOTIFY
0:15.96 CreateWindow: 0x3F06AC
0:15.96 5 INFO TEST-PASS | /tests/toolkit/components/alerts/test/test_alerts_noobserve.html | showAlertNotification() succeeded
0:15.98 0x4906D4 - 0x0210 WM_PARENTNOTIFY
0:15.98 CreateWindow: 0x2703AE
0:15.98 ProcessNextNativeEvent mayWait=0
0:15.98 EventWindowProc NativeEventCallback
0:15.98 ProcessNextNativeEvent exit
0:15.98 ProcessNextNativeEvent mayWait=1
0:15.98 ScheduleNativeEventCallback PostMessage (scheduled)
0:15.98 0x4906D4 - 0x000F WM_PAINT
0:15.98 0x4906D4 - 0x0085 WM_NCPAINT
(freeze, no callback)
(move mouse...)
0:25.99 EventWindowProc NativeEventCallback (posted msg prcessed)
0:25.99 ScheduleNativeEventCallback PostMessage
0:25.99 ProcessNextNativeEvent exit
0:25.99 0x4B06AA - 0x0086 WM_NCACTIVATE
0:25.99 0x4B06AA - 0x0006 WM_ACTIVATE
0:25.99 0x4906D4 - 0x001C WM_ACTIVATEAPP
0:25.99 0x4B06AA - 0x001C WM_ACTIVATEAPP
0:25.99 0x2906D0 - 0x001C WM_ACTIVATEAPP
0:25.99 0x4B06AA - 0x0008 WM_KILLFOCUS
0:25.99 0x4B06AA - 0x0281 WM_IME_SETCONTEXT
0:25.99 0x4B06AA - 0x0282 WM_IME_NOTIFY
What we could do here is dump calls that might mark a message as non-pending that might get called during paint processing - 

0:15.98 ScheduleNativeEventCallback PostMessage (scheduled)
0:15.98 0x4906D4 - 0x000F WM_PAINT
0:15.98 0x4906D4 - 0x0085 WM_NCPAINT
(freeze, no callback)

If we can figure out where the posted event gets marked as non-pending we can work around it.

Another thing to consider would be to make WaitMessage non-infinite, and do our own checks for pending events. This would result in some delay since the timeout would have to be large, so it's not an optimal fix.

from WaitMessage docs:

Note that WaitMessage does not return if there is unread input in the message queue after the thread has called a function to check the queue. This is because functions such as PeekMessage, GetMessage, GetQueueStatus, WaitMessage, MsgWaitForMultipleObjects, and MsgWaitForMultipleObjectsEx check the queue and then change the state information for the queue so that the input is no longer considered new.
Status: NEW → RESOLVED
Closed: 10 years ago
No longer depends on: 937306
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.